Hi Guillaume, Any idea on what the 5 sec timeout might be ( which happens only 3-4 times a day ) ?
Is it the timeout_idle as mentioned by Dridi ? What can be done to fix it ? On Fri, 27 Dec 2019 at 14:22, Maninder Singh <[email protected]> wrote: > Here are the different timeouts: > > *timeout_idle* (default: 5 seconds): How long we will wait from we > `accept()` the connection, until the client must have sent us a > non-whitespace character. (typically this will be the G in "GET /url > HTTP/1.1") > > Isn't idle_timeout for client to varnish requests ?? > > Also, just so that you know, these requests dont make it to apache logs > also. > > > > backend_idle_timeout 60.000 [seconds] (default) > between_bytes_timeout 60.000 [seconds] (default) > cli_timeout 60.000 [seconds] (default) > connect_timeout 3.500 [seconds] (default) > first_byte_timeout 60.000 [seconds] (default) > idle_send_timeout 60.000 [seconds] (default) > pipe_timeout 60.000 [seconds] (default) > send_timeout 600.000 [seconds] (default) > thread_pool_timeout 300.000 [seconds] (default) > timeout_idle 5.000 [seconds] (default) > timeout_linger 0.050 [seconds] (default) > > > On Fri, 27 Dec 2019 at 13:15, Dridi Boukelmoune <[email protected]> wrote: > >> On Fri, Dec 27, 2019 at 1:00 AM Maninder Singh <[email protected]> wrote: >> > >> > I only have php-fpm slow logging for requests greater than 5secs. >> Otherwise it should be all defaults for varnish/apache/fpm. >> > >> > Does varnish or apache have anything defaulting to 5secs? >> >> timeout_idle defaults to 5s >> >> > Otherwise fpm might be closing the connection for logging a slow >> request ? Strange? >> > >> > On Thu, 26 Dec, 2019, 10:44 pm Guillaume Quintard, < >> [email protected]> wrote: >> >> >> >> 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 >> >
_______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
