Fix for audio stream XCASE connect:connect failures

Fix for audio stream XCASE connect:connect failures

[Peter Hurley]

[-- Attachment #1: Type: text/plain, Size: 8991 bytes --]

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.

[-- Attachment #2: xcase.diff --]
[-- Type: text/x-patch, Size: 874 bytes --]

diff --git a/audio/avdtp.c b/audio/avdtp.c
index 131ff4f..d97aff2 100644
--- a/audio/avdtp.c
+++ b/audio/avdtp.c
@@ -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;

Re: Fix for audio stream XCASE connect:connect failures

[Johan Hedberg]

Hi Peter,

On Tue, Sep 08, 2009, Peter Hurley wrote:
..lots of great analysis snipped..
> 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

Re: Fix for audio stream XCASE connect:connect failures

[Luiz Augusto von Dentz]

Hi,

On Tue, Sep 8, 2009 at 7:28 PM, Johan Hedberg <johan.hedberg@gmail.com> wrote:
> - 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,

-- 
Luiz Augusto von Dentz
Engenheiro de Computação

Re: Fix for audio stream XCASE connect:connect failures

[Peter Hurley]

Johan Hedberg wrote:
> That's some really nice analysis of the situation you've done.
Thanks.
> - 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...

Luiz Augusto von Dentz wrote:
> ........................ 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

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

[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(-)

diff --git a/audio/avdtp.c b/audio/avdtp.c
index 131ff4f..6cb9e7d 100644
--- a/audio/avdtp.c
+++ b/audio/avdtp.c
@@ -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;
-- 
1.6.0.4

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

[Johan Hedberg]

Hi Peter,

On Wed, Sep 09, 2009, Peter Hurley wrote:
> 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