Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: Varnish: Misc

Varnish 500's now not 302's

 

 

Varnish misc RSS feed   Index | Next | Previous | View Threaded


Nicholas_Maesepp at scee

May 8, 2012, 7:11 PM

Post #1 of 9 (765 views)
Permalink
Varnish 500's now not 302's

Hi

Continuing on with my last problem of the varnish cache returning a 302
for certain objects without contacting the backend I am now getting 500
errors from the cache. Object is available from the backend so definitely
not a 500 from the backend and logs + tcpdump show it trying to deliver
from cache only. Oddly enough its on mainly gif and png images that I
notice anyhow, and it happened to multiple caches within 1 hour of each
other on the same objects. A restart of varnish stopped the 500 errors.

Previously to attempt to resolve my 302 issue I lowered the amount of RAM
malloc'ed to 5 gig. Varnish now uses up 73% of the system's RAM. I have no
swap and there was at least a gig free on all caches before they started
serving 500's.

Here is a copy of the varnishlog.

16 ReqStart c 10.130.XX.XX 3259 1429474950
16 RxRequest c GET
16 RxURL c /static/furn/portal/common/pixel.gif
16 RxProtocol c HTTP/1.1
16 RxHeader c host: www.example.com
16 RxHeader c Accept: text/html, application/xhtml+xml, */*
16 RxHeader c Accept-Encoding: gzip, deflate
16 RxHeader c Accept-Language: en-US
16 RxHeader c Cache-Control: max-age=259200
16 RxHeader c Cookie: portalLocaleCookie=en_AU;
WT_FPC=id=XX.XX.XX.XX-249718560.30138265:lv=1336488750511:ss=1336488730455;
PDC4_COOKIE=Vk6CPp9WGbfxrZMnGxQlhFfWW0cJD0NGB4mNFcvQJ6nFwmRD1kxS!-925861289
16 RxHeader c User-Agent: Mozilla/5.0 (compatible; MSIE 9.0;
Windows NT 6.1; WOW64; Trident/5.0)
16 RxHeader c Via: 1.1 xx.xx.xx.xx:3128 (squid/2.6.STABLE21)
16 RxHeader c Xroxy-Connection: keep-alive
16 RxHeader c Z-Forwarded-For: AAAAAAAAAAAA
16 RxHeader c X-Forwarded-For: XX.XX.XX.XX
16 RxHeader c X-Forwarded-Port: 80
16 RxHeader c X-Forwarded-Proto: http
16 RxHeader c Connection: keep-alive
16 VCL_call c recv lookup
16 VCL_call c hash hash
16 Hit c 1429284571
16 VCL_call c hit deliver
16 VCL_call c deliver deliver
16 TxProtocol c HTTP/1.1
16 TxStatus c 500
16 TxResponse c Internal Server Error
16 TxHeader c cache-control: max-age=900
16 TxHeader c Content-Length: 0
16 TxHeader c Accept-Ranges: bytes
16 TxHeader c Date: Wed, 09 May 2012 00:54:41 GMT
16 TxHeader c X-Varnish: 1429474950 1429284571
16 TxHeader c Age: 33236
16 TxHeader c Via: 1.1 varnish
16 TxHeader c Connection: keep-alive
16 Length c 0
16 ReqEnd c 1429474950 1336524881.724712133

How I understand this is my server does the recv call, determines its a
lookup and then hashes as per my vcl, which is req,url and then server.ip
and then it does hit which is just to return deliver. Which should deliver
the object from cache, instead it gives me a 500.

I've decided to turn off range_support as I understand this is considered
experimental ? I'd like to avoid trial and error of my configuration if
possible. I'm just guessing at current really. Any more knowledgeable
ideas are welcomed. However I'd like to not have to go to disk for the
cache, I don't see why malloc should not be working as intended if this is
my issue.


Sony Computer Entertainment Australia Pty Ltd
Level 1, 63-73 Ann Street Surry Hills NSW 2010
P.O. Box 5023 Darlinghurst NSW 2010
ph: +61 (0)2 9324 9500 fax: +61 (0)2 9324 9558
http://au.playstation.com
http://www.facebook.com/PlayStationAU


THE WORLD IS IN PLAY.
PlayStationŽVita has arrived.
http://www.psvita.com




**********************************************************************
This email and any files transmitted with it are confidential and intended
solely for the use of the individual or entity to whom they are addressed.
If you have received this email in error please notify postmaster [at] scee
This footnote also confirms that this email message has been checked for
all known viruses.
Sony Computer Entertainment Australia Pty. Limited
Registered Office: Level 1, 63-73 Ann Street, Surry Hills, NSW 2010
Australia
Registered in Australia: 077 583 183
**********************************************************************

Please consider the environment before printing this e-mail


apj at mutt

May 9, 2012, 12:45 AM

Post #2 of 9 (729 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

On Wed, May 09, 2012 at 01:11:16PM +1100, Nicholas_Maesepp [at] scee wrote:
>
> How I understand this is my server does the recv call, determines its a
> lookup and then hashes as per my vcl, which is req,url and then server.ip
> and then it does hit which is just to return deliver. Which should deliver
> the object from cache, instead it gives me a 500.

It does deliver from cache. The 500 is the object in the cache.

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc


Nicholas_Maesepp at scee

May 10, 2012, 3:30 PM

Post #3 of 9 (735 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

I guess technically I realize this is from the cache, my question is more
along the lines of what could be causing my objects in the cache to become
stop being delivered as is and having a 500 error returned. Is my cache
being corrupted in some way when varnish starts to max out the malloc'ed
RAM? Seems like a bug to me but can't pinpoint exactly what causes it,
just that it happens after X amount of time to any of my instances.

Cheers

Nick




From: Andreas Plesner Jacobsen <apj [at] mutt>
To: varnish-misc [at] varnish-cache
Date: 05/09/2012 05:47 PM
Subject: Re: Varnish 500's now not 302's
Sent by: varnish-misc-bounces [at] varnish-cache



On Wed, May 09, 2012 at 01:11:16PM +1100, Nicholas_Maesepp [at] scee wrote:
>
> How I understand this is my server does the recv call, determines its a
> lookup and then hashes as per my vcl, which is req,url and then
server.ip
> and then it does hit which is just to return deliver. Which should
deliver
> the object from cache, instead it gives me a 500.

It does deliver from cache. The 500 is the object in the cache.

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc




Sony Computer Entertainment Australia Pty Ltd
Level 1, 63-73 Ann Street Surry Hills NSW 2010
P.O. Box 5023 Darlinghurst NSW 2010
ph: +61 (0)2 9324 9500 fax: +61 (0)2 9324 9558
http://au.playstation.com
http://www.facebook.com/PlayStationAU


THE WORLD IS IN PLAY.
PlayStationŽVita has arrived.
http://www.psvita.com




**********************************************************************
This email and any files transmitted with it are confidential and intended
solely for the use of the individual or entity to whom they are addressed.
If you have received this email in error please notify postmaster [at] scee
This footnote also confirms that this email message has been checked for
all known viruses.
Sony Computer Entertainment Australia Pty. Limited
Registered Office: Level 1, 63-73 Ann Street, Surry Hills, NSW 2010
Australia
Registered in Australia: 077 583 183
**********************************************************************

Please consider the environment before printing this e-mail


apj at mutt

May 11, 2012, 1:40 AM

Post #4 of 9 (728 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

On Fri, May 11, 2012 at 09:30:52AM +1100, Nicholas_Maesepp [at] scee wrote:

> I guess technically I realize this is from the cache, my question is more
> along the lines of what could be causing my objects in the cache to become
> stop being delivered as is and having a 500 error returned. Is my cache
> being corrupted in some way when varnish starts to max out the malloc'ed
> RAM? Seems like a bug to me but can't pinpoint exactly what causes it,
> just that it happens after X amount of time to any of my instances.

Then you misunderstood me. The 500 is a cached object that your backend served
at the time. You can avoid caching such objects by inspecting the HTTP response
in vcl_fetch and setting TTL and/or using hit for pass and/or saint mode.

It's almost certainly not a bug.

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc


hugues.alary at gmail

May 11, 2012, 10:27 AM

Post #5 of 9 (724 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

At this point, sending your configuration file would maybe be a good idea.
On May 11, 2012 1:41 AM, "Andreas Plesner Jacobsen" <apj [at] mutt> wrote:

> On Fri, May 11, 2012 at 09:30:52AM +1100, Nicholas_Maesepp [at] scee wrote:
>
> > I guess technically I realize this is from the cache, my question is more
> > along the lines of what could be causing my objects in the cache to
> become
> > stop being delivered as is and having a 500 error returned. Is my cache
> > being corrupted in some way when varnish starts to max out the malloc'ed
> > RAM? Seems like a bug to me but can't pinpoint exactly what causes it,
> > just that it happens after X amount of time to any of my instances.
>
> Then you misunderstood me. The 500 is a cached object that your backend
> served
> at the time. You can avoid caching such objects by inspecting the HTTP
> response
> in vcl_fetch and setting TTL and/or using hit for pass and/or saint mode.
>
> It's almost certainly not a bug.
>
> --
> Andreas
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc [at] varnish-cache
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>


Nicholas_Maesepp at scee

May 13, 2012, 5:20 PM

Post #6 of 9 (705 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

Nothing special about my config file apart from the hashing of objects, I
do have the following already in my vcl_fetch:

set beresp.grace = 3m;
if (beresp.status == 500) {
set beresp.saintmode = 5s;
}

======
vcl_recv {
set req.grace = 40s;
if (req.request != "GET" && req.request != "HEAD") {
/* We only deal with GET and HEAD by default */
return (pass);
}
if (req.http.Accept-Encoding && req.url ~ "\.(png|gif|jpg|swf|mov|flv)$")
{
remove req.http.Accept-Encoding;
}
return (lookup);

