Bug 107044

Summary: PulseAudio is crashing when connecting AD2P device
Product: PulseAudio Reporter: mikefender
Component: modulesAssignee: pulseaudio-bugs
Status: RESOLVED FIXED QA Contact: pulseaudio-bugs
Severity: normal    
Priority: medium CC: anthony.louis.eden, dominik, lennart, rdieter, yousef.su.2000
Version: unspecified   
Hardware: x86-64 (AMD64)   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Bug Depends on:    
Bug Blocks: 107071    
Attachments: Debug level log.
Patched Pulseaudio debug level log

Description mikefender 2018-06-26 11:09:00 UTC
Hello, I'm running Pulseaudio 12.0 on Arch Linux.

When I try to switch my Bluetooth headphones to the AD2P profile PulseAudio is crashing with the following in the log:

Jun 26 11:38:01 jason pulseaudio[1306]: E: [pulseaudio] module-bluez5-device.c: Assertion '!u->thread' failed at modules/bluetooth/module-bluez5-device.c:1731, function start_thread(). Aborting.
Jun 26 11:38:02 jason systemd[1037]: pulseaudio.service: Main process exited, code=dumped, status=6/ABRT
Jun 26 11:38:02 jason systemd[1037]: pulseaudio.service: Failed with result 'core-dump'.
Jun 26 11:38:02 jason systemd[1037]: pulseaudio.service: Service hold-off time over, scheduling restart.
Jun 26 11:38:02 jason systemd[1037]: pulseaudio.service: Scheduled restart job, restart counter is at 1.
Jun 26 11:38:02 jason systemd[1037]: Stopped Sound Service.
Jun 26 11:38:02 jason systemd[1037]: Starting Sound Service...
Jun 26 11:38:02 jason pulseaudio[4006]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
Jun 26 11:38:02 jason systemd-coredump[3987]: Process 1306 (pulseaudio) of user 1000 dumped core.
                                              Stack trace of thread 1306:
                                              #0  0x00007f5aa7ab086b raise (libc.so.6)
                                              #1  0x00007f5aa7a9b40e abort (libc.so.6)
                                              #2  0x00007f5a967a7d17 n/a (module-bluez5-device.so)
                                              #3  0x00007f5a967aac3f n/a (module-bluez5-device.so)
                                              #4  0x00007f5aa9037c4a pa_card_set_profile (libpulsecore-12.0.so)
                                              #5  0x00007f5aa009a481 n/a (libprotocol-native.so)
                                              #6  0x00007f5aa8b7cf48 pa_pdispatch_run (libpulsecommon-12.0.so)
                                              #7  0x00007f5aa00a30d6 n/a (libprotocol-native.so)
                                              #8  0x00007f5aa8b7fa9f n/a (libpulsecommon-12.0.so)
                                              #9  0x00007f5aa8b8290b n/a (libpulsecommon-12.0.so)
                                              #10 0x00007f5aa8b82cba n/a (libpulsecommon-12.0.so)
                                              #11 0x00007f5aa8b8354a n/a (libpulsecommon-12.0.so)
                                              #12 0x00007f5aa8de5d18 pa_mainloop_dispatch (libpulse.so.0)
                                              #13 0x00007f5aa8de5fef pa_mainloop_iterate (libpulse.so.0)
                                              #14 0x00007f5aa8de6091 pa_mainloop_run (libpulse.so.0)
                                              #15 0x000055e1835003b3 main (pulseaudio)
                                              #16 0x00007f5aa7a9d06b __libc_start_main (libc.so.6)
                                              #17 0x000055e18350109a _start (pulseaudio)
                                              Stack trace of thread 1310:
                                              #0  0x00007f5aa7b67fa6 ppoll (libc.so.6)
                                              #1  0x00007f5aa9047e10 pa_rtpoll_run (libpulsecore-12.0.so)
                                              #2  0x00007f5a9efe9911 n/a (libalsa-util.so)
                                              #3  0x00007f5aa8b939fc n/a (libpulsecommon-12.0.so)
                                              #4  0x00007f5aa8041075 start_thread (libpthread.so.0)
                                              #5  0x00007f5aa7b7253f __clone (libc.so.6)
                                              Stack trace of thread 3985:
                                              #0  0x00007f5aa7b67fa6 ppoll (libc.so.6)
                                              #1  0x00007f5aa9047e10 pa_rtpoll_run (libpulsecore-12.0.so)
                                              #2  0x00007f5a967ab338 n/a (module-bluez5-device.so)
                                              #3  0x00007f5aa8b939fc n/a (libpulsecommon-12.0.so)
                                              #4  0x00007f5aa8041075 start_thread (libpthread.so.0)
                                              #5  0x00007f5aa7b7253f __clone (libc.so.6)
                                              Stack trace of thread 1311:
                                              #0  0x00007f5aa7b67fa6 ppoll (libc.so.6)
                                              #1  0x00007f5aa9047e10 pa_rtpoll_run (libpulsecore-12.0.so)
                                              #2  0x00007f5a9eff0267 n/a (libalsa-util.so)
                                              #3  0x00007f5aa8b939fc n/a (libpulsecommon-12.0.so)
                                              #4  0x00007f5aa8041075 start_thread (libpthread.so.0)
                                              #5  0x00007f5aa7b7253f __clone (libc.so.6)

