Bug 447543

Summary: Rhythmbox crashes.... related to pulseaudio?
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: pulseaudioAssignee: Lennart Poettering <lpoetter>
Status: CLOSED UPSTREAM QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: low    
Version: rawhideCC: antonio.montagnani, lkundrak, pertusus, pierre-bugzilla, yaneti
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2008-06-26 18:37:16 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
quick dirty fix for pause assertion fail
none
quick dirty fix for pause and jump forth and back assertion fail none

Description Tom London 2008-05-20 13:52:04 UTC
Description of problem:
With latest Rawhide rhythmbox and pulseaudio, I'm seeing frequent crashes of
rhythmbox, typically at the end of an mp3.

Besides the bug-buddy report to gnome on rhythmbox, I see this in
~/.xsession-errors:

E: time-smoother.c: Assertion 'x >= s->pause_time' failed at
pulsecore/time-smoother.c:423, function pa_smoother_resume(). Aborting.

Could this be a pulseaudio issue?

I see this in /var/log/messages at about the "right time":
May 20 06:32:34 localhost pulseaudio[3588]: pcm_hw.c: SNDRV_PCM_IOCTL_DRAIN failed

[Sorry if this is just noise, just want to get this in front of the right eyes....]

Version-Release number of selected component (if applicable):
rhythmbox-0.11.5-14.fc10.i386
pulseaudio-libs-glib2-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-gconf-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-libs-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-utils-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-bluetooth-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-x11-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-zeroconf-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-esound-compat-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-debuginfo-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-libs-zeroconf-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-core-libs-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-jack-0.9.11-0.1.svn20080516.fc10.i386
pulseaudio-module-lirc-0.9.11-0.1.svn20080516.fc10.i386


How reproducible:
Very frequent, but irregular

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 antonio montagnani 2008-05-22 12:03:29 UTC
1) when I try to import a folder, Rhythmbox crashes and it doesn't sound any on
my radio, that was doing before upgrading from F9 to rawhide...

Comment 2 Tom London 2008-05-28 21:12:48 UTC
I'm still getting this crash, typically "at the end of a song".

Here is the output from gdb of a crash:

[tbl@localhost ~]$ gdb rhythmbox
GNU gdb Fedora (6.8-9.fc10)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...
(gdb) 
(gdb) run
Starting program: /usr/bin/rhythmbox 
[Thread debugging using libthread_db enabled]
[New Thread 0xb80a19a0 (LWP 4475)]
Detaching after fork from child process 4486.

