[
https://issues.apache.org/jira/browse/DIRMINA-687?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12708321#action_12708321
]
Emmanuel Lecharny commented on DIRMINA-687:
-------------------------------------------
Ok, I now understand what happens.
The doDecode method in the MyRequestDecoder class create a new thread, and
launch it. This thread does a sleep(500), nothing more. This has the side
effect to let the main thread processing another event. If this new thread is
not created, then the program works well. Here are the logs I got :
[06:38:34]-main INFO [testcase.MinaRegressionTest] - START
...
[06:38:34]-NioProcessor-2 INFO [testcase.MyIoHandler] - Creation of session 5
[06:38:34]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_OPENED to session 5
Queue : [SESSION_OPENED, ]
[06:38:34]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
SESSION_OPENED for session 5
[06:38:34]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_OPENED event for session 5
[06:38:34]-MinaThread INFO [testcase.MyIoHandler] - Session 5 is opened
[06:38:34]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event SESSION_OPENED has been fired for session 5
...
[06:38:34]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 5
Queue : [MESSAGE_RECEIVED, ]
...
[06:38:34]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
MESSAGE_RECEIVED for session 5
[06:38:34]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 5
[06:38:34]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 5
...
[06:38:34]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 5
Queue : [MESSAGE_RECEIVED, ]
...
[06:38:34]-MinaThread DEBUG [testcase.MyRequestDecoder] - Sleep for 1000 ms for
session 5
[06:38:34]-Thread-0 DEBUG [testcase.MyRequestDecoder] - Sleep for 500 ms for
session 5
...
[06:38:34]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
MESSAGE_RECEIVED for session 5
[06:38:34]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 5
[06:38:34]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 5
...
[06:38:35]-Thread-0 DEBUG [testcase.MyRequestDecoder] - Wake up now from a 500
ms sleep for session 5
...
[06:38:35]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_CLOSED to session 5
Queue : [SESSION_CLOSED, ]
[06:38:35]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
SESSION_CLOSED for session 5
[06:38:35]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_CLOSED event for session 5
[06:38:35]-MinaThread INFO [testcase.MyIoHandler] - 5> Session closed
[06:38:35]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event SESSION_CLOSED has been fired for session 5
...
[06:38:35]-MinaThread DEBUG [testcase.MyRequestDecoder] - Wake up now from a
1000 ms sleep for session 5
[06:38:35]-MinaThread ERROR [testcase.MyRequestDecoder] - 5> !session closed
before decoding completes!
[06:38:35]-MinaThread ERROR [testcase.MyRequestDecoder] - 5> !decoding for
closed session!
[06:38:35]-MinaThread DEBUG [testcase.MyRequestDecoder] - Sleep for 1000 ms for
session 5
[06:38:35]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event MESSAGE_RECEIVED has been fired for session 5
...
[06:38:37]-main INFO [testcase.MinaRegressionTest] - Received: 0
[06:38:37]-main INFO [testcase.MinaRegressionTest] - Sent: 10
[06:38:37]-main INFO [testcase.MinaRegressionTest] - FINISH
Now, the question is why does the MinaThread can process another event while
the thread is supposed to be 'busy' ?
> 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
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Fix For: 2.0.0-RC1
>
> 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.
