Hi Luiz,
On Sun, 2011-08-14 at 15:57 -0400, Luiz Augusto von Dentz wrote:
> Hi Peter,
>
> On Fri, Aug 12, 2011 at 6:00 PM, Peter Hurley <peter@xxxxxxxxxxxxxxxxxx> wrote:
> > AVDTP_CONNECT_TIMEOUT controls the delay between HSP/HFP
> > connection establishment and AVDTP signal channel establishment.
> > The original value of 1 sec. is too short to avoid racing for AVDTP
> > connection establishment (eg., if the device continues to configure
> > the HFP service level connection with add'l AT cmds).
> >
> > Some devices have broken AVDTP implementations that just cannot
> > handle the race conditions that arise if both devices are attempting
> > stream establishment at the same time. However, these conditions arise
> > only when the remote device is the ACL initiator (and in practice, the
> > RFCOMM initiator as well). This fix bumps out the timeout value only
> > when the headset has initiated the link.
> > ---
> >
> > v2: Follow established naming convention
>
> How about if we add some retry logic? I think it would be more
> efficient since it would not add an extra delay for devices that do
> not have such problem, perhaps we can even eliminate the 1 sec we
> currently have and just retry if we detect a collision has happened.
I'm not attached to a particular solution - tbh, I don't really care if
collectively the decision is to refuse to address interoperability with
"broken" devices. I'm aware that this is less than pleasant and I
seriously considered not submitting this at all.
As far as taking a different approach (be it retry or whatever), here's
what we're up against. In the trial excerpted below, we removed the
extra delay (thus virtually guaranteeing no race). Excerpt of
hs_conn.trial#2A:
.... headset initiates RFCOMM ....
2011-08-11 18:35:02.264185 > ACL data: handle 13 flags 0x02 dlen 12
L2CAP(s): Connect req: psm 3 scid 0x0053
2011-08-11 18:35:02.264201 < ACL data: handle 13 flags 0x00 dlen 16
L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0053 result 0 status 0
Connection successful
.... <snip typical RFCOMM init> ....
2011-08-11 18:35:03.778185 > ACL data: handle 13 flags 0x02 dlen 28
L2CAP(d): cid 0x0040 len 24 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 26 pf 1 ilen 19 fcs 0xf8 credits 2
0000: 41 54 2b 43 4d 45 52 3d 33 2c 20 30 2c 20 30 2c AT+CMER=3, 0, 0,
0010: 20 31 0d 1.
2011-08-11 18:35:03.778256 < ACL data: handle 13 flags 0x00 dlen 14
L2CAP(d): cid 0x0053 len 10 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 26 pf 0 ilen 6 fcs 0x3e
0000: 0d 0a 4f 4b 0d 0a ..OK..
.... HFP SLC -> immediately initiate AVDTP signaling channel ....
2011-08-11 18:35:03.778410 < ACL data: handle 13 flags 0x00 dlen 12
L2CAP(s): Connect req: psm 25 scid 0x0041
2011-08-11 18:35:03.784183 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 2
2011-08-11 18:35:03.795183 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0055 scid 0x0041 result 1 status 2
Connection pending - Authorization pending
2011-08-11 18:35:04.177185 > ACL data: handle 13 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 26 pf 1 ilen 10 fcs 0xf8 credits 1
0000: 41 54 2b 56 47 53 3d 31 35 0d AT+VGS=15.
2011-08-11 18:35:04.177260 < ACL data: handle 13 flags 0x00 dlen 14
L2CAP(d): cid 0x0053 len 10 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 26 pf 0 ilen 6 fcs 0x3e
0000: 0d 0a 4f 4b 0d 0a ..OK..
2011-08-11 18:35:04.330184 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 1
2011-08-11 18:35:04.340185 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0055 scid 0x0041 result 0 status 0
Connection successful
.... signaling channel OK -> config chan ....
2011-08-11 18:35:04.340197 < ACL data: handle 13 flags 0x00 dlen 12
L2CAP(s): Config req: dcid 0x0055 flags 0x00 clen 0
2011-08-11 18:35:04.350184 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0041 flags 0x00 clen 4
MTU 895
2011-08-11 18:35:04.350194 < ACL data: handle 13 flags 0x00 dlen 18
L2CAP(s): Config rsp: scid 0x0055 flags 0x00 result 0 clen 4
MTU 895
2011-08-11 18:35:04.361182 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 2
2011-08-11 18:35:04.395184 > ACL data: handle 13 flags 0x02 dlen 14
L2CAP(s): Config rsp: scid 0x0041 flags 0x00 result 0 clen 0
Success
.... AVDTP Discover + Get Capabilities ....
2011-08-11 18:35:04.395240 < ACL data: handle 13 flags 0x00 dlen 6
L2CAP(d): cid 0x0055 len 2 [psm 25]
AVDTP(s): Discover cmd: transaction 4 nsp 0x00
2011-08-11 18:35:04.481185 > ACL data: handle 13 flags 0x02 dlen 10
L2CAP(d): cid 0x0041 len 6 [psm 25]
AVDTP(s): Discover rsp: transaction 4 nsp 0x00
ACP SEID 1 - Audio Sink
ACP SEID 2 - Audio Sink
2011-08-11 18:35:04.481294 < ACL data: handle 13 flags 0x00 dlen 7
L2CAP(d): cid 0x0055 len 3 [psm 25]
AVDTP(s): Capabilities cmd: transaction 5 nsp 0x00
ACP SEID 1
2011-08-11 18:35:04.506184 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 2
2011-08-11 18:35:04.516184 > HCI Event: Link Supervision Timeout Change (0x38) plen 4
handle 13 timeout 8064
2011-08-11 18:35:04.562184 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(d): cid 0x0041 len 12 [psm 25]
AVDTP(s): Capabilities rsp: transaction 5 nsp 0x00
Media Transport
Media Codec - SBC
16kHz 32kHz 44.1kHz 48kHz
Mono DualChannel Stereo JointStereo
4 8 12 16 Blocks
4 8 Subbands
SNR Loudness
Bitpool Range 2-44
2011-08-11 18:35:04.562240 < ACL data: handle 13 flags 0x00 dlen 7
L2CAP(d): cid 0x0055 len 3 [psm 25]
AVDTP(s): Capabilities cmd: transaction 6 nsp 0x00
ACP SEID 2
2011-08-11 18:35:04.637186 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(d): cid 0x0041 len 12 [psm 25]
AVDTP(s): Capabilities rsp: transaction 6 nsp 0x00
Media Transport
Media Codec - MPEG-1,2 Audio
3F 07 FF FE
.... AVDTP Set Configuration ....
2011-08-11 18:35:04.637300 < ACL data: handle 13 flags 0x00 dlen 18
L2CAP(d): cid 0x0055 len 14 [psm 25]
AVDTP(s): Set config cmd: transaction 7 nsp 0x00
ACP SEID 1 - INT SEID 1
Media Transport
Media Codec - SBC
44.1kHz
JointStereo
16 Blocks
8 Subbands
Loudness
Bitpool Range 2-44
.... Now, what can we do about what happens next? ....
2011-08-11 18:35:04.651185 > ACL data: handle 13 flags 0x02 dlen 6
L2CAP(d): cid 0x0041 len 2 [psm 25]
AVDTP(s): Discover cmd: transaction 10 nsp 0x00
2011-08-11 18:35:04.651237 < ACL data: handle 13 flags 0x00 dlen 8
L2CAP(d): cid 0x0055 len 4 [psm 25]
AVDTP(s): Discover rsp: transaction 10 nsp 0x00
ACP SEID 1 - Audio Source (InUse)
2011-08-11 18:35:04.653184 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 2
2011-08-11 18:35:04.693186 > ACL data: handle 13 flags 0x02 dlen 8
L2CAP(d): cid 0x0041 len 4 [psm 25]
AVDTP(s): Set config rej: transaction 7 nsp 0x00
Reserved
Error code 19
2011-08-11 18:35:04.761186 > ACL data: handle 13 flags 0x02 dlen 12
L2CAP(s): Disconn req: dcid 0x0041 scid 0x0055
2011-08-11 18:35:04.761202 < ACL data: handle 13 flags 0x00 dlen 12
L2CAP(s): Disconn rsp: dcid 0x0041 scid 0x0055
The headset has disconnected the AVDTP signaling channel because we have
marked the SEP as "in use" (which is, of course, exactly what was
required prior to issuing the Set Config). Like I wrote in the commit
message, "broken AVDTP implementations".
My point here is a lot has happened before discovering that something is
wrong. I'm not even sure if this headset would respond to an attempt to
restart from this - maybe.
In the baseline trial with existing delay of 1 sec. (using HSP profile),
the headset simply never responds to the GET_CAPABILITIES for seid 2 -
the connection times out after 5 seconds and is disconnected:
2011-08-12 06:36:16.992657 < ACL data: handle 13 flags 0x00 dlen 6
L2CAP(d): cid 0x0056 len 2 [psm 25]
AVDTP(s): Discover cmd: transaction 3 nsp 0x00
2011-08-12 06:36:17.078604 > ACL data: handle 13 flags 0x02 dlen 10
L2CAP(d): cid 0x0041 len 6 [psm 25]
AVDTP(s): Discover rsp: transaction 3 nsp 0x00
ACP SEID 1 - Audio Sink
ACP SEID 2 - Audio Sink
2011-08-12 06:36:17.078692 < ACL data: handle 13 flags 0x00 dlen 7
L2CAP(d): cid 0x0056 len 3 [psm 25]
AVDTP(s): Capabilities cmd: transaction 4 nsp 0x00
ACP SEID 1
2011-08-12 06:36:17.083599 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 2
2011-08-12 06:36:17.122604 > HCI Event: Link Supervision Timeout Change (0x38) plen 4
handle 13 timeout 8064
2011-08-12 06:36:17.372605 > ACL data: handle 13 flags 0x02 dlen 16
L2CAP(d): cid 0x0041 len 12 [psm 25]
AVDTP(s): Capabilities rsp: transaction 4 nsp 0x00
Media Transport
Media Codec - SBC
16kHz 32kHz 44.1kHz 48kHz
Mono DualChannel Stereo JointStereo
4 8 12 16 Blocks
4 8 Subbands
SNR Loudness
Bitpool Range 2-44
2011-08-12 06:36:17.372720 < ACL data: handle 13 flags 0x00 dlen 7
L2CAP(d): cid 0x0056 len 3 [psm 25]
AVDTP(s): Capabilities cmd: transaction 5 nsp 0x00
ACP SEID 2
2011-08-12 06:36:17.594603 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 1
2011-08-12 06:36:22.406607 > HCI Event: Max Slots Change (0x1b) plen 3
handle 13 slots 1
2011-08-12 06:36:22.596605 > HCI Event: Mode Change (0x14) plen 6
status 0x00 handle 13 mode 0x02 interval 1024
Mode: Sniff
2011-08-12 06:36:23.573334 < ACL data: handle 13 flags 0x00 dlen 12
L2CAP(s): Disconn req: dcid 0x0056 scid 0x0041
2011-08-12 06:36:24.094607 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 13 packets 1
2011-08-12 06:36:24.519609 > ACL data: handle 13 flags 0x02 dlen 12
L2CAP(s): Disconn rsp: dcid 0x0056 scid 0x0041
Let me know what you think.
Regards,
Peter Hurley
��.n��������+%������w��{.n�����{��� �^n�r������&��z�ޗ�zf���h���~����������_��+v���)ߣ�
