Native bluetooth module skips bytes

[volkris]

Switching from the alsa module to the native module in pulseaudio 0.9.16 and bluez 4.45 the audio seems to play for half a second, pause for half a second, and repeat. It seems to buffer instead of dropping sound, and when I click stop on the player the audio continues until it's caught up.

syslog is full of the following type of line

pulseaudio[3210]: module-bluetooth-device.c: Skipping 28590 us (= 5040 bytes) in audio stream

[lennart]

Is there any related output in dmesg?

[volkris]

I went through the turn on process again today for additional info.

Normally I run "pactl load-module module-bluetooth-device profile=a2dp sink_name=fred address=00:19:1F:00:0A:4D" to make sure the bluetooth headphones are registered (the autodiscovery seems a little tricky). Often I still have to go into Volume Control's configuration screen to change the profile from Off to A2DP.

Here's what I see in syslog. Starred (*) lines repeat over and over:

hci_scodata_packet: hci0 SCO packet for unknown connection handle 92 (*) bluetoothd[3606]: No matching connection found for handle 92 rtkit-daemon[3204]: Failed to make ourselves RT: Invalid argument rtkit-daemon[3204]: Failed to make ourselves RT: Invalid argument pulseaudio[3202]: module-bluetooth-device.c: Skipping 441 us (= 76 bytes) in audio stream pulseaudio[3202]: module-bluetooth-device.c: Skipping 28608 us (= 5044 bytes) in audio stream (* with different skip us and bytes)

Meanwhile, dmesg says: hci_scodata_packet: hci0 SCO packet for unknown connection handle 92 (*)

but nothing else

[volkris]

Reposing that with formatting... plus an update

hci_scodata_packet: hci0 SCO packet for unknown connection handle 92 (*)
bluetoothd[3606]: No matching connection found for handle 92
rtkit-daemon[3204]: Failed to make ourselves RT: Invalid argument
rtkit-daemon[3204]: Failed to make ourselves RT: Invalid argument
pulseaudio[3202]: module-bluetooth-device.c: Skipping 441 us (= 76 bytes) in audio stream
pulseaudio[3202]: module-bluetooth-device.c: Skipping 28608 us (= 5044 bytes) in audio stream (* with different skip us and bytes)

Meanwhile, dmesg says:
hci_scodata_packet: hci0 SCO packet for unknown connection handle 92 (*)

Then I toggle configuration to off and back to a2dp after a second or two. The rtkit-daemon message reappears, followed by the skipping message. The SCO messages don't show back up, so I guess that's something that only happens at first initialization.

[lennart]

There is not autodiscovery. You need to run a recent version of gnome-bluetooth to activate the headset in PA. Just click on the BT notification icon and select the headset to connect.

The rtkit messages simply suggest that you are not running a kernel that supports rtkit properly. What distro is that? This is unrelated too the BT issue however.

No clue about the "hci_scodata_packet: hci0 SCO packet for unknown connection handle 92 (*)" message. Could you bring this to the attention of the folks on #bluez?

[volkris]

Distro is the upcoming release of Ubuntu. I'm trying to help them catch errors before the thing's released this time.

The relevant error seems to be the "module-bluetooth-device skipping" messages, as they're the ones coming while the audio goes wonky. Any ideas?

[lennart]

Please make sure then that Ubuntu actually pulls the SCHED_RESET_ON_FORK patch into their kernel. Otherwise rtkit is useless.

The "skipping" messages happen when the BT stack in the kernel didn't allow us to write any audio data to the BT socket for more than 100ms. In which case we then decide to drop a bit of audio data since otherwise our clock would be become very uneven.

You should prbably focus on the BT/SCO related message in dmesg if you want to track this down. It probably explains why the BT socket is stuck. That's why I asked you to bring this to the attention of the bluez folks. Often enough this is just caused by a shitty BT dongle, so you want to check if using another dongle might make the problem go away.

[volkris]

I followed your suggestion to use the gnome-bluetooth connect method to activate the BT in PA.

rtkit message remains, but the SCO messages are gone. Come to think of it, the pactl method I was using previously may have created a duplicate device in PA, one auto-activated and one forced with pactl. Maybe that somehow lead to the SCO error/warning.

Now dmesg says nothing and syslog has the following:
bluetoothd[2805]: link_key_request (sba=00:11:67:55:91:B0, dba=00:19:1F:00:0A:4D)[[BR]] bluetoothd[2805]: link_key_request (sba=00:11:67:55:91:B0, dba=00:19:1F:00:0A:4D)[[BR]] rtkit-daemon[3218]: Failed to make ourselves RT: Invalid argument
rtkit-daemon[3218]: Failed to make ourselves RT: Invalid argument
pulseaudio[3216]: module-bluetooth-device.c: Skipping 8186 us (= 1444 bytes) in audio stream
pulseaudio[3216]: module-bluetooth-device.c: Skipping 28601 us (= 5044 bytes) in audio stream

This dongle worked fine using the alsa module in the past.

So let me know what you think I should do. I can talk to #bluez if you think it's a problem over there (though I suspect they'd bounce me back here), or I can try to dig up a different dongle if you think the PA native module may be incompatible while the alsa method was able to work around whatever the problem is.

[lennart]

Hmm, You might want to play around with MAX_PLAYBACK_CATCH_UP_USEC in src/modules/bluetooth/module-bluetooth-device.c. Try setting it to 500ms or so and check if that makes your problem go away. Maybe our threashold of 100ms is just too low.

[volkris]

Changing MAX_PLAYBACK_CATCH_UP_USEC didn't seem to make a difference. I'll play around with the various constants nearby and see if anything changes.

One observation, though: syslog always starts spewing those lines even when I'm not trying to play audio. Is that expected... at least as expected as anything? When I connect the bluetooth, the only client connected is System Sounds, so I don't think PA should have bytes to skip.

[lennart]

Replying to volkris:

Changing MAX_PLAYBACK_CATCH_UP_USEC didn't seem to make a difference. I'll play around with the various constants nearby and see if anything changes.

If increasing that had not much effect then this is almost certainly breakage in the bt stack, in your dongle or some incompat with your headset.

I'd really recommend bringing this to the attention of the bluez guys. Also, you might want to checkout if a different BT dongle fixes the issues.

One observation, though: syslog always starts spewing those lines even when I'm not trying to play audio. Is that expected... at least as expected as anything? When I connect the bluetooth, the only client connected is System Sounds, so I don't think PA should have bytes to skip.

If module-suspend-on-idle is loaded (which it is by default) PA willl auto-suspend BT devices after 2s of idle. Are you saying that does not work on your machine?

[volkris]

Updated to bluez 4.47. No help. #bluez didn't have any immediate thoughts, so when I get a chance I'll collect my thoughts for a mailing list post.

As for module-suspend-on-idle, it is installed but the "skipping..." messages continue even when there is no audio playing and/or the device is muted through PA's Volume Control. I don't know what the expected behavior is here, so I don't know if it's not working.

[volkris]

Someone in the ubuntu bug reported luck connecting to headphones using blueman. Sure enough, that worked.

Now I right click on the headphones in blueman, disconnect "Input Service" and "Headset Service", and connect "A2DP Service." Then everything works fine.