I'm not convinced that I'm caching 500 responses on all these objects, I
do wonder if its because I remove accept-encoding on those objects, those
are the ones that end up with 500's. But also maybe my saintmode and grace
numbers are too low if the back-end is infact serving 500's. But at least
it's an avenue to explore and get some evidence to prove or disprove it.
Will also try using hit for pass instead and see if that gives me more
resilience.


Cheers

Nick




From: Hugues Alary <hugues.alary [at] gmail>
To: Andreas Plesner Jacobsen <apj [at] mutt>
Cc: varnish-misc [at] varnish-cache
Date: 05/12/2012 03:29 AM
Subject: Re: Varnish 500's now not 302's
Sent by: varnish-misc-bounces [at] varnish-cache



At this point, sending your configuration file would maybe be a good idea.
On May 11, 2012 1:41 AM, "Andreas Plesner Jacobsen" <apj [at] mutt> wrote:
On Fri, May 11, 2012 at 09:30:52AM +1100, Nicholas_Maesepp [at] scee wrote:

> I guess technically I realize this is from the cache, my question is
more
> along the lines of what could be causing my objects in the cache to
become
> stop being delivered as is and having a 500 error returned. Is my cache
> being corrupted in some way when varnish starts to max out the malloc'ed
> RAM? Seems like a bug to me but can't pinpoint exactly what causes it,
> just that it happens after X amount of time to any of my instances.

