All of lore.kernel.org
 help / color / mirror / Atom feed
* [A2DP] Incoming connections do not succeed
@ 2014-07-26  1:33 Artem Rakhov
  2014-07-28  8:21 ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-07-26  1:33 UTC (permalink / raw)
  To: linux-bluetooth

Hello,

I have a problem with A2DP incoming connections. I have a BT speaker
(Monster Clarity HD), which automatically reconnects on startup to the
last connected source. It works fine with BlueZ 4, but it never
reconnects successfully when using BlueZ 5.19

Here is btmon log:
< ACL Data TX: Handle 21 flags 0x00 dlen 16
               [hci0] 3471.224113
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 108
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
< ACL Data TX: Handle 21 flags 0x00 dlen 16
               [hci0] 3471.224313
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 108
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12
               [hci0] 3471.224417
      L2CAP: Configure Request (0x04) ident 2 len 4
        Destination CID: 108
        Flags: 0x0000
> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.226831
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.227794
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.228807
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                           [hci0] 3471.256507
      L2CAP: Disconnection Request (0x06) ident 3 len 4
        Destination CID: 64
        Source CID: 108
< ACL Data TX: Handle 21 flags 0x00 dlen 12
               [hci0] 3471.256592
      L2CAP: Disconnection Response (0x07) ident 3 len 4
        Destination CID: 64
        Source CID: 108
> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.258773
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Vendor (0xff) plen 7                                                     [hci0] 3471.549833
        82 00 01 00 01 15 00                             .......
> HCI Event: Disconnect Complete (0x05) plen 4                                        [hci0] 3471.550757
        Status: Success (0x00)
        Handle: 21
        Reason: Remote User Terminated Connection (0x13)
@ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3


As could be seen from the log, after the source sends L2CAP Configure
Request the speaker does not answer and disconnects (sends L2CAP
Disconnection Request).

Debugging avdtp.c showed that processing of incoming connections is
held in avdtp_confirm_cb() function. There, at some point after
successful authorization G_IO_ERR and G_IO_HUP events appear. And then
session_cb() function is called (as callback for these events), which
drops the connection.

Does anyone experience the same issue or have any ideas on how to fix it?

