[QPID-8100] [Broker-J] [AMQP 0-10] SESSION_BUSY sent on wrong channel leading to hung Messaging API based application

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.32, qpid-java-broker-7.0.0, qpid-java-broker-7.0.1
• Fix Version/s: qpid-java-broker-7.0.2, qpid-java-broker-7.1.0
• Component/s: Broker-J

Environment

• Qpid Broker-J 0.32 derivative
• Qpid Cpp Client using messaging API.

• Assignee: Unassigned
• Reporter: Keith Wall
• Created: 15/Feb/18 13:52
• Updated: 02/Oct/19 19:22
• Resolved: 20/Feb/18 13:18

Description

If, during session attachment, the Broker detects that the 0-10 session is already in use by the same principal, the Broker is required to detach the session by sending a session.detach on the same channel. Currently owing to a defect, the Broker sends this detach on channel 0, regardless of the channel used by the peer.

This defect was a contributory factor in a larger problem. It prevented an application from recovering automatically. In that case, a Qpid CPP Messaging API, recovering from a missing heartbeat, entered a hung state whilst attaching the existing session. The client library discarded the session.detach on the unexpected channel, so it continued to await the session.attached, which never came.

/// original session attach
2018-02-15 13:17:50 [Network] trace SENT [[10.211.55.3:60054-10.241.132.41:5672]]: Frame[BEbe; channel=1; {SessionAttachBody: name=e2baafab-5e5f-4daf-8276-33ccaa9f940a; }]
2018-02-15 13:17:50 [Network] trace RECV [[10.211.55.3:60054-10.241.132.41:5672]]: Frame[BEbe; channel=1; {SessionAttachedBody: name=e2baafab-5e5f-4daf-8276-33ccaa9f940a; }]
2018-02-15 13:17:50 [Network] trace SENT [[10.211.55.3:60054-10.241.132.41:5672]]: Frame[BEbe; channel=1; {SessionRequestTimeoutBody: timeout=0; }]
/// snip - later heartbeat timeout
2018-02-15 13:18:20 [Client] debug Traffic timeout
/// snip - reconnecting again
2018-02-15 13:18:20 [System] info Connecting: 10.241.132.41:5672
/// snip -reuse the same session id
2018-02-15 13:18:28 [Client] debug Known-brokers for connection:
2018-02-15 13:18:28 [Network] trace SENT [[10.211.55.3:60056-10.241.132.41:5672]]: Frame[BEbe; channel=1; {SessionAttachBody: name=e2baafab-5e5f-4daf-8276-33ccaa9f940a; }]
2018-02-15 13:18:28 [Network] trace RECV [[10.211.55.3:60056-10.241.132.41:5672]]: Frame[BEbe; channel=0; {SessionDetachedBody: name=e2baafab-5e5f-4daf-8276-33ccaa9f940a; code=1; }]
2018-02-15 13:18:28 [Client] info Connection [10.211.55.3:60056-10.241.132.41:5672] dropping frame received on invalid channel: Frame[BEbe; channel=0; {SessionDetachedBody: name=e2baafab-5e5f-4daf-8276-33ccaa9f940a; code=1; }]