[
https://issues.apache.org/jira/browse/DIRMINA-687?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Serge Baranov updated DIRMINA-687:
----------------------------------
Attachment: regression-test.zip
Once I've understood better what is happening, I managed to write a proper test
case for this bug. It appears that sessionClosed is indeed invoked before
doDecode completes the packet decoding.
Output of the test with 2.0.0-M4:
[2009-04-17 03:01:19,042] START
[2009-04-17 03:01:21,182] 9> done decoding
[2009-04-17 03:01:21,182] 9> Session closed
[2009-04-17 03:01:21,183] 4> done decoding
[2009-04-17 03:01:21,183] 4> Session closed
[2009-04-17 03:01:21,183] 10> done decoding
[2009-04-17 03:01:21,183] 10> Session closed
[2009-04-17 03:01:21,183] 18> done decoding
[2009-04-17 03:01:21,184] 18> Session closed
[2009-04-17 03:01:21,682] 14> done decoding
[2009-04-17 03:01:21,682] 20> done decoding
[2009-04-17 03:01:21,682] 14> Session closed
[2009-04-17 03:01:21,682] 20> Session closed
[2009-04-17 03:01:22,177] 13> done decoding
[2009-04-17 03:01:22,177] 17> done decoding
[2009-04-17 03:01:22,177] 13> Session closed
[2009-04-17 03:01:22,177] 17> Session closed
[2009-04-17 03:01:22,184] 2> done decoding
[2009-04-17 03:01:22,184] 2> Session closed
[2009-04-17 03:01:22,185] 5> done decoding
[2009-04-17 03:01:22,185] 5> Session closed
[2009-04-17 03:01:22,185] Received: 0
[2009-04-17 03:01:22,185] Sent: 10
[2009-04-17 03:01:22,189] FINISH
Output with 2.0.0-M5:
[2009-04-17 03:00:21,577] START
[2009-04-17 03:00:22,221] 4> Session closed
[2009-04-17 03:00:22,221] 15> Session closed
[2009-04-17 03:00:22,719] 4> !session closed before decoding completes!
[2009-04-17 03:00:22,719] 15> !session closed before decoding completes!
[2009-04-17 03:00:22,719] 15> !decoding for closed session!
[2009-04-17 03:00:22,719] 4> !decoding for closed session!
[2009-04-17 03:00:22,721] 17> Session closed
[2009-04-17 03:00:22,722] 19> Session closed
[2009-04-17 03:00:22,723] 21> Session closed
[2009-04-17 03:00:23,218] 13> Session closed
[2009-04-17 03:00:23,221] 17> !session closed before decoding completes!
[2009-04-17 03:00:23,221] 17> !decoding for closed session!
[2009-04-17 03:00:23,222] 19> !session closed before decoding completes!
[2009-04-17 03:00:23,222] 19> !decoding for closed session!
[2009-04-17 03:00:23,223] 21> !session closed before decoding completes!
[2009-04-17 03:00:23,223] 21> !decoding for closed session!
[2009-04-17 03:00:23,717] 13> !session closed before decoding completes!
[2009-04-17 03:00:23,717] 13> !decoding for closed session!
[2009-04-17 03:00:23,719] 4> !session closed before decoding completes!
[2009-04-17 03:00:23,719] 15> !session closed before decoding completes!
[2009-04-17 03:00:23,719] 4> done decoding
[2009-04-17 03:00:23,719] 15> done decoding
[2009-04-17 03:00:23,721] 6> done decoding
[2009-04-17 03:00:23,721] 6> Session closed
[2009-04-17 03:00:23,722] 10> done decoding
[2009-04-17 03:00:23,722] 9> done decoding
[2009-04-17 03:00:23,722] 10> Session closed
[2009-04-17 03:00:23,722] 9> Session closed
[2009-04-17 03:00:24,221] 17> !session closed before decoding completes!
[2009-04-17 03:00:24,221] 17> done decoding
[2009-04-17 03:00:24,222] 19> !session closed before decoding completes!
[2009-04-17 03:00:24,222] 19> done decoding
[2009-04-17 03:00:24,223] 21> !session closed before decoding completes!
[2009-04-17 03:00:24,223] 21> done decoding
[2009-04-17 03:00:24,717] 2> done decoding
[2009-04-17 03:00:24,717] 13> !session closed before decoding completes!
[2009-04-17 03:00:24,717] 2> Session closed
[2009-04-17 03:00:24,717] 13> done decoding
[2009-04-17 03:00:24,717] Received: 0
[2009-04-17 03:00:24,717] Sent: 10
[2009-04-17 03:00:24,721] FINISH
The test is designed so that the server session closes itself from another
thread while doDecode is in progress.
M4 continues decoding while M5 calls sessionClosed even if decoding is in
progress which removes session attributes used in doDecode. Order of events is
violated.
The test case is sensitive to the position of the executor in the chain.
Executor must be located before the codec. If it's after decoder, the output
will be different (you will not see "done decoding" lines at all and the bug
will be not reproducible).
With M5 the test doesn't reproduce the bug in 100% of runs, so one may need to
run several times or increase the number of messages and/or wait times.
> 2.0.0-M5 REGRESSION: sessionClosed called before doDecode completes
> -------------------------------------------------------------------
>
> Key: DIRMINA-687
> URL: https://issues.apache.org/jira/browse/DIRMINA-687
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.0-M5
> Reporter: Serge Baranov
> Priority: Critical
> Attachments: regression-test.zip
>
>
> The problem is described in detail at
> http://markmail.org/message/3iqmkdcukhygxxva .
> I did more tests by setting the CLOSED custom attribute inside sessionClosed
> and by checking for this attribute in the middle of doDecode.
> Under some networking conditions on the production server I can see the
> following in the logs:
> [2009-04-16 22:30:17,329] Session closed in the middle of decoding!
> [2009-04-16 22:30:21,126] Session closed in the middle of decoding!
> [2009-04-16 22:30:22,345] Session closed in the middle of decoding!
> [2009-04-16 22:30:22,969] Session closed in the middle of decoding!
> [2009-04-16 22:30:25,217] Session closed in the middle of decoding!
> [2009-04-16 22:30:25,840] Session closed in the middle of decoding!
> [2009-04-16 22:30:59,958] Session closed in the middle of decoding!
> Unfortunately, I didn't manage to prepare an isolated test case for this
> issue, must be some race condition which is tricky to catch.
> Most likely the problem is caused by this commit:
> http://svn.apache.org/viewvc?view=rev&revision=762167 .
> As mentioned, this problem is new to 2.0.0-M5, worked fine for many months
> with 2.0.0-M4 and previous builds. Rolling back to M4 builds fixes the
> problem instantly.
> OrderedThreadPool must guarantee the order of events, sessionClosed must not
> be called when doDecode is in progress.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
