Hi André,
On 22.04.2009 18:29, André Warnier wrote:
As (maybe) part of another issue which I am still trying to track down
with the concerned network people (client write errors, Sample 2 below),
Before commenting Sample 1: Although we generally respond to the "client
errors" topic with "Users press reload or click on another link before
answer returns - check whether your responses take to long", we now
observed two cases, where there were real network problems (I generally
avoid to bash the network people, but it is still possible that the
trouble comes from the network):
- once a bad cable
- once a bad driver for a network card used by a VMware guest system
(problems with TCP offloading). TCP offloading problems seem to become a
new trend :(
I find the following kind of messages regularly in the mod_jk logfile
(Sample 1).
I just want to know if this indicates a problem somewhere, or if these
are normal occurrences.
These [info] messages do not always come as often as shown below, but
seem to come with some regularity nevertheless.
Basically, my question is whether this indicates that there might be a
discrepancy between front-end and back(-)end or something of the kind,
or if there is some other parameter to adjust to make these go away.
Apache 2.x prefork MPM
mod_jk 1.2.27
Tomcat 5.5.x
under RHEL, single host
JkLogLevel info
and
worker.ajp13.port=8009
worker.ajp13.host=localhost
worker.ajp13.type=ajp13
# new options since 1.2.27 :
worker.ajp13.ping_mode=A
(single worker, no load balancing)
back-end Connector :
<Connector port="8009"
enableLookups="false" redirectPort="8443" protocol="AJP/1.3"
maxThreads="150" minSpareThreads="25" maxSpareThreads="100"
backlog="100" />
The configuration contains no means for shutting down idle workers.
Neither mod_jk (connection_pool_timeout) nor Tomcat (connectTimeout)
will close idle connections. So it's possible, that an intermediate
system, e.g. firewall drops connections.
Sample 1 :
--------
[Tue Apr 21 13:34:59 2009] GET /myapp/normen/servlet.myapp 200 0.007701
4897
[Tue Apr 21 13:34:59 2009] GET /myapp/normen/servlet.myapp 200 0.004344
1457
[Tue Apr 21 13:34:59 2009] GET /myapp/normen/servlet.myapp 200 0.101926
1945
[Tue Apr 21 13:34:59 2009] GET /myapp/normen/servlet.myapp 200 0.322939
296975
[Tue Apr 21 13:35:14 2009] POST /myapp/normen/servlet.myapp 200 0.032625
1576
[Tue Apr 21 13:35:14 2009] GET /myapp/normen/servlet.myapp 200 0.003084
4176
It would be nicer to put the JK access logging into the access log and
add the pid (process id) there, so you could identify exaclty which
access log line relates to which JK info/error message block. not
critical though.
[Tue Apr 21 13:35:14 2009] [18753:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 16 returned -32 (errno=32)
[Tue Apr 21 13:35:14 2009] [18753:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:35:14 2009] [18753:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
As you already noticed, errno=32 is a broken pipe error. Sending the
cping packet uses the write() system call. The linux man pages for
write(2) on my systems say:
EPIPE fd is connected to a pipe or socket whose reading end is closed.
When this happens the writing process will also receive a SIGPIPE
signal. (Thus, the write return value is seen only if the program
catches, blocks or ignores this signal.)
So we should have "reading end is closed", which is Tomcat, so the
connection should bw in CLOSE_WAIT from the point of view of mod_jk. I
would expect a RST send by a firewall or similar between mod_jk and
Tomcat to also result in EPIPE.
[Tue Apr 21 13:35:14 2009] GET /myapp/normen/servlet.myapp 200 0.010538
1366
[Tue Apr 21 13:35:14 2009] GET /myapp/normen/servlet.myapp 200 0.002768
2507
[Tue Apr 21 13:35:14 2009] GET /myapp/normen/servlet.myapp 200 0.002658
1999
[Tue Apr 21 13:35:17 2009] POST /myapp/normen/servlet.myapp 200 0.060688
21560
[Tue Apr 21 13:35:19 2009] POST /myapp/normen/servlet.myapp 200 0.017692
23635
[Tue Apr 21 13:35:22 2009] POST /myapp/normen/servlet.myapp 200 1.032645
21400
[Tue Apr 21 13:35:34 2009] [30410:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 16 returned -32 (errno=32)
[Tue Apr 21 13:35:34 2009] [30410:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:35:34 2009] [30410:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
Same again.
[Tue Apr 21 13:35:34 2009] POST /myapp/normen/servlet.myapp 200 0.071825
20753
[Tue Apr 21 13:35:36 2009] POST /myapp/normen/servlet.myapp 200 0.115782
14137
[Tue Apr 21 13:35:56 2009] [30413:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 1 returned -32 (errno=32)
[Tue Apr 21 13:35:56 2009] [30413:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:35:56 2009] [30413:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
Again
[Tue Apr 21 13:35:56 2009] POST /myapp/normen/servlet.myapp 200 0.040233
20753
[Tue Apr 21 13:35:57 2009] [29827:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 16 returned -32 (errno=32)
[Tue Apr 21 13:35:57 2009] [29827:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:35:57 2009] [29827:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
Again
[Tue Apr 21 13:35:57 2009] POST /myapp/normen/servlet.myapp 200 0.036396
12264
[Tue Apr 21 13:36:36 2009] GET /myapp/normen/servlet.myapp 200 0.292587
1409
[Tue Apr 21 13:36:36 2009] GET /myapp/normen/servlet.myapp 200 0.010833
6729
[Tue Apr 21 13:36:36 2009] GET /myapp/normen/servlet.myapp 200 0.015750
3484
[Tue Apr 21 13:36:36 2009] GET /myapp/normen/servlet.myapp 200 0.032983
2915
Note that all 4 cases were logged by a diffrent PID (process id), and in
the prefork case, each process has its own pool of size 1. So 4
different processes experienced a connection closed by the backend or
something in between. If you would log the JK access data and the PID in
the apache access log, you could verify, when those processes used the
backend connection the last time previously to verify the idleness theory.
Sample 2 : (for illustration of the other issue only)
--------
[Tue Apr 21 13:15:32 2009] GET /myapp/normen/servlet.myapp 200 0.016737
6729
[Tue Apr 21 13:15:32 2009] GET /myapp/normen/servlet.myapp 200 0.019133
3484
[Tue Apr 21 13:15:32 2009] GET /myapp/normen/servlet.myapp 200 0.010458
2915
[Tue Apr 21 13:15:32 2009] GET /myapp/normen/servlet.myapp 200 0.112756
18897
[Tue Apr 21 13:15:44 2009] [29831:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 1 returned -32 (errno=32)
[Tue Apr 21 13:15:44 2009] [29831:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:15:44 2009] [29831:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
The same for pid 29831
[Tue Apr 21 13:15:44 2009] [30401:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 17 returned -32 (errno=32)
[Tue Apr 21 13:15:44 2009] [30401:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:15:44 2009] [30401:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
pid 30401
[Tue Apr 21 13:15:49 2009] [29827:2537034048] [info]
ajp_connection_tcp_send_message::jk_ajp_common.c (1064): sendfull for
socket 16 returned -32 (errno=32)
[Tue Apr 21 13:15:49 2009] [29827:2537034048] [info]
ajp_handle_cping_cpong::jk_ajp_common.c (855): can't send cping query
[Tue Apr 21 13:15:49 2009] [29827:2537034048] [info]
ajp_maintain::jk_ajp_common.c (3046): (ajp13) failed sending request,
socket -1 keepalive cping/cpong failure (errno=32)
pid 29827
[Tue Apr 21 13:15:49 2009] [29831:2537034048] [info]
ajp_process_callback::jk_ajp_common.c (1748): Writing to client aborted
or client network problems
[Tue Apr 21 13:15:49 2009] [29831:2537034048] [info]
ajp_service::jk_ajp_common.c (2407): (ajp13) sending request to tomcat
failed (unrecoverable), because of client write error (attempt=1)
Now a client write error, again pid 29831. Possibly, the cping write
error above too a long time to be detected and that's why the response
retrieved via a fresh connection wasn't consumed by the client? Although
the below response times seem to tell us, that the longest request in
the snippet here took 9 seconds, which is not that long.
There is no mod_jk internal relation between the cping send failure and
a client write error. It could only be in some indirect way, like both
being caused by a general network problem (occuring on the path to the
browser and on the path to the backend - but then why don't we see lots
of other communication errors as well?) or by some timing issue
triggering user behaviour - not very likely in light of the blow
duration lines.
[Tue Apr 21 13:15:49 2009] POST /myapp/normen/servlet.myapp 200 5.210358
8184
[Tue Apr 21 13:15:49 2009] [29831:2537034048] [info]
jk_handler::mod_jk.c (2469): Aborting connection for worker=ajp13
This is a consequence of the client write error, so next time this
process will open a fresh connection to the backend.
[Tue Apr 21 13:15:49 2009] POST /myapp/normen/servlet.myapp 200 0.363977
20753
[Tue Apr 21 13:15:54 2009] POST /myapp/normen/servlet.myapp 200 9.057331
20755
[Tue Apr 21 13:15:55 2009] POST /myapp/normen/servlet.myapp 200 0.215937
14166
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
