Keith Wall created QPID-6502:
--------------------------------
Summary: Close connection in response to a CSRE condition rather
than sending a execution exception
Key: QPID-6502
URL: https://issues.apache.org/jira/browse/QPID-6502
Project: Qpid
Issue Type: Bug
Components: Java Broker
Reporter: Keith Wall
Fix For: 6.0 [Java]
The Java Broker internally throws a ConnectionScopeRuntimeException in response
to abnormal conditions encountered whilst processing commands from the wire.
The intention is that this exception causes the Broker to close the messaging
connection.
This is currently not the case within the 0-10 implementation. A CSRE
originating from beneath ServerSessionDelegate#command currently causes a
execution exception to be sent down the wire, but the connection remains open.
This problem is currently causing
MultiNodeTest#testTransferMasterWhilstMessagesInFlight to fail consistently on
the 0-10 BDB profile. Here the execution exception causes the client to close
the JMS Session. The JE thread, in response to lost of mastership, then
causes the connection to be closed, and the client then fails-over. However
on reconnection to the new master the JMS connection no longer has a Session so
the test fails.
Broker side:
{noformat}
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) -
org.apache.qpid.server.util.ConnectionScopedRuntimeException: Environment
'nodetestTransferMasterWhilstMessagesInFlight10001' cannot finish JE operation
because master is unknown
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.handleDatabaseException(ReplicatedEnvironmentFacade.java:409)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.commit(ReplicatedEnvironmentFacade.java:288)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.commitTranImpl(AbstractBDBMessageStore.java:788)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.access$1200(AbstractBDBMessageStore.java:74)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore$BDBTransaction.commitTran(AbstractBDBMessageStore.java:1367)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.txn.LocalTransaction.commit(LocalTransaction.java:348)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.txn.LocalTransaction.commit(LocalTransaction.java:338)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerSession.commit(ServerSession.java:672)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:552)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:86)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:82)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:55)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerSessionDelegate.command(ServerSessionDelegate.java:103)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerSessionDelegate.command(ServerSessionDelegate.java:86)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.Method.delegate(Method.java:159)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.Session.received(Session.java:596)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.Connection.dispatch(Connection.java:463)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.MethodDelegate.txCommit(MethodDelegate.java:152)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:82)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.Method.delegate(Method.java:159)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.Connection.received(Connection.java:416)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerConnection.access$001(ServerConnection.java:70)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerConnection$2.run(ServerConnection.java:347)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerConnection$2.run(ServerConnection.java:343)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
java.security.AccessController.doPrivileged(Native Method)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
javax.security.auth.Subject.doAs(Subject.java:360)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerConnection.received(ServerConnection.java:342)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.Assembler.emit(Assembler.java:98)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:199)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.Assembler.frame(Assembler.java:132)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.Frame.delegate(Frame.java:128)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.Assembler.received(Assembler.java:103)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ServerAssembler.received(ServerAssembler.java:48)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:200)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:115)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.v0_10.ProtocolEngine_0_10.received(ProtocolEngine_0_10.java:218)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:159)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.transport.NonBlockingConnection.doRead(NonBlockingConnection.java:375)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.transport.NonBlockingConnection.doWork(NonBlockingConnection.java:276)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.transport.NetworkConnectionScheduler.processConnection(NetworkConnectionScheduler.java:94)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.transport.NetworkConnectionScheduler.access$000(NetworkConnectionScheduler.java:34)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.transport.NetworkConnectionScheduler$2.run(NetworkConnectionScheduler.java:75)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
java.lang.Thread.run(Thread.java:745)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - Caused by:
com.sleepycat.je.rep.UnknownMasterException: (JE 5.0.104) Problem closing
transaction -68. The current state is:UNKNOWN. The node transitioned to this
state at:Fri Apr 17 22:49:01 BST 2015
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
com.sleepycat.je.rep.impl.RepImpl.checkIfMaster(RepImpl.java:872)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
com.sleepycat.je.rep.txn.MasterTxn.checkIfFrozen(MasterTxn.java:631)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
com.sleepycat.je.txn.Txn.commit(Txn.java:834)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
com.sleepycat.je.Transaction.doCommit(Transaction.java:609)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
com.sleepycat.je.Transaction.commit(Transaction.java:410)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - at
org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.commit(ReplicatedEnvironmentFacade.java:284)
2015-04-17 22:49:01,624 INFO [STD] (BROKER-10000) - ... 47 more
{noformat}
Client side:
{noformat}
at
org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1082)
at
org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:936)
at
org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:182)
at
org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:32)
at
org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103)
at
org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:55)
at
org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50)
at
org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:32)
at org.apache.qpid.transport.Method.delegate(Method.java:159)
at org.apache.qpid.transport.Session.received(Session.java:596)
at org.apache.qpid.transport.Connection.dispatch(Connection.java:463)
at
org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64)
at
org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40)
at
org.apache.qpid.transport.MethodDelegate.executionException(MethodDelegate.java:110)
at
org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103)
at
org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54)
at
org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40)
at org.apache.qpid.transport.Method.delegate(Method.java:159)
at org.apache.qpid.transport.Connection.received(Connection.java:416)
at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:98)
at
org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:199)
at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:132)
at org.apache.qpid.transport.network.Frame.delegate(Frame.java:128)
at
org.apache.qpid.transport.network.Assembler.received(Assembler.java:103)
at
org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:200)
at
org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:115)
at org.apache.qpid.transport.network.io.IoReceiver.run(
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
