GStreamer update (7-Oct-2008, Intrepid) causes Banshee crash

[Michael B. Trausch]

  affects ubuntu/banshee
  affects ubuntu/gstreamer0.10
  done

Today after updating gstreamer, Banshee media player now randomly
crashes after a song is finished playing with the following output from
gstreamer, and subsequently killing the Banshee media player
application:

** GStreamer:ERROR:gstcaps.c:1370:gst_caps_subtract: assertion failed:
(subtrahend->structs->len > 0)

** (Nereid:7261): WARNING **: Thread (nil) may have been prematurely finalized

** (Nereid:7261): WARNING **: Thread (nil) may have been prematurely finalized
zsh: segmentation fault (core dumped) banshee

Now, I am not sure if the update is triggering a bug in Banshee or if
the update created a bug in gstreamer, so I am marking this bug as a bug
in both until that can be determined.

This crash did not happen prior to updating today; it presently happens
with alarming regularity (not on _every_ song switch; I can play
anywhere from 1 to 15 songs before it crashes, and it does not seem to
crash unless I let the song play all the way through to the end). My
music collection consists of mostly Ogg Vorbis music, though there is
some MP3 present within it.

[Michael B. Trausch (mtrausch)]

Crash Logs for Banshee
======================

Crash 1 (there was no core anywhere, even though the shell said it was dumped):
Ubuntu Intrepid:[0-3/1998-139]:~> time banshee
[Info 17:51:45.820] Running Banshee 1.2.1
[Info 17:51:48.435] All services are started 2.322674s
[Info 17:51:49.796] nereid Client Started

(Nereid:11637): GStreamer-CRITICAL **: gst_caps_is_fixed: assertion `GST_IS_CAPS (caps)' failed

(Nereid:11637): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:11637): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed

(Nereid:11637): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:11637): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed
**
GStreamer:ERROR:gstcaps.c:1370:gst_caps_subtract: assertion failed: (subtrahend->structs->len > 0)

** (Nereid:11637): WARNING **: Thread (nil) may have been prematurely finalized

** (Nereid:11637): WARNING **: Thread (nil) may have been prematurely finalized
zsh: segmentation fault (core dumped) banshee
banshee 145.37s user 17.70s system 8% cpu 33:21.77 total

Crash 2 (there was no core anywhere, even though the shell said it was dumped):
Ubuntu Intrepid:[0-4/1999-139]:~> time banshee
[Info 19:37:28.242] Running Banshee 1.2.1
[Info 19:37:31.132] All services are started 2.553555s
[Info 19:37:32.458] nereid Client Started

(Nereid:12835): GStreamer-CRITICAL **: gst_caps_is_fixed: assertion `GST_IS_CAPS (caps)' failed

(Nereid:12835): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:12835): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed

(Nereid:12835): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:12835): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed
**
GStreamer:ERROR:gstcaps.c:1370:gst_caps_subtract: assertion failed: (subtrahend->structs->len > 0)

** (Nereid:12835): WARNING **: Thread (nil) may have been prematurely finalized

** (Nereid:12835): WARNING **: Thread (nil) may have been prematurely finalized
zsh: segmentation fault (core dumped) banshee
banshee 349.09s user 44.59s system 8% cpu 1:21:20.89 total

Every crash looks the same, and happens also when playing Internet radio (the two crashes above were triggered while playing netradio). Apport does not kick off when it dies, nor does the Mono runtime leave behind a core file when Banshee gets the signal via gstreamer.

[Sebastian Dröge (slomo)]

Hi,
which version of banshee, gstreamer0.10-plugins-base and gstreamer0.10 is this?

Could you try to get a backtrace with debugging symbols for glib, banshee, gst-plugins-base and gstreamer installed?

[Michael B. Trausch (mtrausch)]

On Wed, Oct 08, 2008 at 08:16:03AM -0000, =?ISO-8859-1?Q?Sebastian_Dr=F6ge_ wrote:
> Hi,
> which version of banshee, gstreamer0.10-plugins-base and gstreamer0.10 is this?

