arkq / bluez-alsa

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

arecord not working on embedded ARM target. #347

Closed grahamnaylorccfe closed 4 years ago

grahamnaylorccfe commented 4 years ago

I have an embedded A9 coretex ARM running on a Zynq chip with an Ubuntu like Petalinux OS. I managed to install the dependencies and bluez-alsa downloaded from master yesterday (21/6/2020, so v2.1 with bluez 5.48). I have similar issues as issue #262 in that aplay works fine on both a2dp and sco (eg with aplay -D bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco sample.wav ), however when trying to record (you see I need the mic input as I am tring to build an SDR) I get no sound a recorded file of just 44 bytes (using arecord -D bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco recorded.wav). I have tried with an Asus USB BT dongle with the Broadsom chip (BCM20702A1 (001.002.014)) and get the same problem with another BT dongle using a CSR chip. For the Broadcom I have the .hcd driver in /lib/firmware/brcm/ , though it does seem that there are two in circulation (BCM20702A1-0a5c-21e8.hcd) and also BCM20702A1-0b05-17cb.hcd, though I have put both in for good measure (both 34kB). No errors in dmesg and all seems OK, but nothing on record.

@borine has helpfully suggested using btmon --sco to diagnose issues on the sco channel during an attempted record, but don't know what to make of it. Any ideas?:

@ RAW Open: bluealsa (privileged) version 2.22 {0x0003} 137.389523 @ RAW Close: bluealsa {0x0003} 137.389976 < HCI Command: Exit Sniff Mode (0x02|0x0004) plen 2 #2040 [hci0] 137.390455 Handle: 12

HCI Event: Command Status (0x0f) plen 4 #2041 [hci0] 137.391115 Exit Sniff Mode (0x02|0x0004) ncmd 1 Status: Success (0x00) HCI Event: Mode Change (0x14) plen 6 #2042 [hci0] 137.685101 Status: Success (0x00) Handle: 12 Mode: Active (0x00) Interval: 0.000 msec (0x0000) < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17 #2043 [hci0] 137.685174 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 #2044 [hci0] 137.686098 Setup Synchronous Connection (0x01|0x0028) ncmd 1 Status: Success (0x00) HCI Event: Synchronous Connect Complete (0x2c) plen 17 #2045 [hci0] 137.695099 Status: Success (0x00) Handle: 6 Address: 50:19:01:90:7F:39 (OUI 50-19-01) 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 #2046 [hci0] 137.698871 01 e4 f0 e3 68 e4 49 e5 e3 e6 85 e8 93 e9 55 eb ....h.I.......U. 4d ed 3c ef 81 f1 b7 f3 42 f5 99 f6 b3 f8 e8 fa M.<.....B....... 15 fd 6c ff 39 00 48 01 5d 03 11 05 2f 06 40 07 ..l.9.H.].../.@. HCI Event: Mode Change (0x14) plen 6 #2047 [hci0] 167.712922 Status: Success (0x00) Handle: 12 Mode: Sniff (0x02) Interval: 100.000 msec (0x00a0) < HCI Command: Disconnect (0x01|0x0006) plen 3 #2048 [hci0] 181.718741 Handle: 6 Reason: Remote User Terminated Connection (0x13) HCI Event: Command Status (0x0f) plen 4 #2049 [hci0] 181.719856 Disconnect (0x01|0x0006) ncmd 1 Status: Success (0x00) HCI Event: Disconnect Complete (0x05) plen 4 #2050 [hci0] 181.780838 Status: Success (0x00) Handle: 6 Reason: Connection Terminated By Local Host (0x16)

It looked as though it started streaming, but then stopped as if it was going in to a brick wall.

cheers G

grahamnaylorccfe commented 4 years ago

For info, I launched bluealsa using: bluealsa -p a2dp-source -p a2dp-sink -p hfp-hf -p hfp-ag -p hsp-hs -p hsp-ag -p hfp-ofono to try and cover all bases!

With the Broadcom I reproducibly get the following monitor output when trying to record: RAW Open: bluealsa (privileged) version 2.22 {0x0003} 20.876873 @ RAW Close: bluealsa {0x0003} 20.877322 < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17 #2037 [hci0] 20.877799 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 #2038 [hci0] 20.883304 Setup Synchronous Connection (0x01|0x0028) ncmd 1 Status: Success (0x00) HCI Event: Synchronous Connect Complete (0x2c) plen 17 #2039 [hci0] 20.912228 Status: Success (0x00) Handle: 6 Address: 50:19:01:90:7F:39 (OUI 50-19-01) 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 #2040 [hci0] 20.916940 59 ed 6a ea 89 e8 59 e7 64 e5 20 e4 f3 e3 07 e4 Y.j...Y.d. ..... 01 e4 f0 e3 68 e4 49 e5 e3 e6 85 e8 93 e9 55 eb ....h.I.......U. 4d ed 3c ef 81 f1 b7 f3 42 f5 99 f6 b3 f8 e8 fa M.<.....B....... < SCO Data TX: Handle 6 flags 0x00 dlen 48 #2041 [hci0] 20.920276 15 fd 6c ff 39 00 48 01 5d 03 11 05 2f 06 40 07 ..l.9.H.].../.@. 6e 08 f9 08 db 09 fe 09 14 0a cf 0a 2c 0b b9 0a n...........,... 79 0a f1 0a 45 0a d6 09 24 0a e1 09 42 09 e8 08 y...E...$...B... < HCI Command: Disconnect (0x01|0x0006) plen 3 #2042 [hci0] 27.260320 Handle: 6 Reason: Remote User Terminated Connection (0x13) HCI Event: Command Status (0x0f) plen 4 #2043 [hci0] 27.263242 Disconnect (0x01|0x0006) ncmd 1 Status: Success (0x00) HCI Event: Disconnect Complete (0x05) plen 4 #2044 [hci0] 27.267227 Status: Success (0x00) Handle: 6 Reason: Connection Terminated By Local Host (0x16)

It seems to be sending two blocks of 48 bytes but then maybe some buffer becomes full?

borine commented 4 years ago

Hi Graham The btmon suggestion was just to confirm that SCO data packets are actually being routed through the HCI. Your traces above show that none are received by the host (no RX), and that the SCO link is terminated by the local host. To find out why, you need to look at bluetoothd and bluealsa logs. Run bluetoothd with -d option to get debug info; bluealsa needs to be built with --enable-debug at the configure step.

I would recommend you start bluealsa with only one profile to minimize the number of variables here. If your microphone supports HSP then that is the simplest SCO profile and is the best bet for initial troubleshooting:

bluealsa -p hsp-ag

If there is no HSP support, or once you have HSP working, then if required try HFP:

bluealsa -p hfp-ag

Finally, try in combination with A2DP if required.

Do not use the hsp-hs or hfp-hf profiles, they are for the microphone/speaker end of the link; from your description it looks like you are trying to build a gateway.

borine commented 4 years ago

A quick web search found this, which may (or may not) be helpful for your Asus adapter:

https://community.cypress.com/message/30511#30511

borine commented 4 years ago

A bit more research ...

The naming convention for Broadcom USB firmware is BCM20702A1-<VID>-<PID>.hcd where VID and PID are the USB vendor and product ids. To see the VID and PID for your adapter(s), type

lsusb

You will see ID xxxx:xxxx against each. Make sure you have the correct firmware. There are a number of different firmwares available at: https://github.com/winterheart/broadcom-bt-firmware/tree/master/brcm

grahamnaylorccfe commented 4 years ago

