Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@activemq.apache.org
Date: Wed, 26 Oct 2011 16:33:32 +0000 (UTC)
From: "Claudio Corsi (Updated) (JIRA)" <jira@apache.org>
To: dev@activemq.apache.org
Message-ID: 
 <40378797.18905.1319646812184.JavaMail.tomcat@hel.zones.apache.org>
In-Reply-To: 
 <898750720.16524.1319599952079.JavaMail.tomcat@hel.zones.apache.org>
Subject: [jira] [Updated] (AMQ-3567) The InactivityMonitor onException call
 interrupts itself when the readCheckTime was exceeded.
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


     [ https://issues.apache.org/jira/browse/AMQ-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Claudio Corsi updated AMQ-3567:
-------------------------------

    Attachment: inactivitymonitor.patch

Here is the patch for this issue.

The patch also includes a test that will reproduce the exception but the thing to note is that to be able to confirm that the patch worked.  I needed to use the underlying log4j logging implementation.  The test will depend on that to be able to confirm that it works.  If in the future activemq intends to use a different slf4j bridge then this test case will need to be updated.

                
> The InactivityMonitor onException call interrupts itself when the readCheckTime was exceeded.
> ---------------------------------------------------------------------------------------------
>
>                 Key: AMQ-3567
>                 URL: https://issues.apache.org/jira/browse/AMQ-3567
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: JMS client
>    Affects Versions: 5.5.0, 5.5.1
>            Reporter: Claudio Corsi
>            Priority: Trivial
>              Labels: patch
>             Fix For: 5.5.0, 5.5.1, 5.6.0
>
>         Attachments: inactivitymonitor.patch
>
>
> The process that activemq uses to check if there has been inactivity for a connection has a flaw when it tries to close the connection because of inactivity. The current process generates the following interrupt exception. 
> {code} 
> 2011-10-25 12:13:56,878 | DEBUG | org.apache.activemq.util.ServiceSupport - Could not stop service: tcp://localhost/127.0.0.1:61616. Reason: java.lang.InterruptedException
> java.lang.InterruptedException
>     at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1302)
>     at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:253)
>     at org.apache.activemq.transport.tcp.TcpTransport.doStop(TcpTransport.java:553)
>     at org.apache.activemq.util.ServiceSupport.stop(ServiceSupport.java:70)
>     at org.apache.activemq.transport.tcp.TcpTransport.stop(TcpTransport.java:570)
>     at org.apache.activemq.transport.InactivityMonitor.stop(InactivityMonitor.java:132)
>     at org.apache.activemq.transport.TransportFilter.stop(TransportFilter.java:65)
>     at org.apache.activemq.transport.WireFormatNegotiator.stop(WireFormatNegotiator.java:91)
>     at org.apache.activemq.util.ServiceSupport.dispose(ServiceSupport.java:43)
>     at org.apache.activemq.transport.failover.FailoverTransport.disposeTransport(FailoverTransport.java:207)
>     at org.apache.activemq.transport.failover.FailoverTransport.handleTransportFailure(FailoverTransport.java:223)
>     at org.apache.activemq.transport.failover.FailoverTransport$3.onException(FailoverTransport.java:184)
>     at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:101)
>     at org.apache.activemq.transport.WireFormatNegotiator.onException(WireFormatNegotiator.java:160)
>     at org.apache.activemq.transport.InactivityMonitor.onException(InactivityMonitor.java:265)
>     at org.apache.activemq.transport.InactivityMonitor$4.run(InactivityMonitor.java:185)
>     at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>     at java.lang.Thread.run(Thread.java:680)
> {code} 
> This is caused because the spawned thread in the AbstractInactivityMonitor classes readCheck method calls the onException method. This method will then call the stopMonitorThreads method which subsequently calls the shutdownNow method of the ASYNC_TASKS executor. This call causes the executor to call the interrupt method for all active threads in the executor. The problem is that the calling thread is part of the ASYNC_TASKS executor and therefore it is generating the interrupt exception. 
> Here is the stack trace of the call that is causing the interrupt. 
> {code} 
> Daemon Thread [InactivityMonitor Async Task: java.util.concurrent.ThreadPoolExecutor$Worker@66da9ea4] (Suspended (entry into method interrupt in Thread))   
>     Thread.interrupt() line: 902   
>     ThreadPoolExecutor$Worker.interruptNow() line: 855   
>     ThreadPoolExecutor.shutdownNow() line: 1167   
>     InactivityMonitor.stopMonitorThreads() line: 363   
>     InactivityMonitor.onException(IOException) line: 264   
>     InactivityMonitor$4.run() line: 185   
>     ThreadPoolExecutor$Worker.runTask(Runnable) line: 886   
>     ThreadPoolExecutor$Worker.run() line: 908   
>     Thread.run() line: 680  
> {code} 
> The solution is to replace the shutdownNow method call with shutdown. Subsequent testing with this change does not cause the interrupt exception. 
> I was able to create a testcase that reproduces this issue. The testcase uses the useInactivityMonitor=false attribute to reproduce this issue, thanks Gary for the hint. Unfortunately there aren't any steps that I can use to determine that the raised interrupted exception was raised or not. The test will pass either way. 
> A patch will be added to this issue.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira