search

arkq / bluez-alsa

Bluetooth Audio ALSA Backend
MIT License
862 stars 189 forks source link

No sound when playing via SCO #258

Closed killerkalamari closed 5 years ago

killerkalamari commented 5 years ago

When I play via SCO and hsp-ag on my headset I hear a pop, but no actual audio playback. Best I can tell, I'm not getting an error either. The sound file is 16-bit, 8000 Hz.

How I'm playing: aplay -v -D bluealsa:DEV=E9:08:EF:2D:40:33,PROFILE=sco test_8k.wav, and output:

bluealsa-pcm.c:589: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Setting constraints
Playing WAVE 'test_8k.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
bluealsa-pcm.c:319: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Initializing HW
bluealsa-pcm.c:346: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: FIFO buffer size: 4096
bluealsa-pcm.c:352: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Selected HW buffer: 4 periods x 2000 bytes == 8000 bytes
bluealsa-pcm.c:367: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Initializing SW
bluealsa-pcm.c:367: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Initializing SW
bluealsa-pcm.c:389: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Prepared
bluealsa-pcm.c:367: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Initializing SW
Plug PCM: BlueALSA PCM: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco
BlueALSA BlueZ device: /org/bluez/hci0/dev_E9_08_EF_2D_40_33
BlueALSA Bluetooth codec: 0x1
bluealsa-pcm.c:240: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Starting
bluealsa-pcm.c:134: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Starting IO loop: 8
bluealsa-pcm.c:280: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Stopping
bluealsa-pcm.c:104: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: IO thread cleanup
bluealsa-pcm.c:280: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Stopping
bluealsa-pcm.c:359: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Freeing HW
bluealsa-pcm.c:309: /org/bluealsa/hci0/dev_E9_08_EF_2D_40_33/sco: Closing

How I'm running bluealsa: sudo /usr/bin/bluealsa -p hsp-ag, and initial output:

/usr/bin/bluealsa: ba-adapter.c:141: Freeing adapter: hci0
/usr/bin/bluealsa: bluez.c:1068: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
/usr/bin/bluealsa: bluez.c:1098: Registering hands-free profile: /org/bluez/HSP/AudioGateway
/usr/bin/bluealsa: main.c:353: Acquiring D-Bus service name: org.bluealsa
/usr/bin/bluealsa: main.c:358: Starting main dispatching loop

Output when BT headset is connected:

/usr/bin/bluealsa: bluez.c:1036: Called: org.bluez.Profile1.NewConnection()
/usr/bin/bluealsa: bluez.c:960: RFCOMM: HSP Audio Gateway configured for device E9:08:EF:2D:40:33
/usr/bin/bluealsa: ba-transport.c:601: State transition: 0 -> 2
/usr/bin/bluealsa: io.c:2576: Created new IO thread: RFCOMM: HSP Audio Gateway
/usr/bin/bluealsa: ba-transport.c:601: State transition: 0 -> 2
/usr/bin/bluealsa: rfcomm.c:597: Starting loop: RFCOMM: HSP Audio Gateway
/usr/bin/bluealsa: io.c:2576: Created new IO thread: HSP Audio Gateway
/usr/bin/bluealsa: io.c:2074: Starting IO loop: HSP Audio Gateway
/usr/bin/bluealsa: at.c:161: AT message: SET: command:+VGS, value:15
/usr/bin/bluealsa: rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
/usr/bin/bluealsa: at.c:161: AT message: SET: command:+CKPD, value:200
/usr/bin/bluealsa: Unsupported AT message: SET: command:+CKPD, value:200
/usr/bin/bluealsa: rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
/usr/bin/bluealsa: at.c:161: AT message: SET: command:+XAPL, value:0000-0000-0100,7
/usr/bin/bluealsa: rfcomm.c:105: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,0
/usr/bin/bluealsa: at.c:161: AT message: SET: command:+IPHONEACCEV, value:2,1,8,2,0
/usr/bin/bluealsa: rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK

Output during playback:

/usr/bin/bluealsa: bluealsa-dbus.c:134: Called: org.bluealsa.Manager1.GetPCMs()
/usr/bin/bluealsa: bluealsa-dbus.c:328: Called: org.bluealsa.PCM1.Open()
/usr/bin/bluealsa: ba-transport.c:601: State transition: 2 -> 2
/usr/bin/bluealsa: ba-transport.c:848: New SCO link: 17 (MTU: R:48 W:48)
/usr/bin/bluealsa: ba-transport.c:678: PCM drained
/usr/bin/bluealsa: ba-transport.c:882: Closing PCM: 8
/usr/bin/bluealsa: io.c:126: PCM read buffer flushed: -1
/usr/bin/bluealsa: io.c:126: PCM read buffer flushed: -1
/usr/bin/bluealsa: ba-transport.c:858: Closing SCO: 17

