Cross-posting this to the tomcat users list (also posted to users@httpd)...
Hello, I've been trying to track down an intermittent problem with a Java web
application that is running on tcServer fronted by Apache HTTP Server. We
get intermittent "Server Unavailable / HTTP 500" errors, and when we do see
them, there is the same set of log statements written to the Apache HTTP Server
error log:
[Mon Jul 23 10:03:15 2012] [error] (70014)End of file found:
ajp_ilink_receive() can't receive header
[Mon Jul 23 10:03:15 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Mon Jul 23 10:03:15 2012] [error] (120006)APR does not understand this error
code: proxy: dialog to 127.0.0.1:7071 (127.0.0.1) failed
We are not seeing any error messages in the tcServer logs.
I believe the issue is with the mod_proxy_ajp module but it's been very
difficult tracking down what exactly the problem is. What's interesting is
that this Apache / tcServer configuration is used with other applications that
work just fine and never have the intermittent 500 error. We also can run our
application strictly in Tomcat (no Apache front) without any intermittent
errors.
We haven't ruled out that there could be something in our Java application code
that is causing this, in combination with the mod_proxy_ajp module, but we have
hit a wall as to what this issue could be. Has anyone else experienced a
similar intermittent issue combined with the above error messages? Below is a
copy of the error log and some configuration settings.
Thanks, Tony
---------------------
Apache HTTP Error Log
---------------------
[Mon Jul 23 10:03:15 2012] [debug] mod_cache.c(141): Adding CACHE_SAVE filter
for /myapp/
[Mon Jul 23 10:03:15 2012] [debug] mod_cache.c(148): Adding CACHE_REMOVE_URL
filter for /myapp/
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(45): proxy: AJP:
canonicalising URL //127.0.0.1:7071/myapp/
[Mon Jul 23 10:03:15 2012] [debug] proxy_util.c(1506): [client ***cleansed***]
proxy: ajp: found worker ajp://127.0.0.1:7071/myapp for
ajp://127.0.0.1:7071/myapp/
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy.c(1020): Running scheme ajp
handler (attempt 0)
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_http.c(1963): proxy: HTTP:
declining URL ajp://127.0.0.1:7071/myapp/
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(681): proxy: AJP: serving
URL ajp://127.0.0.1:7071/myapp/
[Mon Jul 23 10:03:15 2012] [debug] proxy_util.c(2011): proxy: AJP: has acquired
connection for (127.0.0.1)
[Mon Jul 23 10:03:15 2012] [debug] proxy_util.c(2067): proxy: connecting
ajp://127.0.0.1:7071/myapp/ to 127.0.0.1:7071
[Mon Jul 23 10:03:15 2012] [debug] proxy_util.c(2193): proxy: connected /myapp/
to 127.0.0.1:7071
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[0] [x-forwarded-for] = [***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[1] [Host] = [***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[2] [Connection] = [keep-alive]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[3] [User-Agent] = [Mozilla/5.0 (Windows NT 6.1; WOW64)
AppleWebKit/536.11 (KHTML, like Gecko) Chrome/20.0.1132.57 Safari/536.11]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[4] [Accept] =
[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[5] [Accept-Encoding] = [gzip,deflate,sdch]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[6] [Accept-Language] = [en-US,en;q=0.8]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[7] [Accept-Charset] = [ISO-8859-1,utf-8;q=0.7,*;q=0.3]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[8] [Cookie] = [SSOTOKEN=***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[9] [SSO_LOGIN] = [***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[10] [SSO_ID] = [***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(290): ajp_marshal_into_msgb:
Header[11] [SSO_EMAIL] = [***cleansed***]
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(450): ajp_marshal_into_msgb:
Done
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(268): proxy:
APR_BUCKET_IS_EOS
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(273): proxy: data to read
(max 8186 at 4)
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(288): proxy: got 0 bytes of
data
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(687): ajp_read_header:
ajp_ilink_received 03
[Mon Jul 23 10:03:15 2012] [debug] ajp_header.c(697): ajp_parse_type: got 03
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(460): Ignoring flush message
received before headers
[Mon Jul 23 10:03:15 2012] [error] (70014)End of file found:
ajp_ilink_receive() can't receive header
[Mon Jul 23 10:03:15 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(549): (120006)APR does not
understand this error code: ajp_read_header failed
[Mon Jul 23 10:03:15 2012] [debug] mod_proxy_ajp.c(564): proxy: Processing of
request failed backend: 1, output: 0
[Mon Jul 23 10:03:15 2012] [error] (120006)APR does not understand this error
code: proxy: dialog to 127.0.0.1:7071 (127.0.0.1) failed
[Mon Jul 23 10:03:15 2012] [debug] proxy_util.c(2029): proxy: AJP: has released
connection for (127.0.0.1)
[Mon Jul 23 10:03:15 2012] [debug] mod_deflate.c(615): [***cleansed***] Zlib:
Compressed 323 to 218 : URL /myapp/
---------------------------------
Apache HTTP Server (apachectl -V)
---------------------------------
Server version: Apache/2.2.22 (Unix)
Server built: Jul 17 2012 17:20:28
Server's Module Magic Number: 20051115:30
Server loaded: APR 1.4.5, APR-Util 1.4.1
Compiled using: APR 1.4.5, APR-Util 1.4.1
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 SINGLE_LISTEN_UNSERIALIZED_ACCEPT
-D APR_HAS_OTHER_CHILD
-D AP_HAVE_RELIABLE_PIPED_LOGS
-D DYNAMIC_MODULE_LIMIT=128
-D HTTPD_ROOT="/apps/apache2"
-D SUEXEC_BIN="/apps/apache2/bin/suexec"
-D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
-D DEFAULT_ERRORLOG="logs/error_log"
-D AP_TYPES_CONFIG_FILE="conf/mime.types"
-D SERVER_CONFIG_FILE="conf/httpd.conf"
-------------------------------
httpd.conf (relevant settings):
-------------------------------
<IfModule worker.c>
StartServers 2
MaxClients 400
MinSpareThreads 25
MaxSpareThreads 75
ThreadsPerChild 25
MaxRequestsPerChild 10000
</IfModule>
ProxyRequests Off
ProxyPreserveHost on
ProxyReceiveBufferSize 0
ProxyErrorOverride Off
RewriteEngine on
ProxyPass /myapp ajp://127.0.0.1:7071/myapp
ProxyPassReverse /myapp ajp://127.0.0.1:7071/myapp
-----------------------------------------------
tcServer 2.0.4.RELEASE (Tomcat 6.0.29 binaries)
-----------------------------------------------
server.xml:
<Executor name="tomcatThreadPool" namePrefix="tomcat-ajp--" maxThreads="300"
minSpareThreads="50"/>
<Connector executor="tomcatThreadPool"
address="127.0.0.1"
port="7071"
protocol="org.apache.coyote.ajp.AjpAprProtocol"
connectionTimeout="60000"
redirectPort="8443"
backlog="100"
tcpNoDelay="true"
enableLookups="false"
URIEncoding="UTF-8" />
