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/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" /> > >> > >> > >> > >> > >> > >> > > --------------------------------------------------------------------- > 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
