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.
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
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
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
Hi,
On Tue, Sep 8, 2009 at 7:28 PM, Johan Hedberg <[email protected]> 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
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