Thanks,
Artem

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-07-26  1:33 [A2DP] Incoming connections do not succeed Artem Rakhov
@ 2014-07-28  8:21 ` Luiz Augusto von Dentz
  2014-07-29  0:24   ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-07-28  8:21 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: linux-bluetooth

Hi Artem,

On Sat, Jul 26, 2014 at 4:33 AM, Artem Rakhov <arakhov@chromium.org> wrote:
> Hello,
>
> I have a problem with A2DP incoming connections. I have a BT speaker
> (Monster Clarity HD), which automatically reconnects on startup to the
> last connected source. It works fine with BlueZ 4, but it never
> reconnects successfully when using BlueZ 5.19
>
> Here is btmon log:
> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>                [hci0] 3471.224113
>       L2CAP: Connection Response (0x03) ident 2 len 8
>         Destination CID: 64
>         Source CID: 108
>         Result: Connection pending (0x0001)
>         Status: Authorization pending (0x0002)
> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>                [hci0] 3471.224313
>       L2CAP: Connection Response (0x03) ident 2 len 8
>         Destination CID: 64
>         Source CID: 108
>         Result: Connection successful (0x0000)
>         Status: No further information available (0x0000)
> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>                [hci0] 3471.224417
>       L2CAP: Configure Request (0x04) ident 2 len 4
>         Destination CID: 108
>         Flags: 0x0000
>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.226831
>         Num handles: 1
>         Handle: 21
>         Count: 1
>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.227794
>         Num handles: 1
>         Handle: 21
>         Count: 1
>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.228807
>         Num handles: 1
>         Handle: 21
>         Count: 1
>> ACL Data RX: Handle 21 flags 0x02 dlen 12                                           [hci0] 3471.256507
>       L2CAP: Disconnection Request (0x06) ident 3 len 4
>         Destination CID: 64
>         Source CID: 108
> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>                [hci0] 3471.256592
>       L2CAP: Disconnection Response (0x07) ident 3 len 4
>         Destination CID: 64
>         Source CID: 108
>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.258773
>         Num handles: 1
>         Handle: 21
>         Count: 1
>> HCI Event: Vendor (0xff) plen 7                                                     [hci0] 3471.549833
>         82 00 01 00 01 15 00                             .......
>> HCI Event: Disconnect Complete (0x05) plen 4                                        [hci0] 3471.550757
>         Status: Success (0x00)
>         Handle: 21
>         Reason: Remote User Terminated Connection (0x13)
> @ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3
>
>
> As could be seen from the log, after the source sends L2CAP Configure
> Request the speaker does not answer and disconnects (sends L2CAP
> Disconnection Request).
>
> Debugging avdtp.c showed that processing of incoming connections is
> held in avdtp_confirm_cb() function. There, at some point after
> successful authorization G_IO_ERR and G_IO_HUP events appear. And then
> session_cb() function is called (as callback for these events), which
> drops the connection.

This looks pretty strange as the remote seems to be disconnecting not
us, btw did you tried to mark the device as trusted? Regarding it
working with BlueZ 4, what kernel are you using with that and can you
try to compare what is the difference in the logs, perhaps the remote
does like the Configure Request for some reason.


-- 
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-07-28  8:21 ` Luiz Augusto von Dentz
@ 2014-07-29  0:24   ` Artem Rakhov
  2014-07-29  5:16     ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-07-29  0:24 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: linux-bluetooth

Hi Luiz,

Yes, the device is trusted.
So far I've tried BlueZ 4 with kernel 3.13, and Bluez 5.19 with kernel 3.8.11

Thanks,
Artem

On Mon, Jul 28, 2014 at 1:21 AM, Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
> Hi Artem,
>
> On Sat, Jul 26, 2014 at 4:33 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>> Hello,
>>
>> I have a problem with A2DP incoming connections. I have a BT speaker
>> (Monster Clarity HD), which automatically reconnects on startup to the
>> last connected source. It works fine with BlueZ 4, but it never
>> reconnects successfully when using BlueZ 5.19
>>
>> Here is btmon log:
>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>                [hci0] 3471.224113
>>       L2CAP: Connection Response (0x03) ident 2 len 8
>>         Destination CID: 64
>>         Source CID: 108
>>         Result: Connection pending (0x0001)
>>         Status: Authorization pending (0x0002)
>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>                [hci0] 3471.224313
>>       L2CAP: Connection Response (0x03) ident 2 len 8
>>         Destination CID: 64
>>         Source CID: 108
>>         Result: Connection successful (0x0000)
>>         Status: No further information available (0x0000)
>> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>>                [hci0] 3471.224417
>>       L2CAP: Configure Request (0x04) ident 2 len 4
>>         Destination CID: 108
>>         Flags: 0x0000
>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.226831
>>         Num handles: 1
>>         Handle: 21
>>         Count: 1
>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.227794
>>         Num handles: 1
>>         Handle: 21
>>         Count: 1
>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.228807
>>         Num handles: 1
>>         Handle: 21
>>         Count: 1
>>> ACL Data RX: Handle 21 flags 0x02 dlen 12                                           [hci0] 3471.256507
>>       L2CAP: Disconnection Request (0x06) ident 3 len 4
>>         Destination CID: 64
>>         Source CID: 108
>> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>>                [hci0] 3471.256592
>>       L2CAP: Disconnection Response (0x07) ident 3 len 4
>>         Destination CID: 64
>>         Source CID: 108
>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.258773
>>         Num handles: 1
>>         Handle: 21
>>         Count: 1
>>> HCI Event: Vendor (0xff) plen 7                                                     [hci0] 3471.549833
>>         82 00 01 00 01 15 00                             .......
>>> HCI Event: Disconnect Complete (0x05) plen 4                                        [hci0] 3471.550757
>>         Status: Success (0x00)
>>         Handle: 21
>>         Reason: Remote User Terminated Connection (0x13)
>> @ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3
>>
>>
>> As could be seen from the log, after the source sends L2CAP Configure
>> Request the speaker does not answer and disconnects (sends L2CAP
>> Disconnection Request).
>>
>> Debugging avdtp.c showed that processing of incoming connections is
>> held in avdtp_confirm_cb() function. There, at some point after
>> successful authorization G_IO_ERR and G_IO_HUP events appear. And then
>> session_cb() function is called (as callback for these events), which
>> drops the connection.
>
> This looks pretty strange as the remote seems to be disconnecting not
> us, btw did you tried to mark the device as trusted? Regarding it
> working with BlueZ 4, what kernel are you using with that and can you
> try to compare what is the difference in the logs, perhaps the remote
> does like the Configure Request for some reason.
>
>
> --
> Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-07-29  0:24   ` Artem Rakhov
@ 2014-07-29  5:16     ` Artem Rakhov
  2014-07-29  5:29       ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-07-29  5:16 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: linux-bluetooth

Have tried to connect the speaker to Macbook Pro (OS X, does not use
BlueZ). For some reason, when speaker initiates the incoming
connection, it connects via L2CAP to different PSM.
First, it goes to PSM 0x01 (Service Discovery Protocol), then
disconnects. Then it connects to 0x03 (RFCOMM) and keeps the
connection. After that speaker connects to PSM 0x01 again, and drops
connection.
And then finally the Mac itself initiates two L2CAP connections to
speaker, with correct PSM 0x19 (AVDTP). On device with BlueZ L2CAP
connection goes straight to PSM 0x19.

Here is a log from Macbook for the first connection to AVDTP:
[Jul 28 21:06:37.848]  [L2CAP SEND]  Connection Request - PSM: 0x0019
               Connection Request - PSM: 0x0019
               Identifier: 0x81
               Size: 4 (0x0004)
               PSM: 0x0019 - AVDTP (Audio/Video Distribution Transport
Protocol).
               Source CID: 0x0043
               Channel ID: 0x0001  Length: 0x0008 (08) [ 0B 20 0C 00
08 00 01 00 ]
               00000000: 0800 0100 0281 0400 1900 4300            ..........C.
[Jul 28 21:06:37.848]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x000C (12)]
[Jul 28 21:06:37.849]  [HCI COMMAND]  [FC48] Vendor Specific Command
[FC48] - Read Raw RSSI
[Jul 28 21:06:37.851]  [HCI EVENT]  [FC48] Command Complete - Broadcom
VSC Event - Read Raw RSSI - Handle: 0x000B  -50 dBm
[Jul 28 21:06:37.877]  [L2CAP RECEIVE]  Connection Response
               Connection Response
               Identifier: 0x81
               Size: 8 (0x0008)
               Destination CID: 0x0043
               Source CID: 0x0043
               Result: 0x0001 (Connection Pending)
               Status: 0x0002 (Authorization Pending)
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 03 81 08 00 ]
               00000000: 0c00 0100 0381 0800 4300 4300 0100 0200
........C.C.....
[Jul 28 21:06:37.877]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:37.986]  [L2CAP RECEIVE]  Connection Response
               Connection Response
               Identifier: 0x81
               Size: 8 (0x0008)
               Destination CID: 0x0043
               Source CID: 0x0043
               Result: 0x0000 (Connection Successful)
               Status: 0x0000 (No further information available)
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 03 81 08 00 ]
               00000000: 0c00 0100 0381 0800 4300 4300 0000 0000
........C.C.....
[Jul 28 21:06:37.986]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:37.986]  [L2CAP SEND]  Configuration Request
               Configuration Request
               Identifier: 0x84
               Size: 8 (0x0008)
               Destination CID: 0x0043
               Flags: 0x0000  - Not Continuation
               Options:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0xFFFF
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 04 84 08 00 ]
               00000000: 0c00 0100 0484 0800 4300 0000 0102 ffff
........C.......
[Jul 28 21:06:37.986]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:37.987]  [L2CAP RECEIVE]  Configuration Request
               Configuration Request
               Identifier: 0x0a
               Size: 8 (0x0008)
               Destination CID: 0x0043
               Flags: 0x0000  - Not Continuation
               Options:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0x037F
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 04 0A 08 00 ]
               00000000: 0c00 0100 040a 0800 4300 0000 0102 7f03
........C.......
[Jul 28 21:06:37.987]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:37.987]  [L2CAP SEND]  Configure Response
               Configure Response
               Identifier: 0x0a
               Size: 10 (0x000A)
               Source CID: 0x0043
               Flags: 0x0000 - Not Continuation
               Result: 0x0000
               Success
               Config:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0x037F
               Channel ID: 0x0001  Length: 0x000E (14) [ 0B 20 12 00
0E 00 01 00 05 0A 0A 00 43 00 ]
               00000000: 0e00 0100 050a 0a00 4300 0000 0000 0102
........C.......
               00000010: 7f03                                     ..
[Jul 28 21:06:37.987]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0012 (18)]
[Jul 28 21:06:37.991]  [HCI EVENT]  Number of Completed Packets -
Connection Handle: 0x000B - Packets: 0x0002
[Jul 28 21:06:38.020]  [L2CAP RECEIVE]  Configure Response
               Configure Response
               Identifier: 0x84
               Size: 6 (0x0006)
               Source CID: 0x0043
               Flags: 0x0000 - Not Continuation
               Result: 0x0000
               Success
               Empty Config Response.
               Channel ID: 0x0001  Length: 0x000A (10) [ 0B 20 0E 00
0A 00 01 00 05 84 ]
               00000000: 0a00 0100 0584 0600 4300 0000 0000       ........C.....
[Jul 28 21:06:38.020]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x000E (14)]
[Jul 28 21:06:38.020]  [AVDTP SEND]  Discover: Signal (0x01)
[Jul 28 21:06:38.024]  [HCI EVENT]  Number of Completed Packets -
Connection Handle: 0x000B - Packets: 0x0002
[Jul 28 21:06:38.077]  [AVDTP RECEIVE]  Discover: Accept-Response (0x01)
[Jul 28 21:06:38.178]  [AVDTP SEND]  Get Cap.: Signal (0x02)
...

Log for the second connection:
[Jul 28 21:06:38.519]  [L2CAP SEND]  Connection Request - PSM: 0x0019
               Connection Request - PSM: 0x0019
               Identifier: 0x14
               Size: 4 (0x0004)
               PSM: 0x0019 - AVDTP (Audio/Video Distribution Transport
Protocol).
               Source CID: 0x0044
               Channel ID: 0x0001  Length: 0x0008 (08) [ 0B 20 0C 00
08 00 01 00 ]
               00000000: 0800 0100 0214 0400 1900 4400            ..........D.
[Jul 28 21:06:38.519]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x000C (12)]
[Jul 28 21:06:38.520]  [HCI COMMAND]  [FC48] Vendor Specific Command
[FC48] - Read Raw RSSI
[Jul 28 21:06:38.521]  [HCI EVENT]  [FC48] Command Complete - Broadcom
VSC Event - Read Raw RSSI - Handle: 0x000B  -48 dBm
[Jul 28 21:06:38.550]  [L2CAP RECEIVE]  Connection Response
               Connection Response
               Identifier: 0x14
               Size: 8 (0x0008)
               Destination CID: 0x0044
               Source CID: 0x0044
               Result: 0x0001 (Connection Pending)
               Status: 0x0002 (Authorization Pending)
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 03 14 08 00 ]
               00000000: 0c00 0100 0314 0800 4400 4400 0100 0200
........D.D.....
[Jul 28 21:06:38.550]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:38.608]  [L2CAP RECEIVE]  Connection Response
               Connection Response
               Identifier: 0x14
               Size: 8 (0x0008)
               Destination CID: 0x0044
               Source CID: 0x0044
               Result: 0x0000 (Connection Successful)
               Status: 0x0000 (No further information available)
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 03 14 08 00 ]
               00000000: 0c00 0100 0314 0800 4400 4400 0000 0000
........D.D.....
[Jul 28 21:06:38.608]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:38.608]  [L2CAP SEND]  Configuration Request
               Configuration Request
               Identifier: 0x3d
               Size: 8 (0x0008)
               Destination CID: 0x0044
               Flags: 0x0000  - Not Continuation
               Options:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0xFFFF
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 04 3D 08 00 ]
               00000000: 0c00 0100 043d 0800 4400 0000 0102 ffff
.....=..D.......
[Jul 28 21:06:38.608]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:38.611]  [HCI EVENT]  Number of Completed Packets -
Connection Handle: 0x000B - Packets: 0x0002
[Jul 28 21:06:38.640]  [L2CAP RECEIVE]  Configuration Request
               Configuration Request
               Identifier: 0x0b
               Size: 8 (0x0008)
               Destination CID: 0x0044
               Flags: 0x0000  - Not Continuation
               Options:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0x037F
               Channel ID: 0x0001  Length: 0x000C (12) [ 0B 20 10 00
0C 00 01 00 04 0B 08 00 ]
               00000000: 0c00 0100 040b 0800 4400 0000 0102 7f03
........D.......
[Jul 28 21:06:38.640]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0010 (16)]
[Jul 28 21:06:38.640]  [L2CAP SEND]  Configure Response
               Configure Response
               Identifier: 0x0b
               Size: 10 (0x000A)
               Source CID: 0x0044
               Flags: 0x0000 - Not Continuation
               Result: 0x0000
               Success
               Config:
               Type: 0x01 (Hint)
               Length: 0x02
               MTU: 0x037F
               Channel ID: 0x0001  Length: 0x000E (14) [ 0B 20 12 00
0E 00 01 00 05 0B 0A 00 44 00 ]
               00000000: 0e00 0100 050b 0a00 4400 0000 0000 0102
........D.......
               00000010: 7f03                                     ..
[Jul 28 21:06:38.640]  [ACL SEND]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x0012 (18)]
[Jul 28 21:06:38.641]  [L2CAP RECEIVE]  Configure Response
               Configure Response
               Identifier: 0x3d
               Size: 6 (0x0006)
               Source CID: 0x0044
               Flags: 0x0000 - Not Continuation
               Result: 0x0000
               Success
               Empty Config Response.
               Channel ID: 0x0001  Length: 0x000A (10) [ 0B 20 0E 00
0A 00 01 00 05 3D ]
               00000000: 0a00 0100 053d 0600 4400 0000 0000       .....=..D.....
[Jul 28 21:06:38.641]  [ACL RECEIVE]  Data [Handle: 0x000B, Packet
Boundary Flags: 0x2, Length: 0x000E (14)]


Another observation is that BlueZ's L2CAP Configure Request does not
contain any MTU. Is that normal?

Thanks,
Artem

On Mon, Jul 28, 2014 at 5:24 PM, Artem Rakhov <arakhov@chromium.org> wrote:
> Hi Luiz,
>
> Yes, the device is trusted.
> So far I've tried BlueZ 4 with kernel 3.13, and Bluez 5.19 with kernel 3.8.11
>
> Thanks,
> Artem
>
> On Mon, Jul 28, 2014 at 1:21 AM, Luiz Augusto von Dentz
> <luiz.dentz@gmail.com> wrote:
>> Hi Artem,
>>
>> On Sat, Jul 26, 2014 at 4:33 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>>> Hello,
>>>
>>> I have a problem with A2DP incoming connections. I have a BT speaker
>>> (Monster Clarity HD), which automatically reconnects on startup to the
>>> last connected source. It works fine with BlueZ 4, but it never
>>> reconnects successfully when using BlueZ 5.19
>>>
>>> Here is btmon log:
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>                [hci0] 3471.224113
>>>       L2CAP: Connection Response (0x03) ident 2 len 8
>>>         Destination CID: 64
>>>         Source CID: 108
>>>         Result: Connection pending (0x0001)
>>>         Status: Authorization pending (0x0002)
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>                [hci0] 3471.224313
>>>       L2CAP: Connection Response (0x03) ident 2 len 8
>>>         Destination CID: 64
>>>         Source CID: 108
>>>         Result: Connection successful (0x0000)
>>>         Status: No further information available (0x0000)
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>>>                [hci0] 3471.224417
>>>       L2CAP: Configure Request (0x04) ident 2 len 4
>>>         Destination CID: 108
>>>         Flags: 0x0000
>>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.226831
>>>         Num handles: 1
>>>         Handle: 21
>>>         Count: 1
>>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.227794
>>>         Num handles: 1
>>>         Handle: 21
>>>         Count: 1
>>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.228807
>>>         Num handles: 1
>>>         Handle: 21
>>>         Count: 1
>>>> ACL Data RX: Handle 21 flags 0x02 dlen 12                                           [hci0] 3471.256507
>>>       L2CAP: Disconnection Request (0x06) ident 3 len 4
>>>         Destination CID: 64
>>>         Source CID: 108
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 12
>>>                [hci0] 3471.256592
>>>       L2CAP: Disconnection Response (0x07) ident 3 len 4
>>>         Destination CID: 64
>>>         Source CID: 108
>>>> HCI Event: Number of Completed Packets (0x13) plen 5                                [hci0] 3471.258773
>>>         Num handles: 1
>>>         Handle: 21
>>>         Count: 1
>>>> HCI Event: Vendor (0xff) plen 7                                                     [hci0] 3471.549833
>>>         82 00 01 00 01 15 00                             .......
>>>> HCI Event: Disconnect Complete (0x05) plen 4                                        [hci0] 3471.550757
>>>         Status: Success (0x00)
>>>         Handle: 21
>>>         Reason: Remote User Terminated Connection (0x13)
>>> @ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3
>>>
>>>
>>> As could be seen from the log, after the source sends L2CAP Configure
>>> Request the speaker does not answer and disconnects (sends L2CAP
>>> Disconnection Request).
>>>
>>> Debugging avdtp.c showed that processing of incoming connections is
>>> held in avdtp_confirm_cb() function. There, at some point after
>>> successful authorization G_IO_ERR and G_IO_HUP events appear. And then
>>> session_cb() function is called (as callback for these events), which
>>> drops the connection.
>>
>> This looks pretty strange as the remote seems to be disconnecting not
>> us, btw did you tried to mark the device as trusted? Regarding it
>> working with BlueZ 4, what kernel are you using with that and can you
>> try to compare what is the difference in the logs, perhaps the remote
>> does like the Configure Request for some reason.
>>
>>
>> --
>> Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-07-29  5:16     ` Artem Rakhov
@ 2014-07-29  5:29       ` Marcel Holtmann
  2014-08-08  7:32         ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Marcel Holtmann @ 2014-07-29  5:29 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Luiz Augusto von Dentz, linux-bluetooth

Hi Artem,

> Have tried to connect the speaker to Macbook Pro (OS X, does not use
> BlueZ). For some reason, when speaker initiates the incoming
> connection, it connects via L2CAP to different PSM.
> First, it goes to PSM 0x01 (Service Discovery Protocol), then
> disconnects. Then it connects to 0x03 (RFCOMM) and keeps the
> connection. After that speaker connects to PSM 0x01 again, and drops
> connection.
> And then finally the Mac itself initiates two L2CAP connections to
> speaker, with correct PSM 0x19 (AVDTP). On device with BlueZ L2CAP
> connection goes straight to PSM 0x19.
> 
> Here is a log from Macbook for the first connection to AVDTP:
> [Jul 28 21:06:37.848]  [L2CAP SEND]  Connection Request - PSM: 0x0019
>               Connection Request - PSM: 0x0019
>               Identifier: 0x81
>               Size: 4 (0x0004)
>               PSM: 0x0019 - AVDTP (Audio/Video Distribution Transport
> Protocol).
>               Source CID: 0x0043
>               Channel ID: 0x0001  Length: 0x0008 (08) [ 0B 20 0C 00
> 08 00 01 00 ]
>               00000000: 0800 0100 0281 0400 1900 4300            ..........C.

you know that hcidump and btmon can read Packet Logger files created on OS X. So maybe sending a binary pklg file around might be helpful for anybody looking at the details here.

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-07-29  5:29       ` Marcel Holtmann
@ 2014-08-08  7:32         ` Artem Rakhov
  2014-08-10  7:32           ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-08  7:32 UTC (permalink / raw)
  To: Marcel Holtmann; +Cc: Luiz Augusto von Dentz, linux-bluetooth

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

Hi Marcel,

Please find Packet Logger's btsnoop log in the attachment.

So far I have 2 observations:
1. Mac does not require any authorization (most likely it's not the cause)
2. I found another BT speaker which works properly. At first, I'm
seeing the same behavior: speaker initiates connection, BlueZ sends
Configure Request (with no MTU), then speaker disconnects. But after
that the device tries to initiate connection for the second time, and
this time it is successful: after BlueZ sends Configure Request with
no MTU, speaker answers with another Configure Request (with some
MTU), and connection is established normally. Is it possible, that
BlueZ is doing something wrong, but then this new speaker tries
something else, while the old one does not?

I also tried kernel 3.10 and latest BlueZ, it didn't change anything.

Thanks,
Artem

On Mon, Jul 28, 2014 at 10:29 PM, Marcel Holtmann <marcel@holtmann.org> wrote:
> Hi Artem,
>
>> Have tried to connect the speaker to Macbook Pro (OS X, does not use
>> BlueZ). For some reason, when speaker initiates the incoming
>> connection, it connects via L2CAP to different PSM.
>> First, it goes to PSM 0x01 (Service Discovery Protocol), then
>> disconnects. Then it connects to 0x03 (RFCOMM) and keeps the
>> connection. After that speaker connects to PSM 0x01 again, and drops
>> connection.
>> And then finally the Mac itself initiates two L2CAP connections to
>> speaker, with correct PSM 0x19 (AVDTP). On device with BlueZ L2CAP
>> connection goes straight to PSM 0x19.
>>
>> Here is a log from Macbook for the first connection to AVDTP:
>> [Jul 28 21:06:37.848]  [L2CAP SEND]  Connection Request - PSM: 0x0019
>>               Connection Request - PSM: 0x0019
>>               Identifier: 0x81
>>               Size: 4 (0x0004)
>>               PSM: 0x0019 - AVDTP (Audio/Video Distribution Transport
>> Protocol).
>>               Source CID: 0x0043
>>               Channel ID: 0x0001  Length: 0x0008 (08) [ 0B 20 0C 00
>> 08 00 01 00 ]
>>               00000000: 0800 0100 0281 0400 1900 4300            ..........C.
>
> you know that hcidump and btmon can read Packet Logger files created on OS X. So maybe sending a binary pklg file around might be helpful for anybody looking at the details here.
>
> Regards
>
> Marcel
>

[-- Attachment #2: bluetooth_packet.btsnoop --]
[-- Type: application/octet-stream, Size: 15436 bytes --]

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-08  7:32         ` Artem Rakhov
@ 2014-08-10  7:32           ` Luiz Augusto von Dentz
  2014-08-11  6:07             ` Michal Labedzki
  2014-08-18  7:11             ` Artem Rakhov
  0 siblings, 2 replies; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-08-10  7:32 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Marcel Holtmann, linux-bluetooth

Hi Artem,

On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org> wrote:
> Hi Marcel,
>
> Please find Packet Logger's btsnoop log in the attachment.
>
> So far I have 2 observations:
> 1. Mac does not require any authorization (most likely it's not the cause)
> 2. I found another BT speaker which works properly. At first, I'm
> seeing the same behavior: speaker initiates connection, BlueZ sends
> Configure Request (with no MTU), then speaker disconnects. But after
> that the device tries to initiate connection for the second time, and
> this time it is successful: after BlueZ sends Configure Request with
> no MTU, speaker answers with another Configure Request (with some
> MTU), and connection is established normally. Is it possible, that
> BlueZ is doing something wrong, but then this new speaker tries
> something else, while the old one does not?

I could not find anything l2cap related in this logs, but I notice
there a LE scanning ongoing perhaps you have should try disabling it
with Disconnect method for now. Anyway A2DP code is not really
involved with L2CAP connection setup so we would have to look at the
kernel changes but I quick check doesn't show anything and you said
you have tried with 3.10 so Im afraid this is only reproducible with
some specific device.

Btw, if you want to really isolate the problem you can try to connect
using avinfo or l2test directly.


-- 
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-10  7:32           ` Luiz Augusto von Dentz
@ 2014-08-11  6:07             ` Michal Labedzki
  2014-08-18  7:11             ` Artem Rakhov
  1 sibling, 0 replies; 25+ messages in thread
From: Michal Labedzki @ 2014-08-11  6:07 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Artem Rakhov, Marcel Holtmann, linux-bluetooth

Hi Luiz,

> I could not find anything l2cap related in this logs

See frame 258. It seems to be HFP. However log file seems to be broken
or... btmon and Wireshark have broken support for H1 (direction
[Sent/Recv] seems to be correct in logs, but Channel type is not
[btmon/wireshark treat 0 as ACL, 1 as HCI? little strange...]).

On 10 August 2014 09:32, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrot=
e:
> Hi Artem,
>
> On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org> wrot=
e:
>> Hi Marcel,
>>
>> Please find Packet Logger's btsnoop log in the attachment.
>>
>> So far I have 2 observations:
>> 1. Mac does not require any authorization (most likely it's not the caus=
e)
>> 2. I found another BT speaker which works properly. At first, I'm
>> seeing the same behavior: speaker initiates connection, BlueZ sends
>> Configure Request (with no MTU), then speaker disconnects. But after
>> that the device tries to initiate connection for the second time, and
>> this time it is successful: after BlueZ sends Configure Request with
>> no MTU, speaker answers with another Configure Request (with some
>> MTU), and connection is established normally. Is it possible, that
>> BlueZ is doing something wrong, but then this new speaker tries
>> something else, while the old one does not?
>
> I could not find anything l2cap related in this logs, but I notice
> there a LE scanning ongoing perhaps you have should try disabling it
> with Disconnect method for now. Anyway A2DP code is not really
> involved with L2CAP connection setup so we would have to look at the
> kernel changes but I quick check doesn't show anything and you said
> you have tried with 3.10 so Im afraid this is only reproducible with
> some specific device.
>
> Btw, if you want to really isolate the problem you can try to connect
> using avinfo or l2test directly.
>
>
> --
> Luiz Augusto von Dentz
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth=
" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html



