[
https://issues.apache.org/jira/browse/DIRMINA-687?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12708315#action_12708315
]
Emmanuel Lecharny commented on DIRMINA-687:
-------------------------------------------
I have run the tests against 2.0.0-M5, and got some error, accordingly to the
report. So I went a bit further last week-end, adding some logs, up to a point
I obtained those traces :
[05:56:01]-main INFO [testcase.MinaRegressionTest] - START
...
[05:56:02]-NioProcessor-2 INFO [testcase.MyIoHandler] - Creation of session 4
[05:56:02]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_OPENED to session 4
Queue : [SESSION_OPENED, ]
[05:56:02]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
SESSION_OPENED for session 4
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_OPENED event for session 4
[05:56:02]-MinaThread INFO [testcase.MyIoHandler] - Session 4 is opened
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event SESSION_OPENED has been fired for session 4
[05:56:02]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 4
Queue : [MESSAGE_RECEIVED, ]
[05:56:02]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
MESSAGE_RECEIVED for session 4
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 4
[05:56:02]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 4
[05:56:02]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 4
Queue : [MESSAGE_RECEIVED, ]
[05:56:02]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
MESSAGE_RECEIVED for session 4
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 4
[05:56:02]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 4
[05:56:02]-NioProcessor-2 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_CLOSED to session 4
Queue : [SESSION_CLOSED, ]
[05:56:02]-MinaThread INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Processing task
SESSION_CLOSED for session 4
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_CLOSED event for session 4
[05:56:02]-MinaThread INFO [testcase.MyIoHandler] - 4> Session closed
[05:56:02]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event SESSION_CLOSED has been fired for session 4
[05:56:03]-MinaThread ERROR [testcase.MyRequestDecoder] - 4> !session closed
before decoding completes!
[05:56:03]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event MESSAGE_RECEIVED has been fired for session 4
[05:56:03]-MinaThread ERROR [testcase.MyRequestDecoder] - 4> !decoding for
closed session!
[05:56:04]-MinaThread ERROR [testcase.MyRequestDecoder] - 4> !session closed
before decoding completes!
[05:56:04]-MinaThread INFO [testcase.MyRequestDecoder] - 4> done decoding
[05:56:04]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event MESSAGE_RECEIVED has been fired for session 4
...
[05:56:04]-main INFO [testcase.MinaRegressionTest] - Received: 0
[05:56:04]-main INFO [testcase.MinaRegressionTest] - Sent: 10
[05:56:04]-main INFO [testcase.MinaRegressionTest] - FINISH
(I'm focusing on session 4, from the server side, as it's one of the failing
session. It's random...)
What puzzle me is that the MESSAGE_RECEIVED event is added twice (but that
should not be a problem). More important, the SESSION_CLOSED event is processed
*before* the MESSAGE_RECEIVED is completely processed (even if the first
message is being processed by the codec).
Still debugging ...
> 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.
