2019-01-17 12:14:34

by Per Waagø

[permalink] [raw]
Subject: Disconnection of signaling channel after AVDTP close

We have a product that implements an A2DP sink running bluez 5.50. I'm
try to qualify this product with the Bluetooth SIG using the Profile
Tuning Suite (PTS), but I am having trouble passing a test that verifies
reported delay value (A2DP/SNK/SYN/BV-01-C).

In that test, PTS configures an AVDTP stream and verifies the delay
report, then opens the stream, streams some data and closes the stream.
This is repeated. The problem seems to be that after the stream is
closed, bluez immediately also closes the L2CAP signaling channel.

I have pasted the problematic sequence from btmon at the bottom of this
email, the problem is the last L2CAP Disconnection request.

This was introduced with commit 7ece89b0b6 between version 5.47 and
5.48. Before that, there was always a one second delay before the
signaling channel was disconnected,
which was enough for PTS to configure a new stream.

What was the rationale for always disconnecting immediately? Could there
be circumstances where it would make sense to keep the signaling channel
open a bit longer? Is there any other way we can force the channel to
stay open?

Best regards,
Per Waagø

--
> ACL Data RX: Handle 12 flags 0x02 dlen 7 #329 [hci0]
48.732441
Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
AVDTP: Close (0x08) Command (0x00) type 0x00 label 2 nosp 0
ACP SEID: 1
< ACL Data TX: Handle 12 flags 0x00 dlen 6 #330 [hci0]
48.732775
Channel: 64 len 2 [PSM 25 mode 0] {chan 0}
AVDTP: Close (0x08) Response Accept (0x02) type 0x00 label 2 nosp 0
> ACL Data RX: Handle 12 flags 0x02 dlen 310 #331 [hci0]
48.736692
> ACL Data RX: Handle 12 flags 0x01 dlen 337 #332 [hci0]
48.771536
Channel: 65 len 643 [PSM 25 mode 0] {chan 1}
> ACL Data RX: Handle 12 flags 0x02 dlen 12 #333 [hci0]
48.771963
L2CAP: Disconnection Request (0x06) ident 30 len 4
Destination CID: 65
Source CID: 65
< ACL Data TX: Handle 12 flags 0x00 dlen 12 #334 [hci0]
48.772019
L2CAP: Disconnection Response (0x07) ident 30 len 4
Destination CID: 65
Source CID: 65
< ACL Data TX: Handle 12 flags 0x00 dlen 12 #335 [hci0]
48.772960
L2CAP: Disconnection Request (0x06) ident 4 len 4
Destination CID: 64
Source CID: 64
> HCI Event: Number of Completed Packets (0x13) plen 5 #336 [hci0]
48.778131
Num handles: 1
Handle: 12
Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #337 [hci0]
48.953264
Num handles: 1
Handle: 12
Count: 1
> HCI Event: Disconnect Complete (0x05) plen 4 #338 [hci0]
50.167143
Status: Success (0x00)
Handle: 12
Reason: Remote Device Terminated due to Power Off (0x15)



2019-01-21 12:34:21

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Disconnection of signaling channel after AVDTP close

Hi Per,

On Thu, Jan 17, 2019 at 9:19 AM Per Waagø <[email protected]> wrote:
>
> We have a product that implements an A2DP sink running bluez 5.50. I'm
> try to qualify this product with the Bluetooth SIG using the Profile
> Tuning Suite (PTS), but I am having trouble passing a test that verifies
> reported delay value (A2DP/SNK/SYN/BV-01-C).
>
> In that test, PTS configures an AVDTP stream and verifies the delay
> report, then opens the stream, streams some data and closes the stream.
> This is repeated. The problem seems to be that after the stream is
> closed, bluez immediately also closes the L2CAP signaling channel.
>
> I have pasted the problematic sequence from btmon at the bottom of this
> email, the problem is the last L2CAP Disconnection request.
>
> This was introduced with commit 7ece89b0b6 between version 5.47 and
> 5.48. Before that, there was always a one second delay before the
> signaling channel was disconnected,
> which was enough for PTS to configure a new stream.
>
> What was the rationale for always disconnecting immediately? Could there
> be circumstances where it would make sense to keep the signaling channel
> open a bit longer? Is there any other way we can force the channel to
> stay open?

Could you please try to check with the patch Ive just sent? That
should track who has closed/aborted the stream so in case the remote
have done it will set a timeout before destroying the session.


> Best regards,
> Per Waagø
>
> --
> > ACL Data RX: Handle 12 flags 0x02 dlen 7 #329 [hci0]
> 48.732441
> Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
> AVDTP: Close (0x08) Command (0x00) type 0x00 label 2 nosp 0
> ACP SEID: 1
> < ACL Data TX: Handle 12 flags 0x00 dlen 6 #330 [hci0]
> 48.732775
> Channel: 64 len 2 [PSM 25 mode 0] {chan 0}
> AVDTP: Close (0x08) Response Accept (0x02) type 0x00 label 2 nosp 0
> > ACL Data RX: Handle 12 flags 0x02 dlen 310 #331 [hci0]
> 48.736692
> > ACL Data RX: Handle 12 flags 0x01 dlen 337 #332 [hci0]
> 48.771536
> Channel: 65 len 643 [PSM 25 mode 0] {chan 1}
> > ACL Data RX: Handle 12 flags 0x02 dlen 12 #333 [hci0]
> 48.771963
> L2CAP: Disconnection Request (0x06) ident 30 len 4
> Destination CID: 65
> Source CID: 65
> < ACL Data TX: Handle 12 flags 0x00 dlen 12 #334 [hci0]
> 48.772019
> L2CAP: Disconnection Response (0x07) ident 30 len 4
> Destination CID: 65
> Source CID: 65
> < ACL Data TX: Handle 12 flags 0x00 dlen 12 #335 [hci0]
> 48.772960
> L2CAP: Disconnection Request (0x06) ident 4 len 4
> Destination CID: 64
> Source CID: 64
> > HCI Event: Number of Completed Packets (0x13) plen 5 #336 [hci0]
> 48.778131
> Num handles: 1
> Handle: 12
> Count: 2
> > HCI Event: Number of Completed Packets (0x13) plen 5 #337 [hci0]
> 48.953264
> Num handles: 1
> Handle: 12
> Count: 1
> > HCI Event: Disconnect Complete (0x05) plen 4 #338 [hci0]
> 50.167143
> Status: Success (0x00)
> Handle: 12
> Reason: Remote Device Terminated due to Power Off (0x15)
>


--
Luiz Augusto von Dentz