Java Mailing List Archive

http://www.junlu.com/

Home » Home (12/2007) » Apache Tomcat »

Re: [OT] mod_jk -> tomcat sending delay

babu

2007-02-09

Replies:


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@(protected)
>>> 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@(protected)
>>> To unsubscribe, e-mail: users-unsubscribe@(protected)
>>> For additional commands, e-mail: users-help@(protected)
>>>
>>>
>>>
>>
>
> --
> 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@(protected)
> To unsubscribe, e-mail: users-unsubscribe@(protected)
> For additional commands, e-mail: users-help@(protected)
>
>
>

--
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To start a new topic, e-mail: users@(protected)
To unsubscribe, e-mail: users-unsubscribe@(protected)
For additional commands, e-mail: users-help@(protected)

©2008 junlu.com - Jax Systems, LLC, U.S.A.