GNOME Bugzilla – Bug 350276
can't seek in mt-daapd-transcoded wav-stream
Last modified: 2018-05-24 11:44:40 UTC
Please describe the problem: Am using 9.5 on Ubuntu Dapper. Have mt-daapd (svn-1333) on Debian, which transcodes .ogg files to a .wav stream on-the-fly, and serves them as such (since some clients don't read ogg) This works fine with my roku soundbridge, but rhythmbox doesn't even start to play the file, but jumps directly to the next one in the playlist. Playing ogg (or mp3) files from mt-daapd without any transcoding works fine. Steps to reproduce: 1. Have mt-daapd on a seperate machine, and serve a transcoded file 2. Let Rhythmbox find the daap-share 3. Double-click a song (must be in a format mt-daapd is configured to transcode) Actual results: I get the ugly red sign, and rhythmbox jumps to the next song. (see debugging-log below) Expected results: Rhythmbox should play my song. Does this happen every time? Yes! Other information: When running rhythmbox -d, and playing a transcoded file of the mt-daapd server, I get the following: (14:12:49) [0x8147908] [rhythmdb_process_events] rhythmdb.c:1718: processing RHYTHMDB_EVENT_THREAD_EXITED (14:13:36) [0x8147908] [rb_tray_icon_button_press_event_cb] rb-tray-icon.c:374: tray button press (14:13:37) [0x8147908] [rb_shell_player_cmd_play] rb-shell-player.c:1592: play! (14:13:37) [0x8147908] [rb_shell_player_playpause] rb-shell-player.c:1607: doing playpause (14:13:37) [0x8147908] [rb_shell_player_playpause] rb-shell-player.c:1633: no playing source, using selected source (14:13:37) [0x8147908] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2171: setting playing source to 0x87d8820 (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: 0x87d8820, active entry: (nil) (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2021: clearing title (14:13:37) [0x8147908] [rb_shell_player_get_playing_song_duration] rb-shell-player.c:2361: [color=red]Did not get playing entry : return -1 as length[/color] (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = (nil) (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:360: not playing (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_playing_source_changed_cb] rb-shell.c:1820: playing source changed (14:13:37) [0x8147908] [rb_shell_player_playpause] rb-shell-player.c:1669: getting entry from play order (14:13:37) [0x8147908] [rb_shell_player_open_location] rb-shell-player.c:984: Opening daap://192.168.1.3:3689/databases/1/items/3632.wav?session-id=2... (14:13:37) [0x8147908] [rb_player_gst_sync_pipeline] rb-player-gst.c:586: syncing pipeline (14:13:37) [0x8147908] [rb_player_gst_sync_pipeline] rb-player-gst.c:597: PAUSING pipeline (14:13:37) [0x8147908] [rb_daap_src_open] rb-daap-src.c:665: Connecting to DAAP source: daap://192.168.1.3:3689/databases/1/items/3632.wav?session-id=2 (14:13:37) [0x8147908] [rb_player_gst_sync_pipeline] rb-player-gst.c:586: syncing pipeline (14:13:37) [0x8147908] [rb_player_gst_sync_pipeline] rb-player-gst.c:588: PLAYING pipeline (14:13:37) [0x8147908] [rb_shell_player_set_playing_entry] rb-shell-player.c:1133: Success! (14:13:37) [0x8147908] [rb_tray_icon_notify] rb-tray-icon.c:526: doing notify: Fyrsti þáttur af fjórum (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: 0x87d8820, active entry: 0xb6cd9468 (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2044: setting title to "Megas - Fyrsti þáttur af fjórum" (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = 0xb6cd9468 (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: 0x87d8820, active entry: 0xb6cd9468 (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = 0xb6cd9468 (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (14:13:37) [0x8147908] [rb_shell_clipboard_sync] rb-shell-clipboard.c:486: syncing clipboard [color=red](14:13:37) [0x8147908] [rb_shell_player_error] rb-shell-player.c:2468: playback error while playing: Could not determine type of stream.[/color] (14:13:37) [0x8147908] [error_cb] rb-shell-player.c:2506: exiting error hander (14:13:37) [0x8147908] [eos_cb] rb-shell-player.c:2387: eos! (14:13:37) [0x8147908] [rb_shell_player_do_next] rb-shell-player.c:1487: No next entry, stopping playback (14:13:37) [0x8147908] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2171: setting playing source to (nil) (14:13:37) [0x8147908] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2194: source is already playing, stopping it (14:13:37) [0x8147908] [rb_shell_player_stop] rb-shell-player.c:2245: stopping (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: (nil), active entry: (nil) (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2021: clearing title (14:13:37) [0x8147908] [rb_shell_player_get_playing_song_duration] rb-shell-player.c:2361: Did not get playing entry : return -1 as length (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = (nil) (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:360: not playing (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: (nil), active entry: (nil) (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2021: clearing title (14:13:37) [0x8147908] [rb_shell_player_get_playing_song_duration] rb-shell-player.c:2361: Did not get playing entry : return -1 as length (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = (nil) (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:360: not playing (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_playing_source_changed_cb] rb-shell.c:1820: playing source changed (14:13:37) [0x8147908] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2171: setting playing source to (nil) (14:13:37) [0x8147908] [rb_shell_player_stop] rb-shell-player.c:2245: stopping (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: (nil), active entry: (nil) (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2021: clearing title (14:13:37) [0x8147908] [rb_shell_player_get_playing_song_duration] rb-shell-player.c:2361: Did not get playing entry : return -1 as length (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = (nil) (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:360: not playing (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_player_sync_with_source] rb-shell-player.c:2048: playing source: (nil), active entry: (nil) (14:13:37) [0x8147908] [rb_shell_set_window_title] rb-shell.c:2021: clearing title (14:13:37) [0x8147908] [rb_shell_player_get_playing_song_duration] rb-shell-player.c:2361: Did not get playing entry : return -1 as length (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:331: syncing with entry = (nil) (14:13:37) [0x8147908] [rb_header_sync] rb-header.c:360: not playing (14:13:37) [0x8147908] [rb_shell_player_sync_buttons] rb-shell-player.c:2107: syncing with source 0x87d8820 (14:13:37) [0x8147908] [rb_shell_playing_source_changed_cb] rb-shell.c:1820: playing source changed (14:13:37) [0x8147908] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:694: entryview changed (14:13:37) [0x8147908] [rb_shell_clipboard_sync] rb-shell-clipboard.c:486: syncing clipboard (14:13:49) [0x8147908] [rhythmdb_read_enter] rhythmdb.c:680: counter: 1 (14:13:49) [0x8147908] [rhythmdb_read_enter] rhythmdb.c:680: counter: 2 (14:13:49) [0x81a7878] [query_thread_main] rhythmdb.c:2949: entering query thread (14:13:49) [0x81a7878] [rhythmdb_query_internal] rhythmdb.c:2926: doing query (14:13:49) [0x81a7878] [do_query_recurse] rhythmdb-tree.c:1774: doing recursive query, 1 conjunctions (14:13:49) [0x81a7878] [rhythmdb_query_model_add_results] rhythmdb-query-model.c:1697: adding 0 entries (14:13:49) [0x8147908] [idle_process_update] rhythmdb-query-model.c:911: inserting 0 rows (14:13:49) [0x81a7878] [rhythmdb_query_internal] rhythmdb.c:2932: completed (14:13:49) [0x8749210] [query_thread_main] rhythmdb.c:2949: entering query thread (14:13:49) [0x8749210] [rhythmdb_query_internal] rhythmdb.c:2926: doing query (14:13:49) [0x8749210] [do_query_recurse] rhythmdb-tree.c:1774: doing recursive query, 1 conjunctions (14:13:49) [0x8749210] [rhythmdb_query_model_add_results] rhythmdb-query-model.c:1697: adding 5 entries (14:13:49) [0x8147908] [idle_process_update] rhythmdb-query-model.c:911: inserting 5 rows (14:13:49) [0x8749210] [rhythmdb_query_internal] rhythmdb.c:2932: completed (14:13:49) [0x8147908] [rhythmdb_process_events] rhythmdb.c:1725: processing RHYTHMDB_EVENT_QUERY_COMPLETE (14:13:49) [0x8147908] [rhythmdb_read_leave] rhythmdb.c:694: counter: 1 (14:13:49) [0x8147908] [rhythmdb_process_events] rhythmdb.c:1718: processing RHYTHMDB_EVENT_THREAD_EXITED (14:13:49) [0x8147908] [rhythmdb_process_events] rhythmdb.c:1725: processing RHYTHMDB_EVENT_QUERY_COMPLETE (14:13:49) [0x8147908] [rhythmdb_read_leave] rhythmdb.c:694: counter: 0 (14:13:49) [0x8147908] [rhythmdb_process_events] rhythmdb.c:1718: processing RHYTHMDB_EVENT_THREAD_EXITED
... As seen in the debugging info, the problem seems to be that rhythmbox either fails to recognize the type of the stream, or doesn't know it should be able to play this kind of stream.
Could you try running "GST_DEBUG=decodebin:5 GST_DEBUG_NO_COLOR=1 rhythmbox", and attaching the output you get when you try to play one of these streams?
Created attachment 70621 [details] Debug log Ran "GST_DEBUG=decodebin:5 GST_DEBUG_NO_COLOR=1 rhythmbox", and tried to play a stream generated by transcoding an ogg-file. (Playing the same tune using Roku soundbridge works).
This is a problem with GStreamer type-finding the stream, so reassigning there.
That debug log doesn't have any useful information. Perhaps: "GST_DEBUG=*typefind*:5 GST_DEBUG_NO_COLOR=1 rhythmbox would have better info.
Created attachment 70703 [details] Debug log 2 This time I ran GST_DEBUG=*typefind*:5 GST_DEBUG_NO_COLOR=1 rhythmbox and played the same song as before (same results with other .ogg songs though).
That output seems strange - I would expect to see output from various typefinding functions rejecting the data - it's almost as if it's receiving either no data bytes at all, or at best very few. Rhythmbox guys, is there any tool for testing daap retrievals so we can have a look at exactly what's arriving?
Looks like typefind receives an EOS event without getting any data to me as well. Possibly related either to the source element used or the server. Could you create and attach a full log with GST_DEBUG=*:5 GST_DEBUG_NO_COLOR=1 please? (please compress the log with bzip2 or gzip before attaching)
Created attachment 72762 [details] error log Ran GST_DEBUG=*:5 GST_DEBUG_NO_COLOR=1 rhythmbox, and this was the output
This looks like a rbdaapsrc problem. It returns GST_FLOW_UNEXPECTED as flow return (= EOS) in its create function instead of creating a buffer. The rest of the pipeline behaves correctly accordingly. basesrc(18822) gstbasesrc.c(1318):gst_base_src_get_range:<source> unexpected length 0 (offset=0, size=0) basesrc(18822) gstbasesrc.c(1421):gst_base_src_loop:<source> pausing after gst_base_src_get_range() = -3 basesrc(18822) gstbasesrc.c(1492):gst_base_src_loop:<source> pausing task, reason unexpected This is the last log line from rbdaapsrc: [Invalid UTF-8] DEBUG (0x81478e8 - 0:00:32.794533000) daapsrc(18788) rb-daap-src.c(739):rb_daap_src_open:<source> Got HTTP response: HTTP/1.1 200 OK Connection: Close Expires: -1 Cache-Control: no-cache Content-Type: audio/wav DAAP-Server: mt-daapd/svn-1333 Accept-Ranges: bytes Date: Fri, 15 Sep 2006 07:36:56 GMT RIFFTH\x8e&WAVEfmt \x10 Re-assigning to rhythmbox ...
Convincing mt-daapd to do server-side decoding: probably about an hour Fixing the rb-daap-src so it can at least play the wav stream: about 2 minutes. nnnngh. Seeking doesn't work at all, though, so I'm leaving the bug open.
*** Bug 374290 has been marked as a duplicate of this bug. ***
I can confirm that this indeed works in version 0.9.7 (from experimental in Debian), but it leaks memory severely...
GStreamer's wavparse element has a pretty big leak in it at the moment (see bug 407057). While investigating, I also found that we leak the parsed HTTP response headers, so I've fixed that.
well, as a workaround, I just set up two instances of mt-daapd, one especially for rhythmbox that didn't transcode anything on the fly, this lets me at least listen to my music. Just a few minutes ago, I upgraded to ubuntu feisty fawn, which uses rhythmbox 0.10.0, and can confirm that the mentioned issue no longer exists with that version. thanks alot Indriði
-- GitLab Migration Automatic Message -- This bug has been migrated to GNOME's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.gnome.org/GNOME/rhythmbox/issues/221.