Improved request verification. Drop connections for invalid requests.

After more debugging it seems that some of the requests coming from the browser don't contain any parameters at all. The logs also show that Tomcat fails to parse the HTTP requests. This might be caused by a very fast interaction with the page, creating a lot of successive AJAX request that might cancel each other.

Previous changes have not completely resolved this issue. Re-opened.

Remove delay when starting monitoring thread (1.6 branch). This fixes the problem we saw with pings being sent repeatedly after the session-expired message was received by the bridge.

We cannot reproduce the issue with the trunk (1.7 release), so no changes were necessary.

Here's a snippet of the IE javascript log when a message missing the ice.session parameter is posted. It may be informative.

3:36:13 info [window.async-connection.heartbeat] : ping
3:36:15 debug [window.async-connection.ui] : [2511824] : send asynchronous POST
3:36:16 debug [window.async-connection.blocking] : [5947530] : receive [200] OK
3:36:16 debug [window.async-connection.ui] : [2511824] : receive [200] OK
3:36:16 debug [window.async-connection.ui] : [2510065] : send asynchronous POST
3:36:16 debug [window.async-connection] : closing previous connection...
3:36:16 debug [window.async-connection.blocking] : [5947530] : connection closed
3:36:16 debug [window.async-connection] : connect...
3:36:17 debug [window.async-connection.blocking] : [3875609] : send asynchronous POST
3:36:17 warn [window.async-connection.heartbeat] : pong lost
3:36:17 warn [window] : connection in trouble
3:36:17 debug [window.async-connection] : retry to connect...
3:36:17 debug [window.async-connection] : closing previous connection...
3:36:17 debug [window.async-connection.blocking] : [3875609] : connection closed
3:36:17 debug [window.async-connection] : connect...
3:36:18 debug [window.async-connection.blocking] : [1931911] : send asynchronous POST
3:36:18 debug [window.async-connection.ui] : [2510065] : receive [200] OK
3:36:18 info [window.async-connection.heartbeat] : pong
3:36:18 debug [window.async-connection.ui] : [2510065] : connection closed
3:36:36 info [window.async-connection.heartbeat] : ping

I would suspect that the portion of the code where it says 'retry to connect' followed by "closing previous connection" is exactly the place where the ngrep log shows the [AF] protocol packets, and that further, this is happening at exactly the wrong time for the exchange that is ongoing at that time. Once the session is expired, the following output is logged:

3:42:50 info [window.async-connection.heartbeat] : ping
3:42:50 debug [window.async-connection.ui] : [2293878] : send asynchronous POST
3:42:50 debug [window.async-connection.ui] : [2293878] : receive [200] OK
3:42:53 warn [window.async-connection.heartbeat] : pong lost
3:42:53 warn [window] : connection in trouble
3:42:53 debug [window.async-connection] : retry to connect...
3:43:10 info [window.async-connection.heartbeat] : ping
3:43:10 debug [window.async-connection.ui] : [5219114] : send asynchronous POST
3:43:11 debug [window.async-connection.ui] : [5219114] : receive [200] OK
3:43:13 warn [window.async-connection.heartbeat] : pong lost
3:43:13 warn [window] : connection in trouble
3:43:13 debug [window.async-connection] : retry to connect...
3:43:31 info [window.async-connection.heartbeat] : ping
3:43:31 debug [window.async-connection.ui] : [2266888] : send asynchronous POST
3:43:31 debug [window.async-connection.ui] : [2266888] : receive [200] OK
3:43:34 warn [window.async-connection.heartbeat] : pong lost
3:43:34 warn [window] : connection in trouble
3:43:34 debug [window.async-connection] : retry to connect...

Which provides ample opportunity for the error to occur.

More info. After a point in time, the requests as seen by ngrep on the server changes to an incorrect mode. Sometimes, this seems to be related to session timeout, but under some test runs, it is unrelated.

At startup, the following normal request response pattern occurs.

