activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From jliezers <john.liez...@metoffice.gov.uk>
Subject Re: Successfully delivered message ends up on DLQ
Date Wed, 13 Feb 2013 08:38:19 GMT
I've had one new DLQ occurrence in the last 24 hours, again the message was
consumed successfully and acknowledged. 

This time I have been able to tie the JDBC failure directly to the DLQ
message event using the time and more importantly the message id in the
stack trace.

While handling the Ack the JDBC failure results in the message being put
onto the DLQ.

The root cause is a JDBC/database issue and not an ActiveMQ problem, when
this is resolved the problem should go away.

I'm not qualified to say whether ActiveMQ should be creating a DLQ entry in
response to this exception.


19:30:01.131 [MessageService] x.x.x.x. [ActiveMQ Transport:
tcp:///x.x.x.x:50668] WARN  o.a.a.s.jdbc.JDBCPersistenceAdapter - JDBC
Failure: Io exception: Connection reset java.sql.SQLRecoverableException: Io
exception: Connection reset
        at
oracle.jdbc.driver.SQLStateMapping.newSQLException(SQLStateMapping.java:101)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.DatabaseError.newSQLException(DatabaseError.java:133)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:199)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBCDriver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:263)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBCDriver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:521)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBCDriver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:969)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:897)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1186)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3387)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3431)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
~[commons-dbcp-1.4.jar:1.4]
        at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
~[commons-dbcp-1.4.jar:1.4]
        at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
~[commons-dbcp-1.4.jar:1.4]
        at
org.apache.activemq.store.jdbc.adapter.DefaultJDBCAdapter.getStoreSequenceId(DefaultJDBCAdapter.java:278)
~[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.jdbc.JDBCMessageStore.getStoreSequenceIdForMessageId(JDBCMessageStore.java:335)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.jdbc.JDBCMessageStore.removeMessage(JDBCMessageStore.java:190)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.memory.MemoryTransactionStore.removeMessage(MemoryTransactionStore.java:332)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.memory.MemoryTransactionStore$1.removeAsyncMessage(MemoryTransactionStore.java:161)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.Queue.acknowledge(Queue.java:850)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.Queue.removeMessage(Queue.java:1604)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.QueueSubscription.acknowledge(QueueSubscription.java:59)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:225)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:276)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:461)
[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:150)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:619) [na:1.6.0_21]
Caused by: java.net.SocketException: Connection reset
        at
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
~[na:1.6.0_21]
        at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
~[na:1.6.0_21]
        at oracle.net.ns.DataPacket.send(DataPacket.java:150)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at oracle.net.ns.NetOutputStream.flush(NetOutputStream.java:180)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:169)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driverversion -
"11.1.0.7.0-Production"]
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:117)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:92)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version
-"11.1.0.7.0-Production"]
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:77)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version
-"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1034)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1010)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:588)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:194)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        at
oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:953)
~[ojdbc6-11.1.0.7.0-Production.jar:Oracle JDBC Driver version -
"11.1.0.7.0-Production"]
        ... 35 common frames omitted

19:30:01.132 [MessageService] x.x.x.x [ActiveMQ Transport:
tcp:///x.x.x.x:50668] WARN  o.a.a.store.jdbc.TransactionContext - Close
failed: Already closed. java.sql.SQLException: Already closed.
        at
org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:114)
~[commons-dbcp-1.4.jar:1.4]
        at
org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:191)
~[commons-dbcp-1.4.jar:1.4]
        at
org.apache.activemq.store.jdbc.TransactionContext.close(TransactionContext.java:142)
~[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.jdbc.JDBCMessageStore.getStoreSequenceIdForMessageId(JDBCMessageStore.java:340)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.jdbc.JDBCMessageStore.removeMessage(JDBCMessageStore.java:190)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.memory.MemoryTransactionStore.removeMessage(MemoryTransactionStore.java:332)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.store.memory.MemoryTransactionStore$1.removeAsyncMessage(MemoryTransactionStore.java:161)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.Queue.acknowledge(Queue.java:850)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.Queue.removeMessage(Queue.java:1604)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.QueueSubscription.acknowledge(QueueSubscription.java:59)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:225)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:276)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:461)
[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:150)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
[activemq-core-5.6.0.jar:5.6.0]
        at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:619) [na:1.6.0_21]

19:30:01.132 [MessageService] x.x.x.x [ActiveMQ Transport:
tcp:///x.x.x.x:50668] WARN  o.a.a.b.T.Transport - 
Transport Connection to: tcp://x.x.x.x:50668 failed: java.io.IOException:
Failed to get store sequenceId for messageId:
ID:server.x.x.x-48625-1360250400164-0:1832:1:1:2, on: queue://MyQueue.
Reason: java.sql.SQLRecoverableException: Io exception: Connection reset




--
View this message in context: http://activemq.2283324.n4.nabble.com/Successfully-delivered-message-ends-up-on-DLQ-tp4663232p4663320.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

Mime
View raw message