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