[Varnish] #1221: 304 not modified response with body makes next request fail
Varnish
varnish-bugs at varnish-cache.org
Tue Oct 23 12:44:30 CEST 2012
#1221: 304 not modified response with body makes next request fail
------------------------------+--------------------
Reporter: tmagnien | Type: defect
Status: new | Priority: normal
Milestone: | Component: build
Version: 3.0.2 | Severity: normal
Keywords: 304 chunked body |
------------------------------+--------------------
If a backend sends a "304 not modified" response which includes a body,
encoded as chunked, varnish logs body into garbage but next request fails
with "http format error".
Here are the logs:
Request n°1
{{{
588 TxRequest b GET
588 TxURL b /webmail/20121016184402/img/inbox_progressbar.png
588 TxProtocol b HTTP/1.1
588 TxHeader b Accept: */*
588 TxHeader b Accept-Language: fr-FR
588 TxHeader b User-Agent: Mozilla/4.0 (compatible; MSIE 8.0;
Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR
3.5.30729; .NET CLR 3.0.30729; Med
588 TxHeader b If-Modified-Since: Tue, 16 Oct 2012 16:46:10 GMT
588 TxHeader b Proxy-Connection: Keep-Alive
588 TxHeader b Host: xxx.s-sfr.fr
588 TxHeader b Cookie: _sm_au_c=iVVDKjVQjbQKkVrq0d
588 TxHeader b X-Forwarded-For: 77.242.201.53, 77.242.201.53
588 TxHeader b X-Varnish: 1284584803
588 RxProtocol b HTTP/1.1
588 RxStatus b 304
588 RxResponse b Not Modified
588 RxHeader b Server: Apache
588 RxHeader b Transfer-Encoding: chunked
588 RxHeader b Date: Tue, 23 Oct 2012 09:44:02 GMT
588 RxHeader b X-Varnish: 1153195315
588 RxHeader b Age: 0
588 RxHeader b Connection: keep-alive
588 RxHeader b Via: 1.1 varnish, 1.1 bou2-ncdn-cache06
588 Fetch_Body b 0(none) cls 0 mklen 0
588 Length b 0
588 BackendReuse b pop_storage
}}}
Capture with tcpdump, the backend response n°1:
{{{
HTTP/1.1 304 Not Modified^M
Server: Apache^M
Transfer-Encoding: chunked^M
Date: Tue, 23 Oct 2012 09:44:02 GMT^M
X-Varnish: 1153195315^M
Age: 0^M
Connection: keep-alive^M
Via: 1.1 varnish, 1.1 bou2-ncdn-cache06^M
^M
0^M
^M
}}}
Request n°2:
{{{
588 TxRequest b GET
588 TxURL b /192653626-bfm_business_1256k1376.ts
588 TxProtocol b HTTP/1.1
588 TxHeader b Host: xxx.sfr.fr
588 TxHeader b User-Agent: AppleCoreMedia/1.0.0.11E53 (Macintosh; U;
Intel Mac OS X 10_7_4; fr_fr)
588 TxHeader b Accept: */*
588 TxHeader b X-Playback-Session-Id: 33105B46-96CF-4EB6-8EBA-
1D13D07FBBB5
588 TxHeader b X-Real-IP: 86.72.72.122
588 TxHeader b X-Forwarded-For: 86.72.72.122, 86.72.72.122
588 TxHeader b X-Varnish: 1284584825
588 TxHeader b Accept-Encoding: gzip
588 HttpGarbage b 0^M
^M
588 BackendClose b pop_storage
719 ReqStart c 86.72.72.122 51666 1284584825
719 RxRequest c GET
719 RxURL c /192653626-bfm_business_1256k1376.ts
719 RxProtocol c HTTP/1.1
719 RxHeader c Host: ncdn.adam.sfr.fr
719 RxHeader c User-Agent: AppleCoreMedia/1.0.0.11E53 (Macintosh; U;
Intel Mac OS X 10_7_4; fr_fr)
719 RxHeader c Accept: */*
719 RxHeader c Accept-Encoding: identity
719 RxHeader c X-Playback-Session-Id: 33105B46-96CF-4EB6-8EBA-
1D13D07FBBB5
719 RxHeader c Cookie: session_id=601c; authent=JCvjFa5FRocCF2l;
c_m=%5B%5BB%5D%5D; evar28=1_1349343177365_1929597724229097; ext_ref=;
s_cc=true; s_pp
719 RxHeader c Connection: keep-alive
719 VCL_call c recv
719 VCL_Log c X-SessionId: 9569e746601c
719 VCL_Log c X-Backend: adam_director
719 VCL_return c lookup
719 VCL_call c hash
719 Hash c /192653626-bfm_business_1256k1376.ts
719 Hash c ncdn.adam.sfr.fr
719 VCL_return c hash
719 VCL_call c miss fetch
719 Backend c 588 ncdn_storage pop_storage
719 FetchError c http format error
719 VCL_call c error deliver
719 VCL_call c deliver deliver
719 TxProtocol c HTTP/1.1
719 TxStatus c 503
719 TxResponse c Service Unavailable
719 TxHeader c Server: Varnish
719 TxHeader c Content-Type: text/html; charset=utf-8
719 TxHeader c Retry-After: 5
719 TxHeader c Content-Length: 419
719 TxHeader c Accept-Ranges: bytes
719 TxHeader c Date: Tue, 23 Oct 2012 09:44:02 GMT
719 TxHeader c X-Varnish: 1284584825
719 TxHeader c Age: 0
719 TxHeader c Connection: close
719 TxHeader c Via: 1.1 varnish, 1.1 bou2-ncdn-cache00
719 Length c 419
719 ReqEnd c 1284584825 1350985442.104519367 1350985442.104895592
0.030051947 0.000344038 0.000032187
719 SessionClose c error
719 StatSess c 86.72.72.122 51666 0 1 2 0 1 1 693 632
}}}
Backend response n°2:
{{{
HTTP/1.1 200 OK^M
Server: nginx/0.7.67^M
Content-Type: application/octet-stream^M
Last-Modified: Tue, 23 Oct 2012 09:43:57 GMT^M
Content-Length: 1389712^M
Accept-Ranges: bytes^M
Date: Tue, 23 Oct 2012 09:44:02 GMT^M
X-Varnish: 1153195320 1153195119^M
Age: 2^M
Connection: keep-alive^M
Via: 1.1 varnish, 1.1 bou2-ncdn-cache06^M
}}}
So varnish takes garbage from the previous request as body of the second
request.
Regards,
Thierry
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1221>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list