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?)
-- Guillaume Quintard On Thu, Dec 26, 2019 at 3:12 PM Maninder Singh <[email protected]> wrote: > 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 <[email protected]> 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 <[email protected]> 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, < >>> [email protected]> 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 <[email protected]> >>>> 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 >>>>> [email protected] >>>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc >>>>> >>>>
_______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
