Hi Tony,
Could you be running out of database connections? Try taking a thread dump
when the issue occurs, or schedule periodic thread-dumps. And see if any
threads are stuck during the time of issue. You could also cron a job
every minute to find out the number of connections going into the database
server over the course of the application. I haven't tested the script
(sorry!), but something like:
---------------
#!/bin/sh
DB_SERVER_IP=127.0.0.1 # ==> Please change
# Build the regular datestamp:
#
DATE=`date "+%Y-%m-%d %H:%M:%S"`
DB_CONNECTIONS=`netstat -anT | grep ${DB_SERVER_IP} | wc -l`
/bin/echo ${DATE} ${DB_CONNECTIONS} >> /tmp/database-server-connections
-------------------
What does the web-application write out in it's response? Is the response
based on user-input? Do you see a pattern that the 500 errors are
happening after the application has been in use for a while?
Thanks.
-Shanti
On Thu, Jul 26, 2012 at 8:00 PM, Igor Cicimov <icici...@gmail.com> wrote:
> On Fri, Jul 27, 2012 at 4:20 AM, Carlucci, Tony <acarlu...@mitre.org>
> wrote:
>
> > >-----Original Message-----
> > >From: Igor Cicimov [mailto:icici...@gmail.com]
> > >Sent: Wednesday, July 25, 2012 9:12 PM
> > >To: Tomcat Users List
> > >Subject: Re: Intermittent mod_proxy_ajp error - APR does not understand
> > this
> > >error code: proxy: dialog
> > >
> > >You have max clients on the apache side set to 400 but only 300 threads
> on
> > >tomcat side. No wonder you get 500 error...
> >
> > Thanks for the suggestion Igor, I increased the tomcat threads to 400 but
> > that did not resolve the issue.
> >
> > Tony
> >
> >
> > >
> > >On Wed, Jul 25, 2012 at 12:22 AM, Carlucci, Tony <acarlu...@mitre.org
> > >wrote:
> > >
> > >> 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/myappfor
> > >> 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" />
> > >>
> > >>
> > >>
> > >>
> > >>
> > >>
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> > For additional commands, e-mail: users-h...@tomcat.apache.org
> >
> >
> Hi Tony,
>
> If we look at the ajp log provided carefully we can notice the following
> when the problem starts:
>
> [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
>
> which indicates that mod_ajp connected and sent a request to Tomcat but
> didn't get anything back in response. This is classic error 500 scenario
> when the backend is too busy to respond. I don't think anything is wrong
> with mod_ajp if any bug it would had been caught till now and solved ages
> ago since this module has been in the mainstream for quit a time now.
>
> I think you need to focus all your attention to the Tomcat side or more
> specific I would say your application. Something is keeping the threads
> busy for too long and from my experience it is usually something to do with
> database. If your application connects and deals with some kind of database
> that's where I would start from i.e. application not closing connections,
> long running queries etc. To start with you can take a thread dump in
> Tomcat at the moment you get the errors and check what the threads are
> doing at that time.
>
> You can try increasing the thread count on Tomcat side to 1500 (if the
> server memory resources permit that) but that will just postpone the
> errors. The best thing is to debug your application and solve the problem
> there.
>
> In the Tomcat configuration I personally can't see anything wrong. Have you
> tried using the "org.apache.coyote.ajp.AjpProtocol" instead the APR one and
> see if that makes any difference?
>
> Cheers,
> Igor
>
