https://bz.apache.org/bugzilla/show_bug.cgi?id=60511
Bug ID: 60511
Summary: org.apache.coyote.ajp.AjpNio2Protocol sends wrong data
to Apache MOD_JK connector causing connection closure
and multiple reconnects
Product: Tomcat 8
Version: 8.0.38
Hardware: PC
OS: Linux
Status: NEW
Severity: major
Priority: P2
Component: Connectors
Assignee: dev@tomcat.apache.org
Reporter: areg.vrtanes...@arm.com
Target Milestone: ----
Created attachment 34548
--> https://bz.apache.org/bugzilla/attachment.cgi?id=34548&action=edit
sanitised mod_jk debug log
Hi Team
I have been working with Atlassian and in Jira we discovered that
"org.apache.coyote.ajp.AjpNio2Protocol" in Tomcat causing troubles.
-------------------------------------------------------------------------------
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
map_uri_to_worker_ext::jk_uri_worker_map.c (1185): Attempting to map URI
'sanitised_url' from 4 maps
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
find_match::jk_uri_worker_map.c (980): Attempting to map context URI
'/*=jira-pro0-lb' source 'JkMount'
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
find_match::jk_uri_worker_map.c (993): Found a wildchar match '/*=jira-pro0-lb'
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_handler::mod_jk.c (2823): Into handler jakarta-servlet worker=jira-pro0-lb
r->proxyreq=0
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
wc_get_worker_for_name::jk_worker.c (120): found a worker jira-pro0-lb
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
wc_get_name_for_type::jk_worker.c (304): Found worker type 'lb'
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
init_ws_service::mod_jk.c (1196): Service protocol=HTTP/1.1 method=GET ssl=true
host=(null) addr=nn.nn.nn.nn name=jira.company.com port=443 auth=(null)
user=(null) laddr=nn.n.nnn.nn raddr=nn.nn.nn.nn uaddr=nn.nn.nn.nn
uri=sanitised_url
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
service::jk_lb_worker.c (1270): service sticky_session=1
id='7B8F781E9D9786ABFD7408CFC8E82667.jira-pro0-node2'
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
get_most_suitable_worker::jk_lb_worker.c (1078): searching worker for partial
sessionid 7B8F781E9D9786ABFD7408CFC8E82667.jira-pro0-node2
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
get_most_suitable_worker::jk_lb_worker.c (1086): searching worker for session
route jira-pro0-node2
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
get_most_suitable_worker::jk_lb_worker.c (1101): found worker jira-pro0-n2
(jira-pro0-node2) for route jira-pro0-node2 and partial sessionid
7B8F781E9D9786ABFD7408CFC8E82667.jira-pro0-node2
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
service::jk_lb_worker.c (1315): service worker=jira-pro0-n2
route=jira-pro0-node2 failover=false
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_get_endpoint::jk_ajp_common.c (3356): (jira-pro0-n2) acquired connection
pool slot=0 after 0 retries
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_marshal_into_msgb::jk_ajp_common.c (684): (jira-pro0-n2) ajp marshaling
done
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_service::jk_ajp_common.c (2591): processing jira-pro0-n2 with 2 retries
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_shutdown_socket::jk_connect.c (932): About to shutdown socket 38
[nn.n.nnn.nn:47243 -> nn.n.nnn.nn:8600]
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_is_input_event::jk_connect.c (1411): error event during poll on socket 38
[nn.n.nnn.nn:47243 -> nn.n.nnn.nn:8600] (event=16)
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_shutdown_socket::jk_connect.c (1016): Shutdown socket 38 [nn.n.nnn.nn:47243
-> nn.n.nnn.nn:8600] and read 0 lingering bytes in 0 sec.
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_send_request::jk_ajp_common.c (1639): (jira-pro0-n2) failed sending
request, socket 38 is not connected any more (errno=0)
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_abort_endpoint::jk_ajp_common.c (821): (jira-pro0-n2) aborting endpoint
with socket 38
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
ajp_send_request::jk_ajp_common.c (1717): (jira-pro0-n2) no usable connection
found, will create a new one, detected by connect check (1), cping (0), send
(0).
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_open_socket::jk_connect.c (675): socket TCP_NODELAY set to On
[Wed Dec 21 15:38:05.939 2016] [22617:140683748223040] [debug]
jk_open_socket::jk_connect.c (799): trying to connect socket 38 to
nn.n.nnn.nn:8600
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
jk_open_socket::jk_connect.c (825): socket 38 [nn.n.nnn.nn:47284 ->
nn.n.nnn.nn:8600] connected
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1267): sending to ajp13 pos=4
len=2291 max=8192
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0000 xx xx xx xx xx
xx xx xx xx xx xx xx xx xx xx xx - xxxxxxxxxxxxxxxx
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0010 xx xx xx xx xx
xx xx xx xx xx xx xx xx xx xx xx - xxxxxxxxxxxxxxxx
....
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 03e0 xx xx xx xx xx
xx xx xx xx xx xx xx xx xx xx xx - xxxxxxxxxxxxxxxx
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 03f0 xx xx xx xx xx
xx xx xx xx xx xx xx xx xx xx xx - xxxxxxxxxxxxxxxx
[Wed Dec 21 15:38:05.940 2016] [22617:140683748223040] [debug]
ajp_send_request::jk_ajp_common.c (1782): (jira-pro0-n2) request body to send 0
- request body to resend 0
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_get_message::jk_ajp_common.c (1462): received from ajp13
pos=0 len=2 max=8192
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0000 05 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 - ................
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [warn]
ajp_process_callback::jk_ajp_common.c (2121): (jira-pro0-n2) AJP13 protocol:
Reuse is set to false
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
ajp_reset_endpoint::jk_ajp_common.c (851): (jira-pro0-n2) resetting endpoint
with socket 38 (socket shutdown)
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
ajp_abort_endpoint::jk_ajp_common.c (821): (jira-pro0-n2) aborting endpoint
with socket 38
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
jk_shutdown_socket::jk_connect.c (932): About to shutdown socket 38
[nn.n.nnn.nn:47284 -> nn.n.nnn.nn:8600]
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
jk_is_input_event::jk_connect.c (1411): error event during poll on socket 38
[errno=107] (event=16)
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
jk_shutdown_socket::jk_connect.c (1016): Shutdown socket 38 [nn.n.nnn.nn:47284
-> nn.n.nnn.nn:8600] and read 39 lingering bytes in 0 sec.
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
ajp_done::jk_ajp_common.c (3287): recycling connection pool for worker
jira-pro0-n2 and socket -1
[Wed Dec 21 15:38:05.941 2016] [22617:140683748223040] [debug]
jk_handler::mod_jk.c (2979): Service finished with status=200 for
worker=jira-pro0-lb
-------------------------------------------------------------------------------
The part of sanitised log is attached.
This was really caused big problems to us and we rolled back to previous AJP
connector - "org.apache.coyote.ajp.AjpNioProtocol".
This may be related to bug 57674, bug 58970 or bug 42269
Regards,
Areg
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
