4

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
Florian
  • 103
  • 10

2 Answers2

4

Take a look at your request headers.

Cache-Control:no-cache

and 

Cache-Control:max-age=0

Edit: These were not the cause of trouble and can be safely ignored. Varnish documentation stating:

Note By default, Varnish does not care about the Cache-Control request header. If you want to let users update the cache via a force refresh you need to do it yourself.

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. 

-   Debug          "XXXX HIT-FOR-PASS"
-   HitPass        2147516455

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:

    if (beresp.ttl < 48h) {
      set beresp.uncacheable = true;
      return (deliver);
    }

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: 

    if (beresp.ttl < 48h) {
      set beresp.ttl = 48h;
    }

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_ttl at default value which is 120 seconds. (that can be changed on the varnishd command line)

Community
  • 1
Fox
  • 3,887
  • 16
  • 23
  • Caching isn't disabled in chrome debug settings and i got the response headers with curl, too (added them to my question). I don't know, where the no-cache header comes from :/ – Florian May 10 '15 at 20:46
  • @Florian then maybe you could try using `varnishlog`, to see what happens with your request. – Fox May 10 '15 at 20:59
  • like i said, i'm a newbie in varnish, so i added the varnishlog to my question and hope, that you can take a look. I think, that the VCL_call to BACKEND_FETCH can't be correct?! – Florian May 10 '15 at 21:06
  • You're my hero! :D I tested it with my test.php and it works fine with curl, but not with my Chrone (and like i said, the checkbox for "disable cache" isn't checked. I need to find out, why this happens, maybe you have an idea? But the questions i asked here is answered, many thanks for that! I will ask on the discussion page, why this is directive exists :) P.S.: I have to wait the 24 hours to award my bounty to you, but you will get it! :) – Florian May 10 '15 at 22:14
  • i'll added the headers of the now working solution, it only loads the first request from cache, all requests following comes from the backend :/ – Florian May 10 '15 at 22:39
  • @Florian I have modified the answer. The Request Cache-Control headers can be safely ignored. – Fox May 10 '15 at 22:39
  • I think i found the problem. Chrome sends some cookies and varnish doesn't cache these requests. So i now check for a userID cookie (which will be set, when a user is logged in) and unset all cookies, if the userID isn't set. Just to be sure: Can i do this savely? :) – Florian May 10 '15 at 23:08
1

can you post the content of /etc/varnish/default.vlc configuration file? Look like your request don't even go to varnish, or at least go though it and varnish does check whether or not the content is reachable from cache.

Moreover, can you add this into this configuration file, and restart varnish after this? And then from your client (wget or curl) give us the output of two consecutive requests? Especially for the extra HTTP X-MISC added?

sub vcl_deliver {
    if (obj.hits > 0) {
            set resp.http.X-MISC = "HIT";
    } else {
            set resp.http.X-MISC = "MIS";
    }
}
philippe
  • 2,131
  • 4
  • 30
  • 53
  • I copied the configuration from https://www.mediawiki.org/w/index.php?title=Manual:Varnish_caching&oldid=1353762#Configuring_Varnish_4.x (like i mentioned in my question, maybe i should make it much more clear :)). I added your code for deliver to my varnish default.vcl, restarted varnish and made the two requests. I added the headers to my question :) – Florian May 10 '15 at 21:36