T 2008/01/28 13:11:09.359153 10.18.39.167:4813 -> 10.18.40.13:8080 [AP]
POST /component-showcase/block/ping HTTP/1.1.
Accept: /.
Accept-Language: en-ca.
Referer: http://lntest3:8080/component-showcase/.
Content-Type: application/x-www-form-urlencoded; charset=UTF-8.
UA-CPU: x86.
Accept-Encoding: gzip, deflate.
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1).
Host: lntest3:8080.
Content-Length: 111.
Connection: Keep-Alive.
Cache-Control: no-cache.
Cookie: updates=; bconn=started; JSESSIONID=E34087AB0D5FFE17AC018CB5CCD907E9.
.

T 2008/01/28 13:11:09.359175 10.18.39.167:4813 -> 10.18.40.13:8080 [AP]
ice.focus=undefined&ice.window=1333&ice.session=XwKu-5_8PWt515ZyB_z1Jg&ice.view.all=1&rand=0.3258847928923563

T 2008/01/28 13:11:09.366360 10.18.40.13:8080 -> 10.18.39.167:4813 [AP]
HTTP/1.1 200 OK.
Server: Apache-Coyote/1.1.
Content-Length: 0.
Date: Mon, 28 Jan 2008 20:10:49 GMT.
.

This is what ngrep sees. There is an initial packet, followed by another packet containing the request parameters. Then the server response with: 200 OK. Great. It's interesting that the User-agent field for IE 7 starts with Mozilla/4.0

After 4 minutes, with a session timeout of 10 minutes, we see the following:

T 2008/01/28 13:13:49.819655 10.18.39.167:4813 -> 10.18.40.13:8080 [AP]
POST /component-showcase/block/ping HTTP/1.1.
Accept: /.
Accept-Language: en-ca.
Referer: http://lntest3:8080/component-showcase/.
Content-Type: application/x-www-form-urlencoded; charset=UTF-8.
UA-CPU: x86.
Accept-Encoding: gzip, deflate.
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1).
Host: lntest3:8080.
Content-Length: 112.
Connection: Keep-Alive.
Cache-Control: no-cache.
Cookie: updates=; bconn=started; JSESSIONID=E34087AB0D5FFE17AC018CB5CCD907E9.
.

T 2008/01/28 13:13:49.819708 10.18.39.167:4813 -> 10.18.40.13:8080 [AP]
ice.focus=undefined&ice.window=1333&ice.session=XwKu-5_8PWt515ZyB_z1Jg&ice.view.all=1&rand=0.15033830778031265

So far, this is a normal request. But the following packets are quickly seen.

T 2008/01/28 13:13:49.898853 10.18.39.167:4813 -> 10.18.40.13:8080 [A]
......

T 2008/01/28 13:13:49.931582 10.18.39.167:4813 > 10.18.40.13:8080 [AF] < This is an attempt on the part of the browser
to close the socket.
......

T 2008/01/28 13:13:50.157550 10.18.39.167:4825 -> 10.18.40.13:8080 [A]
......

T 2008/01/28 13:13:50.168545 10.18.39.167:4825 -> 10.18.40.13:8080 [AP]
POST /component-showcase/block/ping HTTP/1.1.
Accept: /.
Accept-Language: en-ca.
Referer: http://lntest3:8080/component-showcase/.
Content-Type: application/x-www-form-urlencoded; charset=UTF-8.
UA-CPU: x86.
Accept-Encoding: gzip, deflate.
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1).
Host: lntest3:8080.
Content-Length: 112.
Connection: Keep-Alive.
Cache-Control: no-cache.
Cookie: updates=; bconn=started; JSESSIONID=E34087AB0D5FFE17AC018CB5CCD907E9.
.

3/10's of a second later, the browser re-pings the server, this time, it doesn't contain the request parameters and 20 seconds
later, the server responds with the error message that ice.session is not found.

T 2008/01/28 13:14:10.179375 10.18.40.13:8080 -> 10.18.39.167:4825 [A]
HTTP/1.1 500 Internal Server Error.
Server: Apache-Coyote/1.1.
Content-Type: text/html;charset=utf-8.
Content-Length: 2672.
Date: Mon, 28 Jan 2008 20:14:10 GMT.
Connection: close.

blah blah.... more stack dump follows. No session expired responses are found in the log file until 13:20:04, which is correct given my 10 minute session timeout.

