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 application the Qpid C++ code will simply refuse to open any connections to the other virtual machine nor will it open any connections for exchanges that are hosted by my application.
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 open connections for 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 between my VM and the Test VM 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 weeks now and I don't feel any closer to finding a solution. 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 the IP of my VMs external facing network interface, 192.168.56.55 is the Test VM I'd like to talk to. The 10.43.1.XX IP addresses are internal addresses of the exchanges I'm responsible for hosting. qpidd log options are "trace+:Protocol" and "error:System":
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [System] error Connection qpid.10.43.1.10:31111-10.43.1.11:54704 No protocol received after 10s, closing
Dec 22 20:38:10 stbdlcp qpidd[28517]: 2020-12-22 20:38:10 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=0; {ConnectionHeartbeatBody: }]
Dec 22 20:38:10 stbdlcp qpidd[28517]: 2020-12-22 20:38:10 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=0; {ConnectionHeartbeatBody: }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionKnownCompletedBody: commands={ [5708,5739] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageReleaseBody: transfers={ }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageCancelBody: destination=a662b9ed-f116-4c91-a9aa-7e7bd58221e1#; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {QueueQueryBody: queue=a662b9ed-f116-4c91-a9aa-7e7bd58221e1#; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=5743; value=\x08\x01\xFB\x00%a662b9ed-f116-4c91-a9aa-7e7bd58221e1#\x00\
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5743] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageReleaseBody: transfers={ }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageCancelBody: destination=a662b9ed-f116-4c91-a9aa-7e7bd58221e1#; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {QueueQueryBody: queue=a662b9ed-f116-4c91-a9aa-7e7bd58221e1#; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=5743; value=\x08\x01\xFB\x00%a662b9ed-f116-4c91-a9aa-7e7bd58221e1#\x00\
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5743] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {QueueDeleteBody: queue=a662b9ed-f116-4c91-a9aa-7e7bd58221e1#; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5744] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5745] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageReleaseBody: transfers={ }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExchangeBoundBody: exchange=3c2637c8-b488-4387-82eb-7469cdf9dd0e#; queue=3c2637c8-b488-4387-82eb-7469cd
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExecutionResultBody: command-id=5747; value=\x07\x02\x03\x00; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5747] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {QueueDeclareBody: queue=3c2637c8-b488-4387-82eb-7469cdf9dd0e#; alternate-exchange=; exclusive=1; auto-d
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace SENT [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [5740,5749] }; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[BEbe; channel=1; {MessageSubscribeBody: queue=3c2637c8-b488-4387-82eb-7469cdf9dd0e#; destination=3c2637c8-b488-4387-82eb-
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[Bbe; channel=1; {MessageTransferBody: destination=qmf.default.direct; accept-mode=1; acquire-mode=0; }]
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[be; channel=1; header (198 bytes); properties={{MessageProperties: content-length=106; correlation-id=3778; reply-to={Rep
Dec 22 20:38:09 stbdlcp qpidd[28517]: 2020-12-22 20:38:09 [Protocol] trace RECV [qpid.192.168.56.2:31111-192.168.56.55:42624]: Frame[Ebe; channel=1; content (106 bytes) \x00\x00\x00f\x00\x00\x00\x02
I think I figured it out. For whatever reason having my NSS database password protected seems to be causing the issue. With the password removed I am unable to reproduce the issue like before.
I'm not sure why this is the case, I'll have to do some more research to figure out what exactly I was doing wrong. If the NSS DB password was misconfigured I wouldn't expect QPID authentication to work at all rather than having random connection problems like it was.
Very confusing.