Re: Last-Modified header overridden

["Vacelet, Manuel" <manuel.vacelet@xxxxxxxxxxx>]

Hi Luca

On Sat, Jun 4, 2016 at 4:54 PM, Luca Toscano <toscano.luca@xxxxxxxxx> 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