-
15. Re: Error processing courier
marklittle May 23, 2008 9:13 AM (in response to bowlere)Thanks for the analysis. It does look as though there is an issue with the connection pooling. Thanks also for the associated JIRA.
-
16. Re: Error processing courier
kconner May 27, 2008 5:15 AM (in response to bowlere)Hiya Ed.
Apologies for not getting back to you before now, last week was a bit hectic getting the release out.
The ESB server should definitely not be getting into that state, whether the issue lies in your code or not. I will take a look at this later today and let you know what I find.
Apologies again for the delay
Kev -
17. Re: Error processing courier
bowlere May 27, 2008 9:06 AM (in response to bowlere)No need for appolgies, I really appreciate the help. I've updated to
the 4.3.GA release, and have patched the JmsConnectionPool to log the
JMSException. I'm hoping this will give me a better idea of what's
causing the problem, and how to recover from the JMS failure. Just
waiting for it to occur naturally again, rather than me forcing it by
messing with the firewall.
Thanks again for the assistance. -
18. Re: Error processing courier
bowlere May 29, 2008 12:31 PM (in response to bowlere)I've now seen this exception:
2008-05-28 18:34:50,420 WARN [org.jboss.resource.connectionmanager.TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@54229bc6[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@3f14890 handles=1 lastUse=1211996045638 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@210f7fb1 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@74d494b9 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@53f09312 txSync=null] javax.resource.spi.ResourceAdapterInternalException: Unexpected error at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:293) at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.connectionError(BaseWrapperManagedConnection.java:273) ... at org.apache.juddi.registry.local.RequestHandler.run(RequestHandler.java:129) at java.lang.Thread.run(Thread.java:619) Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded at java.lang.StringCoding$StringDecoder.decode(StringCoding.java:133) ... at com.mysql.jdbc.ResultSet.getString(ResultSet.java:5420) at org.jboss.resource.adapter.jdbc.WrappedResultSet.getString(WrappedResultSet.java:867)
Which seems to be the root cause of a lot of issues, for the next half
an hour. Followed By:2008-05-28 18:34:59,533 ERROR [org.apache.juddi.datastore.jdbc.JDBCDataStore] Exception occured while attempting to aquire a JDBC connection: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] )) org.jboss.util.NestedSQLException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] )) at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94) ... at org.apache.juddi.registry.local.RequestHandler.run(RequestHandler.java:129) at java.lang.Thread.run(Thread.java:619) Caused by: javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ) at org.jboss.resource.connectionmanager.InternalManagedConnectionPool.getConnection(InternalManagedConnectionPool.java:301) ... at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88) ... 12 more
some Database connection & transaction:2008-05-28 18:52:59,008 ERROR [org.apache.juddi.datastore.jdbc.JDBCDataStore] Exception occured while attempting to aquire a JDBC connection: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] )) org.jboss.util.NestedSQLException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] )) at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94) ... at org.apache.juddi.registry.local.RequestHandler.run(RequestHandler.java:129) at java.lang.Thread.run(Thread.java:619) Caused by: javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ) at org.jboss.resource.connectionmanager.InternalManagedConnectionPool.getConnection(InternalManagedConnectionPool.java:301) ... at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88) ... 12 more
issues then:2008-05-28 18:54:38,273 DEBUG [org.jboss.internal.soa.esb.couriers.JmsCourier] JMS error. Attempting JMS reconnect. javax.jms.IllegalStateException: The consumer is closed at org.jboss.mq.SpyMessageConsumer.checkClosed(SpyMessageConsumer.java:952) ... at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619) ... 2008-05-28 18:54:38,297 DEBUG [org.jboss.soa.esb.listeners.message.MessageAwareListener] Courier Exception org.jboss.soa.esb.couriers.CourierTransportException: Caught exception during receive and could not reconnect! at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:435) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:232) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:214) at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:280) at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:248) at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619) Caused by: javax.jms.IllegalStateException: The consumer is closed at org.jboss.mq.SpyMessageConsumer.checkClosed(SpyMessageConsumer.java:952) at org.jboss.mq.SpyMessageConsumer.receive(SpyMessageConsumer.java:356) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:430) ... 7 more 2008-05-28 18:54:38,300 WARN [org.jboss.soa.esb.listeners.message.MessageAwareListener] Error processing courier, backing off for 1000 milliseconds
... the backing off exception. It's probably a memory leak in my code
that's causing the out of memory exception, or something that's
creating and destroying a lot of objects. I don't see this before
other occurrences of the "backing off" error, so I cannot take this as
the only cause. I've added the "-XX:-UseGCOverheadLimit" flag to the
JVM, and restarted the application server. -
19. Re: Error processing courier
bowlere Jun 2, 2008 7:17 AM (in response to bowlere)We ran jboss over the weekend and after a day running the following
errors were logged:2008-06-01 10:06:35,259 ERROR [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOExcepti on: ping timeout.) 2008-06-01 10:06:35,260 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Emptied the session pool now closing the connection to the factory. 2008-06-01 10:06:35,264 ERROR [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOExcepti on: ping timeout.) 2008-06-01 10:06:35,264 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Emptied the session pool now closing the connection to the factory. 2008-06-01 10:06:35,264 ERROR [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOExcepti on: ping timeout.) 2008-06-01 10:06:35,264 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Emptied the session pool now closing the connection to the factory.
It seems as though the same issue is being logged three times. Shortly
after this, we see this error (also logged three times, removed
duplicates for clarity):2008-06-01 10:06:35,671 DEBUG [org.jboss.internal.soa.esb.couriers.JmsCourier] JMS error. Attempting JMS reconnect. javax.jms.IllegalStateException: The consumer is closed at org.jboss.mq.SpyMessageConsumer.checkClosed(SpyMessageConsumer.java:952) at org.jboss.mq.SpyMessageConsumer.receive(SpyMessageConsumer.java:356) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:430) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:232) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:214) at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:280) at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:248) at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619)
followed by (again, three times):2008-06-01 10:06:36,066 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:218) at java.io.BufferedInputStream.read(BufferedInputStream.java:237) at org.jboss.util.stream.NotifyingBufferedInputStream.read(NotifyingBufferedInputStream.java:79) at java.io.ObjectInputStream $PeekInputStream.peek(ObjectInputStream.java:2249) at java.io.ObjectInputStream $BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2429) at java.io.ObjectInputStream $BlockDataInputStream.refill(ObjectInputStream.java:2499) at java.io.ObjectInputStream $BlockDataInputStream.read(ObjectInputStream.java:2571) at java.io.ObjectInputStream $BlockDataInputStream.readByte(ObjectInputStream.java:2720) at java.io.ObjectInputStream.readByte(ObjectInputStream.java:895) at org.jboss.mq.il.uil2.SocketManager $ReadTask.run(SocketManager.java:340) at java.lang.Thread.run(Thread.java:619)
followed by (again, three times):2008-06-01 10:06:42,606 DEBUG [org.jboss.soa.esb.listeners.message.MessageAwareListener] Courier Exception org.jboss.soa.esb.couriers.CourierTransportException: Caught exception during receive and could not reconnect! at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:435) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:232) at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:214) at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:280) at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:248) at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619) Caused by: javax.jms.IllegalStateException: The consumer is closed at org.jboss.mq.SpyMessageConsumer.checkClosed(SpyMessageConsumer.java:952) at org.jboss.mq.SpyMessageConsumer.receive(SpyMessageConsumer.java:356) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:430) ... 7 more 2008-06-01 10:06:42,607 WARN [org.jboss.soa.esb.listeners.message.MessageAwareListener] Error processing courier, backing off for 1000 milliseconds
followed by (again, three times):2008-06-01 10:06:57,368 DEBUG [org.jboss.internal.soa.esb.couriers.JmsCourier] Failed to reconnect to JMS org.jboss.soa.esb.couriers.CourierServiceBindException: Failed to get JMS Session from pool. at org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:162) at org.jboss.internal.soa.esb.couriers.JmsCourier.createMessageConsumer(JmsCourier.java:499) at org.jboss.internal.soa.esb.couriers.JmsCourier.jmsConnectRetry(JmsCourier.java:287) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:434) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402) ... at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:280) at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:248) at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619) Caused by: org.jboss.internal.soa.esb.rosetta.pooling.ConnectionException: Connection pool has been terminated at org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.initConnection(JmsConnectionPool.java:401) at org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.getSession(JmsConnectionPool.java:163) at org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:156) ... 10 more
we then see the backing off errors again with the backing off time
increased. Then we see the following occurring every 30 seconds or so:2008-06-01 10:07:03,096 DEBUG [org.jboss.soa.esb.listeners.message.MessageAwareListener] Courier Exception org.jboss.soa.esb.couriers.CourierException: Unable to create Message Consumer at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:422) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402) ... at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115) at java.lang.Thread.run(Thread.java:619) Caused by: org.jboss.soa.esb.couriers.CourierServiceBindException: Failed to get JMS Session from pool. at org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:162) at org.jboss.internal.soa.esb.couriers.JmsCourier.createMessageConsumer(JmsCourier.java:499) at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:414) ... 7 more Caused by: org.jboss.internal.soa.esb.rosetta.pooling.ConnectionException: Connection pool has been terminated at org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.initConnection(JmsConnectionPool.java:401) at org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.getSession(JmsConnectionPool.java:163) at org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:156) ... 9 more
-
20. Re: Error processing courier
kconner Jun 10, 2008 10:44 AM (in response to bowlere)Hiya Ed.
I have managed to reproduce this and believe I know the cause.
The connection pool is cleaning up when an error occurs, throwing everything away and starting from scratch. Unfortunately the JmsCourier is holding onto a reference of the connection pool and uses the stale reference to attempt to recreate the connection/session.
I'll get this fixed in trunk asap.
Thanks for the details, they were very helpful. -
21. Re: Error processing courier
kconner Jun 11, 2008 7:43 AM (in response to bowlere)I have committed the fix into trunk, revision 20417.
Thanks again for the report.
Kev -
22. Re: Error processing courier
bowlere Jun 11, 2008 8:16 AM (in response to bowlere)Excellent. Thank-you very much. I'll get this patch, deploy it and let you know how we go. Thanks again.
-
23. Re: Error processing courier
bowlere Jul 25, 2008 7:16 AM (in response to bowlere)Hi - just so you know, we've now been running this patch in beta for some time, and are processing over a million messages a day without any problems.
Many thanks again. -
24. Re: Error processing courier
kconner Jul 25, 2008 7:25 AM (in response to bowlere)Hiya Ed.
This is great news, thanks for letting us know. Your help was invaluable.
Kev -
25. Re: Error processing courier
maxfede May 4, 2009 9:23 PM (in response to bowlere)Hi.
I´m having this problem with jbossesb-server-4.5.GA .
When i start the server i get the WARN Error processing courier, backing off.
I´m new with this kind of STuff so i apreciated that someone could give me some help.
Thanks
Fede