Fix for audio stream XCASE connect:connect failures

PATCH In review Peter Hurley 3 participants 6 messages Sep 8, 2009 – Sep 9, 2009 Bluetooth drivers

Share & tools

Peter Hurley

author

2009-09-08 20:57 UTC #0 lore raw

For several days now, I've been exploring what I felt was a race condition in audio/avdtp.c (many thanks to Johan for some helpful guidance). The behavior I was observing was that AVDTP connections were erroring out when the headset device (Motorola S9) was powering on. The following is a typical error log of was I was observing:

Sep  4 07:30:05 dev-wkstn bluetoothd[2713]: State changed /org/bluez/2713/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_ref(0x7fd0c11c9f50): ref=2
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_ref(0x7fd0c11c9f50): ref=3
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=2
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Received AT+CKPD=200
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: telephony-dummy: got key press request for 200
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP: incoming connect from 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP: connected signaling channel to 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: AVDTP imtu=672, omtu=895
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: send: Transport endpoint is not connected (107)
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: session_cb
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Received DISCOVER_CMD
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: send: Transport endpoint is not connected (107)
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Unable to handle command. Disconnecting
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: Disconnected from 00:0D:FD:1E:99:30
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=1
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: connect:connect XCASE detected
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): ref=0
Sep  4 07:30:06 dev-wkstn bluetoothd[2713]: avdtp_unref(0x7fd0c11c9f50): freeing session and removing from list
Sep  4 07:30:09 dev-wkstn bluetoothd[2713]: Stream setup failed, after XCASE connect:connect

Note the "Transport endpoint is not connected (107)" errors. Until I more fully understood the architecture, I did not understand that those errors were related to the "connect:connect XCASE detected" and "Stream setup failed, after XCASE connect:connect" messages. Now that I do understand, I thought I'd share what I learned and a suggested patch to resolve the problem. (I'm sure I'm rediscovering what others already know but I could find no reference to it in the mail archive).

The short version of the problem is that it is possible for a device to initiate an l2cap channel for the avdtp 'signalling' channel even though a host-initiated avdtp connection is already pending with that device. In the hcidump capture below, the first packet is the Connect initiated from the host side. The 4th packet shows the device initiating it's own connection (even though it has already acknowledged a pending 'signalling' channel connection from the host). (Per the AVDTP spec, the 'signalling' channel is simply the 1st avdtp channel created when none exist.)

2009-09-04 22:32:09.000236 < ACL data: handle 11 flags 0x02 dlen 12
   L2CAP(s): Connect req: psm 25 scid 0x0041
2009-09-04 22:32:09.018962 > HCI Event: Number of Completed Packets (0x13) plen 5
   handle 11 packets 2
2009-09-04 22:32:09.024959 > ACL data: handle 11 flags 0x02 dlen 16
   L2CAP(s): Connect rsp: dcid 0x005d scid 0x0041 result 1 status 2
     Connection pending - Authorization pending
2009-09-04 22:32:09.226945 > ACL data: handle 11 flags 0x02 dlen 12
   L2CAP(s): Connect req: psm 25 scid 0x005e
2009-09-04 22:32:09.227002 < ACL data: handle 11 flags 0x02 dlen 16
   L2CAP(s): Connect rsp: dcid 0x0042 scid 0x005e result 1 status 2
     Connection pending - Authorization pending
2009-09-04 22:32:09.282939 > ACL data: handle 11 flags 0x02 dlen 16
   L2CAP(s): Connect rsp: dcid 0x005d scid 0x0041 result 0 status 0
     Connection successful
2009-09-04 22:32:09.282980 < ACL data: handle 11 flags 0x02 dlen 12
   L2CAP(s): Config req: dcid 0x005d flags 0x00 clen 0
2009-09-04 22:32:09.292932 > ACL data: handle 11 flags 0x02 dlen 16
   L2CAP(s): Config req: dcid 0x0041 flags 0x00 clen 4
     MTU 895
2009-09-04 22:32:09.292976 < ACL data: handle 11 flags 0x02 dlen 18
   L2CAP(s): Config rsp: scid 0x005d flags 0x00 result 0 clen 4
     MTU 895
2009-09-04 22:32:09.293932 > HCI Event: Number of Completed Packets (0x13) plen 5
   handle 11 packets 2
2009-09-04 22:32:09.338933 > ACL data: handle 11 flags 0x02 dlen 14
   L2CAP(s): Config rsp: scid 0x0041 flags 0x00 result 0 clen 0
     Success
2009-09-04 22:32:09.387923 > ACL data: handle 11 flags 0x02 dlen 6
   L2CAP(d): cid 0x0041 len 2 [psm 25]
     AVDTP(s): Discover cmd: transaction 2

