h2o returns 304 instead of 200 in connection with php-fpm

[utrenkner]

This is driving me crazy, but finally I can at least describe the problem:
I have an installation of the CMS TYPO3 running in a FreeBSD jail. Everything seems to be working ok, except that in the backend, a certain URL is returned with a 304 instead of 200. And thus an older version of the content is loaded.

Both Apache (v. 2.4.27 with mod_php) and Nginx (v. 1.12.1 with php-fpm) return the new page with HTTP Status 200. Especially the latter is interesting, as it uses the same php-fpm via UNIX socket as the h2o. I can even stop h2o and start nginx and nginx serves the correct new version. And in the other direction, I can stop nginx, start h2o and get a 304 instead.

Does anyone have an idea, what could possibly be the reason for this difference?

Here are the HTTP headers, when I force-reload the URL from h2o (CTRL + SHIFT + R):

http://testserver.local/typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit

GET /typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit HTTP/1.1
Host: testserver.local
User-Agent: Mozilla/5.0 (X11; FreeBSD i386; rv:43.0) Gecko/20100101 Firefox/43.0 SeaMonkey/2.40
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Cookie: be_typo_user=9dc68c1e0a89687f525a2ae44b410ca2; PHPSESSID=bk7hs9h6vqbae93t64bv0n3b93; phpMyAdmin=bk7hs9h6vqbae93t64bv0n3b93
DNT: 1
Connection: keep-alive
Upgrade-Insecure-Requests: 1
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.1 200 OK
Date: Tue, 18 Jul 2017 12:50:28 GMT
Connection: keep-alive
Server: h2o/2.2.2
X-Powered-By: PHP/5.6.31
Expires: 0
Last-Modified: Tue, 18 Jul 2017 12:50:28 GMT
Cache-Control: no-cache, must-revalidate
Pragma: no-cache
x-frame-options: SAMEORIGIN
Content-Type: text/html;charset=utf-8
Content-Encoding: gzip
Vary: accept-encoding
Accept-Ranges: none
Transfer-Encoding: chunked

Note, all the cache-related headers indicating that this page should not be cached!

And here h2o upon normal reload (STRG + R) replies with the wrong 304:

http://testserver.local/typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit

GET /typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit HTTP/1.1
Host: testserver.local
User-Agent: Mozilla/5.0 (X11; FreeBSD i386; rv:43.0) Gecko/20100101 Firefox/43.0 SeaMonkey/2.40
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Cookie: be_typo_user=9dc68c1e0a89687f525a2ae44b410ca2; PHPSESSID=bk7hs9h6vqbae93t64bv0n3b93; phpMyAdmin=bk7hs9h6vqbae93t64bv0n3b93
DNT: 1
Connection: keep-alive
Upgrade-Insecure-Requests: 1
If-Modified-Since: Tue, 18 Jul 2017 12:50:28 GMT
Cache-Control: max-age=0

HTTP/1.1 304 Not Modified
Date: Tue, 18 Jul 2017 12:51:24 GMT
Connection: keep-alive
Server: h2o/2.2.2
Etag: "58f63dd6-603"
Vary: accept-encoding

Nginx and Apache always reply with a 200, like this:

http://testserver.local/typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit

GET /typo3/alt_doc.php?returnUrl=%2Ftypo3conf%2Fext%2Ftemplavoila%2Fmod1%2Findex.php%3Fid%3D38347%23ccfa36ed4fe4ea9ae5540ab0356ea4897&edit[tt_content][104987]=edit HTTP/1.1
Host: testserver.local
User-Agent: Mozilla/5.0 (X11; FreeBSD i386; rv:43.0) Gecko/20100101 Firefox/43.0 SeaMonkey/2.40
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Cookie: be_typo_user=9dc68c1e0a89687f525a2ae44b410ca2; PHPSESSID=bk7hs9h6vqbae93t64bv0n3b93; phpMyAdmin=bk7hs9h6vqbae93t64bv0n3b93
DNT: 1
Connection: keep-alive
Upgrade-Insecure-Requests: 1
If-Modified-Since: Tue, 18 Jul 2017 12:48:18 GMT
Cache-Control: max-age=0