So errored responses to pings at
13:14:10
13:21:42
13:22:44
13:23:44
13:24:44
13:26:04
13:27:25

Which appears to be on the 20 second ping schedule, but not always every minute. Also, once session timeout has occurred,
the problem appears very readily, but I can't say it's completely limited to being after a session times out.

Oh yes, to turn on the error logging to catch this issue in the 1.7 Beta release, one must set the log category for

com.icesoft.faces.webapp.http.servlet.ServletRequestResponse

to debug. Note that the problem will still throw a runtime exception that will pop a dialog box up at the browser. It isn't possible to carry on at this stage, as we really do need the ice.session value to create a response for the client.

We've tried all week to duplicate this issue with no success. Well, actually, we can do it, but always the browser is impaired in some way. Either Firebug is actively causing the problem, or Firebug is enabled (but not visible) and it uses up memory in the browser until the browser starts to generate anomalous requests. If the client has any ability at all to use some network sniffing tools in their environment, it would be extremely helpful. We can log what we see inside the servlets, or even inside the filter, and we'll never be able to discern who exactly is breaking things. They can either run Wireshark on a windows platform with the client as long as the server is somewhere else, or they can run ngrep on a unix platform. There is a limitation running wireshark on a windows platform where the client and the server are on the same machine.

http://www.wireshark.org/
or
http://ngrep.sourceforge.net/

Wireshark is a windows app, and pretty straightforward aside from its inability to easily monitor traffic generated and destined for the localhost (even installing the loopback adapter) but to run ngrep on a Unix platform, I've been using the following command:

ngrep -d eth0 -q -W byline -t port 8080 > capture.log &

At least we have not seen this error because of collisions caused by over use. We've had 5 browser sessions, 2 with tab key generated traffic and two external remote clients hitting the Linux server very hard for hours at a time with no duplication of the error.

Even browsers just pinging consume memory, and it's possible that there's some form of resource struggle going on in IE after some idle time. It's possible that there is some form of request sharing collision happening within our framework, but the odds are getting slimmer the more we hit on it without result. Also a remote possibility is request sharing within Tomcat, but googling for that finds no hits. I would think that scenario would have been long solved if it were a real possibility.

Greg's long running test showed the following network activity characteristic of the error:

T 10.18.39.167:3392 -> 10.18.40.13:8080 [A]
......

T 10.18.39.167:3392 -> 10.18.40.13:8080 [AP]
POST /syncTest/block/receive-updated-views HTTP/1.1.
Accept: /.
Accept-Language: en-ca.
Referer: http://lntest3:8080/syncTest/.
Content-Type: application/x-www-form-urlencoded; charset=UTF-8.
UA-CPU: x86.
Accept-Encoding: gzip, deflate.
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1).
Host: lntest3:8080.
Content-Length: 61.
Connection: Keep-Alive.
Cache-Control: no-cache.
Cookie: updates=ixK_g7cA4SVnBI8mdvhVcg:1; bconn=acquired; JSESSIONID=4A8D3BBF50EEA4C51F09C8F0B426496C.
.

T 10.18.39.167:3392 -> 10.18.40.13:8080 [AF]
......

T 10.18.40.13:8080 -> 10.18.39.167:3392 [A]
HTTP/1.1 500 Internal Server Error.
Server: Apache-Coyote/1.1.
Content-Type: text/html;charset=utf-8.
Content-Length: 2668.
Date: Thu, 24 Jan 2008 00:20:11 GMT.
Connection: close.

According to the network activity, the browser is not sending the remainder of the HTTP request, instead, it is closing the connection after sending the headers with the [AF] packet (indicating a TCP FIN).

Althought using FireBug does cause this problem to occur, we are still able to reproduce the issue without Firebug. Re-opened.

To be honest, it was Sam who noted that the problem couldn't be reproduced. I added some logging to the code to give more information if the parameter was missing, and it never fired unless we were actively poking around with Firebug.

This would explain why it occurs on each of the platforms, despite what must certainly be different request pooling mechanisms on each one.

