Mailing List Archive

Checking for purge prevents caching
I don't know if this is a weird bug or my lack of vcl knowledge, so here
we go:

I want this behavior: When somebody hits <ctrl>-F5 in a browser, varnish
will purge the current page from the cache.

Firefox puts this in its request header when you do that:

Cache-Control: no-cache

So I inserted this piece of vcl:

--
sub vcl_hit {
if(req.http.Cache-Control == "no-cache") {
set obj.ttl = 0s;
error 200 "Hey, we got a purge";
}
}
--

At first glance that kind of works. When somebody hits <ctrl>-F5 the
page gets purged and I get my custom error message.

However suddenly the page is not served from the cache _at all_. That is
unless I just hit F5, _then_ I get a cached page. Hitting F5 sends this
request header in Firefox:

Cache-Control: max-age=0

I don't send any caching headers on the backend if that matters, just
relying on the default Varnish fallback to 120 sec.

Any ideas?


/Anton
Checking for purge prevents caching [ In reply to ]
Anton Stonor <stonorn at giraffen.dk> writes:
> At first glance that kind of works. When somebody hits <ctrl>-F5 the
> page gets purged and I get my custom error message.
>
> However suddenly the page is not served from the cache _at all_. That
> is unless I just hit F5, _then_ I get a cached page. Hitting F5 sends
> this request header in Firefox:
>
> Cache-Control: max-age=0
>
> I don't send any caching headers on the backend if that matters, just
> relying on the default Varnish fallback to 120 sec.
>
> Any ideas?

Hard to tell without logs...

DES
--
Dag-Erling Sm?rgrav
Senior Software Developer
Linpro AS - www.linpro.no
Checking for purge prevents caching [ In reply to ]
Dag-Erling Sm?rgrav wrote:

> Anton Stonor <stonorn at giraffen.dk> writes:
>> At first glance that kind of works. When somebody hits <ctrl>-F5 the
>> page gets purged and I get my custom error message.
>>
>> However suddenly the page is not served from the cache _at all_. That
>> is unless I just hit F5, _then_ I get a cached page. Hitting F5 sends
>> this request header in Firefox:
>>
>> Cache-Control: max-age=0
>>
>> I don't send any caching headers on the backend if that matters, just
>> relying on the default Varnish fallback to 120 sec.
>>
>> Any ideas?
>
> Hard to tell without logs...

OK, here it is:


FIRST "NORMAL" REQUEST - it should be served from the cache
-----------------------------------------------------------

0 StatAddr 127.0.0.1 0 264 2 6 0 0 2 1672 145
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175105738
0 CLI Rd vcl.load boot /tmp/vcl.XXu1YKyr
0 CLI Wr 0 200 Loaded "/tmp/vcl.XXu1YKyr" as "boot"

0 CLI Rd vcl.use boot
0 CLI Wr 0 200
0 CLI Rd start
0 CLI Wr 0 200
0 WorkThread 0xae04f1b4 start
13 SessionOpen c 127.0.0.1 42443
13 ReqStart c 127.0.0.1 42443 1440795409
13 RxRequest c GET
13 RxURL c /headerstuff
13 RxProtocol c HTTP/1.1
13 RxHeader c Host: localhost:9008
13 RxHeader c User-Agent: Mozilla/5.0 (X11; U; Linux i686;
da-DK; rv:1.8.0.5) Gecko/20060731 Ubuntu/dapper-security Firefox/1.5.0.5
13 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
13 RxHeader c Accept-Language: da,en-us;q=0.7,en;q=0.3
13 RxHeader c Accept-Encoding: gzip,deflate
13 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
13 RxHeader c Keep-Alive: 300
13 RxHeader c Connection: keep-alive
13 VCL_call c recv
13 VCL_return c lookup
13 VCL_call c miss
13 VCL_return c fetch
16 BackendOpen b default 127.0.0.1 54436 127.0.0.1 8080
16 BackendXID b 1440795409
13 Backend c 16 default
16 TxRequest b GET
16 TxURL b /headerstuff
16 TxProtocol b HTTP/1.1
16 TxHeader b Host: localhost:9008
16 TxHeader b User-Agent: Mozilla/5.0 (X11; U; Linux i686;
da-DK; rv:1.8.0.5) Gecko/20060731 Ubuntu/dapper-security Firefox/1.5.0.5
16 TxHeader b Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
16 TxHeader b Accept-Language: da,en-us;q=0.7,en;q=0.3
16 TxHeader b Accept-Encoding: gzip,deflate
16 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
16 TxHeader b X-Varnish: 1440795409
16 TxHeader b X-Forwarded-for: 127.0.0.1
16 RxProtocol b HTTP/1.1
16 RxStatus b 200
16 RxResponse b OK
16 RxHeader b Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
16 RxHeader b Date: Wed, 28 Mar 2007 18:15:40 GMT
16 RxHeader b Content-Length: 29
16 RxHeader b Content-Type: text/plain; charset=iso-8859-15
13 TTL c 1440795409 RFC 120 1175105740 1175105740 0 0 0
13 VCL_call c fetch
13 VCL_return c insert
13 ObjProtocol c HTTP/1.1
13 ObjStatus c 200
13 ObjResponse c OK
13 ObjHeader c Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
13 ObjHeader c Date: Wed, 28 Mar 2007 18:15:40 GMT
13 ObjHeader c Content-Type: text/plain; charset=iso-8859-15
13 ObjHeader c Content-Length: 29
16 BackendReuse b default
13 Length c 29
13 TxProtocol c HTTP/1.1
13 TxStatus c 200
13 TxResponse c OK
13 TxHeader c Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
13 TxHeader c Date: Wed, 28 Mar 2007 18:15:40 GMT
13 TxHeader c Content-Type: text/plain; charset=iso-8859-15
13 TxHeader c Content-Length: 29
13 TxHeader c X-Varnish: 1440795409
13 TxHeader c Age: 0
13 TxHeader c Via: 1.1 varnish
13 ReqEnd c 1440795409 1175105740.472784000
1175105740.642282000 0.000369000 0.009144000 0.160354000