The versions in Intrepid as of the time the bug report was created...
Ubuntu Intrepid:[0-8/2123-1]:test> COLUMNS=78 dpkg -l | egrep '(banshee|gstreamer)'
ii banshee 1.2.1-3ubuntu1 Media Management and Playback application
ii gstreamer0.10- 0.10.21-1 GStreamer plugin for ALSA
ii gstreamer0.10- 0.10.5-1 FFmpeg plugin for GStreamer
ii gstreamer0.10- 0.10.7.debian- Fluendo mp3 decoder GStreamer plugin
ii gstreamer0.10- 0.10.21-1 GStreamer plugin for GnomeVFS
ii gstreamer0.10- 0.10.8-1 GStreamer plugins from the "bad" set
ii gstreamer0.10- 0.10.21-1 GStreamer plugins from the "base" set
ii gstreamer0.10- 0.10.21-1 GStreamer helper programs from the "base" se
ii gstreamer0.10- 0.10.10-1 GStreamer plugins from the "good" set
ii gstreamer0.10- 0.10.9-1 GStreamer plugins from the "ugly" set
ii gstreamer0.10- 0.10.10-1 GStreamer plugin for PulseAudio
ii gstreamer0.10- 0.10.21-2 Tools for use with GStreamer
ii gstreamer0.10- 0.10.21-1 GStreamer plugins for X11 and Pango
ii libgstreamer-p 0.10.21-1 GStreamer libraries from the "base" set
ii libgstreamer0. 0.10.21-2 Core GStreamer libraries and elements

There is a new version of gstreamer for Intrepid (0.10.21-3) now, so I
am going to try that before I try to tear through the system.

> Could you try to get a backtrace with debugging symbols for glib,
> banshee, gst-plugins-base and gstreamer installed?

See the attached file, which contains the best I've been able to come up
with so far. I am about to install today's updates, and I *hope* that
whatever brokeded yesterday is unbrokeded today, but we'll see; I
noticed a few gstreamer updates in today's batch.

Note that there are no “debugging symbols”, per sé, for Banshee.
Banshee is a managed mode application and requires a different debugger
for dumping stack traces. Don't know if I know how to do that quite yet
or not, I know how to use the traces when Mono's runtime outputs them
automatically, but that's not happening in this case. It seems (from
the second stack trace in the attached file) that the SIGSEGV is being
caused by the Mono runtime's inability to handle SIGABRT properly in
this case. It's strange given that I'm used to the runtime outputting a
very helpful stack trace when something goes horribly wrong outside of
the managed world.

    --- Mike

--
My sigfile ran away and is on hiatus.

[Michael B. Trausch (mtrausch)]

Meh. Today's update did not fix the problem; it has happened again.

The way it is presently is *definitely* unsuitable for release.

[Sebastian Dröge (slomo)]

Ok, so two things are broken here... mono's SIGABRT handler and something else ;)

As I can't reproduce it here could you try getting a string representation of the two parameters passed to gst_caps_subtract()?
Just call "p gst_caps_to_string (0x2549780)" of course with the correct, updated address.

Also the name of the last pad (0x7f2f48757e10 in your case) and it's parent would be interesting.

For this call "p gst_object_get_name (0x7f2f48757e10)" and "p gst_object_get_name (gst_object_get_parent (0x7f2f48757e10))"

Don't forget to update all addresses :) It seems that the pad at 0x7f2f48757e10 has empty caps for some reason which should not happen in any case...

[Nathan (nathansamson)]

How do we run "p gst_blablabla"?

[Sebastian Dröge (slomo)]

In gdb after the SIGABRT happened... the same way as "bt" is called

[Michael B. Trausch (mtrausch)]

Alright, well, this isn't going to yield as much information as you'd like, I'm afraid. I have the debugger attached to the process at the moment, and am attaching the debug session. However, when I did "p gst_object_get_name(0x169ee30)" (0x169ee30 being the pad number this time around) after the SIGABRT, I was greeted with:

==========
(gdb) p gst_object_get_name(0x169ee30)
[Thread 0x43abf950 (LWP 8863) exited]

==========

Banshee was responsive again, tried to activate a new song, and that of course failed.

I gave a SIGINT, and got:

==========
[Thread 0x43abf950 (LWP 9304) exited]
^C
Program received signal SIGINT, Interrupt.
[Switching to Thread 0x7f99deb98710 (LWP 8581)]
0x00007f99ddeb0b04 in __lll_lock_wait () from /lib/libpthread.so.0
The program being debugged was signaled while in a function called from GDB.
GDB remains in the frame where the signal was received.
To change this behavior use "set unwindonsignal on"
Evaluation of the expression containing the function (gst_object_get_name) will be abandoned.
==========

