#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 thomaslc):
Think I have the problem too. For me it seems a piped POST request fails
when it reuses a backend connection that previously PASSed requests. It
works when retrying after a failure because a new backend connection is
opened.
Here is the (anonymized) varnishlog output. The client does a first
request that ends up in a pass, and then a second one ending up with a
pipe.
{{{
* << Session >> 21123429
- Begin sess 0 HTTP/1
- SessOpen CLIENT_IP 32470 :80 VARNISH_IP 80 1452591080.300133 51
- Link req 21123430 rxreq
- SessClose REM_CLOSE 5.135
- End
** << Request >> 21123430
-- Begin req 21123429 rxreq
-- Timestamp Start: 1452591080.300852 0.000000 0.000000
-- Timestamp Req: 1452591080.300852 0.000000 0.000000
-- ReqStart CLIENT_IP 32470
-- ReqMethod GET
-- ReqURL /images/REDACTED
-- ReqProtocol HTTP/1.1
-- ReqHeader Host: img.directindustry.fr
-- ReqHeader Connection: keep-alive
-- ReqHeader Pragma: no-cache
-- ReqHeader Cache-Control: no-cache
-- ReqHeader Accept: image/webp,image/*,*/*;q=0.8
-- ReqHeader User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36
-- ReqHeader DNT: 1
-- ReqHeader Referer:
http://REDACTED -- ReqHeader Accept-Encoding: gzip, deflate, sdch
-- ReqHeader Accept-Language: en-US,en;q=0.8,fr;q=0.6
-- ReqHeader Cookie: cookieAllowed=1;
__gads=ID=8e63413b2db7cdc9:T=1445582966:S=ALNI_MbI6b5xwPjrR2dJO-
5YVDmoZxGDng; __unam=409b964-1509375ef74-804c90-9;
kameleoonVisit=6l6b56grglamufva/0/1445583360532/20150708/0/;
__utma=115893401.330538632.1444723972.1445582991.1448
-- ReqHeader X-Forwarded-For: CLIENT_IP
-- VCL_call RECV
-- ReqHeader X-Int-Backend: orig
-- ReqUnset X-Forwarded-For: CLIENT_IP
-- ReqHeader X-Forwarded-For: CLIENT_IP
-- ReqHeader X-VE-Hops: 1
-- ReqUnset Accept-Encoding: gzip, deflate, sdch
-- ReqHeader Accept-Encoding: gzip
-- ReqUnset Cookie: cookieAllowed=1;
__gads=ID=8e63413b2db7cdc9:T=1445582966:S=ALNI_MbI6b5xwPjrR2dJO-
5YVDmoZxGDng; __unam=409b964-1509375ef74-804c90-9;
kameleoonVisit=6l6b56grglamufva/0/1445583360532/20150708/0/;
__utma=115893401.330538632.1444723972.1445582991.1448
-- ReqHeader X-Host-Subdomain: img
-- VCL_return pass
-- VCL_call HASH
-- ReqHeader X-VE-Host: img.directindustry
-- VCL_return lookup
-- VCL_call PASS
-- ReqHeader X-Varnish-Mode: pass
-- VCL_return fetch
-- Link bereq 21123431 pass
-- Timestamp Fetch: 1452591080.386848 0.085996 0.085996
-- RespProtocol HTTP/1.1
-- RespStatus 200
-- RespReason OK
-- RespHeader Date: Tue, 12 Jan 2016 09:31:20 GMT
-- RespHeader Server: Apache
-- RespHeader Last-Modified: Mon, 01 Dec 2014 13:59:16 GMT
-- RespHeader ETag: "2a8403d-4c8-50928041f647c"
-- RespHeader Content-Length: 1224
-- RespHeader X-From: 3-10 in D=365 microseconds
-- RespHeader X-Content-Type-Options: nosniff
-- RespHeader X-XSS-Protection: 1; mode=block
-- RespHeader Content-Type: image/gif
-- RespHeader X-Varnish-Origin-TTL: 0.000
-- RespHeader X-Cache: nc[arz01/s] conn[>origin]
-- RespHeader X-Host: img.directindustry.fr
-- RespHeader X-Url: /images_di/REDACTED
-- RespHeader X-Host-Subdomain: img
-- RespHeader X-Varnish-Retries: 0
-- RespHeader X-Varnish: 21123430
-- RespHeader Age: 0
-- RespHeader Via: 1.1 varnish-v4
-- VCL_call DELIVER
-- VCL_Log VEMR:-
-- RespUnset X-Varnish-Retries: 0
-- RespUnset X-From: 3-10 in D=365 microseconds
-- RespUnset X-Host-Subdomain: img
-- RespUnset X-Url: /images_di/REDACTED
-- RespUnset X-Varnish-Origin-TTL: 0.000
-- RespUnset Via: 1.1 varnish-v4
-- RespUnset X-Varnish: 21123430
-- RespUnset X-Host: img.directindustry.fr
-- VCL_return deliver
-- Timestamp Process: 1452591080.386898 0.086046 0.000050
-- RespHeader Accept-Ranges: bytes
-- Debug "RES_MODE 2"
-- RespHeader Connection: keep-alive
-- Timestamp Resp: 1452591080.386958 0.086106 0.000060
-- ReqAcct 876 0 876 356 1224 1580
-- End
*** << BeReq >> 21123431
--- Begin bereq 21123430 pass
--- Timestamp Start: 1452591080.302007 0.000000 0.000000
--- BereqMethod GET
--- BereqURL /images_di/REDACTED
--- BereqProtocol HTTP/1.1
--- BereqHeader Host: img.directindustry.fr
--- BereqHeader Pragma: no-cache
--- BereqHeader Cache-Control: no-cache
--- BereqHeader Accept: image/webp,image/*,*/*;q=0.8
--- BereqHeader User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36
--- BereqHeader DNT: 1
--- BereqHeader Referer:
http://www.directindustry.fr/BACKOFFICE--- REDACTED
--- BereqHeader Accept-Language: en-US,en;q=0.8,fr;q=0.6
--- BereqHeader X-Int-Backend: orig
--- BereqHeader X-Forwarded-For: CLIENT_IP
--- BereqHeader X-VE-Hops: 1
--- BereqHeader Accept-Encoding: gzip
--- BereqHeader X-Host-Subdomain: img
--- BereqHeader X-VE-Host: img.directindustry
--- BereqHeader X-Varnish-Mode: pass
--- BereqHeader X-Varnish: 21123431
--- VCL_call BACKEND_FETCH
--- BereqProtocol HTTP/1.1
--- VCL_return fetch
--- BackendOpen 56 c62563df-b4d7-421a-915e-5c448e453d00.agk01
BACKEND_IP 80 VARNISH_IP 33974
--- Timestamp Bereq: 1452591080.331480 0.029472 0.029472
--- Timestamp Beresp: 1452591080.386700 0.084693 0.055221
--- BerespProtocol HTTP/1.1
--- BerespStatus 200
--- BerespReason OK
--- BerespHeader Date: Tue, 12 Jan 2016 09:31:20 GMT
--- BerespHeader Server: Apache
--- BerespHeader Last-Modified: Mon, 01 Dec 2014 13:59:16 GMT
--- BerespHeader ETag: "2a8403d-4c8-50928041f647c"
--- BerespHeader Accept-Ranges: bytes
--- BerespHeader Content-Length: 1224
--- BerespHeader X-From: 3-10 in D=365 microseconds
--- BerespHeader X-Content-Type-Options: nosniff
--- BerespHeader X-XSS-Protection: 1; mode=block
--- BerespHeader Content-Type: image/gif
--- TTL RFC 432000 10 -1 1452591080 1452591080 1452591080 0 0
--- VCL_call BACKEND_RESPONSE
--- BerespHeader X-Varnish-Origin-TTL: 0.000
--- TTL VCL -1 60 0 1452591080
--- BerespHeader X-Cache: conn[>origin]
--- BerespUnset X-Cache: conn[>origin]
--- BerespHeader X-Cache: nc[arz01/s] conn[>origin]
--- BerespHeader X-Host: img.directindustry.fr
--- BerespHeader X-Url: /images_di/REDACTED
--- BerespHeader X-Host-Subdomain: img
--- BerespHeader X-Varnish-Retries: 0
--- BerespUnset Accept-Ranges: bytes
--- VCL_return deliver
--- Storage malloc Transient
--- ObjProtocol HTTP/1.1
--- ObjStatus 200
--- ObjReason OK
--- ObjHeader Date: Tue, 12 Jan 2016 09:31:20 GMT
--- ObjHeader Server: Apache
--- ObjHeader Last-Modified: Mon, 01 Dec 2014 13:59:16 GMT
--- ObjHeader ETag: "2a8403d-4c8-50928041f647c"
--- ObjHeader Content-Length: 1224
--- ObjHeader X-From: 3-10 in D=365 microseconds
--- ObjHeader X-Content-Type-Options: nosniff
--- ObjHeader X-XSS-Protection: 1; mode=block
--- ObjHeader Content-Type: image/gif
--- ObjHeader X-Varnish-Origin-TTL: 0.000
--- ObjHeader X-Cache: nc[arz01/s] conn[>origin]
--- ObjHeader X-Host: img.directindustry.fr
--- ObjHeader X-Url: /images/REDACTED
--- ObjHeader X-Host-Subdomain: img
--- ObjHeader X-Varnish-Retries: 0
--- Fetch_Body 3 length stream
--- BackendReuse 56 c62563df-b4d7-421a-915e-5c448e453d00.agk01
--- Timestamp BerespBody: 1452591080.386850 0.084843 0.000150
--- Length 1224
--- BereqAcct 603 0 603 324 1224 1548
--- End
* << Session >> 73570869
- Begin sess 0 HTTP/1
- SessOpen CLIENT_IP 31052 :80 VARNISH_IP 80 1452591082.783081 64
- Link req 73570870 rxreq
- SessClose TX_PIPE 10.172
- End
** << Request >> 73570870
-- Begin req 73570869 rxreq
-- Timestamp Start: 1452591082.784323 0.000000 0.000000
-- Timestamp Req: 1452591082.784323 0.000000 0.000000
-- ReqStart CLIENT_IP 31052
-- ReqMethod POST
-- ReqURL /AJAX---REDACTED
-- ReqProtocol HTTP/1.1
-- ReqHeader Host: www.directindustry.fr
-- ReqHeader Connection: keep-alive
-- ReqHeader Content-Length: 280
-- ReqHeader Pragma: no-cache
-- ReqHeader Cache-Control: no-cache
-- ReqHeader Accept: */*
-- ReqHeader Origin:
http://www.directindustry.fr -- ReqHeader X-Requested-With: XMLHttpRequest
-- ReqHeader User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36
-- ReqHeader Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
-- ReqHeader DNT: 1
-- ReqHeader Referer:
http://www.directindustry.fr/BACKOFFICE--- REDACTED
-- ReqHeader Accept-Encoding: gzip, deflate
-- ReqHeader Accept-Language: en-US,en;q=0.8,fr;q=0.6
-- ReqHeader Cookie: REDACTED
-- ReqHeader X-Forwarded-For: CLIENT_IP
-- VCL_call RECV
-- ReqHeader X-Int-Backend: orig
-- ReqUnset X-Forwarded-For: CLIENT_IP
-- ReqHeader X-Forwarded-For: CLIENT_IP
-- ReqHeader X-VE-Hops: 1
-- ReqUnset Accept-Encoding: gzip, deflate
-- ReqHeader Accept-Encoding: gzip
-- VCL_return pipe
-- VCL_call HASH
-- VCL_return lookup
-- Link bereq 73570871 pipe
-- Timestamp Pipe: 1452591082.785460 0.001137 0.001137
-- Timestamp PipeSess: 1452591092.955365 10.171043 10.169906
-- PipeAcct 1378 1478 280 527
-- End
*** << BeReq >> 73570871
--- Begin bereq 73570870 pipe
--- BereqMethod POST
--- BereqURL /AJAX---REDACTED
--- BereqProtocol HTTP/1.1
--- BereqHeader Host: www.directindustry.fr
--- BereqHeader Connection: keep-alive
--- BereqHeader Content-Length: 280
--- BereqHeader Pragma: no-cache
--- BereqHeader Cache-Control: no-cache
--- BereqHeader Accept: */*
--- BereqHeader Origin:
http://www.directindustry.fr --- BereqHeader X-Requested-With: XMLHttpRequest
--- BereqHeader User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36
--- BereqHeader Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
--- BereqHeader DNT: 1
--- BereqHeader Referer:
http://www.directindustry.fr/BACKOFFICE--- REDACTED
--- BereqHeader Accept-Language: en-US,en;q=0.8,fr;q=0.6
--- BereqHeader Cookie: callerLoad=function
editProduct(productID,containerID){load('Product-
editProduct',{productID:productID,containerID:containerID},function(request){openProduts([productID],request.getResponseHeader('containerIDs').split(','),productID);
callerGet=f
--- BereqHeader X-Int-Backend: orig
--- BereqHeader X-Forwarded-For: CLIENT_IP
--- BereqHeader X-VE-Hops: 1
--- BereqHeader Accept-Encoding: gzip
--- BereqHeader X-Varnish: 73570870
--- BereqHeader Connection: close
--- VCL_call PIPE
--- VCL_return pipe
--- BackendOpen 56 c62563df-b4d7-421a-915e-5c448e453d00.agk01
BACKEND_IP 80 VARNISH_IP 33974
--- Timestamp Bereq: 1452591082.785452 0.000000 0.000000
--- BackendClose 56 c62563df-b4d7-421a-915e-5c448e453d00.agk01
--- BereqAcct 0 0 0 0 0 0
--- End
}}}
The thing that got my attention was that the first request does a
BackendReuse on the backend connection 56. Then, the next request starts a
pipe (because ReqURL matches a specific backend URL). There, varnish does
a BackendOpen on 56, not a BackendReuse.
The tcpdump performed on the backend shows a rather weird sequence:
{{{
4 2016-01-12 10:16:30.494287 46.37.4.239 10.80.30.11
HTTP 669 GET /images_di/IMAGE---URL 0 HTTP/1.1
7 2016-01-12 10:16:30.498630 10.80.30.11 46.37.4.239
HTTP 247 HTTP/1.1 200 OK (GIF89a)
11 2016-01-12 10:16:42.835985 10.80.30.11 46.37.4.239
HTTP 593 HTTP/1.1 503 Service Unavailable (text/html)[Malformed
Packet]
14 2016-01-12 10:16:42.864200 46.37.4.239 10.80.30.11
HTTP 346 POST /BACKOFFICE---URL HTTP/1.1 (application/x-www-form-
urlencoded)
}}}
As you can see, the 503 error is sent by the backend BEFORE the piped
request is sent by varnish. This extract shows only the HTTP stuff. I can
send the complete PCAP dump with the TCP stuff by e-mail (it contains
sensitive data).
Thanks
Thomas
--
Ticket URL: <
https://www.varnish-cache.org/trac/ticket/1806#comment:13>
Varnish <
https://varnish-cache.org/>
The Varnish HTTP Accelerator
_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs