You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Marcin Zajączkowski <ms...@wp.pl> on 2007/01/26 12:24:24 UTC
mod_jk -> tomcat sending delay
Hi,
I observe in mod_jk's log errors:
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
or refused connection. No response has been sent to the client (yet)
In the rush hours (20-30 requests/second) up to several entries per hour.
Sometimes it's followed by:
[error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
tomcat failed. Tomcat is probably not started or is listening on the
wrong port
or
[error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
can't receive the response message from tomcat, network problems or
tomcat is down (127.0.0.1:8009), err=-104
but usually it is covered by another retries. It's corresponding to
exception in tomcat:
ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
java.net.SocketTimeoutException: Read timed out
*Note* Post is quite long because of info from logs. To get know what it
is about it is enough to read descriptions next to numbers.
I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
checked issues it looks like:
*1*. mod_jk talks with tomcat and some request is serviced.
(...)
[11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
protocol: Reuse is OK
[debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
slot=0 for worker ajp13w
[debug] jk_handler::mod_jk.c (2126): Service finished with status=200
for worker=wlb
*2*. A few seconds later thread is used again by an another request.
[11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
worker wlb
[debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
[debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
method=POST (...)
[debug] service::jk_lb_worker.c (840): service sticky_session=1
id='8A49C0D934C8A115342BA5CBFC79C434'
[debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
[debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
pool slot=0
[debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
[debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
retries
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
to ajp13 pos=4 len=307 max=8192
(...) [header is sent and it is received by tomcat]
*3*.
a) mod_jk tries to send body:
[11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
body to send 646 - request body to resend 0
b) tomcat is waiting for it:
DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
org.apache.jk.common.HandlerRequest@1ca8b3d
DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
DEBUG [org.apache.jk.common.ChannelSocket] receive()
*4*. 5 seconds later (connector timeout is 5000ms) tomcat throws exception:
[11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
request
java.net.SocketTimeoutException: Read timed out
and resets connection (regarding to tcpdump log)
*5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
sending a body:
[11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
(893): sending to ajp13 pos=4 len=652 max=8192
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
12 34 02 88 02 86 3C 3F (...) [body's dump]
*6*. Unfortunately connection was already reseted by tomcat and mod_jk
got info about that:
[11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
(942): (ajp13w) Tomcat has forced a connection close for socket 28
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
or refused connection. No response has been sent to the client (yet)
[info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
tomcat failed, recoverable operation attempt=0
*7*. mod_jk tries to do send request again to tomcat:
[11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
request to tomcat failed, recoverable operation attempt=1
[debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
[debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
to 127.0.0.1:8009
[debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
127.0.0.1:8009
[debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
28 to (127.0.0.1:8009)
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
to ajp13 pos=4 len=307 max=8192
Usually (but not always) it is able to do that without errors.
I sniffed into mod_jk source code, but I haven't found a place where it
can stuck.
*Question*
What can be delay (about 8 seconds) in mod_jk between sending HTTP
header and HTTP content caused by?
I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
mod_jk configuration is quite simple, without load balancing (and wasn't
changed for years).
<workers.properties>
workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
workers.java_home=/jboss/java
ps=/
worker.list=wlb,jkstatus
worker.ajp13w.type=ajp13
worker.ajp13w.host=localhost
worker.ajp13w.port=8009
worker.wlb.type=lb
worker.wlb.balance_workers=ajp13w
</workers.properties>
The only change in mod_jk config was:
JkShmSize 1024k
<servel.xml>
<Connector port="8009" address="127.0.0.1"
minProcessors="5" maxProcessors="100"
enableLookups="false" acceptCount="100" debug="0"
connectionTimeout="5000" useURIValidationHack="false"
protocol="AJP/1.3"/>
</servel.xml>
Thanks for your advice
Marcin
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: [OT] mod_jk -> tomcat sending delay
Posted by babu <ba...@gmail.com>.
Hi,
We tried updating it once but we have problem in load balancing and we went
back to original mod_jk which we working fine. We upgraded to 1.2.15, but we
are planing to try out new one 1.2.20, but I am watching this discussion
board and there issues even in 1.2.20 and I have posted because of thius.
With regards,
Babulal Satasiya
Rainer Jung-3 wrote:
>
> Version 1.2.6 of mod_jk is an antiquity. First update before
> investigating the problem.
>
> babu wrote:
>> Hi,
>>
>> We are also facing same problem and we are using mod_jk 1.2.6 with apache
>> 2.0.53 and tomcat 5.0.27. Mod_jk is configured with loadbalancer. We have
>> Apache+mod_jk with LB + 9 tomcats in backend. Mod_jk is set with sticky
>> bit
>> set.
>>
>> Partial workers.properites
>>
>> worker.list=loadbalancer
>> worker.loadbalancer.type=lb
>> worker.loadbalancer.balanced_workers=tc_1_1,tc_1_2,tc_1_3,tc_2_1,tc_2_2,tc_2_3,tc_3_1,tc_3_2,tc_3_3
>>
>>
>>
>> worker.tc_1_1.host=cna-prod-app-25
>> worker.tc_1_1.port=8000
>> worker.tc_1_1.type=ajp13
>> worker.tc_1_1.lbfactor=1
>> worker.tc_1_1.cachesize=50
>> worker.tc_1_1.cache_timeout=180
>> worker.tc_1_1.socket_timeout=300
>> worker.tc_1_1.socket_keepalive=1
>> worker.tc_1_1.recovery_options=0
>> worker.tc_1_1.sticky_session=1
>>
>> server.xml
>>
>> <Connector port="8000"
>> protocol="AJP/1.3"
>> address="cna-prod-app-25"
>> minProcessors="50"
>> maxProcessors="100"
>> enableLookups="false"
>> debug="0"
>> URIEncoding="UTF-8"
>> connectionTimeout="180000"
>> />
>>
>> I found in one of discussion board, that connection timeout in sever.xml
>> and
>> timeout parameters in workers.properties should be matched properly and
>> also
>> found that in server.xml its in miliseconds and in workers.properites it
>> is
>> seconds.
>>
>>
>> We do not find any issue at client side but erorr keeps going in mod_jk
>> log.
>> ( I am not sure of client side issues are there or not)
>>
>>
>> mod_jk log
>>
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_3_3 failed errno = 0
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.109:8002), err=-1
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_1_3 failed errno = 0
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8001), err=-1
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_2_2 failed errno = 0
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.109:8000), err=-1
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=0
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8002), err=-1
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=1
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8002), err=-1
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=0
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8001), err=-1
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_2_2 failed errno = 0
>>
>> If you find any soluttion to this then please update me with your
>> solution.
>>
>> with regards,
>>
>> Babulal Satasiya
>>
>> Cisco System Inc.
>> Sanjose, CA.
>>
>>
>> Marcin Zajączkowski wrote:
>>> Hi,
>>>
>>>
>>> I observe in mod_jk's log errors:
>>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>>> or refused connection. No response has been sent to the client (yet)
>>>
>>> In the rush hours (20-30 requests/second) up to several entries per
>>> hour.
>>> Sometimes it's followed by:
>>> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
>>> tomcat failed. Tomcat is probably not started or is listening on the
>>> wrong port
>>> or
>>> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
>>> can't receive the response message from tomcat, network problems or
>>> tomcat is down (127.0.0.1:8009), err=-104
>>>
>>> but usually it is covered by another retries. It's corresponding to
>>> exception in tomcat:
>>> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
>>> java.net.SocketTimeoutException: Read timed out
>>>
>>> *Note* Post is quite long because of info from logs. To get know what it
>>> is about it is enough to read descriptions next to numbers.
>>>
>>>
>>> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
>>> checked issues it looks like:
>>>
>>> *1*. mod_jk talks with tomcat and some request is serviced.
>>>
>>> (...)
>>> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
>>> protocol: Reuse is OK
>>> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
>>> slot=0 for worker ajp13w
>>> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
>>> for worker=wlb
>>>
>>> *2*. A few seconds later thread is used again by an another request.
>>>
>>> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
>>> worker wlb
>>> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
>>> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
>>> method=POST (...)
>>> [debug] service::jk_lb_worker.c (840): service sticky_session=1
>>> id='8A49C0D934C8A115342BA5CBFC79C434'
>>> [debug] service::jk_lb_worker.c (860): service worker=ajp13w
>>> route=ajp13w
>>> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
>>> pool slot=0
>>> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling
>>> done
>>> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
>>> retries
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>>> to ajp13 pos=4 len=307 max=8192
>>> (...) [header is sent and it is received by tomcat]
>>>
>>> *3*.
>>> a) mod_jk tries to send body:
>>>
>>> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
>>> body to send 646 - request body to resend 0
>>>
>>> b) tomcat is waiting for it:
>>> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
>>> org.apache.jk.common.HandlerRequest@1ca8b3d
>>> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
>>> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>>>
>>> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws
>>> exception:
>>> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
>>> request
>>> java.net.SocketTimeoutException: Read timed out
>>> and resets connection (regarding to tcpdump log)
>>>
>>> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
>>> sending a body:
>>> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
>>> (893): sending to ajp13 pos=4 len=652 max=8192
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
>>> 12 34 02 88 02 86 3C 3F (...) [body's dump]
>>>
>>> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
>>> got info about that:
>>> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
>>> (942): (ajp13w) Tomcat has forced a connection close for socket 28
>>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>>> or refused connection. No response has been sent to the client (yet)
>>> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
>>> tomcat failed, recoverable operation attempt=0
>>>
>>> *7*. mod_jk tries to do send request again to tomcat:
>>> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
>>> request to tomcat failed, recoverable operation attempt=1
>>> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
>>> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
>>> to 127.0.0.1:8009
>>> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
>>> 127.0.0.1:8009
>>> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
>>> 28 to (127.0.0.1:8009)
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>>> to ajp13 pos=4 len=307 max=8192
>>>
>>> Usually (but not always) it is able to do that without errors.
>>>
>>> I sniffed into mod_jk source code, but I haven't found a place where it
>>> can stuck.
>>>
>>>
>>> *Question*
>>> What can be delay (about 8 seconds) in mod_jk between sending HTTP
>>> header and HTTP content caused by?
>>>
>>>
>>> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
>>> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>>>
>>> mod_jk configuration is quite simple, without load balancing (and wasn't
>>> changed for years).
>>>
>>> <workers.properties>
>>> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
>>> workers.java_home=/jboss/java
>>> ps=/
>>>
>>> worker.list=wlb,jkstatus
>>>
>>> worker.ajp13w.type=ajp13
>>> worker.ajp13w.host=localhost
>>> worker.ajp13w.port=8009
>>>
>>> worker.wlb.type=lb
>>> worker.wlb.balance_workers=ajp13w
>>> </workers.properties>
>>>
>>> The only change in mod_jk config was:
>>> JkShmSize 1024k
>>>
>>> <servel.xml>
>>> <Connector port="8009" address="127.0.0.1"
>>> minProcessors="5" maxProcessors="100"
>>> enableLookups="false" acceptCount="100" debug="0"
>>> connectionTimeout="5000" useURIValidationHack="false"
>>> protocol="AJP/1.3"/>
>>> </servel.xml>
>>>
>>>
>>> Thanks for your advice
>>> Marcin
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To start a new topic, e-mail: users@tomcat.apache.org
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>>
>>>
>>
>
> --
> kippdata informationstechnologie GmbH
> Bornheimer Str. 33a
> 53111 Bonn
>
> Tel.: 0228/98549-0
> Fax: 0228/98549-50
> www.kippdata.de
> =======================
> kippdata informationstechnologie GmbH
> Bornheimer Str. 33a
> D-53111 Bonn
>
> Tel.: +49/0228/98549-0
> Fax: +49/0228/98549-50
> www.kippdata.de
>
> ---------------------------------------------------------------------
> To start a new topic, e-mail: users@tomcat.apache.org
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
>
--
View this message in context: http://www.nabble.com/mod_jk--%3E-tomcat-sending-delay-tf3121799.html#a8896404
Sent from the Tomcat - User mailing list archive at Nabble.com.
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: [OT] mod_jk -> tomcat sending delay
Posted by nuka <nu...@gmail.com>.
Hello,
I am facing to a similar exception in tomcat:
ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
java.net.SocketTimeoutException: Read timed out
having a timeout for Tomcat AJP connector = 1 minute.
It seems that this timeout has a good value, but I still get this kind of
errors
thanks,
Rainer Jung-3 wrote:
>
> Version 1.2.6 of mod_jk is an antiquity. First update before
> investigating the problem.
>
> babu wrote:
>> Hi,
>>
>> We are also facing same problem and we are using mod_jk 1.2.6 with apache
>> 2.0.53 and tomcat 5.0.27. Mod_jk is configured with loadbalancer. We have
>> Apache+mod_jk with LB + 9 tomcats in backend. Mod_jk is set with sticky
>> bit
>> set.
>>
>> Partial workers.properites
>>
>> worker.list=loadbalancer
>> worker.loadbalancer.type=lb
>> worker.loadbalancer.balanced_workers=tc_1_1,tc_1_2,tc_1_3,tc_2_1,tc_2_2,tc_2_3,tc_3_1,tc_3_2,tc_3_3
>>
>>
>>
>> worker.tc_1_1.host=cna-prod-app-25
>> worker.tc_1_1.port=8000
>> worker.tc_1_1.type=ajp13
>> worker.tc_1_1.lbfactor=1
>> worker.tc_1_1.cachesize=50
>> worker.tc_1_1.cache_timeout=180
>> worker.tc_1_1.socket_timeout=300
>> worker.tc_1_1.socket_keepalive=1
>> worker.tc_1_1.recovery_options=0
>> worker.tc_1_1.sticky_session=1
>>
>> server.xml
>>
>> <Connector port="8000"
>> protocol="AJP/1.3"
>> address="cna-prod-app-25"
>> minProcessors="50"
>> maxProcessors="100"
>> enableLookups="false"
>> debug="0"
>> URIEncoding="UTF-8"
>> connectionTimeout="180000"
>> />
>>
>> I found in one of discussion board, that connection timeout in sever.xml
>> and
>> timeout parameters in workers.properties should be matched properly and
>> also
>> found that in server.xml its in miliseconds and in workers.properites it
>> is
>> seconds.
>>
>>
>> We do not find any issue at client side but erorr keeps going in mod_jk
>> log.
>> ( I am not sure of client side issues are there or not)
>>
>>
>> mod_jk log
>>
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_3_3 failed errno = 0
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.109:8002), err=-1
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_1_3 failed errno = 0
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8001), err=-1
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_2_2 failed errno = 0
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.109:8000), err=-1
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=0
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8002), err=-1
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=1
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8002), err=-1
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=0
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
>> the response message from tomcat, network problems or tomcat is down
>> (128.107.229.110:8001), err=-1
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
>> network problems. No response has been sent to the client (yet)
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
>> from
>> tomcat failed, recoverable operation. err=2
>> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1477)]: Error connecting to
>> tomcat. Tomcat is probably not started or is listening on the wrong port.
>> worker=tc_2_2 failed errno = 0
>>
>> If you find any soluttion to this then please update me with your
>> solution.
>>
>> with regards,
>>
>> Babulal Satasiya
>>
>> Cisco System Inc.
>> Sanjose, CA.
>>
>>
>> Marcin Zajączkowski wrote:
>>> Hi,
>>>
>>>
>>> I observe in mod_jk's log errors:
>>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>>> or refused connection. No response has been sent to the client (yet)
>>>
>>> In the rush hours (20-30 requests/second) up to several entries per
>>> hour.
>>> Sometimes it's followed by:
>>> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
>>> tomcat failed. Tomcat is probably not started or is listening on the
>>> wrong port
>>> or
>>> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
>>> can't receive the response message from tomcat, network problems or
>>> tomcat is down (127.0.0.1:8009), err=-104
>>>
>>> but usually it is covered by another retries. It's corresponding to
>>> exception in tomcat:
>>> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
>>> java.net.SocketTimeoutException: Read timed out
>>>
>>> *Note* Post is quite long because of info from logs. To get know what it
>>> is about it is enough to read descriptions next to numbers.
>>>
>>>
>>> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
>>> checked issues it looks like:
>>>
>>> *1*. mod_jk talks with tomcat and some request is serviced.
>>>
>>> (...)
>>> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
>>> protocol: Reuse is OK
>>> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
>>> slot=0 for worker ajp13w
>>> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
>>> for worker=wlb
>>>
>>> *2*. A few seconds later thread is used again by an another request.
>>>
>>> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
>>> worker wlb
>>> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
>>> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
>>> method=POST (...)
>>> [debug] service::jk_lb_worker.c (840): service sticky_session=1
>>> id='8A49C0D934C8A115342BA5CBFC79C434'
>>> [debug] service::jk_lb_worker.c (860): service worker=ajp13w
>>> route=ajp13w
>>> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
>>> pool slot=0
>>> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling
>>> done
>>> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
>>> retries
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>>> to ajp13 pos=4 len=307 max=8192
>>> (...) [header is sent and it is received by tomcat]
>>>
>>> *3*.
>>> a) mod_jk tries to send body:
>>>
>>> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
>>> body to send 646 - request body to resend 0
>>>
>>> b) tomcat is waiting for it:
>>> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
>>> org.apache.jk.common.HandlerRequest@1ca8b3d
>>> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
>>> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>>>
>>> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws
>>> exception:
>>> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
>>> request
>>> java.net.SocketTimeoutException: Read timed out
>>> and resets connection (regarding to tcpdump log)
>>>
>>> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
>>> sending a body:
>>> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
>>> (893): sending to ajp13 pos=4 len=652 max=8192
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
>>> 12 34 02 88 02 86 3C 3F (...) [body's dump]
>>>
>>> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
>>> got info about that:
>>> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
>>> (942): (ajp13w) Tomcat has forced a connection close for socket 28
>>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>>> or refused connection. No response has been sent to the client (yet)
>>> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
>>> tomcat failed, recoverable operation attempt=0
>>>
>>> *7*. mod_jk tries to do send request again to tomcat:
>>> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
>>> request to tomcat failed, recoverable operation attempt=1
>>> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
>>> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
>>> to 127.0.0.1:8009
>>> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
>>> 127.0.0.1:8009
>>> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
>>> 28 to (127.0.0.1:8009)
>>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>>> to ajp13 pos=4 len=307 max=8192
>>>
>>> Usually (but not always) it is able to do that without errors.
>>>
>>> I sniffed into mod_jk source code, but I haven't found a place where it
>>> can stuck.
>>>
>>>
>>> *Question*
>>> What can be delay (about 8 seconds) in mod_jk between sending HTTP
>>> header and HTTP content caused by?
>>>
>>>
>>> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
>>> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>>>
>>> mod_jk configuration is quite simple, without load balancing (and wasn't
>>> changed for years).
>>>
>>> <workers.properties>
>>> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
>>> workers.java_home=/jboss/java
>>> ps=/
>>>
>>> worker.list=wlb,jkstatus
>>>
>>> worker.ajp13w.type=ajp13
>>> worker.ajp13w.host=localhost
>>> worker.ajp13w.port=8009
>>>
>>> worker.wlb.type=lb
>>> worker.wlb.balance_workers=ajp13w
>>> </workers.properties>
>>>
>>> The only change in mod_jk config was:
>>> JkShmSize 1024k
>>>
>>> <servel.xml>
>>> <Connector port="8009" address="127.0.0.1"
>>> minProcessors="5" maxProcessors="100"
>>> enableLookups="false" acceptCount="100" debug="0"
>>> connectionTimeout="5000" useURIValidationHack="false"
>>> protocol="AJP/1.3"/>
>>> </servel.xml>
>>>
>>>
>>> Thanks for your advice
>>> Marcin
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To start a new topic, e-mail: users@tomcat.apache.org
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>>
>>>
>>
>
> --
> kippdata informationstechnologie GmbH
> Bornheimer Str. 33a
> 53111 Bonn
>
> Tel.: 0228/98549-0
> Fax: 0228/98549-50
> www.kippdata.de
> =======================
> kippdata informationstechnologie GmbH
> Bornheimer Str. 33a
> D-53111 Bonn
>
> Tel.: +49/0228/98549-0
> Fax: +49/0228/98549-50
> www.kippdata.de
>
> ---------------------------------------------------------------------
> To start a new topic, e-mail: users@tomcat.apache.org
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
>
--
View this message in context: http://www.nabble.com/mod_jk--%3E-tomcat-sending-delay-tf3121799.html#a9061753
Sent from the Tomcat - User mailing list archive at Nabble.com.
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: [OT] mod_jk -> tomcat sending delay
Posted by Rainer Jung <ra...@kippdata.de>.
Version 1.2.6 of mod_jk is an antiquity. First update before
investigating the problem.
babu wrote:
> Hi,
>
> We are also facing same problem and we are using mod_jk 1.2.6 with apache
> 2.0.53 and tomcat 5.0.27. Mod_jk is configured with loadbalancer. We have
> Apache+mod_jk with LB + 9 tomcats in backend. Mod_jk is set with sticky bit
> set.
>
> Partial workers.properites
>
> worker.list=loadbalancer
> worker.loadbalancer.type=lb
> worker.loadbalancer.balanced_workers=tc_1_1,tc_1_2,tc_1_3,tc_2_1,tc_2_2,tc_2_3,tc_3_1,tc_3_2,tc_3_3
>
>
>
> worker.tc_1_1.host=cna-prod-app-25
> worker.tc_1_1.port=8000
> worker.tc_1_1.type=ajp13
> worker.tc_1_1.lbfactor=1
> worker.tc_1_1.cachesize=50
> worker.tc_1_1.cache_timeout=180
> worker.tc_1_1.socket_timeout=300
> worker.tc_1_1.socket_keepalive=1
> worker.tc_1_1.recovery_options=0
> worker.tc_1_1.sticky_session=1
>
> server.xml
>
> <Connector port="8000"
> protocol="AJP/1.3"
> address="cna-prod-app-25"
> minProcessors="50"
> maxProcessors="100"
> enableLookups="false"
> debug="0"
> URIEncoding="UTF-8"
> connectionTimeout="180000"
> />
>
> I found in one of discussion board, that connection timeout in sever.xml and
> timeout parameters in workers.properties should be matched properly and also
> found that in server.xml its in miliseconds and in workers.properites it is
> seconds.
>
>
> We do not find any issue at client side but erorr keeps going in mod_jk log.
> ( I am not sure of client side issues are there or not)
>
>
> mod_jk log
>
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_3_3 failed errno = 0
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.109:8002), err=-1
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_1_3 failed errno = 0
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8001), err=-1
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_2_2 failed errno = 0
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.109:8000), err=-1
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=0
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8002), err=-1
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=1
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8002), err=-1
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=0
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8001), err=-1
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_2_2 failed errno = 0
>
> If you find any soluttion to this then please update me with your solution.
>
> with regards,
>
> Babulal Satasiya
>
> Cisco System Inc.
> Sanjose, CA.
>
>
> Marcin Zajączkowski wrote:
>> Hi,
>>
>>
>> I observe in mod_jk's log errors:
>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>> or refused connection. No response has been sent to the client (yet)
>>
>> In the rush hours (20-30 requests/second) up to several entries per hour.
>> Sometimes it's followed by:
>> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
>> tomcat failed. Tomcat is probably not started or is listening on the
>> wrong port
>> or
>> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
>> can't receive the response message from tomcat, network problems or
>> tomcat is down (127.0.0.1:8009), err=-104
>>
>> but usually it is covered by another retries. It's corresponding to
>> exception in tomcat:
>> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
>> java.net.SocketTimeoutException: Read timed out
>>
>> *Note* Post is quite long because of info from logs. To get know what it
>> is about it is enough to read descriptions next to numbers.
>>
>>
>> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
>> checked issues it looks like:
>>
>> *1*. mod_jk talks with tomcat and some request is serviced.
>>
>> (...)
>> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
>> protocol: Reuse is OK
>> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
>> slot=0 for worker ajp13w
>> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
>> for worker=wlb
>>
>> *2*. A few seconds later thread is used again by an another request.
>>
>> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
>> worker wlb
>> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
>> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
>> method=POST (...)
>> [debug] service::jk_lb_worker.c (840): service sticky_session=1
>> id='8A49C0D934C8A115342BA5CBFC79C434'
>> [debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
>> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
>> pool slot=0
>> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
>> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
>> retries
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>> to ajp13 pos=4 len=307 max=8192
>> (...) [header is sent and it is received by tomcat]
>>
>> *3*.
>> a) mod_jk tries to send body:
>>
>> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
>> body to send 646 - request body to resend 0
>>
>> b) tomcat is waiting for it:
>> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
>> org.apache.jk.common.HandlerRequest@1ca8b3d
>> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
>> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>>
>> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws
>> exception:
>> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
>> request
>> java.net.SocketTimeoutException: Read timed out
>> and resets connection (regarding to tcpdump log)
>>
>> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
>> sending a body:
>> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
>> (893): sending to ajp13 pos=4 len=652 max=8192
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
>> 12 34 02 88 02 86 3C 3F (...) [body's dump]
>>
>> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
>> got info about that:
>> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
>> (942): (ajp13w) Tomcat has forced a connection close for socket 28
>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>> or refused connection. No response has been sent to the client (yet)
>> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
>> tomcat failed, recoverable operation attempt=0
>>
>> *7*. mod_jk tries to do send request again to tomcat:
>> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
>> request to tomcat failed, recoverable operation attempt=1
>> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
>> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
>> to 127.0.0.1:8009
>> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
>> 127.0.0.1:8009
>> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
>> 28 to (127.0.0.1:8009)
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>> to ajp13 pos=4 len=307 max=8192
>>
>> Usually (but not always) it is able to do that without errors.
>>
>> I sniffed into mod_jk source code, but I haven't found a place where it
>> can stuck.
>>
>>
>> *Question*
>> What can be delay (about 8 seconds) in mod_jk between sending HTTP
>> header and HTTP content caused by?
>>
>>
>> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
>> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>>
>> mod_jk configuration is quite simple, without load balancing (and wasn't
>> changed for years).
>>
>> <workers.properties>
>> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
>> workers.java_home=/jboss/java
>> ps=/
>>
>> worker.list=wlb,jkstatus
>>
>> worker.ajp13w.type=ajp13
>> worker.ajp13w.host=localhost
>> worker.ajp13w.port=8009
>>
>> worker.wlb.type=lb
>> worker.wlb.balance_workers=ajp13w
>> </workers.properties>
>>
>> The only change in mod_jk config was:
>> JkShmSize 1024k
>>
>> <servel.xml>
>> <Connector port="8009" address="127.0.0.1"
>> minProcessors="5" maxProcessors="100"
>> enableLookups="false" acceptCount="100" debug="0"
>> connectionTimeout="5000" useURIValidationHack="false"
>> protocol="AJP/1.3"/>
>> </servel.xml>
>>
>>
>> Thanks for your advice
>> Marcin
>>
>>
>> ---------------------------------------------------------------------
>> To start a new topic, e-mail: users@tomcat.apache.org
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>>
>
--
kippdata informationstechnologie GmbH
Bornheimer Str. 33a
53111 Bonn
Tel.: 0228/98549-0
Fax: 0228/98549-50
www.kippdata.de
=======================
kippdata informationstechnologie GmbH
Bornheimer Str. 33a
D-53111 Bonn
Tel.: +49/0228/98549-0
Fax: +49/0228/98549-50
www.kippdata.de
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: [OT] mod_jk -> tomcat sending delay
Posted by babu <ba...@gmail.com>.
Hi,
We are also facing same problem and we are using mod_jk 1.2.6 with apache
2.0.53 and tomcat 5.0.27. Mod_jk is configured with loadbalancer. We have
Apache+mod_jk with LB + 9 tomcats in backend. Mod_jk is set with sticky bit
set.
Partial workers.properites
worker.list=loadbalancer
worker.loadbalancer.type=lb
worker.loadbalancer.balanced_workers=tc_1_1,tc_1_2,tc_1_3,tc_2_1,tc_2_2,tc_2_3,tc_3_1,tc_3_2,tc_3_3
worker.tc_1_1.host=cna-prod-app-25
worker.tc_1_1.port=8000
worker.tc_1_1.type=ajp13
worker.tc_1_1.lbfactor=1
worker.tc_1_1.cachesize=50
worker.tc_1_1.cache_timeout=180
worker.tc_1_1.socket_timeout=300
worker.tc_1_1.socket_keepalive=1
worker.tc_1_1.recovery_options=0
worker.tc_1_1.sticky_session=1
server.xml
<Connector port="8000"
protocol="AJP/1.3"
address="cna-prod-app-25"
minProcessors="50"
maxProcessors="100"
enableLookups="false"
debug="0"
URIEncoding="UTF-8"
connectionTimeout="180000"
/>
I found in one of discussion board, that connection timeout in sever.xml and
timeout parameters in workers.properties should be matched properly and also
found that in server.xml its in miliseconds and in workers.properites it is
seconds.
We do not find any issue at client side but erorr keeps going in mod_jk log.
( I am not sure of client side issues are there or not)
mod_jk log
[Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=2
[Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1477)]: Error connecting to
tomcat. Tomcat is probably not started or is listening on the wrong port.
worker=tc_3_3 failed errno = 0
[Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.109:8002), err=-1
[Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=2
[Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1477)]: Error connecting to
tomcat. Tomcat is probably not started or is listening on the wrong port.
worker=tc_1_3 failed errno = 0
[Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.110:8001), err=-1
[Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=2
[Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1477)]: Error connecting to
tomcat. Tomcat is probably not started or is listening on the wrong port.
worker=tc_2_2 failed errno = 0
[Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.109:8000), err=-1
[Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=0
[Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.110:8002), err=-1
[Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=1
[Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.110:8002), err=-1
[Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=0
[Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
the response message from tomcat, network problems or tomcat is down
(128.107.229.110:8001), err=-1
[Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
network problems. No response has been sent to the client (yet)
[Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving from
tomcat failed, recoverable operation. err=2
[Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1477)]: Error connecting to
tomcat. Tomcat is probably not started or is listening on the wrong port.
worker=tc_2_2 failed errno = 0
If you find any soluttion to this then please update me with your solution.
with regards,
Babulal Satasiya
Cisco System Inc.
Sanjose, CA.
Marcin Zajączkowski wrote:
>
> Hi,
>
>
> I observe in mod_jk's log errors:
> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
> or refused connection. No response has been sent to the client (yet)
>
> In the rush hours (20-30 requests/second) up to several entries per hour.
> Sometimes it's followed by:
> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
> tomcat failed. Tomcat is probably not started or is listening on the
> wrong port
> or
> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
> can't receive the response message from tomcat, network problems or
> tomcat is down (127.0.0.1:8009), err=-104
>
> but usually it is covered by another retries. It's corresponding to
> exception in tomcat:
> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
> java.net.SocketTimeoutException: Read timed out
>
> *Note* Post is quite long because of info from logs. To get know what it
> is about it is enough to read descriptions next to numbers.
>
>
> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
> checked issues it looks like:
>
> *1*. mod_jk talks with tomcat and some request is serviced.
>
> (...)
> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
> protocol: Reuse is OK
> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
> slot=0 for worker ajp13w
> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
> for worker=wlb
>
> *2*. A few seconds later thread is used again by an another request.
>
> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
> worker wlb
> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
> method=POST (...)
> [debug] service::jk_lb_worker.c (840): service sticky_session=1
> id='8A49C0D934C8A115342BA5CBFC79C434'
> [debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
> pool slot=0
> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
> retries
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
> to ajp13 pos=4 len=307 max=8192
> (...) [header is sent and it is received by tomcat]
>
> *3*.
> a) mod_jk tries to send body:
>
> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
> body to send 646 - request body to resend 0
>
> b) tomcat is waiting for it:
> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
> org.apache.jk.common.HandlerRequest@1ca8b3d
> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>
> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws
> exception:
> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
> request
> java.net.SocketTimeoutException: Read timed out
> and resets connection (regarding to tcpdump log)
>
> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
> sending a body:
> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
> (893): sending to ajp13 pos=4 len=652 max=8192
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
> 12 34 02 88 02 86 3C 3F (...) [body's dump]
>
> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
> got info about that:
> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
> (942): (ajp13w) Tomcat has forced a connection close for socket 28
> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
> or refused connection. No response has been sent to the client (yet)
> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
> tomcat failed, recoverable operation attempt=0
>
> *7*. mod_jk tries to do send request again to tomcat:
> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
> request to tomcat failed, recoverable operation attempt=1
> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
> to 127.0.0.1:8009
> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
> 127.0.0.1:8009
> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
> 28 to (127.0.0.1:8009)
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
> to ajp13 pos=4 len=307 max=8192
>
> Usually (but not always) it is able to do that without errors.
>
> I sniffed into mod_jk source code, but I haven't found a place where it
> can stuck.
>
>
> *Question*
> What can be delay (about 8 seconds) in mod_jk between sending HTTP
> header and HTTP content caused by?
>
>
> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>
> mod_jk configuration is quite simple, without load balancing (and wasn't
> changed for years).
>
> <workers.properties>
> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
> workers.java_home=/jboss/java
> ps=/
>
> worker.list=wlb,jkstatus
>
> worker.ajp13w.type=ajp13
> worker.ajp13w.host=localhost
> worker.ajp13w.port=8009
>
> worker.wlb.type=lb
> worker.wlb.balance_workers=ajp13w
> </workers.properties>
>
> The only change in mod_jk config was:
> JkShmSize 1024k
>
> <servel.xml>
> <Connector port="8009" address="127.0.0.1"
> minProcessors="5" maxProcessors="100"
> enableLookups="false" acceptCount="100" debug="0"
> connectionTimeout="5000" useURIValidationHack="false"
> protocol="AJP/1.3"/>
> </servel.xml>
>
>
> Thanks for your advice
> Marcin
>
>
> ---------------------------------------------------------------------
> To start a new topic, e-mail: users@tomcat.apache.org
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
>
--
View this message in context: http://www.nabble.com/mod_jk--%3E-tomcat-sending-delay-tf3121799.html#a8894508
Sent from the Tomcat - User mailing list archive at Nabble.com.
---------------------------------------------------------------------
To start a new topic, e-mail: users@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 -> tomcat sending delay
Posted by Rainer Jung <ra...@kippdata.de>.
Hi Marcin,
Thank you for your careful analysis.
Your connectionTimeout on the tomcat side is way too low. This timeout
is meant for cutting connections after a longer idle time. It should
coincide with the connection_pool_timeout of mod_jk (although tomcat
uses milliseconds and mod_jk seconds). Normal values are 10 minutes or
maybe 1 minute.
Concerning your question, what could be blocking between forwarding the
headers and the body: reading the request body from the browser sits in
between. If you increase the JklogLevel to trace, you will find an
"enter" and an "exit" message for the nested functions
ajp_read_into_msg_buff() and ajp_read_fully_from_server() which read the
POST body from the browser (via apache methods). Most likely you will
find out, that the time passes by between enter and exit of
ajp_read_fully_from_server().
Hope that helps?
Regards,
Rainer
Marcin Zajączkowski wrote:
> Hi,
>
>
> I observe in mod_jk's log errors:
> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
> or refused connection. No response has been sent to the client (yet)
>
> In the rush hours (20-30 requests/second) up to several entries per hour.
> Sometimes it's followed by:
> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
> tomcat failed. Tomcat is probably not started or is listening on the
> wrong port
> or
> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
> can't receive the response message from tomcat, network problems or
> tomcat is down (127.0.0.1:8009), err=-104
>
> but usually it is covered by another retries. It's corresponding to
> exception in tomcat:
> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
> java.net.SocketTimeoutException: Read timed out
>
> *Note* Post is quite long because of info from logs. To get know what it
> is about it is enough to read descriptions next to numbers.
>
>
> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
> checked issues it looks like:
>
> *1*. mod_jk talks with tomcat and some request is serviced.
>
> (...)
> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
> protocol: Reuse is OK
> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
> slot=0 for worker ajp13w
> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
> for worker=wlb
>
> *2*. A few seconds later thread is used again by an another request.
>
> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
> worker wlb
> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
> method=POST (...)
> [debug] service::jk_lb_worker.c (840): service sticky_session=1
> id='8A49C0D934C8A115342BA5CBFC79C434'
> [debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
> pool slot=0
> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
> retries
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
> to ajp13 pos=4 len=307 max=8192
> (...) [header is sent and it is received by tomcat]
>
> *3*.
> a) mod_jk tries to send body:
>
> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
> body to send 646 - request body to resend 0
>
> b) tomcat is waiting for it:
> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
> org.apache.jk.common.HandlerRequest@1ca8b3d
> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>
> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws exception:
> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
> request
> java.net.SocketTimeoutException: Read timed out
> and resets connection (regarding to tcpdump log)
>
> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
> sending a body:
> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
> (893): sending to ajp13 pos=4 len=652 max=8192
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000 12
> 34 02 88 02 86 3C 3F (...) [body's dump]
>
> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
> got info about that:
> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
> (942): (ajp13w) Tomcat has forced a connection close for socket 28
> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
> or refused connection. No response has been sent to the client (yet)
> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
> tomcat failed, recoverable operation attempt=0
>
> *7*. mod_jk tries to do send request again to tomcat:
> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
> request to tomcat failed, recoverable operation attempt=1
> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
> to 127.0.0.1:8009
> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
> 127.0.0.1:8009
> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
> 28 to (127.0.0.1:8009)
> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
> to ajp13 pos=4 len=307 max=8192
>
> Usually (but not always) it is able to do that without errors.
>
> I sniffed into mod_jk source code, but I haven't found a place where it
> can stuck.
>
>
> *Question*
> What can be delay (about 8 seconds) in mod_jk between sending HTTP
> header and HTTP content caused by?
>
>
> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>
> mod_jk configuration is quite simple, without load balancing (and wasn't
> changed for years).
>
> <workers.properties>
> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
> workers.java_home=/jboss/java
> ps=/
>
> worker.list=wlb,jkstatus
>
> worker.ajp13w.type=ajp13
> worker.ajp13w.host=localhost
> worker.ajp13w.port=8009
>
> worker.wlb.type=lb
> worker.wlb.balance_workers=ajp13w
> </workers.properties>
>
> The only change in mod_jk config was:
> JkShmSize 1024k
>
> <servel.xml>
> <Connector port="8009" address="127.0.0.1"
> minProcessors="5" maxProcessors="100"
> enableLookups="false" acceptCount="100" debug="0"
> connectionTimeout="5000" useURIValidationHack="false"
> protocol="AJP/1.3"/>
> </servel.xml>
>
>
> Thanks for your advice
> Marcin
---------------------------------------------------------------------
To start a new topic, e-mail: users@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 -> tomcat sending delay
Posted by Mladen Turk <ml...@gmail.com>.
Marcin Zajączkowski wrote:
> Hi,
>
>
> I observe in mod_jk's log errors:
> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
> or refused connection. No response has been sent to the client (yet)
>
All those error messages are 'normal' :)
>
> <servel.xml>
> <Connector port="8009" address="127.0.0.1"
> minProcessors="5" maxProcessors="100"
> enableLookups="false" acceptCount="100" debug="0"
> connectionTimeout="5000" useURIValidationHack="false"
> protocol="AJP/1.3"/>
> </servel.xml>
>
Increase connectionTimeout to 60000 (1 minute).
The reason you are seeing those messages is because
Tomcat closes his part of connection.
If you wish to lower down the delay add
worker.ajpw13.connection_timeout=60000
worker.ajpw13.prepost_timeout=60000
Regards,
Mladen.
---------------------------------------------------------------------
To start a new topic, e-mail: users@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 -> tomcat sending delay
Posted by Babu Satasiya <ba...@gmail.com>.
Hi,
oh!!
Its always - Apache+mod_jk - connecting to multiple tomcates on different
systems.
With regards,
Babu Satasiya
Propes, Barry L [GCG-NAOT] wrote:
>
> New using Tomcat 5 series -- just where is mod_jk within Tomcat?
>
> Please let me know.
>
> Thanks,
>
>
> -----Original Message-----
> From: babu [mailto:babulalsatasiya@gmail.com]
> Sent: Friday, February 09, 2007 4:11 PM
> To: users@tomcat.apache.org
> Subject: Re: [OT] mod_jk -> tomcat sending delay
>
>
>
> Hi,
>
> We are also facing same problem and we are using mod_jk 1.2.6 with apache
> 2.0.53 and tomcat 5.0.27. Mod_jk is configured with loadbalancer. We have
> Apache+mod_jk with LB + 9 tomcats in backend. Mod_jk is set with sticky
> bit
> set.
>
> Partial workers.properites
>
> worker.list=loadbalancer
> worker.loadbalancer.type=lb
> worker.loadbalancer.balanced_workers=tc_1_1,tc_1_2,tc_1_3,tc_2_1,tc_2_2,tc_2_3,tc_3_1,tc_3_2,tc_3_3
>
>
>
> worker.tc_1_1.host=cna-prod-app-25
> worker.tc_1_1.port=8000
> worker.tc_1_1.type=ajp13
> worker.tc_1_1.lbfactor=1
> worker.tc_1_1.cachesize=50
> worker.tc_1_1.cache_timeout=180
> worker.tc_1_1.socket_timeout=300
> worker.tc_1_1.socket_keepalive=1
> worker.tc_1_1.recovery_options=0
> worker.tc_1_1.sticky_session=1
>
> server.xml
>
> <Connector port="8000"
> protocol="AJP/1.3"
> address="cna-prod-app-25"
> minProcessors="50"
> maxProcessors="100"
> enableLookups="false"
> debug="0"
> URIEncoding="UTF-8"
> connectionTimeout="180000"
> />
>
> I found in one of discussion board, that connection timeout in sever.xml
> and
> timeout parameters in workers.properties should be matched properly and
> also
> found that in server.xml its in miliseconds and in workers.properites it
> is
> seconds.
>
>
> We do not find any issue at client side but erorr keeps going in mod_jk
> log.
> ( I am not sure of client side issues are there or not)
>
>
> mod_jk log
>
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:00:55 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_3_3 failed errno = 0
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.109:8002), err=-1
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:01:21 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_1_3 failed errno = 0
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8001), err=-1
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:01:41 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_2_2 failed errno = 0
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.109:8000), err=-1
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:01:44 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=0
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8002), err=-1
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:03 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=1
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8002), err=-1
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:49 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=0
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (783)]: ERROR: can't receive
> the response message from tomcat, network problems or tomcat is down
> (128.107.229.110:8001), err=-1
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1250)]: Tomcat is down or
> network problems. No response has been sent to the client (yet)
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1449)]: ERROR: Receiving
> from
> tomcat failed, recoverable operation. err=2
> [Fri Feb 09 22:02:59 2007] [jk_ajp_common.c (1477)]: Error connecting to
> tomcat. Tomcat is probably not started or is listening on the wrong port.
> worker=tc_2_2 failed errno = 0
>
> If you find any soluttion to this then please update me with your
> solution.
>
> with regards,
>
> Babulal Satasiya
>
> Cisco System Inc.
> Sanjose, CA.
>
>
> Marcin Zajączkowski wrote:
>>
>> Hi,
>>
>>
>> I observe in mod_jk's log errors:
>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>> or refused connection. No response has been sent to the client (yet)
>>
>> In the rush hours (20-30 requests/second) up to several entries per hour.
>> Sometimes it's followed by:
>> [error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to
>> tomcat failed. Tomcat is probably not started or is listening on the
>> wrong port
>> or
>> [error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w)
>> can't receive the response message from tomcat, network problems or
>> tomcat is down (127.0.0.1:8009), err=-104
>>
>> but usually it is covered by another retries. It's corresponding to
>> exception in tomcat:
>> ERROR [org.apache.jk.common.HandlerRequest] Error decoding request
>> java.net.SocketTimeoutException: Read timed out
>>
>> *Note* Post is quite long because of info from logs. To get know what it
>> is about it is enough to read descriptions next to numbers.
>>
>>
>> I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few
>> checked issues it looks like:
>>
>> *1*. mod_jk talks with tomcat and some request is serviced.
>>
>> (...)
>> [11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13
>> protocol: Reuse is OK
>> [debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool
>> slot=0 for worker ajp13w
>> [debug] jk_handler::mod_jk.c (2126): Service finished with status=200
>> for worker=wlb
>>
>> *2*. A few seconds later thread is used again by an another request.
>>
>> [11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a
>> worker wlb
>> [debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
>> [debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1
>> method=POST (...)
>> [debug] service::jk_lb_worker.c (840): service sticky_session=1
>> id='8A49C0D934C8A115342BA5CBFC79C434'
>> [debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
>> [debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection
>> pool slot=0
>> [debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
>> [debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2
>> retries
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>> to ajp13 pos=4 len=307 max=8192
>> (...) [header is sent and it is received by tomcat]
>>
>> *3*.
>> a) mod_jk tries to send body:
>>
>> [11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request
>> body to send 646 - request body to resend 0
>>
>> b) tomcat is waiting for it:
>> DEBUG [org.apache.jk.common.ChannelSocket] Call next 0
>> org.apache.jk.common.HandlerRequest@1ca8b3d
>> DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
>> DEBUG [org.apache.jk.common.ChannelSocket] receive()
>>
>> *4*. 5 seconds later (connector timeout is 5000ms) tomcat throws
>> exception:
>> [11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding
>> request
>> java.net.SocketTimeoutException: Read timed out
>> and resets connection (regarding to tcpdump log)
>>
>> *5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts
>> sending a body:
>> [11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c
>> (893): sending to ajp13 pos=4 len=652 max=8192
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000
>> 12 34 02 88 02 86 3C 3F (...) [body's dump]
>>
>> *6*. Unfortunately connection was already reseted by tomcat and mod_jk
>> got info about that:
>> [11:10:40] [info] ajp_connection_tcp_get_message::jk_ajp_common.c
>> (942): (ajp13w) Tomcat has forced a connection close for socket 28
>> [error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down
>> or refused connection. No response has been sent to the client (yet)
>> [info] ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from
>> tomcat failed, recoverable operation attempt=0
>>
>> *7*. mod_jk tries to do send request again to tomcat:
>> [11:10:40] [info] ajp_service::jk_ajp_common.c (1916): (ajp13w) sending
>> request to tomcat failed, recoverable operation attempt=1
>> [debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
>> [debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28
>> to 127.0.0.1:8009
>> [debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
>> 127.0.0.1:8009
>> [debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket
>> 28 to (127.0.0.1:8009)
>> [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending
>> to ajp13 pos=4 len=307 max=8192
>>
>> Usually (but not always) it is able to do that without errors.
>>
>> I sniffed into mod_jk source code, but I haven't found a place where it
>> can stuck.
>>
>>
>> *Question*
>> What can be delay (about 8 seconds) in mod_jk between sending HTTP
>> header and HTTP content caused by?
>>
>>
>> I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with
>> Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.
>>
>> mod_jk configuration is quite simple, without load balancing (and wasn't
>> changed for years).
>>
>> <workers.properties>
>> workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
>> workers.java_home=/jboss/java
>> ps=/
>>
>> worker.list=wlb,jkstatus
>>
>> worker.ajp13w.type=ajp13
>> worker.ajp13w.host=localhost
>> worker.ajp13w.port=8009
>>
>> worker.wlb.type=lb
>> worker.wlb.balance_workers=ajp13w
>> </workers.properties>
>>
>> The only change in mod_jk config was:
>> JkShmSize 1024k
>>
>> <servel.xml>
>> <Connector port="8009" address="127.0.0.1"
>> minProcessors="5" maxProcessors="100"
>> enableLookups="false" acceptCount="100" debug="0"
>> connectionTimeout="5000" useURIValidationHack="false"
>> protocol="AJP/1.3"/>
>> </servel.xml>
>>
>>
>> Thanks for your advice
>> Marcin
>>
>>
>> ---------------------------------------------------------------------
>> To start a new topic, e-mail: users@tomcat.apache.org
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>>
>
> --
> View this message in context:
> http://www.nabble.com/mod_jk--%3E-tomcat-sending-delay-tf3121799.html#a8894508
> Sent from the Tomcat - User mailing list archive at Nabble.com.
>
>
> ---------------------------------------------------------------------
> To start a new topic, e-mail: users@tomcat.apache.org
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
>
--
View this message in context: http://www.nabble.com/mod_jk--%3E-tomcat-sending-delay-tf3121799.html#a8955371
Sent from the Tomcat - User mailing list archive at Nabble.com.
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org