Alright, so I tried to continue a few times, failing of course. So, I did another backtrace and found out that gst_object_get_parent(...) was calling for a mutex, and hanging on attempting to get it. I don't know how to work around that.

I'll leave the debugger active for now... Any advice on how to proceed from here? The entire debugging session so far is attached.

[Michael B. Trausch (mtrausch)]

Here is an updated debug log with the new info

[Michael B. Trausch (mtrausch)]

Here is the entire debug session up through termination. Core file
(compressed with bzip2) coming soon, it's too big to email in; hopefully
it may be useful to someone doing a postmortem on the process.

--
My sigfile ran away and is on hiatus.

[Michael B. Trausch (mtrausch)]

Ugh... LP puked on the email I sent it. Multiple attachments coming from the next run leading to a crash. In this one, the debug session for this time around. The command ran this time was:

"GST_DEBUG_NO_COLOR=1 GST_DEBUG=*STATE*:5 banshee &> log"

Which was then attached to with GDB.

[Michael B. Trausch (mtrausch)]

Recently, Mono 2.0 was made available for Intrepid in a PPA, so I decided to install it to see if I could get any more insight. It would appear that the SIGABRT problem with Mono 1.9 in Intrepid was fixed, yielding a far more useful crash output. I don't know if this will be in any help, but since it just crashed in my terminal window, here is the output:

Friday, 2008-Oct-17 at 03:09:48 - mbt@zest - Linux v2.6.27
Ubuntu Intrepid:[0-5/6082-0]:~> banshee
[Info 03:09:50.218] Running Banshee 1.2.1
[Info 03:09:52.790] All services are started 2.300377s
[Info 03:09:54.219] nereid Client Started

(Nereid:27164): GStreamer-CRITICAL **: gst_caps_is_fixed: assertion `GST_IS_CAPS (caps)' failed

(Nereid:27164): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:27164): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed

(Nereid:27164): GStreamer-CRITICAL **: gst_caps_is_any: assertion `GST_IS_CAPS (caps)' failed

