[prev in list] [next in list] [prev in thread] [next in thread] 

List:       apache-httpd-users
Subject:    Re: [users@httpd] AJP proxy timeout problem
From:       Rainer Jung <rainer.jung () kippdata ! de>
Date:       2011-10-29 9:43:06
Message-ID: 4EABCAAA.5000400 () kippdata ! de
[Download RAW message or body]

On 29.10.2011 10:21, SpliFF wrote:
> 2.2.20 running on Gentoo 64-bit.
> 
> Server version: Apache/2.2.20 (Unix)
> Server built:   Sep 22 2011 02:42:57
> Server's Module Magic Number: 20051115:28
> Server loaded:  APR 1.4.5, APR-Util 1.3.12
> Compiled using: APR 1.4.5, APR-Util 1.3.12
> Architecture:   64-bit
> Server MPM:     Worker
> threaded:     yes (fixed thread count)
> forked:     yes (variable process count)
> Server compiled with....
> -D APACHE_MPM_DIR="server/mpm/worker"
> -D APR_HAS_SENDFILE
> -D APR_HAS_MMAP
> -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
> -D APR_USE_SYSVSEM_SERIALIZE
> -D APR_USE_PTHREAD_SERIALIZE
> -D APR_HAS_OTHER_CHILD
> -D AP_HAVE_RELIABLE_PIPED_LOGS
> -D DYNAMIC_MODULE_LIMIT=128
> -D HTTPD_ROOT="/usr"
> -D SUEXEC_BIN="/usr/sbin/suexec"
> -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
> -D DEFAULT_ERRORLOG="logs/error_log"
> -D AP_TYPES_CONFIG_FILE="/etc/apache2/mime.types"
> -D SERVER_CONFIG_FILE="/etc/apache2/httpd.conf"
> 
> 
> On 28/10/11 19:16, Rainer Jung wrote:
> > Which version of httpd?
> > 
> > On 28.10.2011 08:49, SpliFF wrote:
> > > I've having an issue where a long-running backend script behind AJP is causing \
> > > apache to error with "Service Temporarily Unavailable" after exactly 5 minutes.
> > > 
> > > I tried to solve this by moving from mod_rewrite to mod_proxy, with the \
> > > following configuration: 
> > > # Search Engine Safe URL rewrite
> > > # Redirect Coldfusion requests to index.cfm
> > > # matches /file.mp4 but not /file:name.mp4 (ie; is a real file)
> > > RewriteCond %{REQUEST_FILENAME} !/[^/:]+\.[^/:]{2,5}$
> > > RewriteRule (.*) /index.cfm$1 [PT]
> > > 
> > > # Proxy CFML files to Jetty via AJP connector
> > > <Proxy *>
> > > Allow from 127.0.0.1
> > > </Proxy>
> > > ProxyPreserveHost On
> > > ProxyRequests Off
> > > ProxyPassMatch ^/(.+\.cf[cm])(/.*)?$ ajp://localhost:8009/$1$2 \
> > > connectiontimeout=6000 timeout=6000 
> > > 
> > > If I'm not mistaken those timeouts are in seconds so AJP should be waiting at \
> > > least 100 minutes. 
> > > I also made sure the Railo backend would wait long enough, using the following \
> > > CFML tag: 
> > > <cfsetting requesttimeout=6000 />
> > > 
> > > I checked the Jetty (Application server) config but there doesn't seem to be \
> > > any timeout options. 
> > > The apache error log (with debugging) says:
> > > 
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy_ajp.c(45): proxy: AJP: \
> > > canonicalising URL //localhost:8009/index.cfm/subscribers/importold
> > > [Fri Oct 28 15:28:45 2011] [debug] proxy_util.c(1525): [client 192.168.1.60] \
> > > proxy: *: found reverse proxy worker for \
> > >                 ajp://localhost:8009/index.cfm/subscribers/importold
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy.c(1015): Running scheme ajp \
> > >                 handler (attempt 0)
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving \
> > > URL ajp://localhost:8009/index.cfm/subscribers/importold
> > > [Fri Oct 28 15:28:45 2011] [debug] proxy_util.c(2011): proxy: AJP: has acquired \
> > >                 connection for (*)
> > > [Fri Oct 28 15:28:45 2011] [debug] proxy_util.c(2067): proxy: connecting
> > > ajp://localhost:8009/index.cfm/subscribers/importold to localhost:8009
> > > [Fri Oct 28 15:28:45 2011] [debug] proxy_util.c(2193): proxy: connected \
> > >                 /index.cfm/subscribers/importold to localhost:8009
> > > [Fri Oct 28 15:28:45 2011] [debug] proxy_util.c(2444): proxy: AJP: fam 2 socket \
> > >                 created to connect to *
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(224): Into \
> > >                 ajp_marshal_into_msgb
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > > Header[0] [Host] = [users.arcmail.betamax.arc.net.au]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > > Header[1] [User-Agent] = [Mozilla/5.0 (X11; Linux x86_64; rv:7.0.1) \
> > >                 Gecko/20100101 Firefox/7.0.1]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > > Header[2] [Accept] = \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > >                 \
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > >                 Header[3] [Accept-Language] = [en-us,en;q=0.5]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > >                 Header[4] [Accept-Encoding] = [gzip, deflate]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > > Header[5] [Accept-Charset] = [ISO-8859-1,utf-8;q=0.7,*;q=0.7]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > >                 Header[6] [DNT] = [1]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > >                 Header[7] [Connection] = [keep-alive]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: \
> > > Header[8] [Cookie] = [CFID=d5b4b21d-bea4-4875-b2f3-7dc003c7fa64; CFTOKEN=0; \
> > >                 FW_BUGZ=; RAILO_ADMIN_LANG=en; \
> > >                 RAILO_ADMIN_LASTPAGE=server.cache]
> > > [Fri Oct 28 15:28:45 2011] [debug] ajp_header.c(450): ajp_marshal_into_msgb: \
> > >                 Done
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy_ajp.c(265): proxy: \
> > >                 APR_BUCKET_IS_EOS
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy_ajp.c(270): proxy: data to read \
> > >                 (max 8186 at 4)
> > > [Fri Oct 28 15:28:45 2011] [debug] mod_proxy_ajp.c(285): proxy: got 0 bytes of \
> > >                 data
> > > [Fri Oct 28 15:28:46 2011] [debug] ajp_header.c(687): ajp_read_header: \
> > >                 ajp_ilink_received 06
> > > [Fri Oct 28 15:28:46 2011] [debug] ajp_header.c(697): ajp_parse_type: got 06
> > > [Fri Oct 28 15:33:46 2011] [error] ajp_read_header: ajp_ilink_receive failed
> > > [Fri Oct 28 15:33:46 2011] [debug] mod_proxy_ajp.c(531): (120006)APR does not \
> > > understand this error code: ajp_read_header failed
> > > [Fri Oct 28 15:33:46 2011] [debug] mod_proxy_ajp.c(546): proxy: Processing of \
> > >                 request failed backend: 1, output: 0
> > > [Fri Oct 28 15:33:46 2011] [error] (120006)APR does not understand this error \
> > >                 code: proxy: dialog to (null) (*) failed
> > > [Fri Oct 28 15:33:46 2011] [debug] proxy_util.c(2029): proxy: AJP: has released \
> > > connection for (*) 
> > > Note the delay between "ajp_parse_type: got 06" and "ajp_ilink_receive failed" \
> > > is 5 minutes accurate to the second. I read somewhere that 5 minutes is the \
> > > default timeout for mod_proxy so my suspicion is the timeout settings are being \
> > > ignored. The only other theory I have is that the [PT] flag on the first \
> > > rewrite rule is causing those values to be ignored.

Did you truncate the log output? There seems to be helpful lines missing.

In addition: what kind of inf did you relace by "*"? It is fine to
replace confidential info, but in some places I would have just expected
something like "localhost" where you put "*". So I wonder whether there
are other proxy workers defined in the configuration apart from the ones
you have shown us?

I checked the code again, mod_proxy_ajp.c constructs the connection
using ap_proxy_connect_backend() which explicitely uses the worker
timeouts if set and only falls back to the proxy or server timeouts if
no worker timeout is set.

Regards,

Rainer

---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
   "   from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org


[prev in list] [next in list] [prev in thread] [next in thread] 

Configure | About | News | Add a list | Sponsored by KoreLogic