SECOND "NORMAL" REQUEST - now, it should really be in the cache
---------------------------------------------------------------

0 StatAddr 127.0.0.1 0 0 1 1 0 0 1 240 29
0 CLI Rd vcl.load boot /tmp/vcl.XXu1YKyr
0 CLI Wr 0 200 Loaded "/tmp/vcl.XXu1YKyr" as "boot"

0 CLI Rd vcl.use boot
0 CLI Wr 0 200
0 CLI Rd start
0 CLI Wr 0 200
0 WorkThread 0xae04f1b4 start
13 SessionOpen c 127.0.0.1 42445
13 ReqStart c 127.0.0.1 42445 555485910
13 RxRequest c GET
13 RxURL c /headerstuff
13 RxProtocol c HTTP/1.1
13 RxHeader c Host: localhost:9008
13 RxHeader c User-Agent: Mozilla/5.0 (X11; U; Linux i686;
da-DK; rv:1.8.0.5) Gecko/20060731 Ubuntu/dapper-security Firefox/1.5.0.5
13 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
13 RxHeader c Accept-Language: da,en-us;q=0.7,en;q=0.3
13 RxHeader c Accept-Encoding: gzip,deflate
13 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
13 RxHeader c Keep-Alive: 300
13 RxHeader c Connection: keep-alive
13 VCL_call c recv
13 VCL_return c lookup
13 VCL_call c miss
13 VCL_return c fetch
16 BackendOpen b default 127.0.0.1 54438 127.0.0.1 8080
16 BackendXID b 555485910
13 Backend c 16 default
16 TxRequest b GET
16 TxURL b /headerstuff
16 TxProtocol b HTTP/1.1
16 TxHeader b Host: localhost:9008
16 TxHeader b User-Agent: Mozilla/5.0 (X11; U; Linux i686;
da-DK; rv:1.8.0.5) Gecko/20060731 Ubuntu/dapper-security Firefox/1.5.0.5
16 TxHeader b Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
16 TxHeader b Accept-Language: da,en-us;q=0.7,en;q=0.3
16 TxHeader b Accept-Encoding: gzip,deflate
16 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
16 TxHeader b X-Varnish: 555485910
16 TxHeader b X-Forwarded-for: 127.0.0.1
16 RxProtocol b HTTP/1.1
16 RxStatus b 200
16 RxResponse b OK
16 RxHeader b Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
16 RxHeader b Date: Wed, 28 Mar 2007 18:15:41 GMT
16 RxHeader b Content-Length: 29
16 RxHeader b Content-Type: text/plain; charset=iso-8859-15
13 TTL c 555485910 RFC 120 1175105741 1175105741 0 0 0
13 VCL_call c fetch
13 VCL_return c insert
13 ObjProtocol c HTTP/1.1
13 ObjStatus c 200
13 ObjResponse c OK
13 ObjHeader c Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
13 ObjHeader c Date: Wed, 28 Mar 2007 18:15:41 GMT
13 ObjHeader c Content-Type: text/plain; charset=iso-8859-15
13 ObjHeader c Content-Length: 29
16 BackendReuse b default
13 Length c 29
13 TxProtocol c HTTP/1.1
13 TxStatus c 200
13 TxResponse c OK
13 TxHeader c Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
13 TxHeader c Date: Wed, 28 Mar 2007 18:15:41 GMT
13 TxHeader c Content-Type: text/plain; charset=iso-8859-15
13 TxHeader c Content-Length: 29
13 TxHeader c X-Varnish: 555485910
13 TxHeader c Age: 0
13 TxHeader c Via: 1.1 varnish
13 ReqEnd c 555485910 1175105741.342312000
1175105741.518589000 0.000377000 0.007488000 0.168789000


