<div dir="auto">I only have php-fpm slow logging for requests greater than 5secs. Otherwise it should be all defaults for varnish/apache/fpm. <div dir="auto"><br></div><div dir="auto">Does varnish or apache have anything defaulting to 5secs?</div><div dir="auto"><br></div><div dir="auto">Otherwise fpm might be closing the connection for logging a slow request ? Strange?</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 26 Dec, 2019, 10:44 pm Guillaume Quintard, <<a href="mailto:guillaume@varnish-software.com">guillaume@varnish-software.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">The first looks like the backend is just closing the door on you. The other one (Resource temporarily unavailable), because of the Timestamp:Beresp, is most probably a timeout (did you set anything to 5s?)<div><br clear="all"><div><div dir="ltr" data-smartmail="gmail_signature"><div dir="ltr"><div>-- <br></div>Guillaume Quintard<br></div></div></div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, Dec 26, 2019 at 3:12 PM Maninder Singh <<a href="mailto:mandys@gmail.com" target="_blank" rel="noreferrer">mandys@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Another one.<div>This one is diff error.</div><div><br></div><div>* << BeReq >> 19327398<br>- Begin bereq 19327397 pass<br>- Timestamp Start: 1577370022.344818 0.000000 0.000000<br>- BereqMethod POST<br>- BereqURL /LetsCelebrate<br>- BereqProtocol HTTP/1.1<br>- 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<br>- 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<br>- BereqHeader Cache-Control: max-age=0<br>- BereqHeader SSLClientCertStatus: NoClientCert<br>- BereqHeader X-Forwarded-Proto: https<br>- BereqHeader Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryBBVOJciq1v4rbZs9<br>- BereqHeader Accept-Language: en-GB,en-US;q=0.9,en;q=0.8<br>- BereqHeader SSLClientCipher: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384, version=TLSv1.2, bits=256<br>- BereqHeader Host: <a href="http://mydomain.com" target="_blank" rel="noreferrer">mydomain.com</a><br>- BereqHeader Referer: <a href="https://mydomain.com/LetsCelebrate" target="_blank" rel="noreferrer">https://mydomain.com/LetsCelebrate</a><br>- BereqHeader SSLSessionID: 97258494A3DD008A855B552F701E9F95C25CDC7B1CF5FD63D382ED09391585C7<br>- BereqHeader Origin: <a href="https://mydomain.com" target="_blank" rel="noreferrer">https://mydomain.com</a><br>- BereqHeader X-Cluster-Client-Ip: X.X.X.X<br>- BereqHeader X-Forwarded-Port: 443<br>- BereqHeader Upgrade-Insecure-Requests: 1<br>- BereqHeader Sec-Fetch-User: ?1<br>- BereqHeader Sec-Fetch-Site: same-origin<br>- BereqHeader Sec-Fetch-Mode: nested-navigate<br>- BereqHeader Accept-Encoding: gzip, deflate, br<br>- BereqHeader Content-Length: 2076<br>- BereqHeader X-Forwarded-For: X.X.X.X, 10.187.187.36<br>- BereqHeader browser: other<br>- BereqHeader serverIp: 10.208.225.235<br>- BereqHeader X-Varnish: 19327398<br>- VCL_call BACKEND_FETCH<br>- VCL_return fetch<br>- BackendOpen 23 reload_2019-12-18T054238.default 127.0.0.1 8080 127.0.0.1 39568<br>- BackendStart 127.0.0.1 8080<br>- FetchError req.body read error: 11 (Resource temporarily unavailable)<br>- FetchError backend write error: 11 (Resource temporarily unavailable)<br>- Timestamp Bereq: 1577370027.344908 5.000090 5.000090<br>- BackendClose 23 reload_2019-12-18T054238.default<br>- Timestamp Beresp: 1577370027.345014 5.000196 0.000105<br>- Timestamp Error: 1577370027.345025 5.000206 0.000011<br>- BerespProtocol HTTP/1.1<br>- BerespStatus 503<br>- BerespReason Service Unavailable<br>- BerespReason Backend fetch failed<br>- BerespHeader Date: Thu, 26 Dec 2019 14:20:27 GMT<br>- BerespHeader Server: Varnish<br>- VCL_call BACKEND_ERROR<br>- BerespHeader Content-Type: text/html; charset=utf-8<br>- BerespHeader Retry-After: 5<br>- VCL_return deliver<br>- Storage malloc Transient<br>- ObjProtocol HTTP/1.1<br>- ObjStatus 503<br>- ObjReason Backend fetch failed<br>- ObjHeader Date: Thu, 26 Dec 2019 14:20:27 GMT<br>- ObjHeader Server: Varnish<br>- ObjHeader Content-Type: text/html; charset=utf-8<br>- ObjHeader Retry-After: 5<br>- Length 1288<br>- BereqAcct 1276 0 1276 0 0 0<br>- End<br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 26 Dec 2019 at 17:27, Maninder Singh <<a href="mailto:mandys@gmail.com" target="_blank" rel="noreferrer">mandys@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Got one in the log.<div><br></div><div>varnishlog -r /var/log/varnish/503.log<br>* << BeReq >> 21993384<br>- Begin bereq 21993383 pass<br>- Timestamp Start: 1577360704.829258 0.000000 0.000000<br>- BereqMethod POST<br>- BereqURL /corp/contact.php?cf=exitpopup<br>- BereqProtocol HTTP/1.1<br>- BereqHeader User-Agent: Mozilla/5.0 (Windows NT 6.1; Trident/7.0; rv:11.0) like Gecko<br>- BereqHeader Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, */*<br>- BereqHeader SSLClientCertStatus: NoClientCert<br>- BereqHeader X-Forwarded-Proto: https<br>- BereqHeader Content-Type: application/x-www-form-urlencoded<br>- BereqHeader SSLClientCipher: SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA, version=TLSv1, bits=256<br>- BereqHeader Host: <a href="http://www.mydomain.com" target="_blank" rel="noreferrer">www.mydomain.com</a><br>- BereqHeader Referer: <a href="http://mydomain.com/solutions/enterprise.php" target="_blank" rel="noreferrer">http://mydomain.com/solutions/enterprise.php</a><br>- BereqHeader SSLSessionID: 3C119EF3FE70318789F82E9B583581C876B4DDE520C0182C33CD6AF1AA46E63A<br>- BereqHeader X-Cluster-Client-Ip: X.X.X.X<br>- BereqHeader Cookie: X-Mapping-fjhppofk=E8F494E9A630955F1975EEDF11EBC4D7<br>- BereqHeader X-Forwarded-Port: 443<br>- BereqHeader Accept-Encoding: gzip, deflate<br>- BereqHeader Content-Length: 1366<br>- BereqHeader X-Forwarded-For: X.X.X.X, 10.187.187.36<br>- BereqHeader browser: other<br>- BereqHeader serverIp: 10.208.224.192<br>- BereqHeader X-Varnish: 21993384<br>- VCL_call BACKEND_FETCH<br>- VCL_return fetch<br>- BackendOpen 26 reload_2019-12-18T054253.default 127.0.0.1 8080 127.0.0.1 59998<br>- BackendStart 127.0.0.1 8080<br>- Timestamp Bereq: 1577360705.664932 0.835674 0.835674<br>- FetchError http first read error: EOF<br>- BackendClose 26 reload_2019-12-18T054253.default<br>- Timestamp Beresp: 1577360705.665020 0.835763 0.000089<br>- Timestamp Error: 1577360705.665028 0.835770 0.000008<br>- BerespProtocol HTTP/1.1<br>- BerespStatus 503<br>- BerespReason Service Unavailable<br>- BerespReason Backend fetch failed<br>- BerespHeader Date: Thu, 26 Dec 2019 11:45:05 GMT<br>- BerespHeader Server: Varnish<br>- VCL_call BACKEND_ERROR<br>- BerespHeader Content-Type: text/html; charset=utf-8<br>- BerespHeader Retry-After: 5<br>- VCL_return deliver<br>- Storage malloc Transient<br>- ObjProtocol HTTP/1.1<br>- ObjStatus 503<br>- ObjReason Backend fetch failed<br>- ObjHeader Date: Thu, 26 Dec 2019 11:45:05 GMT<br>- ObjHeader Server: Varnish<br>- ObjHeader Content-Type: text/html; charset=utf-8<br>- ObjHeader Retry-After: 5<br>- Length 1288<br>- BereqAcct 849 1366 2215 0 0 0<br>- End<br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 26 Dec 2019 at 15:21, Maninder Singh <<a href="mailto:mandys@gmail.com" target="_blank" rel="noreferrer">mandys@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="auto">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. </div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 26 Dec, 2019, 3:10 pm Guillaume Quintard, <<a href="mailto:guillaume@varnish-software.com" target="_blank" rel="noreferrer">guillaume@varnish-software.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hi,<div><br></div><div>Most probably, varnishncsa isn't going to give you the full picture, so let's go for the exhaustive way:</div><div><br></div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div><font face="monospace">varnishlog -q "BerespStatus eq 503" -w /whatever/file</font></div></blockquote><div><br></div><div>you can then read the logs with</div><div><br></div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div><font face="monospace">varnishlog -r /whatever/file</font></div></blockquote><div><br></div><div>(more logging pointers here: <a href="https://docs.varnish-software.com/tutorials/vsl-query/" rel="noreferrer noreferrer" target="_blank">https://docs.varnish-software.com/tutorials/vsl-query/</a>)</div><div><br></div><div>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.</div><div><br></div><div><div><div dir="ltr"><div dir="ltr"><div>-- <br></div>Guillaume Quintard<br></div></div></div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, Dec 26, 2019 at 6:33 AM Maninder Singh <<a href="mailto:mandys@gmail.com" rel="noreferrer noreferrer" target="_blank">mandys@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hi,<div><br></div><div>I am facing a strange problem.</div><div><br></div><div>I am running varnish 4.1.11 on port 80 which is behind a LB.</div><div><br></div><div>Varnish then connects to apache 2.4 ( on port 8080 ) and also have php-fpm running.</div><div><br></div><div>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 ).</div><div><br></div><div>Where does this request vanish ?</div><div><br></div><div>How do I debug this issue ?</div><div><br></div><div>Some more details:</div><div><br></div><div>* I have varnishncsa turned on with following flags.</div><div><br></div><div>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<br></div><div><br></div><div>Here is the entry in varnish log during that time.</div><div><br></div><div><span style="color:rgb(0,0,0);font-family:arial,sans-serif">X.X.X.X, LB.IP.0.0 - - [25/Dec/2019:00:26:40 -0600] 2629363 "POST </span><a href="http://mydomain.com/LetsCelebrate" rel="noreferrer noreferrer" target="_blank">http://mydomain.com/LetsCelebrate</a><span style="color:rgb(0,0,0);font-family:arial,sans-serif"> HTTP/1.1" 503 1288 "</span><a href="https://referringdomain.com/LetsCelebrate?hostingUrl=https%3A%2F%2Fxy.abc.com" rel="noreferrer noreferrer" target="_blank">https://referringdomain.com/LetsCelebrate?hostingUrl=https%3A%2F%2Fxy.abc.com</a><span style="color:rgb(0,0,0);font-family:arial,sans-serif">" "Mozilla/5.0 (Linux; Android 9; SM-A920F) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.93 Mobile Safari/537.36" "</span><a href="http://mydomain.com" rel="noreferrer noreferrer" target="_blank">mydomain.com</a><span style="color:rgb(0,0,0);font-family:arial,sans-serif">" miss</span><br></div><div><div><br></div><div>In .vcl file I have following set.</div><div> .first_byte_timeout = 120s;<br></div><div><br></div><div>Now, I am not logging varnish to apache requests ( which backend fetch ).</div><div>As you can see above I am only logging client requests.</div><div><br></div><div>Is their a way to log client requests like above but then also log backend fetch failures to another log file ?</div><div>[ Running 2 instances of varnishncsa ? ]</div><div><br></div><div>Any pointers ?</div><div><br></div><div>Please let me know.</div><div><br></div><div>Thanks.<font face="arial, sans-serif"><br></font><p></p><p></p></div></div></div>
_______________________________________________<br>
varnish-misc mailing list<br>
<a href="mailto:varnish-misc@varnish-cache.org" rel="noreferrer noreferrer" target="_blank">varnish-misc@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc" rel="noreferrer noreferrer noreferrer" target="_blank">https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc</a><br>
</blockquote></div>
</blockquote></div>
</blockquote></div>
</blockquote></div>
</blockquote></div>
</blockquote></div>