HA-JMS and MDB question
I'm currently running JBoss version 4.0.1 on Suse 8.0 with java version 1.4.2_10. I'm posting this to the clustering forum as we recently moved to a clustered deployment using HA_JMS with JBoss 4.0.1 from JBoss 4.0.0 and had not seen this problem at that point. To simplify our deployment, we always run in clustered mode, whether it be a cluster of one node or many nodes. In this instance we are running with one node.
I've got several MDB's deployed that are called from a stateless session bean which opens and closes its connection with each published message. These are used on a very limited basis based on specific business scenarios. We ran into a scenario where we were getting out of memory errors due a too many open files error. To start to track this down, I added the trace logging described in the JBossMQ forum to see what was going on there as when we ran a thread dump from the ServerInfo MBean and saw quite a few threads listed for JBossMQ.
After a restart, without any invocation of any of the MDB's by our EJB's, I am seeing the following error in the server log. It appears the on of the managed socket connections is failing trying to execute the read task. At that point, unless I'm reading it incorrectly, it tell me the connection with token=ConnectionToken:ID:26 was disconnected. At that point I assumed the socket was removed.
2006-03-08 14:34:45,900 DEBUG [org.jboss.mq.il.uil2.SocketManager] Exiting on unexpected error in read task java.lang.OutOfMemoryError: unable to create new native thread at java.lang.Thread.start(Native Method) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.addThread(PooledExecutor.java:520) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(PooledExecutor.java:880) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:301) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:34:45,906 TRACE [org.jboss.mq.Connection] Notified of failure reason=Exiting on unexpected error in read task Connection@23978273[token=ConnectionToken:ID:26/b60caf67496db034de2bcf4325367cb0 rcvstate=STARTED] java.lang.reflect.UndeclaredThrowableException at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(UILClientILService.java:147) at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(SocketManager.java:405) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:347) at java.lang.Thread.run(Thread.java:534) Caused by: java.lang.OutOfMemoryError: unable to create new native thread at java.lang.Thread.start(Native Method) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.addThread(PooledExecutor.java:520) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(PooledExecutor.java:880) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:301) ... 1 more 2006-03-08 14:34:45,913 WARN [org.jboss.mq.Connection] Connection failure: org.jboss.mq.SpyJMSException: Exiting on unexpected error in read task; - nested throwable: (java.lang.reflect.UndeclaredThrowableException) at org.jboss.mq.Connection.asynchFailure(Connection.java:436) at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(UILClientILService.java:147) at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(SocketManager.java:405) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:347) at java.lang.Thread.run(Thread.java:534) Caused by: java.lang.reflect.UndeclaredThrowableException ... 4 more Caused by: java.lang.OutOfMemoryError: unable to create new native thread at java.lang.Thread.start(Native Method) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.addThread(PooledExecutor.java:520) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(PooledExecutor.java:880) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:301) ... 1 more 2006-03-08 14:34:45,914 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run 2006-03-08 14:34:45,914 TRACE [org.jboss.mq.il.uil2.SocketManager] WriteTask was interrupted java.lang.InterruptedException at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:429) at EDU.oswego.cs.dl.util.concurrent.LinkedQueue.take(LinkedQueue.java:122) at org.jboss.mq.il.uil2.SocketManager$WriteTask.run(SocketManager.java:484) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:34:45,914 TRACE [org.jboss.mq.il.uil2.SocketManager] Exiting on IOE java.io.EOFException at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2603) at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:284) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:34:45,915 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run 2006-03-08 14:34:45,915 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE java.io.EOFException at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2603) at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:284) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:34:45,916 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing 2006-03-08 14:34:45,916 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:26->close() 2006-03-08 14:34:45,916 TRACE [org.jboss.mq.sm.file.DynamicStateManager] Client id 'ID:26' is logged out. 2006-03-08 14:34:45,921 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing 2006-03-08 14:34:45,921 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run 2006-03-08 14:34:45,921 TRACE [org.jboss.mq.il.uil2.SocketManager] WriteTask was interrupted java.lang.InterruptedException at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:429) at EDU.oswego.cs.dl.util.concurrent.LinkedQueue.take(LinkedQueue.java:122) at org.jboss.mq.il.uil2.SocketManager$WriteTask.run(SocketManager.java:484) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:34:45,921 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
However, it appears it is still active as I continually see ping timed out errrors for that connection token throughout the log file. Is it possible I've got a configuration problem of some kind and this is leading to multiple open sockets resulting in my too many open files error?
2006-03-08 14:35:45,911 TRACE [org.jboss.mq.Connection] Notified of failure reason=Connection Failed Connection@23978273[token=ConnectionToken:ID:26/b60caf67496db034de2bcf4325367cb0 rcvstate=STARTED] java.io.IOException: ping timeout. at org.jboss.mq.Connection$PingTask.run(Connection.java:1377) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364) at java.lang.Thread.run(Thread.java:534) 2006-03-08 14:35:45,911 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg32822736[msgType: m_ping, msgID: -2147482404, error: null] 2006-03-08 14:35:45,911 WARN [org.jboss.mq.Connection] Connection failure: org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping timeout.) at org.jboss.mq.Connection.asynchFailure(Connection.java:436) at org.jboss.mq.Connection$PingTask.run(Connection.java:1385) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364) at java.lang.Thread.run(Thread.java:534) Caused by: java.io.IOException: ping timeout. at org.jboss.mq.Connection$PingTask.run(Connection.java:1377) ... 2 more