JUST PRESS F5 - we get it from the cache
-----------------------------------------

0 StatAddr 127.0.0.1 0 0 1 1 0 0 1 240 29
13 ReqStart c 127.0.0.1 42447 1020536477
13 RxRequest c GET
13 RxURL c /headerstuff
13 RxProtocol c HTTP/1.1
13 RxHeader c Host: localhost:9008
13 RxHeader c User-Agent: Mozilla/5.0 (X11; U; Linux i686;
da-DK; rv:1.8.0.5) Gecko/20060731 Ubuntu/dapper-security Firefox/1.5.0.5
13 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
13 RxHeader c Accept-Language: da,en-us;q=0.7,en;q=0.3
13 RxHeader c Accept-Encoding: gzip,deflate
13 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
13 RxHeader c Keep-Alive: 300
13 RxHeader c Connection: keep-alive
13 RxHeader c Cache-Control: max-age=0
13 VCL_call c recv
13 VCL_return c lookup
13 Hit c 1020536476
13 VCL_call c hit
13 VCL_return c deliver
13 Length c 29
13 TxProtocol c HTTP/1.1
13 TxStatus c 200
13 TxResponse c OK
13 TxHeader c Server: Zope/(Zope 2.10.2-final, python 2.4.3,
linux2) ZServer/1.1
13 TxHeader c Date: Wed, 28 Mar 2007 18:15:43 GMT
13 TxHeader c Content-Type: text/plain; charset=iso-8859-15
13 TxHeader c Content-Length: 29
13 TxHeader c X-Varnish: 1020536477 1020536476
13 TxHeader c Age: 3
13 TxHeader c Via: 1.1 varnish
13 ReqEnd c 1020536477 1175105746.436478000
1175105746.561595000 2.482832000 0.000047000 0.125070000
Checking for purge prevents caching [ In reply to ]
In message <460AC430.6050309 at giraffen.dk>, Anton Stonor writes:
>Dag-Erling Sm?rgrav wrote:
>
>OK, here it is:

I don't see anything wrong in this logfile ?

>SECOND "NORMAL" REQUEST - now, it should really be in the cache
>---------------------------------------------------------------
>
> 0 StatAddr 127.0.0.1 0 0 1 1 0 0 1 240 29
> 0 CLI Rd vcl.load boot /tmp/vcl.XXu1YKyr
> 0 CLI Wr 0 200 Loaded "/tmp/vcl.XXu1YKyr" as "boot"

You restarted varnish here, didn't you ?


--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
Checking for purge prevents caching [ In reply to ]
Poul-Henning Kamp wrote:

>> SECOND "NORMAL" REQUEST - now, it should really be in the cache
>> ---------------------------------------------------------------
>>
>> 0 StatAddr 127.0.0.1 0 0 1 1 0 0 1 240 29
>> 0 CLI Rd vcl.load boot /tmp/vcl.XXu1YKyr
>> 0 CLI Wr 0 200 Loaded "/tmp/vcl.XXu1YKyr" as "boot"
>
> You restarted varnish here, didn't you ?

Ah that is a restart? Nope, I didn't restart anything.

These lines appear on every "normal" request except for f5 and ctrl-f5.
When I remove the VCL, Varnish does not restart, but are running smooth.

What is the best way to dig deeper into why the restarts happen under
this condition?

/Anton
Checking for purge prevents caching [ In reply to ]
In message <460BBD60.5030601 at giraffen.dk>, Anton Stonor writes:

>What is the best way to dig deeper into why the restarts happen under
>this condition?

Run varnishd with "-d -d" options and watch what it says

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
Checking for purge prevents caching [ In reply to ]
Just to share the conclusion on my issue on Varnish restaring
unpredictable with an innocent snippet of VCL:

sub vcl_hit {

if(req.http.Cache-Control == "no-cache") {
set obj.ttl = 0s; error 200 "Hey, we got a purge";
}
}

I have not been able to reproduce it in another environment and with the
latest Varnish. So consider issue #92 bogus.

/Anton