Changed date format for Last-Modified header breaks caching for Varnish/Nginx configs

klausi opened a new pull request for this issue.

So this is the primitive rollback patch that we are going to use on our sites in the meantime.

I see in my testing that browsers do not cache pages in their local cache when using the new DATE_RFC7231 as Last-Modified date. They issue requests to the server with a If-Modified-Since header (containing the last modified date from the last response) or If-None-Match headers which Varnish just answers with a 304 not modified empty response.

Then the browser just displays the last version of the page it got, which can be the authenticated user version, which is wrong when the user is logged out.

@girishmuraly: Varnish is not storing anything for authenticated users. The point is that if you log out then you still get an authenticated user page from your local browser.

Varnish config file we are using attached.

Oh, and our Varnish version:

$ varnishd -V
varnishd (varnish-3.0.6 revision 1899836)

The issue that introduced the old DATE_RFC1123 for Last-Modified originally for Drupal 7 is #147310: Implement better cache headers for reverse proxies. It even has a comprehensive comment about the bug we are seeing here:

+ * Also give each page a unique ETag. This will force clients to include both
+ * an If-Modified-Since header and an If-None-Match header when doing
+ * conditional requests for the page (required by RFC 2616, section 13.3.4),
+ * making the validation more robust. This is a workaround for a bug in Mozilla
+ * Firefox that is triggered when Drupal's caching is enabled and the user
+ * accesses Drupal via an HTTP proxy (see
+ * https://bugzilla.mozilla.org/show_bug.cgi?id=269303): When an authenticated
+ * user requests a page, and then logs out and requests the same page again,
+ * Firefox may send a conditional request based on the page that was cached
+ * locally when the user was logged in. If this page did not have an ETag
+ * header, the request only contains an If-Modified-Since header. The date will
+ * be recent, because with authenticated users the Last-Modified header always
+ * refers to the time of the request. If the user accesses Drupal via a proxy
+ * server, and the proxy already has a cached copy of the anonymous page with an
+ * older Last-Modified date, the proxy may respond with 304 Not Modified, making
+ * the client think that the anonymous and authenticated pageviews are
+ * identical.

klausi pushed some commits to the pull request.

For an interdiff please see the list of recent commits.

Right, implemented znerol's suggestion, which also fixes this issue on my test site.

Just confirmed that Drupal 8 also does not set Last-Modified and ETag headers for authenticated user pages. So no patch against Drupal 8 is necessary and we can continue here against Drupal 7.

znerol said on IRC that we should also check what happens with generated images (image styles) and private downloads.

Private downloads are not affected by this change because they are always uncachable by design, so removing the headers is not a problem.

Image styles using file_transfer() are also not affected since they also set the default Cache-control: no-cache, must-revalidate, post-check=0, pre-check=0 header. That means the browser will request the image again anyway next time, so the Last-Modified and ETag headers are useless here as well.

No, the problem is that the local browser does not respect the Cache-Control: no-cache header. Then the browser sends a request to Varnish with an If-Modified-Since header and Varnish happily answers with 304, so the browser displays the old version of the page where the user is still logged in.

Varnish is not storing a no-cache page. It only stores the anonymous user version with a last modified date. Then the browser asks Varnish if the page has changed with the If-Modified-Since header. Varnish answers with 304, and now the browser should display the anonymous version of the page, but it is lazy and just displays the logged in version, which it should not even have in the cache.

This all goes away when we do not send out Last-Modified headers for authenticated user pages that are not cachable anyway.

First request as anonymous user to the front page, Varnish answers, no request to the backend:

Request headers:
GET / HTTP/1.1
Host: example.com
Connection: keep-alive
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Referer: http://example.com/
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,de;q=0.6

Response headers:

HTTP/1.1 200 OK
Server: nginx
Content-Type: text/html; charset=utf-8
X-Drupal-Cache: MISS
Etag: "1417192716-1"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Cache-Control: public, max-age=1800
Last-Modified: Fri, 28 Nov 2014 16:38:36 GMT
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Vary: Cookie, Accept-Encoding
Content-Encoding: gzip
Content-Length: 2337
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:42:29 GMT
X-Varnish: 61743614 61743488
Age: 232
Via: 1.1 varnish
Connection: keep-alive

Then I log in on the front page login block:

Request headers:
POST /node?destination=node HTTP/1.1
Host: example.com
Connection: keep-alive
Content-Length: 117
Cache-Control: max-age=0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Origin: http://example.com
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Content-Type: application/x-www-form-urlencoded
Referer: http://example.com/
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.8,de;q=0.6
Cookie: has_js=1

Response headers:

HTTP/1.1 302 Moved Temporarily
Server: nginx
Content-Type: text/html; charset=utf-8
X-Drupal-Cache: MISS
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Fri, 28 Nov 2014 16:46:06 GMT
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
ETag: "1417193166"
Content-Language: en
Set-Cookie: SESSac4b504041d138bd7b96d9d03d14626e=JbU-YqUHoUQN_XE8GN5R3sw_WbfCTCwcdi--2polO-8; expires=Sun, 21-Dec-2014 20:19:26 GMT; Max-Age=2000000; path=/; domain=.example.com; HttpOnly
Location: http://example.com/node
Content-Length: 0
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:46:06 GMT
X-Varnish: 61743694
Age: 0
Via: 1.1 varnish
Connection: keep-alive

Request headers:

GET /node HTTP/1.1
Host: example.com
Connection: keep-alive
Cache-Control: max-age=0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Referer: http://example.com/
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,de;q=0.6
Cookie: has_js=1; SESSac4b504041d138bd7b96d9d03d14626e=JbU-YqUHoUQN_XE8GN5R3sw_WbfCTCwcdi--2polO-8

Response headers:

HTTP/1.1 200 OK
Server: nginx
Content-Type: text/html; charset=utf-8
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Fri, 28 Nov 2014 16:46:06 GMT
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Content-Encoding: gzip
Content-Length: 2083
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:46:06 GMT
X-Varnish: 61743695
Age: 0
Via: 1.1 varnish
Connection: keep-alive

Then I click the frontpage again:

GET / HTTP/1.1
Host: example.com
Connection: keep-alive
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Referer: http://example.com/node
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,de;q=0.6
Cookie: SESSac4b504041d138bd7b96d9d03d14626e=FDWmwVi9DKwUSDpY-NhuEe_GVqrvPtOCLo69DMb-sRg; has_js=1
If-None-Match: "1417192716-1"

Response headers:

HTTP/1.1 200 OK
Server: nginx
Content-Type: text/html; charset=utf-8
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Fri, 28 Nov 2014 16:51:02 GMT
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Content-Encoding: gzip
Content-Length: 2082
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:51:02 GMT
X-Varnish: 61743800
Age: 0
Via: 1.1 varnish
Connection: keep-alive

Then I click the logout link:

GET /user/logout HTTP/1.1
Host: example.com
Connection: keep-alive
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Referer: http://example.com/
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,de;q=0.6
Cookie: SESSac4b504041d138bd7b96d9d03d14626e=FDWmwVi9DKwUSDpY-NhuEe_GVqrvPtOCLo69DMb-sRg; has_js=1

Response headers:

HTTP/1.1 302 Moved Temporarily
Server: nginx
Content-Type: text/html
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Fri, 28 Nov 2014 16:52:42 GMT
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
ETag: "1417193562"
Set-Cookie: SESSac4b504041d138bd7b96d9d03d14626e=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/; domain=.example.com; httponly
Location: http://example.com/
Content-Length: 0
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:52:42 GMT
X-Varnish: 61743816
Age: 0
Via: 1.1 varnish
Connection: keep-alive

Request headers:

GET / HTTP/1.1
Host: example.com
Connection: keep-alive
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2114.2 Safari/537.36
Referer: http://example.com/
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,de;q=0.6
Cookie: has_js=1
If-Modified-Since: Fri, 28 Nov 2014 16:51:02 GMT

Response headers:

HTTP/1.1 304 Not Modified
Server: nginx
Content-Type: text/html; charset=utf-8
X-Drupal-Cache: MISS
Etag: "1417192716-1"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Cache-Control: public, max-age=1800
Last-Modified: Fri, 28 Nov 2014 16:38:36 GMT
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Vary: Cookie, Accept-Encoding
Content-Encoding: gzip
Accept-Ranges: bytes
Date: Fri, 28 Nov 2014 16:52:42 GMT
X-Varnish: 61743817 61743488
Age: 845
Via: 1.1 varnish
Connection: keep-alive

And after that request my browser shows me the front page as logged in user, although I'm logged out.

All responses that have an Age header as 0 come from the nginx/PHP backend (Varnish has passed them through), all other responses with Age > 0 come from Varnish directly without invoking the backend.

Thanks Damien. Indeed, the Etag is missing for authenticated requests. It looks like this is related to Nginx and gzip encoding of responses. It appears that Nginx removes the Etag if it alters a response to gzip it. Could not find a good doc page or similar to confirm that yet.

klausi pushed some commits to the pull request.

For an interdiff please see the list of recent commits.

@Damien: the absence of Vary: Cookie is not a bug. RFC 2616 says "A server MAY include a Vary header field with a non-cacheable response ...", so this is not a requirement.

So we cleared up the mystery - Nginx messes with ETags, which we cannot easily fix (we don't want to hack Nginx sources).

Now that we have a better understanding of the situation patch reviews welcome :-)

I think that addition to the release notes is fine, thanks!

You understood correctly. Now that browsers understand the Last-Modified format they make a request to the server, but Nginx has removed the ETag so they don't send a If-None-Match header. Varnish answers with 304 and the browser just displays the previous logged-in page.

Nginx removes the ETag when it applies gzip compression; I added gzip as prerequisite to the issue summary.

Assuming this was just a random testbot fail.