(rhythmbox:4475): GnomeUI-WARNING **: While connecting to session manager:
Could not open network socket.
[New Thread 0xb6dc3b90 (LWP 4487)]
[Thread 0xb6dc3b90 (LWP 4487) exited]
[New Thread 0xb6dc3b90 (LWP 4492)]
[Thread 0xb6dc3b90 (LWP 4492) exited]
[New Thread 0xb6dc3b90 (LWP 4493)]
[Thread 0xb6dc3b90 (LWP 4493) exited]
[New Thread 0xb6dc3b90 (LWP 4494)]
[New Thread 0xb5cffb90 (LWP 4495)]
[New Thread 0xb52feb90 (LWP 4496)]
[Thread 0xb6dc3b90 (LWP 4494) exited]
[Thread 0xb52feb90 (LWP 4496) exited]
Missing separate debuginfo for /home/tbl/.gstreamer-0.10/plugins/libgstflump3dec.so
[New Thread 0xb52feb90 (LWP 4502)]
[New Thread 0xb6dc3b90 (LWP 4503)]
[New Thread 0x31cab90 (LWP 4504)]
[New Thread 0x8045b90 (LWP 4505)]
[New Thread 0xb08fcb90 (LWP 4506)]
[New Thread 0xafefbb90 (LWP 4507)]
[Thread 0xafefbb90 (LWP 4507) exited]
[New Thread 0xafefbb90 (LWP 4512)]
[Thread 0xafefbb90 (LWP 4512) exited]
[New Thread 0xafefbb90 (LWP 4546)]
[New Thread 0xaf4fab90 (LWP 4547)]
[Thread 0xaf4fab90 (LWP 4547) exited]
[Thread 0xafefbb90 (LWP 4546) exited]
[New Thread 0xafefbb90 (LWP 4594)]
[New Thread 0xaf4fab90 (LWP 4595)]
[Thread 0xafefbb90 (LWP 4594) exited]
[Thread 0xaf4fab90 (LWP 4595) exited]
[New Thread 0xaf4fab90 (LWP 4637)]
[New Thread 0xafefbb90 (LWP 4638)]
[Thread 0xaf4fab90 (LWP 4637) exited]
[Thread 0xafefbb90 (LWP 4638) exited]
[Thread 0xb08fcb90 (LWP 4506) exited]
[New Thread 0xb08fcb90 (LWP 4667)]
[New Thread 0xafefbb90 (LWP 4668)]
[New Thread 0xaf4fab90 (LWP 4669)]
[Thread 0xb52feb90 (LWP 4502) exited]
[Thread 0xaf4fab90 (LWP 4669) exited]
[New Thread 0xaf4fab90 (LWP 4682)]
[Thread 0xaf4fab90 (LWP 4682) exited]
[New Thread 0xaf4fab90 (LWP 4724)]
[New Thread 0xb52feb90 (LWP 4725)]
[New Thread 0xaeaf9b90 (LWP 4726)]
[Thread 0xaf4fab90 (LWP 4724) exited]
[Thread 0xb52feb90 (LWP 4725) exited]
[Thread 0xaeaf9b90 (LWP 4726) exited]
[New Thread 0xaeaf9b90 (LWP 4767)]
[New Thread 0xb52feb90 (LWP 4768)]
[Thread 0xaeaf9b90 (LWP 4767) exited]
[Thread 0xb52feb90 (LWP 4768) exited]
[New Thread 0xb52feb90 (LWP 4814)]
[New Thread 0xaeaf9b90 (LWP 4815)]
[Thread 0xb52feb90 (LWP 4814) exited]
[Thread 0xaeaf9b90 (LWP 4815) exited]
E: time-smoother.c: Assertion 'x >= s->pause_time' failed at
pulsecore/time-smoother.c:423, function pa_smoother_resume(). Aborting.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0xb08fcb90 (LWP 4667)]
0x00110416 in __kernel_vsyscall ()
Missing separate debuginfos, use: debuginfo-install ORBit2.i386 acl.i386
alsa-lib.i386 attr.i386 audiofile.i386 avahi.i386 cyrus-sasl.i386 dbus-glib.i386
dbus.i386 e2fsprogs.i386 esound.i386 evolution-data-server.i386 expat.i386
fontconfig.i386 freetype.i386 gamin.i386 gdbm.i386 gnome-keyring.i386
gnome-media.i386 gnome-python2.i386 gnutls.i386 gstreamer-python.i386
keyutils.i386 krb5.i386 libICE.i386 libSM.i386 libX11.i386 libXau.i386
libXcomposite.i386 libXcursor.i386 libXdmcp.i386 libXext.i386 libXfixes.i386
libXi.i386 libXrandr.i386 libXrender.i386 libart_lgpl.i386 libbonobo.i386
libbonoboui.i386 libcap.i386 libgcrypt.i386 libglade2.i386 libgnome.i386
libgnomecanvas.i386 libgnomeui.i386 libgpg-error.i386 libgpod.i386 libjpeg.i386
libmusicbrainz.i386 libnotify.i386 libselinux.i386 libsoup.i386 libtasn1.i386
libxcb.i386 libxml2.i386 nautilus-cd-burner.i386 openssl.i686 pixman.i386
popt.i386 pycairo.i386 pygobject2.i386 pygtk2.i386 python.i386
totem-pl-parser.i386 zlib.i386
(gdb) where
#0  0x00110416 in __kernel_vsyscall ()
#1  0x00a81610 in raise (sig=<value optimized out>)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#2  0x00a82fd8 in abort () at abort.c:88
#3  0x016a7911 in pa_smoother_resume (s=<value optimized out>, 
    x=<value optimized out>) at pulsecore/time-smoother.c:423
#4  0x0167dcd3 in stream_get_timing_info_callback (pd=<value optimized out>, 
    command=<value optimized out>, tag=<value optimized out>, 
    t=<value optimized out>, userdata=<value optimized out>)
    at pulse/stream.c:1423
#5  0x01699995 in run_action (pd=<value optimized out>, 
    r=<value optimized out>, command=<value optimized out>, 
    ts=<value optimized out>) at pulsecore/pdispatch.c:185
#6  0x0169a5b8 in pa_pdispatch_run (pd=<value optimized out>, 
    packet=<value optimized out>, creds=<value optimized out>, userdata=Could
not find the frame base for "pa_pdispatch_run".
)
    at pulsecore/pdispatch.c:236
#7  0x01666dbf in pstream_packet_callback (p=<value optimized out>, 
    packet=<value optimized out>, creds=<value optimized out>, 
    userdata=<value optimized out>) at pulse/context.c:332
#8  0x0169c8b3 in do_something (p=<value optimized out>)
    at pulsecore/pstream.c:818