Then you misunderstood me. The 500 is a cached object that your backend
served
at the time. You can avoid caching such objects by inspecting the HTTP
response
in vcl_fetch and setting TTL and/or using hit for pass and/or saint mode.

It's almost certainly not a bug.

--
Andreas





Sony Computer Entertainment Australia Pty Ltd
Level 1, 63-73 Ann Street Surry Hills NSW 2010
P.O. Box 5023 Darlinghurst NSW 2010
ph: +61 (0)2 9324 9500 fax: +61 (0)2 9324 9558
http://au.playstation.com
http://www.facebook.com/PlayStationAU


THE WORLD IS IN PLAY.
PlayStationŽVita has arrived.
http://www.psvita.com




**********************************************************************
This email and any files transmitted with it are confidential and intended
solely for the use of the individual or entity to whom they are addressed.
If you have received this email in error please notify postmaster [at] scee
This footnote also confirms that this email message has been checked for
all known viruses.
Sony Computer Entertainment Australia Pty. Limited
Registered Office: Level 1, 63-73 Ann Street, Surry Hills, NSW 2010
Australia
Registered in Australia: 077 583 183
**********************************************************************

Please consider the environment before printing this e-mail


hugues.alary at gmail

May 13, 2012, 6:11 PM

Post #7 of 9 (724 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

Are you specifically not caching 500 responses in your config file?
Something like:

if(beresp.status == 500)
{
return (hit_for_pass);
}

If you're not doing that, then you *are* caching 500 responses.

On Sun, May 13, 2012 at 5:20 PM, <Nicholas_Maesepp [at] scee> wrote:

