Qpid
  1. Qpid
  2. QPID-3879

Session#close() on session can produce spurious "dispatcher is not started" messages at ERROR to client logs

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 0.10, 0.12, 0.14, 0.16
    • Fix Version/s: 0.17
    • Component/s: Java Client
    • Labels:
      None

      Description

      Calling Session#close() on a session which is still in the process of receiving messages can result in the following error message to the client log:

      Dispatcher-Channel-1 2012-01-25 22:44:25,298 ERROR [apache.qpid.thread.LoggingUncaughtExceptionHandler] Uncaught exception in thread "Dispatcher-Channel-1"
      java.lang.IllegalStateException: dispatcher is not started
              at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3192)
              at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:55)
              at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3349)
              at java.lang.Thread.run(Thread.java:680)
      

      The problem is longstanding issue, but has probably become more noticeable since QPID-1670 which introduced a uncaught exception handle that directs such errors to SLF4J (rather than stderr). Our tests in general don't show the issue because they tend to consume all the tests message.

        Activity

        Keith Wall created issue -
        Keith Wall made changes -
        Field Original Value New Value
        Summary Session#close() on session can produce spurious "dispatcher is not started" at ERROR messages to client logs Session#close() on session can produce spurious "dispatcher is not started" messages at ERROR to client logs
        Hide
        Keith Wall added a comment -

        There is a race between the Dispatcher thread and the thread calling Session#close() (which resets to the reference to the dispatcher within #closeConsumers()).

        AMQSession$Dispatcher.java
        while (!_closed.get() && ((disp = (Dispatchable) _queue.take()) != null))
        {
            disp.dispatch(AMQSession.this);
        }
        

        In the above, the LHS of the while expression checks the Dispatcher is not closed, then the RHS blocks until a message arrive. This allows the possibility that that the Dispatcher#close() could have been called (and its reference nulled) by the time the take() returns. In the unlucky case, a message is added to the dispatch queue and AMQSession#close() occurs, causing the IllegalStateException further down the delivery path.

        The impact on the end-user application is minimal. As the session is being closed, the Broker will ensure that any unack'd messages will be redelivered. However, the error message will cause confusion to our users.

        Show
        Keith Wall added a comment - There is a race between the Dispatcher thread and the thread calling Session#close() (which resets to the reference to the dispatcher within #closeConsumers()). AMQSession$Dispatcher.java while (!_closed.get() && ((disp = (Dispatchable) _queue.take()) != null )) { disp.dispatch(AMQSession. this ); } In the above, the LHS of the while expression checks the Dispatcher is not closed, then the RHS blocks until a message arrive. This allows the possibility that that the Dispatcher#close() could have been called (and its reference nulled) by the time the take() returns. In the unlucky case, a message is added to the dispatch queue and AMQSession#close() occurs, causing the IllegalStateException further down the delivery path. The impact on the end-user application is minimal. As the session is being closed, the Broker will ensure that any unack'd messages will be redelivered. However, the error message will cause confusion to our users.
        Keith Wall made changes -
        Description Calling Session#close() on a session which is still in the process of receiving messages can result in the following error message to the client log:

        {code}
        Dispatcher-Channel-1 2012-01-25 22:44:25,298 ERROR [apache.qpid.thread.LoggingUncaughtExceptionHandler] Uncaught exception in thread "Dispatcher-Channel-1"
        java.lang.IllegalStateException: dispatcher is not started
                at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3192)
                at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:55)
                at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3349)
                at java.lang.Thread.run(Thread.java:680)
        {code}

        The problem is longstanding issue, but has probably become more noticeable since QPID-1670 which introduced a uncaught exception handle that directs such errors to SLF4J (rather than stderr). Our tests in general don't show the issue because they tend to consumer all the tests message.
        Calling Session#close() on a session which is still in the process of receiving messages can result in the following error message to the client log:

        {code}
        Dispatcher-Channel-1 2012-01-25 22:44:25,298 ERROR [apache.qpid.thread.LoggingUncaughtExceptionHandler] Uncaught exception in thread "Dispatcher-Channel-1"
        java.lang.IllegalStateException: dispatcher is not started
                at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3192)
                at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:55)
                at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3349)
                at java.lang.Thread.run(Thread.java:680)
        {code}

        The problem is longstanding issue, but has probably become more noticeable since QPID-1670 which introduced a uncaught exception handle that directs such errors to SLF4J (rather than stderr). Our tests in general don't show the issue because they tend to consume all the tests message.
        Keith Wall made changes -
        Attachment 0001-QPID-3879-MessageListener-test-improvments.patch [ 12516997 ]
        Keith Wall made changes -
        Attachment 0002-QPID-3879-Session-close-on-session-can-produce-spuri.patch [ 12516998 ]
        Keith Wall made changes -
        Attachment 0001-QPID-3879-MessageListener-test-improvments.patch [ 12516997 ]
        Keith Wall made changes -
        Attachment 0002-QPID-3879-Session-close-on-session-can-produce-spuri.patch [ 12516998 ]
        Hide
        Keith Wall added a comment -

        Commit applied. Robbie, would you mind reviewing please?

        Show
        Keith Wall added a comment - Commit applied. Robbie, would you mind reviewing please?
        Keith Wall made changes -
        Fix Version/s 0.17 [ 12320179 ]
        Fix Version/s Future [ 12315490 ]
        Affects Version/s 0.16 [ 12319870 ]
        Keith Wall made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Keith Wall made changes -
        Status In Progress [ 3 ] Ready To Review [ 10006 ]
        Keith Wall made changes -
        Assignee Keith Wall [ k-wall ] Robbie Gemmell [ gemmellr ]
        Hide
        Robbie Gemmell added a comment -

        Looks ok to me.

        Show
        Robbie Gemmell added a comment - Looks ok to me.
        Robbie Gemmell made changes -
        Status Ready To Review [ 10006 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]

          People

          • Assignee:
            Robbie Gemmell
            Reporter:
            Keith Wall
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development