1 2 Previous Next 25 Replies Latest reply on May 4, 2009 9:23 PM by maxfede Go to original post
      • 15. Re: Error processing courier
        marklittle
        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.

          • Actions
        • 16. Re: Error processing courier
          kconner
          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

            • Actions
          • 17. Re: Error processing courier
            bowlere
            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.

              • Actions
            • 18. Re: Error processing courier
              bowlere
              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.


                • Actions
              • 19. Re: Error processing courier
                bowlere
                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



                  • Actions
                • 20. Re: Error processing courier
                  kconner
                  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.

                    • Actions
                  • 21. Re: Error processing courier
                    kconner
                    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

                      • Actions
                    • 22. Re: Error processing courier
                      bowlere
                      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.

                        • Actions
                      • 23. Re: Error processing courier
                        bowlere
                        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.

                          • Actions
                        • 24. Re: Error processing courier
                          kconner
                          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

                            • Actions
                          • 25. Re: Error processing courier
                            maxfede
                            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

                              • Actions
                            1 2 Previous Next