[
https://issues.apache.org/jira/browse/DIRMINA-687?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12708383#action_12708383
]
Emmanuel Lecharny commented on DIRMINA-687:
-------------------------------------------
Got it !
The previous trace is just confusing. The MinaThread is not sleeping _and_
executing some other task at the same time. It's just that the executor is
processing incoming events using a pool of threads (called 'workers'), but
rename those workers using the main thread name (ie, 'MinaThread'). This is
very bad ...
However, this does not solve the problem : why do we have a session event being
processed while another event is already beoing processed ? This is not what we
expect for an OrderThreadPoolExecutor...
Here is the trace :
[0]-main INFO [testcase.MinaRegressionTest] - START
...
[145]-NioProcessor-3 INFO [testcase.MyIoHandler] - Creation of session 5
[145]-NioProcessor-3 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_OPENED to session 5
Queue : [SESSION_OPENED, ]
...
[148]-MinaThread DEBUG
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] -
[worker-1]Processing task SESSION_OPENEDfor session 5
[148]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_OPENED event for session 5
[148]-MinaThread INFO [testcase.MyIoHandler] - Session 5 is opened
[148]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
SESSION_OPENED has been fired for session 5
...
[153]-NioProcessor-3 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 5
Queue : [MESSAGE_RECEIVED, ]
[153]-MinaThread DEBUG
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] -
[worker-1]Processing task MESSAGE_RECEIVEDfor session 5
[153]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 5
[153]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 5
[153]-MinaThread DEBUG [testcase.MyRequestDecoder] - Sleep for 1000 ms for
session 5
[153]-Thread-1 DEBUG [testcase.MyRequestDecoder] - Sleep for 500 ms for session
5
...
[158]-NioProcessor-3 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
MESSAGE_RECEIVED to session 5
Queue : [MESSAGE_RECEIVED, ]
...
[161]-MinaThread DEBUG
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] -
[worker-6]Processing task MESSAGE_RECEIVEDfor session 5
[161]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a MESSAGE_RECEIVED event for session 5
[161]-MinaThread INFO [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 5
...
[654]-Thread-1 DEBUG [testcase.MyRequestDecoder] - Wake up now from a 500 ms
sleep for session 5
[656]-NioProcessor-3 INFO
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] - Adding event
SESSION_CLOSED to session 5
Queue : [SESSION_CLOSED, ]
...
[663]-MinaThread DEBUG
[org.apache.mina.filter.executor.OrderedThreadPoolExecutor] -
[worker-9]Processing task SESSION_CLOSEDfor session 5
...
[665]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Firing a SESSION_CLOSED event for session 5
[665]-MinaThread INFO [testcase.MyIoHandler] - 5> Session closed
[665]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
SESSION_CLOSED has been fired for session 5
...
[1153]-MinaThread DEBUG [testcase.MyRequestDecoder] - Wake up now from a 1000
ms sleep for session 5
[1154]-MinaThread ERROR [testcase.MyRequestDecoder] - !session 5 closed before
decoding completes!
[1154]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event MESSAGE_RECEIVED has been fired for session 5
[1154]-MinaThread ERROR [testcase.MyRequestDecoder] - !decoding for closed
session 5
[1155]-MinaThread DEBUG [testcase.MyRequestDecoder] - Sleep for 1000 ms for
session 5
[1155]-Thread-11 DEBUG [testcase.MyRequestDecoder] - Sleep for 500 ms for
session 5
...
[1655]-Thread-11 DEBUG [testcase.MyRequestDecoder] - Wake up now from a 500 ms
sleep for session 5
...
[2155]-MinaThread DEBUG [testcase.MyRequestDecoder] - Wake up now from a 1000
ms sleep for session 5
[2155]-MinaThread ERROR [testcase.MyRequestDecoder] - !session 5 closed before
decoding completes!
[2156]-MinaThread INFO [testcase.MyRequestDecoder] - Done decoding for session 5
[2156]-MinaThread DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] -
Event MESSAGE_RECEIVED has been fired for session 5
...
[2686]-main INFO [testcase.MinaRegressionTest] - Received: 0
[2686]-main INFO [testcase.MinaRegressionTest] - Sent: 10
[2686]-main INFO [testcase.MinaRegressionTest] - FINISH
> 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.
