This seems to be the relevant exception. I've attached the rest of the
log as well.
--Rafael
pool-1-thread-22 2009-06-25 14:29:26,512 ERROR
[qpid.server.protocol.AMQPFastProtocolHandler] Exception caught in/127.0\
.0.1:51166(guest), closing session explictly:
org.apache.qpid.AMQException: Fatal internal error: transactional context\
is not empty at beginTran:
org.apache.qpid.server.store.derbymessagestore$connectionwrap...@128215d
org.apache.qpid.AMQException: Fatal internal error: transactional
context is not empty at beginTran: org.apache.qpid.se\
rver.store.derbymessagestore$connectionwrap...@128215d
at
org.apache.qpid.server.store.DerbyMessageStore.beginTran(DerbyMessageStore.java:974)
at
org.apache.qpid.server.txn.NonTransactionalContext.beginTranIfNecessary(NonTransactionalContext.java:76)
at
org.apache.qpid.server.queue.IncomingMessage.routingComplete(IncomingMessage.java:134)
at
org.apache.qpid.server.AMQChannel.publishContentHeader(AMQChannel.java:177)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.contentHeaderReceived(AMQMinaProtocolSession.java:368\
)
at
org.apache.qpid.framing.ContentHeaderBody.handle(ContentHeaderBody.java:118)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.frameReceived(AMQMinaProtocolSession.java:240)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.dataBlockReceived(AMQMinaProtocolSession.java:197)
at
org.apache.qpid.server.protocol.AMQPFastProtocolHandler.messageReceived(AMQPFastProtocolHandler.java:248)
at
org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:7\
03)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:\
800)
at
org.apache.qpid.pool.PoolingFilter.messageReceived(PoolingFilter.java:334)
at
org.apache.mina.filter.ReferenceCountingIoFilter.messageReceived(ReferenceCountingIoFilter.java:96)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:\
800)
at
org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:60)
at
org.apache.mina.filter.codec.QpidProtocolCodecFilter.messageReceived(QpidProtocolCodecFilter.java:174)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:\
800)
at org.apache.qpid.pool.Event$ReceivedEvent.process(Event.java:86)
at org.apache.qpid.pool.Job.processAll(Job.java:114)
at org.apache.qpid.pool.Job.run(Job.java:153)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
main 2009-06-25 14:29:24,315 INFO [qpid.test.utils.QpidTestCase] ==========
start TopicSessionTest.testNonMatchingMessagesDoNotFillQueue ==========
main 2009-06-25 14:29:24,315 INFO [qpid.test.utils.QpidTestCase] starting
broker: /home/rhs/qpid/java/build/bin/qpid-server -p 5672 -m 8999 -c
/home/rhs/qpid/java/build/etc/config-systests.xml -l
/home/rhs/qpid/java/log4j-test.xml
System Properties set to -Damqj.logging.level=info
-DQPID_HOME=/home/rhs/qpid/java/build -DQPID_WORK=/home/rhs/qpid/java/build/work
Using QPID_CLASSPATH
/home/rhs/qpid/java/build/lib/qpid-all.jar:/home/rhs/qpid/java/build/lib/bdbstore-launch.jar
Info: QPID_JAVA_GC not set. Defaulting to JAVA_GC -XX:+UseConcMarkSweepGC
-XX:+HeapDumpOnOutOfMemoryError
Info: QPID_JAVA_MEM not set. Defaulting to JAVA_MEM -Xmx1024m
Using configuration file /home/rhs/qpid/java/build/etc/config-systests.xml
Configuring logger using configuration file /home/rhs/qpid/java/log4j-test.xml
log4j:WARN Continuable parsing error 36 and column 14
log4j:WARN The content of element type "appender" must match
"(errorHandler?,param*,layout?,filter*,appender-ref*)".
main 2009-06-25 14:29:24,833 INFO [qpid.server.registry.ApplicationRegistry]
Initialising Application Registry:1
main 2009-06-25 14:29:24,836 INFO
[qpid.server.management.NoopManagedObjectRegistry] Management is disabled
main 2009-06-25 14:29:24,853 WARN [server.security.access.ACLManager] Plugin
handling security section principal-databases is
main 2009-06-25 14:29:24,853 WARN [server.security.access.ACLManager] Plugin
handling security section access is
main 2009-06-25 14:29:24,853 WARN [server.security.access.ACLManager] Plugin
handling security section msg-auth is
main 2009-06-25 14:29:24,853 WARN [server.security.access.ACLManager] Plugin
handling security section jmx is
main 2009-06-25 14:29:24,857 INFO
[security.auth.database.ConfigurationFilePrincipalDatabaseManager] Initialising
PrincipleDatabase authentication manager
main 2009-06-25 14:29:24,862 INFO
[security.auth.database.PlainPasswordFilePrincipalDatabase] PlainPasswordFile
using file /home/rhs/qpid/java/build/etc/passwd
main 2009-06-25 14:29:24,864 INFO
[security.auth.database.PlainPasswordFilePrincipalDatabase] Created user:guest
main 2009-06-25 14:29:24,864 INFO
[security.auth.database.PlainPasswordFilePrincipalDatabase] Created user:client
main 2009-06-25 14:29:24,864 INFO
[security.auth.database.PlainPasswordFilePrincipalDatabase] Created user:server
main 2009-06-25 14:29:24,864 INFO
[security.auth.database.ConfigurationFilePrincipalDatabaseManager] Initialised
principal database 'passwordfile' successfully
main 2009-06-25 14:29:24,865 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialising
Default PrincipleDatabase authentication manager.
main 2009-06-25 14:29:24,865 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialised
AMQPLAIN SASL provider successfully
main 2009-06-25 14:29:24,866 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialised
PLAIN SASL provider successfully
main 2009-06-25 14:29:24,866 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialised
CRAM-MD5 SASL provider successfully
main 2009-06-25 14:29:24,876 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Additional SASL
providers successfully registered.
main 2009-06-25 14:29:24,912 WARN
[security.access.management.AMQUserManagementMBean] Access rights contains user
'admin' but there is no authentication data for that user
main 2009-06-25 14:29:24,912 WARN
[security.access.management.AMQUserManagementMBean] Access rights contains user
'user' but there is no authentication data for that user
main 2009-06-25 14:29:24,996 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@90832e with routing key
'queue' to exchange:org.apache.qpid.server.virtualhost.virtualh...@1947496
main 2009-06-25 14:29:25,008 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@15356d5 with routing key
'ping' to exchange:org.apache.qpid.server.virtualhost.virtualh...@1947496
main 2009-06-25 14:29:25,143 INFO [qpid.server.store.DerbyMessageStore]
Configuring Derby message store for virtual host development
main 2009-06-25 14:29:25,532 INFO [qpid.server.store.DerbyMessageStore]
Recovering persistent state...
main 2009-06-25 14:29:25,565 INFO [qpid.server.store.DerbyMessageStore]
Recovered message counts: {}
main 2009-06-25 14:29:25,565 INFO [qpid.server.store.DerbyMessageStore]
Persistent state recovered successfully
main 2009-06-25 14:29:25,566 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialising
'development' PrincipleDatabase authentication manager.
main 2009-06-25 14:29:25,566 WARN [server.security.access.ACLManager] Plugin
handling security section principal-databases is
main 2009-06-25 14:29:25,566 WARN [server.security.access.ACLManager] Plugin
handling security section access is
main 2009-06-25 14:29:25,566 WARN [server.security.access.ACLManager] Plugin
handling security section msg-auth is
main 2009-06-25 14:29:25,567 WARN [server.security.access.ACLManager] Plugin
handling security section jmx is
main 2009-06-25 14:29:25,583 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@2515 with routing key 'queue'
to exchange:org.apache.qpid.server.virtualhost.virtualh...@182c132
main 2009-06-25 14:29:25,589 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@159d510 with routing key
'ping' to exchange:org.apache.qpid.server.virtualhost.virtualh...@182c132
main 2009-06-25 14:29:25,589 INFO [qpid.server.store.DerbyMessageStore]
Configuring Derby message store for virtual host test
main 2009-06-25 14:29:25,647 INFO [qpid.server.store.DerbyMessageStore]
Recovering persistent state...
main 2009-06-25 14:29:25,812 INFO [qpid.server.store.DerbyMessageStore]
Recovered message counts: {TempQueue77c52036-b7ac-41d6-b4dd-768d8c382647=1,
TestQueue=1, knownQ=2, myqueue=3, rollback-order-test-queue=5, sendTo_14=1,
sendTo_15=1, sendTo_16=1, sendTo_2=1, testQ=1, tmp_127.0.0.151161_1=2}
main 2009-06-25 14:29:25,812 INFO [qpid.server.store.DerbyMessageStore]
Persistent state recovered successfully
main 2009-06-25 14:29:25,812 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialising
'test' PrincipleDatabase authentication manager.
main 2009-06-25 14:29:25,812 WARN [server.security.access.ACLManager] Plugin
handling security section principal-databases is
main 2009-06-25 14:29:25,812 WARN [server.security.access.ACLManager] Plugin
handling security section access is
main 2009-06-25 14:29:25,813 WARN [server.security.access.ACLManager] Plugin
handling security section msg-auth is
main 2009-06-25 14:29:25,813 WARN [server.security.access.ACLManager] Plugin
handling security section jmx is
main 2009-06-25 14:29:25,836 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@1b5a5cf with routing key
'test-ping' to exchange:org.apache.qpid.server.virtualhost.virtualh...@98bbf6
main 2009-06-25 14:29:25,843 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@18c4a7f with routing key
'queue' to exchange:org.apache.qpid.server.virtualhost.virtualh...@98bbf6
main 2009-06-25 14:29:25,849 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@135da43 with routing key
'test-queue' to exchange:org.apache.qpid.server.virtualhost.virtualh...@98bbf6
main 2009-06-25 14:29:25,855 INFO [qpid.server.virtualhost.VirtualHost] Binding
queue:org.apache.qpid.server.queue.simpleamqqu...@12c4c57 with routing key
'ping' to exchange:org.apache.qpid.server.virtualhost.virtualh...@98bbf6
main 2009-06-25 14:29:25,856 INFO [qpid.server.store.DerbyMessageStore]
Configuring Derby message store for virtual host localhost
main 2009-06-25 14:29:25,884 INFO [qpid.server.store.DerbyMessageStore]
Recovering persistent state...
main 2009-06-25 14:29:25,907 INFO [qpid.server.store.DerbyMessageStore]
Recovered message counts: {}
main 2009-06-25 14:29:25,907 INFO [qpid.server.store.DerbyMessageStore]
Persistent state recovered successfully
main 2009-06-25 14:29:25,937 INFO
[security.auth.manager.PrincipalDatabaseAuthenticationManager] Initialising
'localhost' PrincipleDatabase authentication manager.
main 2009-06-25 14:29:25,937 WARN [server.security.access.ACLManager] Plugin
handling security section principal-databases is
main 2009-06-25 14:29:25,937 WARN [server.security.access.ACLManager] Plugin
handling security section access is
main 2009-06-25 14:29:25,938 WARN [server.security.access.ACLManager] Plugin
handling security section msg-auth is
main 2009-06-25 14:29:25,938 WARN [server.security.access.ACLManager] Plugin
handling security section jmx is
main 2009-06-25 14:29:25,946 INFO [Qpid.Broker] Starting Qpid Broker 0.5 build:
788441
main 2009-06-25 14:29:25,947 WARN [apache.qpid.server.Main] Using Mina IO
Processing
main 2009-06-25 14:29:25,984 INFO [Qpid.Broker] Qpid.AMQP listening on non-SSL
address 0.0.0.0/0.0.0.0:5672
main 2009-06-25 14:29:25,985 INFO [Qpid.Broker] Qpid Broker Ready :0.5 build:
788441
main 2009-06-25 14:29:25,985 INFO [qpid.test.utils.QpidTestCase] get Connection
main 2009-06-25 14:29:25,985 INFO [qpid.test.utils.QpidTestCase] get
ConnectionFactory
main 2009-06-25 14:29:25,985 INFO [qpid.test.utils.QpidTestCase] get
InitialContext
main 2009-06-25 14:29:25,985 INFO
[apache.qpid.jndi.PropertiesFileInitialContextFactory] Loading Properties
from:/home/rhs/qpid/java/test-provider.properties
main 2009-06-25 14:29:25,986 INFO
[apache.qpid.jndi.PropertiesFileInitialContextFactory] Loaded Context
Properties:{connectionfactory.connection1=amqp://username:passw...@clientid/test?brokerlist='tcp://localhost:5672',
topic.topic=topic,
connectionfactory.ssl=amqp://username:passw...@clientid/test?brokerlist='tcp://localhost:5671?ssl='true'',
test.port.ssl=5671, topic.xaTopic=xaTopic,
topic.durableSubscriberTopic=durableSubscriberTopic,
connectionfactory.failover.vm=amqp://username:passw...@clientid/test?brokerlist='vm://:2;vm://:1',
connectionfactory.failover=amqp://username:passw...@clientid/test?brokerlist='tcp://localhost:5673;tcp://localhost:5672'&sync_ack='true'&sync_publish='all'&failover='roundrobin?cyclecount='20'',
test.port=5672, queue.xaQueue=xaQueue,
connectionfactory.default.vm=amqp://username:passw...@clientid/test?brokerlist='vm://:1',
queue.queue=example.queue, test.port.alt=5673,
connectionfactory.connection1.vm=amqp://username:passw...@clientid/test?brokerlist='vm://:1',
java.naming.factory.initial=org.apache.qpid.jndi.PropertiesFileInitialContextFactory,
connectionfactory.default=amqp://username:passw...@clientid/test?brokerlist='tcp://localhost:5672',
queue.MyQueue=example.MyQueue,
connectionfactory.connection2.vm=amqp://username:passw...@clientid/test?brokerlist='vm://:2',
java.naming.provider.url=/home/rhs/qpid/java/test-provider.properties,
connectionfactory.connection2=amqp://username:passw...@clientid/test?brokerlist='tcp://localhost:5673'}
main 2009-06-25 14:29:25,986 DEBUG
[apache.qpid.jndi.PropertiesFileInitialContextFactory] Creating the topic:
topic with the following binding keys topic,
main 2009-06-25 14:29:25,986 DEBUG
[apache.qpid.jndi.PropertiesFileInitialContextFactory] Creating the topic:
xaTopic with the following binding keys xaTopic,
main 2009-06-25 14:29:25,986 DEBUG
[apache.qpid.jndi.PropertiesFileInitialContextFactory] Creating the topic:
durableSubscriberTopic with the following binding keys durableSubscriberTopic,
main 2009-06-25 14:29:25,986 INFO [apache.qpid.client.AMQConnection]
Connection:amqp://guest:*****...@clientid/test?brokerlist='tcp://localhost:5672'
main 2009-06-25 14:29:25,986 DEBUG
[apache.qpid.client.AMQConnectionDelegate_0_10] connecting to host: localhost
port: 5672 vhost: test username: guest password: guest
main 2009-06-25 14:29:25,987 DEBUG [transport.network.io.IoTransport]
default-SO_RCVBUF : 43690
main 2009-06-25 14:29:25,987 DEBUG [transport.network.io.IoTransport]
default-SO_SNDBUF : 8192
main 2009-06-25 14:29:25,987 DEBUG [transport.network.io.IoTransport]
new-SO_RCVBUF : 65536
main 2009-06-25 14:29:25,987 DEBUG [transport.network.io.IoTransport]
new-SO_SNDBUF : 65536
main 2009-06-25 14:29:25,988 DEBUG [apache.qpid.transport.Connection] SEND:
[conn:1ec829f] AMQP.1 0-10
SocketAcceptorIoProcessor-0.0 2009-06-25 14:29:26,014 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Protocol session created
for:/127.0.0.1:51165
SocketAcceptorIoProcessor-0.0 2009-06-25 14:29:26,017 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Session opened
for:/127.0.0.1:51165
pool-1-thread-20 2009-06-25 14:29:26,022 INFO
[qpid.server.protocol.AMQProtocolSession] Received unsupported protocol
initiation for protocol version: org.apache.qpid.framing.protocolvers...@9
IoReceiver - localhost/127.0.0.1:5672 2009-06-25 14:29:26,025 DEBUG
[apache.qpid.transport.Connection] RECV: [conn:1ec829f] AMQP.1 0-9
IoReceiver - localhost/127.0.0.1:5672 2009-06-25 14:29:26,025 DEBUG
[apache.qpid.transport.Connection] connection closed: conn:1ec829f
main 2009-06-25 14:29:26,026 INFO [qpid.client.state.StateWaiter] New
StateWaiter :AMQState: id = 1 name: CONNECTION_NOT_STARTED:[AMQState: id = 4
name: CONNECTION_OPEN, AMQState: id = 6 name: CONNECTION_CLOSED]
main 2009-06-25 14:29:26,026 INFO
[qpid.client.transport.SocketTransportConnection] Using
SimpleByteBufferAllocator
main 2009-06-25 14:29:26,026 INFO [qpid.client.transport.TransportConnection]
Using Mina NIO
main 2009-06-25 14:29:26,026 INFO
[qpid.client.transport.SocketTransportConnection] send-buffer-size = 32768
main 2009-06-25 14:29:26,026 INFO
[qpid.client.transport.SocketTransportConnection] recv-buffer-size = 32768
main 2009-06-25 14:29:26,026 INFO
[qpid.client.transport.SocketTransportConnection] Attempting connection to
localhost/127.0.0.1:5672
SocketAcceptorIoProcessor-0.1 2009-06-25 14:29:26,027 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Protocol session created
for:/127.0.0.1:51166
SocketAcceptorIoProcessor-0.1 2009-06-25 14:29:26,027 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Session opened
for:/127.0.0.1:51166
SocketConnectorIoProcessor-1385.0 2009-06-25 14:29:26,028 DEBUG
[qpid.client.protocol.AMQProtocolHandler] Protocol session created for session
24199265
SocketConnectorIoProcessor-1385.0 2009-06-25 14:29:26,028 INFO
[qpid.client.handler.ClientMethodDispatcherImpl] New Method
Dispatcher:org.apache.qpid.client.protocol.amqprotocolsess...@39bfca
SocketConnectorIoProcessor-1385.0 2009-06-25 14:29:26,028 INFO
[qpid.client.state.AMQStateManager] Setting
ProtocolSession:org.apache.qpid.client.protocol.amqprotocolsess...@39bfca
SocketConnectorIoProcessor-1385.0 2009-06-25 14:29:26,028 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x414d515001010009'
AnonymousIoService-6 2009-06-25 14:29:26,028 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] AMQP1109
pool-1-thread-21 2009-06-25 14:29:26,029 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Protocol Session closed
for:/127.0.0.1:51165
AnonymousIoService-4 2009-06-25 14:29:26,255 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionStartBodyImpl: versionMajor=0, versionMinor=9,
serverProperties=null, mechanisms...@4d964, locales...@5c5511]
AnonymousIoService-4 2009-06-25 14:29:26,255 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ConnectionStartBodyImpl: versionMajor=0, versionMinor=9,
serverProperties=null, mechanisms...@4d964, locales...@5c5511]
AnonymousIoService-4 2009-06-25 14:29:26,255 DEBUG
[qpid.client.handler.ConnectionStartMethodHandler] public void
methodReceived(AMQStateManager stateManager, AMQProtocolSession
protocolSession, AMQMethodEvent evt): called
AnonymousIoService-4 2009-06-25 14:29:26,255 INFO
[qpid.client.handler.ClientMethodDispatcherImpl] New Method
Dispatcher:org.apache.qpid.client.protocol.amqprotocolsess...@39bfca
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[qpid.client.handler.ConnectionStartMethodHandler] mechanism = CRAM-MD5
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[qpid.client.state.AMQStateManager] State changing to AMQState: id = 2 name:
CONNECTION_NOT_TUNED from old state AMQState: id = 1 name:
CONNECTION_NOT_STARTED
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[qpid.client.state.AMQStateManager] Notififying State change to 1 :
[org.apache.qpid.client.state.statewai...@1d50fe6]
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] FieldTable::writeToBuffer: Writing encoded
length of 184...
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] {instance=[LONG_STRING: clientid],
product=[LONG_STRING: qpid], version=[LONG_STRING: 0.5], platform=[LONG_STRING:
OpenJDK Runtime Environment, 1.6.0_0-b16, Sun Microsystems Inc., i386, Linux,
2.6.27.21-170.2.56.fc10.i686, unknown]}
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Writing Property:instance Type:LONG_STRING
Value:clientid
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Buffer Position:15 Remaining:204
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Writing Property:product Type:LONG_STRING
Value:qpid
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Buffer Position:37 Remaining:182
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Writing Property:version Type:LONG_STRING
Value:0.5
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Buffer Position:54 Remaining:165
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Writing Property:platform Type:LONG_STRING
Value:OpenJDK Runtime Environment, 1.6.0_0-b16, Sun Microsystems Inc., i386,
Linux, 2.6.27.21-170.2.56.fc10.i686, unknown
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.FieldTable] Buffer Position:70 Remaining:149
AnonymousIoService-4 2009-06-25 14:29:26,256 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x010000000000d3000a000b000000b808696e7374616e63655300000008636c69656e7469640770726f647563745300000004717069640776657273696f6e5300000003302e3508706c6174666f726d53000000734f70656e4a444b2052756e74696d6520456e7669726f6e6d656e742c20312e362e305f302d6231362c2053756e204d6963726f73797374656d7320496e632e2c20693338362c204c696e75782c20322e362e32372e32312d3137302e322e35362e666331302e693638362c20756e6b6e6f776e084352414d2d4d44350000000005656e5f5553ce'
AnonymousIoService-2 2009-06-25 14:29:26,256 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionStartOkBodyImpl:
clientProperties={instance=[LONG_STRING: clientid], product=[LONG_STRING:
qpid], version=[LONG_STRING: 0.5], platform=[LONG_STRING: OpenJDK Runtime
Environment, 1.6.0_0-b16, Sun Microsystems Inc., i386, Linux,
2.6.27.21-170.2.56.fc10.i686, unknown]}, mechanism=CRAM-MD5, response=null,
locale=en_US]
pool-1-thread-25 2009-06-25 14:29:26,257 INFO
[qpid.server.handler.ConnectionStartOkMethodHandler] SASL Mechanism selected:
CRAM-MD5
pool-1-thread-25 2009-06-25 14:29:26,257 INFO
[qpid.server.handler.ConnectionStartOkMethodHandler] Locale selected: en_US
AnonymousIoService-5 2009-06-25 14:29:26,269 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionSecureBodyImpl: challenge...@106f631]
AnonymousIoService-5 2009-06-25 14:29:26,269 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ConnectionSecureBodyImpl: challenge...@106f631]
AnonymousIoService-5 2009-06-25 14:29:26,269 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x0100000000002e000a0015000000266775657374206534323931613438623436623637373639666531326535343936613063653463ce'
AnonymousIoService-7 2009-06-25 14:29:26,269 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionSecureOkBodyImpl: response...@d19da]
pool-1-thread-27 2009-06-25 14:29:26,271 INFO
[qpid.server.handler.ConnectionSecureOkMethodHandler] Connected as: guest
pool-1-thread-27 2009-06-25 14:29:26,271 INFO
[qpid.server.handler.ConnectionStartOkMethodHandler] Framesize set to 65535
AnonymousIoService-16 2009-06-25 14:29:26,272 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionTuneBodyImpl: channelMax=65535, frameMax=65535,
heartbeat=0]
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ConnectionTuneBodyImpl: channelMax=65535, frameMax=65535, heartbeat=0]
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[qpid.client.handler.ConnectionTuneMethodHandler] ConnectionTune frame received
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[qpid.client.state.AMQStateManager] State changing to AMQState: id = 3 name:
CONNECTION_NOT_OPENED from old state AMQState: id = 2 name: CONNECTION_NOT_TUNED
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[qpid.client.state.AMQStateManager] Notififying State change to 1 :
[org.apache.qpid.client.state.statewai...@1d50fe6]
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x0100000000000c000a001fffff0000ffff0000ce'
AnonymousIoService-16 2009-06-25 14:29:26,272 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x0100000000000c000a0028052f746573740001ce'
AnonymousIoService-1 2009-06-25 14:29:26,272 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionTuneOkBodyImpl: channelMax=65535, frameMax=65535,
heartbeat=0]
AnonymousIoService-1 2009-06-25 14:29:26,272 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionOpenBodyImpl: virtualHost=/test, capabilities=null,
insist=true]
AnonymousIoService-12 2009-06-25 14:29:26,366 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionOpenOkBodyImpl: knownHosts=/test]
AnonymousIoService-12 2009-06-25 14:29:26,366 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ConnectionOpenOkBodyImpl: knownHosts=/test]
AnonymousIoService-12 2009-06-25 14:29:26,366 DEBUG
[qpid.client.state.AMQStateManager] State changing to AMQState: id = 4 name:
CONNECTION_OPEN from old state AMQState: id = 3 name: CONNECTION_NOT_OPENED
AnonymousIoService-12 2009-06-25 14:29:26,366 DEBUG
[qpid.client.state.AMQStateManager] Notififying State change to 1 :
[org.apache.qpid.client.state.statewai...@1d50fe6]
main 2009-06-25 14:29:26,366 DEBUG [apache.qpid.client.AMQConnection] Are we
connected:true
main 2009-06-25 14:29:26,366 DEBUG
[apache.qpid.client.AMQConnectionDelegate_8_0] Write channel open frame for
channel id 1
main 2009-06-25 14:29:26,366 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x010001000000050014000a00ce'
AnonymousIoService-3 2009-06-25 14:29:26,366 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelOpenBodyImpl: outOfBand=null]
AnonymousIoService-15 2009-06-25 14:29:26,374 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelOpenOkBodyImpl: channelid...@1c51e8]
AnonymousIoService-15 2009-06-25 14:29:26,374 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ChannelOpenOkBodyImpl: channelid...@1c51e8]
main 2009-06-25 14:29:26,374 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x0100010000000b003c000a0000000003e800ce'
AnonymousIoService-13 2009-06-25 14:29:26,374 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [BasicQosBodyImpl: prefetchSize=0, prefetchCount=1000,
global=false]
AnonymousIoService-14 2009-06-25 14:29:26,375 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [BasicQosOkBodyImpl: ]
AnonymousIoService-14 2009-06-25 14:29:26,375 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[BasicQosOkBodyImpl: ]
main 2009-06-25 14:29:26,375 DEBUG [apache.qpid.filter.JMSSelectorFilter]
Created JMSSelectorFilter with selector:Selector = 'select'
main 2009-06-25 14:29:26,375 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000001b0028000a000009616d712e746f70696305746f7069630100000000ce'
AnonymousIoService-8 2009-06-25 14:29:26,375 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ExchangeDeclareBodyImpl: ticket=0, exchange=amq.topic,
type=topic, passive=true, durable=false, autoDelete=false, internal=false,
nowait=false, arguments=null]
AnonymousIoService-9 2009-06-25 14:29:26,376 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ExchangeDeclareOkBodyImpl: ]
AnonymousIoService-9 2009-06-25 14:29:26,376 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ExchangeDeclareOkBodyImpl: ]
main 2009-06-25 14:29:26,376 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x010001000000200032000a000014746d705f3132372e302e302e3135313136365f310c00000000ce'
AnonymousIoService-6 2009-06-25 14:29:26,376 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [QueueDeclareBodyImpl: ticket=0, queue=tmp_127.0.0.151166_1,
passive=false, durable=false, exclusive=true, autoDelete=true, nowait=false,
arguments=null]
pool-1-thread-6 2009-06-25 14:29:26,381 INFO
[qpid.server.handler.QueueDeclareHandler] Queue tmp_127.0.0.151166_1 bound to
default exchange(<<default>>)
pool-1-thread-6 2009-06-25 14:29:26,381 INFO
[qpid.server.handler.QueueDeclareHandler] Queue tmp_127.0.0.151166_1 declared
successfully
AnonymousIoService-4 2009-06-25 14:29:26,381 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [QueueDeclareOkBodyImpl: queue=tmp_127.0.0.151166_1,
messageCount=0, consumerCount=0]
AnonymousIoService-4 2009-06-25 14:29:26,381 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[QueueDeclareOkBodyImpl: queue=tmp_127.0.0.151166_1, messageCount=0,
consumerCount=0]
main 2009-06-25 14:29:26,382 DEBUG [apache.qpid.framing.FieldTable]
FieldTable::writeToBuffer: Writing encoded length of 46...
main 2009-06-25 14:29:26,382 DEBUG [apache.qpid.framing.FieldTable]
{x-filter-jms-selector=[LONG_STRING: Selector = 'select']}
main 2009-06-25 14:29:26,382 DEBUG [apache.qpid.framing.FieldTable] Writing
Property:x-filter-jms-selector Type:LONG_STRING Value:Selector = 'select'
main 2009-06-25 14:29:26,382 DEBUG [apache.qpid.framing.FieldTable] Buffer
Position:61 Remaining:47
main 2009-06-25 14:29:26,382 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000006400320014000014746d705f3132372e302e302e3135313136365f3109616d712e746f7069630b746573744e6f4c6f63616c000000002e15782d66696c7465722d6a6d732d73656c6563746f72530000001353656c6563746f72203d202773656c65637427ce'
AnonymousIoService-2 2009-06-25 14:29:26,382 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [QueueBindBodyImpl: ticket=0, queue=tmp_127.0.0.151166_1,
exchange=amq.topic, routingKey=testNoLocal, nowait=false,
arguments={x-filter-jms-selector=[LONG_STRING: Selector = 'select']}]
pool-1-thread-8 2009-06-25 14:29:26,405 INFO
[qpid.server.handler.QueueBindHandler] Binding queue
org.apache.qpid.server.queue.simpleamqqu...@41f227 to exchange
TopicExchange[amq.topic] with routing key testNoLocal
AnonymousIoService-5 2009-06-25 14:29:26,406 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [QueueBindOkBodyImpl: ]
AnonymousIoService-5 2009-06-25 14:29:26,406 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[QueueBindOkBodyImpl: ]
main 2009-06-25 14:29:26,406 DEBUG [apache.qpid.client.AMQSession] Setting
channel flow : suspended
main 2009-06-25 14:29:26,406 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x010001000000050014001400ce'
AnonymousIoService-7 2009-06-25 14:29:26,406 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelFlowBodyImpl: active=false]
AnonymousIoService-16 2009-06-25 14:29:26,406 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelFlowOkBodyImpl: active=false]
AnonymousIoService-16 2009-06-25 14:29:26,406 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ChannelFlowOkBodyImpl: active=false]
AnonymousIoService-16 2009-06-25 14:29:26,406 DEBUG
[qpid.client.handler.ChannelFlowOkMethodHandler] Received Channel.Flow-Ok
message, active = false
main 2009-06-25 14:29:26,406 INFO [apache.qpid.client.AMQSession] Prefetching
delayed existing messages will not flow until requested via receive*() or
setML().
main 2009-06-25 14:29:26,407 DEBUG [apache.qpid.framing.FieldTable]
FieldTable::writeToBuffer: Writing encoded length of 46...
main 2009-06-25 14:29:26,407 DEBUG [apache.qpid.framing.FieldTable]
{x-filter-jms-selector=[LONG_STRING: Selector = 'select']}
main 2009-06-25 14:29:26,407 DEBUG [apache.qpid.framing.FieldTable] Writing
Property:x-filter-jms-selector Type:LONG_STRING Value:Selector = 'select'
main 2009-06-25 14:29:26,407 DEBUG [apache.qpid.framing.FieldTable] Buffer
Position:41 Remaining:47
main 2009-06-25 14:29:26,407 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x01000100000050003c0014000014746d705f3132372e302e302e3135313136365f310131060000002e15782d66696c7465722d6a6d732d73656c6563746f72530000001353656c6563746f72203d202773656c65637427ce'
AnonymousIoService-1 2009-06-25 14:29:26,407 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [BasicConsumeBodyImpl: ticket=0, queue=tmp_127.0.0.151166_1,
consumerTag=1, noLocal=false, noAck=true, exclusive=true, nowait=false,
arguments={x-filter-jms-selector=[LONG_STRING: Selector = 'select']}]
AnonymousIoService-12 2009-06-25 14:29:26,414 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [BasicConsumeOkBodyImpl: consumerTag=1]
AnonymousIoService-12 2009-06-25 14:29:26,414 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[BasicConsumeOkBodyImpl: consumerTag=1]
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000001b0028000a000009616d712e746f70696305746f7069631000000000ce'
main 2009-06-25 14:29:26,414 INFO [apache.qpid.client.BasicMessageProducer_0_8]
MessageProducer org.apache.qpid.client.basicmessageproducer_...@1457b54 using
publish mode : ASYNC_PUBLISH_ALL
AnonymousIoService-3 2009-06-25 14:29:26,414 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ExchangeDeclareBodyImpl: ticket=0, exchange=amq.topic,
type=topic, passive=false, durable=false, autoDelete=false, internal=false,
nowait=true, arguments=null]
main 2009-06-25 14:29:26,414 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content body frames to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,414 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content header frame to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable]
FieldTable::writeToBuffer: Writing encoded length of 0...
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable] {}
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000001d003c0028000009616d712e746f7069630b746573744e6f4c6f63616c00ce0200010000005c003c0000000000000000000ef9d00a746578742f706c61696e055554462d38000000000200002749443a66346661333734352d633061642d333865622d616663352d3462646233366662333530380000012218ade90e056775657374ce0300010000000e6e6f6e2d6d61746368696e672031ce'
main 2009-06-25 14:29:26,414 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content body frames to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,414 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content header frame to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable]
FieldTable::writeToBuffer: Writing encoded length of 20...
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable]
{Selector=[LONG_STRING: select]}
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable] Writing
Property:Selector Type:LONG_STRING Value:select
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.FieldTable] Buffer
Position:79 Remaining:91
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000001d003c0028000009616d712e746f7069630b746573744e6f4c6f63616c00ce02000100000070003c00000000000000000005f9d00a746578742f706c61696e055554462d38000000140853656c6563746f72530000000673656c6563740200002749443a61626235336666622d646230662d336562612d616338382d6631323333663439393464380000012218ade90e056775657374ce0300010000000568656c6c6fce'
main 2009-06-25 14:29:26,414 DEBUG [apache.qpid.client.AMQSession] Setting
channel flow : unsuspended
main 2009-06-25 14:29:26,415 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is '0x010001000000050014001401ce'
AnonymousIoService-15 2009-06-25 14:29:26,415 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff]
org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 1,
bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.topic,
routingKey=testNoLocal, mandatory=false, immediate=false]] 1=[Frame channelId:
1, bodyFrame: org.apache.qpid.framing.contentheaderb...@a3e632] 2=[Frame
channelId: 1, bodyFrame: org.apache.qpid.framing.contentb...@5e04f3]}
AnonymousIoService-15 2009-06-25 14:29:26,415 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff]
org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 1,
bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.topic,
routingKey=testNoLocal, mandatory=false, immediate=false]] 1=[Frame channelId:
1, bodyFrame: org.apache.qpid.framing.contentheaderb...@972413] 2=[Frame
channelId: 1, bodyFrame: org.apache.qpid.framing.contentb...@c17d8c]}
AnonymousIoService-15 2009-06-25 14:29:26,415 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelFlowBodyImpl: active=true]
pool-1-thread-16 2009-06-25 14:29:26,418 INFO
[qpid.server.exchange.TopicExchange] Message routing key: testNoLocal No routes.
pool-1-thread-16 2009-06-25 14:29:26,471 WARN
[qpid.server.queue.IncomingMessage] MESSAGE DISCARDED: No routes for message -
Message[(HC:10188666 ID:21 Ref:1)]: 21; ref count: 1
AnonymousIoService-13 2009-06-25 14:29:26,498 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [ChannelFlowOkBodyImpl: active=true]
AnonymousIoService-13 2009-06-25 14:29:26,498 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ChannelFlowOkBodyImpl: active=true]
AnonymousIoService-13 2009-06-25 14:29:26,498 DEBUG
[qpid.client.handler.ChannelFlowOkMethodHandler] Received Channel.Flow-Ok
message, active = true
main 2009-06-25 14:29:26,499 DEBUG [qpid.client.AMQSession.Dispatcher] Set
Dispatcher Connection Started: Currently Started
Dispatcher-Channel-1 2009-06-25 14:29:26,499 INFO
[qpid.client.AMQSession.Dispatcher] Dispatcher-Channel-1 started
main 2009-06-25 14:29:26,499 INFO [qpid.client.AMQSession.Dispatcher]
Dispatcher-Channel-1 created
AnonymousIoService-14 2009-06-25 14:29:26,509 DEBUG
[apache.qpid.framing.BasicContentHeaderProperties] Property flags: 63952
AnonymousIoService-14 2009-06-25 14:29:26,509 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=1,
redelivered=false, exchange=amq.topic, routingKey=testNoLocal]
AnonymousIoService-14 2009-06-25 14:29:26,509 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[BasicDeliverBodyImpl: consumerTag=1, deliveryTag=1, redelivered=false,
exchange=amq.topic, routingKey=testNoLocal]
AnonymousIoService-14 2009-06-25 14:29:26,509 DEBUG
[qpid.client.handler.BasicDeliverMethodHandler] New JmsDeliver method
received:org.apache.qpid.client.protocol.amqprotocolsess...@39bfca
AnonymousIoService-14 2009-06-25 14:29:26,509 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: org.apache.qpid.framing.contentheaderb...@767b83
AnonymousIoService-14 2009-06-25 14:29:26,509 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
1, bodyFrame: org.apache.qpid.framing.contentb...@a70f23
AnonymousIoService-14 2009-06-25 14:29:26,509 DEBUG
[apache.qpid.client.AMQSession] Message[ContentHeader
org.apache.qpid.framing.contentheaderb...@767b83] received in session
Dispatcher-Channel-1 2009-06-25 14:29:26,509 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Non-fragmented message body
(bodySize=5)
Dispatcher-Channel-1 2009-06-25 14:29:26,509 DEBUG
[qpid.client.message.AbstractJMSMessageFactory] Creating message from buffer
with position=0 and remaining=5
Dispatcher-Channel-1 2009-06-25 14:29:26,509 DEBUG
[apache.qpid.framing.FieldTable] FieldTable::PropFieldTable(buffer,20): Read
type 'LONG_STRING', key 'Selector', value 'select'
Dispatcher-Channel-1 2009-06-25 14:29:26,509 DEBUG
[apache.qpid.framing.FieldTable] FieldTable::FieldTable(buffer,20): Done.
Dispatcher-Channel-1 2009-06-25 14:29:26,509 DEBUG
[apache.qpid.client.BasicMessageConsumer] Message is of type:
org.apache.qpid.client.message.JMSTextMessage
main 2009-06-25 14:29:26,510 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content body frames to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,510 DEBUG
[apache.qpid.client.BasicMessageProducer_0_8] Sending content header frame to
topic://amq.topic/testNoLocal/tmp_127.0.0.151166_1?routingkey='testNoLocal'&exclusive='true'&autodelete='true'
main 2009-06-25 14:29:26,510 DEBUG [apache.qpid.framing.FieldTable]
FieldTable::writeToBuffer: Writing encoded length of 0...
main 2009-06-25 14:29:26,510 DEBUG [apache.qpid.framing.FieldTable] {}
main 2009-06-25 14:29:26,510 DEBUG [apache.qpid.framing.AMQDataBlockEncoder]
Encoded frame byte-buffer is
'0x0100010000001d003c0028000009616d712e746f7069630b746573744e6f4c6f63616c00ce0200010000005c003c0000000000000000000ef9d00a746578742f706c61696e055554462d38000000000200002749443a38346439323262312d643765642d333035342d616561382d6465366231666264616263380000012218ade96e056775657374ce0300010000000e6e6f6e2d6d61746368696e672032ce'
pool-1-thread-22 2009-06-25 14:29:26,511 INFO
[qpid.server.exchange.TopicExchange] Message routing key: testNoLocal No routes.
pool-1-thread-22 2009-06-25 14:29:26,511 INFO [apache.qpid.server.AMQChannel]
Unsubscribing all consumers on channel [/127.0.0.1:51166(guest):1]
pool-1-thread-22 2009-06-25 14:29:26,511 INFO [apache.qpid.server.AMQChannel]
Unsubscribing consumer '1' on channel [/127.0.0.1:51166(guest):1]
pool-1-thread-22 2009-06-25 14:29:26,511 INFO
[qpid.server.queue.SimpleAMQQueue] Auto-deleteing
queue:org.apache.qpid.server.queue.simpleamqqu...@41f227
pool-1-thread-22 2009-06-25 14:29:26,512 ERROR
[qpid.server.protocol.AMQPFastProtocolHandler] Exception caught
in/127.0.0.1:51166(guest), closing session explictly:
org.apache.qpid.AMQException: Fatal internal error: transactional context is
not empty at beginTran:
org.apache.qpid.server.store.derbymessagestore$connectionwrap...@128215d
org.apache.qpid.AMQException: Fatal internal error: transactional context is
not empty at beginTran:
org.apache.qpid.server.store.derbymessagestore$connectionwrap...@128215d
at
org.apache.qpid.server.store.DerbyMessageStore.beginTran(DerbyMessageStore.java:974)
at
org.apache.qpid.server.txn.NonTransactionalContext.beginTranIfNecessary(NonTransactionalContext.java:76)
at
org.apache.qpid.server.queue.IncomingMessage.routingComplete(IncomingMessage.java:134)
at
org.apache.qpid.server.AMQChannel.publishContentHeader(AMQChannel.java:177)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.contentHeaderReceived(AMQMinaProtocolSession.java:368)
at
org.apache.qpid.framing.ContentHeaderBody.handle(ContentHeaderBody.java:118)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.frameReceived(AMQMinaProtocolSession.java:240)
at
org.apache.qpid.server.protocol.AMQMinaProtocolSession.dataBlockReceived(AMQMinaProtocolSession.java:197)
at
org.apache.qpid.server.protocol.AMQPFastProtocolHandler.messageReceived(AMQPFastProtocolHandler.java:248)
at
org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:703)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
at
org.apache.qpid.pool.PoolingFilter.messageReceived(PoolingFilter.java:334)
at
org.apache.mina.filter.ReferenceCountingIoFilter.messageReceived(ReferenceCountingIoFilter.java:96)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
at
org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:60)
at
org.apache.mina.filter.codec.QpidProtocolCodecFilter.messageReceived(QpidProtocolCodecFilter.java:174)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
at org.apache.qpid.pool.Event$ReceivedEvent.process(Event.java:86)
at org.apache.qpid.pool.Job.processAll(Job.java:114)
at org.apache.qpid.pool.Job.run(Job.java:153)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
pool-1-thread-22 2009-06-25 14:29:26,513 INFO
[qpid.server.protocol.AMQProtocolSession] Channel[1] awaiting closure. Should
close socket as client did not close-ok :Frame channelId: 1, bodyFrame:
org.apache.qpid.framing.contentb...@1ed13da
AnonymousIoService-9 2009-06-25 14:29:26,514 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff]
org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 1,
bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.topic,
routingKey=testNoLocal, mandatory=false, immediate=false]] 1=[Frame channelId:
1, bodyFrame: org.apache.qpid.framing.contentheaderb...@109f3f0] 2=[Frame
channelId: 1, bodyFrame: org.apache.qpid.framing.contentb...@6e29b0]}
AnonymousIoService-6 2009-06-25 14:29:26,514 INFO [qpid.protocol] RECV:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=200, replyText=Fatal internal
error: transactional context is not empty at beginTran:
org.apache.qpid.server.store.derbymessagestore$connectionwrap...@128215d,
classId=0, methodId=0]
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[qpid.client.protocol.AMQProtocolHandler] (22975231)Method frame received:
[ConnectionCloseBodyImpl: replyCode=200, replyText=Fatal internal error:
transactional context is not empty at beginTran:
org.apache.qpid.server.store.derbymessagestore$connectionwrap...@128215d,
classId=0, methodId=0]
AnonymousIoService-6 2009-06-25 14:29:26,514 INFO
[qpid.client.handler.ConnectionCloseMethodHandler] ConnectionClose frame
received
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[apache.qpid.framing.AMQDataBlockEncoder] Encoded frame byte-buffer is
'0x01000000000004000a0033ce'
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[qpid.client.protocol.AMQProtocolSession] Waiting for last write to join.
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[qpid.client.protocol.AMQProtocolSession] Closing protocol session
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[qpid.client.state.AMQStateManager] State changing to AMQState: id = 6 name:
CONNECTION_CLOSED from old state AMQState: id = 4 name: CONNECTION_OPEN
AnonymousIoService-6 2009-06-25 14:29:26,514 DEBUG
[qpid.client.state.AMQStateManager] Notififying State change to 0 : []
AnonymousIoService-6 2009-06-25 14:29:26,515 DEBUG [qpid.protocol] SEND:
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] Frame channelId:
0, bodyFrame: [ConnectionCloseOkBodyImpl: ]
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[qpid.client.protocol.AMQProtocolHandler] Session closed called with failover
state currently FailoverState: NOT STARTED
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[apache.qpid.jms.FailoverPolicy] All failover methods exhausted
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[qpid.client.protocol.AMQProtocolHandler] Failover not allowed by policy.
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[apache.qpid.jms.FailoverPolicy] All failover methods exhausted
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[qpid.client.protocol.AMQProtocolHandler] Failover Policy:
Failover not allowed
Failover policy methods
>Single Server:
Max Retries:0
Current Retry:0
tcp://localhost:5672
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[qpid.client.protocol.AMQProtocolHandler] sessionClose() not allowed to failover
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[apache.qpid.client.AMQConnection] exceptionReceived done
by:AnonymousIoService-4
org.apache.qpid.AMQDisconnectedException: Server closed connection and
reconnection not permitted.
at
org.apache.qpid.client.protocol.AMQProtocolHandler.sessionClosed(AMQProtocolHandler.java:329)
at
org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.sessionClosed(AbstractIoFilterChain.java:677)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFilter.java:280)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
at
org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:265)
at
org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:305)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:636)
AnonymousIoService-4 2009-06-25 14:29:26,515 ERROR
[qpid.client.state.AMQStateManager] No Waiters for error saving as last
error:Exception thrown against AMQConnection:
Host: localhost
Port: 5672
Virtual Host: test
Client ID: clientid
Active session count: 1: org.apache.qpid.AMQDisconnectedException: Server
closed connection and reconnection not permitted.
AnonymousIoService-4 2009-06-25 14:29:26,515 ERROR
[apache.qpid.client.AMQConnection] Throwable Received but no listener set:
Server closed connection and reconnection not permitted.
AnonymousIoService-4 2009-06-25 14:29:26,515 INFO
[apache.qpid.client.AMQConnection] Closing AMQConnection due to :Server closed
connection and reconnection not permitted.
Dispatcher-Channel-1 2009-06-25 14:29:26,515 INFO
[qpid.client.AMQSession.Dispatcher] Dispatcher-Channel-1 thread terminating for
channel 1
AnonymousIoService-4 2009-06-25 14:29:26,515 DEBUG
[apache.qpid.client.BasicMessageConsumer] Passed exception to synchronous queue
for propagation to receive()
AnonymousIoService-4 2009-06-25 14:29:26,516 DEBUG
[qpid.client.protocol.AMQProtocolHandler] Protocol Session
[org.apache.qpid.client.protocol.amqprotocolhand...@15e92ff] closed
pool-1-thread-23 2009-06-25 14:29:26,516 INFO
[qpid.server.protocol.AMQPFastProtocolHandler] Protocol Session closed
for:/127.0.0.1:51166
main 2009-06-25 14:29:26,516 INFO [qpid.test.utils.QpidTestCase] stopping
broker: /home/rhs/qpid/java/build/bin/qpid-server -p 5672 -m 8999 -c
/home/rhs/qpid/java/build/etc/config-systests.xml -l
/home/rhs/qpid/java/log4j-test.xml
main 2009-06-25 14:29:26,574 INFO [qpid.test.utils.QpidTestCase] broker exited:
143
main 2009-06-25 14:29:26,575 INFO [qpid.test.utils.QpidTestCase] ==========
stop TopicSessionTest.testNonMatchingMessagesDoNotFillQueue ==========
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:[email protected]
