linux-bluetooth.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Pulseaudio SCO connection fails when the headset requests the connection
@ 2020-03-20  8:29 Kai Ruhnau
  0 siblings, 0 replies; only message in thread
From: Kai Ruhnau @ 2020-03-20  8:29 UTC (permalink / raw)
  To: linux-bluetooth

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

Hi,

I have
- Linux kernel 5.4.26
- Bluez 5.54
- Pulseaudio 12.2
- An i.MX6 SoloX-based platform
- An ODIN W160 module with a WL1273
- A Nokia BH 310 supporting Headset and Handsfree

When I take the headset out of its charging station, it issues a Connect Request and everything starts rolling. This ends with an error, when pulseaudio tries to connect the BTPROTO_SCO socket ("Function not implemented" at https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/blob/v12.2/src/modules/bluetooth/backend-native.c#L153). According to hcidump "headset-connection-request", there is an "Error: Different Transaction Collision" while establishing the synchronous connection.

When I have the headset not connected and connect it through bluetoothctl, everything starts rolling and ends up with a functioning card/source/sink in pulseaudio. The hcidump for that is in "host-connects".

Is this something I have to hide in my application software (disconnect + connect), or is there a proper way to make it work?

Thanks and cheers,
Kai

[-- Attachment #2: host-connects --]
[-- Type: application/octet-stream, Size: 19716 bytes --]

[-- Attachment #3: headset-connection-request --]
[-- Type: application/octet-stream, Size: 12080 bytes --]

HCI sniffer - Bluetooth packet analyzer ver 5.54
device: hci0 snap_len: 1500 filter: 0xffffffff
2020-03-20 07:55:39.053779 > HCI Event: Connect Request (0x04) plen 10
    bdaddr 00:13:8A:32:47:22 class 0x200404 type ACL
2020-03-20 07:55:39.053938 < HCI Command: Accept Connection Request (0x01|0x0009) plen 7
    bdaddr 00:13:8A:32:47:22 role 0x00
    Role: Master
2020-03-20 07:55:39.054676 > HCI Event: Command Status (0x0f) plen 4
    Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1
2020-03-20 07:55:39.214907 > HCI Event: Role Change (0x12) plen 8
    status 0x00 bdaddr 00:13:8A:32:47:22 role 0x00
    Role: Master
2020-03-20 07:55:39.231473 > HCI Event: Connect Complete (0x03) plen 11
    status 0x00 handle 1 bdaddr 00:13:8A:32:47:22 type ACL encrypt 0x00
2020-03-20 07:55:39.236844 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
    handle 1
2020-03-20 07:55:39.238236 > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
    bdaddr 00:13:8A:32:47:22 mode 0
2020-03-20 07:55:39.238266 > ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 1 scid 0x0041
2020-03-20 07:55:39.239135 > HCI Event: Command Status (0x0f) plen 4
    Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
2020-03-20 07:55:39.239235 < HCI Command: Write Scan Enable (0x03|0x001a) plen 1
    enable 0
2020-03-20 07:55:39.239501 > HCI Event: Read Remote Supported Features (0x0b) plen 11
    status 0x00 handle 1
    Features: 0xbc 0xfe 0x8f 0xfe 0x1b 0xfe 0x79 0x87
2020-03-20 07:55:39.240087 > HCI Event: Command Complete (0x0e) plen 4
    Write Scan Enable (0x03|0x001a) ncmd 1
    status 0x00
2020-03-20 07:55:39.240185 < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3
    handle 1 page 1
2020-03-20 07:55:39.241045 > HCI Event: Command Status (0x0f) plen 4
    Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1
2020-03-20 07:55:39.251778 > HCI Event: Read Remote Extended Features (0x23) plen 13
    status 0x00 handle 1 page 1 max 1
    Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
2020-03-20 07:55:39.251838 < HCI Command: Remote Name Request (0x01|0x0019) plen 10
    bdaddr 00:13:8A:32:47:22 mode 2 clkoffset 0x0000
2020-03-20 07:55:39.251852 < ACL data: handle 1 flags 0x00 dlen 10
    L2CAP(s): Info req: type 2
2020-03-20 07:55:39.251914 < ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0041 result 1 status 0
      Connection pending - No futher information available
2020-03-20 07:55:39.251920 < ACL data: handle 1 flags 0x00 dlen 10
    L2CAP(s): Info req: type 2
2020-03-20 07:55:39.253705 > HCI Event: Command Status (0x0f) plen 4
    Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
2020-03-20 07:55:39.257168 > HCI Event: Remote Name Req Complete (0x07) plen 255
    status 0x00 bdaddr 00:13:8A:32:47:22 name 'Nokia BH-310'
2020-03-20 07:55:39.257294 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
2020-03-20 07:55:39.257513 > ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Info rsp: type 2 result 0
      Extended feature mask 0x0200
        Unicast Connectless Data Reception
2020-03-20 07:55:39.258660 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.260995 > ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Info rsp: type 2 result 0
      Extended feature mask 0x0200
        Unicast Connectless Data Reception
2020-03-20 07:55:39.261033 < ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0041 result 0 status 0
      Connection successful
2020-03-20 07:55:39.261045 < ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(s): Config req: dcid 0x0041 flags 0x00 clen 0
2020-03-20 07:55:39.266060 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
2020-03-20 07:55:39.266250 > ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
      MTU 64 
2020-03-20 07:55:39.266284 < ACL data: handle 1 flags 0x00 dlen 18
    L2CAP(s): Config rsp: scid 0x0041 flags 0x00 result 0 clen 4
      MTU 64 
2020-03-20 07:55:39.268536 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.268726 > ACL data: handle 1 flags 0x02 dlen 14
    L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0
      Success
2020-03-20 07:55:39.272308 > ACL data: handle 1 flags 0x02 dlen 31
    L2CAP(d): cid 0x0040 len 27 [psm 1]
        SDP SSA Req: tid 0x0 len 0x16
          pat uuid-16 0x111f (Handsfree AG)
          max 48
          aid(s) 0x0001 (SrvClassIDList) 0x0004 (ProtocolDescList) 0x0009 (BTProfileDescList) 0x0311 (SuppFeatures)
          cont 00
2020-03-20 07:55:39.272696 < ACL data: handle 1 flags 0x00 dlen 14
    L2CAP(d): cid 0x0041 len 10 [psm 1]
        SDP SSA Rsp: tid 0x0 len 0x5
          count 2
          cont 00
2020-03-20 07:55:39.275990 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.279738 > ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Disconn req: dcid 0x0040 scid 0x0041
2020-03-20 07:55:39.279785 < ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(s): Disconn rsp: dcid 0x0040 scid 0x0041
2020-03-20 07:55:39.283480 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.287239 > ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 1 scid 0x0043
2020-03-20 07:55:39.287299 < ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0043 result 0 status 0
      Connection successful
2020-03-20 07:55:39.287309 < ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(s): Config req: dcid 0x0043 flags 0x00 clen 0
2020-03-20 07:55:39.292288 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
2020-03-20 07:55:39.292491 > ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
      MTU 64 
2020-03-20 07:55:39.292525 < ACL data: handle 1 flags 0x00 dlen 18
    L2CAP(s): Config rsp: scid 0x0043 flags 0x00 result 0 clen 4
      MTU 64 
2020-03-20 07:55:39.294775 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.294969 > ACL data: handle 1 flags 0x02 dlen 14
    L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0
      Success
2020-03-20 07:55:39.297297 > ACL data: handle 1 flags 0x02 dlen 28
    L2CAP(d): cid 0x0040 len 24 [psm 1]
        SDP SSA Req: tid 0x0 len 0x13
          pat uuid-16 0x1112 (Headset AG)
          max 48
          aid(s) 0x0001 (SrvClassIDList) 0x0004 (ProtocolDescList) 0x0009 (BTProfileDescList)
          cont 00
2020-03-20 07:55:39.297773 < ACL data: handle 1 flags 0x00 dlen 57
    L2CAP(d): cid 0x0043 len 53 [psm 1]
        SDP SSA Rsp: tid 0x0 len 0x30
          count 45
          record #0
              aid 0x0001 (SrvClassIDList)
                 < uuid-16 0x1112 (Headset AG) uuid-16 0x1203 (Audio) >
              aid 0x0004 (ProtocolDescList)
                 < < uuid-16 0x0100 (L2CAP) > <
                 uuid-16 0x0003 (RFCOMM) uint 0xc > >
              aid 0x0009 (BTProfileDescList)
                 < < uuid-16 0x1108 (Headset) uint 0x102 > >
          cont 00
2020-03-20 07:55:39.300993 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.304741 > ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Disconn req: dcid 0x0040 scid 0x0043
2020-03-20 07:55:39.304795 < ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(s): Disconn rsp: dcid 0x0040 scid 0x0043
2020-03-20 07:55:39.308467 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.312381 > HCI Event: Link Key Request (0x17) plen 6
    bdaddr 00:13:8A:32:47:22
2020-03-20 07:55:39.312413 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
    bdaddr 00:13:8A:32:47:22 key C3AF76C1B3888564048378D9DC6840A2
2020-03-20 07:55:39.313193 > HCI Event: Command Complete (0x0e) plen 10
    Link Key Request Reply (0x01|0x000b) ncmd 1
    status 0x00 bdaddr 00:13:8A:32:47:22
2020-03-20 07:55:39.343833 > HCI Event: Encrypt Change (0x08) plen 4
    status 0x00 handle 1 encrypt 0x01
2020-03-20 07:55:39.343948 < HCI Command: Read Encryption Key Size (0x05|0x0008) plen 2
2020-03-20 07:55:39.344806 > HCI Event: Command Complete (0x0e) plen 7
    Read Encryption Key Size (0x05|0x0008) ncmd 1
2020-03-20 07:55:39.346171 > ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 3 scid 0x0044
2020-03-20 07:55:39.346354 < ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0044 result 0 status 0
      Connection successful
2020-03-20 07:55:39.346388 < ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Config req: dcid 0x0044 flags 0x00 clen 4
      MTU 1013 
2020-03-20 07:55:39.351140 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
2020-03-20 07:55:39.351357 > ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
      MTU 1788 
2020-03-20 07:55:39.351438 < ACL data: handle 1 flags 0x00 dlen 18
    L2CAP(s): Config rsp: scid 0x0044 flags 0x00 result 0 clen 4
      MTU 1788 
2020-03-20 07:55:39.353596 > ACL data: handle 1 flags 0x02 dlen 14
    L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0
      Success
2020-03-20 07:55:39.354824 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.358554 > ACL data: handle 1 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c 
2020-03-20 07:55:39.358719 < ACL data: handle 1 flags 0x00 dlen 8
    L2CAP(d): cid 0x0044 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
2020-03-20 07:55:39.362333 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.366098 > ACL data: handle 1 flags 0x02 dlen 18
    L2CAP(d): cid 0x0040 len 14 [psm 3]
      RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
      dlci 24 frame_type 0 credit_flow 15 pri 0 ack_timer 0
      frame_size 255 max_retrans 0 credits 7
2020-03-20 07:55:39.366266 < ACL data: handle 1 flags 0x00 dlen 18
    L2CAP(d): cid 0x0044 len 14 [psm 3]
      RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
      dlci 24 frame_type 0 credit_flow 14 pri 0 ack_timer 0
      frame_size 255 max_retrans 0 credits 7
2020-03-20 07:55:39.369766 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
2020-03-20 07:55:39.373497 > ACL data: handle 1 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 24 pf 1 ilen 0 fcs 0xa2 
2020-03-20 07:55:39.374195 < ACL data: handle 1 flags 0x00 dlen 8
    L2CAP(d): cid 0x0044 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 24 pf 1 ilen 0 fcs 0x69 
2020-03-20 07:55:39.374382 < ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(d): cid 0x0044 len 8 [psm 3]
      RFCOMM(s): MSC CMD: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
      dlci 24 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 1 b3 0 len 0
2020-03-20 07:55:39.378866 < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17
    handle 1 voice setting 0x0060 ptype 0x0380
2020-03-20 07:55:39.380002 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
2020-03-20 07:55:39.380979 > HCI Event: Command Status (0x0f) plen 4
    Setup Synchronous Connection (0x01|0x0028) status 0x00 ncmd 1
2020-03-20 07:55:39.556998 > HCI Event: Synchronous Connect Complete (0x2c) plen 17
    status 0x2a handle 257 bdaddr 00:13:8A:32:47:22 type eSCO
    Error: Different Transaction Collision
2020-03-20 07:55:59.707686 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 1 reason 0x08
    Reason: Connection Timeout
2020-03-20 07:55:59.711900 < HCI Command: Write Scan Enable (0x03|0x001a) plen 1
    enable 2
2020-03-20 07:55:59.725824 > HCI Event: Command Complete (0x0e) plen 4
    Write Scan Enable (0x03|0x001a) ncmd 1
    status 0x00

^ permalink raw reply	[flat|nested] only message in thread
only message in thread, other threads:[~2020-03-20  8:29 UTC | newest]

Thread overview: (only message) (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-03-20  8:29 Pulseaudio SCO connection fails when the headset requests the connection Kai Ruhnau

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).