The only configure arg that I used is --enable-debug, as I read in other tickets that mSBC might not be working properly for audio output yet. Also, I think I read that mSBC only applies to HFP?

This is on aarch64. It's an embedded platform, but not a Raspberry Pi. Pulseaudio is not installed. I hear the playback fine if I don't restrict to hsp-ag profile and if I play to A2DP, so that works. If I don't restrict to hsp-ag profile and play to SCO, I again hear nothing.

Due to the lack of errors, I'm assuming more information is needed in order to troubleshoot this. Do you have any recommendations on which source files I should be looking to add debugging code to?

borine commented 5 years ago

It is possible that SCO traffic is not being accepted on the HCI link between the host and controller. I know this has been an issue with the raspberry pi, so I guess similar issues might affect other boards too. For example, with the broadcom chip used on the rpi, SCO traffic is by default routed through the "PCM" pins, not the UART pins used by HCI. So the host may be sending SCO data through the HCI (so btmon --sco shows the data packets going out from the host), but the controller is not picking them up to pass to the radio stack. For the rpi, this can be remedied by sending a vendor custom HCI command to switch SCO routing to HCI. To find if any similar kind of issue is affecting your board you would need to do a web search for SCO issues with the bluetooth chip model number

killerkalamari commented 5 years ago

Thank you so much for mentioning btmon --sco. Here's the output from that.

Before connecting:

Bluetooth monitor ver 5.50
= New Index: 70:2C:1F:32:15:85 (Primary,UART,hci0)                                                                                                                                                 [hci0] 0.284101
= Open Index: 70:2C:1F:32:15:85                                                                                                                                                                    [hci0] 0.284104
= Index Info: 70:2C:1F:32:15:85 (Broadcom Corporation)

Connection:

