Bug 53305

Summary: 404 errors when adding query string in a balancer setup with mod_rewrite and mod_proxy_fcgi
Product: Apache httpd-2 Reporter: Joshua Rusch <jdr>
Component: mod_rewriteAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: normal    
Priority: P2    
Version: 2.4.1   
Target Milestone: ---   
Hardware: PC   
OS: Windows NT   

Description Joshua Rusch 2012-05-28 03:23:26 UTC
I seem to be encountering an issue when trying to use mod_proxy_fcgi in a balancer setup via mod_rewrite.

With this rewrite rule:

RewriteRule ^/?(.*\.php(/.*)?)$ fcgi://localhost:9000/usr/local/home/magento/app/current/$1 [P,L]

Everything behaves as expected.

With this:

<Proxy balancer://magento>
    BalancerMember fcgi://localhost:9000
</Proxy>

RewriteRule ^/?(.*\.php(/.*)?)$ balancer://magento/usr/local/home/magento/app/current/$1 [P,L]

I get 404s when adding query strings to the page name. I used wireshark to look at the requests, here are some headers worth noting:

URL requested is /testq.php?test=test

NO BALANCER (working)

SCRIPT_FILENAMEproxy:fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php
QUERY_STRINGtest=test
REQUEST_URI/testq.php?test=test
SCRIPT_NAME/testq.php3

BALANCER (not working)

SCRIPT_FILENAMEproxy:balancer://magento/usr/local/home/magento/app/current/testq.php?test=test
QUERY_STRINGtest=test
REQUEST_URI/testq.php?test=test
SCRIPT_NAME 
PATH_INFO/usr/local/home/magento/app/current/testq.php
PATH_TRANSLATEDproxy:balancer://magento/usr/local/home/magento/app/current/usr/local/home/magento/app/current/testq.php/usr/local/home/magento/app/current/usr/local/home/magento/app/current/testq.php

This COULD be related to issue https://issues.apache.org/bugzilla/show_bug.cgi?id=51077 but I'm not positive. That PATH_TRANSLATED looks a bit funky, is that right?


-----------------
Here are some output from logs as well. First, mod_proxy_fcgi

NO BALANCER:

[Mon May 28 01:59:01.528602 2012] [proxy_fcgi:trace1] [pid 32007:tid 140105644062464] mod_proxy_fcgi.c(90): [client xxx.xxx.xxx.xxx:50665] canonicalising URL //localhost:9000/usr/local/home/magento/app/current/testq.php
[Mon May 28 01:59:01.528713 2012] [proxy_fcgi:debug] [pid 32007:tid 140105644062464] mod_proxy_fcgi.c(120): [client xxx.xxx.xxx.xxx:50665] AH01060: set r->filename to proxy:fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php
[Mon May 28 01:59:01.528806 2012] [proxy_fcgi:debug] [pid 32007:tid 140105644062464] mod_proxy_fcgi.c(944): [client xxx.xxx.xxx.xxx:50665] AH01076: url: fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php proxyname: (null) proxyport: 0
[Mon May 28 01:59:01.528827 2012] [proxy_fcgi:debug] [pid 32007:tid 140105644062464] mod_proxy_fcgi.c(954): [client xxx.xxx.xxx.xxx:50665] AH01078: serving URL //localhost:9000/usr/local/home/magento/app/current/testq.php
[Mon May 28 01:59:01.530348 2012] [proxy_fcgi:trace4] [pid 32007:tid 140105644062464] util_script.c(521): [client xxx.xxx.xxx.xxx:50665] Headers from script 'testq.php':
[Mon May 28 01:59:01.530414 2012] [proxy_fcgi:trace4] [pid 32007:tid 140105644062464] util_script.c(522): [client xxx.xxx.xxx.xxx:50665]   X-Powered-By: PHP/5.4.3
[Mon May 28 01:59:01.530464 2012] [proxy_fcgi:trace4] [pid 32007:tid 140105644062464] util_script.c(522): [client xxx.xxx.xxx.xxx:50665]   Content-type: text/html

BALANCER:

[Mon May 28 01:58:03.480149 2012] [proxy_fcgi:debug] [pid 31905:tid 140545336473344] mod_proxy_fcgi.c(944): [client xxx.xxx.xxx.xxx:50664] AH01076: url: fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php?test=test proxyname: (null) proxyport: 0
[Mon May 28 01:58:03.480315 2012] [proxy_fcgi:debug] [pid 31905:tid 140545336473344] mod_proxy_fcgi.c(954): [client xxx.xxx.xxx.xxx:50664] AH01078: serving URL //localhost:9000/usr/local/home/magento/app/current/testq.php?test=test
[Mon May 28 01:58:03.481519 2012] [proxy_fcgi:trace4] [pid 31905:tid 140545336473344] util_script.c(521): [client xxx.xxx.xxx.xxx:50664] Headers from script 'testq.php?test=test':
[Mon May 28 01:58:03.481584 2012] [proxy_fcgi:trace4] [pid 31905:tid 140545336473344] util_script.c(522): [client xxx.xxx.xxx.xxx:50664]   Status: 404 Not Found
[Mon May 28 01:58:03.481631 2012] [proxy_fcgi:trace1] [pid 31905:tid 140545336473344] util_script.c(599): [client xxx.xxx.xxx.xxx:50664] Status line from script 'testq.php?test=test': Status
[Mon May 28 01:58:03.481674 2012] [proxy_fcgi:trace4] [pid 31905:tid 140545336473344] util_script.c(522): [client xxx.xxx.xxx.xxx:50664]   X-Powered-By: PHP/5.4.3
[Mon May 28 01:58:03.481717 2012] [proxy_fcgi:trace4] [pid 31905:tid 140545336473344] util_script.c(522): [client xxx.xxx.xxx.xxx:50664]   Content-type: text/html