HTTP/1.1 200 OK
Server: nginx/1.12.1
Date: Tue, 18 Jul 2017 12:49:32 GMT
Content-Type: text/html;charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
X-Powered-By: PHP/5.6.31
Expires: 0
Last-Modified: Tue, 18 Jul 2017 12:49:32 GMT
Cache-Control: no-cache, must-revalidate
Pragma: no-cache
x-frame-options: SAMEORIGIN

I tried different browsers (Firefox and Chromium), different caching headers, HTTP/1 and HTTP/2... the result is always the same.

Is this some kind of bug in h2o? Or could a certain parameter or environment variable not be passed to php-fpm in h2o but in Nginx and Apache?

[utrenkner]

I further tested this problem - this time with cURL: When a If-Modified-Since header is supplied by the browser and it is within the last 3 months, I get a 304. When I supply no If-Modified-Since header or one with a date further than 3 months ago, I get the correct 200.

This leads me to the question: Are these three months hard-coded in h2o? How could I work around it? E.g. is it possible to strip the If-Modified-Since header from this specific request, before h2o actually does something with the request?

[utrenkner]

One found one more detail. I have captured the fastcgi traffic on the UNIX socket (using socat as described here).

When supplying a If-Modified-Since header with a time of less than 3 months, h2o does not even relay that request to php-fpm. It just answers the browser by sending the 304. This is different when using Nginx. There, every request is passed on to the php-fpm server. So it really seems that the problem lies with how h2o handles this request.

[utrenkner]

I could identify the Bug! The problem arises, because h2o ignores that the content is dynamic and simply checks the last-modified-time of the PHP file. If the modification time of the file was at least 1 second after the time given by the If-Modified-Since header, h2o returned 200, and 304 otherwise.

I guess that this bug is to be found in /lib/handler/file.c (Lines 629-637).

[utrenkner]

Found a temporary quick-fix.

[deweerdt]

Ah nice find. It looks like simply moving the dynamic handling earlier in the file would result in the behavior you expect:

diff --git a/lib/handler/file.c b/lib/handler/file.c
index adc95f07..c2c35cf2 100644
--- a/lib/handler/file.c
+++ b/lib/handler/file.c
@@ -619,6 +619,13 @@ static int serve_with_generator(struct st_h2o_sendfile_generator_t *generator, h
         method_type = METHOD_IS_OTHER;
     }

+    /* obtain mime type */
+    if (mime_type->type == H2O_MIMEMAP_TYPE_DYNAMIC) {
+        do_close(&generator->super, req);
+        return delegate_dynamic_request(req, req->path_normalized.len, rpath, rpath_len, mime_type);
+    }
+    assert(mime_type->type == H2O_MIMEMAP_TYPE_MIMETYPE);
+
     /* if-non-match and if-modified-since */
     if ((if_none_match_header_index = h2o_find_header(&req->headers, H2O_TOKEN_IF_NONE_MATCH, SIZE_MAX)) != -1) {
         h2o_iovec_t *if_none_match = &req->headers.entries[if_none_match_header_index].value;
@@ -636,13 +643,6 @@ static int serve_with_generator(struct st_h2o_sendfile_generator_t *generator, h
         }
     }

-    /* obtain mime type */
-    if (mime_type->type == H2O_MIMEMAP_TYPE_DYNAMIC) {
-        do_close(&generator->super, req);
-        return delegate_dynamic_request(req, req->path_normalized.len, rpath, rpath_len, mime_type);
-    }
-    assert(mime_type->type == H2O_MIMEMAP_TYPE_MIMETYPE);
-
     /* only allow GET or POST for static files */
     if (method_type == METHOD_IS_OTHER) {
         do_close(&generator->super, req);

@kazuho What do you think? Intuitively it sounds like we should always invoke the cgi handler when the content is dynamic?