[Varnish] #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used

Mon Jun 18 15:45:37 CEST 2012

#1156: first_byte_timeout is "doubled" on the client side when keep-alive is used
-------------------+--------------------------------------------------------
 Reporter:  tnt    |        Type:  defect  
   Status:  new    |    Priority:  normal  
Milestone:         |   Component:  varnishd
  Version:  trunk  |    Severity:  normal  
 Keywords:         |  
-------------------+--------------------------------------------------------

Comment(by tnt):

 The log was generated with a timeout set to 7 sec.

 The call was to a test api that sleep(). The first request is immediate
 sleep(0) and the second is a sleep(15). You can see it took 14 sec (i.e.
 2*first_byte_timeout) to return ...

 time curl -v http://127.0.0.1:8080/wait/0/0
 http://127.0.0.1:8080/wait/15/15
 * About to connect() to 127.0.0.1 port 8080 (#0)
 *   Trying 127.0.0.1...
 * connected
 * Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
 > GET /wait/0/0 HTTP/1.1
 > User-Agent: curl/7.24.0 (x86_64-pc-linux-gnu) libcurl/7.24.0
 OpenSSL/1.0.0j zlib/1.2.5.1
 > Host: 127.0.0.1:8080
 > Accept: */*
 >
 < HTTP/1.1 200 OK
 < Content-Type: text/html; charset=utf-8
 < Transfer-Encoding: chunked
 < Date: Mon, 18 Jun 2012 13:42:46 GMT
 < Age: 0
 < Connection: keep-alive
 < Server: nydb
 <
 0
 EIxmOPybgttZFnLuUaqFejykKywwTXchVHuTgprbuqDglSNzMjxhHtORqMzzGnGvCgPZOBUgSnNmihaIKajtayotYYyiJWBGSUySDLSqTdscyUhnJambtvOhUOLhqSvaJpNcpKZsMjyJfVtRmsyMvczrmAaZPYTurREWNNtRbQjbBxnYUlqMnAkhFJpxiPxMNxTTuoegjjzChhbEhCAiZsAHQChvZfcjniiyPTUXbOokCDRZtupkGFfxHuJDfTcLaoOehTGoXgsiUWOpCUVMAXrcNAQGfTvMxsgznKbWbKnKIajApEfOrnJvGNQluYwxCJsQSZaPAczVISxnRlCnWrtrdgeGiYIwpRwIrVEiOUsKTAeWPVaexIQproTtTjhBuBBsTrRnByrQOkZdsuRzFwZLviEVvlmwwoGVJtNbrIHBbpvBGXXxjeCJamfeuGcDddWxpxhQOQZlYtUfeDkmWFJuEUOzzooCazNVghMbLyXZoiCGjcouSKRJTPAGZUFNaxvtYeiiXseDdjxxormLXDzxVmMbwIKXjPyzZOqBuutCbfdhYOcvQsKcmFwJbfzjQrhlpbMpBiUiGHdCTOISvzaIPlwKSnezGDvPZNTStShuepzTNwsQOjfguHRwGIyVhrIsKpUwnOOXjSaplMwnsFvOueUKDcVzGASaFfoYltrLSiKKxCbhYKVISGyrRRLAsEreRPOPFMRJzqKwZdyjvLVYockohBucvppEqTWJYqmuOvTRXJTwcAsHlVmDXsUYrNQFohZxCuoAmJEmKJvYwMJaCAhiuSIbhowygpOHqjKeEaHUxcupEbxRGLGXLnScUUHLcxOCKzpvwddOfkgkMUjydCrLJiggTffPMQQLIkqmyaLnKAehyFTjdiuKldxcsIuIaTMELcaJKsBcdXEGqmLVGKDraPTwSaKjwFMFcWCYxIGSZfrrxZVWOChxANTFUTDFofUyjZytpwrZdjoHAOknSKeNVhLEdqdUIktcMdhHKyWQukZfqQrUNptmqHJL
 0
 * Connection #0 to host 127.0.0.1 left intact
 * Re-using existing connection! (#0) with host (nil)
 * Connected to (nil) (127.0.0.1) port 8080 (#0)
 > GET /wait/15/15 HTTP/1.1
 > User-Agent: curl/7.24.0 (x86_64-pc-linux-gnu) libcurl/7.24.0
 OpenSSL/1.0.0j zlib/1.2.5.1
 > Host: 127.0.0.1:8080
 > Accept: */*
 >
 < HTTP/1.1 503 Service Unavailable
 < Content-Type: text/html; charset=utf-8
 < Retry-After: 5
 < Content-Length: 419
 < Accept-Ranges: bytes
 < Date: Mon, 18 Jun 2012 13:43:00 GMT
 < Age: 14
 < Connection: close
 < Server: nydb
 <

 <?xml version="1.0" encoding="utf-8"?>
 <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN"
  "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
 <html>
   <head>
     <title>503 Service Unavailable</title>
   </head>
   <body>
     <h1>Error 503 Service Unavailable</h1>
     <p>Service Unavailable</p>
     <h3>Guru Meditation:</h3>
     <p>XID: 1754534937</p>
     <hr>
     <p>Varnish cache server</p>
   </body>
 </html>
 * Closing connection #0

 real    0m14.075s
 user    0m0.000s
 sys     0m0.004s

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