tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rainer Jung <rainer.j...@kippdata.de>
Subject Re: unusual mod_jk 1.2.30 log messages
Date Thu, 02 Sep 2010 16:26:10 GMT
On 02.09.2010 13:39, Brett Delle Grazie wrote:
> Hi,
>
> We're having some strange errors being reported in the 1.2.30 version of
> mod_jk.  We think they might be related to the performance issues we're
> experiencing under load.
>
> OS: RHEL 5.5 (fully patched)
> Apache HTTPD: 2.2.3 (from OS vendor)
> mod_jk: 1.2.30 (downloaded from Tomcat site and compiled locally)
> Tomcat: 6.0.29 (binary distribution from apache.org)
> JVM: 1.6.0_21 (Sun, 64-bit).

Thanks for the info (and for keeping most of it up-to-date) :)

> A sample is below. I'm mostly concerned about the 'awaited reply cpong
> recieved 3 instead' and the subsequenct close  and failure to send
> request.
>
> Has anyone seen this before?
>
> [Thu Sep 02 07:22:47.508 2010] [31759:47279871456000] [info]
> init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
> [Thu Sep 02 07:22:47.588 2010] [31763:47279871456000] [info]
> init_jk::mod_jk.c (3189): mod_jk/1.2.30 initialized
> [Thu Sep 02 07:22:52.896 2010] [31781:1237244224] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:22:52.896 2010] [31781:1237244224] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:22:59.647 2010] [31781:1258223936] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:22:59.647 2010] [31781:1258223936] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:02.042 2010] [32082:1253792064] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:23:02.042 2010] [32082:1253792064] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:06.142 2010] [32049:1325504832] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:23:06.142 2010] [32049:1325504832] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:11.231 2010] [32082:1211832640] [info]
> ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> or client network problems
> [Thu Sep 02 07:23:11.231 2010] [32082:1211832640] [info]
> ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> failed (unrecoverable), because of client write error (attempt=1)
> [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> error state
> [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> Client failed in the middle of request, we can't recover to another
> instance.
> [Thu Sep 02 07:23:11.232 2010] [32082:1211832640] [info]
> jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> [Thu Sep 02 07:23:11.444 2010] [32049:1315014976] [info]
> ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> or client network problems
> [Thu Sep 02 07:23:11.444 2010] [32049:1315014976] [info]
> ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> failed (unrecoverable), because of client write error (attempt=1)
> [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> error state
> [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> Client failed in the middle of request, we can't recover to another
> instance.
> [Thu Sep 02 07:23:11.445 2010] [32049:1315014976] [info]
> jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> [Thu Sep 02 07:23:11.645 2010] [32082:1232812352] [info]
> ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> or client network problems
> [Thu Sep 02 07:23:11.645 2010] [32082:1232812352] [info]
> ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> failed (unrecoverable), because of client write error (attempt=1)
> [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> error state
> [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> Client failed in the middle of request, we can't recover to another
> instance.
> [Thu Sep 02 07:23:11.646 2010] [32082:1232812352] [info]
> jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
> [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm1) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:17.902 2010] [31927:1298282816] [info]
> ajp_send_request::jk_ajp_common.c (1574): (jvm1) all endpoints are
> disconnected, detected by connect check (0), cping (1), send (0)
> [Thu Sep 02 07:23:20.676 2010] [31927:1140934976] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:23:20.676 2010] [31927:1140934976] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:29.280 2010] [31927:1182894400] [warn]
> ajp_handle_cping_cpong::jk_ajp_common.c (906): awaited reply cpong,
> received 3 instead. Closing connection
> [Thu Sep 02 07:23:29.280 2010] [31927:1182894400] [info]
> ajp_send_request::jk_ajp_common.c (1518): (jvm2) failed sending request,
> socket -1 prepost cping/cpong failure (errno=0)
> [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> ajp_process_callback::jk_ajp_common.c (1882): Writing to client aborted
> or client network problems
> [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> ajp_service::jk_ajp_common.c (2540): (jvm1) sending request to tomcat
> failed (unrecoverable), because of client write error (attempt=1)
> [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> service::jk_lb_worker.c (1388): service failed, worker jvm1 is in local
> error state
> [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> service::jk_lb_worker.c (1407): unrecoverable error 200, request failed.
> Client failed in the middle of request, we can't recover to another
> instance.
> [Thu Sep 02 07:23:33.014 2010] [32082:1138403648] [info]
> jk_handler::mod_jk.c (2611): Aborting connection for worker=balancer
>
> The rest of the log continues in the same pattern albeit with higher
> frequency as the load increases.

I guess you hit

https://issues.apache.org/bugzilla/show_bug.cgi?id=49413

Even though you don't use JBoss it could still be a flush issue (see 
comments further down the ticket). In your case, since you have 
cping/cpong active (which is a good thing), it is not the next request 
packet that finds a wrong backend packet on the wire but instead the 
cping. We *thought* we had fixed that shortly before 1.2.30, but there 
might be a glitch in the patch.

Could you apply the following patch and proviede the slightly extended 
log message:

--- jk_ajp_common.c     2010-02-23 08:26:02.000000000 +0100
+++ jk_ajp_common.c.debug       2010-09-02 18:24:41.429730000 +0200
@@ -904,9 +904,9 @@
                       cmd < JK_AJP13_SEND_BODY_CHUNK ||
                       cmd > AJP13_CPONG_REPLY) {
                  jk_log(l, JK_LOG_WARNING,
-                       "awaited reply cpong, received %d instead. "
+                       "awaited reply cpong, received %d (%d / %d) 
instead. "
                         "Closing connection",
-                       cmd);
+                       cmd, i, ae->last_op);
                  /* We can't trust this connection any more. */
                  ajp_abort_endpoint(ae, JK_TRUE, l);
                  JK_TRACE_EXIT(l);

Regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message