1 Reply Latest reply on Jun 23, 2004 9:37 PM by Elias Ross

    Exiting on IOE when use JBossMQ

    zks Newbie

      Hi, I have just setup a MDB in JBoss 3.2.4, it works ok, but when I check the log file, i found some "Exiting on IOE" error, so I use TRACE want to figure out what's problem, it looks like this:

      2004-06-23 11:16:19,125 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : getThreadGroup
      2004-06-23 11:16:19,125 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : getThreadGroup
      2004-06-23 11:16:19,125 TRACE [org.jboss.mq.il.uil2.SocketManager] start called
      java.lang.Exception: Start stack trace
      at org.jboss.mq.il.uil2.SocketManager.start(SocketManager.java:94)
      at org.jboss.mq.il.uil2.UILServerILService.run(UILServerILService.java:127)
      at java.lang.Thread.run(Thread.java:534)
      2004-06-23 11:16:19,140 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2004-06-23 11:16:19,140 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2004-06-23 11:16:19,140 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2004-06-23 11:16:19,140 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_authenticate, msgID: 1
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.CheckUserMsg29283281[msgType: m_authenticate, msgID: 1, error: null]
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 22
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : authenticate
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Autenticating user null/null
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.security.SecurityManager] Username: null is authenticated
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.security.SecurityManager] Adding group : class org.jboss.security.NestableGroup Roles(members:j2ee,guest,john)
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : authenticate
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.CheckUserMsg29283281[msgType: m_authenticate, msgID: 1, error: null]
      2004-06-23 11:16:19,140 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.CheckUserMsg29283281[msgType: m_authenticate, msgID: 1, error: null]
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_setSpyDistributedConnection, msgID: 2
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg722074[msgType: m_setSpyDistributedConnection, msgID: 2, error: null]
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.CheckUserMsg29283281[msgType: m_authenticate, msgID: 1, error: null]
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 22
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 15
      2004-06-23 11:16:19,156 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg722074[msgType: m_setSpyDistributedConnection, msgID: 2, error: null]
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg722074[msgType: m_setSpyDistributedConnection, msgID: 2, error: null]
      2004-06-23 11:16:19,156 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 15
      2004-06-23 11:16:19,156 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg722074[msgType: m_setSpyDistributedConnection, msgID: 2, error: null]
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_ping, msgID: 3
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg5057297[msgType: m_ping, msgID: 3, error: null]
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1088003779171
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.PingMsg2951648[msgType: m_pong, msgID: -2147483646, error: null]
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.PingMsg2951648[msgType: m_pong, msgID: -2147483646, error: null]
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      2004-06-23 11:16:19,171 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg2951648[msgType: m_pong, msgID: -2147483646, error: null]
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_getID, msgID: 4
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.GetIDMsg14913482[msgType: m_getID, msgID: 4, error: null]
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 9
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : getID
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : getID
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.GetIDMsg14913482[msgType: m_getID, msgID: 4, error: null]
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.GetIDMsg14913482[msgType: m_getID, msgID: 4, error: null]
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 9
      2004-06-23 11:16:19,187 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.GetIDMsg14913482[msgType: m_getID, msgID: 4, error: null]
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_setEnabled, msgID: 5
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg10092433[msgType: m_setEnabled, msgID: 5, error: null]
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 14
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : setEnabled
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : true
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:3->setEnabled(enabled=true)
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : setEnabled
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.EnableConnectionMsg10092433[msgType: m_setEnabled, msgID: 5, error: null]
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.EnableConnectionMsg10092433[msgType: m_setEnabled, msgID: 5, error: null]
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 14
      2004-06-23 11:16:19,218 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg10092433[msgType: m_setEnabled, msgID: 5, error: null]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_addMessage, msgID: 6
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.AddMsg5868800[msgType: m_addMessage, msgID: 6, error: null]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 2
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : SpyTextMessage {
      Header {
      jmsDestination : QUEUE.nodeQueue
      jmsDeliveryMode : 2
      jmsExpiration : 0
      jmsPriority : 4
      jmsMessageID : ID:3-10880037792341
      jmsTimeStamp : 1088003779234
      jmsCorrelationID: null
      jmsReplyTo : null
      jmsType : null
      jmsRedelivered : false
      jmsProperties : {}
      jmsPropReadWrite: true
      msgReadOnly : false
      producerClientId: ID:3
      }
      Body {
      text :HELLO,JAMES
      }
      }
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
      Principal: guest
      Principal: Roles(members:j2ee,guest,john)
      ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] About to add message 2 msg=1 hard NOT_STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 transaction=null
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 2 msg=1 hard NOT_STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 transaction=null
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 transaction=null
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] addMessage 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 null org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] internalAddMessage 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] queueMessageForSending Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.AddMsg5868800[msgType: m_addMessage, msgID: 6, error: null]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.AddMsg5868800[msgType: m_addMessage, msgID: 6, error: null]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 2
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Async deliver requests=[ReceiveRequest[message=ID:3-10880037792341 subscription=-2147483648] Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Processing request=ReceiveRequest[message=ID:3-10880037792341 subscription=-2147483648 Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Delivering messageid=0 to consumer=SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] Add message=ID:3-10880037792341 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.AddMsg5868800[msgType: m_addMessage, msgID: 6, error: null]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] run() got message message=ID:3-10880037792341 SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] Waiting for serverSesionPool SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] Waited serverSesion=org.jboss.jms.asf.StdServerSession@161509b session=SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]] SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpySession] Add message msgid=ID:3-10880037792341 SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] Starting the ServerSession=org.jboss.jms.asf.StdServerSession@161509b SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Receive subscription=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] wait=-1
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 subId=-2147483648
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
      Principal: guest
      Principal: Roles(members:j2ee,guest,john)
      ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] receive Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] wait=false org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] run() receivedNoWait got no messageSpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=false internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Receive subscription=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] wait=0
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 0
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 subId=-2147483648
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
      Principal: guest
      Principal: Roles(members:j2ee,guest,john)
      ;principal=null;roles=Roles(members:j2ee,guest,john) for rolePrincipals [publisher, guest]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] receive Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] wait=true org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] addReceiver Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyConnectionConsumer] run() waiting for message SpyConnectionConsumer[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] messages=0 waitingForMessage=true internalThread=Thread[Connection Consumer for dest Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] id=1,5,jboss] sessionPool=org.jboss.jms.asf.StdServerSessionPool@1a998c7 connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpySession] Run messages=1 SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854775807
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpySession] Setting current tx xid=-9223372036854775807 previous: null SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyMessageConsumer] consumer() acking message in tx message=ID:3-10880037792341 SpyMessageConsumer@32702517[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] listening=true receiving=false sessionConsumer=true waitingForMessage=false messages=0 listener=org.jboss.jms.asf.StdServerSession@161509b session=SpySession@11700608[tx=true txid=-9223372036854775807 XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResourceManager] Adding acked message xid=-9223372036854775807 ID:3-10880037792341
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyMessageConsumer] consumer() before onMessage=ID:3-10880037792341 SpyMessageConsumer@32702517[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] listening=true receiving=false sessionConsumer=true waitingForMessage=false messages=0 listener=org.jboss.jms.asf.StdServerSession@161509b session=SpySession@11700608[tx=true txid=-9223372036854775807 XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1], flags=0 SpyXAResource[session=SpySession@11700608[tx=true txid=-9223372036854775807 XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854775807, xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpySession] Setting current tx xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1] previous: -9223372036854775807 SpySession@11700608[tx=true txid=-9223372036854775807 XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 INFO [STDOUT] Got a Message: HELLO,JAMES
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1], flags=67108864 SpyXAResource[session=SpySession@11700608[tx=true txid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1] XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpySession] Unsetting current tx xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1] previous: XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1] SpySession@11700608[tx=true txid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1] XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1], success=true
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResource] Commit xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1], onePhase=true SpyXAResource[session=SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=JamesXDELLXP//24, BranchQual=1], onePhase=true
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.Connection] Transact request=org.jboss.mq.TransactionRequest@b5ac2c Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.TransactionRequest@b5ac2c
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.server.BasicQueue] acknowledge AcknowledgementRequest:ACK,QUEUE.nodeQueue,ID:3-10880037792341 3 org.jboss.mq.server.PersistentQueue@1b2380e{id=QUEUE.nodeQueue}
      2004-06-23 11:16:19,234 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 transaction=3
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message 2 msg=1 hard STORED PERSISTENT queue=QUEUE.nodeQueue priority=4 lateClone=false hashCode=20453088 transaction=3
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.SpyMessageConsumer] consumer() after onMessage=ID:3-10880037792341 SpyMessageConsumer@32702517[sub=Subscription[subId=-2147483648connection=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 destination=QUEUE.nodeQueue messageSelector=null Local Create] listening=true receiving=false sessionConsumer=true waitingForMessage=false messages=0 listener=org.jboss.jms.asf.StdServerSession@161509b session=SpySession@11700608[tx=true txid=null XA RUNNING connection=Connection@11408275[token=ConnectionToken:ID:1/846cb5d3848bafdc9bc4c66fdaa0cda0 rcvstate=STARTED]]]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_setEnabled, msgID: 7
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg4084687[msgType: m_setEnabled, msgID: 7, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 14
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : setEnabled
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : false
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:3->setEnabled(enabled=false)
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : setEnabled
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.EnableConnectionMsg4084687[msgType: m_setEnabled, msgID: 7, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.EnableConnectionMsg4084687[msgType: m_setEnabled, msgID: 7, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 14
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg4084687[msgType: m_setEnabled, msgID: 7, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_connectionClosing, msgID: 8
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.CloseMsg32525990[msgType: m_connectionClosing, msgID: 8, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 5
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:3->close()
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.CloseMsg32525990[msgType: m_connectionClosing, msgID: 8, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.CloseMsg32525990[msgType: m_connectionClosing, msgID: 8, error: null]
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 5
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] WriteTask was interrupted
      java.lang.InterruptedException
      at EDU.oswego.cs.dl.util.concurrent.LinkedQueue.take(LinkedQueue.java:106)
      at org.jboss.mq.il.uil2.SocketManager$WriteTask.run(SocketManager.java:477)
      at java.lang.Thread.run(Thread.java:534)
      2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Exiting on IOE
      java.net.SocketException: Socket closed
      at java.net.SocketInputStream.read(SocketInputStream.java:162)
      at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
      at java.io.BufferedInputStream.read(BufferedInputStream.java:201)
      at org.jboss.util.stream.NotifyingBufferedInputStream.read(NotifyingBufferedInputStream.java:67)
      at java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2133)
      at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2313)
      at java.io.ObjectInputStream$BlockDataInputStream.refill(ObjectInputStream.java:2380)
      at java.io.ObjectInputStream$BlockDataInputStream.read(ObjectInputStream.java:2452)
      at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2601)
      at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845)
      at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:279)
      at java.lang.Thread.run(Thread.java:534)
      2004-06-23 11:16:19,250 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.net.SocketException: Socket closed
      at java.net.SocketInputStream.read(SocketInputStream.java:162)
      at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
      at java.io.BufferedInputStream.read(BufferedInputStream.java:201)
      at org.jboss.util.stream.NotifyingBufferedInputStream.read(NotifyingBufferedInputStream.java:67)
      at java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2133)
      at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2313)
      at java.io.ObjectInputStream$BlockDataInputStream.refill(ObjectInputStream.java:2380)
      at java.io.ObjectInputStream$BlockDataInputStream.read(ObjectInputStream.java:2452)
      at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2601)
      at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845)
      at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:279)
      at java.lang.Thread.run(Thread.java:534)
      2004-06-23 11:16:19,250 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2004-06-23 11:16:19,250 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2004-06-23 11:21:34,609 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000

      I am pretty sure, it is not the MDB part, it should be some problem in UIL2, maybe there's something I missed? Can anybody help me?

        • 1. Re: Exiting on IOE when use JBossMQ
          Elias Ross Master


          It looks like the UIL2 is being closed due to "java.net.SocketException: Socket closed", which is being triggered by this:
          2004-06-23 11:16:19,250 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.CloseMsg32525990[msgType: m_connectionClosing, msgID: 8, error: null]

          Somebody is intentionally closing the connection. As it's an MDB, perhaps whoever is providing the connection is doing it to you.