This may not be a problem in PulseAudio but rather in some libraries, and started with latest package updates.

Can you please give some advice to how debug this issue?
Comment 1 mikefender 2018-06-26 14:23:30 UTC
I managed to make it work by resetting the pair list on both devices and repairing. For some reason it seems that the issue may be related to Low Energy Bluetooth pairing not working fine.

https://askubuntu.com/questions/833322/pair-bose-quietcomfort-35-with-ubuntu-over-bluetooth

Also, I removed tlp as it seems to cause issues with the bluetooth adapter.
Comment 2 Tanu Kaskinen 2018-06-27 15:49:11 UTC
The crash indicates a bug in PulseAudio, even if there were other things somehow broken when this happened. Here's what I found out from the stack trace:

As the assertion error shows, u->thread is non-NULL when start_thread() is called, so we need to find out how that is possible.

The crash happens in start_thread(), which is only called from set_profile_cb() and pa__init(), and we can ignore pa__init() because pa__init() can't be running  when the native protocol calls pa_card_set_profile().

set_profile_cb() calls stop_thread() before calling start_thread(), and stop_thread() sets u->thread to NULL. Therefore, something must set u->thread back to non-NULL before the execution gets to the start_thread() call. That can only be done by set_profile_cb(), so apparently another card profile change was made while the original profile change was still ongoing.

The init_profile() call that set_profile_cb() does between stop_thread() and start_thread() can cause some hooks to fire, and I suspect that some module is setting the profile in those hooks. The main candidates are module-bluetooth-policy and module-switch-on-port-available.

module-bluetooth-policy probably isn't the culprit, because it only sets card profiles when new record streams appear or go away and when the bluetooth device is initially connected.

module-switch-on-port-available seems like a plausible explanation, if the previous profile was "off" (if the previous profile was HSP, then module-switch-on-port-available shouldn't switch the profile, because that would make the source go away, and the module tries to avoid such actions).

Can you try setting the headset profile to off and then back to a2dp? Does PulseAudio crash? (I can't try that myself, as I don't have a functional bluetooth setup.)
Comment 3 mikefender 2018-06-27 19:41:56 UTC
Actually I tried again this evening and it seems that it's failing again, with the same error... I'll provide the full log with --log-level=debug.

Let me know if you need more info.
Comment 4 mikefender 2018-06-27 19:42:42 UTC
Created attachment 140371 [details]
Debug level log.
Comment 5 Tanu Kaskinen 2018-06-29 11:37:04 UTC
It looks like my theory about module-switch-on-port-connect meddling with the profile change process was right. I submitted a patch to the mailing list, can you test it?

Here's the patch in patchwork:
https://patchwork.freedesktop.org/patch/233880/

Link to the raw patch:
https://patchwork.freedesktop.org/patch/233880/mbox/
Comment 6 Tanu Kaskinen 2018-06-29 18:31:12 UTC
Marking this as a 13.0 release blocker (although I suspect we'll release the fix already in 12.1).
Comment 7 mikefender 2018-06-29 19:25:31 UTC
The patch seems to work properly. I can now switch from "off" to "ad2p_sink" profiles without crashing Pulseaudio.

I'll attach a debug log for the patched Pulseaudio.

Cheers.
Comment 8 mikefender 2018-06-29 19:26:32 UTC
Created attachment 140391 [details]
Patched Pulseaudio debug level log
Comment 9 Georg Chini 2018-07-01 08:30:45 UTC
*** Bug 107081 has been marked as a duplicate of this bug. ***
Comment 10 Dominik 'Rathann' Mierzejewski 2018-07-02 10:49:47 UTC
(In reply to Tanu Kaskinen from comment #5)
> It looks like my theory about module-switch-on-port-connect meddling with
> the profile change process was right. I submitted a patch to the mailing
> list, can you test it?
> 
> Here's the patch in patchwork:
> https://patchwork.freedesktop.org/patch/233880/
> 
> Link to the raw patch:
> https://patchwork.freedesktop.org/patch/233880/mbox/

This patch (included in Fedora package version 12.0-2.fc28) fixes the crash for me. Thanks to you and Rex.
Comment 11 Tanu Kaskinen 2018-07-04 10:14:33 UTC
The fix is in master now.
Comment 12 Georg Chini 2018-07-05 19:19:01 UTC
*** Bug 107134 has been marked as a duplicate of this bug. ***
Comment 13 Tanu Kaskinen 2018-07-29 16:09:04 UTC
*** Bug 107228 has been marked as a duplicate of this bug. ***

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.