------------------
Here is a sample from mod_rewrite w logging turned up. It looks like rules are running twice in the balancer setup. Is that normal?

NO BALANCER:
[Mon May 28 02:03:08.125553 2012] [rewrite:trace2] [pid 32127:tid 139957454014208] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50680] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f4a729be458][rid#7f4a48002970/initial] init rewrite engine with requested uri /testq.php
[Mon May 28 02:03:08.125650 2012] [rewrite:trace3] [pid 32127:tid 139957454014208] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50680] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f4a729be458][rid#7f4a48002970/initial] applying pattern '^/?(.*\\.php(/.*)?)$' to uri '/testq.php'
[Mon May 28 02:03:08.125699 2012] [rewrite:trace2] [pid 32127:tid 139957454014208] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50680] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f4a729be458][rid#7f4a48002970/initial] rewrite '/testq.php' -> 'fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php'
[Mon May 28 02:03:08.125722 2012] [rewrite:trace2] [pid 32127:tid 139957454014208] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50680] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f4a729be458][rid#7f4a48002970/initial] forcing proxy-throughput with fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php
[Mon May 28 02:03:08.125741 2012] [rewrite:trace1] [pid 32127:tid 139957454014208] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50680] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f4a729be458][rid#7f4a48002970/initial] go-ahead with proxy request proxy:fcgi://localhost:9000/usr/local/home/magento/app/current/testq.php [OK]


BALANCER:

[Mon May 28 02:03:26.126309 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f5038002970/initial] init rewrite engine with requested uri /testq.php
[Mon May 28 02:03:26.126411 2012] [rewrite:trace3] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f5038002970/initial] applying pattern '^/?(.*\\.php(/.*)?)$' to uri '/testq.php'
[Mon May 28 02:03:26.126468 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f5038002970/initial] rewrite '/testq.php' -> 'balancer://magento/usr/local/home/magento/app/current/testq.php'
[Mon May 28 02:03:26.126488 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f5038002970/initial] forcing proxy-throughput with balancer://magento/usr/local/home/magento/app/current/testq.php
[Mon May 28 02:03:26.126506 2012] [rewrite:trace1] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f5038002970/initial] go-ahead with proxy request proxy:balancer://magento/usr/local/home/magento/app/current/testq.php [OK]
[Mon May 28 02:03:26.127431 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f503800a9b0/subreq] init rewrite engine with requested uri /usr/local/home/magento/app/current/testq.php
[Mon May 28 02:03:26.127494 2012] [rewrite:trace3] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f503800a9b0/subreq] applying pattern '^/?(.*\\.php(/.*)?)$' to uri '/usr/local/home/magento/app/current/testq.php'
[Mon May 28 02:03:26.127546 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f503800a9b0/subreq] rewrite '/usr/local/home/magento/app/current/testq.php' -> 'balancer://magento/usr/local/home/magento/app/current/usr/local/home/magento/app/current/testq.php'
[Mon May 28 02:03:26.127597 2012] [rewrite:trace2] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f503800a9b0/subreq] forcing proxy-throughput with balancer://magento/usr/local/home/magento/app/current/usr/local/home/magento/app/current/testq.php
[Mon May 28 02:03:26.127647 2012] [rewrite:trace1] [pid 32229:tid 139982970947328] mod_rewrite.c(466): [client xxx.xxx.xxx.xxx:50681] xxx.xxx.xxx.xxx - - [my.site.domain/sid#7f50643c8458][rid#7f503800a9b0/subreq] go-ahead with proxy request proxy:balancer://magento/usr/local/home/magento/app/current/usr/local/home/magento/app/current/testq.php [OK]
Comment 1 Joshua Rusch 2012-05-28 03:31:40 UTC
More info:

I'm using php-fpm as my fastcgi process manager.

Version 5.4.3 with the following patch applied:

https://bugs.php.net/bug.php?id=62172

It gets php fpm to strip out the proxy:balancer stuff from the SCRIPT_FILENAME for php, otherwise I'd be getting 404s on all the pages.
Comment 2 IanB 2012-08-15 13:13:12 UTC
This could relate to the following bug:
https://issues.apache.org/bugzilla/show_bug.cgi?id=51077#c5

"However, if the rewrite rule is placed in directory context, the final result has the query string appended to the URI, which in turn causes mod_proxy_fcgi to include the query string as a part of the SCRIPT_FILENAME environment variable, which is unexpected and causes problems for some (many?) back-end servers, including php-fpm"