Re: Last-Modified header overridden (Apache Users)

Hi Manuel,

2016-06-03 9:53 GMT+02:00 Vacelet, Manuel <manuel.vacelet@xxxxxxxxxxx>:

Hi,

Any insights from the logs, where can I look now ?

On Tue, May 31, 2016 at 5:12 PM, Vacelet, Manuel <manuel.vacelet@xxxxxxxxxxx> wrote:

On Tue, May 31, 2016 at 3:00 PM, Luca Toscano <toscano.luca@xxxxxxxxx> 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

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