Bug 41535 - IIS 6+JK 1.2.0+Tomcat 5.5.20 web app FORM based auth hangs
Summary: IIS 6+JK 1.2.0+Tomcat 5.5.20 web app FORM based auth hangs
Status: RESOLVED INVALID
Alias: None
Product: Tomcat Connectors
Classification: Unclassified
Component: Common (show other bugs)
Version: unspecified
Hardware: Other Windows XP
: P2 major (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-02-03 20:50 UTC by Jason Anderson
Modified: 2008-10-05 03:09 UTC (History)
0 users



Attachments
worker.properties (589 bytes, text/plain)
2007-02-03 20:53 UTC, Jason Anderson
Details
rewrite.properties (244 bytes, text/plain)
2007-02-03 20:55 UTC, Jason Anderson
Details
uriworkermap.properties (75 bytes, text/plain)
2007-02-03 20:55 UTC, Jason Anderson
Details
login.jsp (615 bytes, text/plain)
2007-02-03 20:57 UTC, Jason Anderson
Details
isapi_redirect.log (39.37 KB, text/plain)
2007-02-03 21:02 UTC, Jason Anderson
Details
rewrite.properties (228 bytes, text/plain)
2007-02-03 21:02 UTC, Jason Anderson
Details
uriworkermap.properties (69 bytes, text/plain)
2007-02-03 21:03 UTC, Jason Anderson
Details
New set of logs with WireShark PCAP file (10.19 KB, application/zip)
2007-02-06 09:48 UTC, Jason Anderson
Details
ISAPI Redirector 1.2.20 with extended debugging (356.00 KB, application/octet-stream)
2007-02-06 22:23 UTC, Tim Whittington
Details
isapi_redirect.log with debug version of .dll (49.28 KB, text/plain)
2007-02-06 22:43 UTC, Jason Anderson
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jason Anderson 2007-02-03 20:50:50 UTC
When attempting to use FORM based authentication from a web app running in 
Tomcat 5.5.20 (JBoss 4.0.5GA), with JK 1.2.0 via ajp13 (localhost) and IIS 6, 
the form submit via POST hangs.

All other content via the isapi_redirect.dll works just fine.  Also, if you 
change the login.jsp to GET method, it works.  Seems to be problem with just 
POST.

redirect log reports:

[Sat Feb 03 21:31:40 2007] [24540:19136] [error] jk_isapi_plugin.c (624): 
ReadClient failed with 0000274c
[Sat Feb 03 21:31:40 2007] [24540:19136] [info]  jk_ajp_common.c (1110): () 
receiving data from client failed. Connection aborted or network problems
[Sat Feb 03 21:31:40 2007] [24540:19136] [info]  jk_ajp_common.c (1893): 
(ajp13w) sending request to tomcat failed, because of client read error without 
recovery in send loop attempt=0
[Sat Feb 03 21:31:40 2007] [24540:19136] [debug] jk_isapi_plugin.c (1093): 
service() returned OK
[Sat Feb 03 21:31:40 2007] [24540:19136] [debug] jk_ajp_common.c (2229): will 
be shutting down socket 1336 for worker ajp13w



Incomplete POST gets to Tomcat, as Tomcat reports:

2007-02-03 21:30:40,349 DEBUG [org.apache.catalina.connector.CoyoteAdapter]  
Requested cookie session id is CEEA5F00E90E6F3A63C44E81609E6CBB
2007-02-03 21:30:40,349 DEBUG 
[org.apache.catalina.authenticator.AuthenticatorBase] Security checking request 
POST /iffl/tims/content/j_security_check
2007-02-03 21:30:40,365 DEBUG [org.apache.jk.common.JkInputStream] doRead false 
0 0
2007-02-03 21:30:40,365 DEBUG [org.apache.jk.common.ChannelSocket] receive() 
...
2007-02-03 21:31:40,351 INFO  [org.apache.jk.common.JkInputStream] Receiving: 
getting request body chunk -3 4
2007-02-03 21:31:40,351 DEBUG 
[org.apache.catalina.authenticator.FormAuthenticator] Authenticating 
username 'null'
Comment 1 Jason Anderson 2007-02-03 20:53:54 UTC
Created attachment 19505 [details]
worker.properties
Comment 2 Jason Anderson 2007-02-03 20:55:38 UTC
Created attachment 19506 [details]
rewrite.properties
Comment 3 Jason Anderson 2007-02-03 20:55:56 UTC
Created attachment 19507 [details]
uriworkermap.properties
Comment 4 Jason Anderson 2007-02-03 20:57:07 UTC
Created attachment 19508 [details]
login.jsp
Comment 5 Jason Anderson 2007-02-03 21:02:01 UTC
Created attachment 19509 [details]
isapi_redirect.log
Comment 6 Jason Anderson 2007-02-03 21:02:36 UTC
Created attachment 19510 [details]
rewrite.properties
Comment 7 Jason Anderson 2007-02-03 21:03:13 UTC
Created attachment 19511 [details]
uriworkermap.properties
Comment 8 Tim Whittington 2007-02-04 13:45:11 UTC
The error you're getting is a socket timeout - e.g. JK is timing out trying to
read from the request stream.
This is probably due to a confusion between the user agent, IIS and JK about the
content length available to read in the request.
In this case, the incoming request seems to be indicating that there are 45
bytes to read, which JK is timing out on.

Can you attach a trace of the HTTP traffic for the failed request - preferrably
a TCP level trace with Wireshark/Ethereal, but an HTTP trace from something like
Fiddler (http://www.fiddlertool.com/fiddler/) would help.
Comment 9 Jason Anderson 2007-02-06 09:48:52 UTC
Created attachment 19531 [details]
New set of logs with WireShark PCAP file
Comment 10 Jason Anderson 2007-02-06 09:52:57 UTC
I should note that POST via IIS -> redirect -> JK is now failing for *some* 
other forms.  One is another JSP login form and another is a standard 
submit/post form.

It doesn't seem that HTTP POST via the director is stable [in my environment].
Comment 11 Karl-Heinz 2007-02-06 12:08:28 UTC
Can you also attach a pcap file concerning the connection browser to IIS?
Comment 12 Jason Anderson 2007-02-06 12:14:00 UTC
The conversations between browser (10.1.1.120) to IIS (10.1.1.103) to JK 
(10.1.1.10) are all in the same pcap. 

Comment 13 Tim Whittington 2007-02-06 22:23:00 UTC
Created attachment 19533 [details]
ISAPI Redirector 1.2.20 with extended debugging

My reading of the pcap trace is that the HTTP is well formed, and that the 44
bytes of form POST data are in the original request packet - i.e. they should
already be available to IIS and be accessible from the ECB without a ReadClient
call.

There's some strangeness in the logs (namely the "() receiving data from client
failed..."), which may point to something bad as the worker name isn't being
printed, although the code looks fine and the worker name is printed
successfully in the error handler later.

I've attached a build of 1.2.20 that has extended debug statements around the
ISAPI ReadClient. This should give us an idea of whether this is a JK problem
or an IIS problem.
Basically if the ECB reports anything other than 44 total or < 44 available,
then it's an IIS issue.
Otherwise something is broken in JK.

Can you replicate the issue with this build and reattach the isapi_redirect.log
Comment 14 Jason Anderson 2007-02-06 22:43:23 UTC
Created attachment 19534 [details]
isapi_redirect.log with debug version of .dll
Comment 15 Jason Anderson 2007-02-06 23:24:52 UTC
It appears to be working now at least on W2K3 servers.  I tried it initially on 
W2K3 server "A" with the new debug .dll and it failed.

I then tried another W2K3 server "B" which IIS had clean config+redirector and 
it worked.   I compared configs, and the only difference was that on the  
server "A" HTTP compression had been turned on at one point (supposedly it was 
turned off again - was off in IISAdmin, but metabase still had some 
differences).  So I re-turned it off to be sure.  And that's when POST started 
working again on both A and B.

Or it could just be late (past midnight MST) or phase of moon.

However, POST still hangs on Windows XP.   If that's the only environment, then 
I can probably work around as it is only used for developer testing and not 
production.  XP doesn't do HTTP compression.
Comment 16 Tim Whittington 2007-02-07 12:04:03 UTC
The logs attached indicate that IIS is at fault here - it's reporting 44 bytes
total (which is correct), but none available (which isn't correct).
Either the 44 bytes should be in the ECB, or the ReadClient should succeed.