Bug 59815

Summary: different behaviour between 2.4.20 and 2.4.23 using php as cgi with mod_rewrite and parameters sent as get
Product: Apache httpd-2 Reporter: m.gebauer
Component: mod_rewriteAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED FIXED    
Severity: blocker CC: Francis.Asselin, jchampion
Priority: P2 Keywords: FixedInTrunk
Version: 2.4.23   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description m.gebauer 2016-07-07 05:25:19 UTC
Apache 2.4 build with

#! /bin/sh
#
# Created by configure

"./configure" \
"--prefix=/usr/local/apache24" \
"--enable-so" \
"--enable-rewrite" \
"--enable-deflate" \
"--enable-headers" \
"--enable-proxy-fcgi" \
"--with-included-apr" \
"--enable-ssl" \
"$@"


Vhost-Configuration:
Listen 10163
<VirtualHost *:10163>
    ServerName <domain>
    ServerAdmin <mail>
    DocumentRoot /path/to/docroot

    <Directory /path/to/docroot>
      Require all granted
      RewriteEngine On
      RewriteOptions InheritBefore
      RewriteRule ^.*\.php(/.*)?$ fcgi://127.0.0.1:20155/path/to/docroot/$0 [L,P]

      CGIPassAuth On

      AllowOverride All
      FallbackResource /index.php
      DirectoryIndex index.php
    </Directory>
</VirtualHost>


on 2.4.20: http://domain.com/index.php?p=1 -> everything ok
on 2.4.23: http://domain.com/index.php?p=1 -> results in a "file not found" returnd from the fcgi-process.

missed i changes to be made in the configuration?
Comment 1 Eric Covener 2016-07-07 11:32:15 UTC
Can you post LogLevel trace8 of a request going through the system? I think proxy_fcgi will log the envvars it passes to the fcgi script.

Is the recipient php-fpm?
Comment 2 m.gebauer 2016-07-07 12:11:42 UTC
Yes, recipient is php-fpm.

Configuration is:
::::::::::::::
/www/config_php70_fpm/8080_test.pool
::::::::::::::
[www_8080]
  user = nobody
  group = nobody
  listen = 127.0.0.1:18080
  listen.allowed_clients = 127.0.0.1
  pm = ondemand
  pm.max_children = 10
  pm.process_idle_timeout = 30s
  pm.max_requests = 500
  php_flag[display_errors] = on
  catch_workers_output = yes