#9  0x0169d599 in io_callback (io=<value optimized out>, 
    userdata=<value optimized out>) at pulsecore/pstream.c:215
---Type <return> to continue, or q <return> to quit---
#10 0x0168e318 in callback (m=<value optimized out>, e=<value optimized out>, 
    fd=<value optimized out>, f=<value optimized out>, 
    userdata=<value optimized out>) at pulsecore/iochannel.c:121
#11 0x016721c9 in pa_mainloop_dispatch (m=<value optimized out>)
    at pulse/mainloop.c:679
#12 0x01672521 in pa_mainloop_iterate (m=<value optimized out>, 
    block=<value optimized out>, retval=<value optimized out>)
    at pulse/mainloop.c:922
#13 0x016725e4 in pa_mainloop_run (m=<value optimized out>, 
    retval=<value optimized out>) at pulse/mainloop.c:937
#14 0x01681a03 in thread (userdata=Could not find the frame base for "thread".
) at pulse/thread-mainloop.c:91
#15 0x016a9777 in internal_thread_func (userdata=<value optimized out>)
    at pulsecore/thread-posix.c:73
#16 0x00c0351f in start_thread (arg=<value optimized out>)
    at pthread_create.c:297
#17 0x00b39bde in clone () from /lib/libc.so.6
(gdb) quit
The program is running.  Exit anyway? (y or n) y
[tbl@localhost ~]$ 


Comment 3 Bastien Nocera 2008-05-31 16:51:39 UTC
*** Bug 449224 has been marked as a duplicate of this bug. ***

Comment 4 Tom London 2008-06-03 19:03:08 UTC
In addition to the frequent
E: time-smoother.c: Assertion 'x >= s->pause_time' failed at
pulsecore/time-smoother.c:423, function pa_smoother_resume(). Aborting.

rhythmbox aborts, I am also seeing