--=20

Pozdrawiam / Best regards
---------------------------------------------------------------------------=
----------------------------------
Micha=C5=82 =C5=81ab=C4=99dzki, Software Engineer
Tieto Corporation

Product Development Services

http://www.tieto.com / http://www.tieto.pl
---
ASCII: Michal Labedzki
location: Swobodna 1 Street, 50-088 Wroc=C5=82aw, Poland
room: 5.01 (desk next to 5.08)
---
Please note: The information contained in this message may be legally
privileged and confidential and protected from disclosure. If the
reader of this message is not the intended recipient, you are hereby
notified that any unauthorised use, distribution or copying of this
communication is strictly prohibited. If you have received this
communication in error, please notify us immediately by replying to
the message and deleting it from your computer. Thank You.
---
Please consider the environment before printing this e-mail.
---
Tieto Poland sp=C3=B3=C5=82ka z ograniczon=C4=85 odpowiedzialno=C5=9Bci=C4=
=85 z siedzib=C4=85 w
Szczecinie, ul. Malczewskiego 26. Zarejestrowana w S=C4=85dzie Rejonowym
Szczecin-Centrum w Szczecinie, XIII Wydzia=C5=82 Gospodarczy Krajowego
Rejestru S=C4=85dowego pod numerem 0000124858. NIP: 8542085557. REGON:
812023656. Kapita=C5=82 zak=C5=82adowy: 4 271500 PLN

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-10  7:32           ` Luiz Augusto von Dentz
  2014-08-11  6:07             ` Michal Labedzki
@ 2014-08-18  7:11             ` Artem Rakhov
  2014-08-20 22:52               ` Artem Rakhov
  2014-08-20 22:54               ` Artem Rakhov
  1 sibling, 2 replies; 25+ messages in thread
From: Artem Rakhov @ 2014-08-18  7:11 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Marcel Holtmann, linux-bluetooth

Hi Luiz,

I have also tried kernel 3.14, it didn't help.
How can I use avinfo for test? Looks like it shows only basic
information for the device. And it works fine with the speaker.
I tried to use avtest: when I try to connect to the speaker,
everything seems to be working good. Is there any way to use it to
test incoming connections?

Thanks,
Artem

On Sun, Aug 10, 2014 at 12:32 AM, Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
> Hi Artem,
>
> On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>> Hi Marcel,
>>
>> Please find Packet Logger's btsnoop log in the attachment.
>>
>> So far I have 2 observations:
>> 1. Mac does not require any authorization (most likely it's not the cause)
>> 2. I found another BT speaker which works properly. At first, I'm
>> seeing the same behavior: speaker initiates connection, BlueZ sends
>> Configure Request (with no MTU), then speaker disconnects. But after
>> that the device tries to initiate connection for the second time, and
>> this time it is successful: after BlueZ sends Configure Request with
>> no MTU, speaker answers with another Configure Request (with some
>> MTU), and connection is established normally. Is it possible, that
>> BlueZ is doing something wrong, but then this new speaker tries
>> something else, while the old one does not?
>
> I could not find anything l2cap related in this logs, but I notice
> there a LE scanning ongoing perhaps you have should try disabling it
> with Disconnect method for now. Anyway A2DP code is not really
> involved with L2CAP connection setup so we would have to look at the
> kernel changes but I quick check doesn't show anything and you said
> you have tried with 3.10 so Im afraid this is only reproducible with
> some specific device.
>
> Btw, if you want to really isolate the problem you can try to connect
> using avinfo or l2test directly.
>
>
> --
> Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-18  7:11             ` Artem Rakhov
@ 2014-08-20 22:52               ` Artem Rakhov
  2014-08-20 22:54               ` Artem Rakhov
  1 sibling, 0 replies; 25+ messages in thread
From: Artem Rakhov @ 2014-08-20 22:52 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Marcel Holtmann, linux-bluetooth


