You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by "Vacelet, Manuel" <ma...@enalean.com> on 2016/06/03 07:53:42 UTC
Re: [users@httpd] Last-Modified header overridden
Hi,
Any insights from the logs, where can I look now ?
On Tue, May 31, 2016 at 5:12 PM, Vacelet, Manuel <manuel.vacelet@enalean.com
> wrote:
>
> On Tue, May 31, 2016 at 3:00 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>> Another info that it would be great to know: have you tried to set logs
>> to debug level to see if httpd can suggest you what it is doing?
>>
>> https://httpd.apache.org/docs/2.4/mod/core.html#loglevel
>>
>>
> Good idea, with trace8 I get interesting results (I highlighted the
> interesting parts):
>
> Starting php-fpm: [ OK ]
> Starting httpd: [Tue May 31 15:08:38.074202 2016] [core:trace3] [pid 46]
> core.c(3060): Setting LogLevel for all modules to trace8
> AH00558: httpd: Could not reliably determine the server's fully qualified
> domain name, using 172.17.42.7. Set the 'ServerName' directive globally to
> suppress this message
> [ OK ]
> * About to connect() to localhost port 80 (#0)
> * Trying ::1... connected
> * Connected to localhost (::1) port 80 (#0)
> > GET /headers.php HTTP/1.1
> > User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7
> NSS/3.19.1 Basic ECC zlib/1.2.3 libidn/1.18 libssh2/1.4.2
> > Host: localhost
> > Accept: */*
> >
> < HTTP/1.1 200 OK
> < Date: Tue, 31 May 2016 15:08:38 GMT
> < Server: Apache/2.4.12 (Red Hat)
> < X-Powered-By: PHP/5.6.5
> < Last-Modified: Thu, 01 Jan 1970 00:00:00 GMT
> < Content-Length: 0
> < Content-Type: text/html; charset=UTF-8
> <
> * Connection #0 to host localhost left intact
> * Closing connection #0
> [Tue May 31 15:08:38.075284 2016] [suexec:notice] [pid 46] AH01232: suEXEC
> mechanism enabled (wrapper: /opt/rh/httpd24/root/usr/sbin/suexec)
> [Tue May 31 15:08:38.082708 2016] [auth_digest:notice] [pid 47] AH01757:
> generating secret for digest authentication ...
> [Tue May 31 15:08:38.083440 2016] [lbmethod_heartbeat:notice] [pid 47]
> AH02282: No slotmem from mod_heartmonitor
> [Tue May 31 15:08:38.084944 2016] [mpm_prefork:notice] [pid 47] AH00163:
> Apache/2.4.12 (Red Hat) configured -- resuming normal operations
> [Tue May 31 15:08:38.084972 2016] [core:notice] [pid 47] AH00094: Command
> line: '/opt/rh/httpd24/root/usr/sbin/httpd'
> [Tue May 31 15:08:38.088052 2016] [core:trace5] [pid 49] protocol.c(618):
> [client ::1:54638] Request received from client: GET /headers.php HTTP/1.1
> [Tue May 31 15:08:38.088099 2016] [http:trace4] [pid 49]
> http_request.c(301): [client ::1:54638] Headers received from client:
> [Tue May 31 15:08:38.088105 2016] [http:trace4] [pid 49]
> http_request.c(305): [client ::1:54638] User-Agent: curl/7.19.7
> (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC zlib/1.2.3
> libidn/1.18 libssh2/1.4.2
> [Tue May 31 15:08:38.088109 2016] [http:trace4] [pid 49]
> http_request.c(305): [client ::1:54638] Host: localhost
> [Tue May 31 15:08:38.088112 2016] [http:trace4] [pid 49]
> http_request.c(305): [client ::1:54638] Accept: */*
> [Tue May 31 15:08:38.088292 2016] [authz_core:debug] [pid 49]
> mod_authz_core.c(809): [client ::1:54638] AH01626: authorization result of
> Require all granted: granted
> [Tue May 31 15:08:38.088300 2016] [authz_core:debug] [pid 49]
> mod_authz_core.c(809): [client ::1:54638] AH01626: authorization result of
> <RequireAny>: granted
> [Tue May 31 15:08:38.088303 2016] [core:trace3] [pid 49] request.c(293):
> [client ::1:54638] request authorized without authentication by
> access_checker_ex hook: /headers.php
> [Tue May 31 15:08:38.088403 2016] [proxy:trace2] [pid 49]
> proxy_util.c(1976): [client ::1:54638] *: using default reverse proxy
> worker for fcgi://
> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php (no keepalive)
> [Tue May 31 15:08:38.088410 2016] [proxy:debug] [pid 49]
> mod_proxy.c(1163): [client ::1:54638] AH01143: Running scheme fcgi handler
> (attempt 0)
> [Tue May 31 15:08:38.088418 2016] [proxy_ajp:debug] [pid 49]
> mod_proxy_ajp.c(710): [client ::1:54638] AH00894: declining URL fcgi://
> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
> [Tue May 31 15:08:38.088426 2016] [proxy_fcgi:debug] [pid 49]
> mod_proxy_fcgi.c(861): [client ::1:54638] AH01076: url: fcgi://
> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php proxyname:
> (null) proxyport: 0
> [Tue May 31 15:08:38.088430 2016] [proxy_fcgi:debug] [pid 49]
> mod_proxy_fcgi.c(868): [client ::1:54638] AH01078: serving URL fcgi://
> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
> [Tue May 31 15:08:38.088433 2016] [proxy:debug] [pid 49]
> proxy_util.c(2140): AH00942: FCGI: has acquired connection for (*)
> [Tue May 31 15:08:38.088442 2016] [proxy:debug] [pid 49]
> proxy_util.c(2193): [client ::1:54638] AH00944: connecting fcgi://
> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php to
> 127.0.0.1:9000
> [Tue May 31 15:08:38.088503 2016] [proxy:debug] [pid 49]
> proxy_util.c(2394): [client ::1:54638] AH00947: connected
> /opt/rh/httpd24/root/var/www/html/headers.php to 127.0.0.1:9000
> [Tue May 31 15:08:38.088517 2016] [proxy:trace2] [pid 49]
> proxy_util.c(2737): FCGI: fam 2 socket created to connect to *
> [Tue May 31 15:08:38.088586 2016] [proxy:debug] [pid 49]
> proxy_util.c(2771): AH02824: FCGI: connection established with
> 127.0.0.1:9000 (*)
> *[Tue May 31 15:08:38.089143 2016] [proxy_fcgi:trace4] [pid 49]
> util_script.c(522): [client ::1:54638] Headers from script 'headers.php':*
> [Tue May 31 15:08:38.089157 2016] [proxy_fcgi:trace4] [pid 49]
> util_script.c(523): [client ::1:54638] X-Powered-By: PHP/5.6.5
> *[Tue May 31 15:08:38.089161 2016] [proxy_fcgi:trace4] [pid 49]
> util_script.c(523): [client ::1:54638] Last-Modified: foo*
> [Tue May 31 15:08:38.089174 2016] [proxy_fcgi:trace4] [pid 49]
> util_script.c(523): [client ::1:54638] Content-type: text/html;
> charset=UTF-8
> [Tue May 31 15:08:38.089192 2016] [proxy:debug] [pid 49]
> proxy_util.c(2155): AH00943: FCGI: has released connection for (*)
> [Tue May 31 15:08:38.089241 2016] [http:trace3] [pid 49]
> http_filters.c(1006): [client ::1:54638] Response sent with status 200,
> headers:
> [Tue May 31 15:08:38.089246 2016] [http:trace5] [pid 49]
> http_filters.c(1013): [client ::1:54638] Date: Tue, 31 May 2016 15:08:38
> GMT
> [Tue May 31 15:08:38.089248 2016] [http:trace5] [pid 49]
> http_filters.c(1016): [client ::1:54638] Server: Apache/2.4.12 (Red Hat)
> [Tue May 31 15:08:38.089250 2016] [http:trace4] [pid 49]
> http_filters.c(835): [client ::1:54638] X-Powered-By: PHP/5.6.5
> *[Tue May 31 15:08:38.089252 2016] [http:trace4] [pid 49]
> http_filters.c(835): [client ::1:54638] Last-Modified: Thu, 01 Jan 1970
> 00:00:00 GMT*
> [Tue May 31 15:08:38.089255 2016] [http:trace4] [pid 49]
> http_filters.c(835): [client ::1:54638] Content-Length: 0
> [Tue May 31 15:08:38.089257 2016] [http:trace4] [pid 49]
> http_filters.c(835): [client ::1:54638] Content-Type: text/html;
> charset=UTF-8
> [Tue May 31 15:08:38.089274 2016] [core:trace6] [pid 49]
> core_filters.c(527): [client ::1:54638] core_output_filter: flushing
> because of FLUSH bucket
> [Tue May 31 15:08:38.089463 2016] [core:trace6] [pid 49]
> core_filters.c(527): [client ::1:54638] core_output_filter: flushing
> because of FLUSH bucket
>
>
>
--
Manuel VACELET
Enalean Co-founder & Chief Technical Officer
+33 (0)7 61 10 89 90
Skype: manuel.vacelet.enalean
http://www.enalean.com
Twitter @vaceletm <https://twitter.com/vaceletm>
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-09 16:07 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-08 13:42 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>> [+devs]
>>
>> 2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>>
>>>
>>>
>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>
>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>>>
>>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>>> checked the correspondence. Quoting:
>>>>>>>
>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>> more obvious.
>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>
>>>>>>> So my understanding is that you would like to know why a
>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>
>>>>>>
>>>>>> Yes for sure, this is the primary issue.
>>>>>> However, the (undocumented) difference of behavior from one version
>>>>>> to another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions)
>>>>>> is also in question here.
>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>>> behaviour !
>>>>>>
>>>>>>
>>>>>
>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>
>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>> (headers rewritten to EPOCH)
>>>>> However, if I server the very same php script from mod_php (instead of
>>>>> fcgi) it "works" (the headers are not modified).
>>>>>
>>>>>
>>>> For the record, I also have the same behaviour (headers rewritten when
>>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>> So AFAICT, it doesn't seem distro specific.
>>>>
>>>> On the root of the problem, from my point of view:
>>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>>> (even if not desired and not documented).
>>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>>> inconsistencies (I'll try to build a test case for that).
>>>> - however, even if the headers are wrong, I think apache default (use
>>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>>> will never expire). I would prefer either:
>>>> -- do not touch the header
>>>> -- raise a warning and discard the header
>>>>
>>>> What do you think ?
>>>>
>>>
>>>
>>> From my tests the following snippet of code should be responsible for
>>> the switch from 'foo' to unix epoch:
>>>
>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>
>>> The function that contains the code, ap_scan_script_header_err_core_ex,
>>> is wrapped by a lot of other functions eventually called by modules like
>>> mod-proxy-fcgi. A more verbose description of the function in:
>>>
>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>
>>> Not sure what would be the best thing to do, but probably we could
>>> follow up in a official apache bugzilla task?
>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>
>>> Any thoughts by other readers of the email list?
>>>
>>
>> More specifically, the following patch let the "foo" Last-Modified header
>> to be returned instead of unix epoch:
>>
>> --- server/util_script.c (revision 1747375)
>> +++ server/util_script.c (working copy)
>> @@ -665,8 +665,13 @@
>> * pass it on blindly because of restrictions on future values.
>> */
>> else if (!strcasecmp(w, "Last-Modified")) {
>> - ap_update_mtime(r, apr_date_parse_http(l));
>> - ap_set_last_modified(r);
>> + apr_time_t last_modified_date = apr_date_parse_http(l);
>> + if (last_modified_date) {
>> + ap_update_mtime(r, last_modified_date);
>> + ap_set_last_modified(r);
>> + } else {
>> + apr_table_set(r->headers_out, w, l);
>> + }
>> }
>> else if (!strcasecmp(w, "Set-Cookie")) {
>> apr_table_add(cookie_table, w, l);
>>
>> Omitting the "else" branch will force httpd to drop anything that is not
>> a date in Last-Modified (like 'foo'). Of course this patch is only a proof
>> of concept, it is not meant to be the final solution :)
>>
>> Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
>> sure what would be the best course of action.
>>
>> I added the httpd-dev mailing list to get some opinion. Steps to repro
>> are contained in https://bugs.centos.org/view.php?id=10940
>>
>>
> More specific:
>
> ap_scan_script_header_err_core_ex in server/utils.c (that should be used
> by mod-proxy-fcgi) checks headers returned from fcgi scripts and translates
> non RFC compliant Last-Modified header values to unix epoch. For example,
> Last-Modified: foo is returned to the client as Last-Modified: Thu, 01 Jan
> 1970 00:00:00 GMT.
>
> What would be the correct behavior in this case? Not returning any
> Last-Modified to the client (and maybe logging an error/warning?),
> returning the non compliant value as it is, returning Last-Modified: now(),
> other?
>
> Any help would really be appreciated :)
>
After a chat in #httpd-dev I am proposing this trunk patch:
Index: server/util_script.c
===================================================================
--- server/util_script.c (revision 1747855)
+++ server/util_script.c (working copy)
@@ -662,11 +662,19 @@
}
/*
* If the script gave us a Last-Modified header, we can't just
- * pass it on blindly because of restrictions on future values.
+ * pass it on blindly because of restrictions on future or invalid
values.
*/
else if (!ap_cstr_casecmp(w, "Last-Modified")) {
- ap_update_mtime(r, apr_date_parse_http(l));
- ap_set_last_modified(r);
+ apr_time_t last_modified_date = apr_date_parse_http(l);
+ if (last_modified_date) {
+ ap_update_mtime(r, apr_date_parse_http(l));
+ ap_set_last_modified(r);
+ }
+ else {
+ if (APLOGrtrace1(r))
+ ap_log_rerror(SCRIPT_LOG_MARK, APLOG_TRACE1, 0, r,
+ "Invalid header value: Last-Modified:
'%s'", l);
+ }
}
else if (!ap_cstr_casecmp(w, "Set-Cookie")) {
apr_table_add(cookie_table, w, l);
Tested also on 2.4.x, it correctly drops (and log) headers like
'Last-Modified: foo'. This would be my first commit outside the
documentation realm so any feedback would be really great. In case nobody
is against this patch I'll submit a trunk commit during the next days.
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-09 16:07 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-08 13:42 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>> [+devs]
>>
>> 2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>>
>>>
>>>
>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>
>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>>>
>>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>>> checked the correspondence. Quoting:
>>>>>>>
>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>> more obvious.
>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>
>>>>>>> So my understanding is that you would like to know why a
>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>
>>>>>>
>>>>>> Yes for sure, this is the primary issue.
>>>>>> However, the (undocumented) difference of behavior from one version
>>>>>> to another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions)
>>>>>> is also in question here.
>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>>> behaviour !
>>>>>>
>>>>>>
>>>>>
>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>
>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>> (headers rewritten to EPOCH)
>>>>> However, if I server the very same php script from mod_php (instead of
>>>>> fcgi) it "works" (the headers are not modified).
>>>>>
>>>>>
>>>> For the record, I also have the same behaviour (headers rewritten when
>>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>> So AFAICT, it doesn't seem distro specific.
>>>>
>>>> On the root of the problem, from my point of view:
>>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>>> (even if not desired and not documented).
>>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>>> inconsistencies (I'll try to build a test case for that).
>>>> - however, even if the headers are wrong, I think apache default (use
>>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>>> will never expire). I would prefer either:
>>>> -- do not touch the header
>>>> -- raise a warning and discard the header
>>>>
>>>> What do you think ?
>>>>
>>>
>>>
>>> From my tests the following snippet of code should be responsible for
>>> the switch from 'foo' to unix epoch:
>>>
>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>
>>> The function that contains the code, ap_scan_script_header_err_core_ex,
>>> is wrapped by a lot of other functions eventually called by modules like
>>> mod-proxy-fcgi. A more verbose description of the function in:
>>>
>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>
>>> Not sure what would be the best thing to do, but probably we could
>>> follow up in a official apache bugzilla task?
>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>
>>> Any thoughts by other readers of the email list?
>>>
>>
>> More specifically, the following patch let the "foo" Last-Modified header
>> to be returned instead of unix epoch:
>>
>> --- server/util_script.c (revision 1747375)
>> +++ server/util_script.c (working copy)
>> @@ -665,8 +665,13 @@
>> * pass it on blindly because of restrictions on future values.
>> */
>> else if (!strcasecmp(w, "Last-Modified")) {
>> - ap_update_mtime(r, apr_date_parse_http(l));
>> - ap_set_last_modified(r);
>> + apr_time_t last_modified_date = apr_date_parse_http(l);
>> + if (last_modified_date) {
>> + ap_update_mtime(r, last_modified_date);
>> + ap_set_last_modified(r);
>> + } else {
>> + apr_table_set(r->headers_out, w, l);
>> + }
>> }
>> else if (!strcasecmp(w, "Set-Cookie")) {
>> apr_table_add(cookie_table, w, l);
>>
>> Omitting the "else" branch will force httpd to drop anything that is not
>> a date in Last-Modified (like 'foo'). Of course this patch is only a proof
>> of concept, it is not meant to be the final solution :)
>>
>> Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
>> sure what would be the best course of action.
>>
>> I added the httpd-dev mailing list to get some opinion. Steps to repro
>> are contained in https://bugs.centos.org/view.php?id=10940
>>
>>
> More specific:
>
> ap_scan_script_header_err_core_ex in server/utils.c (that should be used
> by mod-proxy-fcgi) checks headers returned from fcgi scripts and translates
> non RFC compliant Last-Modified header values to unix epoch. For example,
> Last-Modified: foo is returned to the client as Last-Modified: Thu, 01 Jan
> 1970 00:00:00 GMT.
>
> What would be the correct behavior in this case? Not returning any
> Last-Modified to the client (and maybe logging an error/warning?),
> returning the non compliant value as it is, returning Last-Modified: now(),
> other?
>
> Any help would really be appreciated :)
>
After a chat in #httpd-dev I am proposing this trunk patch:
Index: server/util_script.c
===================================================================
--- server/util_script.c (revision 1747855)
+++ server/util_script.c (working copy)
@@ -662,11 +662,19 @@
}
/*
* If the script gave us a Last-Modified header, we can't just
- * pass it on blindly because of restrictions on future values.
+ * pass it on blindly because of restrictions on future or invalid
values.
*/
else if (!ap_cstr_casecmp(w, "Last-Modified")) {
- ap_update_mtime(r, apr_date_parse_http(l));
- ap_set_last_modified(r);
+ apr_time_t last_modified_date = apr_date_parse_http(l);
+ if (last_modified_date) {
+ ap_update_mtime(r, apr_date_parse_http(l));
+ ap_set_last_modified(r);
+ }
+ else {
+ if (APLOGrtrace1(r))
+ ap_log_rerror(SCRIPT_LOG_MARK, APLOG_TRACE1, 0, r,
+ "Invalid header value: Last-Modified:
'%s'", l);
+ }
}
else if (!ap_cstr_casecmp(w, "Set-Cookie")) {
apr_table_add(cookie_table, w, l);
Tested also on 2.4.x, it correctly drops (and log) headers like
'Last-Modified: foo'. This would be my first commit outside the
documentation realm so any feedback would be really great. In case nobody
is against this patch I'll submit a trunk commit during the next days.
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-08 13:42 GMT+02:00 Luca Toscano <to...@gmail.com>:
> [+devs]
>
> 2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>>
>>
>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>> checked the correspondence. Quoting:
>>>>>>
>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>> more obvious.
>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>
>>>>>> So my understanding is that you would like to know why a
>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>
>>>>>
>>>>> Yes for sure, this is the primary issue.
>>>>> However, the (undocumented) difference of behavior from one version to
>>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>>> also in question here.
>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>> behaviour !
>>>>>
>>>>>
>>>>
>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>
>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>>> rewritten to EPOCH)
>>>> However, if I server the very same php script from mod_php (instead of
>>>> fcgi) it "works" (the headers are not modified).
>>>>
>>>>
>>> For the record, I also have the same behaviour (headers rewritten when
>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>> So AFAICT, it doesn't seem distro specific.
>>>
>>> On the root of the problem, from my point of view:
>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>> (even if not desired and not documented).
>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>> inconsistencies (I'll try to build a test case for that).
>>> - however, even if the headers are wrong, I think apache default (use
>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>> will never expire). I would prefer either:
>>> -- do not touch the header
>>> -- raise a warning and discard the header
>>>
>>> What do you think ?
>>>
>>
>>
>> From my tests the following snippet of code should be responsible for the
>> switch from 'foo' to unix epoch:
>>
>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>
>> The function that contains the code, ap_scan_script_header_err_core_ex,
>> is wrapped by a lot of other functions eventually called by modules like
>> mod-proxy-fcgi. A more verbose description of the function in:
>>
>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>
>> Not sure what would be the best thing to do, but probably we could follow
>> up in a official apache bugzilla task?
>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>
>> Any thoughts by other readers of the email list?
>>
>
> More specifically, the following patch let the "foo" Last-Modified header
> to be returned instead of unix epoch:
>
> --- server/util_script.c (revision 1747375)
> +++ server/util_script.c (working copy)
> @@ -665,8 +665,13 @@
> * pass it on blindly because of restrictions on future values.
> */
> else if (!strcasecmp(w, "Last-Modified")) {
> - ap_update_mtime(r, apr_date_parse_http(l));
> - ap_set_last_modified(r);
> + apr_time_t last_modified_date = apr_date_parse_http(l);
> + if (last_modified_date) {
> + ap_update_mtime(r, last_modified_date);
> + ap_set_last_modified(r);
> + } else {
> + apr_table_set(r->headers_out, w, l);
> + }
> }
> else if (!strcasecmp(w, "Set-Cookie")) {
> apr_table_add(cookie_table, w, l);
>
> Omitting the "else" branch will force httpd to drop anything that is not a
> date in Last-Modified (like 'foo'). Of course this patch is only a proof of
> concept, it is not meant to be the final solution :)
>
> Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
> sure what would be the best course of action.
>
> I added the httpd-dev mailing list to get some opinion. Steps to repro are
> contained in https://bugs.centos.org/view.php?id=10940
>
>
More specific:
ap_scan_script_header_err_core_ex in server/utils.c (that should be used by
mod-proxy-fcgi) checks headers returned from fcgi scripts and translates
non RFC compliant Last-Modified header values to unix epoch. For example,
Last-Modified: foo is returned to the client as Last-Modified: Thu, 01 Jan
1970 00:00:00 GMT.
What would be the correct behavior in this case? Not returning any
Last-Modified to the client (and maybe logging an error/warning?),
returning the non compliant value as it is, returning Last-Modified: now(),
other?
Any help would really be appreciated :)
Thanks!
Regards,
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-08 13:42 GMT+02:00 Luca Toscano <to...@gmail.com>:
> [+devs]
>
> 2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>>
>>
>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>> checked the correspondence. Quoting:
>>>>>>
>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>> more obvious.
>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>
>>>>>> So my understanding is that you would like to know why a
>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>
>>>>>
>>>>> Yes for sure, this is the primary issue.
>>>>> However, the (undocumented) difference of behavior from one version to
>>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>>> also in question here.
>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>> behaviour !
>>>>>
>>>>>
>>>>
>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>
>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>>> rewritten to EPOCH)
>>>> However, if I server the very same php script from mod_php (instead of
>>>> fcgi) it "works" (the headers are not modified).
>>>>
>>>>
>>> For the record, I also have the same behaviour (headers rewritten when
>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>> So AFAICT, it doesn't seem distro specific.
>>>
>>> On the root of the problem, from my point of view:
>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>> (even if not desired and not documented).
>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>> inconsistencies (I'll try to build a test case for that).
>>> - however, even if the headers are wrong, I think apache default (use
>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>> will never expire). I would prefer either:
>>> -- do not touch the header
>>> -- raise a warning and discard the header
>>>
>>> What do you think ?
>>>
>>
>>
>> From my tests the following snippet of code should be responsible for the
>> switch from 'foo' to unix epoch:
>>
>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>
>> The function that contains the code, ap_scan_script_header_err_core_ex,
>> is wrapped by a lot of other functions eventually called by modules like
>> mod-proxy-fcgi. A more verbose description of the function in:
>>
>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>
>> Not sure what would be the best thing to do, but probably we could follow
>> up in a official apache bugzilla task?
>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>
>> Any thoughts by other readers of the email list?
>>
>
> More specifically, the following patch let the "foo" Last-Modified header
> to be returned instead of unix epoch:
>
> --- server/util_script.c (revision 1747375)
> +++ server/util_script.c (working copy)
> @@ -665,8 +665,13 @@
> * pass it on blindly because of restrictions on future values.
> */
> else if (!strcasecmp(w, "Last-Modified")) {
> - ap_update_mtime(r, apr_date_parse_http(l));
> - ap_set_last_modified(r);
> + apr_time_t last_modified_date = apr_date_parse_http(l);
> + if (last_modified_date) {
> + ap_update_mtime(r, last_modified_date);
> + ap_set_last_modified(r);
> + } else {
> + apr_table_set(r->headers_out, w, l);
> + }
> }
> else if (!strcasecmp(w, "Set-Cookie")) {
> apr_table_add(cookie_table, w, l);
>
> Omitting the "else" branch will force httpd to drop anything that is not a
> date in Last-Modified (like 'foo'). Of course this patch is only a proof of
> concept, it is not meant to be the final solution :)
>
> Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
> sure what would be the best course of action.
>
> I added the httpd-dev mailing list to get some opinion. Steps to repro are
> contained in https://bugs.centos.org/view.php?id=10940
>
>
More specific:
ap_scan_script_header_err_core_ex in server/utils.c (that should be used by
mod-proxy-fcgi) checks headers returned from fcgi scripts and translates
non RFC compliant Last-Modified header values to unix epoch. For example,
Last-Modified: foo is returned to the client as Last-Modified: Thu, 01 Jan
1970 00:00:00 GMT.
What would be the correct behavior in this case? Not returning any
Last-Modified to the client (and maybe logging an error/warning?),
returning the non compliant value as it is, returning Last-Modified: now(),
other?
Any help would really be appreciated :)
Thanks!
Regards,
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
[+devs]
2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>> manuel.vacelet@enalean.com> wrote:
>>
>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>> checked the correspondence. Quoting:
>>>>>
>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>> more obvious.
>>>>> During my tests (this is extracted from an automated test suite), even
>>>>> after having converted dates to rfc1123, I continued to get some sparse
>>>>> errors. What I got is that the value I sent was sometimes slightly modified
>>>>> (a second or 2) depending on the machine load."
>>>>>
>>>>> So my understanding is that you would like to know why a Last-Modified
>>>>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>>>>> couple of seconds from httpd, right?
>>>>>
>>>>
>>>> Yes for sure, this is the primary issue.
>>>> However, the (undocumented) difference of behavior from one version to
>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>> also in question here.
>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>> behaviour !
>>>>
>>>>
>>>
>>> I made another series of test and it seems to be linked to fastcgi.
>>>
>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>> rewritten to EPOCH)
>>> However, if I server the very same php script from mod_php (instead of
>>> fcgi) it "works" (the headers are not modified).
>>>
>>>
>> For the record, I also have the same behaviour (headers rewritten when
>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>> So AFAICT, it doesn't seem distro specific.
>>
>> On the root of the problem, from my point of view:
>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>> (even if not desired and not documented).
>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>> inconsistencies (I'll try to build a test case for that).
>> - however, even if the headers are wrong, I think apache default (use
>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>> will never expire). I would prefer either:
>> -- do not touch the header
>> -- raise a warning and discard the header
>>
>> What do you think ?
>>
>
>
> From my tests the following snippet of code should be responsible for the
> switch from 'foo' to unix epoch:
>
> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>
> The function that contains the code, ap_scan_script_header_err_core_ex, is
> wrapped by a lot of other functions eventually called by modules like
> mod-proxy-fcgi. A more verbose description of the function in:
>
> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>
> Not sure what would be the best thing to do, but probably we could follow
> up in a official apache bugzilla task?
> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>
> Any thoughts by other readers of the email list?
>
More specifically, the following patch let the "foo" Last-Modified header
to be returned instead of unix epoch:
--- server/util_script.c (revision 1747375)
+++ server/util_script.c (working copy)
@@ -665,8 +665,13 @@
* pass it on blindly because of restrictions on future values.
*/
else if (!strcasecmp(w, "Last-Modified")) {
- ap_update_mtime(r, apr_date_parse_http(l));
- ap_set_last_modified(r);
+ apr_time_t last_modified_date = apr_date_parse_http(l);
+ if (last_modified_date) {
+ ap_update_mtime(r, last_modified_date);
+ ap_set_last_modified(r);
+ } else {
+ apr_table_set(r->headers_out, w, l);
+ }
}
else if (!strcasecmp(w, "Set-Cookie")) {
apr_table_add(cookie_table, w, l);
Omitting the "else" branch will force httpd to drop anything that is not a
date in Last-Modified (like 'foo'). Of course this patch is only a proof of
concept, it is not meant to be the final solution :)
Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
sure what would be the best course of action.
I added the httpd-dev mailing list to get some opinion. Steps to repro are
contained in https://bugs.centos.org/view.php?id=10940
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-07-01 16:53 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>
> On Fri, Jul 1, 2016 at 4:14 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>>
>> 2016-06-29 9:38 GMT+02:00 Luca Toscano <to...@gmail.com>:
>>
>>>
>>>
>>> 2016-06-28 18:32 GMT+02:00 Luca Toscano <to...@gmail.com>:
>>>
>>>>
>>>>
>>>> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>
>>>> :
>>>>
>>>>>
>>>>>
>>>>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com>:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <
>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <
>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <
>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>>
>>>>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour
>>>>>>>>>>>>>>>> (the original code sent the date in iso8601 instead of rfc1123) because it
>>>>>>>>>>>>>>>> was more obvious.
>>>>>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't
>>>>>>>>>>>>>>> highlight the behaviour !
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>>>>>> fastcgi.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) &
>>>>>>>>>>>>>> php-fpm (5.4.16 + tons of patches) from RHEL7 and I get the exact same
>>>>>>>>>>>>>> behaviour (headers rewritten to EPOCH)
>>>>>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>> For the record, I also have the same behaviour (headers
>>>>>>>>>>>>> rewritten when using php-fpm + fastcgi) on alpine linux 3.4 that
>>>>>>>>>>>>> ships apache2-2.4.20.
>>>>>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>>>>>
>>>>>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to
>>>>>>>>>>>>> lead to inconsistencies (I'll try to build a test case for that).
>>>>>>>>>>>>> - however, even if the headers are wrong, I think apache
>>>>>>>>>>>>> default (use EPOCH) is wrong as it leads to very inconsistent behaviour
>>>>>>>>>>>>> (the resource will never expire). I would prefer either:
>>>>>>>>>>>>> -- do not touch the header
>>>>>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>>>>>
>>>>>>>>>>>>> What do you think ?
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> From my tests the following snippet of code should be
>>>>>>>>>>>> responsible for the switch from 'foo' to unix epoch:
>>>>>>>>>>>>
>>>>>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>>>>>
>>>>>>>>>>>> The function that contains the code,
>>>>>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>>>>>> description of the function in:
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>>>>>
>>>>>>>>>>>> Not sure what would be the best thing to do, but probably we
>>>>>>>>>>>> could follow up in a official apache bugzilla task?
>>>>>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>> Wow, thanks for the investigation !
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Sorry for the delay! I submitted a patch for trunk with a
>>>>>>>>>> possible fix, namely dropping (and logging at trace1 level) any non
>>>>>>>>>> compliant date/time set in a Last-Modified header returned by a FCGI/CGI
>>>>>>>>>> script: http://svn.apache.org/r1748379
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> Cool :)
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>>>>>> branch, we'll see what other people think about this solution.
>>>>>>>>>>
>>>>>>>>>> We should also do a follow up for the other main issue, namely
>>>>>>>>>> the fact that you see a different/delayed Last-Modified header sometimes
>>>>>>>>>> among your FCGI/httpd responses. Can you give me an example of
>>>>>>>>>> Last-Modified header value before/after the "delay" and a way to repro it?
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> I wrote a test case in the "time" branch:
>>>>>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>>>>>
>>>>>>>>> In my own tests, I get:
>>>>>>>>> --------------------->8---------------------
>>>>>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>>>>>> < X-Powered-By: PHP/5.6.5
>>>>>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>>>>>> < Transfer-Encoding: chunked
>>>>>>>>> < Content-Type: text/html; charset=UTF-8
>>>>>>>>> <
>>>>>>>>> { [data not shown]
>>>>>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>>>>>
>>>>>>>>> * Closing connection #0
>>>>>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>>>>>> --------------------->8---------------------
>>>>>>>>>
>>>>>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as
>>>>>>>>> time zone) but the result is weird as you can see:
>>>>>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>>>>>
>>>>>>>>> Notice the 2 seconds ?
>>>>>>>>> I put a "sleep(2)" in my php script...
>>>>>>>>>
>>>>>>>>> I don't know if your fix also take this into account
>>>>>>>>>
>>>>>>>>
>>>>>>>> Thanks a lot for the precise test! The same code snippet that I
>>>>>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>>>>>> the Last-Modified header with the request's modification time if the value
>>>>>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>>>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>>>>>> than the server's time of message origination (Date).").
>>>>>>>>
>>>>>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying
>>>>>>>> to compare a GMT date vs a "Europe/Paris" one, already formatted for
>>>>>>>> RFC1123, and PHP seems to agree with httpd in recognizing the
>>>>>>>> "Europe/Paris" date as more recent. Moreover, if you generate a GMT date
>>>>>>>> and format it for RFC1123 the header is not modified with the extra two
>>>>>>>> seconds.
>>>>>>>>
>>>>>>>> So from what I can see httpd does the correct thing, I don't see a
>>>>>>>> bug like in the previous case. What do you think? I am far from a PHP
>>>>>>>> expert so I might have missed something important :)
>>>>>>>>
>>>>>>>>
>>>>>>> Mmm I don't think it' the right way to compare the dates here as you
>>>>>>> are really comparing the format strings here.
>>>>>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>>>>>
>>>>>>
>>>>>>> Clearly, just changing the timezone doesn't impact the time
>>>>>>> comparison (and it's the expected behaviour).
>>>>>>>
>>>>>>
>>>>>> Correct, in general the best way should be the one that you proposed,
>>>>>> but in this case we are talking about RFC1123 specific date/times, so the
>>>>>> format string comparison should be relevant imho. A efficient RFC 822/1123
>>>>>> parser would probably assume the GMT timezone and care only about what
>>>>>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>>>>>> super strict and correct parse would also check the GMT bit and return
>>>>>> error if missing, but it may be a bit overkill.
>>>>>>
>>>>>>
>>>>>>> To me there is a wrong attempt to comply with RFC in apache here.
>>>>>>> Either the parser is able to:
>>>>>>> 1. correctly read the header input
>>>>>>> 2. normalize to GMT
>>>>>>> 3. ensure the resulting date is not > to server time (+ probably log
>>>>>>> somthing to help developers to understand things)
>>>>>>> or there should be a warning and the header is dropped (like if it's
>>>>>>> not a date).
>>>>>>>
>>>>>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>>>>>
>>>>>>>
>>>>>> I am seeing things in a different way, namely only point 3
>>>>>> should/could be implemented. AFAIU RFC1123 (and related) assume a GMT
>>>>>> date/time and since the HTTP RFC requires this format for the Last-Modified
>>>>>> header, I don't believe that httpd should be required to be able to convert
>>>>>> multiple formats/timezones to RFC1123. This seems to be backed up by the
>>>>>> comments of the function used by httpd to convert the Last-Modified header
>>>>>> value:
>>>>>>
>>>>>
>>>>> Ok but current behaviour is not correct either.
>>>>>
>>>>
>>>> From https://tools.ietf.org/html/rfc2616#section-14.29
>>>>
>>>> An origin server MUST NOT send a Last-Modified date which is later
>>>> than the server's time of message origination. In such cases, where
>>>> the resource's last modification would indicate some time in the
>>>> future, the server MUST replace that date with the message
>>>> origination date.
>>>>
>>>> It also states that Last-Modified needs to be compliant with RFC
>>>> 882/1123.
>>>>
>>>>
>>>>> If I understood well assume that apache receives a RFC1123 value so it
>>>>> compares with current server time (and eventually sends the later).
>>>>>
>>>>> In my example, the date is not a valid RFC1123 value (because it sends
>>>>> +0200 or Europe/Paris). Here, the most sensible default would be to trash
>>>>> with value.
>>>>> It's as invalid as "foo" in my initial example so from my point of
>>>>> view the behaviour of apache should be the same: discard the header (thanks
>>>>> to your patch) and raise a warning.
>>>>>
>>>>
>>>> We could patch httpd/apr to be super strict but I am not sure if it is
>>>> worth it. In the meantime, I tried to improve logging, would you mind to
>>>> tell me what you think about http://apaste.info/JlZ ?
>>>>
>>>
>>> This one should be clearer: http://apaste.info/8pa
>>>
>>> I will also follow up with the dev@ mailing list to get other opinions
>>> about this bug report.
>>>
>>>
>>>
>> Committed logging in trunk and updated 2.4.x backport proposal:
>> http://svn.apache.org/r1750883
>>
>> The logging message should look like:
>>
>> [Fri Jul 01 06:12:35.639343 2016] [proxy_fcgi:trace1] [pid 3542:tid
>> 140561097561856] util_script.c(688): [client ::1:52261] The Last-Modified
>> header value 'Fri, 01 Jul 2016 08:12:33 GMT' (parsed as RFC882/RFC1123
>> datetime, that assumes the GMT timezone) has been replaced with: 'Fri, 01
>> Jul 2016 06:12:35 GMT'. An origin server with a clock must not send a
>> Last-Modified date that is later than the server's time of message
>> origination.
>>
>> Thanks a lot for the bug report!
>>
>>
> Thanks for fixing it !
>
> However it's RFC822 and not 882 (882 is for domain names:
> https://tools.ietf.org/html/rfc882)
>
>
Fixed with http://svn.apache.org/r1750953, thanks a lot!
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Fri, Jul 1, 2016 at 4:14 PM, Luca Toscano <to...@gmail.com> wrote:
>
>
> 2016-06-29 9:38 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>>
>>
>> 2016-06-28 18:32 GMT+02:00 Luca Toscano <to...@gmail.com>:
>>
>>>
>>>
>>> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>>
>>>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <manuel.vacelet@enalean.com
>>>>> >:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <
>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <
>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>
>>>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour
>>>>>>>>>>>>>>> (the original code sent the date in iso8601 instead of rfc1123) because it
>>>>>>>>>>>>>>> was more obvious.
>>>>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't
>>>>>>>>>>>>>> highlight the behaviour !
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>>>>> fastcgi.
>>>>>>>>>>>>>
>>>>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) &
>>>>>>>>>>>>> php-fpm (5.4.16 + tons of patches) from RHEL7 and I get the exact same
>>>>>>>>>>>>> behaviour (headers rewritten to EPOCH)
>>>>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>> For the record, I also have the same behaviour (headers
>>>>>>>>>>>> rewritten when using php-fpm + fastcgi) on alpine linux 3.4 that
>>>>>>>>>>>> ships apache2-2.4.20.
>>>>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>>>>
>>>>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to
>>>>>>>>>>>> lead to inconsistencies (I'll try to build a test case for that).
>>>>>>>>>>>> - however, even if the headers are wrong, I think apache
>>>>>>>>>>>> default (use EPOCH) is wrong as it leads to very inconsistent behaviour
>>>>>>>>>>>> (the resource will never expire). I would prefer either:
>>>>>>>>>>>> -- do not touch the header
>>>>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>>>>
>>>>>>>>>>>> What do you think ?
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> From my tests the following snippet of code should be
>>>>>>>>>>> responsible for the switch from 'foo' to unix epoch:
>>>>>>>>>>>
>>>>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>>>>
>>>>>>>>>>> The function that contains the code,
>>>>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>>>>> description of the function in:
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>>>>
>>>>>>>>>>> Not sure what would be the best thing to do, but probably we
>>>>>>>>>>> could follow up in a official apache bugzilla task?
>>>>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>> Wow, thanks for the investigation !
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>>>>>> http://svn.apache.org/r1748379
>>>>>>>>>
>>>>>>>>>
>>>>>>>> Cool :)
>>>>>>>>
>>>>>>>>
>>>>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>>>>> branch, we'll see what other people think about this solution.
>>>>>>>>>
>>>>>>>>> We should also do a follow up for the other main issue, namely the
>>>>>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>>>>>> header value before/after the "delay" and a way to repro it?
>>>>>>>>>
>>>>>>>>
>>>>>>>> I wrote a test case in the "time" branch:
>>>>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>>>>
>>>>>>>> In my own tests, I get:
>>>>>>>> --------------------->8---------------------
>>>>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>>>>> < X-Powered-By: PHP/5.6.5
>>>>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>>>>> < Transfer-Encoding: chunked
>>>>>>>> < Content-Type: text/html; charset=UTF-8
>>>>>>>> <
>>>>>>>> { [data not shown]
>>>>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>>>>
>>>>>>>> * Closing connection #0
>>>>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>>>>> --------------------->8---------------------
>>>>>>>>
>>>>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as
>>>>>>>> time zone) but the result is weird as you can see:
>>>>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>>>>
>>>>>>>> Notice the 2 seconds ?
>>>>>>>> I put a "sleep(2)" in my php script...
>>>>>>>>
>>>>>>>> I don't know if your fix also take this into account
>>>>>>>>
>>>>>>>
>>>>>>> Thanks a lot for the precise test! The same code snippet that I
>>>>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>>>>> the Last-Modified header with the request's modification time if the value
>>>>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>>>>> than the server's time of message origination (Date).").
>>>>>>>
>>>>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>>>>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>>>>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>>>>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>>>>>> the header is not modified with the extra two seconds.
>>>>>>>
>>>>>>> So from what I can see httpd does the correct thing, I don't see a
>>>>>>> bug like in the previous case. What do you think? I am far from a PHP
>>>>>>> expert so I might have missed something important :)
>>>>>>>
>>>>>>>
>>>>>> Mmm I don't think it' the right way to compare the dates here as you
>>>>>> are really comparing the format strings here.
>>>>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>>>>
>>>>>
>>>>>> Clearly, just changing the timezone doesn't impact the time
>>>>>> comparison (and it's the expected behaviour).
>>>>>>
>>>>>
>>>>> Correct, in general the best way should be the one that you proposed,
>>>>> but in this case we are talking about RFC1123 specific date/times, so the
>>>>> format string comparison should be relevant imho. A efficient RFC 822/1123
>>>>> parser would probably assume the GMT timezone and care only about what
>>>>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>>>>> super strict and correct parse would also check the GMT bit and return
>>>>> error if missing, but it may be a bit overkill.
>>>>>
>>>>>
>>>>>> To me there is a wrong attempt to comply with RFC in apache here.
>>>>>> Either the parser is able to:
>>>>>> 1. correctly read the header input
>>>>>> 2. normalize to GMT
>>>>>> 3. ensure the resulting date is not > to server time (+ probably log
>>>>>> somthing to help developers to understand things)
>>>>>> or there should be a warning and the header is dropped (like if it's
>>>>>> not a date).
>>>>>>
>>>>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>>>>
>>>>>>
>>>>> I am seeing things in a different way, namely only point 3
>>>>> should/could be implemented. AFAIU RFC1123 (and related) assume a GMT
>>>>> date/time and since the HTTP RFC requires this format for the Last-Modified
>>>>> header, I don't believe that httpd should be required to be able to convert
>>>>> multiple formats/timezones to RFC1123. This seems to be backed up by the
>>>>> comments of the function used by httpd to convert the Last-Modified header
>>>>> value:
>>>>>
>>>>
>>>> Ok but current behaviour is not correct either.
>>>>
>>>
>>> From https://tools.ietf.org/html/rfc2616#section-14.29
>>>
>>> An origin server MUST NOT send a Last-Modified date which is later
>>> than the server's time of message origination. In such cases, where
>>> the resource's last modification would indicate some time in the
>>> future, the server MUST replace that date with the message
>>> origination date.
>>>
>>> It also states that Last-Modified needs to be compliant with RFC
>>> 882/1123.
>>>
>>>
>>>> If I understood well assume that apache receives a RFC1123 value so it
>>>> compares with current server time (and eventually sends the later).
>>>>
>>>> In my example, the date is not a valid RFC1123 value (because it sends
>>>> +0200 or Europe/Paris). Here, the most sensible default would be to trash
>>>> with value.
>>>> It's as invalid as "foo" in my initial example so from my point of view
>>>> the behaviour of apache should be the same: discard the header (thanks to
>>>> your patch) and raise a warning.
>>>>
>>>
>>> We could patch httpd/apr to be super strict but I am not sure if it is
>>> worth it. In the meantime, I tried to improve logging, would you mind to
>>> tell me what you think about http://apaste.info/JlZ ?
>>>
>>
>> This one should be clearer: http://apaste.info/8pa
>>
>> I will also follow up with the dev@ mailing list to get other opinions
>> about this bug report.
>>
>>
>>
> Committed logging in trunk and updated 2.4.x backport proposal:
> http://svn.apache.org/r1750883
>
> The logging message should look like:
>
> [Fri Jul 01 06:12:35.639343 2016] [proxy_fcgi:trace1] [pid 3542:tid
> 140561097561856] util_script.c(688): [client ::1:52261] The Last-Modified
> header value 'Fri, 01 Jul 2016 08:12:33 GMT' (parsed as RFC882/RFC1123
> datetime, that assumes the GMT timezone) has been replaced with: 'Fri, 01
> Jul 2016 06:12:35 GMT'. An origin server with a clock must not send a
> Last-Modified date that is later than the server's time of message
> origination.
>
> Thanks a lot for the bug report!
>
>
Thanks for fixing it !
However it's RFC822 and not 882 (882 is for domain names:
https://tools.ietf.org/html/rfc882)
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-29 9:38 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-28 18:32 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>>
>>
>> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
>>> wrote:
>>>
>>>>
>>>>
>>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>
>>>> :
>>>>
>>>>>
>>>>>
>>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <toscano.luca@gmail.com
>>>>> > wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com>:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <
>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>
>>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour
>>>>>>>>>>>>>> (the original code sent the date in iso8601 instead of rfc1123) because it
>>>>>>>>>>>>>> was more obvious.
>>>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't
>>>>>>>>>>>>> highlight the behaviour !
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>>>> fastcgi.
>>>>>>>>>>>>
>>>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>> For the record, I also have the same behaviour (headers
>>>>>>>>>>> rewritten when using php-fpm + fastcgi) on alpine linux 3.4 that
>>>>>>>>>>> ships apache2-2.4.20.
>>>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>>>
>>>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to
>>>>>>>>>>> lead to inconsistencies (I'll try to build a test case for that).
>>>>>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>>>>>> resource will never expire). I would prefer either:
>>>>>>>>>>> -- do not touch the header
>>>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>>>
>>>>>>>>>>> What do you think ?
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> From my tests the following snippet of code should be responsible
>>>>>>>>>> for the switch from 'foo' to unix epoch:
>>>>>>>>>>
>>>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>>>
>>>>>>>>>> The function that contains the code,
>>>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>>>> description of the function in:
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>>>
>>>>>>>>>> Not sure what would be the best thing to do, but probably we
>>>>>>>>>> could follow up in a official apache bugzilla task?
>>>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> Wow, thanks for the investigation !
>>>>>>>>>
>>>>>>>>
>>>>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>>>>> http://svn.apache.org/r1748379
>>>>>>>>
>>>>>>>>
>>>>>>> Cool :)
>>>>>>>
>>>>>>>
>>>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>>>> branch, we'll see what other people think about this solution.
>>>>>>>>
>>>>>>>> We should also do a follow up for the other main issue, namely the
>>>>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>>>>> header value before/after the "delay" and a way to repro it?
>>>>>>>>
>>>>>>>
>>>>>>> I wrote a test case in the "time" branch:
>>>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>>>
>>>>>>> In my own tests, I get:
>>>>>>> --------------------->8---------------------
>>>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>>>> < X-Powered-By: PHP/5.6.5
>>>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>>>> < Transfer-Encoding: chunked
>>>>>>> < Content-Type: text/html; charset=UTF-8
>>>>>>> <
>>>>>>> { [data not shown]
>>>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>>>
>>>>>>> * Closing connection #0
>>>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>>>> --------------------->8---------------------
>>>>>>>
>>>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>>>>>> zone) but the result is weird as you can see:
>>>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>>>
>>>>>>> Notice the 2 seconds ?
>>>>>>> I put a "sleep(2)" in my php script...
>>>>>>>
>>>>>>> I don't know if your fix also take this into account
>>>>>>>
>>>>>>
>>>>>> Thanks a lot for the precise test! The same code snippet that I
>>>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>>>> the Last-Modified header with the request's modification time if the value
>>>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>>>> than the server's time of message origination (Date).").
>>>>>>
>>>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>>>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>>>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>>>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>>>>> the header is not modified with the extra two seconds.
>>>>>>
>>>>>> So from what I can see httpd does the correct thing, I don't see a
>>>>>> bug like in the previous case. What do you think? I am far from a PHP
>>>>>> expert so I might have missed something important :)
>>>>>>
>>>>>>
>>>>> Mmm I don't think it' the right way to compare the dates here as you
>>>>> are really comparing the format strings here.
>>>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>>>
>>>>
>>>>> Clearly, just changing the timezone doesn't impact the time comparison
>>>>> (and it's the expected behaviour).
>>>>>
>>>>
>>>> Correct, in general the best way should be the one that you proposed,
>>>> but in this case we are talking about RFC1123 specific date/times, so the
>>>> format string comparison should be relevant imho. A efficient RFC 822/1123
>>>> parser would probably assume the GMT timezone and care only about what
>>>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>>>> super strict and correct parse would also check the GMT bit and return
>>>> error if missing, but it may be a bit overkill.
>>>>
>>>>
>>>>> To me there is a wrong attempt to comply with RFC in apache here.
>>>>> Either the parser is able to:
>>>>> 1. correctly read the header input
>>>>> 2. normalize to GMT
>>>>> 3. ensure the resulting date is not > to server time (+ probably log
>>>>> somthing to help developers to understand things)
>>>>> or there should be a warning and the header is dropped (like if it's
>>>>> not a date).
>>>>>
>>>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>>>
>>>>>
>>>> I am seeing things in a different way, namely only point 3 should/could
>>>> be implemented. AFAIU RFC1123 (and related) assume a GMT date/time and
>>>> since the HTTP RFC requires this format for the Last-Modified header, I
>>>> don't believe that httpd should be required to be able to convert multiple
>>>> formats/timezones to RFC1123. This seems to be backed up by the comments of
>>>> the function used by httpd to convert the Last-Modified header value:
>>>>
>>>
>>> Ok but current behaviour is not correct either.
>>>
>>
>> From https://tools.ietf.org/html/rfc2616#section-14.29
>>
>> An origin server MUST NOT send a Last-Modified date which is later
>> than the server's time of message origination. In such cases, where
>> the resource's last modification would indicate some time in the
>> future, the server MUST replace that date with the message
>> origination date.
>>
>> It also states that Last-Modified needs to be compliant with RFC 882/1123.
>>
>>
>>> If I understood well assume that apache receives a RFC1123 value so it
>>> compares with current server time (and eventually sends the later).
>>>
>>> In my example, the date is not a valid RFC1123 value (because it sends
>>> +0200 or Europe/Paris). Here, the most sensible default would be to trash
>>> with value.
>>> It's as invalid as "foo" in my initial example so from my point of view
>>> the behaviour of apache should be the same: discard the header (thanks to
>>> your patch) and raise a warning.
>>>
>>
>> We could patch httpd/apr to be super strict but I am not sure if it is
>> worth it. In the meantime, I tried to improve logging, would you mind to
>> tell me what you think about http://apaste.info/JlZ ?
>>
>
> This one should be clearer: http://apaste.info/8pa
>
> I will also follow up with the dev@ mailing list to get other opinions
> about this bug report.
>
>
>
Committed logging in trunk and updated 2.4.x backport proposal:
http://svn.apache.org/r1750883
The logging message should look like:
[Fri Jul 01 06:12:35.639343 2016] [proxy_fcgi:trace1] [pid 3542:tid
140561097561856] util_script.c(688): [client ::1:52261] The Last-Modified
header value 'Fri, 01 Jul 2016 08:12:33 GMT' (parsed as RFC882/RFC1123
datetime, that assumes the GMT timezone) has been replaced with: 'Fri, 01
Jul 2016 06:12:35 GMT'. An origin server with a clock must not send a
Last-Modified date that is later than the server's time of message
origination.
Thanks a lot for the bug report!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-28 18:32 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>>
>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <manuel.vacelet@enalean.com
>>>>> >:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <toscano.luca@gmail.com
>>>>>> > wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>
>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>>
>>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>>>>>> more obvious.
>>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>>
>>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't
>>>>>>>>>>>> highlight the behaviour !
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>>> fastcgi.
>>>>>>>>>>>
>>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>>
>>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to
>>>>>>>>>> lead to inconsistencies (I'll try to build a test case for that).
>>>>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>>>>> resource will never expire). I would prefer either:
>>>>>>>>>> -- do not touch the header
>>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>>
>>>>>>>>>> What do you think ?
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> From my tests the following snippet of code should be responsible
>>>>>>>>> for the switch from 'foo' to unix epoch:
>>>>>>>>>
>>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>>
>>>>>>>>> The function that contains the code,
>>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>>> description of the function in:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>>
>>>>>>>>> Not sure what would be the best thing to do, but probably we could
>>>>>>>>> follow up in a official apache bugzilla task?
>>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>>
>>>>>>>>>
>>>>>>>> Wow, thanks for the investigation !
>>>>>>>>
>>>>>>>
>>>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>>>> http://svn.apache.org/r1748379
>>>>>>>
>>>>>>>
>>>>>> Cool :)
>>>>>>
>>>>>>
>>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>>> branch, we'll see what other people think about this solution.
>>>>>>>
>>>>>>> We should also do a follow up for the other main issue, namely the
>>>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>>>> header value before/after the "delay" and a way to repro it?
>>>>>>>
>>>>>>
>>>>>> I wrote a test case in the "time" branch:
>>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>>
>>>>>> In my own tests, I get:
>>>>>> --------------------->8---------------------
>>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>>> < X-Powered-By: PHP/5.6.5
>>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>>> < Transfer-Encoding: chunked
>>>>>> < Content-Type: text/html; charset=UTF-8
>>>>>> <
>>>>>> { [data not shown]
>>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>>
>>>>>> * Closing connection #0
>>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>>> --------------------->8---------------------
>>>>>>
>>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>>>>> zone) but the result is weird as you can see:
>>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>>
>>>>>> Notice the 2 seconds ?
>>>>>> I put a "sleep(2)" in my php script...
>>>>>>
>>>>>> I don't know if your fix also take this into account
>>>>>>
>>>>>
>>>>> Thanks a lot for the precise test! The same code snippet that I
>>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>>> the Last-Modified header with the request's modification time if the value
>>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>>> than the server's time of message origination (Date).").
>>>>>
>>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>>>> the header is not modified with the extra two seconds.
>>>>>
>>>>> So from what I can see httpd does the correct thing, I don't see a bug
>>>>> like in the previous case. What do you think? I am far from a PHP expert so
>>>>> I might have missed something important :)
>>>>>
>>>>>
>>>> Mmm I don't think it' the right way to compare the dates here as you
>>>> are really comparing the format strings here.
>>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>>
>>>
>>>> Clearly, just changing the timezone doesn't impact the time comparison
>>>> (and it's the expected behaviour).
>>>>
>>>
>>> Correct, in general the best way should be the one that you proposed,
>>> but in this case we are talking about RFC1123 specific date/times, so the
>>> format string comparison should be relevant imho. A efficient RFC 822/1123
>>> parser would probably assume the GMT timezone and care only about what
>>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>>> super strict and correct parse would also check the GMT bit and return
>>> error if missing, but it may be a bit overkill.
>>>
>>>
>>>> To me there is a wrong attempt to comply with RFC in apache here.
>>>> Either the parser is able to:
>>>> 1. correctly read the header input
>>>> 2. normalize to GMT
>>>> 3. ensure the resulting date is not > to server time (+ probably log
>>>> somthing to help developers to understand things)
>>>> or there should be a warning and the header is dropped (like if it's
>>>> not a date).
>>>>
>>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>>
>>>>
>>> I am seeing things in a different way, namely only point 3 should/could
>>> be implemented. AFAIU RFC1123 (and related) assume a GMT date/time and
>>> since the HTTP RFC requires this format for the Last-Modified header, I
>>> don't believe that httpd should be required to be able to convert multiple
>>> formats/timezones to RFC1123. This seems to be backed up by the comments of
>>> the function used by httpd to convert the Last-Modified header value:
>>>
>>
>> Ok but current behaviour is not correct either.
>>
>
> From https://tools.ietf.org/html/rfc2616#section-14.29
>
> An origin server MUST NOT send a Last-Modified date which is later
> than the server's time of message origination. In such cases, where
> the resource's last modification would indicate some time in the
> future, the server MUST replace that date with the message
> origination date.
>
> It also states that Last-Modified needs to be compliant with RFC 882/1123.
>
>
>> If I understood well assume that apache receives a RFC1123 value so it
>> compares with current server time (and eventually sends the later).
>>
>> In my example, the date is not a valid RFC1123 value (because it sends
>> +0200 or Europe/Paris). Here, the most sensible default would be to trash
>> with value.
>> It's as invalid as "foo" in my initial example so from my point of view
>> the behaviour of apache should be the same: discard the header (thanks to
>> your patch) and raise a warning.
>>
>
> We could patch httpd/apr to be super strict but I am not sure if it is
> worth it. In the meantime, I tried to improve logging, would you mind to
> tell me what you think about http://apaste.info/JlZ ?
>
This one should be clearer: http://apaste.info/8pa
I will also follow up with the dev@ mailing list to get other opinions
about this bug report.
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Tue, Jun 28, 2016 at 6:32 PM, Luca Toscano <to...@gmail.com>
wrote:
>
>
> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>>
>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <manuel.vacelet@enalean.com
>>>>> >:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <toscano.luca@gmail.com
>>>>>> > wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>
>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>>
>>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>>>>>> more obvious.
>>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>>
>>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't
>>>>>>>>>>>> highlight the behaviour !
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>>> fastcgi.
>>>>>>>>>>>
>>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>>
>>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to
>>>>>>>>>> lead to inconsistencies (I'll try to build a test case for that).
>>>>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>>>>> resource will never expire). I would prefer either:
>>>>>>>>>> -- do not touch the header
>>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>>
>>>>>>>>>> What do you think ?
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> From my tests the following snippet of code should be responsible
>>>>>>>>> for the switch from 'foo' to unix epoch:
>>>>>>>>>
>>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>>
>>>>>>>>> The function that contains the code,
>>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>>> description of the function in:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>>
>>>>>>>>> Not sure what would be the best thing to do, but probably we could
>>>>>>>>> follow up in a official apache bugzilla task?
>>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>>
>>>>>>>>>
>>>>>>>> Wow, thanks for the investigation !
>>>>>>>>
>>>>>>>
>>>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>>>> http://svn.apache.org/r1748379
>>>>>>>
>>>>>>>
>>>>>> Cool :)
>>>>>>
>>>>>>
>>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>>> branch, we'll see what other people think about this solution.
>>>>>>>
>>>>>>> We should also do a follow up for the other main issue, namely the
>>>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>>>> header value before/after the "delay" and a way to repro it?
>>>>>>>
>>>>>>
>>>>>> I wrote a test case in the "time" branch:
>>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>>
>>>>>> In my own tests, I get:
>>>>>> --------------------->8---------------------
>>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>>> < X-Powered-By: PHP/5.6.5
>>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>>> < Transfer-Encoding: chunked
>>>>>> < Content-Type: text/html; charset=UTF-8
>>>>>> <
>>>>>> { [data not shown]
>>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>>
>>>>>> * Closing connection #0
>>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>>> --------------------->8---------------------
>>>>>>
>>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>>>>> zone) but the result is weird as you can see:
>>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>>
>>>>>> Notice the 2 seconds ?
>>>>>> I put a "sleep(2)" in my php script...
>>>>>>
>>>>>> I don't know if your fix also take this into account
>>>>>>
>>>>>
>>>>> Thanks a lot for the precise test! The same code snippet that I
>>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>>> the Last-Modified header with the request's modification time if the value
>>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>>> than the server's time of message origination (Date).").
>>>>>
>>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>>>> the header is not modified with the extra two seconds.
>>>>>
>>>>> So from what I can see httpd does the correct thing, I don't see a bug
>>>>> like in the previous case. What do you think? I am far from a PHP expert so
>>>>> I might have missed something important :)
>>>>>
>>>>>
>>>> Mmm I don't think it' the right way to compare the dates here as you
>>>> are really comparing the format strings here.
>>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>>
>>>
>>>> Clearly, just changing the timezone doesn't impact the time comparison
>>>> (and it's the expected behaviour).
>>>>
>>>
>>> Correct, in general the best way should be the one that you proposed,
>>> but in this case we are talking about RFC1123 specific date/times, so the
>>> format string comparison should be relevant imho. A efficient RFC 822/1123
>>> parser would probably assume the GMT timezone and care only about what
>>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>>> super strict and correct parse would also check the GMT bit and return
>>> error if missing, but it may be a bit overkill.
>>>
>>>
>>>> To me there is a wrong attempt to comply with RFC in apache here.
>>>> Either the parser is able to:
>>>> 1. correctly read the header input
>>>> 2. normalize to GMT
>>>> 3. ensure the resulting date is not > to server time (+ probably log
>>>> somthing to help developers to understand things)
>>>> or there should be a warning and the header is dropped (like if it's
>>>> not a date).
>>>>
>>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>>
>>>>
>>> I am seeing things in a different way, namely only point 3 should/could
>>> be implemented. AFAIU RFC1123 (and related) assume a GMT date/time and
>>> since the HTTP RFC requires this format for the Last-Modified header, I
>>> don't believe that httpd should be required to be able to convert multiple
>>> formats/timezones to RFC1123. This seems to be backed up by the comments of
>>> the function used by httpd to convert the Last-Modified header value:
>>>
>>
>> Ok but current behaviour is not correct either.
>>
>
> From https://tools.ietf.org/html/rfc2616#section-14.29
>
> An origin server MUST NOT send a Last-Modified date which is later
> than the server's time of message origination. In such cases, where
> the resource's last modification would indicate some time in the
> future, the server MUST replace that date with the message
> origination date.
>
> It also states that Last-Modified needs to be compliant with RFC 882/1123.
>
Yes, indeed, so it should be the same behaviour if the backend sends
"Last-modified: foo" or "Last modified: Fri, 24 Jun 2016 17:21:46 +0200"
None of them are compliant with RFC 822 or 1123 hence I expect apr/apache
to behave the same way.
>
>> If I understood well assume that apache receives a RFC1123 value so it
>> compares with current server time (and eventually sends the later).
>>
>> In my example, the date is not a valid RFC1123 value (because it sends
>> +0200 or Europe/Paris). Here, the most sensible default would be to trash
>> with value.
>> It's as invalid as "foo" in my initial example so from my point of view
>> the behaviour of apache should be the same: discard the header (thanks to
>> your patch) and raise a warning.
>>
>
> We could patch httpd/apr to be super strict but I am not sure if it is
> worth it. In the meantime, I tried to improve logging, would you mind to
> tell me what you think about http://apaste.info/JlZ ?
>
The log is great (minor fix, I believe it's RFC822 and not RFC1123
according to https://tools.ietf.org/html/rfc2616#section-3.3.1
Manuel
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>
> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>>
>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
>>> wrote:
>>>
>>>>
>>>>
>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>
>>>> :
>>>>
>>>>>
>>>>>
>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com>:
>>>>>>
>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <
>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>
>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>>
>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>>
>>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>>>>> more obvious.
>>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>>
>>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>>> versions) is also in question here.
>>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight
>>>>>>>>>>> the behaviour !
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> I made another series of test and it seems to be linked to
>>>>>>>>>> fastcgi.
>>>>>>>>>>
>>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>>
>>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to lead
>>>>>>>>> to inconsistencies (I'll try to build a test case for that).
>>>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>>>> resource will never expire). I would prefer either:
>>>>>>>>> -- do not touch the header
>>>>>>>>> -- raise a warning and discard the header
>>>>>>>>>
>>>>>>>>> What do you think ?
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> From my tests the following snippet of code should be responsible
>>>>>>>> for the switch from 'foo' to unix epoch:
>>>>>>>>
>>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>>
>>>>>>>> The function that contains the code,
>>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>>> description of the function in:
>>>>>>>>
>>>>>>>>
>>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>>
>>>>>>>> Not sure what would be the best thing to do, but probably we could
>>>>>>>> follow up in a official apache bugzilla task?
>>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>>
>>>>>>>>
>>>>>>> Wow, thanks for the investigation !
>>>>>>>
>>>>>>
>>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>>> http://svn.apache.org/r1748379
>>>>>>
>>>>>>
>>>>> Cool :)
>>>>>
>>>>>
>>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>>> branch, we'll see what other people think about this solution.
>>>>>>
>>>>>> We should also do a follow up for the other main issue, namely the
>>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>>> header value before/after the "delay" and a way to repro it?
>>>>>>
>>>>>
>>>>> I wrote a test case in the "time" branch:
>>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>>
>>>>> In my own tests, I get:
>>>>> --------------------->8---------------------
>>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>>> < Server: Apache/2.4.18 (Red Hat)
>>>>> < X-Powered-By: PHP/5.6.5
>>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>>> < Transfer-Encoding: chunked
>>>>> < Content-Type: text/html; charset=UTF-8
>>>>> <
>>>>> { [data not shown]
>>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>>
>>>>> * Closing connection #0
>>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>>> --------------------->8---------------------
>>>>>
>>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>>>> zone) but the result is weird as you can see:
>>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>>
>>>>> Notice the 2 seconds ?
>>>>> I put a "sleep(2)" in my php script...
>>>>>
>>>>> I don't know if your fix also take this into account
>>>>>
>>>>
>>>> Thanks a lot for the precise test! The same code snippet that I
>>>> modified is responsible for the behavior that you mentioned. Httpd modifies
>>>> the Last-Modified header with the request's modification time if the value
>>>> sent from FCGI appears to be in the future (since the HTTP RFC states "An
>>>> origin server with a clock MUST NOT send a Last-Modified date that is later
>>>> than the server's time of message origination (Date).").
>>>>
>>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>>> the header is not modified with the extra two seconds.
>>>>
>>>> So from what I can see httpd does the correct thing, I don't see a bug
>>>> like in the previous case. What do you think? I am far from a PHP expert so
>>>> I might have missed something important :)
>>>>
>>>>
>>> Mmm I don't think it' the right way to compare the dates here as you are
>>> really comparing the format strings here.
>>> I propose a new version of the snippet: http://apaste.info/Aox
>>>
>>
>>> Clearly, just changing the timezone doesn't impact the time comparison
>>> (and it's the expected behaviour).
>>>
>>
>> Correct, in general the best way should be the one that you proposed, but
>> in this case we are talking about RFC1123 specific date/times, so the
>> format string comparison should be relevant imho. A efficient RFC 822/1123
>> parser would probably assume the GMT timezone and care only about what
>> comes before, this is why Europe/Paris is seen as more recent than GMT. A
>> super strict and correct parse would also check the GMT bit and return
>> error if missing, but it may be a bit overkill.
>>
>>
>>> To me there is a wrong attempt to comply with RFC in apache here.
>>> Either the parser is able to:
>>> 1. correctly read the header input
>>> 2. normalize to GMT
>>> 3. ensure the resulting date is not > to server time (+ probably log
>>> somthing to help developers to understand things)
>>> or there should be a warning and the header is dropped (like if it's not
>>> a date).
>>>
>>> Here I thing either step 1 ou 2 are no done properly in apache.
>>>
>>>
>> I am seeing things in a different way, namely only point 3 should/could
>> be implemented. AFAIU RFC1123 (and related) assume a GMT date/time and
>> since the HTTP RFC requires this format for the Last-Modified header, I
>> don't believe that httpd should be required to be able to convert multiple
>> formats/timezones to RFC1123. This seems to be backed up by the comments of
>> the function used by httpd to convert the Last-Modified header value:
>>
>
> Ok but current behaviour is not correct either.
>
From https://tools.ietf.org/html/rfc2616#section-14.29
An origin server MUST NOT send a Last-Modified date which is later
than the server's time of message origination. In such cases, where
the resource's last modification would indicate some time in the
future, the server MUST replace that date with the message
origination date.
It also states that Last-Modified needs to be compliant with RFC 882/1123.
> If I understood well assume that apache receives a RFC1123 value so it
> compares with current server time (and eventually sends the later).
>
> In my example, the date is not a valid RFC1123 value (because it sends
> +0200 or Europe/Paris). Here, the most sensible default would be to trash
> with value.
> It's as invalid as "foo" in my initial example so from my point of view
> the behaviour of apache should be the same: discard the header (thanks to
> your patch) and raise a warning.
>
We could patch httpd/apr to be super strict but I am not sure if it is
worth it. In the meantime, I tried to improve logging, would you mind to
tell me what you think about http://apaste.info/JlZ ?
Thanks!
Luca
>
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <to...@gmail.com>
wrote:
>
>
> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>>
>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <manuel.vacelet@enalean.com
>>>>> >:
>>>>>
>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <toscano.luca@gmail.com
>>>>>> > wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com>:
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>
>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>>
>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>>
>>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>>>> more obvious.
>>>>>>>>>>> During my tests (this is extracted from an automated test
>>>>>>>>>>> suite), even after having converted dates to rfc1123, I continued to get
>>>>>>>>>>> some sparse errors. What I got is that the value I sent was sometimes
>>>>>>>>>>> slightly modified (a second or 2) depending on the machine load."
>>>>>>>>>>>
>>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>>> versions) is also in question here.
>>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight
>>>>>>>>>> the behaviour !
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>>>>>
>>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>>> However, if I server the very same php script from mod_php
>>>>>>>>> (instead of fcgi) it "works" (the headers are not modified).
>>>>>>>>>
>>>>>>>>>
>>>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>>
>>>>>>>> On the root of the problem, from my point of view:
>>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>>> understandable (even if not desired and not documented).
>>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to lead
>>>>>>>> to inconsistencies (I'll try to build a test case for that).
>>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>>> resource will never expire). I would prefer either:
>>>>>>>> -- do not touch the header
>>>>>>>> -- raise a warning and discard the header
>>>>>>>>
>>>>>>>> What do you think ?
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> From my tests the following snippet of code should be responsible
>>>>>>> for the switch from 'foo' to unix epoch:
>>>>>>>
>>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>>
>>>>>>> The function that contains the code,
>>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>>> description of the function in:
>>>>>>>
>>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>>
>>>>>>> Not sure what would be the best thing to do, but probably we could
>>>>>>> follow up in a official apache bugzilla task?
>>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>>
>>>>>>>
>>>>>> Wow, thanks for the investigation !
>>>>>>
>>>>>
>>>>> Sorry for the delay! I submitted a patch for trunk with a possible
>>>>> fix, namely dropping (and logging at trace1 level) any non compliant
>>>>> date/time set in a Last-Modified header returned by a FCGI/CGI script:
>>>>> http://svn.apache.org/r1748379
>>>>>
>>>>>
>>>> Cool :)
>>>>
>>>>
>>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>>> branch, we'll see what other people think about this solution.
>>>>>
>>>>> We should also do a follow up for the other main issue, namely the
>>>>> fact that you see a different/delayed Last-Modified header sometimes among
>>>>> your FCGI/httpd responses. Can you give me an example of Last-Modified
>>>>> header value before/after the "delay" and a way to repro it?
>>>>>
>>>>
>>>> I wrote a test case in the "time" branch:
>>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>>
>>>> In my own tests, I get:
>>>> --------------------->8---------------------
>>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>>> < Server: Apache/2.4.18 (Red Hat)
>>>> < X-Powered-By: PHP/5.6.5
>>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>>> < Transfer-Encoding: chunked
>>>> < Content-Type: text/html; charset=UTF-8
>>>> <
>>>> { [data not shown]
>>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02
>>>> --:--:-- 21* Connection #0 to host localhost left intact
>>>>
>>>> * Closing connection #0
>>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>>> --------------------->8---------------------
>>>>
>>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>>> zone) but the result is weird as you can see:
>>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>>
>>>> Notice the 2 seconds ?
>>>> I put a "sleep(2)" in my php script...
>>>>
>>>> I don't know if your fix also take this into account
>>>>
>>>
>>> Thanks a lot for the precise test! The same code snippet that I modified
>>> is responsible for the behavior that you mentioned. Httpd modifies the
>>> Last-Modified header with the request's modification time if the value sent
>>> from FCGI appears to be in the future (since the HTTP RFC states "An origin
>>> server with a clock MUST NOT send a Last-Modified date that is later than
>>> the server's time of message origination (Date).").
>>>
>>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>>> the header is not modified with the extra two seconds.
>>>
>>> So from what I can see httpd does the correct thing, I don't see a bug
>>> like in the previous case. What do you think? I am far from a PHP expert so
>>> I might have missed something important :)
>>>
>>>
>> Mmm I don't think it' the right way to compare the dates here as you are
>> really comparing the format strings here.
>> I propose a new version of the snippet: http://apaste.info/Aox
>>
>
>> Clearly, just changing the timezone doesn't impact the time comparison
>> (and it's the expected behaviour).
>>
>
> Correct, in general the best way should be the one that you proposed, but
> in this case we are talking about RFC1123 specific date/times, so the
> format string comparison should be relevant imho. A efficient RFC 822/1123
> parser would probably assume the GMT timezone and care only about what
> comes before, this is why Europe/Paris is seen as more recent than GMT. A
> super strict and correct parse would also check the GMT bit and return
> error if missing, but it may be a bit overkill.
>
>
>> To me there is a wrong attempt to comply with RFC in apache here.
>> Either the parser is able to:
>> 1. correctly read the header input
>> 2. normalize to GMT
>> 3. ensure the resulting date is not > to server time (+ probably log
>> somthing to help developers to understand things)
>> or there should be a warning and the header is dropped (like if it's not
>> a date).
>>
>> Here I thing either step 1 ou 2 are no done properly in apache.
>>
>>
> I am seeing things in a different way, namely only point 3 should/could be
> implemented. AFAIU RFC1123 (and related) assume a GMT date/time and since
> the HTTP RFC requires this format for the Last-Modified header, I don't
> believe that httpd should be required to be able to convert multiple
> formats/timezones to RFC1123. This seems to be backed up by the comments of
> the function used by httpd to convert the Last-Modified header value:
>
Ok but current behaviour is not correct either.
If I understood well assume that apache receives a RFC1123 value so it
compares with current server time (and eventually sends the later).
In my example, the date is not a valid RFC1123 value (because it sends
+0200 or Europe/Paris). Here, the most sensible default would be to trash
with value.
It's as invalid as "foo" in my initial example so from my point of view the
behaviour of apache should be the same: discard the header (thanks to your
patch) and raise a warning.
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-27 13:17 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>
> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>>
>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
>>> wrote:
>>>
>>>>
>>>>
>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>
>>>> :
>>>>
>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com>:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>
>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>>
>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> I was able to repro building httpd from 2.4.x branch and
>>>>>>>>>> following your configuration files on github. I am almost sure that
>>>>>>>>>> somewhere httpd sets the Last-Modified header translating "foo" to the
>>>>>>>>>> first Jan 1970 date. I realized though that I didn't recall the real issue,
>>>>>>>>>> since passing value not following the RFC can lead to inconsistencies, so I
>>>>>>>>>> went back and checked the correspondence. Quoting:
>>>>>>>>>>
>>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>>> more obvious.
>>>>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>>>>
>>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>>> However, the (undocumented) difference of behavior from one
>>>>>>>>> version to another (2.2 -> 2.4 and more surprisingly from between two 2.4
>>>>>>>>> versions) is also in question here.
>>>>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight
>>>>>>>>> the behaviour !
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>>>>
>>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>>> (headers rewritten to EPOCH)
>>>>>>>> However, if I server the very same php script from mod_php (instead
>>>>>>>> of fcgi) it "works" (the headers are not modified).
>>>>>>>>
>>>>>>>>
>>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>>
>>>>>>> On the root of the problem, from my point of view:
>>>>>>> - the difference between mod_php vs. php-fpm + fcgi is
>>>>>>> understandable (even if not desired and not documented).
>>>>>>> - the fact that fcgi handler parse & rewrite headers seems to lead
>>>>>>> to inconsistencies (I'll try to build a test case for that).
>>>>>>> - however, even if the headers are wrong, I think apache default
>>>>>>> (use EPOCH) is wrong as it leads to very inconsistent behaviour (the
>>>>>>> resource will never expire). I would prefer either:
>>>>>>> -- do not touch the header
>>>>>>> -- raise a warning and discard the header
>>>>>>>
>>>>>>> What do you think ?
>>>>>>>
>>>>>>
>>>>>>
>>>>>> From my tests the following snippet of code should be responsible for
>>>>>> the switch from 'foo' to unix epoch:
>>>>>>
>>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>>
>>>>>> The function that contains the code,
>>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>>> description of the function in:
>>>>>>
>>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>>
>>>>>> Not sure what would be the best thing to do, but probably we could
>>>>>> follow up in a official apache bugzilla task?
>>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>>
>>>>>>
>>>>> Wow, thanks for the investigation !
>>>>>
>>>>
>>>> Sorry for the delay! I submitted a patch for trunk with a possible fix,
>>>> namely dropping (and logging at trace1 level) any non compliant date/time
>>>> set in a Last-Modified header returned by a FCGI/CGI script:
>>>> http://svn.apache.org/r1748379
>>>>
>>>>
>>> Cool :)
>>>
>>>
>>>> The fix is also in the list of proposal for backport to the 2.4.x
>>>> branch, we'll see what other people think about this solution.
>>>>
>>>> We should also do a follow up for the other main issue, namely the fact
>>>> that you see a different/delayed Last-Modified header sometimes among your
>>>> FCGI/httpd responses. Can you give me an example of Last-Modified header
>>>> value before/after the "delay" and a way to repro it?
>>>>
>>>
>>> I wrote a test case in the "time" branch:
>>> https://github.com/vaceletm/bug-httpd24/tree/time
>>>
>>> In my own tests, I get:
>>> --------------------->8---------------------
>>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>>> < Server: Apache/2.4.18 (Red Hat)
>>> < X-Powered-By: PHP/5.6.5
>>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>>> < Transfer-Encoding: chunked
>>> < Content-Type: text/html; charset=UTF-8
>>> <
>>> { [data not shown]
>>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02 --:--:--
>>> 21* Connection #0 to host localhost left intact
>>>
>>> * Closing connection #0
>>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>>> --------------------->8---------------------
>>>
>>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>>> zone) but the result is weird as you can see:
>>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>>
>>> Notice the 2 seconds ?
>>> I put a "sleep(2)" in my php script...
>>>
>>> I don't know if your fix also take this into account
>>>
>>
>> Thanks a lot for the precise test! The same code snippet that I modified
>> is responsible for the behavior that you mentioned. Httpd modifies the
>> Last-Modified header with the request's modification time if the value sent
>> from FCGI appears to be in the future (since the HTTP RFC states "An origin
>> server with a clock MUST NOT send a Last-Modified date that is later than
>> the server's time of message origination (Date).").
>>
>> I modified your PHP code snippet (http://apaste.info/EEz) trying to
>> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
>> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
>> more recent. Moreover, if you generate a GMT date and format it for RFC1123
>> the header is not modified with the extra two seconds.
>>
>> So from what I can see httpd does the correct thing, I don't see a bug
>> like in the previous case. What do you think? I am far from a PHP expert so
>> I might have missed something important :)
>>
>>
> Mmm I don't think it' the right way to compare the dates here as you are
> really comparing the format strings here.
> I propose a new version of the snippet: http://apaste.info/Aox
>
> Clearly, just changing the timezone doesn't impact the time comparison
> (and it's the expected behaviour).
>
Correct, in general the best way should be the one that you proposed, but
in this case we are talking about RFC1123 specific date/times, so the
format string comparison should be relevant imho. A efficient RFC 822/1123
parser would probably assume the GMT timezone and care only about what
comes before, this is why Europe/Paris is seen as more recent than GMT. A
super strict and correct parse would also check the GMT bit and return
error if missing, but it may be a bit overkill.
> To me there is a wrong attempt to comply with RFC in apache here.
> Either the parser is able to:
> 1. correctly read the header input
> 2. normalize to GMT
> 3. ensure the resulting date is not > to server time (+ probably log
> somthing to help developers to understand things)
> or there should be a warning and the header is dropped (like if it's not a
> date).
>
> Here I thing either step 1 ou 2 are no done properly in apache.
>
>
I am seeing things in a different way, namely only point 3 should/could be
implemented. AFAIU RFC1123 (and related) assume a GMT date/time and since
the HTTP RFC requires this format for the Last-Modified header, I don't
believe that httpd should be required to be able to convert multiple
formats/timezones to RFC1123. This seems to be backed up by the comments of
the function used by httpd to convert the Last-Modified header value:
https://github.com/apache/apr/blob/72d7d0922949f47d58574c3d638d9d8c30a08e3f/util-misc/apr_date.c#L98
I do agree with you that it would be awesome to have these kind of issues
sorted out directly by httpd, but it is also true that we shouldn't
consider it as catch-all corrector for non RFC compliant HTTP responses
coming from upstream (even if in this case it corrects the wrong value with
a compliant one).
This is my view of things, really curious to know other opinions from the
mailing list!
Thanks again!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano <to...@gmail.com>
wrote:
>
>
> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>>
>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <manuel.vacelet@enalean.com
>>>>> >:
>>>>>
>>>>>>
>>>>>>
>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>
>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>>
>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <
>>>>>>>> toscano.luca@gmail.com> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>>>>> checked the correspondence. Quoting:
>>>>>>>>>
>>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>>> more obvious.
>>>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>>>
>>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>>
>>>>>>>>
>>>>>>>> Yes for sure, this is the primary issue.
>>>>>>>> However, the (undocumented) difference of behavior from one version
>>>>>>>> to another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions)
>>>>>>>> is also in question here.
>>>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight
>>>>>>>> the behaviour !
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>>>
>>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>>> (headers rewritten to EPOCH)
>>>>>>> However, if I server the very same php script from mod_php (instead
>>>>>>> of fcgi) it "works" (the headers are not modified).
>>>>>>>
>>>>>>>
>>>>>> For the record, I also have the same behaviour (headers rewritten
>>>>>> when using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>>
>>>>>> On the root of the problem, from my point of view:
>>>>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>>>>> (even if not desired and not documented).
>>>>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>>>>> inconsistencies (I'll try to build a test case for that).
>>>>>> - however, even if the headers are wrong, I think apache default (use
>>>>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>>>>> will never expire). I would prefer either:
>>>>>> -- do not touch the header
>>>>>> -- raise a warning and discard the header
>>>>>>
>>>>>> What do you think ?
>>>>>>
>>>>>
>>>>>
>>>>> From my tests the following snippet of code should be responsible for
>>>>> the switch from 'foo' to unix epoch:
>>>>>
>>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>>
>>>>> The function that contains the code,
>>>>> ap_scan_script_header_err_core_ex, is wrapped by a lot of other functions
>>>>> eventually called by modules like mod-proxy-fcgi. A more verbose
>>>>> description of the function in:
>>>>>
>>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>>
>>>>> Not sure what would be the best thing to do, but probably we could
>>>>> follow up in a official apache bugzilla task?
>>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>>
>>>>>
>>>> Wow, thanks for the investigation !
>>>>
>>>
>>> Sorry for the delay! I submitted a patch for trunk with a possible fix,
>>> namely dropping (and logging at trace1 level) any non compliant date/time
>>> set in a Last-Modified header returned by a FCGI/CGI script:
>>> http://svn.apache.org/r1748379
>>>
>>>
>> Cool :)
>>
>>
>>> The fix is also in the list of proposal for backport to the 2.4.x
>>> branch, we'll see what other people think about this solution.
>>>
>>> We should also do a follow up for the other main issue, namely the fact
>>> that you see a different/delayed Last-Modified header sometimes among your
>>> FCGI/httpd responses. Can you give me an example of Last-Modified header
>>> value before/after the "delay" and a way to repro it?
>>>
>>
>> I wrote a test case in the "time" branch:
>> https://github.com/vaceletm/bug-httpd24/tree/time
>>
>> In my own tests, I get:
>> --------------------->8---------------------
>> < Date: Fri, 24 Jun 2016 15:21:46 GMT
>> < Server: Apache/2.4.18 (Red Hat)
>> < X-Powered-By: PHP/5.6.5
>> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
>> < Transfer-Encoding: chunked
>> < Content-Type: text/html; charset=UTF-8
>> <
>> { [data not shown]
>> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02 --:--:--
>> 21* Connection #0 to host localhost left intact
>>
>> * Closing connection #0
>> sent value: Fri, 24 Jun 2016 17:21:46 +0200
>> --------------------->8---------------------
>>
>> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time
>> zone) but the result is weird as you can see:
>> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
>> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>>
>> Notice the 2 seconds ?
>> I put a "sleep(2)" in my php script...
>>
>> I don't know if your fix also take this into account
>>
>
> Thanks a lot for the precise test! The same code snippet that I modified
> is responsible for the behavior that you mentioned. Httpd modifies the
> Last-Modified header with the request's modification time if the value sent
> from FCGI appears to be in the future (since the HTTP RFC states "An origin
> server with a clock MUST NOT send a Last-Modified date that is later than
> the server's time of message origination (Date).").
>
> I modified your PHP code snippet (http://apaste.info/EEz) trying to
> compare a GMT date vs a "Europe/Paris" one, already formatted for RFC1123,
> and PHP seems to agree with httpd in recognizing the "Europe/Paris" date as
> more recent. Moreover, if you generate a GMT date and format it for RFC1123
> the header is not modified with the extra two seconds.
>
> So from what I can see httpd does the correct thing, I don't see a bug
> like in the previous case. What do you think? I am far from a PHP expert so
> I might have missed something important :)
>
>
Mmm I don't think it' the right way to compare the dates here as you are
really comparing the format strings here.
I propose a new version of the snippet: http://apaste.info/Aox
Clearly, just changing the timezone doesn't impact the time comparison (and
it's the expected behaviour).
To me there is a wrong attempt to comply with RFC in apache here.
Either the parser is able to:
1. correctly read the header input
2. normalize to GMT
3. ensure the resulting date is not > to server time (+ probably log
somthing to help developers to understand things)
or there should be a warning and the header is dropped (like if it's not a
date).
Here I thing either step 1 ou 2 are no done properly in apache.
Manuel
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-24 17:26 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>
> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>>
>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
>>> wrote:
>>>
>>>>
>>>>
>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>
>>>> :
>>>>
>>>>>
>>>>>
>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>
>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>>
>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <toscano.luca@gmail.com
>>>>>>> > wrote:
>>>>>>>
>>>>>>>>
>>>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>>>> checked the correspondence. Quoting:
>>>>>>>>
>>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>>> more obvious.
>>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>>
>>>>>>>> So my understanding is that you would like to know why a
>>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>>
>>>>>>>
>>>>>>> Yes for sure, this is the primary issue.
>>>>>>> However, the (undocumented) difference of behavior from one version
>>>>>>> to another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions)
>>>>>>> is also in question here.
>>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>>>> behaviour !
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>>
>>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>>> (headers rewritten to EPOCH)
>>>>>> However, if I server the very same php script from mod_php (instead
>>>>>> of fcgi) it "works" (the headers are not modified).
>>>>>>
>>>>>>
>>>>> For the record, I also have the same behaviour (headers rewritten when
>>>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>>> So AFAICT, it doesn't seem distro specific.
>>>>>
>>>>> On the root of the problem, from my point of view:
>>>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>>>> (even if not desired and not documented).
>>>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>>>> inconsistencies (I'll try to build a test case for that).
>>>>> - however, even if the headers are wrong, I think apache default (use
>>>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>>>> will never expire). I would prefer either:
>>>>> -- do not touch the header
>>>>> -- raise a warning and discard the header
>>>>>
>>>>> What do you think ?
>>>>>
>>>>
>>>>
>>>> From my tests the following snippet of code should be responsible for
>>>> the switch from 'foo' to unix epoch:
>>>>
>>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>>
>>>> The function that contains the code, ap_scan_script_header_err_core_ex,
>>>> is wrapped by a lot of other functions eventually called by modules like
>>>> mod-proxy-fcgi. A more verbose description of the function in:
>>>>
>>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>>
>>>> Not sure what would be the best thing to do, but probably we could
>>>> follow up in a official apache bugzilla task?
>>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>>
>>>>
>>> Wow, thanks for the investigation !
>>>
>>
>> Sorry for the delay! I submitted a patch for trunk with a possible fix,
>> namely dropping (and logging at trace1 level) any non compliant date/time
>> set in a Last-Modified header returned by a FCGI/CGI script:
>> http://svn.apache.org/r1748379
>>
>>
> Cool :)
>
>
>> The fix is also in the list of proposal for backport to the 2.4.x branch,
>> we'll see what other people think about this solution.
>>
>> We should also do a follow up for the other main issue, namely the fact
>> that you see a different/delayed Last-Modified header sometimes among your
>> FCGI/httpd responses. Can you give me an example of Last-Modified header
>> value before/after the "delay" and a way to repro it?
>>
>
> I wrote a test case in the "time" branch:
> https://github.com/vaceletm/bug-httpd24/tree/time
>
> In my own tests, I get:
> --------------------->8---------------------
> < Date: Fri, 24 Jun 2016 15:21:46 GMT
> < Server: Apache/2.4.18 (Red Hat)
> < X-Powered-By: PHP/5.6.5
> < Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
> < Transfer-Encoding: chunked
> < Content-Type: text/html; charset=UTF-8
> <
> { [data not shown]
> 0 44 0 44 0 0 21 0 --:--:-- 0:00:02 --:--:--
> 21* Connection #0 to host localhost left intact
>
> * Closing connection #0
> sent value: Fri, 24 Jun 2016 17:21:46 +0200
> --------------------->8---------------------
>
> The value sent doesn't respect RFC1123 (+0200 instead of GMT as time zone)
> but the result is weird as you can see:
> - I sent "Fri, 24 Jun 2016 17:21:46 +0200"
> - but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
>
> Notice the 2 seconds ?
> I put a "sleep(2)" in my php script...
>
> I don't know if your fix also take this into account
>
Thanks a lot for the precise test! The same code snippet that I modified is
responsible for the behavior that you mentioned. Httpd modifies the
Last-Modified header with the request's modification time if the value sent
from FCGI appears to be in the future (since the HTTP RFC states "An origin
server with a clock MUST NOT send a Last-Modified date that is later than
the server's time of message origination (Date).").
I modified your PHP code snippet (http://apaste.info/EEz) trying to compare
a GMT date vs a "Europe/Paris" one, already formatted for RFC1123, and PHP
seems to agree with httpd in recognizing the "Europe/Paris" date as more
recent. Moreover, if you generate a GMT date and format it for RFC1123 the
header is not modified with the extra two seconds.
So from what I can see httpd does the correct thing, I don't see a bug like
in the previous case. What do you think? I am far from a PHP expert so I
might have missed something important :)
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano <to...@gmail.com>
wrote:
>
>
> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>>
>>>>
>>>>
>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>>> manuel.vacelet@enalean.com> wrote:
>>>>>
>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>>>
>>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>>> checked the correspondence. Quoting:
>>>>>>>
>>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>>> more obvious.
>>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>>
>>>>>>> So my understanding is that you would like to know why a
>>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>>
>>>>>>
>>>>>> Yes for sure, this is the primary issue.
>>>>>> However, the (undocumented) difference of behavior from one version
>>>>>> to another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions)
>>>>>> is also in question here.
>>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>>> behaviour !
>>>>>>
>>>>>>
>>>>>
>>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>>
>>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm
>>>>> (5.4.16 + tons of patches) from RHEL7 and I get the exact same behaviour
>>>>> (headers rewritten to EPOCH)
>>>>> However, if I server the very same php script from mod_php (instead of
>>>>> fcgi) it "works" (the headers are not modified).
>>>>>
>>>>>
>>>> For the record, I also have the same behaviour (headers rewritten when
>>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>>> So AFAICT, it doesn't seem distro specific.
>>>>
>>>> On the root of the problem, from my point of view:
>>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>>> (even if not desired and not documented).
>>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>>> inconsistencies (I'll try to build a test case for that).
>>>> - however, even if the headers are wrong, I think apache default (use
>>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>>> will never expire). I would prefer either:
>>>> -- do not touch the header
>>>> -- raise a warning and discard the header
>>>>
>>>> What do you think ?
>>>>
>>>
>>>
>>> From my tests the following snippet of code should be responsible for
>>> the switch from 'foo' to unix epoch:
>>>
>>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>>
>>> The function that contains the code, ap_scan_script_header_err_core_ex,
>>> is wrapped by a lot of other functions eventually called by modules like
>>> mod-proxy-fcgi. A more verbose description of the function in:
>>>
>>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>>
>>> Not sure what would be the best thing to do, but probably we could
>>> follow up in a official apache bugzilla task?
>>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>>
>>>
>> Wow, thanks for the investigation !
>>
>
> Sorry for the delay! I submitted a patch for trunk with a possible fix,
> namely dropping (and logging at trace1 level) any non compliant date/time
> set in a Last-Modified header returned by a FCGI/CGI script:
> http://svn.apache.org/r1748379
>
>
Cool :)
> The fix is also in the list of proposal for backport to the 2.4.x branch,
> we'll see what other people think about this solution.
>
> We should also do a follow up for the other main issue, namely the fact
> that you see a different/delayed Last-Modified header sometimes among your
> FCGI/httpd responses. Can you give me an example of Last-Modified header
> value before/after the "delay" and a way to repro it?
>
I wrote a test case in the "time" branch:
https://github.com/vaceletm/bug-httpd24/tree/time
In my own tests, I get:
--------------------->8---------------------
< Date: Fri, 24 Jun 2016 15:21:46 GMT
< Server: Apache/2.4.18 (Red Hat)
< X-Powered-By: PHP/5.6.5
< Last-Modified: Fri, 24 Jun 2016 15:21:48 GMT
< Transfer-Encoding: chunked
< Content-Type: text/html; charset=UTF-8
<
{ [data not shown]
0 44 0 44 0 0 21 0 --:--:-- 0:00:02 --:--:--
21* Connection #0 to host localhost left intact
* Closing connection #0
sent value: Fri, 24 Jun 2016 17:21:46 +0200
--------------------->8---------------------
The value sent doesn't respect RFC1123 (+0200 instead of GMT as time zone)
but the result is weird as you can see:
- I sent "Fri, 24 Jun 2016 17:21:46 +0200"
- but apache decided to send "Fri, 24 Jun 2016 15:21:48 GMT"
Notice the 2 seconds ?
I put a "sleep(2)" in my php script...
I don't know if your fix also take this into account
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-08 16:14 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>>
>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>>
>>>
>>>
>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>>> manuel.vacelet@enalean.com> wrote:
>>>>
>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>>> checked the correspondence. Quoting:
>>>>>>
>>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>>> more obvious.
>>>>>> During my tests (this is extracted from an automated test suite),
>>>>>> even after having converted dates to rfc1123, I continued to get some
>>>>>> sparse errors. What I got is that the value I sent was sometimes slightly
>>>>>> modified (a second or 2) depending on the machine load."
>>>>>>
>>>>>> So my understanding is that you would like to know why a
>>>>>> Last-Modified header with a legitimate date/time set by a PHP app gets
>>>>>> "delayed" by a couple of seconds from httpd, right?
>>>>>>
>>>>>
>>>>> Yes for sure, this is the primary issue.
>>>>> However, the (undocumented) difference of behavior from one version to
>>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>>> also in question here.
>>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>>> behaviour !
>>>>>
>>>>>
>>>>
>>>> I made another series of test and it seems to be linked to fastcgi.
>>>>
>>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>>> rewritten to EPOCH)
>>>> However, if I server the very same php script from mod_php (instead of
>>>> fcgi) it "works" (the headers are not modified).
>>>>
>>>>
>>> For the record, I also have the same behaviour (headers rewritten when
>>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>>> So AFAICT, it doesn't seem distro specific.
>>>
>>> On the root of the problem, from my point of view:
>>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>>> (even if not desired and not documented).
>>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>>> inconsistencies (I'll try to build a test case for that).
>>> - however, even if the headers are wrong, I think apache default (use
>>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>>> will never expire). I would prefer either:
>>> -- do not touch the header
>>> -- raise a warning and discard the header
>>>
>>> What do you think ?
>>>
>>
>>
>> From my tests the following snippet of code should be responsible for the
>> switch from 'foo' to unix epoch:
>>
>> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
>> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>>
>> The function that contains the code, ap_scan_script_header_err_core_ex,
>> is wrapped by a lot of other functions eventually called by modules like
>> mod-proxy-fcgi. A more verbose description of the function in:
>>
>> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>>
>> Not sure what would be the best thing to do, but probably we could follow
>> up in a official apache bugzilla task?
>> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>>
>>
> Wow, thanks for the investigation !
>
Sorry for the delay! I submitted a patch for trunk with a possible fix,
namely dropping (and logging at trace1 level) any non compliant date/time
set in a Last-Modified header returned by a FCGI/CGI script:
http://svn.apache.org/r1748379
The fix is also in the list of proposal for backport to the 2.4.x branch,
we'll see what other people think about this solution.
We should also do a follow up for the other main issue, namely the fact
that you see a different/delayed Last-Modified header sometimes among your
FCGI/httpd responses. Can you give me an example of Last-Modified header
value before/after the "delay" and a way to repro it?
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
[+devs]
2016-06-07 23:02 GMT+02:00 Luca Toscano <to...@gmail.com>:
>
>
> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>> manuel.vacelet@enalean.com> wrote:
>>
>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>> checked the correspondence. Quoting:
>>>>>
>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>> more obvious.
>>>>> During my tests (this is extracted from an automated test suite), even
>>>>> after having converted dates to rfc1123, I continued to get some sparse
>>>>> errors. What I got is that the value I sent was sometimes slightly modified
>>>>> (a second or 2) depending on the machine load."
>>>>>
>>>>> So my understanding is that you would like to know why a Last-Modified
>>>>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>>>>> couple of seconds from httpd, right?
>>>>>
>>>>
>>>> Yes for sure, this is the primary issue.
>>>> However, the (undocumented) difference of behavior from one version to
>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>> also in question here.
>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>> behaviour !
>>>>
>>>>
>>>
>>> I made another series of test and it seems to be linked to fastcgi.
>>>
>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>> rewritten to EPOCH)
>>> However, if I server the very same php script from mod_php (instead of
>>> fcgi) it "works" (the headers are not modified).
>>>
>>>
>> For the record, I also have the same behaviour (headers rewritten when
>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>> So AFAICT, it doesn't seem distro specific.
>>
>> On the root of the problem, from my point of view:
>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>> (even if not desired and not documented).
>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>> inconsistencies (I'll try to build a test case for that).
>> - however, even if the headers are wrong, I think apache default (use
>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>> will never expire). I would prefer either:
>> -- do not touch the header
>> -- raise a warning and discard the header
>>
>> What do you think ?
>>
>
>
> From my tests the following snippet of code should be responsible for the
> switch from 'foo' to unix epoch:
>
> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>
> The function that contains the code, ap_scan_script_header_err_core_ex, is
> wrapped by a lot of other functions eventually called by modules like
> mod-proxy-fcgi. A more verbose description of the function in:
>
> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>
> Not sure what would be the best thing to do, but probably we could follow
> up in a official apache bugzilla task?
> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>
> Any thoughts by other readers of the email list?
>
More specifically, the following patch let the "foo" Last-Modified header
to be returned instead of unix epoch:
--- server/util_script.c (revision 1747375)
+++ server/util_script.c (working copy)
@@ -665,8 +665,13 @@
* pass it on blindly because of restrictions on future values.
*/
else if (!strcasecmp(w, "Last-Modified")) {
- ap_update_mtime(r, apr_date_parse_http(l));
- ap_set_last_modified(r);
+ apr_time_t last_modified_date = apr_date_parse_http(l);
+ if (last_modified_date) {
+ ap_update_mtime(r, last_modified_date);
+ ap_set_last_modified(r);
+ } else {
+ apr_table_set(r->headers_out, w, l);
+ }
}
else if (!strcasecmp(w, "Set-Cookie")) {
apr_table_add(cookie_table, w, l);
Omitting the "else" branch will force httpd to drop anything that is not a
date in Last-Modified (like 'foo'). Of course this patch is only a proof of
concept, it is not meant to be the final solution :)
Reading https://www.w3.org/Protocols/rfc2616/rfc2616-sec14.html I am not
sure what would be the best course of action.
I added the httpd-dev mailing list to get some opinion. Steps to repro are
contained in https://bugs.centos.org/view.php?id=10940
Thanks!
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano <to...@gmail.com>
wrote:
>
>
> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>>
>>
>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
>> manuel.vacelet@enalean.com> wrote:
>>
>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>>> manuel.vacelet@enalean.com> wrote:
>>>
>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>>> wrote:
>>>>
>>>>>
>>>>> I was able to repro building httpd from 2.4.x branch and following
>>>>> your configuration files on github. I am almost sure that somewhere httpd
>>>>> sets the Last-Modified header translating "foo" to the first Jan 1970 date.
>>>>> I realized though that I didn't recall the real issue, since passing value
>>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>>> checked the correspondence. Quoting:
>>>>>
>>>>> "Actually I wrote this snippet to highlight the behaviour (the
>>>>> original code sent the date in iso8601 instead of rfc1123) because it was
>>>>> more obvious.
>>>>> During my tests (this is extracted from an automated test suite), even
>>>>> after having converted dates to rfc1123, I continued to get some sparse
>>>>> errors. What I got is that the value I sent was sometimes slightly modified
>>>>> (a second or 2) depending on the machine load."
>>>>>
>>>>> So my understanding is that you would like to know why a Last-Modified
>>>>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>>>>> couple of seconds from httpd, right?
>>>>>
>>>>
>>>> Yes for sure, this is the primary issue.
>>>> However, the (undocumented) difference of behavior from one version to
>>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>>> also in question here.
>>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>>> behaviour !
>>>>
>>>>
>>>
>>> I made another series of test and it seems to be linked to fastcgi.
>>>
>>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16
>>> + tons of patches) from RHEL7 and I get the exact same behaviour (headers
>>> rewritten to EPOCH)
>>> However, if I server the very same php script from mod_php (instead of
>>> fcgi) it "works" (the headers are not modified).
>>>
>>>
>> For the record, I also have the same behaviour (headers rewritten when
>> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
>> So AFAICT, it doesn't seem distro specific.
>>
>> On the root of the problem, from my point of view:
>> - the difference between mod_php vs. php-fpm + fcgi is understandable
>> (even if not desired and not documented).
>> - the fact that fcgi handler parse & rewrite headers seems to lead to
>> inconsistencies (I'll try to build a test case for that).
>> - however, even if the headers are wrong, I think apache default (use
>> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
>> will never expire). I would prefer either:
>> -- do not touch the header
>> -- raise a warning and discard the header
>>
>> What do you think ?
>>
>
>
> From my tests the following snippet of code should be responsible for the
> switch from 'foo' to unix epoch:
>
> *https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
> <https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
>
> The function that contains the code, ap_scan_script_header_err_core_ex, is
> wrapped by a lot of other functions eventually called by modules like
> mod-proxy-fcgi. A more verbose description of the function in:
>
> https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
>
> Not sure what would be the best thing to do, but probably we could follow
> up in a official apache bugzilla task?
> https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
>
>
Wow, thanks for the investigation !
I can open the bug on bugzilla but I'm not sure how to properly describe
the problem.
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-07 10:55 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
>
>
> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <
> manuel.vacelet@enalean.com> wrote:
>
>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
>> manuel.vacelet@enalean.com> wrote:
>>
>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>>> wrote:
>>>
>>>>
>>>> I was able to repro building httpd from 2.4.x branch and following your
>>>> configuration files on github. I am almost sure that somewhere httpd sets
>>>> the Last-Modified header translating "foo" to the first Jan 1970 date. I
>>>> realized though that I didn't recall the real issue, since passing value
>>>> not following the RFC can lead to inconsistencies, so I went back and
>>>> checked the correspondence. Quoting:
>>>>
>>>> "Actually I wrote this snippet to highlight the behaviour (the original
>>>> code sent the date in iso8601 instead of rfc1123) because it was more
>>>> obvious.
>>>> During my tests (this is extracted from an automated test suite), even
>>>> after having converted dates to rfc1123, I continued to get some sparse
>>>> errors. What I got is that the value I sent was sometimes slightly modified
>>>> (a second or 2) depending on the machine load."
>>>>
>>>> So my understanding is that you would like to know why a Last-Modified
>>>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>>>> couple of seconds from httpd, right?
>>>>
>>>
>>> Yes for sure, this is the primary issue.
>>> However, the (undocumented) difference of behavior from one version to
>>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>>> also in question here.
>>> Even more strange, 2.4 built for other distrib doesn't highlight the
>>> behaviour !
>>>
>>>
>>
>> I made another series of test and it seems to be linked to fastcgi.
>>
>> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16 +
>> tons of patches) from RHEL7 and I get the exact same behaviour (headers
>> rewritten to EPOCH)
>> However, if I server the very same php script from mod_php (instead of
>> fcgi) it "works" (the headers are not modified).
>>
>>
> For the record, I also have the same behaviour (headers rewritten when
> using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
> So AFAICT, it doesn't seem distro specific.
>
> On the root of the problem, from my point of view:
> - the difference between mod_php vs. php-fpm + fcgi is understandable
> (even if not desired and not documented).
> - the fact that fcgi handler parse & rewrite headers seems to lead to
> inconsistencies (I'll try to build a test case for that).
> - however, even if the headers are wrong, I think apache default (use
> EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
> will never expire). I would prefer either:
> -- do not touch the header
> -- raise a warning and discard the header
>
> What do you think ?
>
From my tests the following snippet of code should be responsible for the
switch from 'foo' to unix epoch:
*https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663
<https://github.com/apache/httpd/blob/2.4.x/server/util_script.c#L663>*
The function that contains the code, ap_scan_script_header_err_core_ex, is
wrapped by a lot of other functions eventually called by modules like
mod-proxy-fcgi. A more verbose description of the function in:
https://github.com/apache/httpd/blob/2.4.x/include/util_script.h#L200
Not sure what would be the best thing to do, but probably we could follow
up in a official apache bugzilla task?
https://bz.apache.org/bugzilla/enter_bug.cgi?product=Apache%20httpd-2
Any thoughts by other readers of the email list?
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel <ma...@enalean.com>
wrote:
> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <
> manuel.vacelet@enalean.com> wrote:
>
>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>> I was able to repro building httpd from 2.4.x branch and following your
>>> configuration files on github. I am almost sure that somewhere httpd sets
>>> the Last-Modified header translating "foo" to the first Jan 1970 date. I
>>> realized though that I didn't recall the real issue, since passing value
>>> not following the RFC can lead to inconsistencies, so I went back and
>>> checked the correspondence. Quoting:
>>>
>>> "Actually I wrote this snippet to highlight the behaviour (the original
>>> code sent the date in iso8601 instead of rfc1123) because it was more
>>> obvious.
>>> During my tests (this is extracted from an automated test suite), even
>>> after having converted dates to rfc1123, I continued to get some sparse
>>> errors. What I got is that the value I sent was sometimes slightly modified
>>> (a second or 2) depending on the machine load."
>>>
>>> So my understanding is that you would like to know why a Last-Modified
>>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>>> couple of seconds from httpd, right?
>>>
>>
>> Yes for sure, this is the primary issue.
>> However, the (undocumented) difference of behavior from one version to
>> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
>> also in question here.
>> Even more strange, 2.4 built for other distrib doesn't highlight the
>> behaviour !
>>
>>
>
> I made another series of test and it seems to be linked to fastcgi.
>
> I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16 +
> tons of patches) from RHEL7 and I get the exact same behaviour (headers
> rewritten to EPOCH)
> However, if I server the very same php script from mod_php (instead of
> fcgi) it "works" (the headers are not modified).
>
>
For the record, I also have the same behaviour (headers rewritten when
using php-fpm + fastcgi) on alpine linux 3.4 that ships apache2-2.4.20.
So AFAICT, it doesn't seem distro specific.
On the root of the problem, from my point of view:
- the difference between mod_php vs. php-fpm + fcgi is understandable (even
if not desired and not documented).
- the fact that fcgi handler parse & rewrite headers seems to lead to
inconsistencies (I'll try to build a test case for that).
- however, even if the headers are wrong, I think apache default (use
EPOCH) is wrong as it leads to very inconsistent behaviour (the resource
will never expire). I would prefer either:
-- do not touch the header
-- raise a warning and discard the header
What do you think ?
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel <manuel.vacelet@enalean.com
> wrote:
> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>> I was able to repro building httpd from 2.4.x branch and following your
>> configuration files on github. I am almost sure that somewhere httpd sets
>> the Last-Modified header translating "foo" to the first Jan 1970 date. I
>> realized though that I didn't recall the real issue, since passing value
>> not following the RFC can lead to inconsistencies, so I went back and
>> checked the correspondence. Quoting:
>>
>> "Actually I wrote this snippet to highlight the behaviour (the original
>> code sent the date in iso8601 instead of rfc1123) because it was more
>> obvious.
>> During my tests (this is extracted from an automated test suite), even
>> after having converted dates to rfc1123, I continued to get some sparse
>> errors. What I got is that the value I sent was sometimes slightly modified
>> (a second or 2) depending on the machine load."
>>
>> So my understanding is that you would like to know why a Last-Modified
>> header with a legitimate date/time set by a PHP app gets "delayed" by a
>> couple of seconds from httpd, right?
>>
>
> Yes for sure, this is the primary issue.
> However, the (undocumented) difference of behavior from one version to
> another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
> also in question here.
> Even more strange, 2.4 built for other distrib doesn't highlight the
> behaviour !
>
>
I made another series of test and it seems to be linked to fastcgi.
I took the stock apache (2.4.6 plus tons of patches) & php-fpm (5.4.16 +
tons of patches) from RHEL7 and I get the exact same behaviour (headers
rewritten to EPOCH)
However, if I server the very same php script from mod_php (instead of
fcgi) it "works" (the headers are not modified).
Manuel
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano <to...@gmail.com> wrote:
>
> I was able to repro building httpd from 2.4.x branch and following your
> configuration files on github. I am almost sure that somewhere httpd sets
> the Last-Modified header translating "foo" to the first Jan 1970 date. I
> realized though that I didn't recall the real issue, since passing value
> not following the RFC can lead to inconsistencies, so I went back and
> checked the correspondence. Quoting:
>
> "Actually I wrote this snippet to highlight the behaviour (the original
> code sent the date in iso8601 instead of rfc1123) because it was more
> obvious.
> During my tests (this is extracted from an automated test suite), even
> after having converted dates to rfc1123, I continued to get some sparse
> errors. What I got is that the value I sent was sometimes slightly modified
> (a second or 2) depending on the machine load."
>
> So my understanding is that you would like to know why a Last-Modified
> header with a legitimate date/time set by a PHP app gets "delayed" by a
> couple of seconds from httpd, right?
>
Yes for sure, this is the primary issue.
However, the (undocumented) difference of behavior from one version to
another (2.2 -> 2.4 and more surprisingly from between two 2.4 versions) is
also in question here.
Even more strange, 2.4 built for other distrib doesn't highlight the
behaviour !
>
> The next step that I want to try is to add more logging in the C files
> where the Last-Modified header is set via apr_table_setn to narrow down the
> code responsible for this behavior (please everybody let me know if you
> have a better/smarter/etc idea :).
>
>
I built apache on my own with the same arguments from the redhat package
(and without any patches) and I got the error.
So, as far as I understand, this is the default behaviour of apache. The
question is now: why I don't get the bug on ubuntu or alpine ?
Manuel
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
2016-06-06 15:57 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
> On Mon, Jun 6, 2016 at 1:36 PM, Vacelet, Manuel <
> manuel.vacelet@enalean.com> wrote:
>
>> Hi Luca
>>
>> On Sat, Jun 4, 2016 at 4:54 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>> Can you post the list of modules that you have loaded plus your full
>>> httpd config (maybe you can upload them to the bug report)? Another think
>>> to try would be to use gdb and http -X to trace one process, but it might
>>> be overkill. You could also try to add trace-log specific prints in the
>>> httpd .c files where Last-Modified is changed to see if anything comes up,
>>> but again it might be very time consuming.
>>>
>>> I tried to repro on 2.4.20 but I wasn't able, so I took a look to
>>> https://www.apache.org/dist/httpd/CHANGES_2.4 to see if it was
>>> something corrected with 2.4.13 but I didn't see anything obvious. You also
>>> mentioned that there seem to be no distro specific patches applied to the
>>> httpd package, so the issue might be really difficult to track.
>>>
>>> Will try to check you docker image during the next days, maybe we can
>>> come up with something. In the meantime, is there any possibility to switch
>>> to a different httpd version (that works) to unblock you?
>>>
>>> Luca
>>>
>>>
>> I hoped there might be some "obvious" configuration stuff that might
>> affected the behaviour but it seems to be a very specific bug.
>> I don't know how to use gdb in this situation, if you have any hint, I
>> would be happy to give it a try.
>>
>> I will start by rebuilding the package without the patches to see where
>> the things starts to get bad.
>>
>>
> Hmm :/
> I rebuilt the package with all the patches (but one to adapt to
> RHEL/Fedora layout) removed and it still doesn't work.
>
>
I was able to repro building httpd from 2.4.x branch and following your
configuration files on github. I am almost sure that somewhere httpd sets
the Last-Modified header translating "foo" to the first Jan 1970 date. I
realized though that I didn't recall the real issue, since passing value
not following the RFC can lead to inconsistencies, so I went back and
checked the correspondence. Quoting:
"Actually I wrote this snippet to highlight the behaviour (the original
code sent the date in iso8601 instead of rfc1123) because it was more
obvious.
During my tests (this is extracted from an automated test suite), even
after having converted dates to rfc1123, I continued to get some sparse
errors. What I got is that the value I sent was sometimes slightly modified
(a second or 2) depending on the machine load."
So my understanding is that you would like to know why a Last-Modified
header with a legitimate date/time set by a PHP app gets "delayed" by a
couple of seconds from httpd, right?
The next step that I want to try is to add more logging in the C files
where the Last-Modified header is set via apr_table_setn to narrow down the
code responsible for this behavior (please everybody let me know if you
have a better/smarter/etc idea :).
Luca
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
On Mon, Jun 6, 2016 at 1:36 PM, Vacelet, Manuel <ma...@enalean.com>
wrote:
> Hi Luca
>
> On Sat, Jun 4, 2016 at 4:54 PM, Luca Toscano <to...@gmail.com>
> wrote:
>
>>
>> Can you post the list of modules that you have loaded plus your full
>> httpd config (maybe you can upload them to the bug report)? Another think
>> to try would be to use gdb and http -X to trace one process, but it might
>> be overkill. You could also try to add trace-log specific prints in the
>> httpd .c files where Last-Modified is changed to see if anything comes up,
>> but again it might be very time consuming.
>>
>> I tried to repro on 2.4.20 but I wasn't able, so I took a look to
>> https://www.apache.org/dist/httpd/CHANGES_2.4 to see if it was something
>> corrected with 2.4.13 but I didn't see anything obvious. You also mentioned
>> that there seem to be no distro specific patches applied to the httpd
>> package, so the issue might be really difficult to track.
>>
>> Will try to check you docker image during the next days, maybe we can
>> come up with something. In the meantime, is there any possibility to switch
>> to a different httpd version (that works) to unblock you?
>>
>> Luca
>>
>>
> I hoped there might be some "obvious" configuration stuff that might
> affected the behaviour but it seems to be a very specific bug.
> I don't know how to use gdb in this situation, if you have any hint, I
> would be happy to give it a try.
>
> I will start by rebuilding the package without the patches to see where
> the things starts to get bad.
>
>
Hmm :/
I rebuilt the package with all the patches (but one to adapt to RHEL/Fedora
layout) removed and it still doesn't work.
Re: [users@httpd] Last-Modified header overridden
Posted by "Vacelet, Manuel" <ma...@enalean.com>.
Hi Luca
On Sat, Jun 4, 2016 at 4:54 PM, Luca Toscano <to...@gmail.com> wrote:
>
> Can you post the list of modules that you have loaded plus your full httpd
> config (maybe you can upload them to the bug report)? Another think to try
> would be to use gdb and http -X to trace one process, but it might be
> overkill. You could also try to add trace-log specific prints in the httpd
> .c files where Last-Modified is changed to see if anything comes up, but
> again it might be very time consuming.
>
> I tried to repro on 2.4.20 but I wasn't able, so I took a look to
> https://www.apache.org/dist/httpd/CHANGES_2.4 to see if it was something
> corrected with 2.4.13 but I didn't see anything obvious. You also mentioned
> that there seem to be no distro specific patches applied to the httpd
> package, so the issue might be really difficult to track.
>
> Will try to check you docker image during the next days, maybe we can come
> up with something. In the meantime, is there any possibility to switch to a
> different httpd version (that works) to unblock you?
>
> Luca
>
>
I hoped there might be some "obvious" configuration stuff that might
affected the behaviour but it seems to be a very specific bug.
I don't know how to use gdb in this situation, if you have any hint, I
would be happy to give it a try.
I will start by rebuilding the package without the patches to see where the
things starts to get bad.
For what is worth, I tried with an updated version of the package (based on
2.4.18) and I got the same result. Here is the new trace:
[Mon Jun 06 11:32:41.663635 2016] [suexec:notice] [pid 55] AH01232: suEXEC
mechanism enabled (wrapper: /opt/rh/httpd24/root/usr/sbin/suexec)
[Mon Jun 06 11:32:41.671425 2016] [auth_digest:notice] [pid 56] AH01757:
generating secret for digest authentication ...
[Mon Jun 06 11:32:41.671568 2016] [http2:warn] [pid 56] AH02951: mod_ssl
does not seem to be enabled
[Mon Jun 06 11:32:41.672107 2016] [lbmethod_heartbeat:notice] [pid 56]
AH02282: No slotmem from mod_heartmonitor
[Mon Jun 06 11:32:41.674127 2016] [mpm_prefork:notice] [pid 56] AH00163:
Apache/2.4.18 (Red Hat) configured -- resuming normal operations
[Mon Jun 06 11:32:41.674150 2016] [core:notice] [pid 56] AH00094: Command
line: '/opt/rh/httpd24/root/usr/sbin/httpd'
[Mon Jun 06 11:32:41.676422 2016] [http2:trace1] [pid 58] h2_h2.c(596):
[client ::1:59372] h2_h2, process_conn
[Mon Jun 06 11:32:41.676473 2016] [core:trace5] [pid 58] protocol.c(616):
[client ::1:59372] Request received from client: GET /headers.php HTTP/1.1
[Mon Jun 06 11:32:41.676497 2016] [http:trace4] [pid 58]
http_request.c(394): [client ::1:59372] Headers received from client:
[Mon Jun 06 11:32:41.676501 2016] [http:trace4] [pid 58]
http_request.c(398): [client ::1:59372] User-Agent: curl/7.19.7
(x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC zlib/1.2.3
libidn/1.18 libssh2/1.4.2
[Mon Jun 06 11:32:41.676503 2016] [http:trace4] [pid 58]
http_request.c(398): [client ::1:59372] Host: localhost
[Mon Jun 06 11:32:41.676505 2016] [http:trace4] [pid 58]
http_request.c(398): [client ::1:59372] Accept: */*
[Mon Jun 06 11:32:41.676634 2016] [authz_core:debug] [pid 58]
mod_authz_core.c(809): [client ::1:59372] AH01626: authorization result of
Require all granted: granted
[Mon Jun 06 11:32:41.676644 2016] [authz_core:debug] [pid 58]
mod_authz_core.c(809): [client ::1:59372] AH01626: authorization result of
<RequireAny>: granted
[Mon Jun 06 11:32:41.676646 2016] [core:trace3] [pid 58] request.c(293):
[client ::1:59372] request authorized without authentication by
access_checker_ex hook: /headers.php
[Mon Jun 06 11:32:41.676718 2016] [proxy:trace2] [pid 58]
proxy_util.c(1989): [client ::1:59372] *: using default reverse proxy
worker for fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php (no keepalive)
[Mon Jun 06 11:32:41.676724 2016] [proxy:debug] [pid 58] mod_proxy.c(1160):
[client ::1:59372] AH01143: Running scheme fcgi handler (attempt 0)
[Mon Jun 06 11:32:41.676728 2016] [proxy_ajp:debug] [pid 58]
mod_proxy_ajp.c(738): [client ::1:59372] AH00894: declining URL fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
[Mon Jun 06 11:32:41.676731 2016] [proxy_fcgi:debug] [pid 58]
mod_proxy_fcgi.c(879): [client ::1:59372] AH01076: url: fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php proxyname:
(null) proxyport: 0
[Mon Jun 06 11:32:41.676734 2016] [proxy_fcgi:debug] [pid 58]
mod_proxy_fcgi.c(886): [client ::1:59372] AH01078: serving URL fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
[Mon Jun 06 11:32:41.676737 2016] [proxy:debug] [pid 58]
proxy_util.c(2160): AH00942: FCGI: has acquired connection for (*)
[Mon Jun 06 11:32:41.676743 2016] [proxy:debug] [pid 58]
proxy_util.c(2213): [client ::1:59372] AH00944: connecting fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php to
127.0.0.1:9000
[Mon Jun 06 11:32:41.676782 2016] [proxy:debug] [pid 58]
proxy_util.c(2422): [client ::1:59372] AH00947: connected
/opt/rh/httpd24/root/var/www/html/headers.php to 127.0.0.1:9000
[Mon Jun 06 11:32:41.676791 2016] [proxy:trace2] [pid 58]
proxy_util.c(2765): FCGI: fam 2 socket created to connect to *
[Mon Jun 06 11:32:41.676846 2016] [proxy:debug] [pid 58]
proxy_util.c(2799): AH02824: FCGI: connection established with
127.0.0.1:9000 (*)
[Mon Jun 06 11:32:41.676882 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'UNIQUE_ID' value 'AAAAAKxJoyMmnHek7RDFUQAAAAA'
[Mon Jun 06 11:32:41.676888 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'proxy-nokeepalive' value '1'
[Mon Jun 06 11:32:41.676895 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'HTTP_USER_AGENT' value 'curl/7.19.7 (x86_64-redhat-linux-gnu)
libcurl/7.19.7 NSS/3.19.1 Basic ECC zlib/1.2.3 libidn/1.18 libssh2/1.4.2'
[Mon Jun 06 11:32:41.676898 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'HTTP_HOST' value 'localhost'
[Mon Jun 06 11:32:41.676900 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'HTTP_ACCEPT' value '*/*'
[Mon Jun 06 11:32:41.676902 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var 'PATH'
value
'/opt/rh/httpd24/root/usr/bin:/opt/rh/httpd24/root/usr/sbin:/sbin:/usr/sbin:/bin:/usr/bin'
[Mon Jun 06 11:32:41.676904 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'LD_LIBRARY_PATH' value '/opt/rh/httpd24/root/usr/lib64'
[Mon Jun 06 11:32:41.676906 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_SIGNATURE' value ''
[Mon Jun 06 11:32:41.676908 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_SOFTWARE' value 'Apache/2.4.18 (Red Hat)'
[Mon Jun 06 11:32:41.676910 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_NAME' value 'localhost'
[Mon Jun 06 11:32:41.676912 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_ADDR' value '::1'
[Mon Jun 06 11:32:41.676914 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_PORT' value '80'
[Mon Jun 06 11:32:41.676916 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'REMOTE_ADDR' value '::1'
[Mon Jun 06 11:32:41.676918 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'DOCUMENT_ROOT' value '/opt/rh/httpd24/root/var/www/html'
[Mon Jun 06 11:32:41.676920 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'REQUEST_SCHEME' value 'http'
[Mon Jun 06 11:32:41.676922 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'CONTEXT_PREFIX' value ''
[Mon Jun 06 11:32:41.676924 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'CONTEXT_DOCUMENT_ROOT' value '/opt/rh/httpd24/root/var/www/html'
[Mon Jun 06 11:32:41.676926 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_ADMIN' value 'root@localhost'
[Mon Jun 06 11:32:41.676928 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SCRIPT_FILENAME' value 'proxy:fcgi://
127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php'
[Mon Jun 06 11:32:41.676930 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'REMOTE_PORT' value '59372'
[Mon Jun 06 11:32:41.676932 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'GATEWAY_INTERFACE' value 'CGI/1.1'
[Mon Jun 06 11:32:41.676934 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SERVER_PROTOCOL' value 'HTTP/1.1'
[Mon Jun 06 11:32:41.676936 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'REQUEST_METHOD' value 'GET'
[Mon Jun 06 11:32:41.676938 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'QUERY_STRING' value ''
[Mon Jun 06 11:32:41.676940 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'REQUEST_URI' value '/headers.php'
[Mon Jun 06 11:32:41.676942 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(294): [client ::1:59372] AH01062: sending env var
'SCRIPT_NAME' value '/headers.php'
[Mon Jun 06 11:32:41.677447 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(578): [client ::1:59372] FastCGI header (8 bytes)
[Mon Jun 06 11:32:41.677456 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(578): [client ::1:59372] .....W.. 0106000100570100
[Mon Jun 06 11:32:41.677462 2016] [proxy_fcgi:trace4] [pid 58]
util_script.c(544): [client ::1:59372] Headers from script 'headers.php':
[Mon Jun 06 11:32:41.677465 2016] [proxy_fcgi:trace4] [pid 58]
util_script.c(545): [client ::1:59372] X-Powered-By: PHP/5.6.5
[Mon Jun 06 11:32:41.677468 2016] [proxy_fcgi:trace4] [pid 58]
util_script.c(545): [client ::1:59372] Last-Modified: foo
[Mon Jun 06 11:32:41.677477 2016] [proxy_fcgi:trace4] [pid 58]
util_script.c(545): [client ::1:59372] Content-type: text/html;
charset=UTF-8
[Mon Jun 06 11:32:41.677483 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(578): [client ::1:59372] FastCGI header (8 bytes)
[Mon Jun 06 11:32:41.677485 2016] [proxy_fcgi:trace8] [pid 58]
mod_proxy_fcgi.c(578): [client ::1:59372] ........ 0103000100080000
[Mon Jun 06 11:32:41.677488 2016] [proxy:debug] [pid 58]
proxy_util.c(2175): AH00943: FCGI: has released connection for (*)
[Mon Jun 06 11:32:41.677523 2016] [http:trace3] [pid 58]
http_filters.c(1006): [client ::1:59372] Response sent with status 200,
headers:
[Mon Jun 06 11:32:41.677527 2016] [http:trace5] [pid 58]
http_filters.c(1013): [client ::1:59372] Date: Mon, 06 Jun 2016 11:32:41
GMT
[Mon Jun 06 11:32:41.677529 2016] [http:trace5] [pid 58]
http_filters.c(1016): [client ::1:59372] Server: Apache/2.4.18 (Red Hat)
[Mon Jun 06 11:32:41.677532 2016] [http:trace4] [pid 58]
http_filters.c(835): [client ::1:59372] X-Powered-By: PHP/5.6.5
[Mon Jun 06 11:32:41.677534 2016] [http:trace4] [pid 58]
http_filters.c(835): [client ::1:59372] Last-Modified: Thu, 01 Jan 1970
00:00:00 GMT
[Mon Jun 06 11:32:41.677536 2016] [http:trace4] [pid 58]
http_filters.c(835): [client ::1:59372] Content-Length: 0
[Mon Jun 06 11:32:41.677538 2016] [http:trace4] [pid 58]
http_filters.c(835): [client ::1:59372] Content-Type: text/html;
charset=UTF-8
[Mon Jun 06 11:32:41.677552 2016] [core:trace6] [pid 58]
core_filters.c(525): [client ::1:59372] core_output_filter: flushing
because of FLUSH bucket
[Mon Jun 06 11:32:41.677691 2016] [core:trace6] [pid 58]
core_filters.c(525): [client ::1:59372] core_output_filter: flushing
because of FLUSH bucket
Re: [users@httpd] Last-Modified header overridden
Posted by Luca Toscano <to...@gmail.com>.
Hi Manuel,
2016-06-03 9:53 GMT+02:00 Vacelet, Manuel <ma...@enalean.com>:
> Hi,
>
> Any insights from the logs, where can I look now ?
>
> On Tue, May 31, 2016 at 5:12 PM, Vacelet, Manuel <
> manuel.vacelet@enalean.com> wrote:
>
>>
>> On Tue, May 31, 2016 at 3:00 PM, Luca Toscano <to...@gmail.com>
>> wrote:
>>
>>>
>>> Another info that it would be great to know: have you tried to set logs
>>> to debug level to see if httpd can suggest you what it is doing?
>>>
>>> https://httpd.apache.org/docs/2.4/mod/core.html#loglevel
>>>
>>>
>> Good idea, with trace8 I get interesting results (I highlighted the
>> interesting parts):
>>
>> Starting php-fpm: [ OK ]
>> Starting httpd: [Tue May 31 15:08:38.074202 2016] [core:trace3] [pid 46]
>> core.c(3060): Setting LogLevel for all modules to trace8
>> AH00558: httpd: Could not reliably determine the server's fully qualified
>> domain name, using 172.17.42.7. Set the 'ServerName' directive globally to
>> suppress this message
>> [ OK ]
>> * About to connect() to localhost port 80 (#0)
>> * Trying ::1... connected
>> * Connected to localhost (::1) port 80 (#0)
>> > GET /headers.php HTTP/1.1
>> > User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7
>> NSS/3.19.1 Basic ECC zlib/1.2.3 libidn/1.18 libssh2/1.4.2
>> > Host: localhost
>> > Accept: */*
>> >
>> < HTTP/1.1 200 OK
>> < Date: Tue, 31 May 2016 15:08:38 GMT
>> < Server: Apache/2.4.12 (Red Hat)
>> < X-Powered-By: PHP/5.6.5
>> < Last-Modified: Thu, 01 Jan 1970 00:00:00 GMT
>> < Content-Length: 0
>> < Content-Type: text/html; charset=UTF-8
>> <
>> * Connection #0 to host localhost left intact
>> * Closing connection #0
>> [Tue May 31 15:08:38.075284 2016] [suexec:notice] [pid 46] AH01232:
>> suEXEC mechanism enabled (wrapper: /opt/rh/httpd24/root/usr/sbin/suexec)
>> [Tue May 31 15:08:38.082708 2016] [auth_digest:notice] [pid 47] AH01757:
>> generating secret for digest authentication ...
>> [Tue May 31 15:08:38.083440 2016] [lbmethod_heartbeat:notice] [pid 47]
>> AH02282: No slotmem from mod_heartmonitor
>> [Tue May 31 15:08:38.084944 2016] [mpm_prefork:notice] [pid 47] AH00163:
>> Apache/2.4.12 (Red Hat) configured -- resuming normal operations
>> [Tue May 31 15:08:38.084972 2016] [core:notice] [pid 47] AH00094: Command
>> line: '/opt/rh/httpd24/root/usr/sbin/httpd'
>> [Tue May 31 15:08:38.088052 2016] [core:trace5] [pid 49] protocol.c(618):
>> [client ::1:54638] Request received from client: GET /headers.php HTTP/1.1
>> [Tue May 31 15:08:38.088099 2016] [http:trace4] [pid 49]
>> http_request.c(301): [client ::1:54638] Headers received from client:
>> [Tue May 31 15:08:38.088105 2016] [http:trace4] [pid 49]
>> http_request.c(305): [client ::1:54638] User-Agent: curl/7.19.7
>> (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC zlib/1.2.3
>> libidn/1.18 libssh2/1.4.2
>> [Tue May 31 15:08:38.088109 2016] [http:trace4] [pid 49]
>> http_request.c(305): [client ::1:54638] Host: localhost
>> [Tue May 31 15:08:38.088112 2016] [http:trace4] [pid 49]
>> http_request.c(305): [client ::1:54638] Accept: */*
>> [Tue May 31 15:08:38.088292 2016] [authz_core:debug] [pid 49]
>> mod_authz_core.c(809): [client ::1:54638] AH01626: authorization result of
>> Require all granted: granted
>> [Tue May 31 15:08:38.088300 2016] [authz_core:debug] [pid 49]
>> mod_authz_core.c(809): [client ::1:54638] AH01626: authorization result of
>> <RequireAny>: granted
>> [Tue May 31 15:08:38.088303 2016] [core:trace3] [pid 49] request.c(293):
>> [client ::1:54638] request authorized without authentication by
>> access_checker_ex hook: /headers.php
>> [Tue May 31 15:08:38.088403 2016] [proxy:trace2] [pid 49]
>> proxy_util.c(1976): [client ::1:54638] *: using default reverse proxy
>> worker for fcgi://
>> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php (no
>> keepalive)
>> [Tue May 31 15:08:38.088410 2016] [proxy:debug] [pid 49]
>> mod_proxy.c(1163): [client ::1:54638] AH01143: Running scheme fcgi handler
>> (attempt 0)
>> [Tue May 31 15:08:38.088418 2016] [proxy_ajp:debug] [pid 49]
>> mod_proxy_ajp.c(710): [client ::1:54638] AH00894: declining URL fcgi://
>> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
>> [Tue May 31 15:08:38.088426 2016] [proxy_fcgi:debug] [pid 49]
>> mod_proxy_fcgi.c(861): [client ::1:54638] AH01076: url: fcgi://
>> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php proxyname:
>> (null) proxyport: 0
>> [Tue May 31 15:08:38.088430 2016] [proxy_fcgi:debug] [pid 49]
>> mod_proxy_fcgi.c(868): [client ::1:54638] AH01078: serving URL fcgi://
>> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php
>> [Tue May 31 15:08:38.088433 2016] [proxy:debug] [pid 49]
>> proxy_util.c(2140): AH00942: FCGI: has acquired connection for (*)
>> [Tue May 31 15:08:38.088442 2016] [proxy:debug] [pid 49]
>> proxy_util.c(2193): [client ::1:54638] AH00944: connecting fcgi://
>> 127.0.0.1:9000/opt/rh/httpd24/root/var/www/html/headers.php to
>> 127.0.0.1:9000
>> [Tue May 31 15:08:38.088503 2016] [proxy:debug] [pid 49]
>> proxy_util.c(2394): [client ::1:54638] AH00947: connected
>> /opt/rh/httpd24/root/var/www/html/headers.php to 127.0.0.1:9000
>> [Tue May 31 15:08:38.088517 2016] [proxy:trace2] [pid 49]
>> proxy_util.c(2737): FCGI: fam 2 socket created to connect to *
>> [Tue May 31 15:08:38.088586 2016] [proxy:debug] [pid 49]
>> proxy_util.c(2771): AH02824: FCGI: connection established with
>> 127.0.0.1:9000 (*)
>> *[Tue May 31 15:08:38.089143 2016 <089143%202016>] [proxy_fcgi:trace4]
>> [pid 49] util_script.c(522): [client ::1:54638] Headers from script
>> 'headers.php':*
>> [Tue May 31 15:08:38.089157 2016] [proxy_fcgi:trace4] [pid 49]
>> util_script.c(523): [client ::1:54638] X-Powered-By: PHP/5.6.5
>> *[Tue May 31 15:08:38.089161 2016 <089161%202016>] [proxy_fcgi:trace4]
>> [pid 49] util_script.c(523): [client ::1:54638] Last-Modified: foo*
>> [Tue May 31 15:08:38.089174 2016] [proxy_fcgi:trace4] [pid 49]
>> util_script.c(523): [client ::1:54638] Content-type: text/html;
>> charset=UTF-8
>> [Tue May 31 15:08:38.089192 2016] [proxy:debug] [pid 49]
>> proxy_util.c(2155): AH00943: FCGI: has released connection for (*)
>> [Tue May 31 15:08:38.089241 2016] [http:trace3] [pid 49]
>> http_filters.c(1006): [client ::1:54638] Response sent with status 200,
>> headers:
>> [Tue May 31 15:08:38.089246 2016] [http:trace5] [pid 49]
>> http_filters.c(1013): [client ::1:54638] Date: Tue, 31 May 2016 15:08:38
>> GMT
>> [Tue May 31 15:08:38.089248 2016] [http:trace5] [pid 49]
>> http_filters.c(1016): [client ::1:54638] Server: Apache/2.4.12 (Red Hat)
>> [Tue May 31 15:08:38.089250 2016] [http:trace4] [pid 49]
>> http_filters.c(835): [client ::1:54638] X-Powered-By: PHP/5.6.5
>> *[Tue May 31 15:08:38.089252 2016 <089252%202016>] [http:trace4] [pid 49]
>> http_filters.c(835): [client ::1:54638] Last-Modified: Thu, 01 Jan 1970
>> 00:00:00 GMT*
>> [Tue May 31 15:08:38.089255 2016] [http:trace4] [pid 49]
>> http_filters.c(835): [client ::1:54638] Content-Length: 0
>> [Tue May 31 15:08:38.089257 2016] [http:trace4] [pid 49]
>> http_filters.c(835): [client ::1:54638] Content-Type: text/html;
>> charset=UTF-8
>> [Tue May 31 15:08:38.089274 2016] [core:trace6] [pid 49]
>> core_filters.c(527): [client ::1:54638] core_output_filter: flushing
>> because of FLUSH bucket
>> [Tue May 31 15:08:38.089463 2016] [core:trace6] [pid 49]
>> core_filters.c(527): [client ::1:54638] core_output_filter: flushing
>> because of FLUSH bucket
>>
>>
Can you post the list of modules that you have loaded plus your full httpd
config (maybe you can upload them to the bug report)? Another think to try
would be to use gdb and http -X to trace one process, but it might be
overkill. You could also try to add trace-log specific prints in the httpd
.c files where Last-Modified is changed to see if anything comes up, but
again it might be very time consuming.
I tried to repro on 2.4.20 but I wasn't able, so I took a look to
https://www.apache.org/dist/httpd/CHANGES_2.4 to see if it was something
corrected with 2.4.13 but I didn't see anything obvious. You also mentioned
that there seem to be no distro specific patches applied to the httpd
package, so the issue might be really difficult to track.
Will try to check you docker image during the next days, maybe we can come
up with something. In the meantime, is there any possibility to switch to a
different httpd version (that works) to unblock you?
Luca