Varnish Closing Backend Connection
Guillaume Quintard
guillaume at varnish-software.com
Mon Dec 3 14:15:08 UTC 2018
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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at varnish-cache.org
>>>>>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>>>>>
>>>>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20181203/536c438b/attachment-0001.html>
More information about the varnish-misc
mailing list