[jboss-remoting-issues] [JBoss JIRA] (JBREM-1308) MicroSocketClientInvoker hangs on SocketInputStream.read causing deadlock in MessageSucker.setConsuming

MicroSocketClientInvoker hangs on SocketInputStream.read causing deadlock in MessageSucker.setConsuming ------------------------------------------------------------------------------------------------------- Key: JBREM-1308 URL: https://issues.jboss.org/browse/JBREM-1308 Project: JBoss Remoting Issue Type: Bug Security Level: Public(Everyone can see) Components: transport Affects Versions: 2.2.4, 2.5.4.SP3 Environment: jboss-4.2.3.GA with jboss-messaging-1.4.5.GA and latest jboss-remoting-2_2_4, 3 node cluster, jms clustered queues Reporter: Giovanni Pelosi Assignee: Ron Sigal Attachments: jstack-20120604-0501.log, jstack-20120604-0502.log, jstack-20120604-0503.log In production enviroment, our jboss line of 3 clustered servers randomly (once a week) seemes to hang, refusing to reply to remote jms clients. Taking stack trace of all jboss instances (jstack) we always see the same pattern of deadlock: A non-pooled thread, started internally by remoting, is trying to recover a "connectionExeption" condition (ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:120)), but the task hangs (without timeout) on a socket read: (MicroSocketClientInvoker.readVersion(MicroSocketClientInvoker.java:1077)) This non-terminating network operation holds a lock, acquired in MessageSucker.suspend(MessageSucker.java:225) that in turns cause deadlock in messaging layer: org.jboss.messaging.core.impl.MessagingQueue.informSuckers(MessagingQueue.java:566) causing blocks in all jms traffic. Offending thread stack: ------------------------------------------------- "Thread-5163" daemon prio=10 tid=0x00007f1bc4d10800 nid=0x2b70 runnable [0x00007f1af61e0000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:146) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read(BufferedInputStream.java:254) - locked <0x00000006d23445f8> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(FilterInputStream.java:83) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.readVersion(MicroSocketClientInvoker.java:1077) at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:682) at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:458) at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:141) at org.jboss.remoting.Client.invoke(Client.java:1925) at org.jboss.remoting.Client.invoke(Client.java:786) at org.jboss.remoting.Client.invoke(Client.java:774) at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189) at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160) at org.jboss.jms.client.delegate.ClientConsumerDelegate.org$jboss$jms$client$delegate$ClientConsumerDelegate$close$aop(ClientConsumerDelegate.java:122) at org.jboss.jms.client.delegate.ClientConsumerDelegate$close_N4742752445160157748.invokeNext(ClientConsumerDelegate$close_N4742752445160157748.java) at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientConsumerDelegate$close_N4742752445160157748.invokeNext(ClientConsumerDelegate$close_N4742752445160157748.java) at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientConsumerDelegate$close_N4742752445160157748.invokeNext(ClientConsumerDelegate$close_N4742752445160157748.java) at org.jboss.jms.client.delegate.ClientConsumerDelegate.close(ClientConsumerDelegate.java) at org.jboss.messaging.core.impl.clusterconnection.MessageSucker.suspend(MessageSucker.java:225) - locked <0x0000000605960788> (a org.jboss.messaging.core.impl.clusterconnection.MessageSucker) at org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager$ConnectionInfo.cleanupConnection(ClusterConnectionManager.java:804) - locked <0x0000000605960ca8> (a org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager$ConnectionInfo) at org.jboss.messaging.core.impl.clusterconnection.ClusterConnectionManager$ConnectionInfo.onException(ClusterConnectionManager.java:785) at org.jboss.jms.client.remoting.ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:120) at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:498) ------------------------------------------------- JMS Layer main lock ------------------------------------------------- "Thread-5167" daemon prio=10 tid=0x00007f1be0069800 nid=0x2b82 waiting for monitor entry [0x00007f1afac2b000] java.lang.Thread.State: BLOCKED (on object monitor) at org.jboss.messaging.core.impl.clusterconnection.MessageSucker.setConsuming(MessageSucker.java:288) - waiting to lock <0x0000000605960788> (a org.jboss.messaging.core.impl.clusterconnection.MessageSucker) at org.jboss.messaging.core.impl.MessagingQueue.informSuckers(MessagingQueue.java:566) at org.jboss.messaging.core.impl.MessagingQueue.deliverInternal(MessagingQueue.java:516) at org.jboss.messaging.core.impl.ChannelSupport.deliver(ChannelSupport.java:375) - locked <0x00000006012cdd50> (a java.lang.Object) at org.jboss.jms.server.endpoint.ServerSessionEndpoint$2.run(ServerSessionEndpoint.java:1574) at org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor.run(OrderedExecutorFactory.java:120) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) ------------------------------------------------- Sample of deadlocked JMS Client Thread: ------------------------------------------- "WorkManager(2)-42959" daemon prio=10 tid=0x00007f1bb806c000 nid=0x2b6c waiting for monitor entry [0x00007f1adf230000] java.lang.Thread.State: BLOCKED (on object monitor) at org.jboss.messaging.core.impl.ChannelSupport.handle(ChannelSupport.java:242) - waiting to lock <0x00000006012cdd50> (a java.lang.Object) at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.routeInternal(MessagingPostOffice.java:2345) at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.route(MessagingPostOffice.java:515) at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendMessage(ServerConnectionEndpoint.java:769) at org.jboss.jms.server.endpoint.ServerSessionEndpoint.send(ServerSessionEndpoint.java:399) at org.jboss.jms.server.endpoint.advised.SessionAdvised.org$jboss$jms$server$endpoint$advised$SessionAdvised$send$aop(SessionAdvised.java:87) at org.jboss.jms.server.endpoint.advised.SessionAdvised$send_7280680627620114891.invokeNext(SessionAdvised$send_7280680627620114891.java) at org.jboss.jms.server.container.SecurityAspect.handleSend(SecurityAspect.java:157) at sun.reflect.GeneratedMethodAccessor153.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121) at org.jboss.jms.server.endpoint.advised.SessionAdvised$send_7280680627620114891.invokeNext(SessionAdvised$send_7280680627620114891.java) at org.jboss.jms.server.endpoint.advised.SessionAdvised.send(SessionAdvised.java) at org.jboss.jms.wireformat.SessionSendRequest.serverInvoke(SessionSendRequest.java:95) at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:157) at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:862) at org.jboss.remoting.ServerInvoker$1.run(ServerInvoker.java:1901) at org.jboss.jms.server.remoting.DirectThreadPool.run(DirectThreadPool.java:63) at org.jboss.remoting.ServerInvoker.handleOnewayInvocation(ServerInvoker.java:1912) at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:832) at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101) at org.jboss.remoting.Client.invoke(Client.java:1925) at org.jboss.remoting.Client.invoke(Client.java:786) at org.jboss.remoting.Client.invokeOneway(Client.java:837) at org.jboss.remoting.Client.invokeOneway(Client.java:1023) at org.jboss.remoting.Client.invokeOneway(Client.java:1014) at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:180) at org.jboss.jms.client.delegate.DelegateSupport.doInvokeOneway(DelegateSupport.java:165) at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$send$aop(ClientSessionDelegate.java:495) at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java) at org.jboss.jms.client.container.SessionAspect.handleSend(SessionAspect.java:661) at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect28.invoke(SessionAspect28.java) at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java) at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java) at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientSessionDelegate$send_6145266547759487588.invokeNext(ClientSessionDelegate$send_6145266547759487588.java) at org.jboss.jms.client.delegate.ClientSessionDelegate.send(ClientSessionDelegate.java) at org.jboss.jms.client.container.ProducerAspect.handleSend(ProducerAspect.java:276) at org.jboss.aop.advice.org.jboss.jms.client.container.ProducerAspect39.invoke(ProducerAspect39.java) at org.jboss.jms.client.delegate.ClientProducerDelegate$send_3961598017717988886.invokeNext(ClientProducerDelegate$send_3961598017717988886.java) at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientProducerDelegate$send_3961598017717988886.invokeNext(ClientProducerDelegate$send_3961598017717988886.java) at org.jboss.jms.client.delegate.ClientProducerDelegate.send(ClientProducerDelegate.java) at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:165) at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:208) at org.jboss.jms.client.JBossMessageProducer.send(JBossMessageProducer.java:146) at com.pirelli.pmp.jms.JmsClient.send(JmsClient.java:457) at com.pirelli.pmp.jms.JmsClient.send(JmsClient.java:606) at com.pirelli.pmp.jms.JmsClient.send(JmsClient.java:655) at com.pirelli.pmp.jms.GuiResponseQueueHelper.sendReplyMessage(GuiResponseQueueHelper.java:31) at com.pirelli.pmp.jms.GuiResponseQueueHelper.sendReplyMessage(GuiResponseQueueHelper.java:26) at com.pirelli.pmp.mdb.ActivityStarterMdb.replyToGUI(ActivityStarterMdb.java:153) at com.pirelli.pmp.mdb.ActivityStarterMdb.onMessage(ActivityStarterMdb.java:95) at sun.reflect.GeneratedMethodAccessor1335.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112) at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166) at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126) at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:249) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:268) at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:138) at $Proxy117.onMessage(Unknown Source) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.onMessage(JmsServerSession.java:178) at org.jboss.jms.client.container.ClientConsumer.callOnMessageStatic(ClientConsumer.java:160) at org.jboss.jms.client.container.SessionAspect.handleRun(SessionAspect.java:831) at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect14.invoke(SessionAspect14.java) at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java) at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170) at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105) at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java) at org.jboss.jms.client.delegate.ClientSessionDelegate.run(ClientSessionDelegate.java) at org.jboss.jms.client.JBossSession.run(JBossSession.java:199) at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:237) at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204) at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761) at java.lang.Thread.run(Thread.java:679) -------------------------------------------