Since the kernel l2cap driver has limited knowledge of avdtp protocol, it continues to handle the l2cap channel configuration ultimately resulting in 2 'signalling' channels being created (behavior which is outside the AVDTP spec). This situation also confuses the software state machine in audio/avdtp.c because it does not account for 2 signalling channels (nor should it).

Possible solutions to this situation (perhaps not exhaustive) include:

1)  Reject incoming avdtp connection attempt from device when outgoing connection request is pending.
2)  Give priority to device-initiated connection, killing outgoing connection request.
3)  Move knowledge of avdtp into l2cap kernel driver (or make separate avdtp kernel driver).
4)  Lengthen timer setup in device.c to give devices more time to initiate an avdtp connection.

I discarded option 4 as not solving the problem, but simply avoiding it. Option 3 seems like taking an architectural step backwards (not to mention how significant the effort would be). Initially, I tried option 2 by state-checking and parameter-testing avdtp_connect_cb(). I had this working to a certain extent but ultimately option 1 proved to be a much cleaner implementation.

Patch for option 1 is attached. Here's an excerpt from the daemon.log when this patch works (note the 'connect already in progress' message).

Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVDTP: incoming connect from 00:0D:FD:1E:99:30
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: avdtp_confirm_cb: connect already in progress (XCASE connect:connect)
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVDTP: connected signaling channel to 00:0D:FD:1E:99:30
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVDTP imtu=672, omtu=895
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVCTP Connecting
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: session_cb
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: DISCOVER request succeeded
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: seid 1 type 1 media 0 in use 0
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: seid 2 type 1 media 0 in use 0
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: session_cb
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: GET_CAPABILITIES request succeeded
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: seid 1 type 1 media 0
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: session_cb
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: GET_CAPABILITIES request succeeded
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: seid 2 type 1 media 0
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: Discovery complete
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: a2dp_config: selected SEP 0x7f89d7a8d190
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: avdtp_ref(0x7f89d7a86c30): ref=3
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: setup_ref(0x7f89d7a94a40): ref=1
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: avdtp_set_configuration(0x7f89d7a86c30): int_seid=1, acp_seid=1
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: session_cb
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: SET_CONFIGURATION request succeeded
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: Source 0x7f89d7a8d190: Set_Configuration_Cfm
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: stream state changed: IDLE -> CONFIGURED
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: session_cb
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: OPEN request succeeded
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVCTP: connected to 00:0D:FD:1E:99:30
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: Can't open input device: No such file or directory (2)
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVRCP: failed to init uinput for 00:0D:FD:1E:99:30
Sep  8 15:25:03 dev-wkstn bluetoothd[2676]: AVCTP Connected
Sep  8 15:25:04 dev-wkstn bluetoothd[2676]: AVDTP: connected transport channel to 00:0D:FD:1E:99:30
Sep  8 15:25:04 dev-wkstn bluetoothd[2676]: Source 0x7f89d7a8d190: Open_Cfm
Sep  8 15:25:04 dev-wkstn bluetoothd[2676]: setup_ref(0x7f89d7a94a40): ref=2
Sep  8 15:25:04 dev-wkstn bluetoothd[2676]: Stream successfully created

Comments?

Regards,
Peter Hurley

Also, I have prepared a more extensive source code analysis which is more complicated if anyone would prefer that.

audio/avdtp.c +10 -0

index 131ff4f..d97aff2 100644
@@ -2119,6 +2119,16 @@ static void avdtp_confirm_cb(GIOChannel *chan, gpointer data)
 	if (!session)
 		goto drop;
 
