Qpid C++ Periodic Connection Issues Hello,
I am currently working on upgrading a legacy application's QPID communication to support SSL/TLS encryption via x.509 certificates. I was provided a virtual machine to test against and I think I've got most of it ironed out. However, maybe 1 out of 10 times I start up my system my Qpid C++ code will simply refuse to open any connections to the other virtual machine nor will it open any connections to connections for services that are hosted by my application. I came across this issue: https://issues.apache.org/jira/browse/QPID-8221 which describes similar behavior to what I was seeing, so I added "connect-timeout: 5" to my connection options, this did keep the connection open calls from hanging but didn't fix my issue as it continues to fail to connect rather than failing once and hanging like it was without that option. I'm able to force this issue to present (eventually) by restarting my application several times. Not only am I unable to communicate with my test VM when in this error state but I'm also unable to connect to my own exchanges and see lots of logs like "[System] error Connection qpid.10.43.1.10:31111-10.43.1.11:51564 No protocol received after 10s, closing" which are both internal IP addresses. When I enable protocol logging with "log-enable=trace+:Protocol" and browse them while my application is in the error state I see a ton of SEND and RECV calls which seems to indicate that there's some level of communication happening but I'm not exactly sure how to parse what I'm seeing (snippet from the logs below). This issue does not appear to ever occur when I run my application without the SSL/TLS x.509 stuff enabled. I tried using Wireshark to snoop on the message traffic when this occurs and I can see that there is no TLS traffic whatsoever when I'm in the error state, when things are working as intended I can see lots of TLS 1.2 packets flowing back and forth. I've been chasing this issue for a few days with no luck. If anybody has any ideas that might get me on the right track I'd really appreciate it! qpid-cpp client, server, and tools are all version 1.39.0-1 An excerpt of the protocol logs, 192.168.56.2 is my VM, 192.168.56.55 is the Test VM I'd like to talk to: Oct 27 21:34:01 stbdlcp qpidd[14927]: 2020-10-27 21:34:01 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[Bbe; channel=1; {MessageTransferBody: destination=21efd55d-79d4-4ed4-afa0-e259a13ca3a7#; accept-mode=0; acquire-mode=0; } Oct 27 21:34:01 stbdlcp qpidd[14927]: 2020-10-27 21:34:01 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[be; channel=1; header (178 bytes); properties={{MessageProperties: content-length=1622; correlation-id=3277; content-type Oct 27 21:34:01 stbdlcp qpidd[14927]: 2020-10-27 21:34:01 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[Ebe; channel=1; content (1622 bytes) \x00\x00\x06R\x00\x00\x00\x01\xA8\x00\x00\x06I\x00\x00\x00\x06 Oct 27 21:34:01 stbdlcp qpidd[14927]: _create_ts2\x16A\xF6...] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [System] error Connection qpid.10.43.1.10:31111-10.43.1.11:47720 No protocol received after 10s, closing Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageAcceptBody: transfers={ [821,821] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionFlushBody: completed=1; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageStopBody: destination=757fc5f1-659b-475b-942c-1a6ce3e763b8#; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4364,4379] }; timely-reply=1; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4364,4380] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ [4359,4379] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageReleaseBody: transfers={ }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageCancelBody: destination=757fc5f1-659b-475b-942c-1a6ce3e763b8#; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Model] debug Delete subscription. destination:757fc5f1-659b-475b-942c-1a6ce3e763b8# user:TestVM@QPID rhost:qpid.192.168.56.2:31111-192.168.56.55:52718 Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {QueueQueryBody: queue=757fc5f1-659b-475b-942c-1a6ce3e763b8#; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=4383; value=\x08\x01\xFB\x00%757fc5f1-659b-475b-942c-1a6ce3e763b8#\x00\ Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4380,4383] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {QueueDeleteBody: queue=757fc5f1-659b-475b-942c-1a6ce3e763b8#; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Model] debug Deleting queue. name:757fc5f1-659b-475b-942c-1a6ce3e763b8# user:TestVM@QPID rhost:qpid.192.168.56.2:31111-192.168.56.55:52718 Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4380,4384] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {ExecutionSyncBody: }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4380,4385] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageReleaseBody: transfers={ }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {ExchangeBoundBody: exchange=964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e#; queue=964c625a-76ba-4ed2-9eb6-f0c8a5 Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=4387; value=\x07\x02\x03\x00; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4380,4387] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {QueueDeclareBody: queue=964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e#; alternate-exchange=; exclusive=1; auto-d Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Model] debug Create queue. name:964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e# user:TestVM@QPID rhost:qpid.192.168.56.2:31111-192.168.56.55:52718 durable:F owner:0x7f66d402ec78 autodelete:T alternateE Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {ExecutionSyncBody: }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [4380,4389] }; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[BEbe; channel=1; {MessageSubscribeBody: queue=964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e#; destination=964c625a-76ba-4ed2-9eb6- Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Model] debug Create subscription. queue:964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e# destination:964c625a-76ba-4ed2-9eb6-f0c8a5c54f1e# user:TestVM@QPID rhost:qpid.192.168.56.2:31111-192.168.56.55:52 Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[Bbe; channel=1; {MessageTransferBody: destination=qmf.default.direct; accept-mode=1; acquire-mode=0; }] Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[be; channel=1; header (198 bytes); properties={{MessageProperties: content-length=108; correlation-id=3280; reply-to={Rep Oct 27 21:34:02 stbdlcp qpidd[14927]: 2020-10-27 21:34:02 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:52718]: Frame[Ebe; channel=1; content (108 bytes) \x00\x00\x00h\x00\x00\x00\x02 Thanks in advance. -- Sent from: http://qpid.2158936.n2.nabble.com/Apache-Qpid-users-f2158936.html --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@qpid.apache.org For additional commands, e-mail: users-h...@qpid.apache.org
