GNOME Bugzilla – Bug 342789
[audioresample] doesn't clear state when stopped, causing non-negotiated errors when being reused
Last modified: 2006-08-01 11:12:59 UTC
Please describe the problem: After Rhythmbox plays a song that doesn't have any artist/album/track data, attempting to skip to the next track causes Rhythmbox to repeatedly skip through all other tracks, playing ~1s of each before getting some internal error, placing the "no entry" symbol next to the track and trying another. Repeat until you get annoyed enough to kill it off. Portion of a debug log from this situation: (16:57:25) [0x81528e8] [rb_random_play_order_get_next] rb-play-order-random.c:340: choosing enqueued entry (16:57:25) [0x81528e8] [rb_random_play_order_get_next] rb-play-order-random.c:340: choosing enqueued entry (16:57:25) [0x81528e8] [rb_random_play_order_get_previous] rb-play-order-random.c:386: choosing history entry (16:57:25) [0x81528e8] [rb_shell_player_open_location] rb-shell-player.c:984: Opening file:///local/palfrey/stuff/music/Tom Lehrer/That Was the Year That Was/Tom Lehrer - Wernher Von Braun.mp3... (16:57:25) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:586: syncing pipeline (16:57:25) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:597: PAUSING pipeline (16:57:25) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:586: syncing pipeline (16:57:25) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:588: PLAYING pipeline (16:57:25) [0x81528e8] [rb_shell_player_set_playing_entry] rb-shell-player.c:1133: Success! (16:57:25) [0x81528e8] [rb_tray_icon_notify] rb-tray-icon.c:522: ignoring notification: Tom Lehrer - Wernher Von Braun.mp3 (16:57:25) [0x81528e8] [rb_shell_player_sync_with_source] rb-shell-player.c:2039: playing source: 0x8392090, active entry: 0x3cae4200 (16:57:25) [0x81528e8] [rb_shell_set_window_title] rb-shell.c:2039: setting title to "Unknown - Tom Lehrer - Wernher Von Braun.mp3" (16:57:25) [0x81528e8] [rb_header_sync] rb-header.c:331: syncing with entry = 0x3cae4200 (16:57:25) [0x81528e8] [rb_shell_player_sync_buttons] rb-shell-player.c:2098: syncing with source 0x8392090 (16:57:25) [0x81528e8] [rb_shell_clipboard_sync] rb-shell-clipboard.c:486: syncing clipboard (16:57:25) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:25) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:25) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 0 (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 5 (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 4 (16:57:25) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:26) [0x81528e8] [rb_shell_clipboard_sync] rb-shell-clipboard.c:486: syncing clipboard (16:57:26) [0x81528e8] [rb_shell_player_error] rb-shell-player.c:2458: playback error while playing: not negotiated (16:57:26) [0x81528e8] [error_cb] rb-shell-player.c:2488: exiting error hander (16:57:26) [0x81528e8] [eos_cb] rb-shell-player.c:2377: eos! (16:57:26) [0x81528e8] [rb_random_play_order_get_next] rb-play-order-random.c:340: choosing enqueued entry (16:57:26) [0x81528e8] [rb_random_play_order_get_next] rb-play-order-random.c:340: choosing enqueued entry (16:57:26) [0x81528e8] [rb_random_play_order_get_previous] rb-play-order-random.c:386: choosing history entry (16:57:26) [0x81528e8] [rb_shell_player_open_location] rb-shell-player.c:984: Opening file:///local/palfrey/stuff/music/Tom Lehrer/That Was the Year That Was/Tom Lehrer - New Math.mp3... (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:586: syncing pipeline (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:597: PAUSING pipeline (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:586: syncing pipeline (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:588: PLAYING pipeline (16:57:26) [0x81528e8] [rb_shell_player_set_playing_entry] rb-shell-player.c:1133: Success! (16:57:26) [0x81528e8] [rb_tray_icon_notify] rb-tray-icon.c:522: ignoring notification: Tom Lehrer - New Math.mp3 (16:57:26) [0x81528e8] [rb_shell_player_sync_with_source] rb-shell-player.c:2039: playing source: 0x8392090, active entry: 0x3cae2d78 (16:57:26) [0x81528e8] [rb_shell_set_window_title] rb-shell.c:2039: setting title to "Unknown - Tom Lehrer - New Math.mp3" (16:57:26) [0x81528e8] [rb_header_sync] rb-header.c:331: syncing with entry = 0x3cae2d78 (16:57:26) [0x81528e8] [rb_shell_player_sync_buttons] rb-shell-player.c:2098: syncing with source 0x8392090 (16:57:26) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:26) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:26) [0x81528e8] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 0 (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 5 (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2523: info: 4 (16:57:26) [0x81528e8] [info_available_cb] rb-shell-player.c:2543: Got info_available but entry isn't an iradio station (16:57:26) [0x81528e8] [rb_shell_clipboard_sync] rb-shell-clipboard.c:486: syncing clipboard (16:57:26) [0x81528e8] [main_shell_weak_ref_cb] main.c:416: caught shell finalization (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:859: Finalizing shell (16:57:26) [0x81528e8] [rb_shell_player_stop] rb-shell-player.c:2236: stopping (16:57:26) [0x81528e8] [rb_shell_player_playpause] rb-shell-player.c:1600: doing playpause (16:57:26) [0x81528e8] [rb_shell_player_playpause] rb-shell-player.c:1610: pausing mm player (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:586: syncing pipeline (16:57:26) [0x81528e8] [rb_player_gst_sync_pipeline] ../../player/rb-player-gst.c:597: PAUSING pipeline (16:57:26) [0x81528e8] [rb_shell_player_sync_with_source] rb-shell-player.c:2039: playing source: 0x8392090, active entry: 0x3cae2d78 (16:57:26) [0x81528e8] [rb_header_sync] rb-header.c:331: syncing with entry = 0x3cae2d78 (16:57:26) [0x81528e8] [rb_shell_player_sync_buttons] rb-shell-player.c:2098: syncing with source 0x8392090 (16:57:26) [0x81528e8] [rb_shell_player_sync_buttons] rb-shell-player.c:2098: syncing with source 0x8392090 (16:57:26) [0x81528e8] [rb_tray_icon_finalize] rb-tray-icon.c:233: tray icon 0x8382800 finalizing (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:883: shutting down playlist manager (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:886: unreffing playlist manager (16:57:26) [0x81528e8] [rb_playlist_manager_finalize] rb-playlist-manager.c:272: Finalizing playlist manager (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:889: unreffing removable media manager (16:57:26) [0x81528e8] [rb_proxy_config_dispose] rb-proxy-config.c:125: Removing HTTP proxy config watch (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:894: unreffing clipboard shell (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:897: shutting down DB (16:57:26) [0x81528e8] [rhythmdb_shutdown] rhythmdb.c:545: 1 outstanding threads (16:57:26) [0x8912cf0] [action_thread_main] rhythmdb.c:2087: exiting main thread (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:900: unreffing DB (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:903: destroying prefs (16:57:26) [0x81528e8] [rb_shell_finalize] rb-shell.c:907: destroying tooltips Steps to reproduce: Actual results: Expected results: Does this happen every time? Other information:
Does this really happen for any file with no tags? If so, that's extremely weird, and I can't reproduce it. Is the debug info above from the file that caused the problem, or one of the subsequent files that only played for 1s? It looks like we're getting a fairly vague gstreamer error ("not negotiated") and then nothing works ever again. What gstreamer version are you using? Can you try running 'GST_DEBUG_NO_COLOR=1 GST_DEBUG=*:4 rhythmbox -D player 2>&1 | tee 342789.log', playing a short playlist including a file that causes this problem, and attaching the full log file?
You can find a trace file for this here: https://launchpad.net/distros/ubuntu/+source/rhythmbox/+bug/49714 (its >1Mb so bugzilla wont let me upload) (Untars to 16Mb) RhythmBox 0.9.3.1 Generated with: GST_DEBUG_NO_COLOR=1 GST_DEBUG=*:4 rhythmbox -D player 2>&1 | tee 342789.log I played the first track in the list, got bored with it (it was James Blunt) so skipped to the next track, at which point it skipped through the list as previously reported. To help navigate the file, a quick grep -n gives the following for when the different files were played (or not as the case maybe): 2652:DEBUG (0x81238a0 - 0:00:13.139097000) playbasebin(22752) gstplaybasebin.c(1762):gst_play_base_bin_set_property: setting new uri to file:///home/nol/audio/music/james_blunt/back_to_bedlam/01_high.mp3 79280:DEBUG (0x81238a0 - 0:00:27.299022000) playbasebin(22752) gstplaybasebin.c(1762):gst_play_base_bin_set_property: setting new uri to file:///home/nol/audio/music/james_blunt/back_to_bedlam/02_youre_beautiful.mp3 84352:DEBUG (0x81238a0 - 0:00:28.163181000) playbasebin(22752) gstplaybasebin.c(1762):gst_play_base_bin_set_property: setting new uri to file:///home/nol/audio/music/james_blunt/back_to_bedlam/03_wisemen.mp3 89391:DEBUG (0x81238a0 - 0:00:29.238013000) playbasebin(22752) gstplaybasebin.c(1762):gst_play_base_bin_set_property: setting new uri to file:///home/nol/audio/music/james_blunt/back_to_bedlam/04_goodbye_my_lover.mp3 94555:DEBUG (0x81238a0 - 0:00:30.410072000) playbasebin(22752) gstplaybasebin.c(1762):gst_play_base_bin_set_property: setting new uri to file:///home/nol/audio/music/james_blunt/back_to_bedlam/05_tears_and_rain.mp3 All of the files have id3 tags setup properly, for eg: nol@germany:~/audio/music/james_blunt/back_to_bedlam$ id3v2 -l 01_high.mp3 id3v1 tag info for 01_high.mp3: Title : High Artist: James Blunt Album : Back To Bedlam Year: 2004, Genre: Other (12) Comment: Created by Grip Track: 1 id3v2 tag info for 01_high.mp3: TIT2 (Title/songname/content description): High TPE1 (Lead performer(s)/Soloist(s)): James Blunt TALB (Album/Movie/Show title): Back To Bedlam TYER (Year): 2004 COMM (Comments): ()[]: Created by Grip TCON (Content type): Other (12) TRCK (Track number/Position in set): 1
Thanks for following up on this. I can reproduce the problem by setting my audio sink to 'audio/x-raw-int,rate=22050 ! alsasink' (or anything that requires rate conversion). It works when playbin's audioresample element is in passthrough mode. It seems to be a problem in how audioresample negotiates downstream caps. In my tests, it tries to set rate=44100, which fails, and then it apparently gives up, leaving the volume element with no negotiated caps.
I can reproduce this, don't know what causes it yet though. Looking at the log I think audioresample sometimes has issues when being reused, it doesn't seem to clean-up properly. The log implies the errors happen when audioresample pushes stuff from the sink event function where it handles the NEWSEGMENT event, that would seem to imply it doesn't clean some internal buffer. In fact audioresample doesn't even seem to implement GstBaseTransform::start and/or GstBaseTransform::stop at all.
Created attachment 67483 [details] [review] proposed fix This makes it work again for me.
2006-06-16 Tim-Philipp Müller <tim at centricular dot net> * tests/check/elements/audioresample.c: (test_reuse), (audioresample_suite): Add test case for bug #342789 fixed below. 2006-06-16 Tim-Philipp Müller <tim at centricular dot net> * gst/audioresample/gstaudioresample.c: (gst_audioresample_class_init), (gst_audioresample_init), (audioresample_start), (audioresample_stop), (gst_audioresample_set_property), (gst_audioresample_get_property): Implement GstBaseTransform::start and ::stop so that audioresample can clear its internal state properly and be reused insted of causing non-negotiated errors with playbin under some circumstances (#342789). * tests/check/elements/audioresample.c: (setup_audioresample), (cleanup_audioresample): Need to set element state here so that ::start and ::stop are called.
*** Bug 345900 has been marked as a duplicate of this bug. ***
*** Bug 348890 has been marked as a duplicate of this bug. ***
*** Bug 347966 has been marked as a duplicate of this bug. ***
*** Bug 347283 has been marked as a duplicate of this bug. ***