(Nereid:27164): GStreamer-CRITICAL **: gst_caps_is_empty: assertion `GST_IS_CAPS (caps)' failed
**
GStreamer:ERROR:gstcaps.c:1370:gst_caps_subtract: assertion failed: (subtrahend->structs->len > 0)

** (Nereid:27164): WARNING **: Thread (nil) may have been prematurely finalized

Native stacktrace:

 banshee-1 [0x429cb5]
 banshee-1 [0x52fddd]
 /lib/libpthread.so.0 [0x7fe49f66c0f0]
 banshee-1 [0x4679c7]
 banshee-1(mono_jit_info_table_find+0x3a) [0x46a98a]
 banshee-1 [0x52fb5c]
 /lib/libpthread.so.0 [0x7fe49f66c0f0]
 /lib/libc.so.6(gsignal+0x35) [0x7fe49f098fd5]
 /lib/libc.so.6(abort+0x183) [0x7fe49f09ab43]
 /usr/lib/libglib-2.0.so.0(g_assertion_message+0x113) [0x7fe49fce5d83]
 /usr/lib/libglib-2.0.so.0 [0x7fe49fce6222]
 /usr/lib/libgstreamer-0.10.so.0(gst_caps_subtract+0x1c6) [0x7fe49297d526]
 /usr/lib/libgstreamer-0.10.so.0(gst_caps_is_subset+0xcd) [0x7fe49297d6cd]
 /usr/lib/libgstreamer-0.10.so.0(gst_caps_is_equal+0x4d) [0x7fe49297d73d]
 /usr/lib/libgstreamer-0.10.so.0(gst_pad_accept_caps+0x113) [0x7fe49299c503]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299c681]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299d16f]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db4bb2]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db4bb2]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/gstreamer-0.10/libgstcoreelements.so [0x7fe48d52c70b]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db4bb2]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299cfd9]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db43cf]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db51cc]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299c875]
 /usr/lib/libgstreamer-0.10.so.0(gst_pad_push+0x34b) [0x7fe49299d90b]
 /usr/lib/libgstbase-0.10.so.0 [0x7fe491db5220]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299c875]
 /usr/lib/libgstreamer-0.10.so.0(gst_pad_push+0x34b) [0x7fe49299d90b]
 /usr/lib/libgstreamer-0.10.so.0 [0x7fe49299c875]
 /usr/lib/libgstreamer-0.10.so.0(gst_pad_push+0x34b) [0x7fe49299d90b]
 /usr/lib/gstreamer-0.10/libgstcoreelements.so [0x7fe48d528522]
 /usr/lib...

[Wim Taymans (wim-taymans)]

I did some debugging here, it seems like a race in (the rewritten) basetransform could have caused this. A possible fix is commited to CVS, it seems to make banshee run fine for me now.

2008-10-21 Wim Taymans <email address hidden>

        * libs/gst/base/gstbasetransform.c:
        (gst_base_transform_prepare_output_buffer),
        (gst_base_transform_buffer_alloc), (gst_base_transform_suggest):
        Protect sink_alloc caps with the sinkpad lock to avoid nasty caps
        refcount problems as seen in banshee and maybe also in farsight2.
        Remove atomic int now that we need to take the lock anyways.

[Michael B. Trausch (mtrausch)]

Cool, can the patch be applied to the GStreamer in Intrepid?

[Michael B. Trausch (mtrausch)]

Wim,

Can you isolate the patch and put it here so that I can do something with it? I am utterly unable to get at CVS to find it, and git-cvsimport is taking *forever* for some reason; I wholly do not expect it to finish tonight, if ever. I can't navigate CVS worth a rats' rear, either, and it'd appear that I can't mirror the CVS tree to import it into bzr where I'd be quite happy to work. Anywho, I digress. Any chance you can post the patch? Thanks!

[Casey Greene (casey-s-greene)]

I have the same bug -- since there seems to be a fix I've "nominated it for release." I hope that will bring it to attention so that it can be fixed before intrepid's release. It makes the release look poor since banshee is likely widely used.

Thanks, and I hope this was not an incorrect course of action!

[Michael B. Trausch (mtrausch)]

Well, as it turns out git finally finished. Only took it 8 hours. *sigh*

Anyway, I am seeing if I can patch it... Uploaded a test package to the PPA for building, will hopefully have a candidate today for someone to look at.

[Michael B. Trausch (mtrausch)]

Am testing the patch now...

If my 2½ year old cries today, I'll know it didn't work. :-) (I was playing his favorite song last night when it crashed and he said "FIX IT DADDY"... there's motivation, I suppose, lol)

Anyway, so far, so good. There is a package in the PPA built with the patch:

https://edge.launchpad.net/~mtrausch/+archive

[Michael B. Trausch (mtrausch)]

  affects ubuntu/banshee
  status invalid
  affects ubuntu/gstreamer0.10
  status confirmed
  subscribe ubuntu-main-sponsors
  done

This is the debdiff to fix this issue; the resulting package version is
0.10.21-3ubuntu1. Thanks to Wim Taymans for the fix, which has been
pulled from upstream CVS.

Fix has eliminated the crash in Banshee when switching between songs
and playing Internet radio streams such as RadioIO or stations from
Shoutcast.

This patch is available for testing from my PPA if there are any
questions as to whether or not it works or needs to be verified by
anyone else; the version of the package there is 0.10.21-3ubuntu1~mbt1.

diffstat output:
 debian/patches/04_fix-basetransform-race.patch | 106 +++++++++++++++++
 gstreamer0.10-0.10.21/debian/changelog | 9 +
 2 files changed, 115 insertions(+)

Please upload this patch to Intrepid as soon as possible. Thank you!

--
My sigfile ran away and is on hiatus.

[Sebastien Bacher (seb128)]

thank you for your bug report, could you look if the change if one of those which has been fixed in the recent debian updates? there is bug #287482 about syncing those updates after the intrepid candidate

[Michael B. Trausch (mtrausch)]

  affects ubuntu/gstreamer0.10
  duplicate 287482

Ahh, I see. Yes, this patch is included in the Debian sync request.
(Thanks slomo!) Will go ahead and mark this as a dup of 287482 since
that'll be the issue being closed by the sync and that will
consequently take care of this one.

At the very least, I can attest to the fact that the bugfix works! :)

--
My sigfile ran away and is on hiatus.