[
https://issues.apache.org/jira/browse/QPIDJMS-376?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16501593#comment-16501593
]
Daniel Maier commented on QPIDJMS-376:
--------------------------------------
Thanks a lot.
I tried my "special" scenario (client tries to re-connect due to fail-over but
on successful re-connect prio established link cannot be established again)
with the snapshot, without success. Can you please have a look at my logs? It
seems that I am not allowed to attach files to a closed issue. Here is a
excerpt of the log:
{code:java}
2018-06-05 12:40:03.233 [FailoverProvider: connect thread] INFO
o.a.q.j.p.failover.FailoverProvider - Connection attempt:[11] to:
amqps://192.168.99.100:30071 failed
2018-06-05 12:40:03.235 [FailoverProvider: connect thread] TRACE
o.a.qpid.jms.util.ThreadPoolUtils - Shutdown of ExecutorService:
java.util.concurrent.ScheduledThreadPoolExecutor@66906e1d[Running, pool size =
1, active threads = 0, queued tasks = 0, completed tasks = 2] with await
termination: 10000 millis
2018-06-05 12:40:03.235 [FailoverProvider: connect thread] DEBUG
o.a.qpid.jms.util.ThreadPoolUtils - Shutdown of ExecutorService:
java.util.concurrent.ScheduledThreadPoolExecutor@66906e1d[Terminated, pool size
= 0, active threads = 0, queued tasks = 0, completed tasks = 2] is shutdown:
true and terminated: true took: 0.000 seconds.
2018-06-05 12:40:03.236 [FailoverProvider: connect thread] TRACE
o.a.q.j.p.failover.FailoverProvider - Connection attempt:[11] failed error:
syscall:getsockopt(..) failed: Connection refused: /192.168.99.100:30071
2018-06-05 12:40:03.236 [FailoverProvider: connect thread] TRACE
o.a.q.j.p.failover.FailoverProvider - Next reconnect attempt will be in 10240
milliseconds
2018-06-05 12:40:13.477 [FailoverProvider: connect thread] DEBUG
o.a.q.j.p.failover.FailoverProvider - Connection attempt:[12] to:
amqps://192.168.99.100:30071 in-progress
2018-06-05 12:40:13.478 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Getting SSLContext instance using
protocol: TLS
2018-06-05 12:40:13.479 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Default protocols from the
SSLEngine: [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2]
2018-06-05 12:40:13.479 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Disabled protocols: [SSLv2Hello,
SSLv3]
2018-06-05 12:40:13.479 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Enabled protocols: [TLSv1, TLSv1.1,
TLSv1.2]
2018-06-05 12:40:13.479 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Default cipher suites from the
SSLEngine: [TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2018-06-05 12:40:13.480 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Enabled cipher suites:
[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2018-06-05 12:40:13.480 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Netty Transport using Epoll mode
2018-06-05 12:40:13.561 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - SSL Handshake has completed: [id:
0xee93b98b, L:/192.168.99.1:46244 - R:192.168.99.100/192.168.99.100:30071]
2018-06-05 12:40:13.561 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - Channel has become active! Channel is [id:
0xee93b98b, L:/192.168.99.1:46244 - R:192.168.99.100/192.168.99.100:30071]
2018-06-05 12:40:13.561 [epollEventLoopGroup-15-1] DEBUG
io.netty.handler.ssl.SslHandler - [id: 0xee93b98b, L:/192.168.99.1:46244 -
R:192.168.99.100/192.168.99.100:30071] HANDSHAKEN:
TLS_RSA_WITH_AES_256_CBC_SHA256
2018-06-05 12:40:13.562 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 8 bytes
2018-06-05 12:40:13.569 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 8 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 69)
2018-06-05 12:40:13.570 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: CONNECTION_INIT
2018-06-05 12:40:13.595 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 99 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 99, cap: 165)
2018-06-05 12:40:13.596 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping SCRAM-SHA-1 mechanism
because it is not in the configured mechanisms restriction set
2018-06-05 12:40:13.596 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping SCRAM-SHA-256 mechanism
because it is not in the configured mechanisms restriction set
2018-06-05 12:40:13.596 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Unknown SASL mechanism:
[SCRAM-SHA-512]
2018-06-05 12:40:13.597 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping XOAUTH2 mechanism because
it is not in the configured mechanisms restriction set
2018-06-05 12:40:13.597 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
INFO o.a.q.jms.sasl.SaslMechanismFinder - Best match for SASL auth was:
SASL-PLAIN
2018-06-05 12:40:13.597 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 69 bytes
2018-06-05 12:40:13.662 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 22 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 22, cap: 85)
2018-06-05 12:40:13.663 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 8 bytes
2018-06-05 12:40:13.664 [FailoverProvider: serialization thread] DEBUG
o.a.q.j.p.failover.FailoverProvider - Signalling connection recovery:
AmqpProvider: 192.168.99.100:30071
2018-06-05 12:40:13.664 [FailoverProvider: serialization thread] DEBUG
org.apache.qpid.jms.JmsConnection - Connection
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 is starting recovery.
[953254382:0] -> Open{ containerId='cfid', hostname='192.168.99.100',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS,
version=0.33.0-SNAPSHOT, platform=JVM: 1.8.0_171, 25.171-b11, Oracle
Corporation, OS: Linux, 4.13.0-36-generic, amd64}}
2018-06-05 12:40:13.664 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Open{ containerId='cfid',
hostname='192.168.99.100', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container,
DELAYED_DELIVERY, ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS,
version=0.33.0-SNAPSHOT, platform=JVM: 1.8.0_171, 25.171-b11, Oracle
Corporation, OS: Linux, 4.13.0-36-generic, amd64}}
2018-06-05 12:40:13.665 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 279 bytes
2018-06-05 12:40:13.669 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 8 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 69)
2018-06-05 12:40:13.669 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_LOCAL_OPEN
2018-06-05 12:40:13.671 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 144 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 144, cap: 213)
[953254382:0] <- Open{ containerId='Router.qdrouterd-756f57946-r7zlw',
hostname='null', maxFrameSize=16384, channelMax=32767, idleTimeOut=8000,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY], desiredCapabilities=null,
properties={product=qpid-dispatch-router, version=1.1.0}}
2018-06-05 12:40:13.673 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Open{
containerId='Router.qdrouterd-756f57946-r7zlw', hostname='null',
maxFrameSize=16384, channelMax=32767, idleTimeOut=8000, outgoingLocales=null,
incomingLocales=null, offeredCapabilities=[ANONYMOUS-RELAY],
desiredCapabilities=null, properties={product=qpid-dispatch-router,
version=1.1.0}}
2018-06-05 12:40:13.673 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_REMOTE_OPEN
2018-06-05 12:40:13.674 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: SESSION_INIT
2018-06-05 12:40:13.674 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_LOCAL_OPEN
[953254382:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:13.674 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647,
handleMax=65535, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.675 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 32 bytes
2018-06-05 12:40:13.678 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 35 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 35, cap: 101)
[953254382:0] <- Begin{remoteChannel=0, nextOutgoingId=0,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:13.679 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Begin{remoteChannel=0,
nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647,
handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.679 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_REMOTE_OPEN
2018-06-05 12:40:13.679 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.j.p.a.b.AmqpConnectionBuilder - AmqpConnection {
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 } is now open:
2018-06-05 12:40:13.679 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck being initiated,
initial delay: 4000
[953254382:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:13.682 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647,
handleMax=65535, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.682 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 32 bytes
2018-06-05 12:40:13.686 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 35 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 35, cap: 101)
[953254382:1] <- Begin{remoteChannel=1, nextOutgoingId=0,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:13.687 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Begin{remoteChannel=1,
nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647,
handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.687 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: SESSION_INIT
2018-06-05 12:40:13.687 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_LOCAL_OPEN
2018-06-05 12:40:13.687 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_REMOTE_OPEN
[953254382:1] ->
Attach{name='qpid-jms:receiver:ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1:1:1:telemetry/PERF_TEST_TENANT',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='telemetry/PERF_TEST_TENANT', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.689 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT:
Attach{name='qpid-jms:receiver:ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1:1:1:telemetry/PERF_TEST_TENANT',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='telemetry/PERF_TEST_TENANT', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.689 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 266 bytes
2018-06-05 12:40:13.694 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 212 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 212, cap: 277)
[953254382:1] <-
Attach{name='qpid-jms:receiver:ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1:1:1:telemetry/PERF_TEST_TENANT',
handle=0, role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST, source=null,
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=0, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:13.696 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV:
Attach{name='qpid-jms:receiver:ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1:1:1:telemetry/PERF_TEST_TENANT',
handle=0, role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST, source=null,
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=0, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
[953254382:1] <- Detach{handle=0, closed=true,
error=Error{condition=amqp:not-found, description='Node not found', info=null}}
2018-06-05 12:40:13.697 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Detach{handle=0, closed=true,
error=Error{condition=amqp:not-found, description='Node not found', info=null}}
2018-06-05 12:40:13.697 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_INIT
2018-06-05 12:40:13.698 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_LOCAL_OPEN
2018-06-05 12:40:13.698 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_REMOTE_OPEN
2018-06-05 12:40:13.698 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_REMOTE_CLOSE
2018-06-05 12:40:13.700 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
WARN o.a.q.j.p.a.b.AmqpResourceBuilder - Open of resource:(JmsConsumerInfo: {
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1:1:1, destination =
telemetry/PERF_TEST_TENANT }) failed: Node not found [condition =
amqp:not-found]
2018-06-05 12:40:13.700 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_LOCAL_CLOSE
2018-06-05 12:40:13.700 [FailoverProvider: serialization thread] TRACE
o.a.q.j.p.failover.FailoverProvider - Connection attempt:[12] to:
amqps://192.168.99.100:30071?amqp.saslMechanisms=PLAIN&transport.trustAll=true&transport.verifyHost=false&amqp.traceFrames=true
failed
2018-06-05 12:40:13.700 [FailoverProvider: serialization thread] DEBUG
o.a.q.j.p.failover.FailoverProvider - handling Provider failure: Node not found
[condition = amqp:not-found]
2018-06-05 12:40:13.701 [FailoverProvider: serialization thread] TRACE
o.a.q.j.p.failover.FailoverProvider - stack
java.io.IOException: Node not found [condition = amqp:not-found]
at
org.apache.qpid.jms.util.IOExceptionSupport.create(IOExceptionSupport.java:45)
at
org.apache.qpid.jms.provider.ProviderFuture.failOnError(ProviderFuture.java:114)
at org.apache.qpid.jms.provider.ProviderFuture.sync(ProviderFuture.java:108)
at
org.apache.qpid.jms.JmsMessageConsumer.onConnectionRecovery(JmsMessageConsumer.java:655)
at org.apache.qpid.jms.JmsSession.onConnectionRecovery(JmsSession.java:1352)
at
org.apache.qpid.jms.JmsConnection.onConnectionRecovery(JmsConnection.java:1275)
at
org.apache.qpid.jms.provider.failover.FailoverProvider$15.run(FailoverProvider.java:601)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
at java.util.concurrent.FutureTask.run(FutureTask.java)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: javax.jms.InvalidDestinationException: Node not found [condition =
amqp:not-found]
at
org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:150)
at
org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:117)
at
org.apache.qpid.jms.provider.amqp.builders.AmqpResourceBuilder.handleClosed(AmqpResourceBuilder.java:185)
at
org.apache.qpid.jms.provider.amqp.builders.AmqpResourceBuilder.processRemoteClose(AmqpResourceBuilder.java:129)
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:995)
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.access$1900(AmqpProvider.java:105)
at
org.apache.qpid.jms.provider.amqp.AmqpProvider$17.run(AmqpProvider.java:854)
... 8 common frames omitted
[953254382:1] -> Detach{handle=0, closed=true, error=null}
2018-06-05 12:40:13.703 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Detach{handle=0, closed=true,
error=null}
2018-06-05 12:40:13.703 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 16 bytes
2018-06-05 12:40:13.703 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.p.amqp.AmqpAbstractResource - AmqpConnection {
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 } requesting close on remote.
[953254382:0] -> Close{error=null}
2018-06-05 12:40:13.705 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Close{error=null}
2018-06-05 12:40:13.705 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 12 bytes
2018-06-05 12:40:13.705 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - Cancelling scheduled
IdleTimeoutCheck
2018-06-05 12:40:13.712 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 12 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 12, cap: 69)
[953254382:0] <- Close{error=null}
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Close{error=null}
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: LINK_FINAL
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_LOCAL_CLOSE
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
TRANSPORT_HEAD_CLOSED
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_REMOTE_CLOSE
2018-06-05 12:40:13.713 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.j.p.amqp.AmqpAbstractResource - AmqpConnection {
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 } is now closed:
2018-06-05 12:40:13.714 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
TRANSPORT_TAIL_CLOSED
2018-06-05 12:40:13.714 [AmqpProvider :(13):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: TRANSPORT_CLOSED
2018-06-05 12:40:13.714 [epollEventLoopGroup-15-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - Channel has gone inactive! Channel is [id:
0xee93b98b, L:/192.168.99.1:46244 ! R:192.168.99.100/192.168.99.100:30071]
2018-06-05 12:40:13.716 [FailoverProvider: serialization thread] TRACE
o.a.qpid.jms.util.ThreadPoolUtils - Shutdown of ExecutorService:
java.util.concurrent.ScheduledThreadPoolExecutor@2ec16b7f[Running, pool size =
1, active threads = 0, queued tasks = 3, completed tasks = 14] with await
termination: 10000 millis
2018-06-05 12:40:13.716 [epollEventLoopGroup-15-1] DEBUG
io.netty.buffer.PoolThreadCache - Freed 13 thread-local buffer(s) from thread:
epollEventLoopGroup-15-1
2018-06-05 12:40:13.720 [FailoverProvider: serialization thread] DEBUG
o.a.qpid.jms.util.ThreadPoolUtils - Shutdown of ExecutorService:
java.util.concurrent.ScheduledThreadPoolExecutor@2ec16b7f[Terminated, pool size
= 0, active threads = 0, queued tasks = 0, completed tasks = 14] is shutdown:
true and terminated: true took: 0.001 seconds.
2018-06-05 12:40:13.721 [FailoverProvider: serialization thread] TRACE
o.a.q.j.p.failover.FailoverProvider - Next reconnect attempt will be in 20480
milliseconds
2018-06-05 12:40:14.563 [threadDeathWatcher-3-2] DEBUG
io.netty.buffer.PoolThreadCache - Freed 6 thread-local buffer(s) from thread:
threadDeathWatcher-3-2
2018-06-05 12:40:34.202 [FailoverProvider: connect thread] DEBUG
o.a.q.j.p.failover.FailoverProvider - Connection attempt:[13] to:
amqps://192.168.99.100:30071 in-progress
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Getting SSLContext instance using
protocol: TLS
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Default protocols from the
SSLEngine: [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2]
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Disabled protocols: [SSLv2Hello,
SSLv3]
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Enabled protocols: [TLSv1, TLSv1.1,
TLSv1.2]
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Default cipher suites from the
SSLEngine: [TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.transports.TransportSupport - Enabled cipher suites:
[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2018-06-05 12:40:34.204 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Netty Transport using Epoll mode
2018-06-05 12:40:34.242 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - SSL Handshake has completed: [id:
0xf69f7326, L:/192.168.99.1:46250 - R:192.168.99.100/192.168.99.100:30071]
2018-06-05 12:40:34.242 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - Channel has become active! Channel is [id:
0xf69f7326, L:/192.168.99.1:46250 - R:192.168.99.100/192.168.99.100:30071]
2018-06-05 12:40:34.242 [epollEventLoopGroup-16-1] DEBUG
io.netty.handler.ssl.SslHandler - [id: 0xf69f7326, L:/192.168.99.1:46250 -
R:192.168.99.100/192.168.99.100:30071] HANDSHAKEN:
TLS_RSA_WITH_AES_256_CBC_SHA256
2018-06-05 12:40:34.244 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 8 bytes
2018-06-05 12:40:34.247 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 8 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 69)
2018-06-05 12:40:34.248 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: CONNECTION_INIT
2018-06-05 12:40:34.262 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 99 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 99, cap: 165)
2018-06-05 12:40:34.263 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping SCRAM-SHA-1 mechanism
because it is not in the configured mechanisms restriction set
2018-06-05 12:40:34.263 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping SCRAM-SHA-256 mechanism
because it is not in the configured mechanisms restriction set
2018-06-05 12:40:34.263 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Unknown SASL mechanism:
[SCRAM-SHA-512]
2018-06-05 12:40:34.263 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.jms.sasl.SaslMechanismFinder - Skipping XOAUTH2 mechanism because
it is not in the configured mechanisms restriction set
2018-06-05 12:40:34.263 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
INFO o.a.q.jms.sasl.SaslMechanismFinder - Best match for SASL auth was:
SASL-PLAIN
2018-06-05 12:40:34.264 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 69 bytes
2018-06-05 12:40:34.321 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 22 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 22, cap: 85)
2018-06-05 12:40:34.322 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 8 bytes
2018-06-05 12:40:34.322 [FailoverProvider: serialization thread] DEBUG
o.a.q.j.p.failover.FailoverProvider - Signalling connection recovery:
AmqpProvider: 192.168.99.100:30071
2018-06-05 12:40:34.322 [FailoverProvider: serialization thread] DEBUG
org.apache.qpid.jms.JmsConnection - Connection
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 is starting recovery.
[1626051893:0] -> Open{ containerId='cfid', hostname='192.168.99.100',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS,
version=0.33.0-SNAPSHOT, platform=JVM: 1.8.0_171, 25.171-b11, Oracle
Corporation, OS: Linux, 4.13.0-36-generic, amd64}}
2018-06-05 12:40:34.323 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Open{ containerId='cfid',
hostname='192.168.99.100', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container,
DELAYED_DELIVERY, ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS,
version=0.33.0-SNAPSHOT, platform=JVM: 1.8.0_171, 25.171-b11, Oracle
Corporation, OS: Linux, 4.13.0-36-generic, amd64}}
2018-06-05 12:40:34.323 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 279 bytes
2018-06-05 12:40:34.324 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 8 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 69)
2018-06-05 12:40:34.324 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_LOCAL_OPEN
2018-06-05 12:40:34.325 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 144 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 144, cap: 213)
[1626051893:0] <- Open{ containerId='Router.qdrouterd-756f57946-r7zlw',
hostname='null', maxFrameSize=16384, channelMax=32767, idleTimeOut=8000,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY], desiredCapabilities=null,
properties={product=qpid-dispatch-router, version=1.1.0}}
2018-06-05 12:40:34.325 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Open{
containerId='Router.qdrouterd-756f57946-r7zlw', hostname='null',
maxFrameSize=16384, channelMax=32767, idleTimeOut=8000, outgoingLocales=null,
incomingLocales=null, offeredCapabilities=[ANONYMOUS-RELAY],
desiredCapabilities=null, properties={product=qpid-dispatch-router,
version=1.1.0}}
2018-06-05 12:40:34.325 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
CONNECTION_REMOTE_OPEN
2018-06-05 12:40:34.325 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: SESSION_INIT
2018-06-05 12:40:34.325 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_LOCAL_OPEN
[1626051893:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:34.326 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647,
handleMax=65535, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:34.326 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 32 bytes
2018-06-05 12:40:34.327 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 35 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 35, cap: 101)
[1626051893:0] <- Begin{remoteChannel=0, nextOutgoingId=0,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:34.328 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Begin{remoteChannel=0,
nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647,
handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:34.328 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_REMOTE_OPEN
2018-06-05 12:40:34.328 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
DEBUG o.a.q.j.p.a.b.AmqpConnectionBuilder - AmqpConnection {
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 } is now open:
2018-06-05 12:40:34.328 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck being initiated,
initial delay: 4000
[1626051893:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:34.329 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647,
handleMax=65535, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:34.329 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 32 bytes
2018-06-05 12:40:34.331 [epollEventLoopGroup-16-1] TRACE
o.a.q.j.t.netty.NettyTcpTransport - New data read: 35 bytes incoming:
PooledUnsafeDirectByteBuf(ridx: 0, widx: 35, cap: 101)
[1626051893:1] <- Begin{remoteChannel=1, nextOutgoingId=0,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
2018-06-05 12:40:34.332 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - RECV: Begin{remoteChannel=1,
nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647,
handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
2018-06-05 12:40:34.332 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event: SESSION_INIT
2018-06-05 12:40:34.332 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_LOCAL_OPEN
2018-06-05 12:40:34.332 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - New Proton Event:
SESSION_REMOTE_OPEN
2018-06-05 12:40:34.333 [FailoverProvider: serialization thread] DEBUG
org.apache.qpid.jms.JmsConnection - Connection
ID:1e1943d4-c102-4116-b878-acf5ea02b14e:1 is finalizing recovery.
2018-06-05 12:40:38.329 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with
delay: 4000
[1626051893:0] -> Empty Frame
2018-06-05 12:40:42.329 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.qpid.jms.provider.amqp.FRAMES - SENT: Empty Frame
2018-06-05 12:40:42.329 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.j.t.netty.NettyTcpTransport - Attempted write of: 8 bytes
2018-06-05 12:40:42.330 [AmqpProvider :(14):[amqps://192.168.99.100:30071]]
TRACE o.a.q.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with
delay: 4000
[1626051893:0] -> Empty Frame{code}
Seems that JMS client re-connects successfully, tries to re-establish the
receiver link, this fails, client logs the error, tries to re-connect again,
re-connect is successful, receiver link gets not re-established (because it is
marked as closed now?), we have JMS connection without link now but no
exception listener was called.
> notify the ExceptionListener when a consumer with a MessageListener remotely
> closes
> -----------------------------------------------------------------------------------
>
> Key: QPIDJMS-376
> URL: https://issues.apache.org/jira/browse/QPIDJMS-376
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.31.0
> Environment: AMQP Server: Enmasse 0.17.1
> Enmasse Address Type: anycast
> Reporter: Daniel Maier
> Priority: Major
> Fix For: 0.32.0
>
> Attachments: clientlogs.txt
>
>
> When I create a consumer to an address that just does not exist, I expected
> to get some exception or that the client retries the operation. But there
> seems not even to be a log message which indicates a failure.
> Is this intended behavior or is this a bug? A more general description is: If
> AMQP server closes the receiver link, qpid jms client does not notify the
> user anyhow or does not re-establish the link.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
