Varnish 503 on POST requests once in a while
Maninder Singh
mandys at gmail.com
Thu Dec 26 15:12:41 UTC 2019
Another one.
This one is diff error.
* << BeReq >> 19327398
- Begin bereq 19327397 pass
- Timestamp Start: 1577370022.344818 0.000000 0.000000
- BereqMethod POST
- BereqURL /LetsCelebrate
- BereqProtocol HTTP/1.1
- BereqHeader User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X
10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88
Safari/537.36
- BereqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
- BereqHeader Cache-Control: max-age=0
- BereqHeader SSLClientCertStatus: NoClientCert
- BereqHeader X-Forwarded-Proto: https
- BereqHeader Content-Type: multipart/form-data;
boundary=----WebKitFormBoundaryBBVOJciq1v4rbZs9
- BereqHeader Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
- BereqHeader SSLClientCipher: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
version=TLSv1.2, bits=256
- BereqHeader Host: mydomain.com
- BereqHeader Referer: https://mydomain.com/LetsCelebrate
- BereqHeader SSLSessionID:
97258494A3DD008A855B552F701E9F95C25CDC7B1CF5FD63D382ED09391585C7
- BereqHeader Origin: https://mydomain.com
- BereqHeader X-Cluster-Client-Ip: X.X.X.X
- BereqHeader X-Forwarded-Port: 443
- BereqHeader Upgrade-Insecure-Requests: 1
- BereqHeader Sec-Fetch-User: ?1
- BereqHeader Sec-Fetch-Site: same-origin
- BereqHeader Sec-Fetch-Mode: nested-navigate
- BereqHeader Accept-Encoding: gzip, deflate, br
- BereqHeader Content-Length: 2076
- BereqHeader X-Forwarded-For: X.X.X.X, 10.187.187.36
- BereqHeader browser: other
- BereqHeader serverIp: 10.208.225.235
- BereqHeader X-Varnish: 19327398
- VCL_call BACKEND_FETCH
- VCL_return fetch
- BackendOpen 23 reload_2019-12-18T054238.default 127.0.0.1 8080
127.0.0.1 39568
- BackendStart 127.0.0.1 8080
- FetchError req.body read error: 11 (Resource temporarily
unavailable)
- FetchError backend write error: 11 (Resource temporarily
unavailable)
- Timestamp Bereq: 1577370027.344908 5.000090 5.000090
- BackendClose 23 reload_2019-12-18T054238.default
- Timestamp Beresp: 1577370027.345014 5.000196 0.000105
- Timestamp Error: 1577370027.345025 5.000206 0.000011
- BerespProtocol HTTP/1.1
- BerespStatus 503
- BerespReason Service Unavailable
- BerespReason Backend fetch failed
- BerespHeader Date: Thu, 26 Dec 2019 14:20:27 GMT
- BerespHeader Server: Varnish
- VCL_call BACKEND_ERROR
- BerespHeader Content-Type: text/html; charset=utf-8
- BerespHeader Retry-After: 5
- VCL_return deliver
- Storage malloc Transient
- ObjProtocol HTTP/1.1
- ObjStatus 503
- ObjReason Backend fetch failed
- ObjHeader Date: Thu, 26 Dec 2019 14:20:27 GMT
- ObjHeader Server: Varnish
- ObjHeader Content-Type: text/html; charset=utf-8
- ObjHeader Retry-After: 5
- Length 1288
- BereqAcct 1276 0 1276 0 0 0
- End
On Thu, 26 Dec 2019 at 17:27, Maninder Singh <mandys at gmail.com> wrote:
> Got one in the log.
>
> varnishlog -r /var/log/varnish/503.log
> * << BeReq >> 21993384
> - Begin bereq 21993383 pass
> - Timestamp Start: 1577360704.829258 0.000000 0.000000
> - BereqMethod POST
> - BereqURL /corp/contact.php?cf=exitpopup
> - BereqProtocol HTTP/1.1
> - BereqHeader User-Agent: Mozilla/5.0 (Windows NT 6.1; Trident/7.0;
> rv:11.0) like Gecko
> - BereqHeader Accept: image/gif, image/x-xbitmap, image/jpeg,
> image/pjpeg, application/x-shockwave-flash, */*
> - BereqHeader SSLClientCertStatus: NoClientCert
> - BereqHeader X-Forwarded-Proto: https
> - BereqHeader Content-Type: application/x-www-form-urlencoded
> - BereqHeader SSLClientCipher: SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA,
> version=TLSv1, bits=256
> - BereqHeader Host: www.mydomain.com
> - BereqHeader Referer: http://mydomain.com/solutions/enterprise.php
> - BereqHeader SSLSessionID:
> 3C119EF3FE70318789F82E9B583581C876B4DDE520C0182C33CD6AF1AA46E63A
> - BereqHeader X-Cluster-Client-Ip: X.X.X.X
> - BereqHeader Cookie:
> X-Mapping-fjhppofk=E8F494E9A630955F1975EEDF11EBC4D7
> - BereqHeader X-Forwarded-Port: 443
> - BereqHeader Accept-Encoding: gzip, deflate
> - BereqHeader Content-Length: 1366
> - BereqHeader X-Forwarded-For: X.X.X.X, 10.187.187.36
> - BereqHeader browser: other
> - BereqHeader serverIp: 10.208.224.192
> - BereqHeader X-Varnish: 21993384
> - VCL_call BACKEND_FETCH
> - VCL_return fetch
> - BackendOpen 26 reload_2019-12-18T054253.default 127.0.0.1 8080
> 127.0.0.1 59998
> - BackendStart 127.0.0.1 8080
> - Timestamp Bereq: 1577360705.664932 0.835674 0.835674
> - FetchError http first read error: EOF
> - BackendClose 26 reload_2019-12-18T054253.default
> - Timestamp Beresp: 1577360705.665020 0.835763 0.000089
> - Timestamp Error: 1577360705.665028 0.835770 0.000008
> - BerespProtocol HTTP/1.1
> - BerespStatus 503
> - BerespReason Service Unavailable
> - BerespReason Backend fetch failed
> - BerespHeader Date: Thu, 26 Dec 2019 11:45:05 GMT
> - BerespHeader Server: Varnish
> - VCL_call BACKEND_ERROR
> - BerespHeader Content-Type: text/html; charset=utf-8
> - BerespHeader Retry-After: 5
> - VCL_return deliver
> - Storage malloc Transient
> - ObjProtocol HTTP/1.1
> - ObjStatus 503
> - ObjReason Backend fetch failed
> - ObjHeader Date: Thu, 26 Dec 2019 11:45:05 GMT
> - ObjHeader Server: Varnish
> - ObjHeader Content-Type: text/html; charset=utf-8
> - ObjHeader Retry-After: 5
> - Length 1288
> - BereqAcct 849 1366 2215 0 0 0
> - End
>
> On Thu, 26 Dec 2019 at 15:21, Maninder Singh <mandys at gmail.com> wrote:
>
>> Okay. Let me set it up and get back to you once i see something in that
>> log. It happens only once/twice a day so could be a while before i get
>> back.
>>
>> On Thu, 26 Dec, 2019, 3:10 pm Guillaume Quintard, <
>> guillaume at varnish-software.com> wrote:
>>
>>> Hi,
>>>
>>> Most probably, varnishncsa isn't going to give you the full picture, so
>>> let's go for the exhaustive way:
>>>
>>> varnishlog -q "BerespStatus eq 503" -w /whatever/file
>>>
>>>
>>> you can then read the logs with
>>>
>>> varnishlog -r /whatever/file
>>>
>>>
>>> (more logging pointers here:
>>> https://docs.varnish-software.com/tutorials/vsl-query/)
>>>
>>> If you can get your hands on a failed transaction, we should be able to
>>> tell you what went wrong. Most probably, you hit a timeout of some sort. Or
>>> it could be that the backend was declared sick, if you have probes.
>>>
>>> --
>>> Guillaume Quintard
>>>
>>>
>>> On Thu, Dec 26, 2019 at 6:33 AM Maninder Singh <mandys at gmail.com> wrote:
>>>
>>>> Hi,
>>>>
>>>> I am facing a strange problem.
>>>>
>>>> I am running varnish 4.1.11 on port 80 which is behind a LB.
>>>>
>>>> Varnish then connects to apache 2.4 ( on port 8080 ) and also have
>>>> php-fpm running.
>>>>
>>>> Now, everything works fine but once in a while I am seeing 503 response
>>>> from varnish for a POST request. During this time there is no log in apache
>>>> also ( neither access log nor error log ).
>>>>
>>>> Where does this request vanish ?
>>>>
>>>> How do I debug this issue ?
>>>>
>>>> Some more details:
>>>>
>>>> * I have varnishncsa turned on with following flags.
>>>>
>>>> ExecStart=/usr/bin/varnishncsa -q 'not (ReqURL ~
>>>> "\.(js|css|png|jpeg|jpg|ico|gif|swf|woff)" or ReqHeader:User-Agent ~
>>>> "HTTP-Monitor" or ReqHeader:User-Agent ~ "Monitoring/1.1")' -a -w
>>>> /var/log/varnish/varnishncsa.log -D -f /etc/sysconfig/varnishncsa
>>>>
>>>> Here is the entry in varnish log during that time.
>>>>
>>>> X.X.X.X, LB.IP.0.0 - - [25/Dec/2019:00:26:40 -0600] 2629363 "POST
>>>> http://mydomain.com/LetsCelebrate HTTP/1.1" 503 1288 "
>>>> https://referringdomain.com/LetsCelebrate?hostingUrl=https%3A%2F%2Fxy.abc.com"
>>>> "Mozilla/5.0 (Linux; Android 9; SM-A920F) AppleWebKit/537.36 (KHTML, like
>>>> Gecko) Chrome/79.0.3945.93 Mobile Safari/537.36" "mydomain.com" miss
>>>>
>>>> In .vcl file I have following set.
>>>> .first_byte_timeout = 120s;
>>>>
>>>> Now, I am not logging varnish to apache requests ( which backend fetch
>>>> ).
>>>> As you can see above I am only logging client requests.
>>>>
>>>> Is their a way to log client requests like above but then also log
>>>> backend fetch failures to another log file ?
>>>> [ Running 2 instances of varnishncsa ? ]
>>>>
>>>> Any pointers ?
>>>>
>>>> Please let me know.
>>>>
>>>> Thanks.
>>>>
>>>> _______________________________________________
>>>> varnish-misc mailing list
>>>> varnish-misc at varnish-cache.org
>>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>>
>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20191226/6903312d/attachment.html>
More information about the varnish-misc
mailing list