I'm trying to use varnish cache to cache a mediawiki page for logged in users. I use ubuntu 14.04, varnish 4.0.3 (port 80) and nginx as a webserver (port 8080). As a vcl I copied the configuration from mediawiki.org and with my limited understanding of varnish's vcl I can't find a problem.
Now I have the problem, that mediawiki pages aren't cached (they're delivered through varnish, but not cached (Age is always 0 and only one X-Varnish request id). So I tried to cache a test php file (test.php), which is in the root of my webpage (i.e. example.com/test.php) and checked, if it is cached correctly, but it isn't. I see the same headers, and sometimes the Cache-control with max-age=0. The test.php file has the following content:
<?php
echo 'Hello world';
Now I have no idea where the problem is, I searched by myself, but couldn't find any thread, where at least a non-functional, static test page isn't cached correctly. Can anyone assist me?
Here the headers for the first request (i have replaced the ip and domain by example ones :)):
Request Headers
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding:gzip, deflate, sdch
Accept-Language:de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
Cache-Control:no-cache
Connection:keep-alive
Host:example.com
Pragma:no-cache
User-Agent:Mozilla/5.0 (Linux; Android 4.3; Nexus 7 Build/JSS15Q) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.72 Safari/537.36
Remote Address:0.0.0.0:80
Request URL:http://example.com/test.php
Request Method:GET
Status Code:200 OK
Response Headers
Accept-Ranges:bytes
Age:0
Connection:keep-alive
Content-Encoding:gzip
Content-Type:text/html
Date:Sun, 10 May 2015 20:05:05 GMT
Server:nginx/1.4.6 (Ubuntu)
Transfer-Encoding:chunked
Via:1.1 varnish-v4
X-Powered-By:HHVM/3.7.0
X-Varnish:2
And the headers for the second request:
Request Headers
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding:gzip, deflate, sdch
Accept-Language:de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
Cache-Control:max-age=0
Connection:keep-alive
Host:example.com
User-Agent:Mozilla/5.0 (Linux; Android 4.3; Nexus 7 Build/JSS15Q) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.72 Safari/537.36
Remote Address:0.0.0.0:80
Request URL:http://example.com/test.php
Request Method:GET
Response Headers
Status Code:200 OK
Accept-Ranges:bytes
Age:0
Connection:keep-alive
Content-Encoding:gzip
Content-Length:24
Content-Type:text/html
Date:Sun, 10 May 2015 20:07:49 GMT
Server:nginx/1.4.6 (Ubuntu)
Via:1.1 varnish-v4
X-Powered-By:HHVM/3.7.0
X-Varnish:5
Just for completeness here the nginx configuration for this site:
server {
# Running port
listen 8080;
server_name example.com;
# Root directory
root /data/www/example.com/main;
index index.php;
location ~ \.php$ {
fastcgi_pass 127.0.0.1:9000;
fastcgi_index index.php;
fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
include fastcgi_params;
}
client_max_body_size 5m;
client_body_timeout 60;
location / {
try_files $uri $uri/ @rewrite;
}
location @rewrite {
rewrite ^/(.*)$ /index.php?title=$1&$args;
}
location ^~ /maintenance/ {
return 403;
}
location ~* \.(js|css|png|jpg|jpeg|gif|ico)$ {
try_files $uri /index.php;
expires max;
log_not_found off;
}
location = /_.gif {
expires max;
empty_gif;
}
location ^~ /cache/ {
deny all;
}
location /dumps {
root /data/www/example.com/local;
autoindex on;
}
}
EDIT: Response headers with curl:
HTTP/1.1 200 OK
Server: nginx/1.4.6 (Ubuntu)
Date: Sun, 10 May 2015 20:42:01 GMT
Content-Type: text/html
X-Powered-By: HHVM/3.7.0
Vary: Accept-Encoding
X-Varnish: 17
Age: 0
Via: 1.1 varnish-v4
Content-Length: 4
Connection: keep-alive
Accept-Ranges: bytes
EDIT2: And the varnishlog for this request:
* << BeReq >> 53
- Begin bereq 52 pass
- Timestamp Start: 1431291731.991895 0.000000 0.000000
- BereqMethod GET
- BereqURL /test.php
- BereqProtocol HTTP/1.1
- BereqHeader User-Agent: curl/7.35.0
- BereqHeader Host: example.com
- BereqHeader Accept: */*
- BereqHeader X-Forwarded-For: 0.0.0.1
- BereqHeader X-Varnish: 53
- VCL_call BACKEND_FETCH
- VCL_return fetch
- Backend 17 default default(127.0.0.1,,8080)
- Timestamp Bereq: 1431291731.991930 0.000035 0.000035
- Timestamp Beresp: 1431291731.992944 0.001049 0.001014
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Server: nginx/1.4.6 (Ubuntu)
- BerespHeader Date: Sun, 10 May 2015 21:02:11 GMT
- BerespHeader Content-Type: text/html
- BerespHeader Transfer-Encoding: chunked
- BerespHeader Connection: keep-alive
- BerespHeader X-Powered-By: HHVM/3.7.0
- BerespHeader Vary: Accept-Encoding
- TTL RFC 120 -1 -1 1431291732 1431291732 1431291731 0 0
- VCL_call BACKEND_RESPONSE
- TTL VCL -1 120 0 1431291732
- VCL_return deliver
- Storage malloc Transient
- ObjProtocol HTTP/1.1
- ObjStatus 200
- ObjReason OK
- ObjHeader Server: nginx/1.4.6 (Ubuntu)
- ObjHeader Date: Sun, 10 May 2015 21:02:11 GMT
- ObjHeader Content-Type: text/html
- ObjHeader X-Powered-By: HHVM/3.7.0
- ObjHeader Vary: Accept-Encoding
- Fetch_Body 2 chunked stream
- BackendReuse 17 default(127.0.0.1,,8080)
- Timestamp BerespBody: 1431291731.993028 0.001132 0.000083
- Length 4
- BereqAcct 129 0 129 212 13 225
- End
* << Request >> 52
- Begin req 51 rxreq
- Timestamp Start: 1431291731.991840 0.000000 0.000000
- Timestamp Req: 1431291731.991840 0.000000 0.000000
- ReqStart 79.193.10.211 52555
- ReqMethod GET
- ReqURL /test.php
- ReqProtocol HTTP/1.1
- ReqHeader User-Agent: curl/7.35.0
- ReqHeader Host: example.com
- ReqHeader Accept: */*
- ReqHeader X-Forwarded-For: 0.0.0.1
- VCL_call RECV
- ReqUnset X-Forwarded-For: 0.0.0.1
- ReqHeader X-Forwarded-For: 0.0.0.1
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Debug "XXXX HIT-FOR-PASS"
- HitPass 2147516455
- VCL_call PASS
- VCL_return fetch
- Link bereq 53 pass
- Timestamp Fetch: 1431291731.993038 0.001199 0.001199
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Server: nginx/1.4.6 (Ubuntu)
- RespHeader Date: Sun, 10 May 2015 21:02:11 GMT
- RespHeader Content-Type: text/html
- RespHeader X-Powered-By: HHVM/3.7.0
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 52
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- VCL_return deliver
- Timestamp Process: 1431291731.993080 0.001240 0.000041
- RespHeader Content-Length: 4
- Debug "RES_MODE 2"
- RespHeader Connection: keep-alive
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1431291731.993190 0.001350 0.000110
- Debug "XXX REF 1"
- ReqAcct 82 0 82 269 4 273
- End
* << Session >> 51
- Begin sess 0 HTTP/1
- SessOpen 0.0.0.1 52555 :80 0.0.0.1 80 1431291731.989801 14
- Link req 52 rxreq
- SessClose REM_CLOSE 0.037
- End
EDIT3: Headers for two requests after a new deliver configuration:
florian@florian-VirtualBox:/var/www/html/w$ curl -v http://example.com/test.php
* Hostname was NOT found in DNS cache
* Trying 0.0.0.0...
* Connected to example.com (0.0.0.0) port 80 (#0)
> GET /test.php HTTP/1.1
> User-Agent: curl/7.35.0
> Host: example.com
> Accept: */*
>
< HTTP/1.1 200 OK
* Server nginx/1.4.6 (Ubuntu) is not blacklisted
< Server: nginx/1.4.6 (Ubuntu)
< Date: Sun, 10 May 2015 21:32:52 GMT
< Content-Type: text/html
< X-Powered-By: HHVM/3.7.0
< X-Varnish: 2
< Age: 0
< Via: 1.1 varnish-v4
< X-MISC: MIS
< Transfer-Encoding: chunked
< Connection: keep-alive
< Accept-Ranges: bytes
florian@florian-VirtualBox:/var/www/html/w$ curl -v http://example.com/test.php
* Hostname was NOT found in DNS cache
* Trying 0.0.0.0...
* Connected to dexample.com (0.0.0.0) port 80 (#0)
> GET /test.php HTTP/1.1
> User-Agent: curl/7.35.0
> Host: example.com
> Accept: */*
>
< HTTP/1.1 200 OK
* Server nginx/1.4.6 (Ubuntu) is not blacklisted
< Server: nginx/1.4.6 (Ubuntu)
< Date: Sun, 10 May 2015 21:32:53 GMT
< Content-Type: text/html
< X-Powered-By: HHVM/3.7.0
< Vary: Accept-Encoding
< X-Varnish: 32770
< Age: 0
< Via: 1.1 varnish-v4
< X-MISC: MIS
< Content-Length: 4
< Connection: keep-alive
< Accept-Ranges: bytes
EDITX: Now working for the first request, but all following requests are delivered by the backend, here the headers :/ It sounds false, that varnish sends a max-age=0 cache-control header?
First request:
Request Headers
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding:gzip, deflate, sdch
Accept-Language:de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
Connection:keep-alive
Host:example.com
User-Agent:Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36
Response Headers
Accept-Ranges:bytes
Age:32
Cache-Control:s-maxage=18000, must-revalidate, max-age=0
Connection:keep-alive
Content-Encoding:gzip
Content-language:de
Content-Length:12102
Content-Type:text/html; charset=UTF-8
Date:Sun, 10 May 2015 22:33:34 GMT
Last-Modified:Sun, 10 May 2015 17:33:34 GMT
Server:nginx/1.4.6 (Ubuntu)
Vary:Accept-Encoding, Cookie
Via:1.1 varnish-v4
X-Content-Type-Options:nosniff
X-Powered-By:HHVM/3.7.0
X-UA-Compatible:IE=Edge
X-Varnish:131094 32817
Second request:
Request Headers
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding:gzip, deflate, sdch
Accept-Language:de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
Cache-Control:max-age=0
Connection:keep-alive
Cookie:centralnotice_bucket=0-4.2; __atuvc=1%7C19; __atuvs=554fdce151aee950000; mediaWiki.user.bucket%3Aext.articleFeedback-tracking=0%3Aignore; clicktracking-session=gCQO3Eyuh6ZzPCP0q9mTliq4RNSPD1u2O
Host:example.com
User-Agent:Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.90 Safari/537.36
Response Headers
Accept-Ranges:bytes
Age:0
Cache-Control:s-maxage=18000, must-revalidate, max-age=0
Connection:keep-alive
Content-Encoding:gzip
Content-language:de
Content-Type:text/html; charset=UTF-8
Date:Sun, 10 May 2015 22:37:48 GMT
Last-Modified:Sun, 10 May 2015 17:37:48 GMT
Server:nginx/1.4.6 (Ubuntu)
Transfer-Encoding:chunked
Vary:Accept-Encoding, Cookie
Via:1.1 varnish-v4
X-Content-Type-Options:nosniff
X-Powered-By:HHVM/3.7.0
X-UA-Compatible:IE=Edge
X-Varnish:65630
Best Answer
Take a look at your request headers.
and
Edit: These were not the cause of trouble and can be safely ignored. Varnish documentation stating:
btw. it is a good idea to test these things using curl, that does not add any 'random' headers ...
Edit: Your trouble lies in hit-for-pass being saved for the request.
It is saved on previous request and tells varnish not to try any caching on following requests for the same resource.
Edit: Ok the solution (or rather the problem) is in this part of VCL:
Which pretty much says, that if the TTL on response is shorter than 48 hours, set that response (or rather request) as uncacheable (=hit for pass). I can't think of a reason why this is in the sample configuration (maybe someone will help me). But I'd try commenting it out and see what happens.
It seems to be a mistake on the sample configuration, as varnish 3 sample contains this:
Which just extends the ttl to 48 hours. (that is actually quite weird too, but maybe it works with mediawiki)
btw. I am assuming that you have left your
default_ttlat default value which is 120 seconds. (that can be changed on thevarnishdcommand line)