Bug 44397

The bug is reproducible.

A stack trace:
{{{
#0  0x00007ffff7b92c15 in pa_sink_set_rtpoll () from /usr/lib/libpulsecore-1.98.so
#1  0x00007fffe8cf6e2e in ?? () from /usr/lib/pulse-1.98/modules/module-remap-sink.so
#2  0x00007ffff7b98539 in pa_sink_attach_within_thread () from /usr/lib/libpulsecore-1.98.so
}}}
The last line is repeated many times.

Could you install the debug symbols and send the stack trace again after that? On Debian based distributions the debug symbols are in the package "pulseaudio-dbg", and on Fedora they are in "pulseaudio-debug". I don't know about other distributions, but they should be similar.

A stack trace:
{{{
#0  0x00007ffff7b727de in pa_msgobject_check_type (type_id=0x612040 "pa_object") at pulsecore/msgobject.c:29
#1  0x00007ffff7b8eabe in pa_sink_check_type (type_id=<optimized out>) at pulsecore/sink.c:59
#2  0x00007ffff7b9131d in pa_object_cast (o=0x76ce90) at ./pulsecore/object.h:64
#3  pa_sink_assert_ref (o=0x76ce90) at ./pulsecore/sink.h:289
#4  pa_sink_set_rtpoll (s=<optimized out>, p=0x0) at pulsecore/sink.c:777
#5  0x00007fffe9be260b in sink_input_attach_cb (i=0x775dc0) at modules/module-remap-sink.c:240
#6  0x00007ffff7b98d99 in pa_sink_attach_within_thread (s=0x777430) at pulsecore/sink.c:2861
}}}
The lines #5, #6 are repeated many times.

Often a segmentation fault with the same stacktrace occurs when starting playing in "mplayer". Verified in the latest git version.

I might try reproducing this tomorrow. Could you share your pulseaudio configuration? Apparently you've done some modifications, like loading the remap sink module.

Created attachment 55942 [details]
daemon.conf

Created attachment 55943 [details]
default.pa

I still haven't tried reproducing this... Anyway, I'd like to investigate this before 2.0, so I'll add this to the list of blocker bugs.

Created attachment 58920 [details] [review]
Preliminary patch

Hi,

It's difficult to know exactly what has happened here, but if those lines appear many times, it sounds like we have a cycle in the filter sink graph, somehow the filter is set to output to itself.

I've created a patch that should prevent that from happening. Could you try the latest git version, apply the attached patch and see if it prevents your problem? Thanks!

Created attachment 58966 [details]
daemon.conf

Created attachment 58967 [details]
default.pa

Created attachment 58968 [details]
the console log, with the preliminary patch

PulseAudio does not crash with your patch. Instead, a running client ("mplayer") freezes after I did the item 4 in the bug description. Afterwards, neither the client nor PulseAudio may be terminated by the signal TERM. I attached a new console log, it contains "that would create a cycle." I also updated the configuration files.

Clients use a PulseAudio server via a unix socket.

Thanks. Well, that at least confirms that some kind of cycle was about to be created and I assume it was avoided.

For what happens instead (freeze), I wonder if that is not a separate bug. You have a lot of "Pool full" errors, which is usually a bad sign. Do the "pool full" errors start to appear before you start switching outputs?

Then, that the gnome volume control wants to make cycles in the graph, that's also a separate bug I guess...

