2016-07-01 16:53 GMT+02:00 Vacelet, Manuel <manuel.vace...@enalean.com>:
> > > On Fri, Jul 1, 2016 at 4:14 PM, Luca Toscano <toscano.l...@gmail.com> > wrote: > >> >> >> 2016-06-29 9:38 GMT+02:00 Luca Toscano <toscano.l...@gmail.com>: >> >>> >>> >>> 2016-06-28 18:32 GMT+02:00 Luca Toscano <toscano.l...@gmail.com>: >>> >>>> >>>> >>>> 2016-06-27 14:52 GMT+02:00 Vacelet, Manuel <manuel.vace...@enalean.com> >>>> : >>>> >>>>> >>>>> >>>>> On Mon, Jun 27, 2016 at 2:17 PM, Luca Toscano <toscano.l...@gmail.com> >>>>> wrote: >>>>> >>>>>> >>>>>> >>>>>> 2016-06-27 13:17 GMT+02:00 Vacelet, Manuel < >>>>>> manuel.vace...@enalean.com>: >>>>>> >>>>>>> >>>>>>> >>>>>>> On Sat, Jun 25, 2016 at 11:00 AM, Luca Toscano < >>>>>>> toscano.l...@gmail.com> wrote: >>>>>>> >>>>>>>> >>>>>>>> >>>>>>>> 2016-06-24 17:26 GMT+02:00 Vacelet, Manuel < >>>>>>>> manuel.vace...@enalean.com>: >>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> On Sun, Jun 19, 2016 at 3:17 PM, Luca Toscano < >>>>>>>>> toscano.l...@gmail.com> wrote: >>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> 2016-06-08 16:14 GMT+02:00 Vacelet, Manuel < >>>>>>>>>> manuel.vace...@enalean.com>: >>>>>>>>>> >>>>>>>>>>> On Tue, Jun 7, 2016 at 11:02 PM, Luca Toscano < >>>>>>>>>>> toscano.l...@gmail.com> wrote: >>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> 2016-06-07 10:55 GMT+02:00 Vacelet, Manuel < >>>>>>>>>>>> manuel.vace...@enalean.com>: >>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> On Mon, Jun 6, 2016 at 5:32 PM, Vacelet, Manuel < >>>>>>>>>>>>> manuel.vace...@enalean.com> wrote: >>>>>>>>>>>>> >>>>>>>>>>>>>> dOn Mon, Jun 6, 2016 at 5:00 PM, Vacelet, Manuel < >>>>>>>>>>>>>> manuel.vace...@enalean.com> wrote: >>>>>>>>>>>>>> >>>>>>>>>>>>>>> On Mon, Jun 6, 2016 at 4:09 PM, Luca Toscano < >>>>>>>>>>>>>>> toscano.l...@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!
