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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
