Chipmunk sound problem

[graham8]

At OSMC we are updating to bluealsa 4.1.0 from 3.1.0. Thank you, guys for the continual improvements!

For testing I'm sending audio between two OSMC-powered devices so I can test all codecs. There's something wrong with the clocking - I'm getting bursts of double-speed audio instead of everything at the correct speed.

Note that both devices work as expected with my BT speaker (AAC only) and streaming AAC or AptX from my phone.

Bluealsa is compiled with all codecs except LDAC from 165e15b. To keep it simple, both devices have bluealsa started without the extra a2dp codecs:
/usr/bin/bluealsa -S -p a2dp-source -p a2dp-sink --a2dp-volume -p hfp-ag -c msbc

On the source device I see this:

osmc@veroV5:~$ bluealsa-cli
Service: org.bluealsa
Version: v4.1.0
Adapters: hci0
Profiles:
  A2DP-source : SBC AAC
  A2DP-sink   : SBC AAC
  HFP-AG      : CVSD mSBC
osmc@veroV5:~$ bluealsa-cli list-pcms
/org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsrc/sink
osmc@veroV5:~$ bluealsa-cli info /org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsrc/sink
Device: /org/bluez/hci0/dev_CC_4B_73_6D_FF_67
Sequence: 1
Transport: A2DP-source
Mode: sink
Running: true
Format: S16_LE
Channels: 2
Sampling: 48000 Hz
Available codecs: SBC  <------  Why is AAC not listed here?
Selected codec: SBC
Delay: 15.2 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

On the sink device I see:

osmc@vero4kp2:~$ bluealsa-cli
Service: org.bluealsa
Version: v4.1.0
Adapters: hci1
Profiles:
  A2DP-source : SBC AAC
  A2DP-sink   : SBC AAC
  HFP-AG      : CVSD mSBC
osmc@vero4kp2:~$ bluealsa-cli list-pcms
/org/bluealsa/hci1/dev_38_83_9A_6C_0D_63/a2dpsnk/source
osmc@vero4kp2:~$ bluealsa-cli info /org/bluealsa/hci1/dev_38_83_9A_6C_0D_63/a2dpsnk/source
Device: /org/bluez/hci1/dev_38_83_9A_6C_0D_63
Sequence: 0
Transport: A2DP-sink
Mode: source
Running: true
Format: S16_LE
Channels: 2
Sampling: 48000 Hz
Available codecs: SBC AAC
Selected codec: SBC
Delay: 15.0 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

20-bluealsa.conf is from your template
ALSA is 1.2.4

Any suggestions to fix?

[arkq]

For testing I'm sending audio between two OSMC-powered devices so I can test all codecs.

Does both devices use the same version of BlueALSA?

There's something wrong with the clocking - I'm getting bursts of double-speed audio instead of everything at the correct speed.

OK, I'll look into this. It looks like an issue with sampling frequency.... dunno.

Available codecs: SBC <------ Why is AAC not listed here?

Are you using the same configuration of BlueZ on both devices? In older versions of BlueZ in order to get SEP support one has to enable experimental features.

[graham8]

Bluez-alsa is the same on both devices - installed from the same .deb.
Configuration is the same - conf file, command line options.
I perhaps should have said - testing between two devices has always worked in the past, up until 3.1.0 - 165e15b.
Thanks for investigating - can I get you some logs? Not compiled with debugging atm but I guess I could figure that out if it would help.

[borine]

I think the "chipmonk" effect may be a problem with bluealsa-aplay. I don't normally use AAC, but I've just set up a test system, bluealsa <-> bluealsa with AAC and aptX enabled on both. When first connected, aptX is selected and playback is fine. If I then change to AAC, playback is at half-speed. But if I stop and re-start bluealsa-aplay then playback is as the correct speed. Chnaging codec to aptX and playback is now at double speed "chipmonk".

i note that AAC is sampled at 96000 and aptX at 48000. So my initial conclusion is that bluealsa-aplay does not handle the rate change correctly.

One difference here though is that bluealsa-cli info does correctly show AAC in the available codecs on both source and sink devices.

[graham8]

Thank you. I have noticed 96000 showing up from time to time. I can't say whether each samplerate was associated with a particular codec. It seemed to be random.

None of this was made easier as I couldn't figure out how to change the codec reliably. If I enabled AptX on the bluealsa command line, nothing I could do with bluealsa-cli or 20-bluelasa.conf seemed to affect the chosen codec.

I'll try to repeat your test.

Some may think this is an artificial situation, but anyone who's fashioned a BT speaker using a Raspberry Pi will need this functionality.