[-- Attachment #1.1: Type: text/plain, Size: 2578 bytes --]

Hello,

I found the way to use avtest for testing incoming connections from the
speaker. If anyone is interested: stopped bluetoothd, powered BT back to
on, used "avtest --reject 0". Also had to change avtest to answer like
source instead of sink, which is set by default.

Incoming connections to avtest are always successful. And logs are very
similar (attached). I think the main difference is that the bluetoothd
requires authorization, while avtest does not.

Thanks,
Artem


On Mon, Aug 18, 2014 at 12:11 AM, Artem Rakhov <arakhov@chromium.org> wrote:

> Hi Luiz,
>
> I have also tried kernel 3.14, it didn't help.
> How can I use avinfo for test? Looks like it shows only basic
> information for the device. And it works fine with the speaker.
> I tried to use avtest: when I try to connect to the speaker,
> everything seems to be working good. Is there any way to use it to
> test incoming connections?
>
> Thanks,
> Artem
>
> On Sun, Aug 10, 2014 at 12:32 AM, Luiz Augusto von Dentz
> <luiz.dentz@gmail.com> wrote:
> > Hi Artem,
> >
> > On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org>
> wrote:
> >> Hi Marcel,
> >>
> >> Please find Packet Logger's btsnoop log in the attachment.
> >>
> >> So far I have 2 observations:
> >> 1. Mac does not require any authorization (most likely it's not the
> cause)
> >> 2. I found another BT speaker which works properly. At first, I'm
> >> seeing the same behavior: speaker initiates connection, BlueZ sends
> >> Configure Request (with no MTU), then speaker disconnects. But after
> >> that the device tries to initiate connection for the second time, and
> >> this time it is successful: after BlueZ sends Configure Request with
> >> no MTU, speaker answers with another Configure Request (with some
> >> MTU), and connection is established normally. Is it possible, that
> >> BlueZ is doing something wrong, but then this new speaker tries
> >> something else, while the old one does not?
> >
> > I could not find anything l2cap related in this logs, but I notice
> > there a LE scanning ongoing perhaps you have should try disabling it
> > with Disconnect method for now. Anyway A2DP code is not really
> > involved with L2CAP connection setup so we would have to look at the
> > kernel changes but I quick check doesn't show anything and you said
> > you have tried with 3.10 so Im afraid this is only reproducible with
> > some specific device.
> >
> > Btw, if you want to really isolate the problem you can try to connect
> > using avinfo or l2test directly.
> >
> >
> > --
> > Luiz Augusto von Dentz
>

[-- Attachment #1.2: Type: text/html, Size: 3420 bytes --]

[-- Attachment #2: btmon_avtest --]
[-- Type: application/octet-stream, Size: 18928 bytes --]

luetooth monitor ver 5.19
= New Index: 3C:77:E6:60:5C:B2 (BR/EDR,USB,hci0)                                                                                     [hci0] 0.456259
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.527472
        81 00                                            ..              
> HCI Event: Connect Request (0x04) plen 10                                                                                         [hci0] 22.528472
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)
        Link type: ACL (0x01)
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7                                                                       [hci0] 22.528565
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Slave (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.529462
      Accept Connection Request (0x01|0x0009) ncmd 1
        Status: Success (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.576536
        81 01                                            ..              
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 22.577469
        82 00 00 01 01 15 00                             .......         
> HCI Event: Connect Complete (0x03) plen 11                                                                                        [hci0] 22.578469
        Status: Success (0x00)
        Handle: 21
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link type: ACL (0x01)
        Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2                                                                  [hci0] 22.578641
        Handle: 21
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.579463
      Read Remote Supported Features (0x01|0x001b) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11                                                                          [hci0] 22.605538
        Status: Success (0x00)
        Handle: 21
        Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
          3 slot packets
          5 slot packets
          Encryption
          Slot offset
          Timing accuracy
          Role switch
          Hold mode
          Sniff mode
          Park state
          Power control requests
          Channel quality driven data rate (CQDDR)
          SCO link
          HV2 packets
          HV3 packets
          u-law log synchronous data
          A-law log synchronous data
          CVSD synchronous data
          Paging parameter negotiation
          Power control
          Transparent synchronous data
          Broadcast Encryption
          Enhanced Data Rate ACL 2 Mbps mode
          Enhanced Data Rate ACL 3 Mbps mode
          Enhanced inquiry scan
          Interlaced inquiry scan
          Interlaced page scan
          RSSI with inquiry results
          Extended SCO link (EV3 packets)
          EV4 packets
          EV5 packets
          AFH capable slave
          AFH classification slave
          3-slot Enhanced Data Rate ACL packets
          5-slot Enhanced Data Rate ACL packets
          Sniff subrating
          Pause encryption
          AFH capable master
          AFH classification master
          Enhanced Data Rate eSCO 2 Mbps mode
          Enhanced Data Rate eSCO 3 Mbps mode
          3-slot Enhanced Data Rate eSCO packets
          Extended Inquiry Response
          Secure Simple Pairing
          Encapsulated PDU
          Non-flushable Packet Boundary Flag
          Link Supervision Timeout Changed Event
          Inquiry TX Power Level
          Extended features
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3                                                                   [hci0] 22.605584
        Handle: 21
        Page: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.606460
      Read Remote Extended Features (0x01|0x001c) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Extended Features (0x23) plen 13                                                                           [hci0] 22.615477
        Status: Success (0x00)
        Handle: 21
        Page: 1/1
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          Secure Simple Pairing (Host Support)
< HCI Command: Remote Name Request (0x01|0x0019) plen 10                                                                            [hci0] 22.615583
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.616462
        81 00                                            ..              
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.617463
      Remote Name Request (0x01|0x0019) ncmd 1
        Status: Success (0x00)
> HCI Event: Link Key Request (0x17) plen 6                                                                                         [hci0] 22.654535
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22                                                                         [hci0] 22.654580
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link key: 9a1e116ffd4baad792d15c680b35f152
> HCI Event: Command Complete (0x0e) plen 10                                                                                        [hci0] 22.657473
      Link Key Request Reply (0x01|0x000b) ncmd 1
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.659466
        81 01                                            ..              
> HCI Event: Remote Name Req Complete (0x07) plen 255                                                                               [hci0] 22.676479
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Name: Monster Clarity
@ Device Connected: 10:B7:F6:01:31:ED (0) flags 0x0000
        10 09 4d 6f 6e 73 74 65 72 20 43 6c 61 72 69 74  ..Monster Clarit
        79 04 0d 04 04 24                                y....$          
> HCI Event: Encryption Change (0x08) plen 4                                                                                        [hci0] 22.729470
        Status: Success (0x00)
        Handle: 21
        Encryption: Enabled with E0 (0x01)
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 22.741045
      L2CAP: Connection Request (0x02) ident 2 len 4
        PSM: 25 (0x0019)
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.741104
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 10                                                                                         [hci0] 22.741111
      L2CAP: Information Request (0x0a) ident 1 len 2
        Type: Extended features supported (0x0002)
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 22.741466
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.750463
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.751462
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.757325
      L2CAP: Information Response (0x0b) ident 1 len 8
        Type: Extended features supported (0x0002)
        Result: Success (0x0000)
        Features: 0x00000000
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.757384
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.757389
      L2CAP: Configure Request (0x04) ident 2 len 4
        Destination CID: 65
        Flags: 0x0000
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.766471
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.767464
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.783656
      L2CAP: Configure Request (0x04) ident 3 len 8
        Destination CID: 64
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
< ACL Data TX: Handle 21 flags 0x00 dlen 18                                                                                         [hci0] 22.783723
      L2CAP: Configure Response (0x05) ident 3 len 10
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
> ACL Data RX: Handle 21 flags 0x02 dlen 14                                                                                         [hci0] 22.793532
      L2CAP: Configure Response (0x05) ident 2 len 6
        Source CID: 64
        Flags: 0x0000
        Result: Success (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.795469
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 6                                                                                          [hci0] 22.823472
      Channel: 64 len 2 [PSM 25 mode 0] {chan 0}
        10 01                                            ..              
< ACL Data TX: Handle 21 flags 0x00 dlen 8                                                                                          [hci0] 22.823644
      Channel: 65 len 4 [PSM 25 mode 0] {chan 0}
        12 01 04 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.846535
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 22.868472
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        20 02 04                                          ..             
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.868659
      Channel: 65 len 12 [PSM 25 mode 0] {chan 0}
        22 02 01 00 07 06 00 00 22 15 02 33              "......."..3    
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.892465
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 18                                                                                         [hci0] 22.934721
      Channel: 64 len 14 [PSM 25 mode 0] {chan 0}
        30 03 04 04 01 00 07 06 00 00 22 15 02 33        0........."..3  
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 22.934848
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        32 03                                            2.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.957466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 22.977206
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        40 06 04                                         @..             
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 22.977276
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        42 06                                            B.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.001471
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 23.031050
      L2CAP: Connection Request (0x02) ident 4 len 4
        PSM: 25 (0x0019)
        Source CID: 66
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 23.031137
      L2CAP: Connection Response (0x03) ident 4 len 8
        Destination CID: 65
        Source CID: 66
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 23.031147
      L2CAP: Configure Request (0x04) ident 3 len 4
        Destination CID: 66
        Flags: 0x0000
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 23.031458
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.053469
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.055466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 23.079849
      L2CAP: Configure Request (0x04) ident 5 len 8
        Destination CID: 65
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
< ACL Data TX: Handle 21 flags 0x00 dlen 18                                                                                         [hci0] 23.079898
      L2CAP: Configure Response (0x05) ident 5 len 10
        Source CID: 66
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
> ACL Data RX: Handle 21 flags 0x02 dlen 14                                                                                         [hci0] 23.089835
      L2CAP: Configure Response (0x05) ident 3 len 6
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.091465
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Link Supervision Timeout Changed (0x38) plen 4                                                                         [hci0] 23.206472
        Handle: 21
        Timeout: 10080.000 msec (0x3f00)
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 23.219721
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        50 07 04                                         P..             
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 23.219831
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        52 07                                            R.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.233466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 23.282281
      L2CAP: Connection Request (0x02) ident 6 len 4
        PSM: 23 (0x0017)
        Source CID: 67
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 23.282363
      L2CAP: Connection Response (0x03) ident 6 len 8
        Destination CID: 0
        Source CID: 67
        Result: Connection refused - PSM not supported (0x0002)
        Status: No further information available (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.306540
        Num handles: 1
        Handle: 21
        Count: 1

[-- Attachment #3: btmon_bluetoothd --]
[-- Type: application/octet-stream, Size: 12380 bytes --]

Bluetooth monitor ver 5.19
= New Index: 3C:77:E6:60:5C:B2 (BR/EDR,USB,hci0)                                                                                     [hci0] 0.564246
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.526832
        81 00                                            ..              
> HCI Event: Connect Request (0x04) plen 10                                                                                         [hci0] 21.527763
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)
        Link type: ACL (0x01)
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7                                                                       [hci0] 21.527823
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Master (0x00)
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.528754
      Accept Connection Request (0x01|0x0009) ncmd 1
        Status: Success (0x00)
> HCI Event: Role Change (0x12) plen 8                                                                                              [hci0] 21.680833
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Master (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.752830
        81 01                                            ..              
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 21.753762
        82 00 00 00 01 15 00                             .......         
> HCI Event: Connect Complete (0x03) plen 11                                                                                        [hci0] 21.754761
        Status: Success (0x00)
        Handle: 21
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link type: ACL (0x01)
        Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2                                                                  [hci0] 21.754922
        Handle: 21
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.755754
      Read Remote Supported Features (0x01|0x001b) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11                                                                          [hci0] 21.791757
        Status: Success (0x00)
        Handle: 21
        Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
          3 slot packets
          5 slot packets
          Encryption
          Slot offset
          Timing accuracy
          Role switch
          Hold mode
          Sniff mode
          Park state
          Power control requests
          Channel quality driven data rate (CQDDR)
          SCO link
          HV2 packets
          HV3 packets
          u-law log synchronous data
          A-law log synchronous data
          CVSD synchronous data
          Paging parameter negotiation
          Power control
          Transparent synchronous data
          Broadcast Encryption
          Enhanced Data Rate ACL 2 Mbps mode
          Enhanced Data Rate ACL 3 Mbps mode
          Enhanced inquiry scan
          Interlaced inquiry scan
          Interlaced page scan
          RSSI with inquiry results
          Extended SCO link (EV3 packets)
          EV4 packets
          EV5 packets
          AFH capable slave
          AFH classification slave
          3-slot Enhanced Data Rate ACL packets
          5-slot Enhanced Data Rate ACL packets
          Sniff subrating
          Pause encryption
          AFH capable master
          AFH classification master
          Enhanced Data Rate eSCO 2 Mbps mode
          Enhanced Data Rate eSCO 3 Mbps mode
          3-slot Enhanced Data Rate eSCO packets
          Extended Inquiry Response
          Secure Simple Pairing
          Encapsulated PDU
          Non-flushable Packet Boundary Flag
          Link Supervision Timeout Changed Event
          Inquiry TX Power Level
          Extended features
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3                                                                   [hci0] 21.791806
        Handle: 21
        Page: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.792750
      Read Remote Extended Features (0x01|0x001c) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Extended Features (0x23) plen 13                                                                           [hci0] 21.801761
        Status: Success (0x00)
        Handle: 21
        Page: 1/1
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          Secure Simple Pairing (Host Support)
< HCI Command: Remote Name Request (0x01|0x0019) plen 10                                                                            [hci0] 21.801798
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.802759
        81 00                                            ..              
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.803769
      Remote Name Request (0x01|0x0019) ncmd 1
        Status: Success (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.825755
        81 01                                            ..              
> HCI Event: Remote Name Req Complete (0x07) plen 255                                                                               [hci0] 21.842744
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Name: Monster Clarity
@ Device Connected: 10:B7:F6:01:31:ED (0) flags 0x0000
        10 09 4d 6f 6e 73 74 65 72 20 43 6c 61 72 69 74  ..Monster Clarit
        79 04 0d 04 04 24                                y....$          
> HCI Event: Link Key Request (0x17) plen 6                                                                                         [hci0] 21.879776
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22                                                                         [hci0] 21.879877
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link key: 9a1e116ffd4baad792d15c680b35f152
> HCI Event: Command Complete (0x0e) plen 10                                                                                        [hci0] 21.882760
      Link Key Request Reply (0x01|0x000b) ncmd 1
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
> HCI Event: Encryption Change (0x08) plen 4                                                                                        [hci0] 21.996829
        Status: Success (0x00)
        Handle: 21
        Encryption: Enabled with E0 (0x01)
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 21.997576
      L2CAP: Connection Request (0x02) ident 2 len 4
        PSM: 25 (0x0019)
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 21.997644
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 10                                                                                         [hci0] 21.997652
      L2CAP: Information Request (0x0a) ident 1 len 2
        Type: Extended features supported (0x0002)
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 21.997755
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.000760
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.001757
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.030118
      L2CAP: Information Response (0x0b) ident 1 len 8
        Type: Extended features supported (0x0002)
        Result: Success (0x0000)
        Features: 0x00000000
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.030160
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.030595
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.030735
      L2CAP: Configure Request (0x04) ident 2 len 4
        Destination CID: 65
        Flags: 0x0000
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.032754
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.033752
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.035751
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 22.085097
      L2CAP: Disconnection Request (0x06) ident 3 len 4
        Destination CID: 64
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.085139
      L2CAP: Disconnection Response (0x07) ident 3 len 4
        Destination CID: 64
        Source CID: 65
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.087762
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 22.354831
        82 00 01 00 01 15 00                             .......         
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                      [hci0] 22.355759
        Status: Success (0x00)
        Handle: 21
        Reason: Remote User Terminated Connection (0x13)
@ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-18  7:11             ` Artem Rakhov
  2014-08-20 22:52               ` Artem Rakhov
@ 2014-08-20 22:54               ` Artem Rakhov
  2014-08-21  6:42                 ` Artem Rakhov
  1 sibling, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-20 22:54 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Marcel Holtmann, linux-bluetooth

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

Hello,

I found the way to use avtest for testing incoming connections from
the speaker. If anyone is interested: stopped bluetoothd, powered BT
back to on, used "avtest --reject 0". Also had to change avtest to
answer like source instead of sink, which is set by default.

Incoming connections to avtest are always successful. And logs are
very similar (attached). I think the main difference is that the
bluetoothd requires authorization, while avtest does not.

Thanks,
Artem

On Mon, Aug 18, 2014 at 12:11 AM, Artem Rakhov <arakhov@chromium.org> wrote:
> Hi Luiz,
>
> I have also tried kernel 3.14, it didn't help.
> How can I use avinfo for test? Looks like it shows only basic
> information for the device. And it works fine with the speaker.
> I tried to use avtest: when I try to connect to the speaker,
> everything seems to be working good. Is there any way to use it to
> test incoming connections?
>
> Thanks,
> Artem
>
> On Sun, Aug 10, 2014 at 12:32 AM, Luiz Augusto von Dentz
> <luiz.dentz@gmail.com> wrote:
>> Hi Artem,
>>
>> On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>>> Hi Marcel,
>>>
>>> Please find Packet Logger's btsnoop log in the attachment.
>>>
>>> So far I have 2 observations:
>>> 1. Mac does not require any authorization (most likely it's not the cause)
>>> 2. I found another BT speaker which works properly. At first, I'm
>>> seeing the same behavior: speaker initiates connection, BlueZ sends
>>> Configure Request (with no MTU), then speaker disconnects. But after
>>> that the device tries to initiate connection for the second time, and
>>> this time it is successful: after BlueZ sends Configure Request with
>>> no MTU, speaker answers with another Configure Request (with some
>>> MTU), and connection is established normally. Is it possible, that
>>> BlueZ is doing something wrong, but then this new speaker tries
>>> something else, while the old one does not?
>>
>> I could not find anything l2cap related in this logs, but I notice
>> there a LE scanning ongoing perhaps you have should try disabling it
>> with Disconnect method for now. Anyway A2DP code is not really
>> involved with L2CAP connection setup so we would have to look at the
>> kernel changes but I quick check doesn't show anything and you said
>> you have tried with 3.10 so Im afraid this is only reproducible with
>> some specific device.
>>
>> Btw, if you want to really isolate the problem you can try to connect
>> using avinfo or l2test directly.
>>
>>
>> --
>> Luiz Augusto von Dentz

[-- Attachment #2: btmon_avtest --]
[-- Type: application/octet-stream, Size: 18928 bytes --]

luetooth monitor ver 5.19
= New Index: 3C:77:E6:60:5C:B2 (BR/EDR,USB,hci0)                                                                                     [hci0] 0.456259
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.527472
        81 00                                            ..              
> HCI Event: Connect Request (0x04) plen 10                                                                                         [hci0] 22.528472
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)
        Link type: ACL (0x01)
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7                                                                       [hci0] 22.528565
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Slave (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.529462
      Accept Connection Request (0x01|0x0009) ncmd 1
        Status: Success (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.576536
        81 01                                            ..              
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 22.577469
        82 00 00 01 01 15 00                             .......         
> HCI Event: Connect Complete (0x03) plen 11                                                                                        [hci0] 22.578469
        Status: Success (0x00)
        Handle: 21
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link type: ACL (0x01)
        Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2                                                                  [hci0] 22.578641
        Handle: 21
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.579463
      Read Remote Supported Features (0x01|0x001b) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11                                                                          [hci0] 22.605538
        Status: Success (0x00)
        Handle: 21
        Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
          3 slot packets
          5 slot packets
          Encryption
          Slot offset
          Timing accuracy
          Role switch
          Hold mode
          Sniff mode
          Park state
          Power control requests
          Channel quality driven data rate (CQDDR)
          SCO link
          HV2 packets
          HV3 packets
          u-law log synchronous data
          A-law log synchronous data
          CVSD synchronous data
          Paging parameter negotiation
          Power control
          Transparent synchronous data
          Broadcast Encryption
          Enhanced Data Rate ACL 2 Mbps mode
          Enhanced Data Rate ACL 3 Mbps mode
          Enhanced inquiry scan
          Interlaced inquiry scan
          Interlaced page scan
          RSSI with inquiry results
          Extended SCO link (EV3 packets)
          EV4 packets
          EV5 packets
          AFH capable slave
          AFH classification slave
          3-slot Enhanced Data Rate ACL packets
          5-slot Enhanced Data Rate ACL packets
          Sniff subrating
          Pause encryption
          AFH capable master
          AFH classification master
          Enhanced Data Rate eSCO 2 Mbps mode
          Enhanced Data Rate eSCO 3 Mbps mode
          3-slot Enhanced Data Rate eSCO packets
          Extended Inquiry Response
          Secure Simple Pairing
          Encapsulated PDU
          Non-flushable Packet Boundary Flag
          Link Supervision Timeout Changed Event
          Inquiry TX Power Level
          Extended features
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3                                                                   [hci0] 22.605584
        Handle: 21
        Page: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.606460
      Read Remote Extended Features (0x01|0x001c) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Extended Features (0x23) plen 13                                                                           [hci0] 22.615477
        Status: Success (0x00)
        Handle: 21
        Page: 1/1
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          Secure Simple Pairing (Host Support)
< HCI Command: Remote Name Request (0x01|0x0019) plen 10                                                                            [hci0] 22.615583
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.616462
        81 00                                            ..              
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 22.617463
      Remote Name Request (0x01|0x0019) ncmd 1
        Status: Success (0x00)
> HCI Event: Link Key Request (0x17) plen 6                                                                                         [hci0] 22.654535
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22                                                                         [hci0] 22.654580
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link key: 9a1e116ffd4baad792d15c680b35f152
> HCI Event: Command Complete (0x0e) plen 10                                                                                        [hci0] 22.657473
      Link Key Request Reply (0x01|0x000b) ncmd 1
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 22.659466
        81 01                                            ..              
> HCI Event: Remote Name Req Complete (0x07) plen 255                                                                               [hci0] 22.676479
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Name: Monster Clarity
@ Device Connected: 10:B7:F6:01:31:ED (0) flags 0x0000
        10 09 4d 6f 6e 73 74 65 72 20 43 6c 61 72 69 74  ..Monster Clarit
        79 04 0d 04 04 24                                y....$          
> HCI Event: Encryption Change (0x08) plen 4                                                                                        [hci0] 22.729470
        Status: Success (0x00)
        Handle: 21
        Encryption: Enabled with E0 (0x01)
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 22.741045
      L2CAP: Connection Request (0x02) ident 2 len 4
        PSM: 25 (0x0019)
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.741104
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 10                                                                                         [hci0] 22.741111
      L2CAP: Information Request (0x0a) ident 1 len 2
        Type: Extended features supported (0x0002)
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 22.741466
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.750463
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.751462
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.757325
      L2CAP: Information Response (0x0b) ident 1 len 8
        Type: Extended features supported (0x0002)
        Result: Success (0x0000)
        Features: 0x00000000
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.757384
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.757389
      L2CAP: Configure Request (0x04) ident 2 len 4
        Destination CID: 65
        Flags: 0x0000
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.766471
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.767464
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.783656
      L2CAP: Configure Request (0x04) ident 3 len 8
        Destination CID: 64
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
< ACL Data TX: Handle 21 flags 0x00 dlen 18                                                                                         [hci0] 22.783723
      L2CAP: Configure Response (0x05) ident 3 len 10
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
> ACL Data RX: Handle 21 flags 0x02 dlen 14                                                                                         [hci0] 22.793532
      L2CAP: Configure Response (0x05) ident 2 len 6
        Source CID: 64
        Flags: 0x0000
        Result: Success (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.795469
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 6                                                                                          [hci0] 22.823472
      Channel: 64 len 2 [PSM 25 mode 0] {chan 0}
        10 01                                            ..              
< ACL Data TX: Handle 21 flags 0x00 dlen 8                                                                                          [hci0] 22.823644
      Channel: 65 len 4 [PSM 25 mode 0] {chan 0}
        12 01 04 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.846535
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 22.868472
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        20 02 04                                          ..             
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.868659
      Channel: 65 len 12 [PSM 25 mode 0] {chan 0}
        22 02 01 00 07 06 00 00 22 15 02 33              "......."..3    
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.892465
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 18                                                                                         [hci0] 22.934721
      Channel: 64 len 14 [PSM 25 mode 0] {chan 0}
        30 03 04 04 01 00 07 06 00 00 22 15 02 33        0........."..3  
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 22.934848
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        32 03                                            2.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.957466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 22.977206
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        40 06 04                                         @..             
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 22.977276
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        42 06                                            B.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.001471
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 23.031050
      L2CAP: Connection Request (0x02) ident 4 len 4
        PSM: 25 (0x0019)
        Source CID: 66
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 23.031137
      L2CAP: Connection Response (0x03) ident 4 len 8
        Destination CID: 65
        Source CID: 66
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 23.031147
      L2CAP: Configure Request (0x04) ident 3 len 4
        Destination CID: 66
        Flags: 0x0000
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 23.031458
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.053469
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.055466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 23.079849
      L2CAP: Configure Request (0x04) ident 5 len 8
        Destination CID: 65
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
< ACL Data TX: Handle 21 flags 0x00 dlen 18                                                                                         [hci0] 23.079898
      L2CAP: Configure Response (0x05) ident 5 len 10
        Source CID: 66
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01)
          MTU: 895
> ACL Data RX: Handle 21 flags 0x02 dlen 14                                                                                         [hci0] 23.089835
      L2CAP: Configure Response (0x05) ident 3 len 6
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.091465
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Link Supervision Timeout Changed (0x38) plen 4                                                                         [hci0] 23.206472
        Handle: 21
        Timeout: 10080.000 msec (0x3f00)
> ACL Data RX: Handle 21 flags 0x02 dlen 7                                                                                          [hci0] 23.219721
      Channel: 64 len 3 [PSM 25 mode 0] {chan 0}
        50 07 04                                         P..             
< ACL Data TX: Handle 21 flags 0x00 dlen 6                                                                                          [hci0] 23.219831
      Channel: 65 len 2 [PSM 25 mode 0] {chan 0}
        52 07                                            R.              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.233466
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 23.282281
      L2CAP: Connection Request (0x02) ident 6 len 4
        PSM: 23 (0x0017)
        Source CID: 67
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 23.282363
      L2CAP: Connection Response (0x03) ident 6 len 8
        Destination CID: 0
        Source CID: 67
        Result: Connection refused - PSM not supported (0x0002)
        Status: No further information available (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 23.306540
        Num handles: 1
        Handle: 21
        Count: 1

[-- Attachment #3: btmon_bluetoothd --]
[-- Type: application/octet-stream, Size: 12380 bytes --]

Bluetooth monitor ver 5.19
= New Index: 3C:77:E6:60:5C:B2 (BR/EDR,USB,hci0)                                                                                     [hci0] 0.564246
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.526832
        81 00                                            ..              
> HCI Event: Connect Request (0x04) plen 10                                                                                         [hci0] 21.527763
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)
        Link type: ACL (0x01)
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7                                                                       [hci0] 21.527823
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Master (0x00)
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.528754
      Accept Connection Request (0x01|0x0009) ncmd 1
        Status: Success (0x00)
> HCI Event: Role Change (0x12) plen 8                                                                                              [hci0] 21.680833
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Role: Master (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.752830
        81 01                                            ..              
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 21.753762
        82 00 00 00 01 15 00                             .......         
> HCI Event: Connect Complete (0x03) plen 11                                                                                        [hci0] 21.754761
        Status: Success (0x00)
        Handle: 21
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link type: ACL (0x01)
        Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2                                                                  [hci0] 21.754922
        Handle: 21
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.755754
      Read Remote Supported Features (0x01|0x001b) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11                                                                          [hci0] 21.791757
        Status: Success (0x00)
        Handle: 21
        Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
          3 slot packets
          5 slot packets
          Encryption
          Slot offset
          Timing accuracy
          Role switch
          Hold mode
          Sniff mode
          Park state
          Power control requests
          Channel quality driven data rate (CQDDR)
          SCO link
          HV2 packets
          HV3 packets
          u-law log synchronous data
          A-law log synchronous data
          CVSD synchronous data
          Paging parameter negotiation
          Power control
          Transparent synchronous data
          Broadcast Encryption
          Enhanced Data Rate ACL 2 Mbps mode
          Enhanced Data Rate ACL 3 Mbps mode
          Enhanced inquiry scan
          Interlaced inquiry scan
          Interlaced page scan
          RSSI with inquiry results
          Extended SCO link (EV3 packets)
          EV4 packets
          EV5 packets
          AFH capable slave
          AFH classification slave
          3-slot Enhanced Data Rate ACL packets
          5-slot Enhanced Data Rate ACL packets
          Sniff subrating
          Pause encryption
          AFH capable master
          AFH classification master
          Enhanced Data Rate eSCO 2 Mbps mode
          Enhanced Data Rate eSCO 3 Mbps mode
          3-slot Enhanced Data Rate eSCO packets
          Extended Inquiry Response
          Secure Simple Pairing
          Encapsulated PDU
          Non-flushable Packet Boundary Flag
          Link Supervision Timeout Changed Event
          Inquiry TX Power Level
          Extended features
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3                                                                   [hci0] 21.791806
        Handle: 21
        Page: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.792750
      Read Remote Extended Features (0x01|0x001c) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Extended Features (0x23) plen 13                                                                           [hci0] 21.801761
        Status: Success (0x00)
        Handle: 21
        Page: 1/1
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          Secure Simple Pairing (Host Support)
< HCI Command: Remote Name Request (0x01|0x0019) plen 10                                                                            [hci0] 21.801798
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.802759
        81 00                                            ..              
> HCI Event: Command Status (0x0f) plen 4                                                                                           [hci0] 21.803769
      Remote Name Request (0x01|0x0019) ncmd 1
        Status: Success (0x00)
> HCI Event: Vendor (0xff) plen 2                                                                                                   [hci0] 21.825755
        81 01                                            ..              
> HCI Event: Remote Name Req Complete (0x07) plen 255                                                                               [hci0] 21.842744
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Name: Monster Clarity
@ Device Connected: 10:B7:F6:01:31:ED (0) flags 0x0000
        10 09 4d 6f 6e 73 74 65 72 20 43 6c 61 72 69 74  ..Monster Clarit
        79 04 0d 04 04 24                                y....$          
> HCI Event: Link Key Request (0x17) plen 6                                                                                         [hci0] 21.879776
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22                                                                         [hci0] 21.879877
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
        Link key: 9a1e116ffd4baad792d15c680b35f152
> HCI Event: Command Complete (0x0e) plen 10                                                                                        [hci0] 21.882760
      Link Key Request Reply (0x01|0x000b) ncmd 1
        Status: Success (0x00)
        Address: 10:B7:F6:01:31:ED (OUI 10-B7-F6)
> HCI Event: Encryption Change (0x08) plen 4                                                                                        [hci0] 21.996829
        Status: Success (0x00)
        Handle: 21
        Encryption: Enabled with E0 (0x01)
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 21.997576
      L2CAP: Connection Request (0x02) ident 2 len 4
        PSM: 25 (0x0019)
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 21.997644
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 10                                                                                         [hci0] 21.997652
      L2CAP: Information Request (0x0a) ident 1 len 2
        Type: Extended features supported (0x0002)
> HCI Event: Vendor (0xff) plen 4                                                                                                   [hci0] 21.997755
        86 03 15 00                                      ....            
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.000760
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.001757
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 16                                                                                         [hci0] 22.030118
      L2CAP: Information Response (0x0b) ident 1 len 8
        Type: Extended features supported (0x0002)
        Result: Success (0x0000)
        Features: 0x00000000
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.030160
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
< ACL Data TX: Handle 21 flags 0x00 dlen 16                                                                                         [hci0] 22.030595
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.030735
      L2CAP: Configure Request (0x04) ident 2 len 4
        Destination CID: 65
        Flags: 0x0000
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.032754
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.033752
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.035751
        Num handles: 1
        Handle: 21
        Count: 1
> ACL Data RX: Handle 21 flags 0x02 dlen 12                                                                                         [hci0] 22.085097
      L2CAP: Disconnection Request (0x06) ident 3 len 4
        Destination CID: 64
        Source CID: 65
< ACL Data TX: Handle 21 flags 0x00 dlen 12                                                                                         [hci0] 22.085139
      L2CAP: Disconnection Response (0x07) ident 3 len 4
        Destination CID: 64
        Source CID: 65
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                              [hci0] 22.087762
        Num handles: 1
        Handle: 21
        Count: 1
> HCI Event: Vendor (0xff) plen 7                                                                                                   [hci0] 22.354831
        82 00 01 00 01 15 00                             .......         
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                      [hci0] 22.355759
        Status: Success (0x00)
        Handle: 21
        Reason: Remote User Terminated Connection (0x13)
@ Device Disconnected: 10:B7:F6:01:31:ED (0) reason 3

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-20 22:54               ` Artem Rakhov
@ 2014-08-21  6:42                 ` Artem Rakhov
  2014-08-21  8:38                   ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-21  6:42 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Marcel Holtmann, linux-bluetooth, gustavo

Looks like I found the problem.

Creation of all sockets and all the read/write operations are handled
in btio.c in BlueZ. It allows to set various options for sockets. One
of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
default it is equal to 30. In fact, no profile in BlueZ use this
option, and it is never equal to anything else. And create_io()
function in btio.c also does not use this. The only place 'defer'
option is passed to a kernel level is bt_io_listen() function:

if (confirm)
    setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
sizeof(opts.defer));

As far as I understand, BT_DEFER_SETUP is a kernel option which
enables Defer Setup feature for L2CAP channel. It is a binary flag,
and looks like it has nothing to do with timeout. And it makes no
sense to pass 30 as a value for binary flag.

So I don't see any connection between these two things. As a result,
we almost always turn on Defer Setup feature, which causes connection
problems with my speaker and potentially with other BT devices. My
suggestion is to completely remove 'defer' option from btio.c

Another question is: when and where do we actually need to enable this
Defer Setup feature?

Thanks,
Artem

On Wed, Aug 20, 2014 at 3:54 PM, Artem Rakhov <arakhov@google.com> wrote:
> Hello,
>
> I found the way to use avtest for testing incoming connections from
> the speaker. If anyone is interested: stopped bluetoothd, powered BT
> back to on, used "avtest --reject 0". Also had to change avtest to
> answer like source instead of sink, which is set by default.
>
> Incoming connections to avtest are always successful. And logs are
> very similar (attached). I think the main difference is that the
> bluetoothd requires authorization, while avtest does not.
>
> Thanks,
> Artem
>
> On Mon, Aug 18, 2014 at 12:11 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>> Hi Luiz,
>>
>> I have also tried kernel 3.14, it didn't help.
>> How can I use avinfo for test? Looks like it shows only basic
>> information for the device. And it works fine with the speaker.
>> I tried to use avtest: when I try to connect to the speaker,
>> everything seems to be working good. Is there any way to use it to
>> test incoming connections?
>>
>> Thanks,
>> Artem
>>
>> On Sun, Aug 10, 2014 at 12:32 AM, Luiz Augusto von Dentz
>> <luiz.dentz@gmail.com> wrote:
>>> Hi Artem,
>>>
>>> On Fri, Aug 8, 2014 at 10:32 AM, Artem Rakhov <arakhov@chromium.org> wrote:
>>>> Hi Marcel,
>>>>
>>>> Please find Packet Logger's btsnoop log in the attachment.
>>>>
>>>> So far I have 2 observations:
>>>> 1. Mac does not require any authorization (most likely it's not the cause)
>>>> 2. I found another BT speaker which works properly. At first, I'm
>>>> seeing the same behavior: speaker initiates connection, BlueZ sends
>>>> Configure Request (with no MTU), then speaker disconnects. But after
>>>> that the device tries to initiate connection for the second time, and
>>>> this time it is successful: after BlueZ sends Configure Request with
>>>> no MTU, speaker answers with another Configure Request (with some
>>>> MTU), and connection is established normally. Is it possible, that
>>>> BlueZ is doing something wrong, but then this new speaker tries
>>>> something else, while the old one does not?
>>>
>>> I could not find anything l2cap related in this logs, but I notice
>>> there a LE scanning ongoing perhaps you have should try disabling it
>>> with Disconnect method for now. Anyway A2DP code is not really
>>> involved with L2CAP connection setup so we would have to look at the
>>> kernel changes but I quick check doesn't show anything and you said
>>> you have tried with 3.10 so Im afraid this is only reproducible with
>>> some specific device.
>>>
>>> Btw, if you want to really isolate the problem you can try to connect
>>> using avinfo or l2test directly.
>>>
>>>
>>> --
>>> Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21  6:42                 ` Artem Rakhov
@ 2014-08-21  8:38                   ` Luiz Augusto von Dentz
  2014-08-21 13:33                     ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-08-21  8:38 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Marcel Holtmann, linux-bluetooth, Gustavo F. Padovan

Hi Artem,

On Thu, Aug 21, 2014 at 9:42 AM, Artem Rakhov <arakhov@chromium.org> wrote:
> Looks like I found the problem.
>
> Creation of all sockets and all the read/write operations are handled
> in btio.c in BlueZ. It allows to set various options for sockets. One
> of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
> default it is equal to 30. In fact, no profile in BlueZ use this
> option, and it is never equal to anything else. And create_io()
> function in btio.c also does not use this. The only place 'defer'
> option is passed to a kernel level is bt_io_listen() function:
>
> if (confirm)
>     setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
> sizeof(opts.defer));

Yep the use of this API is wrong, we either set or reset the flag but
there is no timeout involved, but this alone would not cause the
problem since the kernel ignore the actual value and just set the flag
properly:

if (opt) {
    set_bit(BT_SK_DEFER_SETUP, &bt_sk(sk)->flags);
    set_bit(FLAG_DEFER_SETUP, &chan->flags);
}

> As far as I understand, BT_DEFER_SETUP is a kernel option which
> enables Defer Setup feature for L2CAP channel. It is a binary flag,
> and looks like it has nothing to do with timeout. And it makes no
> sense to pass 30 as a value for binary flag.
>
> So I don't see any connection between these two things. As a result,
> we almost always turn on Defer Setup feature, which causes connection
> problems with my speaker and potentially with other BT devices. My
> suggestion is to completely remove 'defer' option from btio.c
>
> Another question is: when and where do we actually need to enable this
> Defer Setup feature?

Defer Setup is quite fundamental to be able to authorize connection
properly otherwise we would have to accept the connection upfront to
be able to identify who is connecting, L2CAP has the authorization
pending as response for this very reason and apparently your headset
cannot handle it properly:

< ACL Data TX: Handle 21 flags 0x00 dlen 16
                                                             [hci0]
22.030160
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)


But note that bluetoothd accepts the connection almost immediately in
the next frame (probably because the device is trusted):

< ACL Data TX: Handle 21 flags 0x00 dlen 16
                                                             [hci0]
22.030595
      L2CAP: Connection Response (0x03) ident 2 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)

This is part of the core specification, unfortunately it doesn't seems
that any test of the testing specification do actually test it, so
chances are that the headset could qualify just because PTS never send
authorization/connection pending status.


-- 
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21  8:38                   ` Luiz Augusto von Dentz
@ 2014-08-21 13:33                     ` Marcel Holtmann
  2014-08-21 13:53                       ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Marcel Holtmann @ 2014-08-21 13:33 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Artem Rakhov, linux-bluetooth, Gustavo F. Padovan

Hi Luiz,

>> Looks like I found the problem.
>> 
>> Creation of all sockets and all the read/write operations are handled
>> in btio.c in BlueZ. It allows to set various options for sockets. One
>> of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
>> default it is equal to 30. In fact, no profile in BlueZ use this
>> option, and it is never equal to anything else. And create_io()
>> function in btio.c also does not use this. The only place 'defer'
>> option is passed to a kernel level is bt_io_listen() function:
>> 
>> if (confirm)
>>    setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
>> sizeof(opts.defer));
> 
> Yep the use of this API is wrong, we either set or reset the flag but
> there is no timeout involved, but this alone would not cause the
> problem since the kernel ignore the actual value and just set the flag
> properly:
> 
> if (opt) {
>    set_bit(BT_SK_DEFER_SETUP, &bt_sk(sk)->flags);
>    set_bit(FLAG_DEFER_SETUP, &chan->flags);
> }
> 
>> As far as I understand, BT_DEFER_SETUP is a kernel option which
>> enables Defer Setup feature for L2CAP channel. It is a binary flag,
>> and looks like it has nothing to do with timeout. And it makes no
>> sense to pass 30 as a value for binary flag.
>> 
>> So I don't see any connection between these two things. As a result,
>> we almost always turn on Defer Setup feature, which causes connection
>> problems with my speaker and potentially with other BT devices. My
>> suggestion is to completely remove 'defer' option from btio.c
>> 
>> Another question is: when and where do we actually need to enable this
>> Defer Setup feature?
> 
> Defer Setup is quite fundamental to be able to authorize connection
> properly otherwise we would have to accept the connection upfront to
> be able to identify who is connecting, L2CAP has the authorization
> pending as response for this very reason and apparently your headset
> cannot handle it properly:
> 
> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>                                                             [hci0]
> 22.030160
>      L2CAP: Connection Response (0x03) ident 2 len 8
>        Destination CID: 64
>        Source CID: 65
>        Result: Connection pending (0x0001)
>        Status: Authorization pending (0x0002)
> 
> 
> But note that bluetoothd accepts the connection almost immediately in
> the next frame (probably because the device is trusted):
> 
> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>                                                             [hci0]
> 22.030595
>      L2CAP: Connection Response (0x03) ident 2 len 8
>        Destination CID: 64
>        Source CID: 65
>        Result: Connection successful (0x0000)
>        Status: No further information available (0x0000)
> 
> This is part of the core specification, unfortunately it doesn't seems
> that any test of the testing specification do actually test it, so
> chances are that the headset could qualify just because PTS never send
> authorization/connection pending status.

it is basic L2CAP behavior since Bluetooth 1.0b specification. It always worked like this. And many many devices are using it exactly like this. It gets ever funnier when the Bluetooth stack puts the Connection Pending and Connection Successful into the same ACL frame.

Is the conclusion that the headset can not handle L2CAP Connection Pending status? Just for my entertainment, can you run hcitool info against that headset and see what manufacturer it is. I am really curious on who got this wrong. Which model is this exactly?

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 13:33                     ` Marcel Holtmann
@ 2014-08-21 13:53                       ` Luiz Augusto von Dentz
  2014-08-21 14:28                         ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-08-21 13:53 UTC (permalink / raw)
  To: Marcel Holtmann; +Cc: Artem Rakhov, linux-bluetooth, Gustavo F. Padovan

Hi Marcel,

On Thu, Aug 21, 2014 at 4:33 PM, Marcel Holtmann <marcel@holtmann.org> wrot=
e:
> Hi Luiz,
>
>>> Looks like I found the problem.
>>>
>>> Creation of all sockets and all the read/write operations are handled
>>> in btio.c in BlueZ. It allows to set various options for sockets. One
>>> of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
>>> default it is equal to 30. In fact, no profile in BlueZ use this
>>> option, and it is never equal to anything else. And create_io()
>>> function in btio.c also does not use this. The only place 'defer'
>>> option is passed to a kernel level is bt_io_listen() function:
>>>
>>> if (confirm)
>>>    setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
>>> sizeof(opts.defer));
>>
>> Yep the use of this API is wrong, we either set or reset the flag but
>> there is no timeout involved, but this alone would not cause the
>> problem since the kernel ignore the actual value and just set the flag
>> properly:
>>
>> if (opt) {
>>    set_bit(BT_SK_DEFER_SETUP, &bt_sk(sk)->flags);
>>    set_bit(FLAG_DEFER_SETUP, &chan->flags);
>> }
>>
>>> As far as I understand, BT_DEFER_SETUP is a kernel option which
>>> enables Defer Setup feature for L2CAP channel. It is a binary flag,
>>> and looks like it has nothing to do with timeout. And it makes no
>>> sense to pass 30 as a value for binary flag.
>>>
>>> So I don't see any connection between these two things. As a result,
>>> we almost always turn on Defer Setup feature, which causes connection
>>> problems with my speaker and potentially with other BT devices. My
>>> suggestion is to completely remove 'defer' option from btio.c
>>>
>>> Another question is: when and where do we actually need to enable this
>>> Defer Setup feature?
>>
>> Defer Setup is quite fundamental to be able to authorize connection
>> properly otherwise we would have to accept the connection upfront to
>> be able to identify who is connecting, L2CAP has the authorization
>> pending as response for this very reason and apparently your headset
>> cannot handle it properly:
>>
>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>                                                             [hci0]
>> 22.030160
>>      L2CAP: Connection Response (0x03) ident 2 len 8
>>        Destination CID: 64
>>        Source CID: 65
>>        Result: Connection pending (0x0001)
>>        Status: Authorization pending (0x0002)
>>
>>
>> But note that bluetoothd accepts the connection almost immediately in
>> the next frame (probably because the device is trusted):
>>
>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>                                                             [hci0]
>> 22.030595
>>      L2CAP: Connection Response (0x03) ident 2 len 8
>>        Destination CID: 64
>>        Source CID: 65
>>        Result: Connection successful (0x0000)
>>        Status: No further information available (0x0000)
>>
>> This is part of the core specification, unfortunately it doesn't seems
>> that any test of the testing specification do actually test it, so
>> chances are that the headset could qualify just because PTS never send
>> authorization/connection pending status.
>
> it is basic L2CAP behavior since Bluetooth 1.0b specification. It always =
worked like this. And many many devices are using it exactly like this. It =
gets ever funnier when the Bluetooth stack puts the Connection Pending and =
Connection Successful into the same ACL frame.

I suspected it is a very basic since iirc we introduce Defer Setup
long time ago and never run into this specific problem. Now if that
actually gets in the same ACL frame this could cause a stack to ignore
the subsequent response which perhaps is the problem here.

> Is the conclusion that the headset can not handle L2CAP Connection Pendin=
g status? Just for my entertainment, can you run hcitool info against that =
headset and see what manufacturer it is. I am really curious on who got thi=
s wrong. Which model is this exactly?

No idea, perhaps Artem is willing to disclose the model, from the logs
it seems it hangs if authorization pending is sent and then at some
point it probably timeout and disconnects.

We do have some logic to handle devices that connect but do not
configure any stream, perhaps we could fit this in the same category
and if they disconnect while authorizing we attempt to reconnect, it
is probably to much of a hack but if the device is really popular then
perhaps it is worth trying.


--=20
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 13:53                       ` Luiz Augusto von Dentz
@ 2014-08-21 14:28                         ` Marcel Holtmann
  2014-08-21 19:16                           ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Marcel Holtmann @ 2014-08-21 14:28 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Artem Rakhov, linux-bluetooth, Gustavo F. Padovan

Hi Luiz,

>>>> Looks like I found the problem.
>>>> 
>>>> Creation of all sockets and all the read/write operations are handled
>>>> in btio.c in BlueZ. It allows to set various options for sockets. One
>>>> of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
>>>> default it is equal to 30. In fact, no profile in BlueZ use this
>>>> option, and it is never equal to anything else. And create_io()
>>>> function in btio.c also does not use this. The only place 'defer'
>>>> option is passed to a kernel level is bt_io_listen() function:
>>>> 
>>>> if (confirm)
>>>>   setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
>>>> sizeof(opts.defer));
>>> 
>>> Yep the use of this API is wrong, we either set or reset the flag but
>>> there is no timeout involved, but this alone would not cause the
>>> problem since the kernel ignore the actual value and just set the flag
>>> properly:
>>> 
>>> if (opt) {
>>>   set_bit(BT_SK_DEFER_SETUP, &bt_sk(sk)->flags);
>>>   set_bit(FLAG_DEFER_SETUP, &chan->flags);
>>> }
>>> 
>>>> As far as I understand, BT_DEFER_SETUP is a kernel option which
>>>> enables Defer Setup feature for L2CAP channel. It is a binary flag,
>>>> and looks like it has nothing to do with timeout. And it makes no
>>>> sense to pass 30 as a value for binary flag.
>>>> 
>>>> So I don't see any connection between these two things. As a result,
>>>> we almost always turn on Defer Setup feature, which causes connection
>>>> problems with my speaker and potentially with other BT devices. My
>>>> suggestion is to completely remove 'defer' option from btio.c
>>>> 
>>>> Another question is: when and where do we actually need to enable this
>>>> Defer Setup feature?
>>> 
>>> Defer Setup is quite fundamental to be able to authorize connection
>>> properly otherwise we would have to accept the connection upfront to
>>> be able to identify who is connecting, L2CAP has the authorization
>>> pending as response for this very reason and apparently your headset
>>> cannot handle it properly:
>>> 
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>                                                            [hci0]
>>> 22.030160
>>>     L2CAP: Connection Response (0x03) ident 2 len 8
>>>       Destination CID: 64
>>>       Source CID: 65
>>>       Result: Connection pending (0x0001)
>>>       Status: Authorization pending (0x0002)
>>> 
>>> 
>>> But note that bluetoothd accepts the connection almost immediately in
>>> the next frame (probably because the device is trusted):
>>> 
>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>                                                            [hci0]
>>> 22.030595
>>>     L2CAP: Connection Response (0x03) ident 2 len 8
>>>       Destination CID: 64
>>>       Source CID: 65
>>>       Result: Connection successful (0x0000)
>>>       Status: No further information available (0x0000)
>>> 
>>> This is part of the core specification, unfortunately it doesn't seems
>>> that any test of the testing specification do actually test it, so
>>> chances are that the headset could qualify just because PTS never send
>>> authorization/connection pending status.
>> 
>> it is basic L2CAP behavior since Bluetooth 1.0b specification. It always worked like this. And many many devices are using it exactly like this. It gets ever funnier when the Bluetooth stack puts the Connection Pending and Connection Successful into the same ACL frame.
> 
> I suspected it is a very basic since iirc we introduce Defer Setup
> long time ago and never run into this specific problem. Now if that
> actually gets in the same ACL frame this could cause a stack to ignore
> the subsequent response which perhaps is the problem here.

I don't think so since there is a test case for this. Question is just if the remote device can really handle the Connection Pending correctly.

>> Is the conclusion that the headset can not handle L2CAP Connection Pending status? Just for my entertainment, can you run hcitool info against that headset and see what manufacturer it is. I am really curious on who got this wrong. Which model is this exactly?
> 
> No idea, perhaps Artem is willing to disclose the model, from the logs
> it seems it hangs if authorization pending is sent and then at some
> point it probably timeout and disconnects.
> 
> We do have some logic to handle devices that connect but do not
> configure any stream, perhaps we could fit this in the same category
> and if they disconnect while authorizing we attempt to reconnect, it
> is probably to much of a hack but if the device is really popular then
> perhaps it is worth trying.

That is something that could work. Since I rather not change the kernel logic to handle and accept() plus a read() right after it with a special delay turning this into a Connection Succesful.

It might be also worthwhile to check if there is a firmware update for this speaker available. I can imagine that this causes issues for a few stacks.

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 14:28                         ` Marcel Holtmann
@ 2014-08-21 19:16                           ` Artem Rakhov
  2014-08-21 20:24                             ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-21 19:16 UTC (permalink / raw)
  To: Marcel Holtmann
  Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

Here is hcitool info:

BD Address:  10:B7:F6:01:31:ED
Device Name: Monster Clarity
LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
Manufacturer: Cambridge Silicon Radio (10)
Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
<3-slot packets>
Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83

Label also says Precision Micro Bluetooth Speaker 100.

Thanks,
Artem

On Thu, Aug 21, 2014 at 7:28 AM, Marcel Holtmann <marcel@holtmann.org> wrot=
e:
> Hi Luiz,
>
>>>>> Looks like I found the problem.
>>>>>
>>>>> Creation of all sockets and all the read/write operations are handled
>>>>> in btio.c in BlueZ. It allows to set various options for sockets. One
>>>>> of these options is called 'defer' (BT_IO_OPT_DEFER_TIMEOUT). By
>>>>> default it is equal to 30. In fact, no profile in BlueZ use this
>>>>> option, and it is never equal to anything else. And create_io()
>>>>> function in btio.c also does not use this. The only place 'defer'
>>>>> option is passed to a kernel level is bt_io_listen() function:
>>>>>
>>>>> if (confirm)
>>>>>   setsockopt(sock, SOL_BLUETOOTH, BT_DEFER_SETUP, &opts.defer,
>>>>> sizeof(opts.defer));
>>>>
>>>> Yep the use of this API is wrong, we either set or reset the flag but
>>>> there is no timeout involved, but this alone would not cause the
>>>> problem since the kernel ignore the actual value and just set the flag
>>>> properly:
>>>>
>>>> if (opt) {
>>>>   set_bit(BT_SK_DEFER_SETUP, &bt_sk(sk)->flags);
>>>>   set_bit(FLAG_DEFER_SETUP, &chan->flags);
>>>> }
>>>>
>>>>> As far as I understand, BT_DEFER_SETUP is a kernel option which
>>>>> enables Defer Setup feature for L2CAP channel. It is a binary flag,
>>>>> and looks like it has nothing to do with timeout. And it makes no
>>>>> sense to pass 30 as a value for binary flag.
>>>>>
>>>>> So I don't see any connection between these two things. As a result,
>>>>> we almost always turn on Defer Setup feature, which causes connection
>>>>> problems with my speaker and potentially with other BT devices. My
>>>>> suggestion is to completely remove 'defer' option from btio.c
>>>>>
>>>>> Another question is: when and where do we actually need to enable thi=
s
>>>>> Defer Setup feature?
>>>>
>>>> Defer Setup is quite fundamental to be able to authorize connection
>>>> properly otherwise we would have to accept the connection upfront to
>>>> be able to identify who is connecting, L2CAP has the authorization
>>>> pending as response for this very reason and apparently your headset
>>>> cannot handle it properly:
>>>>
>>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>>                                                            [hci0]
>>>> 22.030160
>>>>     L2CAP: Connection Response (0x03) ident 2 len 8
>>>>       Destination CID: 64
>>>>       Source CID: 65
>>>>       Result: Connection pending (0x0001)
>>>>       Status: Authorization pending (0x0002)
>>>>
>>>>
>>>> But note that bluetoothd accepts the connection almost immediately in
>>>> the next frame (probably because the device is trusted):
>>>>
>>>> < ACL Data TX: Handle 21 flags 0x00 dlen 16
>>>>                                                            [hci0]
>>>> 22.030595
>>>>     L2CAP: Connection Response (0x03) ident 2 len 8
>>>>       Destination CID: 64
>>>>       Source CID: 65
>>>>       Result: Connection successful (0x0000)
>>>>       Status: No further information available (0x0000)
>>>>
>>>> This is part of the core specification, unfortunately it doesn't seems
>>>> that any test of the testing specification do actually test it, so
>>>> chances are that the headset could qualify just because PTS never send
>>>> authorization/connection pending status.
>>>
>>> it is basic L2CAP behavior since Bluetooth 1.0b specification. It alway=
s worked like this. And many many devices are using it exactly like this. I=
t gets ever funnier when the Bluetooth stack puts the Connection Pending an=
d Connection Successful into the same ACL frame.
>>
>> I suspected it is a very basic since iirc we introduce Defer Setup
>> long time ago and never run into this specific problem. Now if that
>> actually gets in the same ACL frame this could cause a stack to ignore
>> the subsequent response which perhaps is the problem here.
>
> I don't think so since there is a test case for this. Question is just if=
 the remote device can really handle the Connection Pending correctly.
>
>>> Is the conclusion that the headset can not handle L2CAP Connection Pend=
ing status? Just for my entertainment, can you run hcitool info against tha=
t headset and see what manufacturer it is. I am really curious on who got t=
his wrong. Which model is this exactly?
>>
>> No idea, perhaps Artem is willing to disclose the model, from the logs
>> it seems it hangs if authorization pending is sent and then at some
>> point it probably timeout and disconnects.
>>
>> We do have some logic to handle devices that connect but do not
>> configure any stream, perhaps we could fit this in the same category
>> and if they disconnect while authorizing we attempt to reconnect, it
>> is probably to much of a hack but if the device is really popular then
>> perhaps it is worth trying.
>
> That is something that could work. Since I rather not change the kernel l=
ogic to handle and accept() plus a read() right after it with a special del=
ay turning this into a Connection Succesful.
>
> It might be also worthwhile to check if there is a firmware update for th=
is speaker available. I can imagine that this causes issues for a few stack=
s.
>
> Regards
>
> Marcel
>

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 19:16                           ` Artem Rakhov
@ 2014-08-21 20:24                             ` Marcel Holtmann
  2014-08-21 21:31                               ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Marcel Holtmann @ 2014-08-21 20:24 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

Hi Artem,

please do not top post on this mailing list. It does break the reading thread.

> Here is hcitool info:
> 
> BD Address:  10:B7:F6:01:31:ED
> Device Name: Monster Clarity
> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
> Manufacturer: Cambridge Silicon Radio (10)
> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
> <3-slot packets>
> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
> 
> Label also says Precision Micro Bluetooth Speaker 100.

normally all CSR based solutions should just work. Maybe this is just a bad firmware. Are you sure that Connection Pending is really causing the observed problem. It sounds strange to hit that on a CSR based speaker.

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 20:24                             ` Marcel Holtmann
@ 2014-08-21 21:31                               ` Artem Rakhov
  2014-08-27  1:11                                 ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-21 21:31 UTC (permalink / raw)
  To: Marcel Holtmann
  Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

> Hi Artem,
>
> please do not top post on this mailing list. It does break the reading thread.
>
>> Here is hcitool info:
>>
>> BD Address:  10:B7:F6:01:31:ED
>> Device Name: Monster Clarity
>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>> Manufacturer: Cambridge Silicon Radio (10)
>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>> <3-slot packets>
>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>
>> Label also says Precision Micro Bluetooth Speaker 100.
>
> normally all CSR based solutions should just work. Maybe this is just a bad firmware. Are you sure that Connection Pending is really causing the observed problem. It sounds strange to hit that on a CSR based speaker.
>
> Regards
>
> Marcel
>

I compared the logs from avtest and bluetoothd (attached earlier in
this thread). I think the only difference that could matter is this
Authorization Pending response.

Thanks,
Artem

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-21 21:31                               ` Artem Rakhov
@ 2014-08-27  1:11                                 ` Artem Rakhov
  2014-08-27  2:08                                   ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-27  1:11 UTC (permalink / raw)
  To: Marcel Holtmann
  Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

On Thu, Aug 21, 2014 at 2:31 PM, Artem Rakhov <arakhov@chromium.org> wrote:
>> Hi Artem,
>>
>> please do not top post on this mailing list. It does break the reading thread.
>>
>>> Here is hcitool info:
>>>
>>> BD Address:  10:B7:F6:01:31:ED
>>> Device Name: Monster Clarity
>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>> Manufacturer: Cambridge Silicon Radio (10)
>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>> <3-slot packets>
>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>
>>> Label also says Precision Micro Bluetooth Speaker 100.
>>
>> normally all CSR based solutions should just work. Maybe this is just a bad firmware. Are you sure that Connection Pending is really causing the observed problem. It sounds strange to hit that on a CSR based speaker.
>>
>> Regards
>>
>> Marcel
>>
>
> I compared the logs from avtest and bluetoothd (attached earlier in
> this thread). I think the only difference that could matter is this
> Authorization Pending response.
>
> Thanks,
> Artem

Hi Marcel,

I've tested several devices with and without Defer Setup feature enabled.

Here is a list of devices, which successfully initiate A2DP
connection, not depending on Defer Setup:
Creative WP-350 Headset
MiiKey Rythm
JBL Micro Wireless
HMDX Rave
Plantronics BBfit
Bose SoundLink Mobile speaker II
SOL Tracks Air
Sony MDR-1RBT

Here is a list of devices, which fail to initiate A2DP connection with
Defer Setup enabled, but work fine when Defer Setup is disabled:
Monster Clarity HD
Motorola S9-HD
Sennheiser PX210
2010 Toyota Prius

There are no devices, which are working with Defer Setup, and not
working without Defer Setup. So I didn't see any regression.

As a result, 4 out of 12 devices do not connect as expected with Defer
Setup enabled. I think we should consider disabling Defer Setup by
default, at least for audio.

Thanks,
Artem

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-27  1:11                                 ` Artem Rakhov
@ 2014-08-27  2:08                                   ` Marcel Holtmann
  2014-08-27  6:33                                     ` Artem Rakhov
  0 siblings, 1 reply; 25+ messages in thread
From: Marcel Holtmann @ 2014-08-27  2:08 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

Hi Artem,

>>> please do not top post on this mailing list. It does break the reading thread.
>>> 
>>>> Here is hcitool info:
>>>> 
>>>> BD Address:  10:B7:F6:01:31:ED
>>>> Device Name: Monster Clarity
>>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>>> Manufacturer: Cambridge Silicon Radio (10)
>>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>>> <3-slot packets>
>>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>> 
>>>> Label also says Precision Micro Bluetooth Speaker 100.
>>> 
>>> normally all CSR based solutions should just work. Maybe this is just a bad firmware. Are you sure that Connection Pending is really causing the observed problem. It sounds strange to hit that on a CSR based speaker.
>> 
>> I compared the logs from avtest and bluetoothd (attached earlier in
>> this thread). I think the only difference that could matter is this
>> Authorization Pending response.
> 
> I've tested several devices with and without Defer Setup feature enabled.
> 
> Here is a list of devices, which successfully initiate A2DP
> connection, not depending on Defer Setup:
> Creative WP-350 Headset
> MiiKey Rythm
> JBL Micro Wireless
> HMDX Rave
> Plantronics BBfit
> Bose SoundLink Mobile speaker II
> SOL Tracks Air
> Sony MDR-1RBT
> 
> Here is a list of devices, which fail to initiate A2DP connection with
> Defer Setup enabled, but work fine when Defer Setup is disabled:
> Monster Clarity HD
> Motorola S9-HD
> Sennheiser PX210
> 2010 Toyota Prius

are all of these CSR based devices? If so then it sounds like a batch of broken CSR firmware. If not, then the L2CAP test cases might better be extended to have a test case for this. It is dangerous if such a fundamental Bluetooth 1.1 feature is not working correctly.

> There are no devices, which are working with Defer Setup, and not
> working without Defer Setup. So I didn't see any regression.
> 
> As a result, 4 out of 12 devices do not connect as expected with Defer
> Setup enabled. I think we should consider disabling Defer Setup by
> default, at least for audio.

I all cases this is the A2DP signaling channel that causes the problem? It is not the media channel that is required for streaming?

Our real problem is that we need Defer Setup to be able to cleanly reject connections from devices that we do not know and do not want to talk to use. Especially if they are just not authorized to do so.

Maybe we should use the proposal that Luiz had and just disconnect after a timeout and try to establish the connection from our side. That might actually be useful as a workaround. An alternative option is that we delay the connection pending message for some time and give userspace the chance to respond with either read() or close(). That way we would send the correct answer. However that timeout can only be really short since we need to keep the L2CAP signaling working correctly. So it would only work for cases where the daemon has all information to make a decision. If it asks the user, then this is off limits.

That said, Linux 3.17 is allowing us to use a whitelist for BR/EDR that might be useful to mitigate this behavior as well. Unknown devices would be blocked on the ACL level already.

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-27  2:08                                   ` Marcel Holtmann
@ 2014-08-27  6:33                                     ` Artem Rakhov
  2014-08-27 18:34                                       ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Artem Rakhov @ 2014-08-27  6:33 UTC (permalink / raw)
  To: Marcel Holtmann
  Cc: Luiz Augusto von Dentz, linux-bluetooth, Gustavo F. Padovan

On Tue, Aug 26, 2014 at 7:08 PM, Marcel Holtmann <marcel@holtmann.org> wrot=
e:
> Hi Artem,
>
>>>> please do not top post on this mailing list. It does break the reading=
 thread.
>>>>
>>>>> Here is hcitool info:
>>>>>
>>>>> BD Address:  10:B7:F6:01:31:ED
>>>>> Device Name: Monster Clarity
>>>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>>>> Manufacturer: Cambridge Silicon Radio (10)
>>>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>>>> <3-slot packets>
>>>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>>>
>>>>> Label also says Precision Micro Bluetooth Speaker 100.
>>>>
>>>> normally all CSR based solutions should just work. Maybe this is just =
a bad firmware. Are you sure that Connection Pending is really causing the =
observed problem. It sounds strange to hit that on a CSR based speaker.
>>>
>>> I compared the logs from avtest and bluetoothd (attached earlier in
>>> this thread). I think the only difference that could matter is this
>>> Authorization Pending response.
>>
>> I've tested several devices with and without Defer Setup feature enabled=
.
>>
>> Here is a list of devices, which successfully initiate A2DP
>> connection, not depending on Defer Setup:
>> Creative WP-350 Headset
>> MiiKey Rythm
>> JBL Micro Wireless
>> HMDX Rave
>> Plantronics BBfit
>> Bose SoundLink Mobile speaker II
>> SOL Tracks Air
>> Sony MDR-1RBT
>>
>> Here is a list of devices, which fail to initiate A2DP connection with
>> Defer Setup enabled, but work fine when Defer Setup is disabled:
>> Monster Clarity HD
>> Motorola S9-HD
>> Sennheiser PX210
>> 2010 Toyota Prius
>
> are all of these CSR based devices? If so then it sounds like a batch of =
broken CSR firmware. If not, then the L2CAP test cases might better be exte=
nded to have a test case for this. It is dangerous if such a fundamental Bl=
uetooth 1.1 feature is not working correctly.

Yes, all these devices are CSR-based.

>> There are no devices, which are working with Defer Setup, and not
>> working without Defer Setup. So I didn't see any regression.
>>
>> As a result, 4 out of 12 devices do not connect as expected with Defer
>> Setup enabled. I think we should consider disabling Defer Setup by
>> default, at least for audio.
>
> I all cases this is the A2DP signaling channel that causes the problem? I=
t is not the media channel that is required for streaming?

Yes, exactly same scenario. The very first connection fails from
speaker to source, which goes to AVDTP (PSM 25).

> Our real problem is that we need Defer Setup to be able to cleanly reject=
 connections from devices that we do not know and do not want to talk to us=
e. Especially if they are just not authorized to do so.
>
> Maybe we should use the proposal that Luiz had and just disconnect after =
a timeout and try to establish the connection from our side. That might act=
ually be useful as a workaround. An alternative option is that we delay the=
 connection pending message for some time and give userspace the chance to =
respond with either read() or close(). That way we would send the correct a=
nswer. However that timeout can only be really short since we need to keep =
the L2CAP signaling working correctly. So it would only work for cases wher=
e the daemon has all information to make a decision. If it asks the user, t=
hen this is off limits.
>
> That said, Linux 3.17 is allowing us to use a whitelist for BR/EDR that m=
ight be useful to mitigate this behavior as well. Unknown devices would be =
blocked on the ACL level already.
>
> Regards
>
> Marcel
>

Thanks,
Artem

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-27  6:33                                     ` Artem Rakhov
@ 2014-08-27 18:34                                       ` Luiz Augusto von Dentz
  2014-08-28 11:19                                         ` Luiz Augusto von Dentz
  0 siblings, 1 reply; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-08-27 18:34 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Marcel Holtmann, linux-bluetooth, Gustavo F. Padovan

Hi Artem, Marcel,

On Wed, Aug 27, 2014 at 9:33 AM, Artem Rakhov <arakhov@chromium.org> wrote:
> On Tue, Aug 26, 2014 at 7:08 PM, Marcel Holtmann <marcel@holtmann.org> wr=
ote:
>> Hi Artem,
>>
>>>>> please do not top post on this mailing list. It does break the readin=
g thread.
>>>>>
>>>>>> Here is hcitool info:
>>>>>>
>>>>>> BD Address:  10:B7:F6:01:31:ED
>>>>>> Device Name: Monster Clarity
>>>>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>>>>> Manufacturer: Cambridge Silicon Radio (10)
>>>>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>>>>> <3-slot packets>
>>>>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>>>>
>>>>>> Label also says Precision Micro Bluetooth Speaker 100.
>>>>>
>>>>> normally all CSR based solutions should just work. Maybe this is just=
 a bad firmware. Are you sure that Connection Pending is really causing the=
 observed problem. It sounds strange to hit that on a CSR based speaker.
>>>>
>>>> I compared the logs from avtest and bluetoothd (attached earlier in
>>>> this thread). I think the only difference that could matter is this
>>>> Authorization Pending response.
>>>
>>> I've tested several devices with and without Defer Setup feature enable=
d.
>>>
>>> Here is a list of devices, which successfully initiate A2DP
>>> connection, not depending on Defer Setup:
>>> Creative WP-350 Headset
>>> MiiKey Rythm
>>> JBL Micro Wireless
>>> HMDX Rave
>>> Plantronics BBfit
>>> Bose SoundLink Mobile speaker II
>>> SOL Tracks Air
>>> Sony MDR-1RBT
>>>
>>> Here is a list of devices, which fail to initiate A2DP connection with
>>> Defer Setup enabled, but work fine when Defer Setup is disabled:
>>> Monster Clarity HD
>>> Motorola S9-HD
>>> Sennheiser PX210
>>> 2010 Toyota Prius
>>
>> are all of these CSR based devices? If so then it sounds like a batch of=
 broken CSR firmware. If not, then the L2CAP test cases might better be ext=
ended to have a test case for this. It is dangerous if such a fundamental B=
luetooth 1.1 feature is not working correctly.
>
> Yes, all these devices are CSR-based.

Well I have access to none of those which is kind nice.

>>> There are no devices, which are working with Defer Setup, and not
>>> working without Defer Setup. So I didn't see any regression.
>>>
>>> As a result, 4 out of 12 devices do not connect as expected with Defer
>>> Setup enabled. I think we should consider disabling Defer Setup by
>>> default, at least for audio.
>>
>> I all cases this is the A2DP signaling channel that causes the problem? =
It is not the media channel that is required for streaming?
>
> Yes, exactly same scenario. The very first connection fails from
> speaker to source, which goes to AVDTP (PSM 25).

There are some other things to experiment, there seems to be possible
to use ERTM nowadays, for signalling only, and while this does not
exactly change in any way how we use authorization pending response it
perhaps make a difference in terms of timing, if we are lucky,
otherwise we can go with whitelist and retry.

>> Our real problem is that we need Defer Setup to be able to cleanly rejec=
t connections from devices that we do not know and do not want to talk to u=
se. Especially if they are just not authorized to do so.
>>
>> Maybe we should use the proposal that Luiz had and just disconnect after=
 a timeout and try to establish the connection from our side. That might ac=
tually be useful as a workaround. An alternative option is that we delay th=
e connection pending message for some time and give userspace the chance to=
 respond with either read() or close(). That way we would send the correct =
answer. However that timeout can only be really short since we need to keep=
 the L2CAP signaling working correctly. So it would only work for cases whe=
re the daemon has all information to make a decision. If it asks the user, =
then this is off limits.
>>
>> That said, Linux 3.17 is allowing us to use a whitelist for BR/EDR that =
might be useful to mitigate this behavior as well. Unknown devices would be=
 blocked on the ACL level already.

If whitelist for classic is to be based on the trusted list, which I
assume it should be, then the kernel could accept the connection right
away but then we need some mechanism to query if the whitelist has
taken effect or maybe it is fine already since bt_io_accept does the
following:

if (!(pfd.revents & POLLOUT)) {
    if (read(sock, &c, 1) < 0) {
        ERROR_FAILED(err, "read", errno);
        return FALSE;
    }
}

So POLLOUT seems to be for checking if the socket has been accepted
already, in case we have a older kernel we can only retry if
authorization succeeds but that will probably only happen if the
device happens to be trusted otherwise it will trigger the agent for
user to authorize and it more likely the device will disconnect before
the user can react cancelling the authorization.


--=20
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-27 18:34                                       ` Luiz Augusto von Dentz
@ 2014-08-28 11:19                                         ` Luiz Augusto von Dentz
  2014-08-28 20:37                                           ` Marcel Holtmann
  0 siblings, 1 reply; 25+ messages in thread
From: Luiz Augusto von Dentz @ 2014-08-28 11:19 UTC (permalink / raw)
  To: Artem Rakhov; +Cc: Marcel Holtmann, linux-bluetooth

Hi Marcel,

On Wed, Aug 27, 2014 at 9:34 PM, Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
> Hi Artem, Marcel,
>
> On Wed, Aug 27, 2014 at 9:33 AM, Artem Rakhov <arakhov@chromium.org> wrot=
e:
>> On Tue, Aug 26, 2014 at 7:08 PM, Marcel Holtmann <marcel@holtmann.org> w=
rote:
>>> Hi Artem,
>>>
>>>>>> please do not top post on this mailing list. It does break the readi=
ng thread.
>>>>>>
>>>>>>> Here is hcitool info:
>>>>>>>
>>>>>>> BD Address:  10:B7:F6:01:31:ED
>>>>>>> Device Name: Monster Clarity
>>>>>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>>>>>> Manufacturer: Cambridge Silicon Radio (10)
>>>>>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>>>>>> <3-slot packets>
>>>>>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>>>>>
>>>>>>> Label also says Precision Micro Bluetooth Speaker 100.
>>>>>>
>>>>>> normally all CSR based solutions should just work. Maybe this is jus=
t a bad firmware. Are you sure that Connection Pending is really causing th=
e observed problem. It sounds strange to hit that on a CSR based speaker.
>>>>>
>>>>> I compared the logs from avtest and bluetoothd (attached earlier in
>>>>> this thread). I think the only difference that could matter is this
>>>>> Authorization Pending response.
>>>>
>>>> I've tested several devices with and without Defer Setup feature enabl=
ed.
>>>>
>>>> Here is a list of devices, which successfully initiate A2DP
>>>> connection, not depending on Defer Setup:
>>>> Creative WP-350 Headset
>>>> MiiKey Rythm
>>>> JBL Micro Wireless
>>>> HMDX Rave
>>>> Plantronics BBfit
>>>> Bose SoundLink Mobile speaker II
>>>> SOL Tracks Air
>>>> Sony MDR-1RBT
>>>>
>>>> Here is a list of devices, which fail to initiate A2DP connection with
>>>> Defer Setup enabled, but work fine when Defer Setup is disabled:
>>>> Monster Clarity HD
>>>> Motorola S9-HD
>>>> Sennheiser PX210
>>>> 2010 Toyota Prius
>>>
>>> are all of these CSR based devices? If so then it sounds like a batch o=
f broken CSR firmware. If not, then the L2CAP test cases might better be ex=
tended to have a test case for this. It is dangerous if such a fundamental =
Bluetooth 1.1 feature is not working correctly.
>>
>> Yes, all these devices are CSR-based.
>
> Well I have access to none of those which is kind nice.
>
>>>> There are no devices, which are working with Defer Setup, and not
>>>> working without Defer Setup. So I didn't see any regression.
>>>>
>>>> As a result, 4 out of 12 devices do not connect as expected with Defer
>>>> Setup enabled. I think we should consider disabling Defer Setup by
>>>> default, at least for audio.
>>>
>>> I all cases this is the A2DP signaling channel that causes the problem?=
 It is not the media channel that is required for streaming?
>>
>> Yes, exactly same scenario. The very first connection fails from
>> speaker to source, which goes to AVDTP (PSM 25).
>
> There are some other things to experiment, there seems to be possible
> to use ERTM nowadays, for signalling only, and while this does not
> exactly change in any way how we use authorization pending response it
> perhaps make a difference in terms of timing, if we are lucky,
> otherwise we can go with whitelist and retry.
>
>>> Our real problem is that we need Defer Setup to be able to cleanly reje=
ct connections from devices that we do not know and do not want to talk to =
use. Especially if they are just not authorized to do so.
>>>
>>> Maybe we should use the proposal that Luiz had and just disconnect afte=
r a timeout and try to establish the connection from our side. That might a=
ctually be useful as a workaround. An alternative option is that we delay t=
he connection pending message for some time and give userspace the chance t=
o respond with either read() or close(). That way we would send the correct=
 answer. However that timeout can only be really short since we need to kee=
p the L2CAP signaling working correctly. So it would only work for cases wh=
ere the daemon has all information to make a decision. If it asks the user,=
 then this is off limits.
>>>
>>> That said, Linux 3.17 is allowing us to use a whitelist for BR/EDR that=
 might be useful to mitigate this behavior as well. Unknown devices would b=
e blocked on the ACL level already.
>
> If whitelist for classic is to be based on the trusted list, which I
> assume it should be, then the kernel could accept the connection right
> away but then we need some mechanism to query if the whitelist has
> taken effect or maybe it is fine already since bt_io_accept does the
> following:
>
> if (!(pfd.revents & POLLOUT)) {
>     if (read(sock, &c, 1) < 0) {
>         ERROR_FAILED(err, "read", errno);
>         return FALSE;
>     }
> }
>
> So POLLOUT seems to be for checking if the socket has been accepted
> already, in case we have a older kernel we can only retry if
> authorization succeeds but that will probably only happen if the
> device happens to be trusted otherwise it will trigger the agent for
> user to authorize and it more likely the device will disconnect before
> the user can react cancelling the authorization.

I was checking how whitelist actually works currently and in fact it
is not based on trusted list but on persistency, but we could use
action 2 for BREDR once they are marked as trusted but perhaps you
guys had something else in mind while designing Add Device command. If
we can't really reuse action 2, or have a dedicated action for trusted
devices, then Im afraid it won't help in this specific problem.


--=20
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 25+ messages in thread

* Re: [A2DP] Incoming connections do not succeed
  2014-08-28 11:19                                         ` Luiz Augusto von Dentz
@ 2014-08-28 20:37                                           ` Marcel Holtmann
  0 siblings, 0 replies; 25+ messages in thread
From: Marcel Holtmann @ 2014-08-28 20:37 UTC (permalink / raw)
  To: Luiz Augusto von Dentz; +Cc: Artem Rakhov, linux-bluetooth

Hi Luiz,

>>>>>>> please do not top post on this mailing list. It does break the reading thread.
>>>>>>> 
>>>>>>>> Here is hcitool info:
>>>>>>>> 
>>>>>>>> BD Address:  10:B7:F6:01:31:ED
>>>>>>>> Device Name: Monster Clarity
>>>>>>>> LMP Version: 2.1 (0x4) LMP Subversion: 0x189c
>>>>>>>> Manufacturer: Cambridge Silicon Radio (10)
>>>>>>>> Features page 0: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>>>>>>>> <3-slot packets>
>>>>>>>> Features page 1: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x83
>>>>>>>> 
>>>>>>>> Label also says Precision Micro Bluetooth Speaker 100.
>>>>>>> 
>>>>>>> normally all CSR based solutions should just work. Maybe this is just a bad firmware. Are you sure that Connection Pending is really causing the observed problem. It sounds strange to hit that on a CSR based speaker.
>>>>>> 
>>>>>> I compared the logs from avtest and bluetoothd (attached earlier in
>>>>>> this thread). I think the only difference that could matter is this
>>>>>> Authorization Pending response.
>>>>> 
>>>>> I've tested several devices with and without Defer Setup feature enabled.
>>>>> 
>>>>> Here is a list of devices, which successfully initiate A2DP
>>>>> connection, not depending on Defer Setup:
>>>>> Creative WP-350 Headset
>>>>> MiiKey Rythm
>>>>> JBL Micro Wireless
>>>>> HMDX Rave
>>>>> Plantronics BBfit
>>>>> Bose SoundLink Mobile speaker II
>>>>> SOL Tracks Air
>>>>> Sony MDR-1RBT
>>>>> 
>>>>> Here is a list of devices, which fail to initiate A2DP connection with
>>>>> Defer Setup enabled, but work fine when Defer Setup is disabled:
>>>>> Monster Clarity HD
>>>>> Motorola S9-HD
>>>>> Sennheiser PX210
>>>>> 2010 Toyota Prius
>>>> 
>>>> are all of these CSR based devices? If so then it sounds like a batch of broken CSR firmware. If not, then the L2CAP test cases might better be extended to have a test case for this. It is dangerous if such a fundamental Bluetooth 1.1 feature is not working correctly.
>>> 
>>> Yes, all these devices are CSR-based.
>> 
>> Well I have access to none of those which is kind nice.
>> 
>>>>> There are no devices, which are working with Defer Setup, and not
>>>>> working without Defer Setup. So I didn't see any regression.
>>>>> 
>>>>> As a result, 4 out of 12 devices do not connect as expected with Defer
>>>>> Setup enabled. I think we should consider disabling Defer Setup by
>>>>> default, at least for audio.
>>>> 
>>>> I all cases this is the A2DP signaling channel that causes the problem? It is not the media channel that is required for streaming?
>>> 
>>> Yes, exactly same scenario. The very first connection fails from
>>> speaker to source, which goes to AVDTP (PSM 25).
>> 
>> There are some other things to experiment, there seems to be possible
>> to use ERTM nowadays, for signalling only, and while this does not
>> exactly change in any way how we use authorization pending response it
>> perhaps make a difference in terms of timing, if we are lucky,
>> otherwise we can go with whitelist and retry.
>> 
>>>> Our real problem is that we need Defer Setup to be able to cleanly reject connections from devices that we do not know and do not want to talk to use. Especially if they are just not authorized to do so.
>>>> 
>>>> Maybe we should use the proposal that Luiz had and just disconnect after a timeout and try to establish the connection from our side. That might actually be useful as a workaround. An alternative option is that we delay the connection pending message for some time and give userspace the chance to respond with either read() or close(). That way we would send the correct answer. However that timeout can only be really short since we need to keep the L2CAP signaling working correctly. So it would only work for cases where the daemon has all information to make a decision. If it asks the user, then this is off limits.
>>>> 
>>>> That said, Linux 3.17 is allowing us to use a whitelist for BR/EDR that might be useful to mitigate this behavior as well. Unknown devices would be blocked on the ACL level already.
>> 
>> If whitelist for classic is to be based on the trusted list, which I
>> assume it should be, then the kernel could accept the connection right
>> away but then we need some mechanism to query if the whitelist has
>> taken effect or maybe it is fine already since bt_io_accept does the
>> following:
>> 
>> if (!(pfd.revents & POLLOUT)) {
>>    if (read(sock, &c, 1) < 0) {
>>        ERROR_FAILED(err, "read", errno);
>>        return FALSE;
>>    }
>> }
>> 
>> So POLLOUT seems to be for checking if the socket has been accepted
>> already, in case we have a older kernel we can only retry if
>> authorization succeeds but that will probably only happen if the
>> device happens to be trusted otherwise it will trigger the agent for
>> user to authorize and it more likely the device will disconnect before
>> the user can react cancelling the authorization.
> 
> I was checking how whitelist actually works currently and in fact it
> is not based on trusted list but on persistency, but we could use
> action 2 for BREDR once they are marked as trusted but perhaps you
> guys had something else in mind while designing Add Device command. If
> we can't really reuse action 2, or have a dedicated action for trusted
> devices, then Im afraid it won't help in this specific problem.

the action 0x02 is not defined or implemented for BR/EDR devices.

Regards

Marcel


^ permalink raw reply	[flat|nested] 25+ messages in thread

end of thread, other threads:[~2014-08-28 20:37 UTC | newest]

Thread overview: 25+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-07-26  1:33 [A2DP] Incoming connections do not succeed Artem Rakhov
2014-07-28  8:21 ` Luiz Augusto von Dentz
2014-07-29  0:24   ` Artem Rakhov
2014-07-29  5:16     ` Artem Rakhov
2014-07-29  5:29       ` Marcel Holtmann
2014-08-08  7:32         ` Artem Rakhov
2014-08-10  7:32           ` Luiz Augusto von Dentz
2014-08-11  6:07             ` Michal Labedzki
2014-08-18  7:11             ` Artem Rakhov
2014-08-20 22:52               ` Artem Rakhov
2014-08-20 22:54               ` Artem Rakhov
2014-08-21  6:42                 ` Artem Rakhov
2014-08-21  8:38                   ` Luiz Augusto von Dentz
2014-08-21 13:33                     ` Marcel Holtmann
2014-08-21 13:53                       ` Luiz Augusto von Dentz
2014-08-21 14:28                         ` Marcel Holtmann
2014-08-21 19:16                           ` Artem Rakhov
2014-08-21 20:24                             ` Marcel Holtmann
2014-08-21 21:31                               ` Artem Rakhov
2014-08-27  1:11                                 ` Artem Rakhov
2014-08-27  2:08                                   ` Marcel Holtmann
2014-08-27  6:33                                     ` Artem Rakhov
2014-08-27 18:34                                       ` Luiz Augusto von Dentz
2014-08-28 11:19                                         ` Luiz Augusto von Dentz
2014-08-28 20:37                                           ` Marcel Holtmann

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.