Ok, that's great. So just to summarize for someone else benefit Issue Summary: Varnish is displaying backend fetch error when original POST request results in 500 Internal Error and backend_response is used to GET staticpage customized 500 Internal Server Error Message
VarnishLog Output (only relevant message): It can be seen that Backend is being closed as soon as the request is sent. - VCL_call BACKEND_FETCH - VCL_return fetch - BackendOpen 24 boot.staticpages 127.0.0.1 82 127.0.0.1 40696 - BackendStart 127.0.0.1 82 - FetchError backend write error: 0 (Success) - Timestamp Bereq: 1543416195.877756 5.116981 0.000046 - BackendClose 24 boot.staticpages - Timestamp Beresp: 1543416195.877888 5.117113 0.000132 - Timestamp Error: 1543416195.877892 5.117117 0.000004 - BerespProtocol HTTP/1.1 - BerespStatus 503 - BerespReason Service Unavailable - BerespReason Backend fetch failed - BerespHeader Date: Wed, 28 Nov 2018 14:43:15 GMT - BerespHeader Server: Varnish - VCL_call BACKEND_ERROR Root Cause: Varnish can't retry because there's no body to send anymore. Resolution: Cache the body of the original request by using std.cache_req_body(10KB); https://varnish-cache.org/docs/trunk/reference/vmod_generated.html#func-cache-req-body Thanks for your help Guillaume -------- Regards, Junaid On Mon, Dec 3, 2018 at 2:15 PM Guillaume Quintard < [email protected]> wrote: > Arg, we wandered off without including the mailing-list. > > Issue was retrying the backends request without having the body cached. > > Junaid: the body is cached only for the request duration, and it's not > reused outside of that , no worry here. > > On Mon, Dec 3, 2018, 03:28 Junaid Mukhtar <[email protected] wrote: > >> Just teseted it; and it looks to have fixed the problem. >> >> I just imported the vmod and used std.cache_req_body(2000KB); in vcl_recv >> >> Just one question; do you think caching could cause any issues when doing >> the hash etc? we don't really want to cache the post body and use it >> anywhere. >> >> -------- >> Regards, >> Junaid >> >> >> On Fri, Nov 30, 2018 at 11:28 PM Guillaume Quintard < >> [email protected]> wrote: >> >>> Hum, this is a bit of a shot in the dark, but can you try using >>> https://varnish-cache.org/docs/trunk/reference/vmod_generated.html#func-cache-req-body >>> (in vcl_recv)? >>> >>> It could be that varnish can't retry because there's no body to send >>> anymore. I would expect the error to be clearer if that was the case >>> though... >>> >>> -- >>> Guillaume Quintard >>> >>> >>> On Fri, Nov 30, 2018 at 10:19 AM Junaid Mukhtar < >>> [email protected]> wrote: >>> >>>> no, all of the GET requests to staticpages is working fine. >>>> >>>> the issue is only when original POST request gets 500 from app server >>>> and then varnish tries to GET the appropriate staticpage from the >>>> staticpage backend. >>>> >>>> Staticpage backend is only HTTP >>>> >>>> -------- >>>> Regards, >>>> Junaid >>>> >>>> >>>> On Fri, Nov 30, 2018 at 6:16 PM Guillaume Quintard < >>>> [email protected]> wrote: >>>> >>>>> Are all the requests to the "staticpages" backend failures, or just >>>>> some of them? >>>>> >>>>> Is that backend listen to HTTP or to HTTPS? >>>>> >>>>> -- >>>>> Guillaume Quintard >>>>> >>>>> >>>>> On Fri, Nov 30, 2018 at 12:32 AM Junaid Mukhtar < >>>>> [email protected]> wrote: >>>>> >>>>>> Hi >>>>>> >>>>>> Kindly find below. One thing i would like to highlight is that we >>>>>> change backend from application to nginx (staticpage) for the >>>>>> error-pages. >>>>>> >>>>>> Wireshark shows reset being sent by Varnish to nginx. >>>>>> >>>>>> * << BeReq >> 196913 >>>>>> - Begin bereq 196912 pass >>>>>> - Timestamp Start: 1543416190.760775 0.000000 0.000000 >>>>>> - BereqMethod POST >>>>>> - BereqURL /application/person >>>>>> - BereqProtocol HTTP/1.1 >>>>>> - BereqHeader Accept: >>>>>> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8 >>>>>> - BereqHeader Accept-Language: en-GB,en-US;q=0.9,en;q=0.8 >>>>>> - BereqHeader Cache-Control: max-age=0 >>>>>> - BereqHeader Content-Type: application/x-www-form-urlencoded >>>>>> - BereqHeader Cookie: check=true; >>>>>> AMCVS_232334B8527856F80A490D44%40AdobeOrg=1; >>>>>> cookieStatementDisplayedOnce=true; s_cc=true; >>>>>> k2c_Organization_cids=Organization_uaEMwVyUDe8mY5m; >>>>>> JOIN_JSESSIONID=dcd2c25b-a3e5-4a58-826c-e9452190265f; ttco=1543398034746; >>>>>> _gcl_au=1.1.1660607311.15 >>>>>> - BereqHeader Origin: https://development.organization.com >>>>>> - BereqHeader Referer: >>>>>> https://development.organization.com/application/person >>>>>> - BereqHeader Upgrade-Insecure-Requests: 1 >>>>>> - BereqHeader User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X >>>>>> 10_14_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 >>>>>> Safari/537.36 OPR/56.0.3051.104 >>>>>> - BereqHeader X-Forwarded-Port: 443 >>>>>> - BereqHeader X-Forwarded-Proto: https >>>>>> - BereqHeader Content-Length: 888 >>>>>> - BereqHeader X-Forwarded-For: 2.2.2.2, 1.1.1.1 >>>>>> - BereqHeader xff: 2.2.2.2, 1.1.1.1 >>>>>> - BereqHeader host: development.organization.com >>>>>> - BereqHeader Accept-Encoding: gzip >>>>>> - BereqHeader X-Varnish: 196913 >>>>>> - VCL_call BACKEND_FETCH >>>>>> - VCL_return fetch >>>>>> - BackendOpen 39 boot.application1 3.3.3.3 8089 4.4.4.4 58036 >>>>>> - BackendStart 3.3.3.3 8089 >>>>>> - Timestamp Bereq: 1543416190.760820 0.000045 0.000045 >>>>>> - Timestamp Beresp: 1543416195.877653 5.116878 5.116833 >>>>>> - BerespProtocol HTTP/1.1 >>>>>> - BerespStatus 500 >>>>>> - BerespReason Internal Server Error >>>>>> - BerespHeader Server: Apache-Coyote/1.1 >>>>>> - BerespHeader X-Application-Context: application >>>>>> - BerespHeader X-Content-Type-Options: nosniff >>>>>> - BerespHeader X-XSS-Protection: 1; mode=block >>>>>> - BerespHeader Cache-Control: no-cache, no-store, max-age=0, >>>>>> must-revalidate >>>>>> - BerespHeader Pragma: no-cache >>>>>> - BerespHeader Expires: 0 >>>>>> - BerespHeader Strict-Transport-Security: max-age=31536000 ; >>>>>> includeSubDomains >>>>>> - BerespHeader X-Frame-Options: DENY >>>>>> - BerespHeader Content-Type: text/html;charset=ISO-8859-1 >>>>>> - BerespHeader Content-Language: en-GB >>>>>> - BerespHeader Content-Length: 490 >>>>>> - BerespHeader Date: Wed, 28 Nov 2018 14:43:15 GMT >>>>>> - BerespHeader Connection: close >>>>>> - TTL RFC -1 10 -1 1543416196 1543416196 1543416195 0 0 >>>>>> - VCL_call BACKEND_RESPONSE >>>>>> - BereqMethod GET >>>>>> - BereqURL /errors/application/500.html >>>>>> - VCL_return retry >>>>>> - BackendClose 39 boot.application1 >>>>>> - Timestamp Retry: 1543416195.877710 5.116935 0.000057 >>>>>> - Link bereq 262229 retry >>>>>> - End >>>>>> >>>>>> * << BeReq >> 262229 >>>>>> - Begin bereq 196913 retry >>>>>> - Timestamp Start: 1543416195.877710 5.116935 0.000000 >>>>>> - BereqMethod GET >>>>>> - BereqURL /errors/application/500.html >>>>>> - BereqProtocol HTTP/1.1 >>>>>> - BereqHeader Accept: >>>>>> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8 >>>>>> - BereqHeader Accept-Language: en-GB,en-US;q=0.9,en;q=0.8 >>>>>> - BereqHeader Cache-Control: max-age=0 >>>>>> - BereqHeader Content-Type: application/x-www-form-urlencoded >>>>>> - BereqHeader Cookie: check=true; >>>>>> AMCVS_232334B8527856F80A490D44%40AdobeOrg=1; >>>>>> cookieStatementDisplayedOnce=true; s_cc=true; >>>>>> k2c_Organization_cids=Organization_uaEMwVyUDe8mY5m; >>>>>> JOIN_JSESSIONID=dcd2c25b-a3e5-4a58-826c-e9452190265f; ttco=1543398034746; >>>>>> _gcl_au=1.1.1660607311.15 >>>>>> - BereqHeader Origin: https://development.organization.com >>>>>> - BereqHeader Referer: >>>>>> https://development.organization.com/application/person >>>>>> - BereqHeader Upgrade-Insecure-Requests: 1 >>>>>> - BereqHeader User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X >>>>>> 10_14_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 >>>>>> Safari/537.36 OPR/56.0.3051.104 >>>>>> - BereqHeader X-Forwarded-Port: 443 >>>>>> - BereqHeader X-Forwarded-Proto: https >>>>>> - BereqHeader Content-Length: 888 >>>>>> - BereqHeader X-Forwarded-For: 2.2.2.2, 1.1.1.1 >>>>>> - BereqHeader xff: 2.2.2.2, 1.1.1.1 >>>>>> - BereqHeader host: development.organization.com >>>>>> - BereqHeader Accept-Encoding: gzip >>>>>> - BereqHeader X-Varnish: 196913 >>>>>> - BereqUnset X-Varnish: 196913 >>>>>> - BereqHeader X-Varnish: 262229 >>>>>> - VCL_call BACKEND_FETCH >>>>>> - VCL_return fetch >>>>>> - BackendOpen 24 boot.staticpages 127.0.0.1 82 127.0.0.1 40696 >>>>>> - BackendStart 127.0.0.1 82 >>>>>> - FetchError backend write error: 0 (Success) >>>>>> - Timestamp Bereq: 1543416195.877756 5.116981 0.000046 >>>>>> - BackendClose 24 boot.staticpages >>>>>> - Timestamp Beresp: 1543416195.877888 5.117113 0.000132 >>>>>> - Timestamp Error: 1543416195.877892 5.117117 0.000004 >>>>>> - BerespProtocol HTTP/1.1 >>>>>> - BerespStatus 503 >>>>>> - BerespReason Service Unavailable >>>>>> - BerespReason Backend fetch failed >>>>>> - BerespHeader Date: Wed, 28 Nov 2018 14:43:15 GMT >>>>>> - BerespHeader Server: Varnish >>>>>> - VCL_call BACKEND_ERROR >>>>>> - BerespHeader Location: >>>>>> https://development.organization.com/errors/default/unknown.html >>>>>> - BerespStatus 302 >>>>>> - BerespReason Found >>>>>> - VCL_return deliver >>>>>> - Storage malloc Transient >>>>>> - ObjProtocol HTTP/1.1 >>>>>> - ObjStatus 302 >>>>>> - ObjReason Found >>>>>> - ObjHeader Date: Wed, 28 Nov 2018 14:43:15 GMT >>>>>> - ObjHeader Server: Varnish >>>>>> - ObjHeader Location: >>>>>> https://development.organization.com/errors/default/unknown.html >>>>>> - Length 0 >>>>>> - BereqAcct 7123 888 8011 489 0 489 >>>>>> - End >>>>>> >>>>>> -------- >>>>>> Regards, >>>>>> Junaid >>>>>> >>>>>> >>>>>> On Thu, Nov 29, 2018 at 10:34 PM Guillaume Quintard < >>>>>> [email protected]> wrote: >>>>>> >>>>>>> Hi, >>>>>>> >>>>>>> Weird, are you able to show the two full backend request logs? (the >>>>>>> one getting you the 500, then the 503)? >>>>>>> >>>>>>> Kind regards, >>>>>>> >>>>>>> -- >>>>>>> Guillaume Quintard >>>>>>> >>>>>>> >>>>>>> On Wed, Nov 28, 2018 at 8:14 AM Junaid Mukhtar < >>>>>>> [email protected]> wrote: >>>>>>> >>>>>>>> hi Guys >>>>>>>> >>>>>>>> I am facing a rather tricky issue, where it appears that the >>>>>>>> varnish is closing the backend connection without waiting for a >>>>>>>> respones >>>>>>>> from the backend. >>>>>>>> >>>>>>>> We are using Nginx to serve static content Below is teh sequence of >>>>>>>> messages >>>>>>>> >>>>>>>> Varnish sends POST request to App >>>>>>>> App sends back 500 Internal Server Error >>>>>>>> Varnish interprets the 500 internal Server Error >>>>>>>> Varnish sends GET request to Nginx server on the same box to serve >>>>>>>> static content >>>>>>>> Varnish shows error message (even though Nginx sends the response >>>>>>>> successfully within milliseconds) >>>>>>>> - VCL_call BACKEND_FETCH >>>>>>>> - VCL_return fetch >>>>>>>> - BackendOpen 38 boot.staticpages 127.0.0.1 82 127.0.0.1 35064 >>>>>>>> - BackendStart 127.0.0.1 82 >>>>>>>> - FetchError backend write error: 0 (Success) >>>>>>>> - Timestamp Bereq: 1543420795.016075 5.106813 0.000099 >>>>>>>> - BackendClose 38 boot.staticpages >>>>>>>> - Timestamp Beresp: 1543420795.016497 5.107235 0.000422 >>>>>>>> - Timestamp Error: 1543420795.016503 5.107241 0.000005 >>>>>>>> - BerespProtocol HTTP/1.1 >>>>>>>> - BerespStatus 503 >>>>>>>> - BerespReason Service Unavailable >>>>>>>> - BerespReason Backend fetch failed >>>>>>>> - BerespHeader Date: Wed, 28 Nov 2018 15:59:55 GMT >>>>>>>> - BerespHeader Server: Varnish >>>>>>>> - VCL_call BACKEND_ERROR >>>>>>>> >>>>>>>> Varnish then again goes the same Nginx server to display default >>>>>>>> content. >>>>>>>> Nginx sends response and varnish accepts it and sends it back to >>>>>>>> the customer >>>>>>>> >>>>>>>> I am a bit stumped, any help with this is highly appreciated >>>>>>>> >>>>>>>> -------- >>>>>>>> Regards, >>>>>>>> Junaid >>>>>>>> _______________________________________________ >>>>>>>> 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