< HCI Command: Create Connection (0x01|0x0005) plen 13                                                                                                                                        #1 [hci0] 162.904171
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Packet type: 0xcc18
          DM1 may be used
          DH1 may be used
          DM3 may be used
          DH3 may be used
          DM5 may be used
          DH5 may be used
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
        Role switch: Allow slave (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                     #2 [hci0] 162.904873
      Create Connection (0x01|0x0005) ncmd 1
        Status: Success (0x00)
> HCI Event: Connect Complete (0x03) plen 11                                                                                                                                                  #3 [hci0] 165.998347
        Status: Success (0x00)
        Handle: 12
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Link type: ACL (0x01)
        Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2                                                                                                                            #4 [hci0] 165.998696
        Handle: 12
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                     #5 [hci0] 165.999598
      Read Remote Supported Features (0x01|0x001b) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11                                                                                                                                    #6 [hci0] 165.999774
        Status: Success (0x00)
        Handle: 12
        Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x59 0x87
          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
          Enhanced Power Control
          Extended features
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3                                                                                                                             #7 [hci0] 165.999822
        Handle: 12
        Page: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                     #8 [hci0] 166.000402
      Read Remote Extended Features (0x01|0x001c) ncmd 1
        Status: Success (0x00)
> HCI Event: Read Remote Extended Features (0x23) plen 13                                                                                                                                     #9 [hci0] 166.000575
        Status: Success (0x00)
        Handle: 12
        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                                                                                                                                     #10 [hci0] 166.000647
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Page scan repetition mode: R2 (0x02)
        Page scan mode: Mandatory (0x00)
        Clock offset: 0x0000
< ACL Data TX: Handle 12 flags 0x00 dlen 10                                                                                                                                                  #11 [hci0] 166.000707
      L2CAP: Information Request (0x0a) ident 1 len 2
        Type: Extended features supported (0x0002)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                    #12 [hci0] 166.001155
      Remote Name Request (0x01|0x0019) ncmd 1
        Status: Success (0x00)
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7                                                                                                                                  #13 [hci0] 166.003406
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Page scan repetition mode: R1 (0x01)
> HCI Event: Max Slots Change (0x1b) plen 3                                                                                                                                                  #14 [hci0] 166.007089
        Handle: 12
        Max slots: 5
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #15 [hci0] 166.010830
      L2CAP: Information Response (0x0b) ident 1 len 8
        Type: Extended features supported (0x0002)
        Result: Success (0x0000)
        Features: 0x000000b8
          Enhanced Retransmission Mode
          Streaming Mode
          FCS Option
          Fixed Channels
< ACL Data TX: Handle 12 flags 0x00 dlen 10                                                                                                                                                  #16 [hci0] 166.010881
      L2CAP: Information Request (0x0a) ident 2 len 2
        Type: Fixed channels supported (0x0003)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #17 [hci0] 166.013520
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 17                                                                                                                                                  #18 [hci0] 166.014573
> ACL Data RX: Handle 12 flags 0x01 dlen 3                                                                                                                                                   #19 [hci0] 166.016989
      L2CAP: Information Response (0x0b) ident 2 len 12
        Type: Fixed channels supported (0x0003)
        Result: Success (0x0000)
        Channels: 0x0000000000000036
          L2CAP Signaling (BR/EDR)
          Connectionless reception
          Attribute Protocol
          L2CAP Signaling (LE)
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                  #20 [hci0] 166.017041
      L2CAP: Connection Request (0x02) ident 3 len 4
        PSM: 1 (0x0001)
        Source CID: 64
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #21 [hci0] 166.027066
      L2CAP: Connection Response (0x03) ident 3 len 8
        Destination CID: 256
        Source CID: 64
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #22 [hci0] 166.028332
      L2CAP: Connection Response (0x03) ident 3 len 8
        Destination CID: 256
        Source CID: 64
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 12 flags 0x00 dlen 23                                                                                                                                                  #23 [hci0] 166.028386
      L2CAP: Configure Request (0x04) ident 4 len 15
        Destination CID: 256
        Flags: 0x0000
        Option: Retransmission and Flow Control (0x04) [mandatory]
          Mode: Basic (0x00)
          TX window size: 0
          Max transmit: 0
          Retransmission timeout: 0
          Monitor timeout: 0
          Maximum PDU size: 0
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #24 [hci0] 166.029571
      L2CAP: Configure Request (0x04) ident 1 len 8
        Destination CID: 64
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 48
< ACL Data TX: Handle 12 flags 0x00 dlen 18                                                                                                                                                  #25 [hci0] 166.029620
      L2CAP: Configure Response (0x05) ident 1 len 10
        Source CID: 256
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 48
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #26 [hci0] 166.030887
        Num handles: 1
        Handle: 12
        Count: 2
> HCI Event: Remote Name Req Complete (0x07) plen 255                                                                                                                                        #27 [hci0] 166.039297
        Status: Success (0x00)
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Name: TaoTronics TT-BR08
@ Device Connected: E9:08:EF:2D:40:33 (0) flags 0x0000
        13 09 54 61 6f 54 72 6f 6e 69 63 73 20 54 54 2d  ..TaoTronics TT-
        42 52 30 38                                      BR08            
> ACL Data RX: Handle 12 flags 0x02 dlen 14                                                                                                                                                  #28 [hci0] 166.039559
      L2CAP: Configure Response (0x05) ident 4 len 6
        Source CID: 64
        Flags: 0x0000
        Result: Success (0x0000)
< ACL Data TX: Handle 12 flags 0x00 dlen 24                                                                                                                                                  #29 [hci0] 166.045209
      Channel: 256 len 20 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 0 len 15
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              Headset (0x1108)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 0
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #30 [hci0] 166.048418
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #31 [hci0] 166.052164
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 0 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 33                                            .3              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #32 [hci0] 166.052585
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 1 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              Headset (0x1108)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 33                                            .3              
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #33 [hci0] 166.058429
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 1 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 0d                                            ..              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #34 [hci0] 166.058623
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 2 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              Headset (0x1108)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 0d                                            ..              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #35 [hci0] 166.062143
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 25                                                                                                                                                  #36 [hci0] 166.064621
      Channel: 64 len 21 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 2 len 16
        Attribute bytes: 13
        Continuation state: 0
        Combined attribute bytes: 89
          Attribute list: [len 83] {position 0}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x00010001
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                Headset (0x1108)
              UUID (3) with 2 bytes [0 extra bits] len 3
                Headset HS (0x1131)
              UUID (3) with 2 bytes [0 extra bits] len 3
                Generic Audio (0x1203)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 3 bytes [8 extra bits] len 5
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
              Sequence (6) with 5 bytes [8 extra bits] len 7
                UUID (3) with 2 bytes [0 extra bits] len 3
                  RFCOMM (0x0003)
                Unsigned Integer (1) with 1 byte [0 extra bits] len 2
                  0x02
            Attribute: Language Base Attribute ID List (0x0006) [len 2]
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x656e
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x006a
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x0100
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  Headset (0x1108)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0102
            Attribute: Unknown (0x0100) [len 2]
              Headset [len 7]
            Attribute: Unknown (0x0302) [len 2]
              true
< HCI Command: Authentication Requested (0x01|0x0011) plen 2                                                                                                                                 #37 [hci0] 166.065081
        Handle: 12
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                    #38 [hci0] 166.065528
      Authentication Requested (0x01|0x0011) ncmd 1
        Status: Success (0x00)
> HCI Event: Link Key Request (0x17) plen 6                                                                                                                                                  #39 [hci0] 166.065763
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22                                                                                                                                  #40 [hci0] 166.065830
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Link key: 9a9f41905b1dff79374fea25024be995
> HCI Event: Command Complete (0x0e) plen 10                                                                                                                                                 #41 [hci0] 166.067371
      Link Key Request Reply (0x01|0x000b) ncmd 1
        Status: Success (0x00)
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
> HCI Event: Auth Complete (0x06) plen 3                                                                                                                                                     #42 [hci0] 166.073502
        Status: Success (0x00)
        Handle: 12
< HCI Command: Set Connection Encryption (0x01|0x0013) plen 3                                                                                                                                #43 [hci0] 166.073545
        Handle: 12
        Encryption: Enabled (0x01)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                    #44 [hci0] 166.074166
      Set Connection Encryption (0x01|0x0013) ncmd 1
        Status: Success (0x00)
> HCI Event: Encryption Change (0x08) plen 4                                                                                                                                                 #45 [hci0] 166.092970
        Status: Success (0x00)
        Handle: 12
        Encryption: Enabled with E0 (0x01)
< HCI Command: Read Encryption Key Size (0x05|0x0008) plen 2                                                                                                                                 #46 [hci0] 166.093015
        Handle: 12
> HCI Event: Command Complete (0x0e) plen 7                                                                                                                                                  #47 [hci0] 166.093512
      Read Encryption Key Size (0x05|0x0008) ncmd 1
        Status: Success (0x00)
        Handle: 12
        Key size: 16
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                  #48 [hci0] 166.093646
      L2CAP: Connection Request (0x02) ident 5 len 4
        PSM: 3 (0x0003)
        Source CID: 65
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #49 [hci0] 166.099553
      L2CAP: Connection Response (0x03) ident 5 len 8
        Destination CID: 321
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #50 [hci0] 166.100826
      L2CAP: Connection Response (0x03) ident 5 len 8
        Destination CID: 321
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 12 flags 0x00 dlen 27                                                                                                                                                  #51 [hci0] 166.100867
      L2CAP: Configure Request (0x04) ident 6 len 19
        Destination CID: 321
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 1013
        Option: Retransmission and Flow Control (0x04) [mandatory]
          Mode: Basic (0x00)
          TX window size: 0
          Max transmit: 0
          Retransmission timeout: 0
          Monitor timeout: 0
          Maximum PDU size: 0
> ACL Data RX: Handle 12 flags 0x02 dlen 16                                                                                                                                                  #52 [hci0] 166.102068
      L2CAP: Configure Request (0x04) ident 2 len 8
        Destination CID: 65
        Flags: 0x0000
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 4022
< ACL Data TX: Handle 12 flags 0x00 dlen 18                                                                                                                                                  #53 [hci0] 166.102114
      L2CAP: Configure Response (0x05) ident 2 len 10
        Source CID: 321
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 4022
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #54 [hci0] 166.106018
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 17                                                                                                                                                  #55 [hci0] 166.107081
> ACL Data RX: Handle 12 flags 0x01 dlen 1                                                                                                                                                   #56 [hci0] 166.155733
      L2CAP: Configure Response (0x05) ident 6 len 10
        Source CID: 65
        Flags: 0x0000
        Result: Success (0x0000)
        Option: Maximum Transmission Unit (0x01) [mandatory]
          MTU: 1013
< ACL Data TX: Handle 12 flags 0x00 dlen 8                                                                                                                                                   #57 [hci0] 166.155814
      Channel: 321 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Set Async Balance Mode (SABM) (0x2f)
         Address: 0x03 cr 1 dlci 0x00
         Control: 0x3f poll/final 1
         Length: 0
         FCS: 0x1c
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #58 [hci0] 166.158387
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 8                                                                                                                                                   #59 [hci0] 166.160771
      Channel: 65 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Ack (UA) (0x63)
         Address: 0x03 cr 1 dlci 0x00
         Control: 0x73 poll/final 1
         Length: 0
         FCS: 0xd7
< ACL Data TX: Handle 12 flags 0x00 dlen 18                                                                                                                                                  #60 [hci0] 166.160844
      Channel: 321 len 14 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x03 cr 1 dlci 0x00
         Control: 0xef poll/final 0
         Length: 10
         FCS: 0x70
         MCC Message type: DLC Parameter Negotiation CMD (0x20)
           Length: 8
           dlci 4 frame_type 0 credit_flow 15 pri 7
           ack_timer 0 frame_size 1008 max_retrans 0 credits 7
> ACL Data RX: Handle 12 flags 0x02 dlen 18                                                                                                                                                  #61 [hci0] 166.167068
      Channel: 65 len 14 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x01 cr 0 dlci 0x00
         Control: 0xef poll/final 0
         Length: 10
         FCS: 0xaa
         MCC Message type: DLC Parameter Negotiation RSP (0x20)
           Length: 8
           dlci 4 frame_type 0 credit_flow 14 pri 7
           ack_timer 0 frame_size 884 max_retrans 0 credits 1
< ACL Data TX: Handle 12 flags 0x00 dlen 8                                                                                                                                                   #62 [hci0] 166.167137
      Channel: 321 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Set Async Balance Mode (SABM) (0x2f)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0x3f poll/final 1
         Length: 0
         FCS: 0x96
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #63 [hci0] 166.169626
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 8                                                                                                                                                   #64 [hci0] 166.173269
      Channel: 65 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Ack (UA) (0x63)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0x73 poll/final 1
         Length: 0
         FCS: 0x5d
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                  #65 [hci0] 166.173352
      Channel: 321 len 8 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x03 cr 1 dlci 0x00
         Control: 0xef poll/final 0
         Length: 4
         FCS: 0x70
         MCC Message type: Modem Status Command CMD (0x38)
           Length: 2
           dlci 4 
           fc 0 rtc 1 rtr 1 ic 0 dv 1
> ACL Data RX: Handle 12 flags 0x02 dlen 12                                                                                                                                                  #66 [hci0] 166.174559
      Channel: 65 len 8 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x01 cr 0 dlci 0x00
         Control: 0xef poll/final 0
         Length: 4
         FCS: 0xaa
         MCC Message type: Modem Status Command CMD (0x38)
           Length: 2
           dlci 4 
           fc 0 rtc 1 rtr 1 ic 0 dv 1
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                  #67 [hci0] 166.174640
      Channel: 321 len 8 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x03 cr 1 dlci 0x00
         Control: 0xef poll/final 0
         Length: 4
         FCS: 0x70
         MCC Message type: Modem Status Command RSP (0x38)
           Length: 2
           dlci 4 
           fc 0 rtc 1 rtr 1 ic 0 dv 1
> ACL Data RX: Handle 12 flags 0x02 dlen 12                                                                                                                                                  #68 [hci0] 166.177124
      Channel: 65 len 8 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x01 cr 0 dlci 0x00
         Control: 0xef poll/final 0
         Length: 4
         FCS: 0xaa
         MCC Message type: Modem Status Command RSP (0x38)
           Length: 2
           dlci 4 
           fc 0 rtc 1 rtr 1 ic 0 dv 1
< ACL Data TX: Handle 12 flags 0x00 dlen 9                                                                                                                                                   #69 [hci0] 166.177233
      Channel: 321 len 5 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0xff poll/final 1
         Length: 0
         FCS: 0x79
         Credits: 33
        79                                               y               
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #70 [hci0] 166.177245
        Num handles: 1
        Handle: 12
        Count: 2
< ACL Data TX: Handle 12 flags 0x00 dlen 24                                                                                                                                                  #71 [hci0] 166.180626
      Channel: 256 len 20 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 3 len 15
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 0
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #72 [hci0] 166.183389
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 9                                                                                                                                                   #73 [hci0] 166.195773
      Channel: 65 len 5 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xff poll/final 1
         Length: 0
         FCS: 0xa3
         Credits: 1
        a3                                               .               
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #74 [hci0] 166.202127
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 3 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 ed                                            ..              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #75 [hci0] 166.202351
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 4 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 ed                                            ..              
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #76 [hci0] 166.340889
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 4 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 c7                                            ..              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #77 [hci0] 166.341094
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 5 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 c7                                            ..              
> ACL Data RX: Handle 12 flags 0x02 dlen 18                                                                                                                                                  #78 [hci0] 166.342056
      Channel: 65 len 14 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xef poll/final 0
         Length: 10
         FCS: 0xbf
        41 54 2b 56 47 53 3d 31 35 0d bf                 AT+VGS=15..     
< ACL Data TX: Handle 12 flags 0x00 dlen 14                                                                                                                                                  #79 [hci0] 166.343276
      Channel: 321 len 10 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0xef poll/final 0
         Length: 6
         FCS: 0x65
        0d 0a 4f 4b 0d 0a 65                             ..OK..e         
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #80 [hci0] 166.344604
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #81 [hci0] 166.347117
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 5 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 a1                                            ..              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #82 [hci0] 166.347339
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 6 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 a1                                            ..              
> ACL Data RX: Handle 12 flags 0x02 dlen 9                                                                                                                                                   #83 [hci0] 166.348263
      Channel: 65 len 5 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xff poll/final 1
         Length: 0
         FCS: 0xa3
         Credits: 1
        a3                                               .               
> ACL Data RX: Handle 12 flags 0x02 dlen 33                                                                                                                                                  #84 [hci0] 166.349578
      Channel: 65 len 29 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xef poll/final 0
         Length: 25
         FCS: 0xbf
        41 54 2b 58 41 50 4c 3d 30 30 30 30 2d 30 30 30  AT+XAPL=0000-000
        30 2d 30 31 30 30 2c 37 0d bf                    0-0100,7..      
< ACL Data TX: Handle 12 flags 0x00 dlen 28                                                                                                                                                  #85 [hci0] 166.349987
      Channel: 321 len 24 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0xef poll/final 0
         Length: 20
         FCS: 0x65
        0d 0a 2b 58 41 50 4c 3d 42 6c 75 65 41 4c 53 41  ..+XAPL=BlueALSA
        2c 30 0d 0a 65                                   ,0..e           
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #86 [hci0] 166.350928
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #87 [hci0] 166.352149
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 6 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 7b                                            .{              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #88 [hci0] 166.352354
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 7 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 7b                                            .{              
> ACL Data RX: Handle 12 flags 0x02 dlen 9                                                                                                                                                   #89 [hci0] 166.354509
      Channel: 65 len 5 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xff poll/final 1
         Length: 0
         FCS: 0xa3
         Credits: 1
        a3                                               .               
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #90 [hci0] 166.355875
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #91 [hci0] 166.357122
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 7 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 55                                            .U              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #92 [hci0] 166.357312
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 8 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 55                                            .U              
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #93 [hci0] 166.363383
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 8 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 2f                                            ./              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #94 [hci0] 166.363576
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 9 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 2f                                            ./              
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                       #95 [hci0] 166.367116
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 52                                                                                                                                                  #96 [hci0] 166.369621
      Channel: 64 len 48 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 9 len 43
        Attribute bytes: 38
        Continuation state: 2
        00 09                                            ..              
< ACL Data TX: Handle 12 flags 0x00 dlen 26                                                                                                                                                  #97 [hci0] 166.369816
      Channel: 256 len 22 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 10 len 17
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              L2CAP (0x0100)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 2
        00 09                                            ..              
> ACL Data RX: Handle 12 flags 0x02 dlen 21                                                                                                                                                  #98 [hci0] 166.375839
      Channel: 64 len 17 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 10 len 12
        Attribute bytes: 9
        Continuation state: 0
        Combined attribute bytes: 275
          Attribute list: [len 89] {position 0}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x00010000
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                Handsfree (0x111e)
              UUID (3) with 2 bytes [0 extra bits] len 3
                Generic Audio (0x1203)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 3 bytes [8 extra bits] len 5
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
              Sequence (6) with 5 bytes [8 extra bits] len 7
                UUID (3) with 2 bytes [0 extra bits] len 3
                  RFCOMM (0x0003)
                Unsigned Integer (1) with 1 byte [0 extra bits] len 2
                  0x01
            Attribute: Language Base Attribute ID List (0x0006) [len 2]
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x656e
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x006a
              Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                0x0100
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  Handsfree (0x111e)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0106
            Attribute: Unknown (0x0100) [len 2]
              Hands-Free unit [len 15]
            Attribute: Unknown (0x0311) [len 2]
              0x003f
          Attribute list: [len 56] {position 1}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x00010002
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                Audio Sink (0x110b)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0019
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  AVDTP (0x0019)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0102
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  Advanced Audio Distribution (0x110d)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0102
            Attribute: Unknown (0x0311) [len 2]
              0x0001
          Attribute list: [len 59] {position 2}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x00010003
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                A/V Remote Control (0x110e)
              UUID (3) with 2 bytes [0 extra bits] len 3
                A/V Remote Control Controller (0x110f)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0017
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  AVCTP (0x0017)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0103
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  A/V Remote Control (0x110e)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0104
            Attribute: Unknown (0x0311) [len 2]
              0x0001
          Attribute list: [len 56] {position 3}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x00010004
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                A/V Remote Control Target (0x110c)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0017
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  AVCTP (0x0017)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0103
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  A/V Remote Control (0x110e)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0104
            Attribute: Unknown (0x0311) [len 2]
              0x0002
< ACL Data TX: Handle 12 flags 0x00 dlen 24                                                                                                                                                  #99 [hci0] 166.383096
      Channel: 256 len 20 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 11 len 15
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              PnP Information (0x1200)
        Max record count: 65535
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 0
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #100 [hci0] 166.385879
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 14                                                                                                                                                 #101 [hci0] 166.390793
      Channel: 64 len 10 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 11 len 5
        Attribute bytes: 2
        Continuation state: 0
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                 #102 [hci0] 168.242057
      L2CAP: Disconnection Request (0x06) ident 7 len 4
        Destination CID: 256
        Source CID: 64
> ACL Data RX: Handle 12 flags 0x02 dlen 12                                                                                                                                                 #103 [hci0] 168.248132
      L2CAP: Disconnection Response (0x07) ident 7 len 4
        Destination CID: 256
        Source CID: 64
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #104 [hci0] 168.475475
        Num handles: 1
        Handle: 12
        Count: 1
> ACL Data RX: Handle 12 flags 0x02 dlen 33                                                                                                                                                 #105 [hci0] 171.390455
      Channel: 65 len 29 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xef poll/final 0
         Length: 25
         FCS: 0xbf
        41 54 2b 49 50 48 4f 4e 45 41 43 43 45 56 3d 32  AT+IPHONEACCEV=2
        2c 31 2c 38 2c 32 2c 30 0d bf                    ,1,8,2,0..      
< ACL Data TX: Handle 12 flags 0x00 dlen 14                                                                                                                                                 #106 [hci0] 171.391514
      Channel: 321 len 10 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x13 cr 1 dlci 0x04
         Control: 0xef poll/final 0
         Length: 6
         FCS: 0x65
        0d 0a 4f 4b 0d 0a 65                             ..OK..e         
> ACL Data RX: Handle 12 flags 0x02 dlen 9                                                                                                                                                  #107 [hci0] 171.396629
      Channel: 65 len 5 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0xff poll/final 1
         Length: 0
         FCS: 0xa3
         Credits: 1
        a3                                               .               
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #108 [hci0] 171.600229
        Num handles: 1
        Handle: 12
        Count: 1

Playback:

< HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17                                                                                                                           #109 [hci0] 191.447671
        Handle: 12
        Transmit bandwidth: 8000
        Receive bandwidth: 8000
        Max latency: 10
        Setting: 0x0060
          Input Coding: Linear
          Input Data Format: 2's complement
          Input Sample Size: 16-bit
          # of bits padding at MSB: 0
          Air Coding Format: CVSD
        Retransmission effort: Optimize for power consumption (0x01)
        Packet type: 0x0380
          3-EV3 may not be used
          2-EV5 may not be used
          3-EV5 may not be used
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                   #110 [hci0] 191.448376
      Setup Synchronous Connection (0x01|0x0028) ncmd 1
        Status: Success (0x00)
> HCI Event: Synchronous Connect Complete (0x2c) plen 17                                                                                                                                    #111 [hci0] 191.487195
        Status: Success (0x00)
        Handle: 6
        Address: E9:08:EF:2D:40:33 (OUI E9-08-EF)
        Link type: eSCO (0x02)
        Transmission interval: 0x0c
        Retransmission window: 0x02
        RX packet length: 60
        TX packet length: 60
        Air mode: CVSD (0x02)
< SCO Data TX: Handle 6 flags 0x00 dlen 48                                                                                                                                                  

********** SNIP (lots of SCO Data TX) **********

< SCO Data TX: Handle 6 flags 0x00 dlen 48                                                                                                                                                  #799 [hci0] 193.551812
        8e 00 82 fe f8 fc 05 fc 92 fa 8d f8 fb f6 0b f6  ................
        83 f4 96 f2 40 f1 74 f0 d3 ef 1a f1 89 f4 56 f7  ....@.t.......V.
        e1 f9 3e fd e0 00 cd 04 6f 08 ff 0b b3 0f 1e 12  ..>.....o.......
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                              #800 [hci0] 193.562038
        Handle: 6
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                   #801 [hci0] 193.562706
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                              #802 [hci0] 193.586232
        Status: Success (0x00)
        Handle: 6
        Reason: Connection Terminated By Local Host (0x16)
> ACL Data RX: Handle 12 flags 0x02 dlen 8                                                                                                                                                  #803 [hci0] 207.693821
      Channel: 65 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Disconnect (DISC) (0x43)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0x53 poll/final 1
         Length: 0
         FCS: 0x16
< ACL Data TX: Handle 12 flags 0x00 dlen 8                                                                                                                                                  #804 [hci0] 207.693983
      Channel: 321 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Ack (UA) (0x63)
         Address: 0x11 cr 0 dlci 0x04
         Control: 0x73 poll/final 1
         Length: 0
         FCS: 0x3c
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #805 [hci0] 207.847482
        Num handles: 1
        Handle: 12
        Count: 1
> ACL Data RX: Handle 12 flags 0x02 dlen 8                                                                                                                                                  #806 [hci0] 208.737487
      Channel: 65 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Disconnect (DISC) (0x43)
         Address: 0x01 cr 0 dlci 0x00
         Control: 0x53 poll/final 1
         Length: 0
         FCS: 0x9c
< ACL Data TX: Handle 12 flags 0x00 dlen 8                                                                                                                                                  #807 [hci0] 208.737626
      Channel: 321 len 4 [PSM 3 mode 0] {chan 1}
      RFCOMM: Unnumbered Ack (UA) (0x63)
         Address: 0x01 cr 0 dlci 0x00
         Control: 0x73 poll/final 1
         Length: 0
         FCS: 0xb6
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                 #808 [hci0] 208.737645
      L2CAP: Disconnection Request (0x06) ident 8 len 4
        Destination CID: 321
        Source CID: 65
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #809 [hci0] 208.792590
        Num handles: 1
        Handle: 12
        Count: 2
> ACL Data RX: Handle 12 flags 0x02 dlen 12                                                                                                                                                 #810 [hci0] 208.793753
      L2CAP: Disconnection Request (0x06) ident 3 len 4
        Destination CID: 65
        Source CID: 321
< ACL Data TX: Handle 12 flags 0x00 dlen 12                                                                                                                                                 #811 [hci0] 208.793837
      L2CAP: Disconnection Response (0x07) ident 3 len 4
        Destination CID: 65
        Source CID: 321
> ACL Data RX: Handle 12 flags 0x02 dlen 12                                                                                                                                                 #812 [hci0] 208.794995
      L2CAP: Disconnection Response (0x07) ident 8 len 4
        Destination CID: 321
        Source CID: 65
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                                                                                      #813 [hci0] 208.972450
        Num handles: 1
        Handle: 12
        Count: 1
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                              #814 [hci0] 210.791597
        Handle: 12
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                   #815 [hci0] 210.792226
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                              #816 [hci0] 210.943570
        Status: Success (0x00)
        Handle: 12
        Reason: Connection Terminated By Local Host (0x16)
@ Device Disconnected: E9:08:EF:2D:40:33 (0) reason 2
borine commented 5 years ago

That trace appears to show that bluealsa is correctly sending SCO data to the HCI. Can't tell if that data is "music" or just a "pop", but if there are lots of SCO data packets, and the content is not all zeros, then I think it's reasonable to assume bluealsa is doing its job correctly here.

There may be many reasons why the headset does not render the sound, but that's possibly out of scope here, and certainly beyond my knowledge.

You should check that the controller is actually transmitting the data it is receiving on the HCI [SCO and A2DP are handled very differently by the controller hardware] - tcpdump is your friend there - and beyond that you might seek advice for your specific board/controller/headset.

killerkalamari commented 5 years ago

I trimmed the audio. There are some zeros at the beginning, but most looks like audio. Thanks for your help. I'll look into a controller problem.

killerkalamari commented 5 years ago

After some digging, I found out we are using the CYW43455 (also called BCM43455) chip, which is the same as is being used in the Pi 3 Model B+ and Pi 4 (confusingly, the original Pi 3 model used a CYW43438). Found the fix you were referring to, which is for the CYW43438 (or BCM43438). Tried their fix even though it was the wrong chipset, and it actually worked to enable audio on the CYW43455 in both hsp-ag and hfp-ag modes, although I am getting popping and audio truncation (might be a separate issue at this point). Thanks a lot!

Someone in this thread has also already asked Cygnus for CYW43455 help with the Pi 4, as I guess the workaround isn't helping there: https://github.com/raspberrypi/linux/issues/2229#issuecomment-359233111

This ticket is probably resolved, but I'd like to try out the fix on a Pi 3 (original), and a Pi 4, and see how things work there with bluealsa under Raspbian (vs this embedded chipset and OpenWRT installation) and see if there is truncation.

borine commented 5 years ago

You should also try the mtu fix for bluealsa, to see if that helps with the sound quality. See https://github.com/Arkq/bluez-alsa/issues/225, specifically my comment here: https://github.com/Arkq/bluez-alsa/issues/225#issuecomment-522459636. The line numbers to change are now 866 and 867 in src/ba-transport.c in the latest code. You could also try an mtu of 60 instead of 64 to see which, if any, gives best results.

I have spent a lot of time and effort researching this MTU issue with linux bluetooth, but have made little progress in finding a generic solution. However, specifically with bluealsa with the BCM43455, hardcoding the MTU to 64 works for me (but breaks if i then use a USB bt adapter).

killerkalamari commented 5 years ago

Was able to recreate the truncated audio on Pi 3 (original, not the B+) with the hcitool cmd fix and bluez-alsa. So, I decided to try the hcitool fix with pulseaudio on the Pi 3. Well, with pulse, the first part of the sound was missing, and the audio quality was atrocious. If bluealsa used any of that code there has obviously been a lot of repair work done. I'll go ahead and create a new bug for the truncation issue.

killerkalamari commented 5 years ago

Fix for the no sound via SCO issue on the CYW43438 and CYW43455 can be found here (thanks to borine for the tip!): https://github.com/raspberrypi/linux/issues/2229#issuecomment-359233111

Sample run (the output was identical for both chips):

$ sudo hcitool cmd 0x3F 0x01C 0x01 0x02 0x00 0x01 0x01
< HCI Command: ogf 0x3f, ocf 0x001c, plen 5
  01 02 00 01 01 
> HCI Event: 0x0e plen 4
  01 1C FC 00

Closing.

killerkalamari commented 5 years ago

The hcitool call from https://github.com/Arkq/bluez-alsa/issues/258#issuecomment-543280391 is no longer needed since commit 335f48c18a6dc87c4046f34591a14bd6abf65235. Thanks!