This screen capture from Tamper shows the GET request generated by Firebug when you examine the ping request using firebug. Firebug creates a PING request, apparently from cache, which is a GET request and which does not contain the ice.session parameter in the postdata.

Greg has observed that this can be reproduced with firebug; i.e. firebug is the cause. The following GET to /ping would not be produced by the bridge normally (it would normally be a POST) shows this:

T 10.18.39.60:61950 -> 10.18.39.59:8080 [AP]
GET /component-showcase/block/ping HTTP/1.1.
Host: vorlon.ice:8080.
User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en-US; rv:1.8.1.11) Gecko/20071127 Firefox/2.0.0.11.
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5 .
Accept-Language: en-us,en;q=0.5.
Accept-Encoding: gzip,deflate.
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7.
Keep-Alive: 300.
Connection: keep-alive.
Cookie: updates=; bconn=acquired; JSESSIONID=047D76BF12C9167879868BB69524BBC0.
.

T 10.18.39.59:8080 -> 10.18.39.60:61950 [A]
HTTP/1.1 500 Internal Server Error.
Server: Apache-Coyote/1.1.
Content-Type: text/html;charset=utf-8.
Content-Length: 2672.
Date: Mon, 21 Jan 2008 19:19:25 GMT.
Connection: close.
.
<html><head><title>Apache Tomcat/5.5.25 - Error report</title><style><!--H1

H2

H3

BODY

B

P

A

A.name

HR

--></style> </head><body><h1>HTTP Status 500 - </h1><HR size="1" noshade="noshade"><p><b>ty pe</b> Exception report</p><p><b>message</b> <u></u></p><p><b>description</b> <u>The server encountered an internal error () that prevented it from fulfilling this request.</u></p><p><b>exception</b> <pre>java.lang .RuntimeException: Query does not contain parameter named: ice.session
.com.icesoft.faces.webapp.http.servlet.ServletRequestResponse.checkExistenceOf(ServletRequestResponse.java: 249)
.com.icesoft.faces.webapp.http.servlet.ServletRequestResponse.getParameter(ServletRequestResponse.java:112)
.com.icesoft

T 10.18.39.59:8080 -> 10.18.39.60:61950 [AP]
.faces.webapp.http.core.IDVerifier.service(IDVerifier.java:23)
.com.icesoft.faces.webapp.http.common.standard.PathDispatcherServer$Matcher.serviceOnMatch(PathDispatcherSe rver.java:50)
.com.icesoft.faces.webapp.http.common.standard.PathDispatcherServer.service(PathDispatcherServer.java:19)
.com.icesoft.faces.webapp.http.servlet.ThreadBlockingAdaptingServlet.service(ThreadBlockingAdaptingServlet. java:19)
.com.icesoft.faces.webapp.http.servlet.EnvironmentAdaptingServlet.service(EnvironmentAdaptingServlet.java:2 9)
.com.icesoft.faces.webapp.http.servlet.MainSessionBoundServlet.service(MainSessionBoundServlet.java:105)
.com.icesoft.faces.webapp.http.servlet.SessionDispatcher.service(SessionDispatcher.java:37)
.com.icesoft.faces.webapp.http.servlet.PathDispatcher$Matcher.serviceOnMatch(PathDispatcher.java:52)
.com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:29)
.com.icesoft.faces.webapp.http.servlet.MainServlet.service(MainServlet.java:76)
.javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
.com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:54)
.com.icesoft.icefaces.samples.showcase.util.DummyFilter.doFilter(DummyFilter.java:24)
</pre></p><p><b>note</b> <u>The full stack trace of the root cause is available in the Apache Tomcat/5.5.25 logs.</u></p><HR size="1" noshade="noshade"><h3>Apache Tomcat/5.5.25</h3></body></html>

Also happens on WebLogic and WebSphere.

This seems like it could be related to ICE-2410.

We are now able to reproduce this issue with a specific test application (incl. use of a filter) on the following app. servers:

• Tomcat 5.5
• Tomcat 6.0
• Glassfish v2

Does not appear to be a Tomcat specific issue as we originally suspected.

It seems that all the known instances of this involve the use of a filter.

Currently trying to reproduce this reliably (QA).