You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2010/02/27 01:55:33 UTC
DO NOT REPLY [Bug 48826] New: POST request causes access violation
in isapi_redirect 1.2.29 (X64)
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
Summary: POST request causes access violation in isapi_redirect
1.2.29 (X64)
Product: Tomcat Connectors
Version: unspecified
Platform: PC
OS/Version: Windows Server 2008 (Longhorn)
Status: NEW
Severity: major
Priority: P2
Component: isapi
AssignedTo: dev@tomcat.apache.org
ReportedBy: bgstewart@covad.net
I installed 1.2.29 to fix the issue with chunked POST requests. Now I am seeing
instability with ordinary POST requests.
In particular, RequestParamExample from the Tomcat 6.0.24 package crashes
isapi_redirect when I press the Submit Query button, which sends a small POST
request.
This is the X64 binary from
http://www.apache.org/dist/tomcat/tomcat-connectors/jk/binaries/win64/jk-1.2.29/amd64
installed with IIS7.
The isapi_redirect crashes before sending anything about the request to the
Tomcat.
I am using https: -- I didn't think to try http: before I reverted the server
to 1.2.28. If doing that would provide essential information, I can reconfigure
and try it.
The Windows Event Log records this:
Faulting application w3wp.exe, version 7.0.6002.18005, time stamp 0x49e03238,
faulting module isapi_redirect.dll, version 1.2.29.0, time stamp 0x4b83cd06,
exception code 0xc0000005, fault offset 0x00000000000066a6,
process id 0x10b4, application start time 0x01cab7409f9be334.
After a few of these failures, the IIS "DefaultAppPool" stops and has to be
restarted.
I have no X64 development environment available here, so I don't know much more
than that.
With trace level logging, the tail end of the log is:
[Fri Feb 26 19:16:17.785 2010] [4708:4148] [debug]
init_ws_service::jk_isapi_plugin.c (2795): Reading extension header
HTTP_TOMCATQUERY0000000010000000: (null)
[Fri Feb 26 19:16:17.800 2010] [4708:4148] [debug]
init_ws_service::jk_isapi_plugin.c (2850): Applying service extensions
[Fri Feb 26 19:16:17.816 2010] [4708:4148] [debug]
init_ws_service::jk_isapi_plugin.c (3105): Service protocol=HTTP/1.1
method=POST host=192.168.150.158 addr=192.168.150.158 name=192.168.160.15
port=443 auth= user= uri=/examples/servlets/servlet/RequestParamExample
[Fri Feb 26 19:16:17.847 2010] [4708:4148] [debug]
init_ws_service::jk_isapi_plugin.c (3117): Service request headers=12
attributes=9 chunked=no content-length=25 available=25
[Fri Feb 26 19:16:17.863 2010] [4708:4148] [trace]
init_ws_service::jk_isapi_plugin.c (3127): exit
[Fri Feb 26 19:16:17.878 2010] [4708:4148] [trace]
wc_get_worker_for_name::jk_worker.c (106): enter
[Fri Feb 26 19:16:17.894 2010] [4708:4148] [debug]
wc_get_worker_for_name::jk_worker.c (116): found a worker devlb
[Fri Feb 26 19:16:17.910 2010] [4708:4148] [trace]
wc_get_worker_for_name::jk_worker.c (118): exit
[Fri Feb 26 19:16:17.925 2010] [4708:4148] [debug]
HttpExtensionProc::jk_isapi_plugin.c (2162): got a worker for name devlb
[Fri Feb 26 19:16:17.941 2010] [4708:4148] [trace] get_endpoint::jk_lb_worker.c
(1715): enter
[Fri Feb 26 19:16:17.972 2010] [4708:4148] [trace] get_endpoint::jk_lb_worker.c
(1732): exit
[Fri Feb 26 19:16:17.988 2010] [4708:4148] [trace] service::jk_lb_worker.c
(1069): enter
[Fri Feb 26 19:16:18.003 2010] [4708:4148] [debug] service::jk_lb_worker.c
(1118): service sticky_session=1 id='empty'
[Fri Feb 26 19:16:18.019 2010] [4708:4148] [trace]
get_most_suitable_worker::jk_lb_worker.c (907): enter
[Fri Feb 26 19:16:18.034 2010] [4708:4148] [trace]
get_most_suitable_worker::jk_lb_worker.c (919): exit
[Fri Feb 26 19:16:18.050 2010] [4708:4148] [debug] service::jk_lb_worker.c
(1161): service worker=dev route=dev
[Fri Feb 26 19:16:18.081 2010] [4708:4148] [trace]
get_endpoint::jk_ajp13_worker.c (69): enter
[Fri Feb 26 19:16:18.097 2010] [4708:4148] [trace]
ajp_get_endpoint::jk_ajp_common.c (3040): enter
[Fri Feb 26 19:16:18.112 2010] [4708:4148] [debug]
ajp_get_endpoint::jk_ajp_common.c (3093): acquired connection pool slot=0 after
0 retries
[Fri Feb 26 19:16:18.128 2010] [4708:4148] [trace]
ajp_get_endpoint::jk_ajp_common.c (3096): exit
[Fri Feb 26 19:16:18.144 2010] [4708:4148] [trace]
get_endpoint::jk_ajp13_worker.c (71): exit
[Fri Feb 26 19:16:18.159 2010] [4708:4148] [trace] ajp_service::jk_ajp_common.c
(2286): enter
[Fri Feb 26 19:16:18.175 2010] [4708:4148] [trace]
ajp_marshal_into_msgb::jk_ajp_common.c (425): enter
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
Bruce G. Stewart <bg...@covad.net> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution| |FIXED
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #3 from Mladen Turk <mt...@apache.org> 2010-02-27 12:15:58 UTC ---
Use the version from
http://tomcat.apache.org/dev/dist/tomcat-connectors/jk/binaries/win64/jk-1.2.30/
That contains a fixed version
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #4 from Bruce G. Stewart <bg...@covad.net> 2010-02-27 21:21:30 UTC ---
This one works for all the cases I had available to throw at it, with any of
the three tomcat apr processors.
Thanks so much for fixing this so quickly.
The only oddity I see now is that certain GET requests to servlets cause isapi
log message pairs like the following. Do you know offhand, are these likely to
be a defective servlet, or configuration (improper timeouts?), or something
else?
[Sat Feb 27 15:30:54.827 2010] [4024:2796] [info] ajp_service::jk_ajp_common.c
(2540): (nfx1) sending request to tomcat failed (recoverable), because of
server error (attempt=1)
[Sat Feb 27 15:30:55.015 2010] [4024:2796] [info]
ajp_send_request::jk_ajp_common.c (1490): (nfx1) did not receive END_RESPONSE,
closing socket -1
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #6 from Bruce G. Stewart <bg...@covad.net> 2010-02-28 16:26:11 UTC ---
Rainer, thank you for the analysis.
I find that the application (Apache Axis2) sends a gratuitous "flush" or two
after the end-of-response message. As you know, flush is sent as a zero-length
send-body-chunk message. Apparently the jk sees this a protocol violation.
There must be a race in the jk between tearing down the finished request and
posting received data to it, because when I single-step the Tomcat, the isapi
doesn't complain about it.
Since (so far) I only see this behavior on infrequent administrative requests,
and it doesn't effect the results or reliability of the server, I am not going
to worry about it.
Thanks,
Bruce
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #7 from Bruce G. Stewart <bg...@covad.net> 2010-03-01 17:56:05 UTC ---
Actually, Axis2 flushes and closes the stream twice on the offending operation,
so there is an extra end-of-response packet out there. I think the extra packet
waits in the socket, so the next request on that socket fails the first
attempt. I'll file a report at their jira.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #5 from Rainer Jung <ra...@kippdata.de> 2010-02-27 22:21:26 UTC ---
I assume there are not other info, warn or error log messages directly around
those cited. In this case I only found two possible reasons, both detected in
ajp_process_callback():
1) The backend tells us to send the response header stop the client, but we
already were told to do that directly before:
1784 case JK_AJP13_SEND_HEADERS:
1785 {
1786 int rc;
1787 jk_res_data_t res;
1788 if (ae->last_op == JK_AJP13_SEND_HEADERS) {
1789 /* Do not send anything to the client.
1790 * Backend already send us the headers.
1791 */
1792 if (JK_IS_DEBUG_LEVEL(l)) {
1793 jk_log(l, JK_LOG_DEBUG,
1794 "Already received AJP13_SEND HEADERS");
1795 }
1796 JK_TRACE_EXIT(l);
1797 return JK_AJP13_ERROR;
1798 }
or
2) the backend tells us to return a body response packet to the client,
although we didn't yet receive the response headers from the backend.
1836 case JK_AJP13_SEND_BODY_CHUNK:
1837 if (ae->last_op == JK_AJP13_FORWARD_REQUEST) {
1838 /* We have just send a request but received something
1839 * that probably originates from buffered response.
1840 */
1841 if (JK_IS_DEBUG_LEVEL(l)) {
1842 jk_log(l, JK_LOG_DEBUG,
1843 "Unexpected AJP13_SEND_BODY_CHUNK");
1844 }
1845 JK_TRACE_EXIT(l);
1846 return JK_AJP13_ERROR;
1847 }
All other possible reasons for those log messages would already log something
about the precise reason directly before at least with log level info, most of
the times even error.
To decide, which of the two remaining cases it is, you might temporarily
increase the log level in lines 1793 and 1842 in jk_ajp_common.c from
JK_LOG_DEBUG to JK_LOG_INFO (or JK_LOG_ERROR) and remove the surrounding "if
(JK_IS_DEBUG_LEVEL(l)) { ... }".
Regards,
Rainer
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #1 from Mladen Turk <mt...@apache.org> 2010-02-27 08:26:44 UTC ---
Right I can confirm the regression.
We'll withdraw 1.2.29 and immediately release 1.2.30
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
DO NOT REPLY [Bug 48826] POST request causes access violation in
isapi_redirect 1.2.29 (X64)
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=48826
--- Comment #2 from Mladen Turk <mt...@apache.org> 2010-02-27 08:51:59 UTC ---
Created an attachment (id=25064)
--> (https://issues.apache.org/bugzilla/attachment.cgi?id=25064)
1.2.30-dev for x64
Could you confirm this version is OK before I tag 1.2.30
I have confirmed, but would like your confirmation as well
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org