pulseaudio: crashes with " asyncmsgq.c: Assertion 'pa_atomic_load(&(a)->_ref) > 0' failed at pulsecore/asyncmsgq.c:176, function pa_asyncmsgq_get()" disconnecting bluetooth audio (A2DP)

[Greg Whiteley]

Steps to reproduce

0. You'll need a pi3 or bluetooth dongle in an older pi - no desktop. Using 2016-09-23-raspbian-jessie - first apt-get update and apt-get dist-upgrade

1. Add user pi to system pulseaudio group
$ sudo adduser pi pulse-access

2. start pulseaudio as system service
Firstly add the following lines to /etc/pulse/system.pa

load-module module-bluetooth-policy
load-module module-bluetooth-discover

Then start as follows to see log details directly

$ sudo pulseaudio --system --realtime --disallow-exit --no-cpu-limit --high-priority -vvvv &

3. Pair with audio device (eg bluetooth headset or speakers)
$ bluetoothctl
[bluetooth]# scan on
[bluetooth]# pair aa:bb:cc:dd:ee:ff
Attempting to pair with aa:bb:cc:dd:ee:ff
[bluetooth]# connect aa:bb:cc:dd:ee:ff
Attempting to connect aa:bb:cc:dd:ee:ff
Connection successful
[bluetooth]# trust aa:bb:cc:dd:ee:ff
[bluetooth]# quit

4. Verify pulseaudio sink set to new bluez device:
$ pactl info
...
Default Sink: bluez_sink.AA_BB_CC_DD_EE_FF
...

5. From another terminal/ssh: play something - at least a minute long - use aplay or gst123 (eg for mp3)
$ gst123 -z -a pulse=bluez_sink.AA_BB_CC_DD_EE_FF /path/to/mp3/dir

6. Ensure you hear audio on the bluetooth device

7. Turn off the bluetooth device without stopping anything on the pi - pulseaudio eventually (~20sec) crashes during the disconnect:

D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
I: [pulseaudio] module-rescue-streams.c: Successfully moved sink input 1 "gst123" to alsa_output.0.analog-stereo.
D: [pulseaudio] module-rescue-streams.c: No source outputs to move away.
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to remove event.
D: [bluetooth] module-bluez5-device.c: IO thread shutting down
D: [pulseaudio] module-bluez5-device.c: Switching the profile to off due to IO thread failure.
[Thread 0x7167e3f0 (LWP 3467) exited]
D: [pulseaudio] module-bluez5-device.c: Releasing transport /org/bluez/hci0/dev_FC_58_FA_D0_07_6B/fd14
I: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_FC_58_FA_D0_07_6B/fd14 auto-released by BlueZ or already released
D: [pulseaudio] module-bluez5-device.c: Audio stream torn down
I: [pulseaudio] sink.c: Freeing sink 1 "bluez_sink.FC_58_FA_D0_07_6B"
I: [pulseaudio] source.c: Freeing source 1 "bluez_sink.FC_58_FA_D0_07_6B.monitor"
I: [pulseaudio] card.c: Changed profile of card 1 "bluez_card.FC_58_FA_D0_07_6B" to off
E: [pulseaudio] asyncmsgq.c: Assertion 'pa_atomic_load(&(a)->_ref) > 0' failed at pulsecore/asyncmsgq.c:176, function pa_asyncmsgq_get(). Aborting.

Here's the GDB stack trace:

Program received signal SIGABRT, Aborted.
0x76bddf70 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 0x76bddf70 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x76bdf324 in __GI_abort () at abort.c:89
#2 0x76f131fc in pa_asyncmsgq_get (a=0x76cee094 <lock>, a@entry=0x42ed8,
    object=object@entry=0x7efff104, code=code@entry=0x7efff108,
    userdata=userdata@entry=0x7efff10c, offset=offset@entry=0x7efff110,
    chunk=chunk@entry=0x7efff118, wait_op=wait_op@entry=false)
    at pulsecore/asyncmsgq.c:177
#3 0x76f13af4 in pa_asyncmsgq_flush (a=0x42ed8, run=run@entry=true)
    at pulsecore/asyncmsgq.c:338
#4 0x76f77720 in pa_thread_mq_done (q=q@entry=0x4024c)
    at pulsecore/thread-mq.c:154
#5 0x7169c710 in stop_thread (u=u@entry=0x40210)
    at modules/bluetooth/module-bluez5-device.c:1304
#6 0x7169d2cc in set_profile_cb (c=<optimized out>, new_profile=0x56f60)
    at modules/bluetooth/module-bluez5-device.c:1574
#7 0x76f259e0 in pa_card_set_profile (c=c@entry=0x49e00, profile=0x56f60,
    save=save@entry=false) at pulsecore/card.c:281
#8 0x71699b9c in transport_state_changed_cb (y=<optimized out>, t=0x54ae0,
    u=0x40210) at modules/bluetooth/module-bluez5-device.c:1760
#9 0x76f2a92c in pa_hook_fire (hook=0x5ab98, data=data@entry=0x54ae0)
    at pulsecore/hook-list.c:106
#10 0x716e4458 in transport_state_changed (t=0x54ae0,
    state=PA_BLUETOOTH_TRANSPORT_STATE_DISCONNECTED)
    at modules/bluetooth/bluez5-util.c:186
#11 0x716e7de4 in endpoint_clear_configuration (Cannot access memory at address 0x1
conn=<optimized out>,
    userdata=0x5ab78, m=0x5f1c0) at modules/bluetooth/bluez5-util.c:1415
#12 endpoint_handler (c=<optimized out>, m=0x5f1c0, userdata=0x5ab78)
    at modules/bluetooth/bluez5-util.c:1464
#13 0x76df1bd4 in ?? () from /lib/arm-linux-gnueabihf/libdbus-1.so.3

(you might need to `killall gst123` if it doesn't want to stop after pulse has crashed)

For me this is reproducible at 100% rate if the bluetooth device is just switched off and left off.

Incorporating this upstream patch makes this problem go away for me (~20 consecutive disconnects):

https://bugs.freedesktop.org/attachment.cgi?id=114580

The original bug has a number of "defensive code reworkings" attached to the same upstream bug but I don't think they are necessary. I haven't tried to back-port them as they look riskier and more complicated.

pulseaudio version 5.0-13:

$ dpkg -l *pulse* | grep "^ii"
ii gstreamer1.0-pulseaudio:armhf 1.4.4-2 armhf GStreamer plugin for PulseAudio
ii libpulse0:armhf 5.0-13 armhf PulseAudio client libraries
ii libpulsedsp:armhf 5.0-13 armhf PulseAudio OSS pre-load library
ii pulseaudio 5.0-13 armhf PulseAudio sound server
ii pulseaudio-module-bluetooth 5.0-13 armhf Bluetooth module for PulseAudio sound server
ii pulseaudio-module-x11 5.0-13 armhf X11 module for PulseAudio sound server
ii pulseaudio-utils 5.0-13 armhf Command line tools for the PulseAudio sound server