End of audio being truncated when playing via SCO

[killerkalamari]

When I play audio via sco, the end of the audio is truncated. This happens regardless of profile (so not specifying profile, or specifying -p hsp-ag or -p hfp-ag all still experience truncation). If I play using a2dp there is no truncation.

This occurs with hardware with two Broadcom / Cypress chipsets: A Raspberry Pi 3 (CYW43438 chipset) and an embedded board (CYW43455 chipset, which is also used in the Pi 3 B+ and 4). I am using an hcitool cmd hack from here raspberrypi/linux#2229 (comment) in order to reroute the audio properly for SCO. On the CYW43455 system, libasound was compiled with --disable-thread-safety.

Example command line:
aplay -v -D bluealsa:DEV=E9:08:EF:2D:40:33,PROFILE=sco test_8k.wav

When comparing the audio file with the output of sudo btmon --sco, this is the last audio data from the file that appears to be sent. From what I can tell btmon outputs "<" for data sent to SCO, and ">" for responses (the TX and RX also back that up):

< SCO Data TX: Handle 6 flags 0x00 dlen 48                                                                                                                                                  #1153 [hci0] 10.142211
        26 02 54 fb 78 03 fc fe f7 ff 25 00 82 00 9a ff  &.T.x.....%.....
        0c 02 aa fd 04 01 47 00 1f ff 1f 00 88 00 2f fe  ......G......./.
        08 02 da fe de ff b3 ff bd ff a1 00 83 00 24 fe  ..............$.

These are the messages directly after that. There are 3 response messages, followed by a disconnect. It seems that the truncation is happening because it's disconnecting early.

> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1154 [hci0] 10.142333
        03 00 02 00 02 00 02 00 00 00 00 00 ff ff 00 00  ................
        ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
        00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
        00 00 00 00 00 00 00 00 00 00 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1155 [hci0] 10.149459
        ff ff ff ff ff ff 00 00 ff ff f8 ff f8 ff fa ff  ................
        03 00 03 00 02 00 f9 ff f9 ff fa ff fe ff 03 00  ................
        fb ff fc ff fc ff fd ff fd ff ff ff fe ff ff ff  ................
        fe ff ff ff 00 00 ff ff ff ff 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1156 [hci0] 10.149637
        ff ff 07 00 00 00 fc ff fd ff ff ff 06 00 05 00  ................
        04 00 03 00 01 00 01 00 01 00 00 00 01 00 00 00  ................
        ff ff 00 00 ff ff ff ff ff ff 00 00 ff ff f8 ff  ................
        f8 ff fa ff fb ff fc ff fd ff fd ff              ............    
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                              #1157 [hci0] 10.152260
        Handle: 6
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                   #1158 [hci0] 10.152995
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1159 [hci0] 10.156198
        fd ff ff ff fe ff ff ff fe ff fe ff 00 00 ff ff  ................
        00 00 ff ff 00 00 00 00 00 00 00 00 00 00 00 00  ................
        00 00 00 00 00 00 00 00 ff ff 00 00 ff ff 00 00  ................
        07 00 05 00 04 00 02 00 02 00 01 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1160 [hci0] 10.156376
        01 00 00 00 00 00 01 00 ff ff ff ff 00 00 ff ff  ................
        00 00 f9 ff f7 ff fa ff fb ff fc ff fc ff 05 00  ................
        05 00 03 00 02 00 01 00 01 00 01 00 00 00 01 00  ................
        00 00 ff ff 00 00 ff ff 00 00 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1161 [hci0] 10.163696
        ff ff 00 00 ff ff 02 00 08 00 06 00 00 00 02 00  ................
        03 00 02 00 01 00 01 00 00 00 00 00 01 00 ff ff  ................
        ff ff ff ff 00 00 fc ff f7 ff f9 ff fb ff 03 00  ................
        03 00 fb ff fa ff fb ff fc ff fd ff              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1162 [hci0] 10.163872
        fd ff fe ff ff ff fe ff ff ff fe ff ff ff 00 00  ................
        ff ff 00 00 ff ff 00 00 00 00 00 00 ff ff 00 00  ................
        ff ff 00 00 ff ff 03 00 07 00 04 00 03 00 02 00  ................
        01 00 01 00 01 00 00 00 01 00 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1163 [hci0] 10.171186
        ff ff 00 00 ff ff ff ff f8 ff f8 ff fa ff fb ff  ................
        fc ff fd ff fd ff fd ff ff ff fe ff fe ff ff ff  ................
        06 00 05 00 04 00 fe ff fa ff fc ff fc ff fd ff  ................
        fd ff fe ff ff ff ff ff 06 00 ff ff              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1164 [hci0] 10.171373
        fc ff fe ff fd ff ff ff fe ff ff ff fe ff 00 00  ................
        fe ff f6 ff f7 ff fa ff fa ff 01 00 05 00 02 00  ................
        02 00 01 00 01 00 00 00 00 00 01 00 ff ff ff ff  ................
        00 00 ff ff 00 00 ff ff 00 00 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1165 [hci0] 10.178671
        00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
        00 00 00 00 00 00 ff ff 00 00 ff ff 00 00 ff ff  ................
        02 00 08 00 05 00 04 00 02 00 02 00 01 00 01 00  ................
        00 00 00 00 01 00 ff ff ff ff 00 00              ............    
> SCO Data RX: Handle 6 flags 0x00 dlen 60                                                                                                                                                  #1166 [hci0] 10.178854
        00 00 ff ff 00 00 ff ff 01 00 08 00 05 00 04 00  ................
        03 00 02 00 02 00 01 00 00 00 01 00 00 00 01 00  ................
        fa ff f7 ff fa ff fb ff fc ff fc ff fd ff fd ff  ................
        fe ff ff ff ff ff fe ff fe ff 00 00              ............    
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                              #1167 [hci0] 10.185421
        Status: Success (0x00)
        Handle: 6
        Reason: Connection Terminated By Local Host (0x16)

I'd like to know why the disconnect occurred. Was it from bluealsa, aplay, or my Bluetooth chip? Did some kind of error occur? I'm not seeing any errors in the bluealsa or aplay output. I'm mostly not really sure which files or functions to even start to look at. Can anyone offer some guidance on where I should start to look in the bluealsa code? Thanks!

[arkq]

One of reasons, why the audio is truncated, might be lack of "drain" functionality for SCO. See this: https://github.com/Arkq/bluez-alsa/blob/c39fd33f005cd46f8d324f12a0726df5801840f6/src/io.c#L2352

Try to increase this delay and see what will happen: https://github.com/Arkq/bluez-alsa/blob/c39fd33f005cd46f8d324f12a0726df5801840f6/src/ba-transport.c#L705

[killerkalamari]

I increased it to usleep(1000000) and it worked! I don't know if that is the optimal value (too long or maybe still too short, I'll have to take a closer look with btmon), but it sounded like it played all of it. It's funny, because I'd played around with this line of code before when trying to solve that portaudio truncation issue. I didn't realize at the time it was for SCO.

Thanks!

[arkq]

This sleep is not for SCO only, it is for bluetooth communication in general. The problem is, that there is no sync/flush mechanism (or I'm not aware of such). The only thing we can do, it is to wait and pray that everything will be played out. There is one potential solution to this problem. Play silence for few seconds after PCM disconnection. However, right now it will be hard to implement. Firstly I have to make a mixer inside bluealsa so more than one stream could be played simultaneously. Then it will be very easy to add extra silence, which will flush PCM buffers :)

[arkq]

I'm closing it for now because it's not an easy fix.... Please use increased usleep() as a workaround.