+	// This state (ie, session is already *connecting*) happens when the device
+	//  initiates a connect (really a config'd L2CAP channel) even though
+	//  there is a connect we initiated in progress.  In sink.c & source.c,
+	//  this state is referred to as XCASE connect:connect.
+	// Abort the device's channel in favor of our own.
+	if (session->state == AVDTP_SESSION_STATE_CONNECTING) {
+		debug("avdtp_confirm_cb: connect already in progress (XCASE connect:connect)");
+		goto drop;
+	}
+
 	if (session->pending_open && session->pending_open->open_acp) {
 		if (!bt_io_accept(chan, avdtp_connect_cb, session, NULL, NULL))
 			goto drop;

Johan Hedberg

2009-09-08 22:28 UTC #1 lore raw

Hi Peter,

On Tue, Sep 08, 2009, Peter Hurley wrote:
..lots of great analysis snipped..

Quoted 1 line

Comments?

That's some really nice analysis of the situation you've done. The chosen solution seems like the best one and and patch looks good too. Could you still do the following so we can get it pushed upstream and you get the proper credits as the author of the patch:

- Use /* .. */ for comments instead of //
- Make sure your lines are max 80 columns (e.g. shorten the debug message or split it into two lines if necessary)
- commit it to your own tree with a descriptive commit message and prepare a patch using "git format-patch". This way it's easy for me to apply it using "git am" and e.g. the author field gets correctly preserved.

Thanks.

Johan

Luiz Augusto von Dentz

maintainer

2009-09-09 12:32 UTC #2 lore raw

Hi,

Quoted 7 lines · Johan Hedberg

- Use /* .. */ for comments instead of //
- Make sure your lines are max 80 columns (e.g. shorten the debug message or split it into two lines if necessary)
- commit it to your own tree with a descriptive commit message and prepare a patch using "git format-patch". This way it's easy for me to apply it using "git am" and e.g. the author field gets correctly preserved.

Besides this it seems pretty good, please also make sure the DBus signals are right, which in this case means we shouldn't emit disconnected when dropping the second connection attempt, you can use dbus-monitor --system sender='org.bluez'.

Regards,

Signature · 2 lines

Luiz Augusto von Dentz
Engenheiro de Computação

Peter Hurley

author

2009-09-09 15:49 UTC #3 lore raw

In reply to Johan Hedberg

Quoted 1 line · Johan Hedberg

That's some really nice analysis of the situation you've done.

Thanks.

Quoted 7 lines

- Use /* .. */ for comments instead of //
- Make sure your lines are max 80 columns (e.g. shorten the debug message or split it into two lines if necessary)
- commit it to your own tree with a descriptive commit message and prepare a patch using "git format-patch". This way it's easy for me to apply it using "git am" and e.g. the author field gets correctly preserved.

Sorry about the style snafus: that's fixed, committed & the patch has been generated. Since I use T-bird as my email client and that doesn't seem to be going too well with inline patches, I'm setting up Postfix so I can use git send-email. Just need to get SMTP AUTH working with my ISP...

Quoted 5 lines · Luiz Augusto von Dentz

........................ please also make sure the DBus signals are right, which in this case means we shouldn't emit disconnected when dropping the second connection attempt, you can use dbus-monitor --system sender='org.bluez'.

I will be sure to double-check that before I mail the patch. (Shouldn't be a problem because the state change to _CONNECTING on the duplicate connect attempt never happens).

Regards,
Peter

Peter Hurley

author

2009-09-09 17:25 UTC #4 lore raw

PATCH 1/1 Fixed duplicate attempt from device to connect 'signalling' channel

In reply to Johan Hedberg

A device may attempt to initiate a duplicate avdtp channel while a host-initiated channel connection is still pending. This situation is referred to as 'XCASE connect:connect' in sink.c and source.c. This fix rejects the device-initiated connection in this circumstance.

---
 audio/avdtp.c |   12 ++++++++++++
 1 files changed, 12 insertions(+), 0 deletions(-)

audio/avdtp.c +12 -0

index 131ff4f..6cb9e7d 100644
@@ -2119,6 +2119,18 @@ static void avdtp_confirm_cb(GIOChannel *chan, gpointer data)
 	if (!session)
 		goto drop;
 
+	/* This state (ie, session is already *connecting*) happens when the
+	 *  device initiates a connect (really a config'd L2CAP channel) even
+	 *  though there is a connect we initiated in progress.  In sink.c &
+	 *  source.c, this state is referred to as XCASE connect:connect.
+	 * Abort the device's channel in favor of our own.
+	 */
+	if (session->state == AVDTP_SESSION_STATE_CONNECTING) {
+		debug("avdtp_confirm_cb: connect already in progress" \
+					" (XCASE connect:connect)");
+		goto drop;
+	}
+
 	if (session->pending_open && session->pending_open->open_acp) {
 		if (!bt_io_accept(chan, avdtp_connect_cb, session, NULL, NULL))
 			goto drop;

Signature · 1 line

1.6.0.4

Johan Hedberg

2009-09-09 17:55 UTC #5 lore raw

Re: [PATCH 1/1] Fixed duplicate attempt from device to connect 'signalling' channel

Hi Peter,

Quoted 8 lines · Peter Hurley

A device may attempt to initiate a duplicate avdtp channel while a host-initiated channel connection is still pending. This situation is referred to as 'XCASE connect:connect' in sink.c and source.c. This fix rejects the device-initiated connection in this circumstance.
---
 audio/avdtp.c |   12 ++++++++++++
 1 files changed, 12 insertions(+), 0 deletions(-)

Thanks a lot! The patch has been pushed upstream (with a few more very minor coding style changes).

Johan