Thanks alot for all your help @borine - this is where I have got to so for (no cigar yet I'm afraid): I downloaded the firmware you suggested (I had the reference number correct for my version as reported by lsusb as it is the want that was claimed to be missing in the dmesg report. Curiously the one from the repo you pointed to had a different md5 checksum to the one I had. Anyway, with this version I again get perfect response with aplay, but still nothing on arecord. I am not sure how to get the command hci_bcm_write_sco_pcm_int(1,0,0,0,0) to work as I get the response command not found. Where should this be launched from? I will try and check the other debugging outputs you suggested previously for clues. cheers Graham

grahamnaylorccfe commented 4 years ago

BTW I launched bluealsa with -p hsp-ag as it didn't respond with -p hfp-ag

arkq commented 4 years ago

@grahamnaylorccfe have you tried to use aplay and then simultaneously arecord? Maybe your headset requires "input" in order to send something?

EDIT: After looking at btmon output (from your first comment) my suggestion is futile... Otherwise, there would be RX data recorded :/

borine commented 4 years ago

I am not sure how to get the command hci_bcm_write_sco_pcm_int(1,0,0,0,0)

OK, bluealsa tries to do that part for you, with Broadcom bluetooth modules. Please can you post the output of:

hciconfig -a

which should confirm whether the module is reporting itself as Broadcom ?

arkq commented 4 years ago

@borine for my private builds I'm using the broadcom setup also for cypress chips (after cypress acquired broadcom), but I'm not sure whether this will work in all cypress cases so this commit is not mainlined.

EDIT: @grahamnaylorccfe you might try to add cypress to the if statement as follows: https://github.com/Arkq/bluez-alsa/blob/master/src/sco.c#L161

if (a->chip.manufacturer == BT_COMPID_BROADCOM ||
    a->chip.manufacturer == BT_COMPID_CYPRESS) {

However, I'm not sure whether it will help, because since playback works, chip has to read data from HCI, not from PCM interface.

borine commented 4 years ago

after cypress acquired broadcom

and now Infineon has bought Cypress :smile:

grahamnaylorccfe commented 4 years ago

@grahamnaylorccfe have you tried to use aplay and then simultaneously arecord? Maybe your headset requires "input" in order to send something?

EDIT: After looking at btmon output (from your first comment) my suggestion is futile... Otherwise, there would be RX data recorded :/

Yes - tried playing on one terminal and record on another - no luck, aplay works just fine but arecord still gives only a 44 byte file. The dongle announces itself as Broadcom so I guess adding Cypress won't help.

grahamnaylorccfe commented 4 years ago

I am not sure how to get the command hci_bcm_write_sco_pcm_int(1,0,0,0,0)

OK, bluealsa tries to do that part for you, with Broadcom bluetooth modules. Please can you post the output of:

hciconfig -a

which should confirm whether the module is reporting itself as Broadcom ?

hciconfig -a hci0: Type: Primary Bus: USB BD Address: 5C:F3:70:99:0E:8C ACL MTU: 1021:8 SCO MTU: 64:1 UP RUNNING PSCAN RX bytes:14969 acl:288 sco:0 events:635 errors:0 TX bytes:768056 acl:275 sco:14196 commands:367 errors:0 Features: 0xbf 0xfe 0xcf 0xfe 0xdb 0xff 0x7b 0x87 Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 Link policy: RSWITCH SNIFF Link mode: SLAVE ACCEPT Name: 'koheron' Class: 0x200000 Service Classes: Audio Device Class: Miscellaneous, HCI Version: 4.0 (0x6) Revision: 0x15bb LMP Version: 4.0 (0x6) Subversion: 0x220e Manufacturer: Broadcom Corporation (15)

arkq commented 4 years ago

The dongle announces itself as Broadcom so I guess adding Cypress won't help.

So maybe this fix actually breaks somethings... Try to remove the "if" block from my previous comment - lets keep everything as a default. Before test reboot the board/PC.

grahamnaylorccfe commented 4 years ago

Hi Graham The btmon suggestion was just to confirm that SCO data packets are actually being routed through the HCI. Your traces above show that none are received by the host (no RX), and that the SCO link is terminated by the local host. To find out why, you need to look at bluetoothd and bluealsa logs. Run bluetoothd with -d option to get debug info; bluealsa needs to be built with --enable-debug at the configure step.

I would recommend you start bluealsa with only one profile to minimize the number of variables here. If your microphone supports HSP then that is the simplest SCO profile and is the best bet for initial troubleshooting:

bluealsa -p hsp-ag

If there is no HSP support, or once you have HSP working, then if required try HFP:

bluealsa -p hfp-ag

Finally, try in combination with A2DP if required.

Do not use the hsp-hs or hfp-hf profiles, they are for the microphone/speaker end of the link; from your description it looks like you are trying to build a gateway.

I had built the bluez-alsa with debug enabled, here is the transcript when trying to record:

Initially connecting:

bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.Profile1.NewConnection() on /org/bluez/HSP/AudioGateway bluealsa: D: ../../src/ba-rfcomm.c:1263: Created new RFCOMM thread [ba-rfcomm]: HSP Audio Gateway bluealsa: D: ../../src/bluez.c:1050: HSP Audio Gateway configured for device 50:19:01:90:7F:39 bluealsa: D: ../../src/ba-transport.c:721: State transition: 0 -> 2 bluealsa: D: ../../src/ba-transport.c:997: Created new thread [ba-sco]: HSP Audio Gateway bluealsa: D: ../../src/ba-rfcomm.c:880: Starting RFCOMM loop: HSP Audio Gateway bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HSP Audio Gateway state transition: 0 -> 9 bluealsa: D: ../../src/sco.c:241: Starting SCO loop: HSP Audio Gateway bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGS, value:12 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0012-0001-0100,3 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK bluealsa: D: ../../src/at.c:161: AT message: SET: command:+IPHONEACCEV, value:2,1,9,2,0 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK


Then running arecord......


bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_50_19_01_90_7F_39/hspag/source bluealsa: D: ../../src/ba-transport.c:929: New SCO link: 50:19:01:90:7F:39: 18 bluealsa: D: ../../src/hci.c:132: SCO link socket MTU: 18: 64 bluealsa: D: ../../src/ba-transport.c:721: State transition: 2 -> 2


Then ^C to escape


bluealsa: D: ../../src/ba-transport.c:971: Closing PCM: 15 bluealsa: D: ../../src/sco.c:328: Releasing SCO due to PCM inactivity bluealsa: D: ../../src/ba-transport.c:947: Closing SCO: 18

grahamnaylorccfe commented 4 years ago

I killed bluetoothd and relaunched as bluetoothd -d and then restarted bluealsa. I don't get any debug messages from bluetoothd when connecting and trying aplay (succesfully) and arecord (unsuccesfully).

borine commented 4 years ago

hmm, according to https://bluekitchen-gmbh.com/btstack/chipsets/ CSR USB adapters always route SCO over HCI, whereas Broadcom USB adapters by default route SCO to I2S/PCM, and so always need the vendor command to switch routing to HCI. The fact that both CSR and Broadcom are failing in the same way here suggests that SCO routing is not the real issue here after all.

Perhaps the microphone is simply not transmitting any audio ? Is there any way to check that (an LED or other indicator on the headset/microphone perhaps). Is this headset known to work with other systems (linux/mac/windows) ?

grahamnaylorccfe commented 4 years ago

I tried the headset and USB dongle on an Ubuntu 18.04 installation on a regular PC and was able to detect sound from the microphone and sound back to the earpiece using the audio test facility in settings. Echo testing to Skype also worked fine. Back on the embedded board I have tried a few other headsets with the same problem on record. Do you recommend any particular USB dongle to BT headset that is known to work. Ultimately I will need this to work to a waterproof headset for use underground (cave rescue). cheers Graham

borine commented 4 years ago

If the headset/dongle combination works with pulseaudio on Ubuntu 18.04 then it should work with bluealsa also. Its a mystery to me why no SCO data is being received on the HCI on your embedded board.

If you have time to install bluealsa and test on the Ubuntu 18.04 machine, that would help to be sure this is not a bluealsa bug. You will have to temporarily disable pulseaudio to do this (do not use sudo !):

systemctl --user stop pulseaudio.service pulseaudio.socket

Restart pulseaudio later with

systemctl --user start pulseaudio

Please can you test with both dongles (with both pulseaudio and bluealsa) so we can know whether both should be OK on the embedded board.

EDIT I forgot - Ubuntu also runs an instance of pulseaudio with the display manager - stop this with:

echo "autospawn = 0" | sudo tee /var/lib/gdm3/.config/pulse/client.conf
sudo chown gdm:gdm /var/lib/gdm3/.config/pulse/client.conf
sudo killall pulseaudio

To restore it, sudo rm /var/lib/gdm3/.config/pulse/client.conf

grahamnaylorccfe commented 4 years ago

Thanks for your suggestions @borine . Here is where I have got to: I found another embedded Arm board (Zedboard) that runs Xillinux which is Lubuntu 16.04. My headsets connected and were able to work with pulseaudio on play and recored (paplay and parecord, using the CSR USB dongle), so I went ahead and installed bluez-alsa (after compiling and installing all the dependencies) and follow your instructions above Now generally I run as root on these embedded board, but got the following error trying to disable pulse audio in th display manager: ~# echo "autospawn = 0" | sudo tee /var/lib/gdm3/.config/pulse/client.conf tee: /var/lib/gdm3/.config/pulse/client.conf: No such file or directory autospawn = 0

Now there aren't any pulseaudio processes returned by ps -ef, so I launch bluealsa and try in another window running aplay, but get the error: ~# aplay -D bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco sample.wav ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco aplay: main:722: audio open error: No such file or directory

I think I must be missing something fundamental - sorry for being a bit slow on this! You may ask why I don't just run pulseaudio on the Zedboard since that appears to work on both play and record (input and output) - the reason is that the board is rather large and I need to use the somewhat more compact Cora Zynq board. cheers Graham

borine commented 4 years ago

ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco aplay: main:722: audio open error: No such file or directory

That error indicates that bluealsa is not installed correctly. Possibly the config file 20-bluealsa.conf is missing or in the wrong directory. I think it should be installed as /usr/share/alsa/alsa.conf.d/20-bluealsa.conf on Ubuntu 16.04.

Also check that the plugin libraries are correctly installed. Not sure how 16.04 organises it libraries, might be

/usr/lib/alsa-lib/libasound_module_ctl_bluealsa.so
/usr/lib/alsa-lib/libasound_module_pcm_bluealsa.so

or something like:

/usr/lib/arm-linux-aaaaaaaa/alsa-lib/libasound_module_ctl_bluealsa.so
/usr/lib/arm-linux-aaaaaaaa/alsa-lib/libasound_module_pcm_bluealsa.so

(where aaaaaaaa is the abi used by this system, gnueabihf or whatever.

If pulseaudio is installed, you'll also see the pulse plugin in the same directory:

libasound_module_pcm_pulse.so

You may ask why I don't just run pulseaudio on the Zedboard since that appears to work on both play and record (input and output) - the reason is that the board is rather large and I need to use the somewhat more compact Cora Zynq board.

Please don't give up on this - I'm very interested to understand why this is not working, and if it turns out there's a bug in bluealsa I'm sure @Arkq will be keen to find and fix it!

arkq commented 4 years ago

Of course I will help to fix the bug (if it is indeed in bluez-alsa somewhere) :). However, I will repeat my question. @grahamnaylorccfe, please try to build bluez-alsa without Broadcom fixup (e.g. use no-broadcom-setup branch) and check whether it will work or not.

grahamnaylorccfe commented 4 years ago

Thanks guys - I really appreciate your help on this. I will try the no-broadcom-setup branch and let you know how I get on. Do you think there could be any chance that there is a missing module in the Linux kernel? We believed that everything for BT had been included. Cheers G

borine commented 4 years ago

Do you think there could be any chance that there is a missing module in the Linux kernel

Given that HSP playback is working, I think it is unlikely that any kernel modules are missing. If pulseaudio bluetooth capture is working, then there are definitely no kernel modules missing.

If you can assemble a test platform on which your headset and one or both of your BT dongles work with pulseaudio but not bluealsa and arecord, then when should be able to work out where the error is.

grahamnaylorccfe commented 4 years ago

I re-built bluez-alsa (after re-imaging the SD card back to a working state) with the no-broadcom-setup (but am using the CSR dongle - will try the ASUS broadcom dongle later)

That error indicates that bluealsa is not installed correctly. Possibly the config file 20-bluealsa.conf is missing or in the wrong directory. I think it should be installed as /usr/share/alsa/alsa.conf.d/20-bluealsa.conf on Ubuntu 16.04.

Yes this file is present.

or something like:

/usr/lib/arm-linux-gnueabihf/alsa-lib/libasound_module_ctl_bluealsa.so
/usr/lib/arm-linux-gnueabihf/alsa-lib/libasound_module_pcm_bluealsa.so

files also present

If pulseaudio is installed, you'll also see the pulse plugin in the same directory:

libasound_module_pcm_pulse.so

also present

Please don't give up on this - I'm very interested to understand why this is not working, and if it turns out there's a bug in bluealsa I'm sure @Arkq will be keen to find and fix it!

Still getting the same error with aplay suggesting the incorrect installation, however I don't think I missed a step.

Will try the Broadcom dongle next

grahamnaylorccfe commented 4 years ago

Do you think there could be any chance that there is a missing module in the Linux kernel

Given that HSP playback is working, I think it is unlikely that any kernel modules are missing. If pulseaudio bluetooth capture is working, then there are definitely no kernel modules missing.

If you can assemble a test platform on which your headset and one or both of your BT dongles work with pulseaudio but not bluealsa and arecord, then when should be able to work out where the error is.

To be fair, on the smaller board (Cora), pulseaudio does not work on parecord either, hower parecord does work on the larger Zedboard (but with an older Linux kernel, but likely with a different set of kernel modules).

grahamnaylorccfe commented 4 years ago

Tried with the Broadcom dongle. I get the same error: [bluetooth]# connect 50:19:01:90:7F:39 Attempting to connect to 50:19:01:90:7F:39 [CHG] Device 50:19:01:90:7F:39 Connected: yes Connection successful [Trinida]# quit [DEL] Controller 5C:F3:70:99:0E:8C localhost.localdomain [default] root@localhost:~# aplay -D bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco sample.wav ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco aplay: main:722: audio open error: No such file or directory root@localhost:~#

I get this in the bluealsa window: bluealsa: D: ../../src/ba-transport.c:1020: Created new thread [ba-sco]: HSP Audio Gateway bluealsa: D: ../../src/sco.c:241: Starting SCO loop: HSP Audio Gateway bluealsa: D: ../../src/ba-rfcomm.c:880: Starting RFCOMM loop: HSP Audio Gateway bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HSP Audio Gateway state transition: 0 -> 9 bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGS, value:12 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0012-0001-0100,3 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK bluealsa: D: ../../src/at.c:161: AT message: SET: command:+IPHONEACCEV, value:2,1,8,2,0 bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK

but no logging from the aplay command.

arkq commented 4 years ago

Strange, if you like we can talk on freenode #bluealsa in about an hour or so (right now I'm busy).

borine commented 4 years ago

ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM

That error message is from libasound, and results when snd_config_search_definition() cannot find a match for the given name in its configuration. The name it is looking for in this case is bluealsa. This means that libasaound cannot find, or cannot read, the definition of a pcm.bluealsa (which is in the file 20-bluealsa.conf).

I don't have access to an Lubuntu 16.04 installation, so I can't check where its confgured alsa datadir is. What version of libasound does it have (aplay --version)? I'll look into the source code for that version to see if I can guess some likely locations for its datadir.

grahamnaylorccfe commented 4 years ago

For the Zedboard: aplay: version 1.1.0 by Jaroslav Kysela perex@perex.cz For the Cora aplay: version 1.1.3 by Jaroslav Kysela perex@perex.cz

G

borine commented 4 years ago

just had a look at alsa-lib 1.1.0 source. It has much less informative error messages than later versions, to the error

ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM

might also result if it found the bluealsa definition, but the parameters were wrong. So perhaps it has on old version of the file libasound_module_pcm_bluealsa.so with a new version of 20-bluealsa.conf, or vice-versa. You could test this by invoking aplay as:

aplay -D bluealsa:DEV=50:19:01:90:7F:39,PROFILE=sco

and see if the outcome or error message changes

grahamnaylorccfe commented 4 years ago

I ran the aplay command as suggested and got the same error with the Zedboard:

aplay -D bluealsa:DEV=50:19:01:90:7F:39,PROFILE=sco ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM bluealsa:DEV=50:19:01:90:7F:39,PROFILE=sco aplay: main:722: audio open error: No such file or directory root@localhost:~#

borine commented 4 years ago

If alsa-lib finds the bluealsa pcm definition, and successfully loads the bluealsa pcm shared library, then you would not see the error audio open error: No such file or directory. If the device is not connected to bluealsa with the selected profile the error message would be Couldn't get BlueALSA PCM:, which is generated by the bluealsa pcm shared library.

So it is certain that alsa-lib is failing to load the bluealsa pcm. Possible causes that I can think of:

To check for the last option, try ldd /usr/lib/arm-linux-gnueabihf/alsa-lib/libasound_module_pcm_bluealsa.so

grahamnaylorccfe commented 4 years ago

I have abandoned the Zedboard for the moment as that would in any case be a dead end as it is the Cora board that I need to function. I returned to a basic linux installation without pulseaudio and installed the dependencies for bluez-alsa (bluez alsa utils alsa-lib etc..) and performed the installation. Everything seemed to proceed OK, but with the same result. aplay works fine but arecord gives only a 44byte file (but no apparent errors). From btmon --sco get:

@ RAW Open: bluealsa (privileged) version 2.22 {0x0004} 717.723886 @ RAW Close: bluealsa {0x0004} 717.724278 < HCI Command: Setup Synchronous Connection (0x01|0x0028) plen 17 #4139 [hci0] 717.724709 Handle: 69 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 #4140 [hci0] 717.730666 Setup Synchronous Connection (0x01|0x0028) ncmd 1 Status: Success (0x00) HCI Event: Max Slots Change (0x1b) plen 3 #4141 [hci0] 717.746683 Handle: 69 Max slots: 1 HCI Event: Synchronous Connect Complete (0x2c) plen 17 #4142 [hci0] 717.753670 Status: Success (0x00) Handle: 71 Address: 50:19:01:90:7F:39 (OUI 50-19-01) 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 71 flags 0x00 dlen 48 #4143 [hci0] 717.757025 00 09 8c 09 00 0a 00 0a d1 0a 00 0b 00 0b 00 0a ................ 00 0b 67 0a 00 0a 00 0a 00 0a 60 09 00 09 dd 08 ..g.......`..... 00 08 5a 07 00 07 00 06 00 05 54 04 00 03 00 03 ..Z.......T..... HCI Event: Max Slots Change (0x1b) plen 3 #4144 [hci0] 717.764700 Handle: 69 Max slots: 5 ACL Data RX: Handle 69 flags 0x02 dlen 20 #4145 [hci0] 721.778701 Channel: 65 len 16 [PSM 0 mode 0] {chan 0} 11 ef 19 41 54 2b 43 4b 50 44 3d 32 30 30 0d bf ...AT+CKPD=200.. < ACL Data TX: Handle 69 flags 0x00 dlen 17 #4146 [hci0] 721.779200 Channel: 513 len 13 [PSM 0 mode 0] {chan 0} 13 ef 13 0d 0a 45 52 52 4f 52 0d 0a 65 .....ERROR..e HCI Event: Number of Completed Packets (0x13) plen 5 #4147 [hci0] 721.784689 Num handles: 1 Handle: 69 Count: 1 ACL Data RX: Handle 69 flags 0x02 dlen 9 #4148 [hci0] 721.787693 Channel: 65 len 5 [PSM 0 mode 0] {chan 0} 11 ff 01 01 a3 ..... ACL Data RX: Handle 69 flags 0x02 dlen 20 #4149 [hci0] 723.968699 Channel: 65 len 16 [PSM 0 mode 0] {chan 0} 11 ef 19 41 54 2b 43 4b 50 44 3d 32 30 30 0d bf ...AT+CKPD=200.. < ACL Data TX: Handle 69 flags 0x00 dlen 17 #4150 [hci0] 723.969010 Channel: 513 len 13 [PSM 0 mode 0] {chan 0} 13 ef 13 0d 0a 45 52 52 4f 52 0d 0a 65 .....ERROR..e HCI Event: Number of Completed Packets (0x13) plen 5 #4151 [hci0] 723.974693 Num handles: 1 Handle: 69 Count: 1 ACL Data RX: Handle 69 flags 0x02 dlen 9 #4152 [hci0] 723.977696 Channel: 65 len 5 [PSM 0 mode 0] {chan 0} 11 ff 01 01 a3 ..... ACL Data RX: Handle 69 flags 0x02 dlen 20 #4153 [hci0] 726.902705 Channel: 65 len 16 [PSM 0 mode 0] {chan 0} 11 ef 19 41 54 2b 43 4b 50 44 3d 32 30 30 0d bf ...AT+CKPD=200.. < ACL Data TX: Handle 69 flags 0x00 dlen 17 #4154 [hci0] 726.903003 Channel: 513 len 13 [PSM 0 mode 0] {chan 0} 13 ef 13 0d 0a 45 52 52 4f 52 0d 0a 65 .....ERROR..e HCI Event: Number of Completed Packets (0x13) plen 5 #4155 [hci0] 726.910706 Num handles: 1 Handle: 69 Count: 1 ACL Data RX: Handle 69 flags 0x02 dlen 9 #4156 [hci0] 726.917702 Channel: 65 len 5 [PSM 0 mode 0] {chan 0} 11 ff 01 01 a3 .....

The first 48 bytes of the stream seemed to be received and then when I press the call button I get the AT commands picked up (followed by the text 'ERROR..e'). No audio though.

In the bluealsa window I get:

bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_50_19_01_90_7F_39/hspag/source bluealsa: D: ../../src/ba-transport.c:962: New SCO link: 50:19:01:90:7F:39: 18 bluealsa: D: ../../src/hci.c:132: SCO link socket MTU: 18: 64 bluealsa: D: ../../src/ba-transport.c:787: PCM resumed: 15

Anything else I should check? cheers Graham

arkq commented 4 years ago

Please collect whole BT session with tcpdump (pcap library has to be compiled with bluetooth support). Just remember to start tcpdump before BT connection (pairing might be done earlier), so whole session will be dumped. Start it as follows (and attach dump in this issue thread):

tcpdump -i bluetooth0 -w /tmp/xxx.dump

Also, if you've got Android smartphone, try to make the same setup with it and collect HCI snoop log (e.g. https://stackoverflow.com/questions/28445552/bluetooth-hci-snoop-log-not-generated), post dump here.

Then we can compare both dumps and see where is the difference.

grahamnaylorccfe commented 4 years ago

Here is the text of the dump when connecting and then trying the arecord command:

tcpdump -r /tmp/connect_record.dump reading from file /tmp/connect_record.dump, link-type BLUETOOTH_HCI_H4_WITH_PHDR (Bluetooth HCI UART transport layer plus pseudo-header) 22:30:47.647525 0x0000: 0105 040d 397f 9001 1950 18cc 0200 0000 ....9....P...... 0x0010: 01 . 22:30:47.660516 0x0000: 040f 0400 0105 04 ....... 22:30:50.365538 0x0000: 0403 0b00 4600 397f 9001 1950 0100 ....F.9....P.. 22:30:50.366800 0x0000: 011b 0402 4600 ....F. 22:30:50.371573 0x0000: 0420 0739 7f90 0119 5001 ...9....P. 22:30:50.373538 0x0000: 040f 0400 001b 04 ....... 22:30:50.375535 0x0000: 041b 0346 0005 ...F.. 22:30:50.388543 0x0000: 040f 0400 0100 00 ....... 22:30:50.388611 0x0000: 011a 0c01 00 ..... 22:30:50.393526 0x0000: 040e 0401 1a0c 00 ....... 22:30:50.492538 0x0000: 040b 0b00 4600 ffff 8ffa dbff 5b87 ....F.......[. 22:30:50.492598 0x0000: 011c 0403 4600 01 ....F.. 22:30:50.497528 0x0000: 040f 0400 011c 04 ....... 22:30:50.503557 0x0000: 0423 0d00 4600 0101 0300 0000 0000 0000 .#..F........... 22:30:50.503623 0x0000: 0119 040a 397f 9001 1950 0200 0000 ....9....P.... 22:30:50.503642 0x0000: 0246 000a 0006 0001 000a 0102 0002 00 .F............. 22:30:50.509527 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.511530 0x0000: 040f 0400 0119 04 ....... 22:30:50.512533 0x0000: 0246 2010 000c 0001 000b 0108 0002 0000 .F.............. 0x0010: 00b8 0000 00 ..... 22:30:50.512585 0x0000: 0246 000a 0006 0001 000a 0202 0003 00 .F............. 22:30:50.518531 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.541547 0x0000: 0246 2011 0010 0001 000b 020c 0003 0000 .F.............. 0x0010: 0076 0000 0000 .v.... 22:30:50.542532 0x0000: 0246 1003 0000 0000 .F...... 22:30:50.542585 0x0000: 0246 000c 0008 0001 0002 0304 0001 0040 .F.............@ 0x0010: 00 . 22:30:50.553545 0x0000: 0246 2010 000c 0001 0003 0308 0080 0240 .F.............@ 0x0010: 0001 0002 00 ..... 22:30:50.556529 0x0000: 0246 2010 000c 0001 0003 0308 0080 0240 .F.............@ 0x0010: 0000 0000 00 ..... 22:30:50.556579 0x0000: 0246 0017 0013 0001 0004 040f 0080 0200 .F.............. 0x0010: 0004 0900 0000 0000 0000 0000 ............ 22:30:50.557551 0x0000: 0246 2010 000c 0001 0004 0108 0040 0000 .F...........@.. 0x0010: 0001 0230 00 ...0. 22:30:50.557604 0x0000: 0246 0012 000e 0001 0005 010a 0080 0200 .F.............. 0x0010: 0000 0001 0230 00 .....0. 22:30:50.563538 0x0000: 0246 200e 000a 0001 0005 0406 0040 0000 .F...........@.. 0x0010: 0000 00 ... 22:30:50.563749 0x0000: 0246 0018 0014 0080 0206 0000 000f 3503 .F............5. 0x0010: 1911 08ff ff35 050a 0000 ffff 00 .....5....... 22:30:50.571532 0x0000: 0407 ff00 397f 9001 1950 5472 696e 6964 ....9....PTrinid 0x0010: 6100 0000 0000 0000 0000 0000 0000 0000 a............... 0x0020: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0030: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0040: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0050: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0060: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0070: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0080: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0090: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00a0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00b0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00c0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00d0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00e0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x00f0: 0000 0000 0000 0000 0000 0000 0000 0000 ................ 0x0100: 0000 .. 22:30:50.573554 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.574542 0x0000: 0246 2034 0030 0040 0007 0000 002b 0026 .F.4.0.@.....+.& 0x0010: 3600 5636 0053 0900 000a 0001 0005 0900 6.V6.S.......... 0x0020: 0135 0919 1108 1911 3119 1203 0900 0435 .5......1......5 0x0030: 0c35 0319 0100 0200 33 .5......3 22:30:50.575538 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.577536 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.578561 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.586636 0x0000: 0246 001a 0016 0080 0206 0001 0011 3503 .F............5. 0x0010: 1911 08ff ff35 050a 0000 ffff 0200 33 .....5........3 22:30:50.591554 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.602535 0x0000: 0246 2034 0030 0040 0007 0001 002b 0026 .F.4.0.@.....+.& 0x0010: 3505 1900 0308 0409 0006 3509 0965 6e09 5.........5..en. 0x0020: 006a 0901 0009 0009 3508 3506 1911 0809 .j......5.5..... 0x0030: 0102 0901 0025 0200 0d .....%... 22:30:50.602758 0x0000: 0246 001a 0016 0080 0206 0002 0011 3503 .F............5. 0x0010: 1911 08ff ff35 050a 0000 ffff 0200 0d .....5......... 22:30:50.608536 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.613536 0x0000: 0246 2019 0015 0040 0007 0002 0010 000d .F.....@........ 0x0010: 0748 6561 6473 6574 0903 0228 0100 .Headset...(.. 22:30:50.613940 0x0000: 0111 0402 4600 ....F. 22:30:50.617548 0x0000: 040f 0400 0111 04 ....... 22:30:50.619529 0x0000: 0417 0639 7f90 0119 50 ...9....P 22:30:50.619581 0x0000: 010b 0416 397f 9001 1950 33a6 8a5d 9a18 ....9....P3..].. 0x0010: 2bf4 218a 5162 81bd 4351 +.!.Qb..CQ 22:30:50.625534 0x0000: 040e 0a01 0b04 0039 7f90 0119 50 .......9....P 22:30:50.690536 0x0000: 0406 0300 4600 ....F. 22:30:50.690589 0x0000: 0113 0403 4600 01 ....F.. 22:30:50.696537 0x0000: 040f 0400 0113 04 ....... 22:30:50.798541 0x0000: 0408 0400 4600 01 ....F.. 22:30:50.798599 0x0000: 0108 1402 4600 ....F. 22:30:50.803531 0x0000: 040e 0701 0814 0046 0010 .......F.. 22:30:50.803602 0x0000: 0246 000c 0008 0001 0002 0504 0003 0041 .F.............A 0x0010: 00 . 22:30:50.810535 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.812533 0x0000: 0246 2010 000c 0001 0003 0508 00c1 0241 .F.............A 0x0010: 0001 0002 00 ..... 22:30:50.814535 0x0000: 0246 2010 000c 0001 0003 0508 00c1 0241 .F.............A 0x0010: 0000 0000 00 ..... 22:30:50.814587 0x0000: 0246 001b 0017 0001 0004 0613 00c1 0200 .F.............. 0x0010: 0001 02f5 0304 0900 0000 0000 0000 0000 ................ 22:30:50.816540 0x0000: 0246 2010 000c 0001 0004 0208 0041 0000 .F...........A.. 0x0010: 0001 02b6 0f ..... 22:30:50.816593 0x0000: 0246 0012 000e 0001 0005 020a 00c1 0200 .F.............. 0x0010: 0000 0001 02b6 0f ....... 22:30:50.819534 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.820535 0x0000: 0246 2012 000e 0001 0005 060a 0041 0000 .F...........A.. 0x0010: 0000 0001 02f5 03 ....... 22:30:50.820613 0x0000: 0246 0008 0004 00c1 0203 3f01 1c .F........?.. 22:30:50.821537 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.828538 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.828557 0x0000: 0246 2008 0004 0041 0003 7301 d7 .F.....A..s.. 22:30:50.828638 0x0000: 0246 0012 000e 00c1 0203 ef15 8311 08f0 .F.............. 0x0010: 0700 f003 0007 70 ......p 22:30:50.834540 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.839535 0x0000: 0246 2012 000e 0041 0001 ef15 8111 08e0 .F.....A........ 0x0010: 0700 7403 0001 aa ..t.... 22:30:50.839612 0x0000: 0246 0008 0004 00c1 0223 3f01 c9 .F.......#?.. 22:30:50.845534 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.850540 0x0000: 0246 2008 0004 0041 0023 7301 02 .F.....A.#s.. 22:30:50.850623 0x0000: 0246 000c 0008 00c1 0203 ef09 e305 238d .F............#. 0x0010: 70 p 22:30:50.853554 0x0000: 0246 200c 0008 0041 0001 ef09 e305 238d .F.....A......#. 0x0010: aa . 22:30:50.853929 0x0000: 0246 000c 0008 00c1 0203 ef09 e105 238d .F............#. 0x0010: 70 p 22:30:50.856551 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.858545 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.858574 0x0000: 0246 200c 0008 0041 0001 ef09 e105 238d .F.....A......#. 0x0010: aa . 22:30:50.858675 0x0000: 0246 0009 0005 00c1 0223 ff01 2146 .F.......#..!F 22:30:50.864010 0x0000: 0246 0018 0014 0080 0206 0003 000f 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 00 .....5....... 22:30:50.864552 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.868542 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.908541 0x0000: 0246 2009 0005 0041 0021 ff01 019c .F.....A.!.... 22:30:50.911538 0x0000: 0246 2034 0030 0040 0007 0003 002b 0026 .F.4.0.@.....+.& 0x0010: 3601 1036 0059 0900 000a 0001 0000 0900 6..6.Y.......... 0x0020: 0135 0619 111e 1912 0309 0004 350c 3503 .5..........5.5. 0x0030: 1901 0035 0519 0200 ed ...5..... 22:30:50.911761 0x0000: 0246 001a 0016 0080 0206 0004 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 ed .....5......... 22:30:50.912550 0x0000: 0246 2012 000e 0041 0021 ef15 4154 2b56 .F.....A.!..AT+V 0x0010: 4753 3d30 330d 80 GS=03.. 22:30:50.914344 0x0000: 0246 000e 000a 00c1 0223 ef0d 0d0a 4f4b .F.......#....OK 0x0010: 0d0a 5a ..Z 22:30:50.916552 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.918547 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.918569 0x0000: 0246 2034 0030 0040 0007 0004 002b 0026 .F.4.0.@.....+.& 0x0010: 0003 0801 0900 0635 0909 656e 0900 6a09 .......5..en..j. 0x0020: 0100 0900 0935 0835 0619 111e 0901 0609 .....5.5........ 0x0030: 0100 250f 4861 0200 c7 ..%.Ha... 22:30:50.918813 0x0000: 0246 001a 0016 0080 0206 0005 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 c7 .....5......... 22:30:50.921535 0x0000: 0246 2009 0005 0041 0021 ff01 019c .F.....A.!.... 22:30:50.922538 0x0000: 0246 2021 001d 0041 0021 ef33 4154 2b58 .F.!...A.!.3AT+X 0x0010: 4150 4c3d 3030 3132 2d30 3030 312d 3031 APL=0012-0001-01 0x0020: 3030 2c33 0d80 00,3.. 22:30:50.923997 0x0000: 0246 001c 0018 00c1 0223 ef29 0d0a 2b58 .F.......#.)..+X 0x0010: 4150 4c3d 426c 7565 414c 5341 2c36 0d0a APL=BlueALSA,6.. 0x0020: 5a Z 22:30:50.924436 0x0000: 0246 000e 000a 00c1 0223 ef0d 0d0a 4f4b .F.......#....OK 0x0010: 0d0a 5a ..Z 22:30:50.924554 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.925551 0x0000: 0246 2034 0030 0040 0007 0005 002b 0026 .F.4.0.@.....+.& 0x0010: 6e64 732d 4672 6565 2075 6e69 7409 0311 nds-Free.unit... 0x0020: 0900 3f36 0038 0900 000a 0001 0002 0900 ..?6.8.......... 0x0030: 0135 0319 110b 0200 a1 .5....... 22:30:50.925776 0x0000: 0246 001a 0016 0080 0206 0006 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 a1 .....5......... 22:30:50.928536 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.930549 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.930569 0x0000: 0246 2009 0005 0041 0021 ff01 019c .F.....A.!.... 22:30:50.932536 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.933537 0x0000: 0246 2009 0005 0041 0021 ff01 019c .F.....A.!.... 22:30:50.938548 0x0000: 0246 2021 001d 0041 0021 ef33 4154 2b49 .F.!...A.!.3AT+I 0x0010: 5048 4f4e 4541 4343 4556 3d32 2c31 2c38 PHONEACCEV=2,1,8 0x0020: 2c32 2c30 0d80 ,2,0.. 22:30:50.939552 0x0000: 0246 2034 0030 0040 0007 0006 002b 0026 .F.4.0.@.....+.& 0x0010: 0900 0435 1035 0619 0100 0900 1935 0619 ...5.5.......5.. 0x0020: 0019 0901 0209 0009 3508 3506 1911 0d09 ........5.5..... 0x0030: 0102 0903 1109 0200 7b ........{ 22:30:50.940213 0x0000: 0246 001a 0016 0080 0206 0007 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 7b .....5........{ 22:30:50.941043 0x0000: 0246 000e 000a 00c1 0223 ef0d 0d0a 4f4b .F.......#....OK 0x0010: 0d0a 5a ..Z 22:30:50.945540 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.947546 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.947568 0x0000: 0246 2034 0030 0040 0007 0007 002b 0026 .F.4.0.@.....+.& 0x0010: 0001 3600 3b09 0000 0a00 0100 0309 0001 ..6.;........... 0x0020: 3506 1911 0e19 110f 0900 0435 1035 0619 5..........5.5.. 0x0030: 0100 0900 1735 0200 55 .....5..U 22:30:50.947806 0x0000: 0246 001a 0016 0080 0206 0008 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 55 .....5........U 22:30:50.949535 0x0000: 0246 2009 0005 0041 0021 ff01 019c .F.....A.!.... 22:30:50.953537 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.955538 0x0000: 0246 2034 0030 0040 0007 0008 002b 0026 .F.4.0.@.....+.& 0x0010: 0619 0017 0901 0309 0009 3508 3506 1911 ..........5.5... 0x0020: 0e09 0104 0903 1109 0001 3600 3809 0000 ..........6.8... 0x0030: 0a00 0100 0409 0200 2f ......../ 22:30:50.955718 0x0000: 0246 001a 0016 0080 0206 0009 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 2f .....5......../ 22:30:50.966539 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.987536 0x0000: 0246 2034 0030 0040 0007 0009 002b 0026 .F.4.0.@.....+.& 0x0010: 0001 3503 1911 0c09 0004 3510 3506 1901 ..5.......5.5... 0x0020: 0009 0017 3506 1900 1709 0103 0900 0935 ....5..........5 0x0030: 0835 0619 110e 0200 09 .5....... 22:30:50.987723 0x0000: 0246 001a 0016 0080 0206 000a 0011 3503 .F............5. 0x0010: 1901 00ff ff35 050a 0000 ffff 0200 09 .....5......... 22:30:50.993537 0x0000: 0413 0501 4600 0100 ....F... 22:30:50.998542 0x0000: 0246 2015 0011 0040 0007 000a 000c 0009 .F.....@........ 0x0010: 0901 0409 0311 0900 0200 .......... 22:30:51.013143 0x0000: 0246 0018 0014 0080 0206 000b 000f 3503 .F............5. 0x0010: 1912 00ff ff35 050a 0000 ffff 00 .....5....... 22:30:51.016542 0x0000: 0413 0501 4600 0100 ....F... 22:30:51.027541 0x0000: 0246 200e 000a 0040 0007 000b 0005 0002 .F.....@........ 0x0010: 3500 00 5.. 22:30:52.819421 0x0000: 0246 000c 0008 0001 0006 0704 0080 0240 .F.............@ 0x0010: 00 . 22:30:52.823561 0x0000: 0413 0501 4600 0100 ....F... 22:30:52.845560 0x0000: 0246 200c 0008 0001 0007 0704 0080 0240 .F.............@ 0x0010: 00 . 22:30:58.857792 0x0000: 0128 0411 4600 401f 0000 401f 0000 0a00 .(..F.@...@..... 0x0010: 6000 0180 03 `.... 22:30:58.863505 0x0000: 040f 0400 0128 04 .....(. 22:30:58.868594 0x0000: 041b 0346 0001 ...F.. 22:30:58.874578 0x0000: 042c 1100 4100 397f 9001 1950 020c 023c .,..A.9....P...< 0x0010: 003c 0002 .<.. 22:30:58.897612 0x0000: 041b 0346 0005 ...F.. 22:31:05.409048 0x0000: 0106 0403 4100 13 ....A.. 22:31:05.412641 0x0000: 040f 0400 0106 04 ....... 22:31:05.418618 0x0000: 0405 0400 4100 16 ....A..

When I did connect and aplay I got a very long dump, that I assumed was OK. Tomorrow I will try and do the same on a regular Ubuntu PC (not sure how to get the log on my android ¯_(ツ)_/¯ - is there a handy app ;-), I don't have any dev tools on it). G

grahamnaylorccfe commented 4 years ago

I couldn't seem to get bluealsa working on my Ubuntu PC for some reason, but then I tried getting the HCI log on my Android phone as you suggested. This turned out to be stupidly easy thanks to youtube (source of all knowledge after github :-) ). I set up the log, connected to the headset, recorded a message then played it back (worked fine) and grabbed the full report. Here is I believe the relevent part of the very long output:


07-13 19:47:48.639--btsnoop.cc -- Config HCI log for external : enable=0 07-13 19:47:48.642--AdapterState Current state: Turning BLE OFF, message: BLE_STOPPED 07-13 19:47:48.644--AdapterState Entering BT OFF 07-13 19:47:48.685--BluetoothManagerService Call sendEnableMsg to recover. mErrorRecoveryRetryCounter : 1 07-13 19:47:48.702--BluetoothAdapter -- enableRadio() called by PID : 4266 @ null 07-13 19:47:48.702--BluetoothAdapter -- enableRadio() called by PID : 29435 @ com.samsung.android.beaconmanager 07-13 19:47:48.734--BluetoothManagerService -- enableBle(null) BT ManagerService enableBle called 07-13 19:47:48.739--BluetoothManagerService -- enableBle(com.samsung.android.beaconmanager) BT ManagerService enableBle called 07-13 19:47:52.555--BluetoothAdapter -- enable() called by PID : 6254 @ com.android.settings 07-13 19:47:52.556--BluetoothAdapter -- enable() Call : ManagerService enable 07-13 19:47:52.558--BluetoothManagerService -- enable() BT ManagerService enable called 07-13 19:47:52.566--BluetoothManagerService -- Persisting Bluetooth Setting : 1 07-13 19:47:52.966--AdapterState Entering BT OFF 07-13 19:47:53.061--BluetoothManagerService BLUETOOTH_SERVICE_CONNECTED: 1 07-13 19:47:53.088--AdapterState Current state: BT OFF, message: BLE_TURN_ON 07-13 19:47:53.092--AdapterState Entering Turning BLE ON 07-13 19:47:53.200--btsnoop.cc -- Config HCI log for external : enable=0 07-13 19:47:53.384--btif_storage.cc -- before ssSupport 07-13 19:47:53.386--btif_storage.cc -- after ssSupport = 1 vkSupport = 0 07-13 19:47:53.680--BluetoothRemoteDevices -- AbstractionLayer.BT_PROPERTY_UUIDS, device is 940E6B, AudioSource 07-13 19:47:53.693--BluetoothRemoteDevices -- AbstractionLayer.BT_PROPERTY_UUIDS, device is 414217, Handsfree,AudioSink,AvrcpController 07-13 19:47:53.705--[5008]{0029})(04::0) 07-13 19:47:53.706--[5008]{002A}(20::80)(04::0) 07-13 19:47:53.708--PFQU-connect : empty 07-13 19:47:53.710--AdapterState Current state: Turning BLE ON, message: BLE_STARTED 07-13 19:47:53.721--AdapterState Entering BLE ON 07-13 19:47:53.728--BluetoothManagerService bluetooth is recovered from error. Reset mErrorRecoveryRetryCounter as Zero 07-13 19:47:53.729--BluetoothManagerService BLUETOOTH_SERVICE_CONNECTED: 2 07-13 19:47:53.742--AdapterState Current state: BLE ON, message: USER_TURN_ON 07-13 19:47:53.743--AdapterState Entering Turning BT ON 07-13 19:47:53.764--BtGatt.GattService registerServer(android.uid.system) 07-13 19:47:53.969--HFS-IBR true/true 07-13 19:47:53.974--HFIF-max4 eh_sco1 data_path1 IBR1 RVP1/0 DBG1 07-13 19:47:53.976--HFIF-BRSF 4079(0,0) 07-13 19:47:54.089--bta_hh_act.cc -- HID HOST registering success, bta_hh_api_enable() 07-13 19:47:54.240--PBL-pbap12_default, 02_Default 07-13 19:47:54.269--AdapterState Current state: Turning BT ON, message: BREDR_STARTED 07-13 19:47:54.281--AdapterState Entering BT ON 07-13 19:47:54.295--HFBMS-already binded PSC 07-13 19:47:54.299--SapService -- S1(LOADED), S2(ABSENT) 07-13 19:47:54.301--SapService -- S1(LOADED), S2(ABSENT) 07-13 19:47:54.303--SapService -- SIM state changed, enable SDP again 07-13 19:47:54.308--HFIF-DBFW1 SDMP0 07-13 19:47:54.356--SapService -- S1(LOADED), S2(ABSENT) 07-13 19:47:54.433--[1006]{001A}(03::null) 07-13 19:47:54.442--HFBMS-PSC onServiceConnected 07-13 19:47:54.519--HFPS-MS1 CTC0 RAT0 T0 07-13 19:47:54.696--HFS-nA0 nH0 s6 p-1 07-13 19:47:54.756--bta_dm_act.cc -- Set p_search_cback for Inquiry 07-13 19:47:54.765--BluetoothAdapter -- setScanMode() Mode :23, duration : 120, called by PID : 6254 @ com.android.settings 07-13 19:47:55.796--BluetoothUtils[ADVANCED OPP] failed to get p2p mac in time 07-13 19:47:55.798--BluetoothUtils[ADVANCED OPP] mWifiP2pDevice is NULL 07-13 19:47:59.284--BluetoothRemoteDevices -- ACTION_ACL_CONNECTED, device is 940E6B, linktype is 1 07-13 19:47:59.602--[0006]{000A}(27::CONNECTED)(13::5e8945b0-9525-11e3-a5e2-0800200c9a66)(01::940E6B) 07-13 19:48:05.742--DevPref -- onClicked :: [(N) Trinida], [10], [false], [240404], [0], [1] 07-13 19:48:05.747--bta_dm_act.cc -- Search Cancelled 07-13 19:48:05.750--BluetoothDevice -- createBond(0) for dev 501901 called by PID : 6254 @ com.android.settings 07-13 19:48:05.798--BluetoothBondStateMachine -- Bond State Change Intent:501901 OldState: 10 NewState: 11 07-13 19:48:15.583--BluetoothDevice -- setPairingConfirmation(true) for dev 501901 called by PID : 6254 @ com.android.settings 07-13 19:48:15.720--bta_dm_act.cc -- Set p_search_cback for Service Discovery 07-13 19:48:15.743--BluetoothRemoteDevices -- ACTION_ACL_CONNECTED, device is 501901, linktype is 1 07-13 19:48:15.745--BluetoothAdapter -- setScanMode() Mode :23, duration : 120, called by PID : 6254 @ com.android.settings 07-13 19:48:15.984--sdp_discovery.cc -- SDP - No Attributes Returned for target UUID 07-13 19:48:16.151--BluetoothRemoteDevices -- AbstractionLayer.BT_PROPERTY_UUIDS, device is 501901, HSP,Handsfree,AudioSink,AvrcpController 07-13 19:48:16.155--bta_dm_act.cc -- Search Completed 07-13 19:48:16.168--HFS-setPriority 501901, 100, uid/pid=1002/7553 07-13 19:48:16.210--BluetoothBondStateMachine -- Bond State Change Intent:501901 OldState: 11 NewState: 12 07-13 19:48:16.225--BluetoothDataManager -- CONNECTION INFO : {"LO_MFN":"117","LO_LMP":"9","LO_SUB":"0","LO_FWV":"UTC|lassen_s612|S612_E788X_C1_Y20W18A","RE_OUI":"50:19:01","RE_NAM":"Trinida","RE_MFN":"-1","RE_LMP":"-1","RE_SUB":"-1","RE_COD":"2360324","RE_LTY":"-1","RE_ROL":"-1","RE_WEA":"0","CO_CFR":"0","CO_ADR":"","CO_HER":""} 07-13 19:48:16.337--HFFW-connect(501901) by 10389 @ com.android.systemui 07-13 19:48:16.418--HFSM-enter DISC (501901) / 0 07-13 19:48:16.420--HFSM-DISC MSG_1 (501901) 07-13 19:48:16.422--PFQU-add : 111f 07-13 19:48:16.423--PFQU-connect : 111f 07-13 19:48:16.424--HFIF-connect_int([0] 501901) 07-13 19:48:16.426--HFAGSDP-init 07-13 19:48:16.427--BluetoothA2dp -- connect(501901) called by PID : 10389 @ com.android.systemui 07-13 19:48:16.427--HFAGSDP-start 07-13 19:48:16.434--HFCM-isWatch : false(240404) 07-13 19:48:16.465--HFSM-enter CING (501901) 07-13 19:48:16.480--BluetoothPhonePolicy -- profileId = 1 : 0 -> 1 size 0 07-13 19:48:16.487--AdapterProp -- CONNECTION_STATE_CHANGE: 501901 : 0 -> 1 07-13 19:48:16.489--PFQU-add : 110a 07-13 19:48:16.491--AdapterProp -- Connection status :: [Connecting]1, [Connected]0, [Disconnecting]0 07-13 19:48:16.492--PFQU-connect : 111f 07-13 19:48:16.501--HFAGAct-sdp comp(0x0510) 0 07-13 19:48:16.534--BluetoothPhonePolicy -- profileId = 2 : 0 -> 1 size 0 07-13 19:48:16.535--AdapterProp -- Connection status :: [Connecting]2, [Connected]0, [Disconnecting]0 07-13 19:48:16.537--A2DPSVC-Connection state 90:7: 0->1, conn : 0 07-13 19:48:16.682--HFSM-CING ConnE_2 (501901) 07-13 19:48:16.691--HFAGCmd-AG F : 4079, HF F : 191 07-13 19:48:16.695--HFSM-connected device : 501901_191 07-13 19:48:16.701--HFAGCmd-Recv BAC 3 07-13 19:48:16.764--HFSM-CING ConnE_3 (501901) 07-13 19:48:16.766--PFQU-remove : 111f 07-13 19:48:16.767--PFQU-connect : 110a 07-13 19:48:16.770--HFSM-enter CONN (501901, false) / 1 07-13 19:48:16.773--A2DPSM-Connecting ConnectionEvent device : 90:7, state : 1 07-13 19:48:16.775--HFAM-setHighPriorityDevice : null to 501901 07-13 19:48:16.826--HFS-setActiveDevice : null > 501901 07-13 19:48:16.828--BluetoothPhonePolicy -- profileId = 1 : 1 -> 2 size 0 07-13 19:48:16.846--AdapterProp -- CONNECTION_STATE_CHANGE: 501901 : 1 -> 2 07-13 19:48:16.850--AdapterProp -- Connection status :: [Connecting]1, [Connected]1, [Disconnecting]0 07-13 19:48:16.859--HFS-nA0 nH0 s6 p1 07-13 19:48:16.955--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : -1 07-13 19:48:16.975--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : -1 07-13 19:48:17.153--A2DPSM-Connecting ConnectionEvent device : 90:7, state : 2 07-13 19:48:17.156--PFQU-remove : 110a 07-13 19:48:17.159--PFQU-connect : empty 07-13 19:48:17.187--BluetoothPhonePolicy -- profileId = 2 : 1 -> 2 size 0 07-13 19:48:17.192--AdapterProp -- Connection status :: [Connecting]0, [Connected]2, [Disconnecting]0 07-13 19:48:17.202--A2DPSVC-Connection state 90:7: 1->2, conn : 1 07-13 19:48:17.208--A2DPBD-"TrinidX(50:19:01,SBC) connected"{"CCOD":"0","PCOD":"0"} 07-13 19:48:17.225--BluetoothDataManager -- CONNECTION INFO : {"LO_MFN":"117","LO_LMP":"9","LO_SUB":"0","LO_FWV":"UTC|lassen_s612|S612_E788X_C1_Y20W18A","RE_OUI":"50:19:01","RE_NAM":"Trinida","RE_MFN":"10","RE_LMP":"7","RE_SUB":"8648","RE_COD":"2360324","RE_LTY":"1","RE_ROL":"0","RE_WEA":"0","CO_CFR":"0","CO_ADR":"","CO_HER":""} 07-13 19:48:17.250--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : 100 07-13 19:48:17.315--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : 100 07-13 19:48:19.428--AVRCP-(90:7) feature: 3 07-13 19:48:21.194--BluetoothAdapter -- setScanMode() Mode :21, duration : 120, called by PID : 6254 @ com.android.settings 07-13 19:48:23.284--BluetoothDevice -- fetchUuidsWithSdp() for dev 501901 called by PID : 7348 @ com.google.android.projection.gearhead 07-13 19:48:23.292--bta_dm_act.cc -- Set p_search_cback for Service Discovery 07-13 19:48:23.410--sdp_discovery.cc -- SDP - No Attributes Returned for target UUID 07-13 19:48:23.963--bta_dm_act.cc -- Search Completed 07-13 19:48:48.950--A2DPBD-"(50:19:01)Played for 5sec"{"ALF2":"0","ALF3":"160"} 07-13 19:49:26.382--A2DPBD-"(50:19:01)Played for 11sec"{"ALF2":"0","ALF3":"114"} 07-13 19:49:39.996--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : 100 07-13 19:49:48.827--BluetoothAdapter -- setScanMode() Mode :23, duration : 120, called by PID : 6254 @ com.android.settings 07-13 19:49:48.831--bta_dm_act.cc -- Set p_search_cback for Inquiry 07-13 19:50:01.655--bta_dm_act.cc -- Search Completed 07-13 19:50:11.769--BluetoothAdapter -- setScanMode() Mode :21, duration : 120, called by PID : 6254 @ com.android.settings 07-13 19:50:11.946--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : 100 07-13 19:51:02.223--HFFW-semGetHeadsetSetting(501901,2) by 6758 @ com.samsung.android.oneconnect : 100 07-13 19:51:45.294--RFCM-rcvd DISC from 501901 (2, 111f) on 4 07-13 19:51:45.310--HFSM-CONN_A(10) ConnE_0 (501901) 07-13 19:51:45.321--HFSM-enter DISC (501901) / 0 07-13 19:51:45.326--HFAM-setHighPriorityDevice : 501901 to null 07-13 19:51:45.338--HFS-setActiveDevice: 501901 > null 07-13 19:51:45.413--AdapterProp -- Connection status :: [Connecting]0, [Connected]1, [Disconnecting]0 07-13 19:51:45.460--BluetoothPhonePolicy -- profileId = 1 : 2 -> 0 size 0 07-13 19:51:45.797--A2DPSM-Connected ConnectionEvent device : 90:7, state : 0 07-13 19:51:45.807--BluetoothPhonePolicy -- profileId = 2 : 2 -> 0 size 0 07-13 19:51:45.826--AdapterProp -- CONNECTION_STATE_CHANGE: 501901 : 2 -> 0 07-13 19:51:45.828--AdapterProp -- Connection status :: [Connecting]0, [Connected]0, [Disconnecting]0 07-13 19:51:45.854--A2DPSVC-Connection state 90:7: 2->0, conn : 0 07-13 19:51:49.319--[500D]{0035}(29::13)(20::19) 07-13 19:51:49.322--[5008]{0029})(04::0) 07-13 19:51:49.323--[5008]{002A}(20::80)(04::0) 07-13 19:51:49.342--BluetoothRemoteDevices -- ACTION_ACL_DISCONNECTED, device is 501901, reason is 19, linktype is 1 07-13 19:51:49.891--BluetoothDataManager -- CONNECTION INFO : {"LO_MFN":"117","LO_LMP":"9","LO_SUB":"0","LO_FWV":"UTC|lassen_s612|S612_E788X_C1_Y20W18A","RE_OUI":"50:19:01","RE_NAM":"Trinida","RE_MFN":"10","RE_LMP":"7","RE_SUB":"8648","RE_COD":"2360324","RE_LTY":"1","RE_ROL":"0","RE_WEA":"0","CO_CFR":"","CO_ADR":"19","CO_HER":""} 07-13 19:52:08.146--HFFW-isInbandRingingSupported() : 1 by 7553 @ com.android.bluetooth

--------- 0.447s was the duration of dumpsys bluetooth_manager, ending at: 2020-07-13 19:52:08

DUMP OF SERVICE bluetooth_policy: [BLUETOOTH table] --------- 0.006s was the duration of dumpsys bluetooth_policy, ending at: 2020-07-13 19:52:08

DUMP OF SERVICE bluetooth_secure_mode_manager: --------- 0.001s was the duration of dumpsys bluetooth_secure_mode_manager, ending at: 2020-07-13 19:52:08

DUMP OF SERVICE bluetooth_secure_mode_policy: [BluetoothSecureModeTable table] --------- 0.006s was the duration of dumpsys bluetooth_secure_mode_policy, ending at: 2020-07-13 19:52:08

DUMP OF SERVICE browser_policy: [BROWSER table] --------- 0.005s was the duration of dumpsys browser_policy, ending at: 2020-07-13 19:52:08

DUMP OF SERVICE bugreport: --------- 0.001s was the duration of dumpsys bugreport, ending at: 2020-07-13 19:52:08


arkq commented 4 years ago

@grahamnaylorccfe great, please attach these files in the binary format, so it will be possible to compare connections. Also, please include in these logs the case where you are trying to record something from the headset (in bluealsa) and where "recording" (audio from microphone) actually works, e.g. phone call on Android.

grahamnaylorccfe commented 4 years ago

The phone produced loads of files from the log report (~76MB), but I guess the one that is relevant is the file called btsnoop_hci which I attach with the two dump files from the Cora embedded ARM on FPGA when connect and attempting but not recording using arecord (file connect_record.dump ) and when succesfully connecting and playing a .wav file with aplay (file connect_play.dump). connect_record.zip

arkq commented 4 years ago

When creating BT Snoop log from smartphone, did you make a phone call? Because I can only see A2DP transfer (playing music on headset). It seems that the SCO connection was never established (there is no RFCOMM communication which should appear priori to SCO opening).

grahamnaylorccfe commented 4 years ago

I recorded a message using the audio recorder (of my voice from the microphone) and played it back. I can try again. G

arkq commented 4 years ago

I recorded a message using the audio recorder (of my voice from the microphone) and played it back. I can try again.

Hmm... I will check again then. But also please check, that recording does not use internal smartphone microphone.

grahamnaylorccfe commented 4 years ago

I just tried again with the recorder. It seems that it was recording from the phone mic and not the headset (durr) but playing back through the headset. Have tried again with skype echo test service a recorded message and I know that worked through the headset mic as I was outside the room with the phone in a drawer! Once I have the log, I will post the btsnoop log.

grahamnaylorccfe commented 4 years ago

btsnoop_hci.log Here is the log from the phone of a skype echo over bluetooth headset (play then record and then play). (was at about 9:24).

borine commented 4 years ago

@grahamnaylorccfe I've ordered an Asus USB-BT400 bluetooth dongle to experiment with, I think (hope) this has the same broadcom chipset as yours. As for the CSR, is that a branded device or generic cheap one? what does hciconfig -a and lsusb say about it?

grahamnaylorccfe commented 4 years ago

The CSR USB BT dongle is a cheap generic one. If you recommend one that works reliably I am more than happy to give that a go. Anyway, the reponses you requested:

root@koheron:~# lsusb Bus 001 Device 002: ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth Dongle (HCI mode) Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub root@koheron:~# hciconfig -a hci0: Type: Primary Bus: USB BD Address: 00:1A:7D:DA:71:13 ACL MTU: 310:10 SCO MTU: 64:8 UP RUNNING PSCAN RX bytes:1238 acl:0 sco:0 events:75 errors:0 TX bytes:3042 acl:0 sco:0 commands:75 errors:0 Features: 0xff 0xff 0x8f 0xfe 0xdb 0xff 0x5b 0x87 Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 Link policy: RSWITCH HOLD SNIFF PARK Link mode: SLAVE ACCEPT Name: 'koheron' Class: 0x200000 Service Classes: Audio Device Class: Miscellaneous, HCI Version: 4.0 (0x6) Revision: 0x22bb LMP Version: 4.0 (0x6) Subversion: 0x22bb Manufacturer: Cambridge Silicon Radio (10)

borine commented 4 years ago

@grahamnaylorccfe OK, so my Asus USB-BT400 arrived, and HSP playback and recording work fine with it. So I can only assume your issue is a firmware problem.

For reference, mine identifies itself as:

$ dmesg | grep BCM20702A1
BCM20702A1 (001.002.014) build 1467
$ lsusb | grep Broadcom
Bus 001 Device 005: ID 0b05:17cb ASUSTek Computer, Inc. Broadcom BCM20702A0 Bluetooth
$ hciconfig
hci0:   Type: Primary  Bus: USB
    BD Address: 5C:F3:70:9B:FB:1A  ACL MTU: 1021:8  SCO MTU: 64:1
    UP RUNNING 
    RX bytes:395443 acl:59 sco:7635 events:335 errors:0
    TX bytes:60584 acl:54 sco:401 commands:267 errors:0

Here's how I got the correct firmware:

script to generate current Linux firmware for Asus USB-BT400

implements the method found here:

https://gist.github.com/ssledz/69b7f7b0438e653c08c155e244fdf7d8

WIN_DRIVER="DR_USB_BT400_1201710_Windows.zip" ASUS_DOWNLOAD_URL="https://dlcdnets.asus.com/pub/ASUS/wireless/USB-BT400/$WIN_DRIVER"

ARCH_FILELIST_URL="https://aur.archlinux.org/cgit/aur.git/tree/filelist.txt?h=bcm20702a1-firmware"

EXTRACTED_ROOT="Win10_USB-BT400_DRIVERS" HEXFILE_DIR="$EXTRACTED_ROOT/Win10_USB-BT400_Driver_Package/64"

abort on first error

set -e

find the required firmware name from dmesg

FIRMWARE=$(dmesg | sed -n '0,/brcm\/BCM20702A1/s/^.(BCM20702A1.hcd).*$/\1/p') if [[ -z "$FIRMWARE" ]] ; then echo "Unable to identify required firmware from dmesg" exit 1 fi

generate USB ID from firmware name

USB_ID=${FIRMWARE:11:9} USB_ID=${USB_ID/-/:} USB_ID=${USB_ID^^}

lookup firmware hex file name for our USB_ID

HEXFILE=$(curl -s "$ARCH_FILELIST_URL" | grep "$USB_ID") if [[ -z "$HEXFILE" ]] ; then echo "No hexfile match for usb id $USB_ID" exit 1 fi HEXFILE="${HEXFILE:11}"

download Windows driver from Asus

if [[ ! -f "$WIN_DRIVER" ]] ; then wget "$ASUS_DOWNLOAD_URL" fi unzip -qu "$WIN_DRIVER"

generate firmware hcd file from hex file

hex2hcd -o "$FIRMWARE" "$HEXFILE_DIR/$HEXFILE"

remove extracted driver file tree

rm -r "$EXTRACTED_ROOT"

echo echo "Firmware creation complete: filename = $FIRMWARE" echo "Please install into /lib/firmware/brcm/"


- if all goes well you will see the message
  `Firmware creation complete: filename = BCM20702A1-xxxx-xxxx.hcd`

- unplug the Asus dongle

- copy the firmware file to /lib/firmware/brcm
  `sudo cp *.hcd /lib/firmware/brcm`

- plug in the Asus dongle

Please let me know how this works out for you. 
grahamnaylorccfe commented 4 years ago

Thanks @borine. Sorry for the delay in replying - I had been away on holiday with patchy wifi.. I will try and upgrade my firmware following your instructions - looks like I have build 0000!

grahamnaylorccfe commented 4 years ago

I have found a version of the BCM20702A1-0b05-17cb.hcd file that I need that reports a build number of 1467 amongst my pile of versions. I will try that and report back.

grahamnaylorccfe commented 4 years ago

I deleted my previous hcd file and used the one I had previously used with a build number of 1467 and get the following:

root@koheron:~# dmesg | grep BCM [ 1.713615] Bluetooth: hci0: BCM: chip id 63 [ 1.746604] Bluetooth: hci0: BCM20702A [ 1.750598] Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000 [ 2.567617] Bluetooth: hci0: BCM20702A1 (001.002.014) build 1467 [ 212.075823] Bluetooth: hci0: BCM: chip id 63 [ 212.105819] Bluetooth: hci0: BCM20702A [ 212.107804] Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000 [ 212.899790] Bluetooth: hci0: BCM20702A1 (001.002.014) build 1467 [51113.627098] Bluetooth: hci0: BCM: chip id 63 [51113.657119] Bluetooth: hci0: BCM20702A [51113.658117] Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000 [51114.459066] Bluetooth: hci0: BCM20702A1 (001.002.014) build 1467 root@koheron:~# lsusb | grep Broadcom Bus 001 Device 004: ID 0b05:17cb ASUSTek Computer, Inc. Broadcom BCM20702A0 Bluetooth root@koheron:~# hciconfig hci0: Type: Primary Bus: USB BD Address: 5C:F3:70:99:0E:8C ACL MTU: 1021:8 SCO MTU: 64:1 UP RUNNING RX bytes:9913 acl:179 sco:0 events:476 errors:0 TX bytes:145315 acl:181 sco:2026 commands:292 errors:0

I run bluealsa with: bluealsa -p hsp-ag -p hfp-ag

I connect in bluetoothctl The aplay command plays a sound file correctly however the command: arecord -D bluealsa:SRV=org.bluealsa,DEV=50:19:01:90:7F:39,PROFILE=sco record1.wav still yields a file with only 44 bytes

report from blualsa:


bluealsa: D: ../../src/ba-transport.c:962: New SCO link: 50:19:01:90:7F:39: 18 bluealsa: D: ../../src/hci.c:132: SCO link socket MTU: 18: 64 bluealsa: D: ../../src/ba-transport.c:787: PCM resumed: 15 bluealsa: D: ../../src/ba-transport.c:1004: Closing PCM: 15 (then hit ^c after a few seconds as nothing seemed to be happening) bluealsa: D: ../../src/sco.c:328: Releasing SCO due to PCM inactivity bluealsa: D: ../../src/ba-transport.c:980: Closing SCO: 18


I will try again and download the driver following your method above to see if the result is any different. Though I attach here the one I had to see if it is any different from yours (the build number looks the same) BCM20702A1-0b05-17cb.zip

borine commented 4 years ago

The firmware you attached above has the same hash as mine - they are the same.

This line from hciconfig shows that sco traffic is still not being received over the hci: RX bytes:9913 acl:179 sco:0 events:476 errors:0 In normal operation, you would see both sco RX and TX with aplay, and just sco RX with arecord. You are not seeing sco RX with either. Just to confirm, are you using bluealsa built from master branch, or the one on the no-broadcom-setup branch? I am using master branch.