Exiting on IOE when use JBossMQ
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?
