[Varnish] #1806: one minute delay on return (pipe) and a POST-Request

[Varnish]

#1806: one minute delay on return (pipe) and a POST-Request
----------------------+-----------------------
 Reporter:  butzi     |       Owner:
     Type:  defect    |      Status:  needinfo
 Priority:  normal    |   Milestone:
Component:  varnishd  |     Version:  4.1.0
 Severity:  major     |  Resolution:
 Keywords:            |
----------------------+-----------------------

Comment (by butzi):

 Yes, i can reproduce this.

 It makes no sense to me, when i handle the request with "return(pass)"
 instead of "return(pipe)" that it is not a varnish problem, right? The
 backends are not having the problems, when i access them without varnish.

 the client request:
 {{{
 *   << Request  >> 380191421
 -   Begin          req 380191413 rxreq
 -   Timestamp      Start: 1446459772.600275 0.000000 0.000000
 -   Timestamp      Req: 1446459772.600275 0.000000 0.000000
 -   ReqStart       37.49.xxx.xxx 34154
 -   ReqMethod      POST
 -   ReqURL         /index.php?cl=ecs_prudsys_recos_ajax
 -   ReqProtocol    HTTP/1.1
 -   ReqHeader      Host: domain.tld
 -   ReqHeader      Connection: keep-alive
 -   ReqHeader      Content-Length: 97
 -   ReqHeader      Accept: application/json, text/javascript, */*; q=0.01
 -   ReqHeader      Origin: http://domain.tld
 -   ReqHeader      X-Requested-With: XMLHttpRequest
 -   ReqHeader      User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64)
 AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36
 -   ReqHeader      Content-Type: application/x-www-form-urlencoded;
 charset=UTF-8
 -   ReqHeader      Referer: http://domain.tld
 -   ReqHeader      Accept-Encoding: gzip, deflate
 -   ReqHeader      Accept-Language: fr-FR,fr;q=0.8,en-US;q=0.6,en;q=0.4
 -   ReqHeader      Cookie: _ems_visitor=650367453.533136231;
 heias_0=a%3A2%3A%7Bi%3A0%3Bs%3A4%3A%22TRUE%22%3Bi%3A1%3Bi%3A1446458945%3B%7D;
 heias_sc=1; ctest2=1; SHOPDIRECT=none; sid_key=oxid; ecsadmatch=1;
 heias_pid=144645894528888948380; recoUser2session=0; language=3; re
 -   ReqHeader      X-Forwarded-For: 77.157.xxx.xxx
 -   ReqHeader      X-Real-IP: 77.157.xxx.xxx
 -   ReqHeader      X-CBR-IP: 77.157.xxx.xxx
 -   ReqUnset       X-Forwarded-For: 77.157.xxx.xxx
 -   ReqHeader      X-Forwarded-For: 77.157.xxx.xxx, 37.49.xxx.xxx
 -   VCL_call       RECV
 -   ReqHeader      X-UA-Device: Desktop
 -   ReqHeader      x-url: /index.php?cl=ecs_prudsys_recos_ajax
 -   ReqHeader      x-esi-level: 0
 -   VCL_return     pipe
 -   VCL_call       HASH
 -   ReqURL         /index.php?cl=ecs_prudsys_recos_ajax
 -   VCL_return     lookup
 -   Link           bereq 380191422 pipe
 -   Timestamp      Pipe: 1446459772.600482 0.000207 0.000207
 -   Timestamp      PipeSess: 1446459832.773508 60.173233 60.173026
 -   PipeAcct       1086 1200 97 7360
 -   End

 }}}

 the server request:
 {{{
 *   << BeReq    >> 380191422
 -   Begin          bereq 380191421 pipe
 -   BereqMethod    POST
 -   BereqURL       /index.php?cl=ecs_prudsys_recos_ajax
 -   BereqProtocol  HTTP/1.1
 -   BereqHeader    Host: domain.tld
 -   BereqHeader    Connection: keep-alive
 -   BereqHeader    Content-Length: 97
 -   BereqHeader    Accept: application/json, text/javascript, */*; q=0.01
 -   BereqHeader    Origin: http://domain.tld
 -   BereqHeader    X-Requested-With: XMLHttpRequest
 -   BereqHeader    User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64)
 AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.80 Safari/537.36
 -   BereqHeader    Content-Type: application/x-www-form-urlencoded;
 charset=UTF-8
 -   BereqHeader    Referer: http://domain.tld
 -   BereqHeader    Accept-Encoding: gzip, deflate
 -   BereqHeader    Accept-Language: fr-FR,fr;q=0.8,en-US;q=0.6,en;q=0.4
 -   BereqHeader    Cookie: _ems_visitor=650367453.533136231;
 heias_0=a%3A2%3A%7Bi%3A0%3Bs%3A4%3A%22TRUE%22%3Bi%3A1%3Bi%3A1446458945%3B%7D;
 heias_sc=1; ctest2=1; SHOPDIRECT=none; sid_key=oxid; ecsadmatch=1;
 heias_pid=144645894528888948380; recoUser2session=0; language=3; re
 -   BereqHeader    X-Real-IP: 77.157.xxx.xxx
 -   BereqHeader    X-CBR-IP: 77.157.xxx.xxx
 -   BereqHeader    X-Forwarded-For: 77.157.xxx.xxx, 37.49.xxx.xxx
 -   BereqHeader    X-UA-Device: Desktop
 -   BereqHeader    x-url: /index.php?cl=ecs_prudsys_recos_ajax
 -   BereqHeader    x-esi-level: 0
 -   BereqHeader    X-Varnish: 380191421
 -   BereqHeader    Connection: close
 -   VCL_call       PIPE
 -   BereqUnset     Connection: keep-alive
 -   BereqUnset     Connection: close
 -   BereqHeader    connection: close
 -   VCL_return     pipe
 -   BackendOpen    47 u1.prodas06 10.4.132.21 80 10.4.132.2 59156
 -   Timestamp      Bereq: 1446459772.600479 0.000000 0.000000
 -   BackendClose   47 u1.prodas06
 -   BereqAcct      0 0 0 0 0 0
 -   End
 }}}

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1806#comment:2>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator