Bug 313520

Description Jan Bartel 2010-05-19 08:52:37 EDT

The problem reveals itself with DoSFilterTest and the CloseableDoSFilterTest.

Specifically, these test methods fail:
testThrottledIP
testUnavailableIP


I've had to insert a maven test exclusion for these tests so the build can proceed, so you need to use Eclipse to run these tests.

I've left debug printlns in the DoSFilter and in the AsyncContinuation class.

I've looked at the testThrottledIP problem more, so I'll explain that one, but I think the testUnavailableIP probably has the same issue.

The problem appears to be that after the continuation is suspended (in the testThrottledIP case the suspension is to delay the request), when the timer expires, the AsyncContinuation class says that it is rescheduling it (see line 660), but the request never seems to enter into the filter again.

I compared a run with jetty-7 with the same debug to jetty-8.

Here is the jetty-7 run. Not that the request FOO=5 comes back into the filter after the timer expires:

2010-05-19 13:53:45.132:INFO::Logging to StdErrLog::DEBUG=false via org.eclipse.jetty.util.log.StdErrLog
2010-05-19 13:53:45.215:INFO::jetty-7.x.y-SNAPSHOT
2010-05-19 13:53:45.333:INFO::Started LocalConnector@0.0.0.0:0
2010-05-19 13:53:45.343:INFO::Started SelectChannelConnector@127.0.0.1:52340
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=1
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=2
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=3
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=4
In request /ctx /dos/sleeper sleep=2000 FOO=null
New request: /ctx /dos/sleeper sleep=2000 FOO=5
2010-05-19 13:53:45.570:WARN::DOS ALERT: ip=127.0.0.1,session=null,user=null
DoSFilter: will delay 200
Delay continuation timed out for 5
In request /ctx /dos/sleeper sleep=2000 FOO=5
Checking acquire wait=50
Accepted: true
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=6
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=7
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=8
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=9
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=10
2010-05-19 13:53:46.905:WARN::DOS ALERT: ip=127.0.0.1,session=null,user=null
DoSFilter: will delay 200
Delay continuation timed out for 10
In request /ctx /dos/test null FOO=10
Checking acquire wait=50
Accepted: false
Not accepted
Waking up next waiting continuation, queue=3
Not accepted
Delay continuation is complete for 5
In request /ctx /dos/test null FOO=10
Checking acquire wait=50
Accepted: true
Waking up next waiting continuation, queue=3
Not accepted
Delay continuation is complete for 10
2010-05-19 13:53:48.501:INFO::DoSFilter timer exited
2010-05-19 13:53:48.501:INFO::DoSFilter timer exited


Here is a jetty-8 run. Notice that the request with FOO=5 never re-enters the filter, even though the dispatch has been requested:

2010-05-19 14:22:33.864:INFO::Logging to StdErrLog::DEBUG=false via org.eclipse.jetty.util.log.StdErrLog
2010-05-19 14:22:33.927:INFO::jetty-8.0.y.z-SNAPSHOT
2010-05-19 14:22:34.053:INFO::Started LocalConnector@0.0.0.0:0
2010-05-19 14:22:34.063:INFO::Started SelectChannelConnector@127.0.0.1:42259
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=1
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=2
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=3
In request /ctx /dos/sleeper null FOO=null
New request: /ctx /dos/sleeper null FOO=4
In request /ctx /dos/sleeper sleep=3000 FOO=null
New request: /ctx /dos/sleeper sleep=3000 FOO=5
2010-05-19 14:22:34.223:WARN::DOS ALERT: ip=127.0.0.1,session=null,user=null
DoSFilter: will delay 200 for 5
continuation = org.eclipse.jetty.server.AsyncContinuation
Delay continuation timed out for 5
Asking for dispatch of continuation for 5
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=6
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=7
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=8
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=9
In request /ctx /dos/test null FOO=null
New request: /ctx /dos/test null FOO=10
2010-05-19 14:22:35.594:WARN::DOS ALERT: ip=127.0.0.1,session=null,user=null
DoSFilter: will delay 200 for 10
continuation = org.eclipse.jetty.server.AsyncContinuation
Delay continuation timed out for 10
Asking for dispatch of continuation for 10
Delay continuation is complete for 10
2010-05-19 14:22:35.797:INFO::DoSFilter timer exited
2010-05-19 14:22:35.797:INFO::DoSFilter timer exited
Delay continuation is complete for 5


thanks
Jan