[Varnish] #813: Varnish 503's w/ FetchError straight read_error: 11

Thu Nov 11 18:49:21 CET 2010

#813: Varnish 503's w/ FetchError straight read_error: 11
----------------------+-----------------------------------------------------
 Reporter:  ntang     |       Owner:  phk  
     Type:  defect    |      Status:  new  
 Priority:  high      |   Milestone:       
Component:  varnishd  |     Version:  2.1.2
 Severity:  major     |    Keywords:       
----------------------+-----------------------------------------------------
 We're serving mp3 files up through Varnish to Apache/ PHP running
 Wordpress 2.8.4.  Apache serves them up fine, but when we put Varnish in
 front, it spits out a 503 error after a long delay.  I'm not sure what's
 going on, but I'm pretty sure it's not the correct behavior.

 Here's a sample from the logs:

 {{{
    12 SessionOpen  c 10.50.43.20 24510 :6081
    12 ReqStart     c 10.50.43.20 24510 1686468638
    12 RxRequest    c HEAD
    12 RxURL        c /files/2010/10/HM-33-2-WEB.mp3
    12 RxProtocol   c HTTP/1.1
    12 RxHeader     c User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
 libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
    12 RxHeader     c Accept: */*
    12 RxHeader     c Host: [snip]
    12 VCL_call     c recv
    12 VCL_return   c lookup
    12 VCL_call     c hash
    12 VCL_return   c hash
    12 VCL_call     c miss
    12 VCL_return   c fetch
    14 BackendOpen  b default 127.0.0.1 56781 127.0.0.1 80
    12 Backend      c 14 default default
    14 TxRequest    b GET
    14 TxURL        b /files/2010/10/HM-33-2-WEB.mp3
    14 TxProtocol   b HTTP/1.1
    14 TxHeader     b User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
 libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
    14 TxHeader     b Accept: */*
    14 TxHeader     b Host: [snip]
    14 TxHeader     b X-Forwarded-For: 10.50.43.20
    14 TxHeader     b X-Varnish: 1686468638

    14 RxProtocol   b HTTP/1.1
    14 RxStatus     b 200
    14 RxResponse   b OK
    14 RxHeader     b Date: Thu, 11 Nov 2010 17:13:05 GMT
    14 RxHeader     b Server: Apache
    14 RxHeader     b X-Powered-By: PHP/5.2.4
    14 RxHeader     b Vary: Cookie
    14 RxHeader     b Content-Length: 1442796
    14 RxHeader     b Last-Modified: Thu, 11 Nov 2010 12:13:05 -0500
    14 RxHeader     b Expires: Sun, 12 Jan 2014 02:59:45 GMT
    14 RxHeader     b Cache-Control: max-age=3600, must-revalidate
    14 RxHeader     b Content-Type: audio/mpeg
    12 TTL          c 1686468638 RFC 3600 1289495585 0 0 3600 0
    12 VCL_call     c fetch
    12 VCL_return   c pass
    12 ObjProtocol  c HTTP/1.1
    12 ObjStatus    c 200
    12 ObjResponse  c OK
    12 ObjHeader    c Date: Thu, 11 Nov 2010 17:13:05 GMT
    12 ObjHeader    c Server: Apache
    12 ObjHeader    c X-Powered-By: PHP/5.2.4
    12 ObjHeader    c Vary: Cookie
    12 ObjHeader    c Last-Modified: Thu, 11 Nov 2010 12:13:05 -0500
    12 ObjHeader    c Cache-Control: max-age=3600, must-revalidate
    12 ObjHeader    c Content-Type: audio/mpeg
    12 ObjHeader    c magicmarker: 1
    12 ObjHeader    c X-Cacheable: YES
    12 FetchError   c straight read_error: 11
    14 BackendClose b default
    12 VCL_call     c error
    12 VCL_return   c deliver
    12 Length       c 488
    12 VCL_call     c deliver
    12 VCL_return   c deliver
    12 TxProtocol   c HTTP/1.1
    12 TxStatus     c 503
    12 TxResponse   c Service Unavailable
    12 TxHeader     c Server: Varnish
    12 TxHeader     c Retry-After: 0
    12 TxHeader     c Content-Type: text/html; charset=utf-8
    12 TxHeader     c Content-Length: 488
    12 TxHeader     c Date: Thu, 11 Nov 2010 17:14:05 GMT
    12 TxHeader     c X-Varnish: 1686468638
    12 TxHeader     c Age: 60
    12 TxHeader     c Via: 1.1 varnish
    12 TxHeader     c Connection: close
    12 TxHeader     c X-Cache: MISS
    12 ReqEnd       c 1686468638 1289495585.225246668 1289495645.490181923
 0.000139236 60.264884472 0.000050783
    12 SessionClose c error
    12 StatSess     c 10.50.43.20 24510 60 1 1 0 0 0 251 488

 }}}

 Here's what the curl looks like through Apache:

 {{{
 [root at cc20-43 ~]# curl --head --header "Host: [snip]"
 cc85-45:80/files/2010/10/HM-33-2-WEB.mp3
 HTTP/1.1 200 OK
 Date: Thu, 11 Nov 2010 17:45:37 GMT
 Server: Apache
 X-Powered-By: PHP/5.2.4
 Vary: Cookie
 Content-Length: 1442796
 Last-Modified: Thu, 11 Nov 2010 12:45:37 -0500
 Expires: Sun, 12 Jan 2014 03:32:17 GMT
 Cache-Control: max-age=3600, must-revalidate
 Content-Type: audio/mpeg
 }}}

 And here's the curl through Varnish:

 {{{
 [root at cc20-43 ~]# curl --head --header "Host: [snip]"
 cc85-45:6081/files/2010/10/HM-33-2-WEB.mp3
 (pauses for some time...)
 HTTP/1.1 503 Service Unavailable
 Server: Varnish
 Retry-After: 0
 Content-Type: text/html; charset=utf-8
 Content-Length: 488
 Date: Thu, 11 Nov 2010 17:47:29 GMT
 X-Varnish: 1686468640
 Age: 106
 Via: 1.1 varnish
 Connection: close
 X-Cache: MISS
 }}}

 For now, we're going to route around Varnish, but if anyone has any ideas
 as to why this is happening, that'd be great.

 Thanks!

 P.S. The content-length of 1442796 should be correct.

-- 
Ticket URL: <http://varnish-cache.org/trac/ticket/813>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator