QPID-CPP "No Protocol Received" on internal connections

[joshru <ro...@gmail.com>]

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-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org