qemu-kvm: pcm_pulse.c:274: pulse_write: Assertion `pcm->last_size >= (size *
pcm->frame_size)' failed.

qemu-kvm aborts.  

Are these possible related?

Comment 5 Tom London 2008-06-20 19:19:43 UTC
I continue to get this very often (5-10 times per day).

Seems to happen at the same time as I get this in /var/log/messages:
Jun 20 12:07:14 localhost pulseaudio[3201]: pcm_hw.c: SNDRV_PCM_IOCTL_DRAIN failed
Jun 20 12:07:14 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x3
Jun 20 12:07:14 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x2
Jun 20 12:07:14 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x3

Any other helpful information I can provide?

rhythmbox-0.11.5-15.fc10.i386
pulseaudio-module-lirc-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-core-libs-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-glib2-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-debuginfo-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-esound-compat-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-utils-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-jack-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-zeroconf-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-zeroconf-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-x11-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-gconf-0.9.11-0.4.svn20080618.fc10.i386


Comment 6 Patrice Dumas 2008-06-23 10:23:54 UTC
I see the same with gnash.
You can download
http://www.environnement.ens.fr/perso/dumas/sound1.swf

and play it with 
gnash sound1.swf

after a non-reproducible amount of time it will abort with that assertion
failed.

Comment 7 Tom London 2008-06-25 13:27:56 UTC
I continue to get pulseaudio and rhythmbox crashes.  Here is the latest log from
/var/log/messages:

Jun 25 06:18:25 localhost ntpd[2593]: synchronized to 75.173.17.28, stratum 2
Jun 25 06:18:25 localhost ntpd[2593]: time reset +2.787625 s
Jun 25 06:18:25 localhost ntpd[2593]: kernel time sync status change 0001
Jun 25 06:18:25 localhost pulseaudio[3167]: module-alsa-sink.c: Increasing
wakeup watermark to 40.00 ms
Jun 25 06:18:25 localhost pulseaudio[3167]: time-smoother.c: Assertion 'x >=
s->last_x' failed at pulsecore/time-smoother.c:381, function pa_smoother_get().
Aborting.
Jun 25 06:18:25 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x3
Jun 25 06:18:25 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x2

This was following 6 minutes later with another rhythmbox crash.  The following
in /var/log/messages:

Jun 25 06:24:21 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x3
Jun 25 06:24:21 localhost pulseaudio[3785]: pcm_hw.c: SNDRV_PCM_IOCTL_DRAIN failed
Jun 25 06:24:21 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x2
Jun 25 06:24:21 localhost kernel:<4>ALSA sound/pci/hda/hda_codec.c:725:
hda_codec_cleanup_stream: NID=0x3

and this in ~/.xsession-errors:
E: time-smoother.c: Assertion 'x >= s->pause_time' failed at
pulsecore/time-smoother.c:421, function pa_smoother_resume(). Aborting.

Here are the current versions:
pulseaudio-module-x11-0.9.11-0.5.svn20080622.fc10.i386
rhythmbox-0.11.5-15.fc10.i386
pulseaudio-module-zeroconf-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-module-gconf-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-utils-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-module-jack-0.9.11-0.5.svn20080622.fc10.i386
rhythmbox-debuginfo-0.11.5-15.fc10.i386
pulseaudio-debuginfo-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-esound-compat-0.9.11-0.5.svn20080622.fc10.i386
rhythmbox-lirc-0.11.5-15.fc10.i386
pulseaudio-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-module-bluetooth-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-libs-zeroconf-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-core-libs-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-module-lirc-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-libs-glib2-0.9.11-0.5.svn20080622.fc10.i386
pulseaudio-libs-0.9.11-0.5.svn20080622.fc10.i386




Comment 8 santiago angel 2008-06-26 07:55:35 UTC
I see the same with amarok 

play a tracklist, click forward and amarok crash:

E: time-smoother.c: Assertion 'x >= s->pause_time' failed at
pulsecore/time-smoother.c:421, function pa_smoother_resume(). Aborting.

pulseaudio still running

packages

pulseaudio-esound-compat-0.9.11-0.4.svn20080618.fc10.i386
kde-settings-pulseaudio-4.0-23.fc9.noarch
pulseaudio-utils-0.9.11-0.4.svn20080618.fc10.i386
xine-lib-pulseaudio-1.1.12-3.fc10.i386
pulseaudio-libs-devel-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-0.9.11-0.4.svn20080618.fc10.i386
alsa-plugins-pulseaudio-1.0.16-4.fc9.i386
pulseaudio-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-zeroconf-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-lirc-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-zeroconf-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-x11-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-libs-glib2-0.9.11-0.4.svn20080618.fc10.i386
gstreamer-plugins-pulse-0.9.5-0.5.svn20070924.fc9.i386
pulseaudio-core-libs-0.9.11-0.4.svn20080618.fc10.i386
pulseaudio-module-gconf-0.9.11-0.4.svn20080618.fc10.i386
amarok-extras-nonfree-1.4.8-1.lvn9.i386
amarok-1.4.9.1-4.fc10.i386


Comment 9 santiago angel 2008-06-26 08:55:10 UTC
Created attachment 310314 [details]
quick dirty fix for pause assertion fail

Comment 10 santiago angel 2008-06-26 08:56:22 UTC
--- pulseaudio-0.9.11/src/pulsecore/time-smoother.c	2008-05-15
19:04:04.000000000 -0500
+++ pulseaudio-0.9.11.rev/src/pulsecore/time-smoother.c	2008-06-26
03:22:26.000000000 -0500
@@ -420,7 +420,7 @@
     if (!s->paused)
         return;
 
-    pa_assert(x >= s->pause_time);
+    //pa_assert(x >= s->pause_time);
 
 /*     pa_log_debug("resume(%llu)", (unsigned long long) x); */

Comment 11 santiago angel 2008-06-26 09:16:47 UTC
previous patch results in this:

E: time-smoother.c: Assertion 'x >= s->last_x' failed at
pulsecore/time-smoother.c:383, function pa_smoother_get(). Aborting. 



Comment 12 santiago angel 2008-06-26 09:18:24 UTC
quick dirty fix for previous error:


--- pulseaudio-0.9.11/src/pulsecore/time-smoother.c	2008-05-15
19:04:04.000000000 -0500
+++ pulseaudio-0.9.11.rev/src/pulsecore/time-smoother.c	2008-06-26
04:00:52.000000000 -0500
@@ -380,7 +380,7 @@
     if (s->monotonic) {
 
         /* Make sure the querier doesn't jump forth and back. */
-        pa_assert(x >= s->last_x);
+        //pa_assert(x >= s->last_x);
         s->last_x = x;
 
         if (y < s->last_y)
@@ -420,7 +420,7 @@
     if (!s->paused)
         return;
 
-    pa_assert(x >= s->pause_time);
+    //pa_assert(x >= s->pause_time);
 
 /*     pa_log_debug("resume(%llu)", (unsigned long long) x); */

Comment 13 santiago angel 2008-06-26 09:28:21 UTC
Created attachment 310319 [details]
quick dirty fix for pause and jump forth and back assertion fail

Comment 14 Lennart Poettering 2008-06-26 18:36:57 UTC
This has now been fixed upstream. I will upload a new git snapshot shortly.