::::::::::::::
/www/config_php70_fpm/php-fpm.conf
::::::::::::::
[global]
  pid = /var/run/php70-fpm.pid
  log_level = notice
  error_log = /logs/apache/apache_virtuell/php70-fpm-error.log
  emergency_restart_threshold = 0
  emergency_restart_interval = 0
  process_control_timeout = 0
  daemonize = yes
  include=/www/config_php70_fpm/*.pool


In the Apache-Logs i get:

[root@md-ito-ws1 apache_virtuell]# more access_test.log
127.0.0.1 - - [07/Jul/2016:14:08:25 +0200] "GET /index.php?p=1 HTTP/1.1" 404 16 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:45.0)
 Gecko/20100101 Firefox/45.0"


[root@md-ito-ws1 apache_virtuell]# more error.log
[Thu Jul 07 14:08:12.474305 2016] [ssl:trace2] [pid 26348:tid 139681470736128] ssl_engine_rand.c(126): Init: Seeding PRNG with 0 bytes of entropy
[Thu Jul 07 14:08:12.474345 2016] [ssl:info] [pid 26348:tid 139681470736128] AH01887: Init: Initializing (virtual) servers for SSL
[Thu Jul 07 14:08:12.474353 2016] [ssl:info] [pid 26348:tid 139681470736128] AH01876: mod_ssl/2.4.23 compiled against Server: Apache/2.4.23, Library: OpenSSL/1.0.1e
[Thu Jul 07 14:08:12.482683 2016] [ssl:trace2] [pid 26349:tid 139681470736128] ssl_engine_rand.c(126): Init: Seeding PRNG with 0 bytes of entropy
[Thu Jul 07 14:08:12.482810 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(401): AH00821: shmcb_init allocated 128000 bytes of shared memory
[Thu Jul 07 14:08:12.482822 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(417): AH00822: for 127912 bytes (128000 including header), recommending 4 subcaches, 21 indexes each
[Thu Jul 07 14:08:12.482829 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(450): AH00824: shmcb_init_memory choices follow
[Thu Jul 07 14:08:12.482833 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(452): AH00825: subcache_num = 4
[Thu Jul 07 14:08:12.482838 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(454): AH00826: subcache_size = 31976
[Thu Jul 07 14:08:12.482843 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(456): AH00827: subcache_data_offset = 520
[Thu Jul 07 14:08:12.482847 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(458): AH00828: subcache_data_size = 31456
[Thu Jul 07 14:08:12.482852 2016] [socache_shmcb:debug] [pid 26349:tid 139681470736128] mod_socache_shmcb.c(460): AH00829: index_num = 21
[Thu Jul 07 14:08:12.482866 2016] [socache_shmcb:info] [pid 26349:tid 139681470736128] AH00830: Shared memory socache initialised
[Thu Jul 07 14:08:12.482871 2016] [ssl:warn] [pid 26349:tid 139681470736128] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Thu Jul 07 14:08:12.482882 2016] [ssl:info] [pid 26349:tid 139681470736128] AH01887: Init: Initializing (virtual) servers for SSL
[Thu Jul 07 14:08:12.482897 2016] [ssl:info] [pid 26349:tid 139681470736128] AH01876: mod_ssl/2.4.23 compiled against Server: Apache/2.4.23, Library: OpenSSL/1.0.1e
[Thu Jul 07 14:08:12.483528 2016] [core:trace4] [pid 26349:tid 139681470736128] mpm_common.c(533): mpm child 26351 (gen 0/slot 0) started
[Thu Jul 07 14:08:12.483793 2016] [core:trace4] [pid 26349:tid 139681470736128] mpm_common.c(533): mpm child 26352 (gen 0/slot 1) started
[Thu Jul 07 14:08:12.483964 2016] [proxy:debug] [pid 26351:tid 139681470736128] proxy_util.c(1779): AH00925: initializing worker proxy:reverse shared
[Thu Jul 07 14:08:12.483999 2016] [proxy:debug] [pid 26351:tid 139681470736128] proxy_util.c(1821): AH00927: initializing worker proxy:reverse local
[Thu Jul 07 14:08:12.484048 2016] [core:trace4] [pid 26349:tid 139681470736128] mpm_common.c(533): mpm child 26353 (gen 0/slot 2) started
[Thu Jul 07 14:08:12.484053 2016] [proxy:debug] [pid 26351:tid 139681470736128] proxy_util.c(1856): AH00930: initialized pool in child 26351 for (*) min=0 max=25 smax=25
[Thu Jul 07 14:08:12.484062 2016] [mpm_event:notice] [pid 26349:tid 139681470736128] AH00489: Apache/2.4.23 (Unix) OpenSSL/1.0.1e-fips configured -- resuming normal operations
[Thu Jul 07 14:08:12.484070 2016] [mpm_event:info] [pid 26349:tid 139681470736128] AH00490: Server built: Jul  7 2016 07:23:05
[Thu Jul 07 14:08:12.484093 2016] [core:notice] [pid 26349:tid 139681470736128] AH00094: Command line: '/usr/local/apache24/bin/httpd'
[Thu Jul 07 14:08:12.484098 2016] [core:debug] [pid 26349:tid 139681470736128] log.c(1546): AH02639: Using SO_REUSEPORT: yes (1)
[Thu Jul 07 14:08:12.484169 2016] [mpm_event:debug] [pid 26351:tid 139681408624384] event.c(2095): AH02471: start_threads: Using epoll
[Thu Jul 07 14:08:12.484193 2016] [proxy:debug] [pid 26352:tid 139681470736128] proxy_util.c(1779): AH00925: initializing worker proxy:reverse shared
[Thu Jul 07 14:08:12.484214 2016] [proxy:debug] [pid 26352:tid 139681470736128] proxy_util.c(1821): AH00927: initializing worker proxy:reverse local
[Thu Jul 07 14:08:12.484237 2016] [proxy:debug] [pid 26352:tid 139681470736128] proxy_util.c(1856): AH00930: initialized pool in child 26352 for (*) min=0 max=25 smax=25
[Thu Jul 07 14:08:12.484300 2016] [proxy:debug] [pid 26353:tid 139681470736128] proxy_util.c(1779): AH00925: initializing worker proxy:reverse shared
[Thu Jul 07 14:08:12.484311 2016] [mpm_event:debug] [pid 26352:tid 139681408624384] event.c(2095): AH02471: start_threads: Using epoll
[Thu Jul 07 14:08:12.484318 2016] [proxy:debug] [pid 26353:tid 139681470736128] proxy_util.c(1821): AH00927: initializing worker proxy:reverse local
[Thu Jul 07 14:08:12.484342 2016] [proxy:debug] [pid 26353:tid 139681470736128] proxy_util.c(1856): AH00930: initialized pool in child 26353 for (*) min=0 max=25 smax=25
[Thu Jul 07 14:08:12.484404 2016] [mpm_event:debug] [pid 26353:tid 139681408624384] event.c(2095): AH02471: start_threads: Using epoll
[Thu Jul 07 14:08:13.486355 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:13.486424 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:13.486455 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:14.487817 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:14.487860 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:14.487880 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:15.489193 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:15.489208 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:15.489240 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:16.490450 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:16.490451 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:16.490568 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:17.491668 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:17.491743 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:17.491876 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:18.493083 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:18.493083 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:18.493195 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:19.494492 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:19.494492 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:19.494492 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:20.495832 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:20.495825 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:20.495832 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:21.497179 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:21.497179 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:21.497179 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:22.498626 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:22.498626 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:22.498626 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:23.500121 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:23.500121 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:23.500121 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:24.501647 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:24.501647 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:24.501647 2016] [mpm_event:trace6] [pid 26352:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:25.137528 2016] [core:trace5] [pid 26352:tid 139681329051392] protocol.c(616): [client 127.0.0.1:48850] Request received from client: GET /index.php?p=1 HTTP/1.1
[Thu Jul 07 14:08:25.137587 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(394): [client 127.0.0.1:48850] Headers received from client:
[Thu Jul 07 14:08:25.137599 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Host: 127.0.0.1:8080
[Thu Jul 07 14:08:25.137602 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0
[Thu Jul 07 14:08:25.137605 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
[Thu Jul 07 14:08:25.137608 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Accept-Language: de
[Thu Jul 07 14:08:25.137610 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Accept-Encoding: gzip, deflate
[Thu Jul 07 14:08:25.137612 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Cookie: _pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.1449736616.
[Thu Jul 07 14:08:25.137615 2016] [http:trace4] [pid 26352:tid 139681329051392] http_request.c(398): [client 127.0.0.1:48850]   Connection: keep-alive
[Thu Jul 07 14:08:25.137700 2016] [authz_core:debug] [pid 26352:tid 139681329051392] mod_authz_core.c(809): [client 127.0.0.1:48850] AH01626: authorization result of Require all granted: granted
[Thu Jul 07 14:08:25.137706 2016] [authz_core:debug] [pid 26352:tid 139681329051392] mod_authz_core.c(809): [client 127.0.0.1:48850] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 07 14:08:25.137709 2016] [core:trace3] [pid 26352:tid 139681329051392] request.c(293): [client 127.0.0.1:48850] request authorized without authentication by access_checker_ex hook: /index.php
[Thu Jul 07 14:08:25.137728 2016] [rewrite:trace3] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] strip per-dir prefix: /
www/test/htdocs/index.php -> index.php
[Thu Jul 07 14:08:25.137733 2016] [rewrite:trace3] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] applying pattern '^.*\\
.php(/.*)?$' to uri 'index.php'
[Thu Jul 07 14:08:25.137756 2016] [rewrite:trace2] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] rewrite 'index.php' ->
'fcgi://127.0.0.1:18080/www/test/htdocs/index.php'
[Thu Jul 07 14:08:25.137764 2016] [rewrite:trace2] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] escaped URI in per-dir
context for proxy, fcgi://127.0.0.1:18080/www/test/htdocs/index.php -> fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:08:25.137768 2016] [rewrite:trace2] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] forcing proxy-throughpu
t with fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:08:25.137772 2016] [rewrite:trace1] [pid 26352:tid 139681329051392] mod_rewrite.c(477): [client 127.0.0.1:48850] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00002970/initial] [perdir /www/test/htdocs/] go-ahead with proxy req
uest proxy:fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 [OK]
[Thu Jul 07 14:08:25.137792 2016] [proxy:trace2] [pid 26352:tid 139681329051392] proxy_util.c(1985): [client 127.0.0.1:48850] *: using default reverse proxy worker for fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 (no keepalive)
[Thu Jul 07 14:08:25.137797 2016] [proxy:debug] [pid 26352:tid 139681329051392] mod_proxy.c(1200): [client 127.0.0.1:48850] AH01143: Running scheme fcgi handler (attempt 0)
[Thu Jul 07 14:08:25.137804 2016] [proxy_fcgi:debug] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(899): [client 127.0.0.1:48850] AH01076: url: fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 proxyname: (null) proxyport: 0
[Thu Jul 07 14:08:25.137812 2016] [proxy_fcgi:debug] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(906): [client 127.0.0.1:48850] AH01078: serving URL fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1
[Thu Jul 07 14:08:25.137821 2016] [proxy:debug] [pid 26352:tid 139681329051392] proxy_util.c(2156): AH00942: FCGI: has acquired connection for (*)
[Thu Jul 07 14:08:25.137829 2016] [proxy:debug] [pid 26352:tid 139681329051392] proxy_util.c(2209): [client 127.0.0.1:48850] AH00944: connecting fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 to 127.0.0.1:18080
[Thu Jul 07 14:08:25.137874 2016] [proxy:debug] [pid 26352:tid 139681329051392] proxy_util.c(2418): [client 127.0.0.1:48850] AH00947: connected /www/test/htdocs/index.php?p=1 to 127.0.0.1:18080
[Thu Jul 07 14:08:25.137885 2016] [proxy:trace2] [pid 26352:tid 139681329051392] proxy_util.c(2777): FCGI: fam 2 socket created to connect to *
[Thu Jul 07 14:08:25.137920 2016] [proxy:debug] [pid 26352:tid 139681329051392] proxy_util.c(2811): AH02824: FCGI: connection established with 127.0.0.1:18080 (*)
[Thu Jul 07 14:08:25.137963 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'proxy-nokeepalive' value '1'
[Thu Jul 07 14:08:25.137967 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_HOST' value '127.0.0.1:8080'
[Thu Jul 07 14:08:25.137970 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_USER_AGENT' value 'Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/201001
01 Firefox/45.0'
[Thu Jul 07 14:08:25.137972 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_ACCEPT' value 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*
;q=0.8'
[Thu Jul 07 14:08:25.137975 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_ACCEPT_LANGUAGE' value 'de'
[Thu Jul 07 14:08:25.137977 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_ACCEPT_ENCODING' value 'gzip, deflate'
[Thu Jul 07 14:08:25.137979 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_COOKIE' value '_pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.14
49736616.'
[Thu Jul 07 14:08:25.137981 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'HTTP_CONNECTION' value 'keep-alive'
[Thu Jul 07 14:08:25.137984 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'PATH' value '/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:
/usr/sbin:/usr/bin:/root/bin'
[Thu Jul 07 14:08:25.137986 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'LD_LIBRARY_PATH' value '/usr/local/apache24/lib'
[Thu Jul 07 14:08:25.137988 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_SIGNATURE' value ''
[Thu Jul 07 14:08:25.137990 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_SOFTWARE' value 'Apache'
[Thu Jul 07 14:08:25.137993 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_NAME' value 'test'
[Thu Jul 07 14:08:25.137995 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_ADDR' value '127.0.0.1'
[Thu Jul 07 14:08:25.138000 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_PORT' value '80'
[Thu Jul 07 14:08:25.138002 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'REMOTE_ADDR' value '127.0.0.1'
[Thu Jul 07 14:08:25.138004 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:08:25.138007 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'REQUEST_SCHEME' value 'http'
[Thu Jul 07 14:08:25.138009 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'CONTEXT_PREFIX' value ''
[Thu Jul 07 14:08:25.138011 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'CONTEXT_DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:08:25.138013 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_ADMIN' value 'webmaster@falk.de'
[Thu Jul 07 14:08:25.138015 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SCRIPT_FILENAME' value '/www/test/htdocs/index.php?p=1'
[Thu Jul 07 14:08:25.138017 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'REMOTE_PORT' value '48850'
[Thu Jul 07 14:08:25.138020 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'GATEWAY_INTERFACE' value 'CGI/1.1'
[Thu Jul 07 14:08:25.138022 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SERVER_PROTOCOL' value 'HTTP/1.1'
[Thu Jul 07 14:08:25.138024 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'REQUEST_METHOD' value 'GET'
[Thu Jul 07 14:08:25.138026 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'QUERY_STRING' value 'p=1'
[Thu Jul 07 14:08:25.138028 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'REQUEST_URI' value '/index.php?p=1'
[Thu Jul 07 14:08:25.138030 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(304): [client 127.0.0.1:48850] AH01062: sending env var 'SCRIPT_NAME' value '/index.php'
[Thu Jul 07 14:08:25.140256 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] FastCGI header (8 bytes)
[Thu Jul 07 14:08:25.140312 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] ........         0107000100170100
[Thu Jul 07 14:08:25.140320 2016] [proxy_fcgi:error] [pid 26352:tid 139681329051392] [client 127.0.0.1:48850] AH01071: Got error 'Primary script unknown\n'
[Thu Jul 07 14:08:25.140325 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] FastCGI header (8 bytes)
[Thu Jul 07 14:08:25.140327 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] .....j..         01060001006a0600
[Thu Jul 07 14:08:25.140342 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681329051392] util_script.c(563): [client 127.0.0.1:48850] Headers from script 'index.php?p=1':
[Thu Jul 07 14:08:25.140345 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681329051392] util_script.c(564): [client 127.0.0.1:48850]   Status: 404 Not Found
[Thu Jul 07 14:08:25.140357 2016] [proxy_fcgi:trace1] [pid 26352:tid 139681329051392] util_script.c(645): [client 127.0.0.1:48850] Status line from script 'index.php?p=1': 404 Not Found
[Thu Jul 07 14:08:25.140361 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681329051392] util_script.c(564): [client 127.0.0.1:48850]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:08:25.140365 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681329051392] util_script.c(564): [client 127.0.0.1:48850]   Content-type: text/html; charset=UTF-8
[Thu Jul 07 14:08:25.140396 2016] [http:trace3] [pid 26352:tid 139681329051392] http_filters.c(1006): [client 127.0.0.1:48850] Response sent with status 404, headers:
[Thu Jul 07 14:08:25.140400 2016] [http:trace5] [pid 26352:tid 139681329051392] http_filters.c(1013): [client 127.0.0.1:48850]   Date: Thu, 07 Jul 2016 12:08:25 GMT
[Thu Jul 07 14:08:25.140402 2016] [http:trace5] [pid 26352:tid 139681329051392] http_filters.c(1016): [client 127.0.0.1:48850]   Server: Apache
[Thu Jul 07 14:08:25.140405 2016] [http:trace4] [pid 26352:tid 139681329051392] http_filters.c(835): [client 127.0.0.1:48850]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:08:25.140407 2016] [http:trace4] [pid 26352:tid 139681329051392] http_filters.c(835): [client 127.0.0.1:48850]   Connection: close
[Thu Jul 07 14:08:25.140409 2016] [http:trace4] [pid 26352:tid 139681329051392] http_filters.c(835): [client 127.0.0.1:48850]   Transfer-Encoding: chunked
[Thu Jul 07 14:08:25.140412 2016] [http:trace4] [pid 26352:tid 139681329051392] http_filters.c(835): [client 127.0.0.1:48850]   Content-Type: text/html; charset=UTF-8
[Thu Jul 07 14:08:25.140429 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] FastCGI header (8 bytes)
[Thu Jul 07 14:08:25.140432 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681329051392] mod_proxy_fcgi.c(588): [client 127.0.0.1:48850] ........         0103000100080000
[Thu Jul 07 14:08:25.140436 2016] [proxy:debug] [pid 26352:tid 139681329051392] proxy_util.c(2171): AH00943: FCGI: has released connection for (*)
[Thu Jul 07 14:08:25.140513 2016] [core:trace6] [pid 26352:tid 139681329051392] core_filters.c(525): [client 127.0.0.1:48850] core_output_filter: flushing because of FLUSH bucket
[Thu Jul 07 14:08:25.537969 2016] [mpm_event:trace6] [pid 26351:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:08:25.537969 2016] [mpm_event:trace6] [pid 26353:tid 139681066804992] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
Comment 3 m.gebauer 2016-07-07 12:15:26 UTC
oh, please don't be irritated by the different port of the fcgi-proxy - i set up a new, dedicated test-system to reproduce the failure instead of crashing our real develoment-system and i don't want to irritate our internal web-developers...
Comment 4 m.gebauer 2016-07-07 12:22:33 UTC
without the ?p=1 in the request i get:

[Thu Jul 07 14:21:33.325972 2016] [core:trace5] [pid 26352:tid 139681318561536] protocol.c(616): [client 127.0.0.1:51568] Request received from client: GET /index.php HTTP/1.1
[Thu Jul 07 14:21:33.326024 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(394): [client 127.0.0.1:51568] Headers received from client:
[Thu Jul 07 14:21:33.326041 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Host: 127.0.0.1:8080
[Thu Jul 07 14:21:33.326047 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0
[Thu Jul 07 14:21:33.326053 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
[Thu Jul 07 14:21:33.326060 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Accept-Language: de
[Thu Jul 07 14:21:33.326066 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Accept-Encoding: gzip, deflate
[Thu Jul 07 14:21:33.326071 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Cookie: _pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.1449736616.
[Thu Jul 07 14:21:33.326077 2016] [http:trace4] [pid 26352:tid 139681318561536] http_request.c(398): [client 127.0.0.1:51568]   Connection: keep-alive
[Thu Jul 07 14:21:33.326120 2016] [authz_core:debug] [pid 26352:tid 139681318561536] mod_authz_core.c(809): [client 127.0.0.1:51568] AH01626: authorization result of Require all granted: granted
[Thu Jul 07 14:21:33.326130 2016] [authz_core:debug] [pid 26352:tid 139681318561536] mod_authz_core.c(809): [client 127.0.0.1:51568] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 07 14:21:33.326136 2016] [core:trace3] [pid 26352:tid 139681318561536] request.c(293): [client 127.0.0.1:51568] request authorized without authentication by access_checker_ex hook: /index.php
[Thu Jul 07 14:21:33.326150 2016] [rewrite:trace3] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] strip per-dir prefix: /www/test/htdocs/index.php -> index.php
[Thu Jul 07 14:21:33.326158 2016] [rewrite:trace3] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] applying pattern '^.*\\.php(/.*)?$' to uri 'index.php'
[Thu Jul 07 14:21:33.326173 2016] [rewrite:trace2] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] rewrite 'index.php' -> 'fcgi://127.0.0.1:18080/www/test/htdocs/index.php'
[Thu Jul 07 14:21:33.326182 2016] [rewrite:trace2] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] escaped URI in per-dir context for proxy, fcgi://127.0.0.1:18080/www/test/htdocs/index.php -> fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:21:33.326190 2016] [rewrite:trace2] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] forcing proxy-throughput with fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:21:33.326198 2016] [rewrite:trace1] [pid 26352:tid 139681318561536] mod_rewrite.c(477): [client 127.0.0.1:51568] 127.0.0.1 - - [test/sid#1f85d48][rid#7f0a00004980/initial] [perdir /www/test/htdocs/] go-ahead with proxy request proxy:fcgi://127.0.0.1:18080/www/test/htdocs/index.php [OK]
[Thu Jul 07 14:21:33.326213 2016] [proxy:trace2] [pid 26352:tid 139681318561536] proxy_util.c(1985): [client 127.0.0.1:51568] *: using default reverse proxy worker for fcgi://127.0.0.1:18080/www/test/htdocs/index.php (no keepalive)
[Thu Jul 07 14:21:33.326220 2016] [proxy:debug] [pid 26352:tid 139681318561536] mod_proxy.c(1200): [client 127.0.0.1:51568] AH01143: Running scheme fcgi handler (attempt 0)
[Thu Jul 07 14:21:33.326227 2016] [proxy_fcgi:debug] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(899): [client 127.0.0.1:51568] AH01076: url: fcgi://127.0.0.1:18080/www/test/htdocs/index.php proxyname: (null) proxyport: 0
[Thu Jul 07 14:21:33.326237 2016] [proxy_fcgi:debug] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(906): [client 127.0.0.1:51568] AH01078: serving URL fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:21:33.326246 2016] [proxy:debug] [pid 26352:tid 139681318561536] proxy_util.c(2156): AH00942: FCGI: has acquired connection for (*)
[Thu Jul 07 14:21:33.326254 2016] [proxy:debug] [pid 26352:tid 139681318561536] proxy_util.c(2209): [client 127.0.0.1:51568] AH00944: connecting fcgi://127.0.0.1:18080/www/test/htdocs/index.php to 127.0.0.1:18080
[Thu Jul 07 14:21:33.326306 2016] [proxy:debug] [pid 26352:tid 139681318561536] proxy_util.c(2418): [client 127.0.0.1:51568] AH00947: connected /www/test/htdocs/index.php to 127.0.0.1:18080
[Thu Jul 07 14:21:33.326320 2016] [proxy:trace2] [pid 26352:tid 139681318561536] proxy_util.c(2777): FCGI: fam 2 socket created to connect to *
[Thu Jul 07 14:21:33.326354 2016] [proxy:debug] [pid 26352:tid 139681318561536] proxy_util.c(2811): AH02824: FCGI: connection established with 127.0.0.1:18080 (*)
[Thu Jul 07 14:21:33.326391 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'proxy-nokeepalive' value '1'
[Thu Jul 07 14:21:33.326396 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_HOST' value '127.0.0.1:8080'
[Thu Jul 07 14:21:33.326398 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_USER_AGENT' value 'Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0'
[Thu Jul 07 14:21:33.326401 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_ACCEPT' value 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
[Thu Jul 07 14:21:33.326404 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_ACCEPT_LANGUAGE' value 'de'
[Thu Jul 07 14:21:33.326407 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_ACCEPT_ENCODING' value 'gzip, deflate'
[Thu Jul 07 14:21:33.326410 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_COOKIE' value '_pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.1449736616.'
[Thu Jul 07 14:21:33.326412 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'HTTP_CONNECTION' value 'keep-alive'
[Thu Jul 07 14:21:33.326416 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'PATH' value '/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin'
[Thu Jul 07 14:21:33.326421 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'LD_LIBRARY_PATH' value '/usr/local/apache24/lib'
[Thu Jul 07 14:21:33.326425 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_SIGNATURE' value ''
[Thu Jul 07 14:21:33.326430 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_SOFTWARE' value 'Apache'
[Thu Jul 07 14:21:33.326434 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_NAME' value 'test'
[Thu Jul 07 14:21:33.326438 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_ADDR' value '127.0.0.1'
[Thu Jul 07 14:21:33.326447 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_PORT' value '80'
[Thu Jul 07 14:21:33.326452 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'REMOTE_ADDR' value '127.0.0.1'
[Thu Jul 07 14:21:33.326455 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:21:33.326458 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'REQUEST_SCHEME' value 'http'
[Thu Jul 07 14:21:33.326461 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'CONTEXT_PREFIX' value ''
[Thu Jul 07 14:21:33.326464 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'CONTEXT_DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:21:33.326469 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_ADMIN' value 'webmaster@falk.de'
[Thu Jul 07 14:21:33.326473 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SCRIPT_FILENAME' value '/www/test/htdocs/index.php'
[Thu Jul 07 14:21:33.326478 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'REMOTE_PORT' value '51568'
[Thu Jul 07 14:21:33.326482 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'GATEWAY_INTERFACE' value 'CGI/1.1'
[Thu Jul 07 14:21:33.326486 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SERVER_PROTOCOL' value 'HTTP/1.1'
[Thu Jul 07 14:21:33.326491 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'REQUEST_METHOD' value 'GET'
[Thu Jul 07 14:21:33.326495 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'QUERY_STRING' value ''
[Thu Jul 07 14:21:33.326499 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'REQUEST_URI' value '/index.php'
[Thu Jul 07 14:21:33.326503 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(304): [client 127.0.0.1:51568] AH01062: sending env var 'SCRIPT_NAME' value '/index.php'
[Thu Jul 07 14:21:33.329729 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] FastCGI header (8 bytes)
[Thu Jul 07 14:21:33.329773 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] .....C..         0106000100430500
[Thu Jul 07 14:21:33.329788 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681318561536] util_script.c(563): [client 127.0.0.1:51568] Headers from script 'index.php':
[Thu Jul 07 14:21:33.329797 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681318561536] util_script.c(564): [client 127.0.0.1:51568]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:21:33.329805 2016] [proxy_fcgi:trace4] [pid 26352:tid 139681318561536] util_script.c(564): [client 127.0.0.1:51568]   Content-type: text/html; charset=UTF-8
[Thu Jul 07 14:21:33.329820 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] FastCGI header (8 bytes)
[Thu Jul 07 14:21:33.329828 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] ........         01060001fff80000
[Thu Jul 07 14:21:33.329850 2016] [filter:trace4] [pid 26352:tid 139681318561536] mod_filter.c(169): [client 127.0.0.1:51568] Content-Type 'text/html; charset=UTF-8' ...
[Thu Jul 07 14:21:33.329867 2016] [filter:trace4] [pid 26352:tid 139681318561536] mod_filter.c(175): [client 127.0.0.1:51568] ... matched 'text/html'
[Thu Jul 07 14:21:33.329874 2016] [filter:trace2] [pid 26352:tid 139681318561536] mod_filter.c(188): [client 127.0.0.1:51568] Content-Type condition for 'deflate' matched
[Thu Jul 07 14:21:33.331818 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] FastCGI header (8 bytes)
[Thu Jul 07 14:21:33.331840 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] ....a...         0106000161c80000
[Thu Jul 07 14:21:33.333061 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] FastCGI header (8 bytes)
[Thu Jul 07 14:21:33.333076 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] ........         0106000100040400
[Thu Jul 07 14:21:33.333089 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] FastCGI header (8 bytes)
[Thu Jul 07 14:21:33.333096 2016] [proxy_fcgi:trace8] [pid 26352:tid 139681318561536] mod_proxy_fcgi.c(588): [client 127.0.0.1:51568] ........         0103000100080000
[Thu Jul 07 14:21:33.333105 2016] [proxy:debug] [pid 26352:tid 139681318561536] proxy_util.c(2171): AH00943: FCGI: has released connection for (*)
[Thu Jul 07 14:21:33.333675 2016] [deflate:debug] [pid 26352:tid 139681318561536] mod_deflate.c(853): [client 127.0.0.1:51568] AH01384: Zlib: Compressed 90564 to 23297 : URL /index.php
[Thu Jul 07 14:21:33.333749 2016] [http:trace3] [pid 26352:tid 139681318561536] http_filters.c(1006): [client 127.0.0.1:51568] Response sent with status 200, headers:
[Thu Jul 07 14:21:33.333762 2016] [http:trace5] [pid 26352:tid 139681318561536] http_filters.c(1013): [client 127.0.0.1:51568]   Date: Thu, 07 Jul 2016 12:21:33 GMT
[Thu Jul 07 14:21:33.333769 2016] [http:trace5] [pid 26352:tid 139681318561536] http_filters.c(1016): [client 127.0.0.1:51568]   Server: Apache
[Thu Jul 07 14:21:33.333777 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:21:33.333785 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   Vary: Accept-Encoding
[Thu Jul 07 14:21:33.333791 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   Content-Encoding: gzip
[Thu Jul 07 14:21:33.333798 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   Content-Length: 23315
[Thu Jul 07 14:21:33.333804 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   Connection: close
[Thu Jul 07 14:21:33.333811 2016] [http:trace4] [pid 26352:tid 139681318561536] http_filters.c(835): [client 127.0.0.1:51568]   Content-Type: text/html; charset=UTF-8
[Thu Jul 07 14:21:33.333906 2016] [core:trace6] [pid 26352:tid 139681318561536] core_filters.c(525): [client 127.0.0.1:51568] core_output_filter: flushing because of FLUSH bucket
Comment 5 m.gebauer 2016-07-07 12:27:39 UTC
After swiching back to 2.4.20 i get:

[Thu Jul 07 14:26:28.520445 2016] [mpm_event:trace6] [pid 32341:tid 140442819520256] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
[Thu Jul 07 14:26:29.109053 2016] [core:trace5] [pid 32339:tid 140443071276800] protocol.c(616): [client 127.0.0.1:52428] Request received from client: GET /index.php?p=1 HTTP/1.1
[Thu Jul 07 14:26:29.109110 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(394): [client 127.0.0.1:52428] Headers received from client:
[Thu Jul 07 14:26:29.109114 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Host: 127.0.0.1:8080
[Thu Jul 07 14:26:29.109116 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0
[Thu Jul 07 14:26:29.109119 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
[Thu Jul 07 14:26:29.109121 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Accept-Language: de
[Thu Jul 07 14:26:29.109124 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Accept-Encoding: gzip, deflate
[Thu Jul 07 14:26:29.109126 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Cookie: _pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.1449736616.
[Thu Jul 07 14:26:29.109128 2016] [http:trace4] [pid 32339:tid 140443071276800] http_request.c(398): [client 127.0.0.1:52428]   Connection: keep-alive
[Thu Jul 07 14:26:29.109191 2016] [authz_core:debug] [pid 32339:tid 140443071276800] mod_authz_core.c(809): [client 127.0.0.1:52428] AH01626: authorization result of Require all granted: granted
[Thu Jul 07 14:26:29.109202 2016] [authz_core:debug] [pid 32339:tid 140443071276800] mod_authz_core.c(809): [client 127.0.0.1:52428] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 07 14:26:29.109205 2016] [core:trace3] [pid 32339:tid 140443071276800] request.c(293): [client 127.0.0.1:52428] request authorized without authentication by access_checker_ex hook: /index.php
[Thu Jul 07 14:26:29.109222 2016] [rewrite:trace3] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] strip per-dir prefix: /w
ww/test/htdocs/index.php -> index.php
[Thu Jul 07 14:26:29.109226 2016] [rewrite:trace3] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] applying pattern '^.*\\.
php(/.*)?$' to uri 'index.php'
[Thu Jul 07 14:26:29.109249 2016] [rewrite:trace2] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] rewrite 'index.php' -> '
fcgi://127.0.0.1:18080/www/test/htdocs/index.php'
[Thu Jul 07 14:26:29.109256 2016] [rewrite:trace2] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] escaped URI in per-dir c
ontext for proxy, fcgi://127.0.0.1:18080/www/test/htdocs/index.php -> fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:26:29.109261 2016] [rewrite:trace2] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] forcing proxy-throughput
 with fcgi://127.0.0.1:18080/www/test/htdocs/index.php
[Thu Jul 07 14:26:29.109265 2016] [rewrite:trace1] [pid 32339:tid 140443071276800] mod_rewrite.c(477): [client 127.0.0.1:52428] 127.0.0.1 - - [test/sid#9be240][rid#7fbb5c002970/initial] [perdir /www/test/htdocs/] go-ahead with proxy requ
est proxy:fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 [OK]
[Thu Jul 07 14:26:29.109280 2016] [proxy:trace2] [pid 32339:tid 140443071276800] proxy_util.c(1989): [client 127.0.0.1:52428] *: using default reverse proxy worker for fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 (no keepalive)
[Thu Jul 07 14:26:29.109285 2016] [proxy:debug] [pid 32339:tid 140443071276800] mod_proxy.c(1161): [client 127.0.0.1:52428] AH01143: Running scheme fcgi handler (attempt 0)
[Thu Jul 07 14:26:29.109295 2016] [proxy_fcgi:debug] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(889): [client 127.0.0.1:52428] AH01076: url: fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 proxyname: (null) proxyport: 0
[Thu Jul 07 14:26:29.109300 2016] [proxy_fcgi:debug] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(896): [client 127.0.0.1:52428] AH01078: serving URL fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1
[Thu Jul 07 14:26:29.109309 2016] [proxy:debug] [pid 32339:tid 140443071276800] proxy_util.c(2160): AH00942: FCGI: has acquired connection for (*)
[Thu Jul 07 14:26:29.109316 2016] [proxy:debug] [pid 32339:tid 140443071276800] proxy_util.c(2213): [client 127.0.0.1:52428] AH00944: connecting fcgi://127.0.0.1:18080/www/test/htdocs/index.php?p=1 to 127.0.0.1:18080
[Thu Jul 07 14:26:29.109352 2016] [proxy:debug] [pid 32339:tid 140443071276800] proxy_util.c(2422): [client 127.0.0.1:52428] AH00947: connected /www/test/htdocs/index.php?p=1 to 127.0.0.1:18080
[Thu Jul 07 14:26:29.109360 2016] [proxy:trace2] [pid 32339:tid 140443071276800] proxy_util.c(2779): FCGI: fam 2 socket created to connect to *
[Thu Jul 07 14:26:29.109387 2016] [proxy:debug] [pid 32339:tid 140443071276800] proxy_util.c(2813): AH02824: FCGI: connection established with 127.0.0.1:18080 (*)
[Thu Jul 07 14:26:29.109422 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'proxy-nokeepalive' value '1'
[Thu Jul 07 14:26:29.109429 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_HOST' value '127.0.0.1:8080'
[Thu Jul 07 14:26:29.109432 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_USER_AGENT' value 'Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/201001
01 Firefox/45.0'
[Thu Jul 07 14:26:29.109434 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_ACCEPT' value 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*
;q=0.8'
[Thu Jul 07 14:26:29.109437 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_ACCEPT_LANGUAGE' value 'de'
[Thu Jul 07 14:26:29.109439 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_ACCEPT_ENCODING' value 'gzip, deflate'
[Thu Jul 07 14:26:29.109441 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_COOKIE' value '_pk_id.1.dc78=b7daed5ca0191bda.1449736616.1.1449736824.14
49736616.'
[Thu Jul 07 14:26:29.109443 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'HTTP_CONNECTION' value 'keep-alive'
[Thu Jul 07 14:26:29.109446 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'PATH' value '/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:
/usr/sbin:/usr/bin:/root/bin'
[Thu Jul 07 14:26:29.109448 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'LD_LIBRARY_PATH' value '/usr/local/apache24/lib'
[Thu Jul 07 14:26:29.109450 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_SIGNATURE' value ''
[Thu Jul 07 14:26:29.109453 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_SOFTWARE' value 'Apache'
[Thu Jul 07 14:26:29.109456 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_NAME' value 'test'
[Thu Jul 07 14:26:29.109458 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_ADDR' value '127.0.0.1'
[Thu Jul 07 14:26:29.109460 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_PORT' value '80'
[Thu Jul 07 14:26:29.109462 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'REMOTE_ADDR' value '127.0.0.1'
[Thu Jul 07 14:26:29.109464 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:26:29.109466 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'REQUEST_SCHEME' value 'http'
[Thu Jul 07 14:26:29.109469 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'CONTEXT_PREFIX' value ''
[Thu Jul 07 14:26:29.109471 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'CONTEXT_DOCUMENT_ROOT' value '/www/test/htdocs'
[Thu Jul 07 14:26:29.109473 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_ADMIN' value 'webmaster@falk.de'
[Thu Jul 07 14:26:29.109478 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SCRIPT_FILENAME' value 'proxy:fcgi://127.0.0.1:18080/www/test/htdocs/index.ph
p?p=1'
[Thu Jul 07 14:26:29.109480 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'REMOTE_PORT' value '52428'
[Thu Jul 07 14:26:29.109482 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'GATEWAY_INTERFACE' value 'CGI/1.1'
[Thu Jul 07 14:26:29.109484 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SERVER_PROTOCOL' value 'HTTP/1.1'
[Thu Jul 07 14:26:29.109486 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'REQUEST_METHOD' value 'GET'
[Thu Jul 07 14:26:29.109489 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'QUERY_STRING' value 'p=1'
[Thu Jul 07 14:26:29.109491 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'REQUEST_URI' value '/index.php?p=1'
[Thu Jul 07 14:26:29.109493 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(294): [client 127.0.0.1:52428] AH01062: sending env var 'SCRIPT_NAME' value '/index.php'
[Thu Jul 07 14:26:29.119147 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] FastCGI header (8 bytes)
[Thu Jul 07 14:26:29.119186 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] .....C..         0106000100430500
[Thu Jul 07 14:26:29.119206 2016] [proxy_fcgi:trace4] [pid 32339:tid 140443071276800] util_script.c(550): [client 127.0.0.1:52428] Headers from script 'index.php?p=1':
[Thu Jul 07 14:26:29.119212 2016] [proxy_fcgi:trace4] [pid 32339:tid 140443071276800] util_script.c(551): [client 127.0.0.1:52428]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:26:29.119219 2016] [proxy_fcgi:trace4] [pid 32339:tid 140443071276800] util_script.c(551): [client 127.0.0.1:52428]   Content-type: text/html; charset=UTF-8
[Thu Jul 07 14:26:29.119232 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] FastCGI header (8 bytes)
[Thu Jul 07 14:26:29.119235 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] ........         01060001fff80000
[Thu Jul 07 14:26:29.119241 2016] [filter:trace4] [pid 32339:tid 140443071276800] mod_filter.c(169): [client 127.0.0.1:52428] Content-Type 'text/html; charset=UTF-8' ...
[Thu Jul 07 14:26:29.119246 2016] [filter:trace4] [pid 32339:tid 140443071276800] mod_filter.c(175): [client 127.0.0.1:52428] ... matched 'text/html'
[Thu Jul 07 14:26:29.119248 2016] [filter:trace2] [pid 32339:tid 140443071276800] mod_filter.c(188): [client 127.0.0.1:52428] Content-Type condition for 'deflate' matched
[Thu Jul 07 14:26:29.120279 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] FastCGI header (8 bytes)
[Thu Jul 07 14:26:29.120286 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] ....b8..         0106000162380000
[Thu Jul 07 14:26:29.120829 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] FastCGI header (8 bytes)
[Thu Jul 07 14:26:29.120834 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] ........         0106000100060200
[Thu Jul 07 14:26:29.120846 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] FastCGI header (8 bytes)
[Thu Jul 07 14:26:29.120849 2016] [proxy_fcgi:trace8] [pid 32339:tid 140443071276800] mod_proxy_fcgi.c(578): [client 127.0.0.1:52428] ........         0103000100080000
[Thu Jul 07 14:26:29.120853 2016] [proxy:debug] [pid 32339:tid 140443071276800] proxy_util.c(2175): AH00943: FCGI: has released connection for (*)
[Thu Jul 07 14:26:29.121119 2016] [deflate:debug] [pid 32339:tid 140443071276800] mod_deflate.c(853): [client 127.0.0.1:52428] AH01384: Zlib: Compressed 90678 to 23323 : URL /index.php
[Thu Jul 07 14:26:29.121160 2016] [http:trace3] [pid 32339:tid 140443071276800] http_filters.c(1006): [client 127.0.0.1:52428] Response sent with status 200, headers:
[Thu Jul 07 14:26:29.121164 2016] [http:trace5] [pid 32339:tid 140443071276800] http_filters.c(1013): [client 127.0.0.1:52428]   Date: Thu, 07 Jul 2016 12:26:29 GMT
[Thu Jul 07 14:26:29.121167 2016] [http:trace5] [pid 32339:tid 140443071276800] http_filters.c(1016): [client 127.0.0.1:52428]   Server: Apache
[Thu Jul 07 14:26:29.121172 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   X-Powered-By: PHP/7.0.8
[Thu Jul 07 14:26:29.121175 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   Vary: Accept-Encoding
[Thu Jul 07 14:26:29.121177 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   Content-Encoding: gzip
[Thu Jul 07 14:26:29.121180 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   Content-Length: 23341
[Thu Jul 07 14:26:29.121182 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   Connection: close
[Thu Jul 07 14:26:29.121184 2016] [http:trace4] [pid 32339:tid 140443071276800] http_filters.c(835): [client 127.0.0.1:52428]   Content-Type: text/html; charset=UTF-8
[Thu Jul 07 14:26:29.121251 2016] [core:trace6] [pid 32339:tid 140443071276800] core_filters.c(525): [client 127.0.0.1:52428] core_output_filter: flushing because of FLUSH bucket
[Thu Jul 07 14:26:29.521748 2016] [mpm_event:trace6] [pid 32340:tid 140442819520256] event.c(1586): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)
Comment 6 m.gebauer 2016-07-07 12:40:45 UTC
Do you need more information?
Comment 7 Eric Covener 2016-07-07 13:47:08 UTC
(In reply to m.gebauer from comment #6)
> Do you need more information?

In this release the proxy:fcgi prefix is stripped before sending down to php-fpm. I am assuming php-fpm used to see proxy:fcgi then do other fixups like removing what looked like a query string.  Meanwhile, this type of config has presumably always put the query string in the SCRIPT_FILENAME.

I may not be able to test today, but I would be curious if it happens outside of <Directory> and/or with a trailing ? on the substitution (making sure the query string does show up in the FCGI)
Comment 8 Eric Covener 2016-07-07 14:56:47 UTC
(In reply to Eric Covener from comment #7)
> (In reply to m.gebauer from comment #6)
> > Do you need more information?
> 
> In this release the proxy:fcgi prefix is stripped before sending down to
> php-fpm. I am assuming php-fpm used to see proxy:fcgi then do other fixups
> like removing what looked like a query string.  Meanwhile, this type of
> config has presumably always put the query string in the SCRIPT_FILENAME.
> 
> I may not be able to test today, but I would be curious if it happens
> outside of <Directory> and/or with a trailing ? on the substitution (making
> sure the query string does show up in the FCGI)

I was able to sneak in a test.  It only affects per-directory rewrite. I think this patch fixes it by stripping r->args off of r->filename.

http://people.apache.org/~covener/patches/proxy-fcgi-perdir-rewrite-query.diff
Comment 9 Eric Covener 2016-07-08 21:52:43 UTC
proposed for 2.4.x http://svn.apache.org/viewvc?view=revision&revision=1751970
Comment 10 m.gebauer 2016-07-12 10:38:21 UTC
(In reply to Eric Covener from comment #9)
> proposed for 2.4.x
> http://svn.apache.org/viewvc?view=revision&revision=1751970

thank you a lot for the fast response.

works on my test-system, no side-effects found so far.
Comment 11 Trent Lloyd 2016-07-19 06:05:32 UTC
Some extra info for those finding this bug and wanting to work around the issue


Was having this same issue, working on 2.4.20 but broken on 2.4.23.

Same setup, php-fpm using mod_proxy_fcgi.  In my specific case, the problem was two sets of htaccess rules one in the DOCUMENT_ROOT and one in DOCUMENT_ROOT/subdir.  The DOCUMENT_ROOT worked fine but the subdir was broken.

Rule in both directories was more or less as follows and is a fairly standard set used by most applications, including Joomla (parent was joomla, subdir was not)

RewriteEngine on
RewriteCond $1 !^(index\.php|resources|robots\.txt|Sitemap\.xml)
RewriteCond %{REQUEST_FILENAME} !-f
RewriteCond %{REQUEST_FILENAME} !-d
RewriteRule ^(.*)$ index.php/$1 [L,QSA]


Since my use case has no control over the applications, I opted to downgrade now but found that using FallbackResource instead worked the same but avoided the bug.

Seems this is the more modern preferred option but most people aren't using it for compatibility I assume (https://httpd.apache.org/docs/2.4/mod/mod_dir.html#fallbackresource)

FallBackResource index.php
Comment 12 Trent Lloyd 2016-07-19 06:13:19 UTC
Simple test setup for anyone wanting to reproduce.

System: Ubuntu 16.04 xenial with 2.4.23-1+deb.sury.org~xenial+1 fromppa:onrej/apache2 (https://launchpad.net/~ondrej/+archive/ubuntu/apache2) -- also works on trusty, just need to modify the fpm socket path

apt-get install apache2 php7.0-fpm
a2enmod proxy proxy_fcgi rewrite
# after setting up the below 3 files/directoryes, then systemctl restart apache2

root@xenial:/var/www/html/subdir# cat /etc/apache2/sites-enabled/000-default.conf 
<VirtualHost *:80>
  LogLevel alert rewrite:trace3
  ServerAdmin webmaster@localhost
  DocumentRoot /var/www/html
  ErrorLog ${APACHE_LOG_DIR}/error.log
  CustomLog ${APACHE_LOG_DIR}/access.log combined
  <FilesMatch "\.php$">
    SetHandler  "proxy:unix:/run/php/php7.0-fpm.sock|fcgi://"
  </FilesMatch>
  <Directory /var/www/html>
  AllowOverride All
  </Directory>
</VirtualHost>

# vim: syntax=apache ts=4 sw=4 sts=4 sr noet
root@xenial:/var/www/html/subdir# cat .htaccess 
RewriteEngine on
RewriteCond %{REQUEST_FILENAME} !-f
RewriteCond %{REQUEST_FILENAME} !-d
RewriteRule ^(.*)$ index.php/$1 [L,QSA]

root@xenial:/var/www/html/subdir# cat index.php 
<?= phpinfo(); ?>
Comment 13 Jacob Champion 2016-07-19 17:52:40 UTC
(In reply to Trent Lloyd from comment #12)
> Simple test setup for anyone wanting to reproduce.

Trent,

Thanks for the information. I can't reproduce any problems with .htaccess rewrites using your configuration (httpd 2.4.23, Ubuntu 16.04, php7-fpm). Your issue may different. What is the "broken" behavior you're seeing?
Comment 14 nathanjosiah 2016-07-22 16:23:03 UTC
I can confirm this error as well after upgrading from apache 2.4.20. I am running Apache 2.4.23 and php-fpm 5.6.23

----------------------
This is my fpm config:

<FilesMatch "\.php$">
        SetHandler "proxy:unix:/tmp/fpm.sock|fcgi://"
</FilesMatch>

---------------------
And my .htaccess:

RewriteCond %{REQUEST_FILENAME} !-f
RewriteCond %{REQUEST_FILENAME} !-d
RewriteCond %{REQUEST_FILENAME} !-l
RewriteRule (.*) index.php/$1 [L]

---------------------
When requesting /foobar I get a "Primary script unknown" error from fpm but when I request /index.php/foobar I get the correct behavior. So this does seem to be related to mod_rewrite's interaction with fgci.

Is there a workaround for this?
Comment 15 Trent Lloyd 2016-10-21 06:30:57 UTC
I see keywords FixedInTrunk but no comments in the bug history.

This appears to have been fixed with the following commit, but does not appear to have made it into a release yet.  For those using ondrej's apache2 PPA, the patch was backported on October 6 into 2.4.23-5.0

I won't mark this RESOLVED as I am not sure if that is supposed to be done before a release is made / the general way that works here.  But feel free if/when that makes sense.

https://github.com/apache/httpd/commit/e8448d869f1a41fd051715a7e90906c774e0a923

commit e8448d869f1a41fd051715a7e90906c774e0a923
Author: Eric Covener <covener@apache.org>
Date:   Fri Jul 8 21:49:47 2016 +0000

    PR59815: rewrite per-directory + fcgi broken in 2.4.23
    
    remove the query string from r->filename before calculating environment
    (SCRIPT_FILENAME) in mod_proxy_fcgi.  Before PR59618, php-fpm would
    see proxy:fcgi:// and do some of this same stripping.    
    
    git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1751970 13f79535-47bb-0310-9956-ffa450edef68
Comment 16 Eric Covener 2016-12-31 00:20:51 UTC
Fixed in 2.4.25