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 <
guillaume@varnish-software.com> 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 <junaid.mukhtar@gmail.com 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 <
>> guillaume@varnish-software.com> 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 <
>>> junaid.mukhtar@gmail.com> 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 <
>>>> guillaume@varnish-software.com> 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 <
>>>>> junaid.mukhtar@gmail.com> 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 <
>>>>>> guillaume@varnish-software.com> 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 <
>>>>>>> junaid.mukhtar@gmail.com> 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
>>>>>>>> varnish-misc@varnish-cache.org
>>>>>>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>>>>>>
>>>>>>>