[Varnish] #1012: 503 error on 200 backend response: FetchError c straight read_error: -1 12 (Cannot allocate memory)

[Varnish]

#1012: 503 error on 200 backend response: FetchError   c straight read_error: -1
12 (Cannot allocate memory)
----------------------+-----------------------------------------------------
 Reporter:  rzuidhof  |        Type:  defect
   Status:  new       |    Priority:  normal
Milestone:            |   Component:  build 
  Version:  3.0.1     |    Severity:  major 
 Keywords:            |  
----------------------+-----------------------------------------------------
 Sometimes we receive "FetchError c straight read_error: -1 12 (Cannot
 allocate memory)" which results in a 503 error. The backend response on
 these cases is good and fast: a 200 response with the proper byte count.
 It seems to happen more for big files (100 KB - 1 MB).

 In case of a chunked backend response this is "FetchError   c chunked
 read_error: 12 (Cannot allocate memory)".

 It looks like a memory problem. We used to be affected by the memory
 problem in 3.0.0 with the malloc storage. This happens just as well on
 malloc as on file storage. But only when the storage is filled, so not
 directly after restart. We have a high value for beresp.grace (hours).

 {{{
   425 TxURL        b /images/test.pdf
   425 TxProtocol   b HTTP/1.1
   425 TxHeader     b Host: www.localhost.localdomain
   425 TxHeader     b User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1;
 en-US; rv:1.9.2.21) Gecko/20110830 Firefox/3.6.21 GTB7.1 ( .NET CLR
 3.5.30729)
   425 TxHeader     b Accept:
 text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   425 TxHeader     b Accept-Language: en-us,en;q=0.5
   425 TxHeader     b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   425 TxHeader     b X-Forwarded-For: 192.168.1.6
   425 TxHeader     b X-Varnish: 1101341981
   425 TxHeader     b Accept-Encoding: gzip
   425 RxProtocol   b HTTP/1.1
   425 RxStatus     b 200
   425 RxResponse   b OK
   425 RxHeader     b Date: Tue, 06 Sep 2011 15:12:00 GMT
   425 RxHeader     b Server: Apache/2.2.3 (CentOS)
   425 RxHeader     b Last-Modified: Tue, 06 Sep 2011 13:53:29 GMT
   425 RxHeader     b ETag: "169c519-3688b6-4ac3627026840"
   425 RxHeader     b Accept-Ranges: bytes
   425 RxHeader     b Content-Length: 3574942
   425 RxHeader     b Connection: close
   425 RxHeader     b Content-Type: application/pdf
   425 Fetch_Body   b 4 -1 1
   425 BackendClose b localhost

    22 VCL_call     c recv lookup
    22 VCL_call     c hash
    22 Hash         c /images/test.pdf
    22 Hash         c www.localhost.localdomain
    22 VCL_return   c hash
    22 VCL_call     c miss fetch
    22 Backend      c 425 default localhost
    22 TTL          c 1101341981 RFC 120 -1 -1 1315321921 0 1315321920 0 0
    22 VCL_call     c fetch
    22 TTL          c 1101341981 VCL 120 43200 -1 1315321921 -0
    22 TTL          c 1101341981 VCL 1200 43200 -1 1315321921 -0
    22 VCL_return   c deliver
    22 ObjProtocol  c HTTP/1.1
    22 ObjResponse  c OK
    22 ObjHeader    c Date: Tue, 06 Sep 2011 15:12:00 GMT
    22 ObjHeader    c Server: Apache/2.2.3 (CentOS)
    22 ObjHeader    c Last-Modified: Tue, 06 Sep 2011 13:53:29 GMT
    22 ObjHeader    c ETag: "169c519-3688b6-4ac3627026840"
    22 ObjHeader    c Content-Type: application/pdf
    22 FetchError   c straight read_error: -1 12 (Cannot allocate memory)
    22 VCL_call     c error restart
    22 VCL_call     c recv lookup
    22 VCL_call     c hash
    22 Hash         c /images/test.pdf
    22 Hash         c www.localhost.localdomain
    22 VCL_return   c hash
    22 VCL_call     c miss fetch
    22 Backend      c 425 default localhost
    22 TTL          c 1101341981 RFC 120 -1 -1 1315321921 0 1315321920 0 0
    22 VCL_call     c fetch
    22 TTL          c 1101341981 VCL 120 43200 -1 1315321921 -0
    22 TTL          c 1101341981 VCL 1200 43200 -1 1315321921 -0
    22 VCL_return   c deliver
    22 ObjProtocol  c HTTP/1.1
    22 ObjResponse  c OK
    22 ObjHeader    c Date: Tue, 06 Sep 2011 15:12:00 GMT
    22 ObjHeader    c Server: Apache/2.2.3 (CentOS)
    22 ObjHeader    c Last-Modified: Tue, 06 Sep 2011 13:53:29 GMT
    22 ObjHeader    c ETag: "169c519-3688b6-4ac3627026840"
    22 ObjHeader    c Content-Type: application/pdf
    22 FetchError   c straight read_error: -1 12 (Cannot allocate memory)
    22 VCL_call     c error deliver
    22 VCL_call     c deliver deliver
    22 TxProtocol   c HTTP/1.1
    22 TxStatus     c 503
    22 TxResponse   c Service Unavailable
    22 TxHeader     c Server: Varnish
    22 TxHeader     c Content-Type: text/html; charset=utf-8
    22 TxHeader     c Retry-After: 5
    22 TxHeader     c Content-Length: 419
    22 TxHeader     c Accept-Ranges: bytes
    22 TxHeader     c Date: Tue, 06 Sep 2011 15:12:00 GMT
    22 TxHeader     c X-Varnish: 1101341981
    22 TxHeader     c Age: 0
    22 TxHeader     c Via: 1.1 varnish
    22 TxHeader     c Connection: close
    22 Length       c 419
    22 ReqEnd       c 1101341981 1315321920.669218063 1315321920.738457918
 0.000200033 0.069125891 0.000113964
    22 SessionClose c error
    22 StatSess     c 192.168.1.6 10521 0 1 1 0 0 0 257 419

 }}}

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