> Nothing special about my config file apart from the hashing of objects, I
> do have the following already in my vcl_fetch:
>
> set beresp.grace = 3m;
> if (beresp.status == 500) {
> set beresp.saintmode = 5s;
> }
>
> ======
> vcl_recv {
> set req.grace = 40s;
> if (req.request != "GET" && req.request != "HEAD") {
> /* We only deal with GET and HEAD by default */
> return (pass);
> }
> if (req.http.Accept-Encoding && req.url ~ "\.(png|gif|jpg|swf|mov|flv)$") {
> remove req.http.Accept-Encoding;
> }
> return (lookup);
>
> I'm not convinced that I'm caching 500 responses on all these objects, I
> do wonder if its because I remove accept-encoding on those objects, those
> are the ones that end up with 500's. But also maybe my saintmode and grace
> numbers are too low if the back-end is infact serving 500's. But at least
> it's an avenue to explore and get some evidence to prove or disprove it.
> Will also try using hit for pass instead and see if that gives me more
> resilience.
>
>
> Cheers
>
> Nick
>
>
>
>
> From: Hugues Alary <hugues.alary [at] gmail>
> To: Andreas Plesner Jacobsen <apj [at] mutt>
> Cc: varnish-misc [at] varnish-cache
> Date: 05/12/2012 03:29 AM
> Subject: Re: Varnish 500's now not 302's
> Sent by: varnish-misc-bounces [at] varnish-cache
> ------------------------------
>
>
>
> At this point, sending your configuration file would maybe be a good idea.
>
> On May 11, 2012 1:41 AM, "Andreas Plesner Jacobsen" <*apj [at] mutt*<apj [at] mutt>>
> wrote:
> On Fri, May 11, 2012 at 09:30:52AM +1100, *Nicholas_Maesepp [at] scee*<Nicholas_Maesepp [at] scee>wrote:
>
> > I guess technically I realize this is from the cache, my question is more
> > along the lines of what could be causing my objects in the cache to
> become
> > stop being delivered as is and having a 500 error returned. Is my cache
> > being corrupted in some way when varnish starts to max out the malloc'ed
> > RAM? Seems like a bug to me but can't pinpoint exactly what causes it,
> > just that it happens after X amount of time to any of my instances.
>
> Then you misunderstood me. The 500 is a cached object that your backend
> served
> at the time. You can avoid caching such objects by inspecting the HTTP
> response
> in vcl_fetch and setting TTL and/or using hit for pass and/or saint mode.
>
> It's almost certainly not a bug.
>
> --
> Andreas
>
>
> *
> *
>
> *
> Sony Computer Entertainment Australia Pty Ltd*
> Level 1, 63-73 Ann Street Surry Hills NSW 2010
> P.O. Box 5023 Darlinghurst NSW 2010
> ph: +61 (0)2 9324 9500 fax: +61 (0)2 9324 9558
>
> *http://au.playstation.com* <http://au.playstation.com/>*
> **http://www.facebook.com/PlayStationAU*<http://www.facebook.com/PlaystationAU>
>
>
> *
> THE WORLD IS IN PLAY.*
> PlayStationŽVita has arrived.
> http://www.psvita.com
>
> *
> *[image: PSMOVE] <http://au.playstation.com/psvita>
>
> **********************************************************************
> This email and any files transmitted with it are confidential and intended
> solely for the use of the individual or entity to whom they are addressed.
> If you have received this email in error please notify postmaster [at] scee
> This footnote also confirms that this email message has been checked for
> all known viruses.
> Sony Computer Entertainment Australia Pty. Limited
> Registered Office: Level 1, 63-73 Ann Street, Surry Hills, NSW 2010
> Australia
> Registered in Australia: 077 583 183
> **********************************************************************
> *
> Please consider the environment before printing this e-mail*
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc [at] varnish-cache
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>



--
Hugues ALARY


apj at mutt

May 13, 2012, 11:13 PM

Post #8 of 9 (718 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

On Mon, May 14, 2012 at 11:20:23AM +1100, Nicholas_Maesepp [at] scee wrote:

> Nothing special about my config file apart from the hashing of objects, I
> do have the following already in my vcl_fetch:
>
> set beresp.grace = 3m;

So you're at least caching everything for 3 minutes.

> if (beresp.status == 500) {
> set beresp.saintmode = 5s;
> }

And at least using the cached version of 500s for 5 seconds (assuming a single backend).

It shouldn't be too hard to use varnishlog to figure out what happens to these
objects. Try something like varnishlog -cm TxStatus:500

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc


apj at mutt

May 14, 2012, 12:14 AM

Post #9 of 9 (712 views)
Permalink
Re: Varnish 500's now not 302's [In reply to]

On Mon, May 14, 2012 at 08:13:42AM +0200, Andreas Plesner Jacobsen wrote:
>
> > if (beresp.status == 500) {
> > set beresp.saintmode = 5s;
> > }
>
> And at least using the cached version of 500s for 5 seconds (assuming a single backend).
>
> It shouldn't be too hard to use varnishlog to figure out what happens to these
> objects. Try something like varnishlog -cm TxStatus:500

I just found your original mail, and in that you have varnishlog of a hit to the cache.
What is interesting is finding the original request that put the page in the
cache, but from your original post, it's evident, that you've set a high TTL on
the 500 object (Age: 33236).
In other words: You probably have an unconditional
set beresp.ttl = <something larger than 33236>
somewhere, and that's why varnish will cache your 500.
You should also consider restarting the request after setting saint mode. If
you don't, the request will just be added to the backend's saint mode list, but
the response will still be served to the client.

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Varnish misc RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.