Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: Varnish: Bugs

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

 

 

Varnish bugs RSS feed   Index | Next | Previous | View Threaded


varnish-bugs at varnish-cache

Jun 18, 2012, 6:40 AM

Post #1 of 7 (147 views)
Permalink
#1156: first_byte_timeout is "doubled" on the client side when keep-alive is used

#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: |
-------------------+--------------------------------------------------------
I'm experiencing a problem with first_byte_timeout in keepalive
connections. For the second request, if the backend doesn't respond within
the timeout, the backend connection will be closed (normal), but the 503
response will not be sent to the client immediately ... it's gonna take an
additional first_byte_timeout sec for 503 error response to be sent to the
client ...

So if you have a 5s timeout, after 5s the backend connection is closed,
but it's gonna take 10s for the 503 response to be sent out ...

Confirmed on 3.0.3 rc1 and master

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jun 18, 2012, 6:45 AM

Post #2 of 7 (145 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

#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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jun 18, 2012, 6:52 AM

Post #3 of 7 (145 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

#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 kristian):

Block:
{{{
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:2>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jun 18, 2012, 7:28 AM

Post #4 of 7 (148 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

#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):

A bit more investigation turned some more infos:

- The request is actually retried on a new backend connection, which is
why it takes twice as much time
- It doesn't happen on the first connection because there is no 'retry'
for fresh new backend connections.

What happens is that the code that retries request to a backend in case of
keepalive (like is the backend closes the connection) decides to retry the
request ... But that's not an acceptable behavior for a 'timeout' error,
only for things like connection reset or if the request couldn't be sent
but not timeout on the response.

To check if this was really the source of the problem I tried this hack:

{{{
diff --git a/bin/varnishd/cache/cache_fetch.c
b/bin/varnishd/cache/cache_fetch.c
index 7ccba0a..f71cd45 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -510,7 +510,7 @@ FetchHdr(struct sess *sp, int need_host_hdr, int
sendbody)
VDI_CloseFd(&bo->vbc);
/* XXX: other cleanup ? */
/* Retryable if we never received anything */
- return (i == -1 ? retry : -1);
+ return -1;
}

VTCP_set_read_timeout(vc->fd, vc->between_bytes_timeout);
}}}

(It's obviously not a 'fix' because it disables retry in all cases but
that was just to confirm the source of the issue).

Ideally we'd need to know if HTC_Rx timed out or had a real error.

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jul 2, 2012, 4:12 AM

Post #5 of 7 (119 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

#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):

Any progress on this ?

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jul 31, 2012, 1:06 AM

Post #6 of 7 (97 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

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

Comment (by Poul-Henning Kamp <phk@…>):

In [feac37150e5820cb36b0181811a47b957cd9b51c]:
{{{
#!CommitTicketReference repository=""
revision="feac37150e5820cb36b0181811a47b957cd9b51c"
Don't do automatic backend retry if we have received anything from the
backend at all. The retry is only (pseudo-)valid when we have not
received
anything at all, indicating that the backend closed before it got our
request.

Also don't retry if we sent the request body (not part of test-case).

Fixes #1156
}}}

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs


varnish-bugs at varnish-cache

Jul 31, 2012, 1:06 AM

Post #7 of 7 (98 views)
Permalink
Re: #1156: first_byte_timeout is "doubled" on the client side when keep-alive is used [In reply to]

#1156: first_byte_timeout is "doubled" on the client side when keep-alive is used
----------------------+---------------------
Reporter: tnt | Owner:
Type: defect | Status: closed
Priority: normal | Milestone:
Component: varnishd | Version: trunk
Severity: normal | Resolution: fixed
Keywords: |
----------------------+---------------------
Changes (by Poul-Henning Kamp <phk@…>):

* status: new => closed
* resolution: => fixed


Comment:

(In [feac37150e5820cb36b0181811a47b957cd9b51c]) Don't do automatic backend
retry if we have received anything from the
backend at all. The retry is only (pseudo-)valid when we have not
received
anything at all, indicating that the backend closed before it got our
request.

Also don't retry if we sent the request body (not part of test-case).

Fixes #1156

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs

Varnish bugs RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.