You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by "Anthony J. Biacco" <ab...@formatdynamics.com> on 2010/03/16 22:07:39 UTC
mod_jk 1.2.30 error problem after upgrade
System:
x86_64/CentOS 5.4/Apache 2.2.14/Tomcat 6.0.20
Problem:
I just upgraded from mod_jk 1.2.28 to 1.2.30. I have 4 apache servers
JKing to 4 tomcat servers in load balanced worker. Both apache and
tomcat are on the same servers.
After upgrading, I have started to see mod_jk reporting connection
errors when it talks to its local server. i.e. when server1's apache
talks to server1's tomcat, server2's apache talks to server2's tomcat,
etc.. They do not talk via 127.0.0.1, but via its internal ip like to
every other server.
The errors are:
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): sending
to ajp13 pos=4 len=4 max=8192
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): 0000
12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 - .4..............
[debug] jk_is_input_event::jk_connect.c (986): error event during poll
on socket sd = 65 (event=24)
[error] ajp_get_reply::jk_ajp_common.c (2020): (srv2) Timeout with
waiting reply from tomcat. Tomcat is down, stopped or network problems
(errno=24)
[debug] jk_shutdown_socket::jk_connect.c (722): About to shutdown socket
65
[debug] jk_shutdown_socket::jk_connect.c (730): Failed sending SHUT_WR
for socket 65
[error] ajp_service::jk_ajp_common.c (2533): (srv2) sending request to
tomcat failed (unrecoverable), because of reply timeout (attempt=2)
[debug] ajp_reset_endpoint::jk_ajp_common.c (757): (srv2) resetting
endpoint with sd = 4294967295 (socket shutdown)
[debug] ajp_done::jk_ajp_common.c (3010): recycling connection pool
slot=0 for worker srv2
[info] service::jk_lb_worker.c (1388): service failed, worker srv2 is in
error state
[error] service::jk_lb_worker.c (1413): unrecoverable error 504, request
failed. Tomcat failed in the middle of request, we can't recover to
another instance.
[error] service::jk_lb_worker.c (1473): All tomcat instances failed, no
more workers left
Jkstatus lines are for the particular worker are:
Name Type Hostname Address:Port Connection Pool Timeout
Connect Timeout Prepost Timeout Reply Timeout Retries Recovery Options
Max Packet Size
srv2 ajp13 x.x.x.x x.x.x.x:8009 30 30000 20000 20000
2 4 8192
Name Act State D F M V Acc
Err CE RE Wr Rd
Busy Max Con Route RR Cd Rs LR LE
srv2 ACT OK 0 1 1 272 10551 (2/sec)
5 0 0 54M (13K/sec) 65M (16K/sec) 0 5
-20 tr2 0/0 4248
No tomcat changes have been made between 1.2.28 and 1.2.30
workers.properties (local worker only quoted):
worker.template.port=8009
worker.template.type=ajp13
worker.template.lbfactor=1
worker.template.connection_pool_timeout=30
worker.template.connect_timeout=30000
worker.template.fail_on_status=-400,-403,-404,500,503
worker.template.recovery_options=4
worker.template.reply_timeout=20000
worker.template.socket_timeout=20
worker.template.socket_connect_timeout=5000
worker.template.ping_mode=A
worker.template.ping_timeout=20000
worker.srv2.host=x.x.x.x
worker.srv2.reference=worker.template
jk parameters (relevant):
JkWatchdogInterval 60
JkLogLevel info
JkLogStampFormat "[%a %b %d %H:%M:%S %Y] "
JkOptions +ForwardKeySize +ForwardURIProxy -ForwardDirectories
JkRequestLogFormat "%w %R %V %B %T %m %U %s"
JkShmFile logs/jk-runtime-status
tomcat parameters:
<Connector port="8009" protocol="AJP/1.3"
maxThreads="400" backlog="25" maxPostSize="4194304"
enableLookups="false" connectionTimeout="30000"
keepAliveTimeout="10000"
redirectPort="8443" />
-Tony
---------------------------
Manager, IT Operations
Format Dynamics, Inc.
303-573-1800x27
abiacco@formatdynamics.com
http://www.formatdynamics.com
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: mod_jk 1.2.30 error problem after upgrade
Posted by Ramesh XN <fu...@gmail.com>.
Anthony J. Biacco <abiacco <at> formatdynamics.com> writes:
>
> I may have found it from 5 minutes earlier, I didn't go back that far in
> the log. I'll mail it privately, I don't feel comfortable posting the
> content in whole publicly, if that's alright.
>
> Thanks again.
>
> -Tony
> ---------------------------
> Manager, IT Operations
> Format Dynamics, Inc.
> 303-573-1800x27
> abiacco <at> formatdynamics.com
> http://www.formatdynamics.com
>
> > -----Original Message-----
> > From: Mladen Turk [mailto:mturk <at> apache.org]
> > Sent: Wednesday, March 17, 2010 12:57 PM
> > To: users <at> tomcat.apache.org
> > Subject: Re: mod_jk 1.2.30 error problem after upgrade
> >
> > On 03/17/2010 07:15 PM, Anthony J. Biacco wrote:
> > >>
> > >> On 03/16/2010 10:07 PM, Anthony J. Biacco wrote:
> > >>>
> > >>> The errors are:
> > >>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> > >> sending
> > >>> to ajp13 pos=4 len=4 max=8192
> > >>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> > > 0000
> > >>> 12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 -
> .4..............
> > >>
> > >> Do you have
> > >> "browser stop sending data, no need to recover" message before
> those
> > >> two?
> > >>
> > >
> > > I do not.
> > >
> > > I don't see anything other than the snippet I posted. And they're
> all
> > > the same as the above one.
> > > I do notice that successful ones look like this:
> > >
> >
> > There must be something calling ajp_connection_tcp_send_message.
> > It sends the zero length message, so it's hard to figure out
> > from the snippet you gave. You'll have to post the
> > larger one (for the same pid) that causes that.
> >
> > Regards
> > --
> > ^TM
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscribe <at> tomcat.apache.org
> > For additional commands, e-mail: users-help <at> tomcat.apache.org
>
Hi Anthony,
Did you find any soluction to this problem.
I also have the same problem and tried all known possible solution but no
luck. Appreciate if you can share your solution.
[Mon Sep 19 16:19:45 2011] [26120:1328027968] [debug]
jk_map_to_storage::mod_jk.c (3603): no match for /healthcheck/clover.html found
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
ajp_send_request::jk_ajp_common.c (1643): (tomcat01) browser stop sending
data, no need to recover
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1070): sending to ajp13
pos=4 len=6 max=8192
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1070): 0000 12 34 00 02
00 00 00 00 00 00 00 00 00 00 00 00 - .4..............
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [info]
ajp_service::jk_ajp_common.c (2447): (tomcat01) sending request to tomcat
failed (unrecoverable), because of client read error (attempt=1)
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
ajp_reset_endpoint::jk_ajp_common.c (743): (tomcat01) resetting endpoint with
sd = 20 (socket shutdown)
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
jk_shutdown_socket::jk_connect.c (681): About to shutdown socket 20
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
jk_shutdown_socket::jk_connect.c (689): Failed sending SHUT_WR for socket 20
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [debug]
ajp_done::jk_ajp_common.c (2905): recycling connection pool slot=0 for worker
tomcat01
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [info] service::jk_lb_worker.c
(1384): service failed, worker tomcat01 is in local error state
[Mon Sep 19 16:19:46 2011] [26122:1325082944] [info] service::jk_lb_worker.c
(1403): unrecoverable error 400, request failed. Client failed in the middle
of request, we can't recover to another instance.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: mod_jk 1.2.30 error problem after upgrade
Posted by Mladen Turk <mt...@apache.org>.
On 03/18/2010 09:27 PM, Anthony J. Biacco wrote:
>
> Is there something in the new code that is just making things more
> sensitive on the mod_jk side, which is why this never showed up in .28?
>
Yes it is. Although your particular uses case should be
shown in earlier versions as well. At least there should
be long client read delay.
However pre .30 versions would just go on, which could lead
that next request is treated as previous client POST data,
ending up in showing the requested data from the previous
client to the new request (pretty bad).
I'd suggest that you solve the reason why
ajp_read_fully_from_server (which calls httpd's ap_get_client_block)
takes 5 minutes to complete.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: mod_jk 1.2.30 error problem after upgrade
Posted by "Anthony J. Biacco" <ab...@formatdynamics.com>.
>
> However notice that there is 5 minutes gap between the actual data
> has been read from the client and send to the tomcat.
> By that time tomcat already closed the connection (30 seconds in
> server.xml) and then
> any request to send the data fails. Actually all sockets shut down.
>
>
> So, seems like you have very slow client, so try to enlarge the
> timeouts
> or find the reason for slow clients.
Ok, understood. My problem is that it only occurs for the tomcat local
to the mod_jk. This is a very weird circumstance. If it was a client
problem, I'd think it'd be server-agnostic, but I can confirm only
seeing it from one client (which is a really a series of http proxies
from the client. One ASP based and the other custom, that's all I know
about it).
Is there something in the new code that is just making things more
sensitive on the mod_jk side, which is why this never showed up in .28?
>
> Also why are you using recovery_options = 4 ?
>
This seemed the most logical. 4 seemed natural because why should we
close the connection to tomcat if a client write error occurs and I also
didn't want 1 and 2 because I figure that it should be able to recover
to a different tomcat if any particular tomcat errored out (wouldn't
mean ALL tomcats would error).
-Tony
---------------------------
Manager, IT Operations
Format Dynamics, Inc.
303-573-1800x27
abiacco@formatdynamics.com
http://www.formatdynamics.com
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: mod_jk 1.2.30 error problem after upgrade
Posted by Mladen Turk <mt...@apache.org>.
On 03/17/2010 09:35 PM, Anthony J. Biacco wrote:
> I may have found it from 5 minutes earlier, I didn't go back that far in
> the log. I'll mail it privately, I don't feel comfortable posting the
> content in whole publicly, if that's alright.
>
OK. Here is the problem
Send request header
[Wed Mar 17 09:45:14 2010] [521:1221798208] [debug] ajp_send_request::jk_ajp_common.c (1639): (tr1) request body to send 6815 - request body to resend 0
Since this is POST mod_jk sends immediately the first body chunk of post data
[Wed Mar 17 09:50:14 2010] [521:1221798208] [debug] ajp_send_request::jk_ajp_common.c (1744): (tr1) sending 5840 bytes of request body
However notice that there is 5 minutes gap between the actual data
has been read from the client and send to the tomcat.
By that time tomcat already closed the connection (30 seconds in server.xml) and then
any request to send the data fails. Actually all sockets shut down.
E.g
[Wed Mar 17 09:50:14 2010] [521:1221798208] [debug] jk_is_input_event::jk_connect.c (986): error event during poll on socket sd = 68 (event=24)
This means the read side has been down.
[Wed Mar 17 09:50:14 2010] [521:1221798208] [debug] jk_shutdown_socket::jk_connect.c (730): Failed sending SHUT_WR for socket 68
... and even write side.
So, seems like you have very slow client, so try to enlarge the timeouts
or find the reason for slow clients.
Also why are you using recovery_options = 4 ?
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: mod_jk 1.2.30 error problem after upgrade
Posted by "Anthony J. Biacco" <ab...@formatdynamics.com>.
I may have found it from 5 minutes earlier, I didn't go back that far in
the log. I'll mail it privately, I don't feel comfortable posting the
content in whole publicly, if that's alright.
Thanks again.
-Tony
---------------------------
Manager, IT Operations
Format Dynamics, Inc.
303-573-1800x27
abiacco@formatdynamics.com
http://www.formatdynamics.com
> -----Original Message-----
> From: Mladen Turk [mailto:mturk@apache.org]
> Sent: Wednesday, March 17, 2010 12:57 PM
> To: users@tomcat.apache.org
> Subject: Re: mod_jk 1.2.30 error problem after upgrade
>
> On 03/17/2010 07:15 PM, Anthony J. Biacco wrote:
> >>
> >> On 03/16/2010 10:07 PM, Anthony J. Biacco wrote:
> >>>
> >>> The errors are:
> >>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> >> sending
> >>> to ajp13 pos=4 len=4 max=8192
> >>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> > 0000
> >>> 12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 -
.4..............
> >>
> >> Do you have
> >> "browser stop sending data, no need to recover" message before
those
> >> two?
> >>
> >
> > I do not.
> >
> > I don't see anything other than the snippet I posted. And they're
all
> > the same as the above one.
> > I do notice that successful ones look like this:
> >
>
> There must be something calling ajp_connection_tcp_send_message.
> It sends the zero length message, so it's hard to figure out
> from the snippet you gave. You'll have to post the
> larger one (for the same pid) that causes that.
>
> Regards
> --
> ^TM
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: mod_jk 1.2.30 error problem after upgrade
Posted by Mladen Turk <mt...@apache.org>.
On 03/17/2010 07:15 PM, Anthony J. Biacco wrote:
>>
>> On 03/16/2010 10:07 PM, Anthony J. Biacco wrote:
>>>
>>> The errors are:
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
>> sending
>>> to ajp13 pos=4 len=4 max=8192
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> 0000
>>> 12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 - .4..............
>>
>> Do you have
>> "browser stop sending data, no need to recover" message before those
>> two?
>>
>
> I do not.
>
> I don't see anything other than the snippet I posted. And they're all
> the same as the above one.
> I do notice that successful ones look like this:
>
There must be something calling ajp_connection_tcp_send_message.
It sends the zero length message, so it's hard to figure out
from the snippet you gave. You'll have to post the
larger one (for the same pid) that causes that.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: mod_jk 1.2.30 error problem after upgrade
Posted by "Anthony J. Biacco" <ab...@formatdynamics.com>.
>
> On 03/16/2010 10:07 PM, Anthony J. Biacco wrote:
> >
> > The errors are:
> > [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
> sending
> > to ajp13 pos=4 len=4 max=8192
> > [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152):
0000
> > 12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 - .4..............
>
> Do you have
> "browser stop sending data, no need to recover" message before those
> two?
>
I do not.
> This looks like empty POST message caused by client
> cheating C-L header.
>
> Anyhow post the log snippet for the
> ajp_connection_tcp_send_message callee.
I don't see anything other than the snippet I posted. And they're all
the same as the above one.
I do notice that successful ones look like this:
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): sending
to ajp13 pos=4 len=5 max=16
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): 0000
12 34 00 01 0A 00 00 00 00 00 00 00 00 00 00 00 - .4..............
[debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1336): received
from ajp13 pos=0 len=1 max=16
[debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1336): 0000
09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 - ................
-Tony
> Regards
> --
> ^TM
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: mod_jk 1.2.30 error problem after upgrade
Posted by Mladen Turk <mt...@apache.org>.
On 03/16/2010 10:07 PM, Anthony J. Biacco wrote:
>
> The errors are:
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): sending
> to ajp13 pos=4 len=4 max=8192
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1152): 0000
> 12 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 - .4..............
Do you have
"browser stop sending data, no need to recover" message before those two?
This looks like empty POST message caused by client
cheating C-L header.
Anyhow post the log snippet for the
ajp_connection_tcp_send_message callee.
> [debug] jk_is_input_event::jk_connect.c (986): error event during poll
> on socket sd = 65 (event=24)
It means that Tomcat closed the connection (POLLHUP | POLLERR)
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org