(In reply to comment #15)
> For what happens instead (freeze), I wonder if that is not a separate bug. You
I am not sure. Without your patch, I get not a freeze, but "Segmentation fault" when I send the TERM signal to PulseAudio. Is this "Segmentation fault" considered a bug, should I report it?

> have a lot of "Pool full" errors, which is usually a bad sign. Do the "pool
> full" errors start to appear before you start switching outputs?
Yeah, I get the message "Pool full" even without your patch when playing. Is it considered a bug, should I report it?

Not sure I follow. 

If you get a segfault only when my patch is NOT present, we can assume my patch fixes that segfault.

If you get a segfault when my patch IS present, could you post a stack trace for that segfault in this bug, please?


For the pool full errors, I haven't looked into what that means in more detail. I just get a feeling it means something is wrong...

Created attachment 59067 [details]
client.conf

If I send the TERM signal:
- With your patch, PulseAudio ignores it. It is not frozen, it throws log messages.
- Without your patch, PulseAudio yields "Segmentation fault".

Also, with your patch, PulseAudio does not respond to clients. (My previous report is incorrect.)
{{{
$ mplayer -ao pulse 14\ -\ It\ Was\ a\ Very\ Good\ Year\ -\ Frank\ Sinatra.mp3
MPlayer SVN-r34426-4.6.2 (C) 2000-2011 MPlayer Team
{{{skipped}}}
AO: [pulse] Init failed: Timeout
Failed to initialize audio driver 'pulse'
Could not open/initialize audio device -> no sound.
Audio: no sound
Video: no video


Exiting... (End of file)
}}}

With the patch:
If I clear the state of PulseAudio (in ~/.pulse), it responds to clients. When I remap a client (mplayer, audacious) with pavucontrol to another sink, PulseAudio stops responding.

Is PulseAudio taking up 100% CPU in that state, and if so, can you check with gdb where that is (full stack trace)?

Thanks.

(In reply to comment #21)
> Is PulseAudio taking up 100% CPU in that state, and if so, can you check with
> gdb where that is (full stack trace)?
Yes, 100% CPU.
{{{
#0  find_filter_sink_input (s=0x7026f0, target=<optimized out>) at pulsecore/sink-input.c:1387
#1  pa_sink_input_may_move_to (i=0x741a90, dest=0x7026f0) at pulsecore/sink-input.c:1409
#2  0x00007ffff7b8d795 in pa_sink_input_move_to (i=0x741a90, dest=0x7026f0, save=true) at pulsecore/sink-input.c:1727
#3  0x00007ffff1cf64a1 in command_move_stream (pd=<optimized out>, command=67, tag=61, t=<optimized out>, userdata=0x7101c0) at pulsecore/protocol-native.c:4493
#4  0x00007ffff76d4e45 in pa_pdispatch_run (pd=0x7268c0, packet=<optimized out>, creds=0x70dc20, userdata=0x7101c0) at pulsecore/pdispatch.c:336
#5  0x00007ffff1cfe921 in pstream_packet_callback (p=0x70dad0, packet=0x7311b0, creds=0x70dc20, userdata=0x7101c0) at pulsecore/protocol-native.c:4747
#6  0x00007ffff76d8b1d in do_read (p=0x70dad0) at pulsecore/pstream.c:812
#7  do_something (p=0x70dad0) at pulsecore/pstream.c:180
#8  0x00007ffff76d9600 in io_callback (io=<optimized out>, userdata=<optimized out>) at pulsecore/pstream.c:209
#9  0x00007ffff76c736c in callback (m=<optimized out>, e=<optimized out>, fd=<optimized out>, f=<optimized out>, userdata=0x642e20) at pulsecore/iochannel.c:160
#10 0x00007ffff7920c87 in dispatch_pollfds (m=0x63d070) at pulse/mainloop.c:677
#11 pa_mainloop_dispatch (m=0x63d070) at pulse/mainloop.c:927
#12 0x00007ffff7920dde in pa_mainloop_iterate (m=0x63d070, block=<optimized out>, retval=0x7fffffffe578) at pulse/mainloop.c:958
#13 0x00007ffff7920e2c in pa_mainloop_run (m=0x63d070, retval=0x7fffffffe578) at pulse/mainloop.c:973
#14 0x000000000040c0cd in main (argc=<optimized out>, argv=<optimized out>) at daemon/main.c:1135
}}}

Could you dump the output of 'pacmd ls' from /before/ you start a move/playback that breaks everything?

Created attachment 59079 [details]
pacmd ls

@David: Maybe, you should replace "s = s->input_to_master->origin_sink;" with "s = s->input_to_master->sink;" in your patch?

The console log:
{{{
D: [pulseaudio] module-stream-restore.c: Client gnome-control-center changes entry sink-input-by-media-role:filter.
}}}
I.e. "gnome-control-center" connects all filter sink inputs to the sink selected in "Sound Preferences". Do I understand it correctly? If so then I will report it to the Gnome bugtracker.

Created attachment 59098 [details] [review]
Patch to catch loops of length > 1

Roman, here's another, independent, patch that might fix this. Could you give this a go? (and thank you for your patience in pinning this down!)

My suspicion is that this is a loop, as David surmises, but the loop length is >1 which David's patch won't catch. This patch isn't bullet proof -- it would fail in a loop with more than one type of filter, but I don't see that this would happen in your configuration. If this works, we can convert this into proper loop detection, independent of the module name logic.

@Roman, comment #25, well spotted! Yes, I think this should change. Could you try your change and see if it resolves your problem?

@Arun, the patch is indeed meant to catch cycles even if the length > 1, hence the while loop. However maybe the while loop should itself be more resilient against existing loops.

Comment on attachment 59098 [details] [review]
Patch to catch loops of length > 1

David, indeed, I was being blind.

Created attachment 59107 [details] [review]
patch.beroal.0

This patch does not lead to freezes.

Ok, thanks for the feedback! I have now committed a patch for both sinks and sources, which should be in the 1.99.2 release. 
Please reopen this bug if this should not be fixed in that release. Thank you!

Patch reference:
http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=b7fab75fdde21569ef0be4c7c52887031393d75c