[borine]

Some may think this is an artificial situation

Not me. I use bluealsa<->bluealsa every day in my main system. And, I think this problem may also occur if you switch codecs in the phone without disconnecting it first.

I have a fix that should appear as a PR very soon.

nothing I could do ... seemed to affect the chosen codec

The initial codec used on connection is negotiated between the devices. For Bluez <> Bluez it is normally the last codec used, got from the Bluez cache. You should be able to change it after connecting by using the bluealsa-cli codec command, at least that does work for me. I don't yet know why bluealsa-cli info is not showing AAC for you, so maybe there is another issue somewhere that I have not reproduced here yet.

[borine]

See PR #644

[graham8]

That's good service! I won't be able to test that until next week as I'm away for the weekend.

[borine]

bluez-alsa commit e6218b5 in the master branch has now fixed the chipmunk sound (many thanks to @arkq for dealing with this so quickly).

As for the bluealsa-cli codec issue, I still have not been able to reproduce it here. What version of Bluez are you using? The list of codecs reported is actually generated from the list of service end-points (SEPs) created by Bluez, so I'm now wondering whether this problem could be caused by Bluez. I have no idea how AAC can work (albeit with chipmunks) if Bluez is not creating a SEP for it, but at present I am stumped for anywhere else to look.

[arkq]

many thanks to @arkq for dealing with this so quickly

I think that most credits should go to you, after all you've spotted duplications in the ba_pcms cache :) Also, I'm trying to wrap up commits for fixup release, before I will push more destructive ones :D

I'm now wondering whether this problem could be caused by Bluez.

Maybe such behavior can be reproduced in two steps. Firstly, connect bluealsa<->bluealsa with SBC only enabled. BlueZ will cache available SEPS. Then, connect with extended list of SEPs. In such case, BlueZ (on the connection receiver side) can report old SEP list. But like you've said, without BlueZ exact version it's only a guess...

[graham8]

Thanks for the commit. So I updated both devices to e6218b5. Connected them, but I'm now getting this on the source device:

osmc@veroV5:/etc/alsa/conf.d$ speaker-test -t wav -c2 -Dbluealsa -l2

speaker-test 1.2.4

