[Varnish] #1221: 304 not modified response with body makes next request fail

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