Pipewire sometimes crashes libpulse on device removal
Powering off bluez5 devices sometimes crashes libpulse (apparently double-free), when the device is removed. Pipewire itself doesn't crash and continues to work normally, but stuff like gnome-shell and pavucontrol go down. This may be a pulseaudio bug, but maybe pipewire-pulse is sending unexpected stuff to the apps.
With pulseaudio-libs-14.0-2.fc33.x86_64, pipewire 84fc63e6
(gdb) bt
#0 0x00007f7c2f44c9d5 in raise () at /lib64/libc.so.6
#1 0x000055785d411332 in dump_gjs_stack_on_signal_handler (signo=6) at ../src/main.c:392
#2 0x00007f7c2f44ca60 in <signal handler called> () at /lib64/libc.so.6
#3 0x00007f7c2f44c9d5 in raise () at /lib64/libc.so.6
#4 0x00007f7c2f4358a4 in abort () at /lib64/libc.so.6
#5 0x00007f7c2f48f177 in __libc_message () at /lib64/libc.so.6
#6 0x00007f7c2f496e6c in annobin_top_check.start () at /lib64/libc.so.6
#7 0x00007f7c2f4982bc in _int_free () at /lib64/libc.so.6
#8 0x00007f7be612ac53 in pa_xfree (p=0x55785ec64c40) at pulse/xmalloc.c:129
#9 pa_xfree (p=0x55785ec64c40) at pulse/xmalloc.c:122
#10 0x00007f7be6112d72 in card_info_free (i=0x7ffce9a7a0b0) at pulse/introspect.c:799
#11 0x00007f7be6119b17 in context_get_card_info_callback
(pd=pd@entry=0x55785e427770, command=command@entry=2, tag=tag@entry=265, t=t@entry=0x557861119990, userdata=userdata@entry=0x55786193ec20) at pulse/introspect.c:993
#12 0x00007f7be60b0773 in run_action (pd=0x55785e427770, r=0x55786193edb0, command=2, ts=0x557861119990) at pulsecore/pdispatch.c:288
#13 0x00007f7be60b118f in pa_pdispatch_run (pd=0x55785e427770, packet=<optimized out>, ancil_data=0x5578610b99f8, userdata=0x5578603ea300) at pulsecore/pdispatch.c:341
#14 0x00007f7be6107843 in pstream_packet_callback (p=<optimized out>, packet=0x55785e430ef0, ancil_data=0x5578610b99f8, userdata=0x5578603ea300) at pulse/context.c:353
#15 0x00007f7be60b5cfd in do_read (p=p@entry=0x5578610b9760, re=re@entry=0x5578610b98e0) at pulsecore/pstream.c:1020
#16 0x00007f7be60b789f in do_pstream_read_write (p=0x5578610b9760) at pulsecore/pstream.c:260
#17 0x00007f7be61dc90e in dispatch_func () at /lib64/libpulse-mainloop-glib.so.0
#18 0x00007f7c30255a9f in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#19 0x00007f7c302a7a98 in g_main_context_iterate.constprop () at /lib64/libglib-2.0.so.0
#20 0x00007f7c30255163 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#21 0x00007f7c2f6a5dba in meta_run () at /lib64/libmutter-7.so.0
#22 0x000055785d410c9c in main (argc=<optimized out>, argv=<optimized out>) at ../src/main.c:550
#1 0x000055785d411332 in dump_gjs_stack_on_signal_handler (signo=6) at ../src/main.c:392
392 raise (signo);
(gdb) up
#2 <signal handler called>
(gdb) up
#3 0x00007f7c2f44c9d5 in raise () from /lib64/libc.so.6
(gdb) up
#4 0x00007f7c2f4358a4 in abort () from /lib64/libc.so.6
(gdb) up
#5 0x00007f7c2f48f177 in __libc_message () from /lib64/libc.so.6
(gdb) up
#6 0x00007f7c2f496e6c in malloc_printerr () from /lib64/libc.so.6
(gdb) up
#7 0x00007f7c2f4982bc in _int_free () from /lib64/libc.so.6
(gdb) up
#8 0x00007f7be612ac53 in pa_xfree (p=0x55785ec64c40) at pulse/xmalloc.c:129
129 free(p);
(gdb) p p
$11 = (void *) 0x55785ec64c40
(gdb) up
#9 pa_xfree (p=0x55785ec64c40) at pulse/xmalloc.c:122
122 void pa_xfree(void *p) {
(gdb) up
#10 0x00007f7be6112d72 in card_info_free (i=0x7ffce9a7a0b0) at pulse/introspect.c:799
799 pa_xfree(i->ports[j]->profiles);
(gdb) up
#11 0x00007f7be6119b17 in context_get_card_info_callback (pd=pd@entry=0x55785e427770, command=command@entry=2, tag=tag@entry=265, t=t@entry=0x557861119990,
userdata=userdata@entry=0x55786193ec20) at pulse/introspect.c:993
993 card_info_free(&i);
(gdb) p i
$12 = {index = 54, name = 0x7f7c0849cc10 "bluez_card.00:00:AA:AA:AA:AA", owner_module = 4294967295, driver = 0x7f7c0849cc33 "bluez5", n_profiles = 2, profiles = 0x55785ecdbca0,
active_profile = 0x55785ecdbca0, proplist = 0x557862eafbc0, n_ports = 2, ports = 0x5578628c9690, profiles2 = 0x557861062990, active_profile2 = 0x557860309520}
(gdb) up
#12 0x00007f7be60b0773 in run_action (pd=0x55785e427770, r=0x55786193edb0, command=2, ts=0x557861119990) at pulsecore/pdispatch.c:288
288 callback(pd, command, tag, ts, userdata);
(gdb) up
#13 0x00007f7be60b118f in pa_pdispatch_run (pd=0x55785e427770, packet=<optimized out>, ancil_data=0x5578610b99f8, userdata=0x5578603ea300) at pulsecore/pdispatch.c:341
341 run_action(pd, r, command, ts);
(gdb) up
#14 0x00007f7be6107843 in pstream_packet_callback (p=<optimized out>, packet=0x55785e430ef0, ancil_data=0x5578610b99f8, userdata=0x5578603ea300) at pulse/context.c:353
353 if (pa_pdispatch_run(c->pdispatch, packet, ancil_data, c) < 0)
(gdb) p packet
$13 = (pa_packet *) 0x55785e430ef0
(gdb) p *packet
$14 = {_ref = {value = 1}, type = PA_PACKET_DYNAMIC, length = 1005, data = 0x7f7c0849cc00 "L", per_type = {
appended = "L\000\000\000\035L\000\000\001\nL\000\000\000=L\000\000\000\066L\000\005b L\000@\000\000L\000\005b L\000\005T\\L\000\000\r\310a\003\002\000\000\254Dm\002\001\002L\000\000\000\071tbluez_output.00_00_AB_CD_7A_DE.a2dp-sink\000\060U\000\000\000\000\000\035\350@fB\001PNPN\000\000\000\000\000\000\000"}}
(gdb) p ancil_data
$15 = (pa_cmsg_ancil_data *) 0x5578610b99f8
(gdb) p *ancil_data
$16 = {creds = {gid = 1000, uid = 1000}, creds_valid = true, nfd = 0, fds = {0, 0}, close_fds_on_cleanup = false}
(gdb) p c
$17 = (pa_context *) 0x5578603ea300
(gdb) p *c
$18 = {_ref = {value = 2}, system_bus = 0x0, session_bus = 0x0, proplist = 0x5578603ea470, mainloop = 0x5578603e7230, client = 0x0, pstream = 0x5578610b9760, pdispatch = 0x55785e427770,
srb_template = {readfd = -1, writefd = -1, memblock = 0x0}, srb_setup_tag = 0, record_streams = 0x5578603eafa0, playback_streams = 0x5578603eab60, streams = 0x0,
operations = 0x5578605ec1f0, version = 34, ctag = 267, csyncid = 0, error = 0x5578603ea450, state = PA_CONTEXT_READY, state_callback = 0x7f7be61ec710 <_pa_context_state_cb>,
state_userdata = 0x55785e6c7300, subscribe_callback = 0x7f7be61f4e60 <_pa_context_subscribe_cb>, subscribe_userdata = 0x55785e6c7300, event_callback = 0x0, event_userdata = 0x0,
mempool = 0x5578603eb590, is_local = true, do_shm = false, memfd_on_local = true, server_specified = false, no_fail = true, do_autospawn = false, use_rtclock = false, filter_added = false,
spawn_api = {prefork = 0x0, postfork = 0x0, atfork = 0x0}, shm_type = PA_MEM_TYPE_PRIVATE, server_list = 0x5578603e7150, server = 0x5578603e7030 "/run/user/1000/pulse/native",
conf = 0x557860471000, client_index = 50, ext_device_manager = {callback = 0x0, userdata = 0x0}, ext_device_restore = {callback = 0x0, userdata = 0x0}, ext_stream_restore = {
callback = 0x7f7be61ec690 <_pa_ext_stream_restore_subscribe_cb>, userdata = 0x55785e6c7300}}
(gdb) up
#15 0x00007f7be60b5cfd in do_read (p=p@entry=0x5578610b9760, re=re@entry=0x5578610b98e0) at pulsecore/pstream.c:1020
1020 p->receive_packet_callback(p, re->packet, &p->read_ancil_data, p->receive_packet_callback_userdata);
(gdb) up
#16 0x00007f7be60b789f in do_pstream_read_write (p=0x5578610b9760) at pulsecore/pstream.c:260
260 if (do_read(p, &p->readio) < 0)
(gdb) up
#17 0x00007f7be61dc90e in dispatch_func () from /lib64/libpulse-mainloop-glib.so.0
(gdb) up
#18 0x00007f7c30255a9f in g_main_context_dispatch () from /lib64/libglib-2.0.so.0
Meanwhile in pipewire logs:
helmi 19 20:08:24 pipewire-media-session[2254]: a2dp-sink 0x55ad1e60dc88: error 24
helmi 19 20:08:24 pipewire-media-session[2254]: bluez5-device: profiles changed to 00000011 00000010 (prev 00000011 00000011, change 00000001) switching_codec:0
helmi 19 20:08:24 pipewire-media-session[2254]: metadata 0x55ad1e488cd0: remove id:0 key:default.configured.audio.sink
helmi 19 20:08:24 pipewire-media-session[2254]: (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-18) running -> suspended
helmi 19 20:08:24 pipewire-media-session[2254]: (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-18) destroy
helmi 19 20:08:24 pipewire-media-session[2254]: context 0x55ad1e442cb0: busy:0 reason:active node destroy
helmi 19 20:08:24 pipewire-media-session[2254]: (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-0) destroy
helmi 19 20:08:24 pipewire-media-session[2254]: context 0x55ad1e442cb0: busy:0 reason:active node destroy
helmi 19 20:08:24 pipewire[2216]: (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-92) destroy
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 92.0) deactivated
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 92.0) active -> paused
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 92.1) deactivated
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 92.1) active -> paused
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 92.0) paused -> init
helmi 19 20:08:24 pipewire[2216]: context 0x556128c66ab0: busy:0 reason:link unprepared
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 92.1) paused -> init
helmi 19 20:08:24 pipewire[2216]: context 0x556128c66ab0: busy:0 reason:link unprepared
helmi 19 20:08:24 pipewire[2216]: (spotify-61) -> change driver (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-92 -> spotify-61)
helmi 19 20:08:24 pipewire[2216]: (bluez_output.00_00_AA_AA_AA_AA.a2dp-sink-92) running -> suspended
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 92.0) destroy
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 92.1) destroy
helmi 19 20:08:24 pipewire[2216]: context 0x556128c66ab0: busy:0 reason:active node destroy
helmi 19 20:08:24 pipewire-media-session[2254]: error id:0 seq:5488 res:-2 (No such file or directory): unknown resource 96 op:7
helmi 19 20:08:24 pipewire-media-session[2254]: trying to link node 61 exclusive:0 reconnect:1 target:-1 follows-default:1
helmi 19 20:08:24 pipewire-media-session[2254]: node 61 monitor:0 channelmix 2->2
helmi 19 20:08:24 pipewire-media-session[2254]: linking node 61 to node 42
helmi 19 20:08:24 pipewire-pulse[2215]: (spotify-10) running -> idle
helmi 19 20:08:24 gsd-media-keys[2662]: Unable to get default sink
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_SERVER_INFO tag:1173
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_CARD_INFO tag:1174 idx:73 name:(null)
helmi 19 20:08:24 pipewire[2216]: (spotify-61) running -> idle
helmi 19 20:08:24 pipewire-media-session[2254]: metadata 0x55ad1e488cd0: change id:0 key:default.audio.sink type:Spa:Id value:42
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) (spotify) -> (alsa_output.pci-0000_00_1b.0.analog-stereo)
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) (spotify) -> (alsa_output.pci-0000_00_1b.0.analog-stereo)
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) init -> negotiating
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) init -> negotiating
helmi 19 20:08:24 pipewire-media-session[2254]: trying to link node 61 exclusive:0 reconnect:1 target:-1 follows-default:1
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) negotiating -> allocating
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) negotiating -> allocating
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) allocating -> paused
helmi 19 20:08:24 pipewire[2216]: context 0x556128c66ab0: busy:0 reason:link prepared
helmi 19 20:08:24 pipewire[2216]: (spotify-61) -> change driver (spotify-61 -> alsa_output.pci-0000_00_1b.0.analog-stereo-42)
helmi 19 20:08:24 pipewire[2216]: (alsa_output.pci-0000_00_1b.0.analog-stereo-42) new quantum:1024->8192
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) activated
helmi 19 20:08:24 pipewire[2216]: (61.0 -> 42.0) paused -> active
helmi 19 20:08:24 pipewire[2216]: alsa-pcm 0x556128d01cd8: ALSA device open 'front:1' playback
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_SINK_INPUT_INFO tag:1175 idx:61 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [spotify] GET_SINK_INPUT_INFO tag:5031237 idx:61 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_SERVER_INFO tag:815
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_SINK_INPUT_INFO tag:816 idx:61 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_CARD_INFO tag:817 idx:73 name:(null)
helmi 19 20:08:24 pipewire[2216]: alsa-pcm front:1 (playback): format:S32_LE access:mmap-interleaved rate:48000 channels:2 buffer frames 32768, period frames 1024, periods 32, frame_si>
helmi 19 20:08:24 pipewire[2216]: merger 0x7f47fbadf8c8: Spa:Enum:AudioFormat:F32P/1@48000x2->Spa:Enum:AudioFormat:F32P/2@48000
helmi 19 20:08:24 pipewire[2216]: fmtconvert 0x7f47fbd413c0: Spa:Enum:AudioFormat:F32P/2@48000->Spa:Enum:AudioFormat:S32LE/2@48000
helmi 19 20:08:24 pipewire[2216]: channelmix 0x7f47fbd2a8d0: Spa:Enum:AudioFormat:F32P/2@48000->Spa:Enum:AudioFormat:F32P/2@48000 00000018:00000018
helmi 19 20:08:24 pipewire[2216]: resample 0x7f47fbd40390: Spa:Enum:AudioFormat:F32P/2@48000->Spa:Enum:AudioFormat:F32P/2@48000
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) allocating -> paused
helmi 19 20:08:24 pipewire[2216]: context 0x556128c66ab0: busy:0 reason:link prepared
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) activated
helmi 19 20:08:24 pipewire[2216]: (61.1 -> 42.1) paused -> active
helmi 19 20:08:24 pipewire[2216]: (alsa_output.pci-0000_00_1b.0.analog-stereo-42) suspended -> running
helmi 19 20:08:24 pipewire-pulse[2215]: fmtconvert 0x563069958a50: Spa:Enum:AudioFormat:F32LE/2@44100->Spa:Enum:AudioFormat:F32P/2@44100
helmi 19 20:08:24 pipewire-pulse[2215]: splitter 0x563069981d20: Spa:Enum:AudioFormat:F32P/2@48000->Spa:Enum:AudioFormat:F32P/1@48000x2
helmi 19 20:08:24 pipewire-pulse[2215]: channelmix 0x563069961e40: Spa:Enum:AudioFormat:F32P/2@44100->Spa:Enum:AudioFormat:F32P/2@44100 00000018:00000018
helmi 19 20:08:24 pipewire-pulse[2215]: resample 0x563069977900: Spa:Enum:AudioFormat:F32P/2@44100->Spa:Enum:AudioFormat:F32P/2@48000
helmi 19 20:08:24 pipewire-media-session[2254]: 0x55ad1e4d1b10: reserve acquired 1
helmi 19 20:08:24 pipewire[2216]: (spotify-61) idle -> running
helmi 19 20:08:24 pipewire-pulse[2215]: (spotify-10) idle -> running
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_SINK_INFO tag:818 idx:42 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_SINK_INPUT_INFO tag:819 idx:61 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_SINK_INFO tag:1176 idx:42 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_SINK_INPUT_INFO tag:1177 idx:61 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [spotify] GET_SINK_INPUT_INFO tag:5031251 idx:61 name:(null)
helmi 19 20:08:24 pipewire-media-session[2254]: native: lost RFCOMM connection.
helmi 19 20:08:24 pipewire-media-session[2254]: bluez5-device: profiles changed to 00000011 00000000 (prev 00000011 00000010, change 00000010) switching_codec:0
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Volume Control Media Keys] GET_CARD_INFO tag:1178 idx:73 name:(null)
helmi 19 20:08:24 pipewire-pulse[2215]: pulse-server 0x5630695fa5c0: [GNOME Shell Volume Control] GET_CARD_INFO tag:820 idx:73 name:(null)
helmi 19 20:08:24 gnome-shell[31156]: free(): invalid next size (fast)
Edited by P V