Playback device is bluealsa
Stream parameters are 48000Hz, S16_LE, 2 channels
WAV file(s)
ALSA lib bluealsa-pcm.c:1390:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
Playback open error: -19,No such device
osmc@veroV5:/etc/alsa/conf.d$ bluealsa-cli list-pcms
/org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsnk/source
osmc@veroV5:/etc/alsa/conf.d$ systemctl status bluealsa
● bluealsa.service - BlueALSA service
     Loaded: loaded (/lib/systemd/system/bluealsa.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2023-06-20 15:55:03 BST; 20min ago
       Docs: man:bluealsa(8)
   Main PID: 2959 (bluealsa)
      Tasks: 5 (limit: 3658)
     Memory: 4.5M
     CGroup: /system.slice/bluealsa.service
             └─2959 /usr/bin/bluealsa -S -p a2dp-source -p a2dp-sink --a2dp-volume

Jun 20 15:55:03 veroV5 systemd[1]: Starting BlueALSA service...
Jun 20 15:55:03 veroV5 systemd[1]: Started BlueALSA service.

Bluez is 5.62-3. Any thoughts?

[arkq]

I'm watching live TV and having to adjust between about 800ms advance to 300ms delay.

If I understand that correctly, you are using bluealsa as a BT speaker in your setup. If that is true, you can experience A/V desync, because bluealsa does not report playback delay to the BT source (e.g. TV or smartphone). As for now, delay reporting in such setup is not supported by the BlueZ. I've been trying to add such feature to BlueZ some time ago, but due to lack of time I had to give up. Maybe I will come back to that in the future...

[graham8]

OK. Maybe it never worked in sync with a bluealsa-bluealsa setup.

Edit: just to be clear, are you saying Bluez will accept playback delay messages from, eg earbuds but can't send such messages? My BT speaker (JBL) is perfectly in sync (better than ever, in fact!).

[arkq]

Bluez will accept playback delay messages from, eg earbuds but can't send such messages?

Yes, BlueZ D-Bus API internals for sending delay to the connected BT device are not implemented (if BlueZ acts as a sink, receiving delay from remote sink, e.g. headset, works fine). Client (e.g. BlueALSA) can update Delay property, but that's all, it will not be sent anywhere :D (at least that was the status a year ago).

[graham8]

So when @borine says

I use bluealsa<->bluealsa every day in my main system.

he can't be watching many videos? Is this just for audio?

[arkq]

he can't be watching many videos?

Not necessarily, it can be used for video, but the delay will have to be set by the user initially (in the asoundrc) or during video playback. It can vary few milliseconds back and forth (for one codec, but between codecs it can vary in 100s of ms), but that should not be a big deal. Anyway, you've said that you have to adjust the delay/advance in a rather big range... so I suspect that something is indeed wrong.

[graham8]

OK, I couldn't find any significant differences between 3.1.0 and 4.1.0 on the issues discussed here. I have now updated both devices to bluez 5.66 and launched bluez-alsa with only the default codecs as my first post. I'm getting proper sound but I'm not getting AAC selected. I see this on the source:

osmc@veroV5:~$ bluealsa-cli
Service: org.bluealsa
Version: v4.1.0
Adapters: hci0
Profiles:
  A2DP-source : SBC AAC
  A2DP-sink   : SBC AAC
osmc@veroV5:~$ bluealsa-cli list-pcms
/org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsrc/sink
osmc@veroV5:~$ bluealsa-cli info /org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsrc/sink
Device: /org/bluez/hci0/dev_CC_4B_73_6D_FF_67
Sequence: 1
Transport: A2DP-source
Mode: sink
Running: true
Format: S16_LE
Channels: 2
Sampling: 48000 Hz
Available codecs: SBC
Selected codec: SBC
Delay: 15.2 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

And this on the sink:

osmc@vero4kp2:~$ bluealsa-cli
Service: org.bluealsa
Version: v4.1.0
Adapters: hci1
Profiles:
  A2DP-source : SBC AAC
  A2DP-sink   : SBC AAC
osmc@vero4kp2:~$ bluealsa-cli list-pcms
/org/bluealsa/hci1/dev_38_83_9A_6C_0D_63/a2dpsnk/source
osmc@vero4kp2:~$ bluealsa-cli info /org/bluealsa/hci1/dev_38_83_9A_6C_0D_63/a2dpsnk/source
Device: /org/bluez/hci1/dev_38_83_9A_6C_0D_63
Sequence: 0
Transport: A2DP-sink
Mode: source
Running: true
Format: S16_LE
Channels: 2
Sampling: 48000 Hz
Available codecs: SBC AAC
Selected codec: SBC
Delay: 15.0 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

The delay now seems more stable.

[arkq]

Interesting: I delete /var/lib/bluetooth/*, reboot and still get a list of devices in bluetoothctl.

I think that might happen if by default you've got scan enabled. Test something like that:

1. Power of one of your devices.
2. On the other device stop bluetooth service (it's important to do this before wiping out /var) and wipe out /var/lib/bluetooth
3. Start bleutooth service (or restart device), and check whether in the bleutoothctl devices there is no powered off device. If you still see powered off device, then, like borine has said, there must be some other storage...

[graham8]

I did in the end get a nil return from bluetoothctl devices both ends. Now I've got that frustrating Failed to connect: org.bluez.Error.InProgress br-connection-busy message.

I'll have to give up for the evening, now, before I smash something up. Anything in the logs I posted?

[graham8]

I lied. I gave it one more go. Reconnected, ran speaker-test at 48kHz and now I'm getting this:

osmc@veroV5:~$ bluealsa-cli info /org/bluealsa/hci0/dev_CC_4B_73_6D_FF_67/a2dpsrc/sink
Device: /org/bluez/hci0/dev_CC_4B_73_6D_FF_67
Sequence: 0
Transport: A2DP-source
Mode: sink
Running: false
Format: S16_LE
Channels: 2
Sampling: 96000 Hz
Available codecs: SBC AAC
Selected codec: AAC
Delay: 15.0 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

Same at the sink:

osmc@vero4kp2:~$ bluealsa-cli info /org/bluealsa/hci1/dev_38_83_9A_6C_0D_63/a2dpsnk/source
Device: /org/bluez/hci1/dev_38_83_9A_6C_0D_63
Sequence: 1
Transport: A2DP-sink
Mode: source
Running: false
Format: S16_LE
Channels: 2
Sampling: 96000 Hz
Available codecs: SBC AAC
Selected codec: AAC
Delay: 15.0 ms
SoftVolume: false
Volume: L: 127 R: 127
Muted: L: false R: false

[arkq]

OK, there is something wrong with your setup....

veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SRC]: CC:4B:73:6D:FF:67: aptX    <-- cache was not wiped
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SRC]: CC:4B:73:6D:FF:67: aptX
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SNK]: CC:4B:73:6D:FF:67: aptX
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SNK]: CC:4B:73:6D:FF:67: aptX
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SNK]: CC:4B:73:6D:FF:67: SBC
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SNK]: CC:4B:73:6D:FF:67: SBC
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SRC]: CC:4B:73:6D:FF:67: SBC
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SNK]: CC:4B:73:6D:FF:67: SBC
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SRC]: CC:4B:73:6D:FF:67: AAC  <- why there is only one AAC...
                                                                                     BlueALSA starts 2 SEPs per codec
                                                                                     per sink/source, so there should
                                                                                     be at lest 2 AAC SEPs
veroV5 : bluez.c:1199: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
veroV5 : bluez.c:1290: Adding new Stream End-Point [SRC]: CC:4B:73:6D:FF:67: SBC
veroV5 : bluez.c:1308: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()   <-- SEP removed here... strange
veroV5 : bluez.c:1355: Removing SEP [SNK]: SBC
veroV5 : bluez.c:1308: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()  
veroV5 : bluez.c:1355: Removing SEP [SRC]: AAC

veroV5 : bluealsa-dbus.c:577: Available SEPs: 8
veroV5 : bluealsa-dbus.c:580: SEP [SRC]: SBC  <- SRC will be skipped, we're searching for SNK
veroV5 : bluealsa-dbus.c:580: SEP [SRC]: SBC
veroV5 : bluealsa-dbus.c:580: SEP [SNK]: aptX  <- not supported by current instance
                                                  you've started bluealsa without -c aptx
                                                  so this codec will not be reported
veroV5 : bluealsa-dbus.c:580: SEP [SRC]: aptX
veroV5 : bluealsa-dbus.c:580: SEP [SRC]: aptX
veroV5 : bluealsa-dbus.c:580: SEP [SNK]: SBC
veroV5 : bluealsa-dbus.c:580: SEP [SNK]: SBC
veroV5 : bluealsa-dbus.c:596: SEP: duplicate found, skipping
veroV5 : bluealsa-dbus.c:580: SEP [SNK]: aptX
veroV5 : bluealsa-dbus.c:596: SEP: duplicate found, skipping

So, we've got only SBC and aptX SEPs, but aptX is not reported because it was not enabled by the current bluealsa instance. So, SEPs reporting by bluealsa-ctl works as expected. The problem is that SEPs reported by BlueZ (to BlueALSA) are incorrect or out of date. And this strange behavior where the AAC SEP was removed just after it was created (and that only one was created)... Are you sure that you are not running any other application which register itself in BlueZ as a media application?

[graham8]

OK I must have stuffed up with clearing /var. Now I'm getting this https://paste.osmc.tv/edagedojuh.vhdl which looks better from your description above.

So now we just need to know how to make sure users don't get into this bind. I'll enable AptX etc now and see if I can change codec with bluealsa-cli which was where I started from! Thank you both for your help (so far :P)

[borine]

osmc@vero4kp2:~$ bluealsa-cli
Service: org.bluealsa
Version: v4.1.0

That version number looks iffy. It may be because your build did not refresh the m4 cache after running git pull (for that I use autoreconf --force), or perhaps somehow the installed binaries have reverted to the original 4.1.0 build ?

[borine]

I get Version: v4.1.0-9-g1ef3111 - note the git commit hash at the end of the string. Perhaps there is some simple reason why our builds give different results, I admit to having virtually no understanding of (of liking for) the gnu autotools.

[graham8]

ic. I'm using our own build script which evidently doesn't pull in the commit number.

I'm out and about atm but later I'll see if I can follow your build instructions on our platform to make sure we are on he same page.

[borine]

OK, but its odd though. The version number is got from git automatically by "configure". Unfortunately the m4 code that does it results in the value being cached, so subsequent runs of "configure" do not update it unless the cache is cleared first. I don't do anything special, just configure; make; make install and the git version is magically embedded in the binaries. Oh well, I guess the embedded version id is not something I should rely on in future.

[graham8]

Our build script just pulls (wgets) the code blob from this repo, it doesn't clone bluez-alsa so in this line

test -d .git && git describe --always --dirty || echo v4.1.0

there's no attempt to find the latest commit. We don't mess with any of your code so the binaries should be good and up to date.

[borine]

OK, thanks for checking. I'll go back to my usual state of not having a clue then 😆

[graham8]

Closing this as the chipmunk problem was fixed with 4.1.1 and the threads in here have become unnavigable (thank you github). There are still some oddities with bluealsa-cli which I'll open a new issue for.