There's some more information after enabling debug on GStreamer

(00:37:50) [0x2075060] [rb_audioscrobbler_should_handshake] rb-audioscrobbler.c:839: No username set
(00:37:50) [0x2075060] [rb_audioscrobbler_should_handshake] rb-audioscrobbler.c:839: No username set
(00:37:50) [0x2075060] [rb_uri_could_be_podcast] rb-file-helpers.c:617: 'file:///home/marlinc/Music/file.mp3' can't be a Podcast or OPML file, not the right scheme
(00:37:50) [0x2075060] [load_uri_finish] rb-shell.c:2902: found an entry to play
(00:37:50) [0x2075060] [rb_shell_player_stop] rb-shell-player.c:2119: stopping
(00:37:50) [0x2075060] [start_state_change] rb-player-gst.c:406: changing state to NULL
0:00:46.401768688 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2501:gst_element_set_state_func:<playbin0> set_state to NULL
0:00:46.401783562 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2539:gst_element_set_state_func:<playbin0> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS
0:00:46.401792438 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2573:gst_element_set_state_func:<playbin0> final: setting state from NULL to NULL
0:00:46.401803101 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2664:gst_bin_change_state_func:<playbin0> changing state of children from NULL to NULL
0:00:46.401810243 18590      0x2075060 DEBUG                    bin gstbin.c:2712:gst_bin_change_state_func:<playbin0> clearing all cached messages
0:00:46.401817445 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playbin0> 0x364d330 ref 1->2
0:00:46.401825241 18590      0x2075060 DEBUG                    bin gstbin.c:2195:gst_bin_sort_iterator_resync:<playbin0> resync
0:00:46.401831097 18590      0x2075060 DEBUG                    bin gstbin.c:1981:add_to_queue:<playbin0> adding 'playsink' to queue
0:00:46.401836918 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playsink> 0x3664210 ref 1->2
0:00:46.401843702 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playbin0> element playsink not linked on any sinkpads
0:00:46.401851830 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playsink> 0x3664210 unref 3->2
0:00:46.401858638 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playbin0> queue head gives playsink
0:00:46.401864263 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playbin0> element playsink not linked on any sinkpads
0:00:46.401869972 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<playsink> current NULL pending VOID_PENDING, desired next NULL
0:00:46.401876988 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playbin0> no message found matching types 00100000
0:00:46.401883424 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playbin0>   async-start
0:00:46.401889333 18590      0x2075060 DEBUG                    bin gstbin.c:2411:gst_bin_element_set_state:<playbin0> setting element playsink to NULL, base_time 0:00:00.000000000
0:00:46.401897176 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2501:gst_element_set_state_func:<playsink> set_state to NULL
0:00:46.401902832 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2539:gst_element_set_state_func:<playsink> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS
0:00:46.401909709 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2573:gst_element_set_state_func:<playsink> final: setting state from NULL to NULL
0:00:46.401916970 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2664:gst_bin_change_state_func:<playsink> changing state of children from NULL to NULL
0:00:46.401923417 18590      0x2075060 DEBUG                    bin gstbin.c:2712:gst_bin_change_state_func:<playsink> clearing all cached messages
0:00:46.401929114 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playsink> 0x3664210 ref 2->3
0:00:46.401935718 18590      0x2075060 DEBUG                    bin gstbin.c:2195:gst_bin_sort_iterator_resync:<playsink> resync
0:00:46.401941517 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playsink> no message found matching types 00001000
0:00:46.401947112 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playsink>   structure-change
0:00:46.401952611 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element audiotee not linked on any sinkpads
0:00:46.401958212 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element streamsynchronizer0 not linked on any sinkpads
0:00:46.401964327 18590      0x2075060 DEBUG                    bin gstbin.c:2167:gst_bin_sort_iterator_next:<playsink> queue empty, next best: audiotee
0:00:46.401970285 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playsink> queue head gives audiotee
0:00:46.401977376 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playsink> no message found matching types 00001000
0:00:46.401985436 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playsink>   structure-change
0:00:46.401993068 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element audiotee not linked on any sinkpads
0:00:46.402002422 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<audiotee> current NULL pending VOID_PENDING, desired next NULL
0:00:46.402012989 18590      0x2075060 INFO              GST_STATES gstbin.c:2433:gst_bin_element_set_state:<audiotee> skipping transition from NULL to  NULL
0:00:46.402022789 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'audiotee' changed state to 1(NULL) successfully
0:00:46.402035304 18590      0x2075060 DEBUG                    bin gstbin.c:2167:gst_bin_sort_iterator_next:<playsink> queue empty, next best: streamsynchronizer0
0:00:46.402045994 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playsink> queue head gives streamsynchronizer0
0:00:46.402055104 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element streamsynchronizer0 not linked on any sinkpads
0:00:46.402065480 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<streamsynchronizer0> current NULL pending VOID_PENDING, desired next NULL
0:00:46.402076665 18590      0x2075060 INFO              GST_STATES gstbin.c:2433:gst_bin_element_set_state:<streamsynchronizer0> skipping transition from NULL to  NULL
0:00:46.402087300 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'streamsynchronizer0' changed state to 1(NULL) successfully
0:00:46.402099705 18590      0x2075060 DEBUG                    bin gstbin.c:2171:gst_bin_sort_iterator_next:<playsink> queue empty, elements exhausted
0:00:46.402108196 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2823:gst_bin_change_state_func:<playsink> iterator done
0:00:46.402117256 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2890:gst_element_change_state_func:<playsink> element is already in the NULL state
0:00:46.402128289 18590      0x2075060 DEBUG                    bin gstbin.c:2213:gst_bin_sort_iterator_free:<playsink> free
0:00:46.402136696 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playsink> 0x3664210 unref 3->2
0:00:46.402143835 18590      0x2075060 DEBUG                    bin gstbin.c:2858:gst_bin_change_state_func:<playsink> no async elements
0:00:46.402148588 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2892:gst_bin_change_state_func:<playsink> done changing bin's state from NULL to NULL, now in NULL, ret SUCCESS
0:00:46.402158952 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2662:gst_element_change_state:<playsink> element changed state SUCCESS
0:00:46.402168210 18590      0x2075060 INFO              GST_STATES gstelement.c:2350:gst_element_continue_state:<playsink> completed state change to NULL
0:00:46.402178257 18590      0x2075060 LOG               GST_STATES gstelement.c:2678:gst_element_change_state:<playsink> exit state change 1
0:00:46.402187598 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2585:gst_element_set_state_func:<playsink> returned SUCCESS
0:00:46.402197313 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playbin0> child 'playsink' changed state to 1(NULL) successfully
0:00:46.402207815 18590      0x2075060 DEBUG                    bin gstbin.c:2171:gst_bin_sort_iterator_next:<playbin0> queue empty, elements exhausted
0:00:46.402213226 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2823:gst_bin_change_state_func:<playbin0> iterator done
0:00:46.402218277 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2890:gst_element_change_state_func:<playbin0> element is already in the NULL state
0:00:46.402224028 18590      0x2075060 DEBUG                    bin gstbin.c:2213:gst_bin_sort_iterator_free:<playbin0> free
0:00:46.402228871 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playbin0> 0x364d330 unref 2->1
0:00:46.402235181 18590      0x2075060 DEBUG                    bin gstbin.c:2858:gst_bin_change_state_func:<playbin0> no async elements
0:00:46.402239728 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2892:gst_bin_change_state_func:<playbin0> done changing bin's state from NULL to NULL, now in NULL, ret SUCCESS
0:00:46.402246659 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2662:gst_element_change_state:<playbin0> element changed state SUCCESS
0:00:46.402251694 18590      0x2075060 INFO              GST_STATES gstelement.c:2350:gst_element_continue_state:<playbin0> completed state change to NULL
0:00:46.402257510 18590      0x2075060 LOG               GST_STATES gstelement.c:2678:gst_element_change_state:<playbin0> exit state change 1
0:00:46.402262881 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2585:gst_element_set_state_func:<playbin0> returned SUCCESS
(00:37:50) [0x2075060] [start_state_change] rb-player-gst.c:410: state change succeeded synchronously
(00:37:50) [0x2075060] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2055: setting playing source to (nil)
(00:37:50) [0x2075060] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2078: source is already playing, stopping it
(00:37:50) [0x2075060] [player_has_prev_changed_cb] rb-mpris-plugin.c:1326: emitting CanGoPrevious change
(00:37:50) [0x2075060] [player_has_next_changed_cb] rb-mpris-plugin.c:1314: emitting CanGoNext change
(00:37:50) [0x2075060] [rb_shell_player_sync_with_source] rb-shell-player.c:1882: playing source: (nil), active entry: (nil)
0:00:46.402888176 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x7f835c002660
0:00:46.402896894 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x3645d40 position
0:00:46.402901771 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.402909264 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x3645d40 (type position) to sink children
0:00:46.402915537 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.402920758 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.402925208 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x3645d40 (type position) to sink children
0:00:46.402930001 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.402935166 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.402940636 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x3645d40 result 0
0:00:46.402945584 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x3645d40 result 0
0:00:46.402949475 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x3645d40 unref 1->0
0:00:46.402954726 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x7f835c002660
(00:37:50) [0x2075060] [rb_shell_set_window_title] rb-shell.c:2403: clearing title
(00:37:50) [0x2075060] [rb_shell_player_sync_buttons] rb-shell-player.c:1974: syncing with source 0x265a270
(00:37:50) [0x2075060] [rb_shell_playing_source_changed_cb] rb-shell.c:2250: playing source changed
(00:37:50) [0x2075060] [playing_source_changed_cb] rb-mpris-plugin.c:1302: emitting CanPause change
(00:37:50) [0x2075060] [playing_source_changed_cb] rb-mpris-plugin.c:1305: emitting ActivePlaylist change
(00:37:50) [0x2075060] [rb_shell_player_sync_with_source] rb-shell-player.c:1882: playing source: (nil), active entry: (nil)
0:00:46.403096366 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x23b6520
0:00:46.403103489 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x7f83240016d0 position
0:00:46.403108590 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.403115653 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x7f83240016d0 (type position) to sink children
0:00:46.403121893 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.403127645 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.403132873 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x7f83240016d0 (type position) to sink children
0:00:46.403138521 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.403143987 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.403150042 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x7f83240016d0 result 0
0:00:46.403156115 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x7f83240016d0 result 0
0:00:46.403160786 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x7f83240016d0 unref 1->0
0:00:46.403166671 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x23b6520
(00:37:50) [0x2075060] [rb_shell_set_window_title] rb-shell.c:2403: clearing title
(00:37:50) [0x2075060] [rb_audioscrobbler_song_changed_cb] rb-audioscrobbler.c:1065: called with no playing entry
(00:37:50) [0x2075060] [rb_audioscrobbler_song_changed_cb] rb-audioscrobbler.c:1065: called with no playing entry
(00:37:50) [0x2075060] [playing_entry_changed_cb] rb-mpris-plugin.c:1226: emitting Metadata and CanSeek changed
0:00:46.403234800 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x20b6f20
0:00:46.403241584 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x3746ca0 seeking
0:00:46.403246702 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.403253006 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x3746ca0 (type seeking) to sink children
0:00:46.403258957 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.403264581 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.403269913 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x3746ca0 (type seeking) to sink children
0:00:46.403275208 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.403280555 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.403286402 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x3746ca0 result 0
0:00:46.403292149 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x3746ca0 result 0
0:00:46.403296854 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x3746ca0 unref 1->0
0:00:46.403302454 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x20b6f20
0:00:46.403306811 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x234e780
0:00:46.403311531 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x20c3e30 duration
0:00:46.403316005 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.403321036 18590      0x2075060 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again
0:00:46.403326212 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x20c3e30 (type duration) to sink children
0:00:46.403331720 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.403337160 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.403341672 18590      0x2075060 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again
0:00:46.403346319 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x20c3e30 (type duration) to sink children
0:00:46.403351930 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.403357142 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.403362791 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x20c3e30 result 0
0:00:46.403368173 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x20c3e30 result 0
0:00:46.403373141 18590      0x2075060 DEBUG                playbin gstplaybin2.c:2758:gst_play_bin_update_cached_duration_from_query:<playbin0> Updating cached duration from query
0:00:46.403378195 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x20c3e30 unref 1->0
0:00:46.403383428 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x234e780
(00:37:50) [0x2075060] [playing_changed_cb] rb-mpris-plugin.c:1206: emitting PlaybackStatus change
(00:37:50) [0x2075060] [rb_shell_player_sync_buttons] rb-shell-player.c:1974: syncing with source 0x265a270
(00:37:50) [0x2075060] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:2055: setting playing source to 0x265a270
(00:37:50) [0x2075060] [player_has_prev_changed_cb] rb-mpris-plugin.c:1326: emitting CanGoPrevious change
(00:37:50) [0x2075060] [player_has_next_changed_cb] rb-mpris-plugin.c:1314: emitting CanGoNext change
(00:37:50) [0x2075060] [rb_shell_player_sync_with_source] rb-shell-player.c:1882: playing source: 0x265a270, active entry: (nil)
0:00:46.403842429 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x234e780
0:00:46.403849071 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x20bbf70 position
0:00:46.403853520 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.403859896 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x20bbf70 (type position) to sink children
0:00:46.403865376 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.403870290 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.403874976 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x20bbf70 (type position) to sink children
0:00:46.403879907 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.403884624 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.403890014 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x20bbf70 result 0
0:00:46.403895079 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x20bbf70 result 0
0:00:46.403899248 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x20bbf70 unref 1->0
0:00:46.403904142 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x234e780
(00:37:50) [0x2075060] [rb_shell_set_window_title] rb-shell.c:2403: clearing title
(00:37:50) [0x2075060] [rb_shell_player_sync_buttons] rb-shell-player.c:1974: syncing with source 0x265a270
(00:37:50) [0x2075060] [rb_shell_playing_source_changed_cb] rb-shell.c:2250: playing source changed
(00:37:50) [0x2075060] [playing_source_changed_cb] rb-mpris-plugin.c:1302: emitting CanPause change
(00:37:50) [0x2075060] [playing_source_changed_cb] rb-mpris-plugin.c:1305: emitting ActivePlaylist change
(00:37:50) [0x2075060] [start_state_change] rb-player-gst.c:406: changing state to NULL
0:00:46.404019975 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2501:gst_element_set_state_func:<playbin0> set_state to NULL
0:00:46.404026518 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2539:gst_element_set_state_func:<playbin0> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS
0:00:46.404032506 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2573:gst_element_set_state_func:<playbin0> final: setting state from NULL to NULL
0:00:46.404038811 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2664:gst_bin_change_state_func:<playbin0> changing state of children from NULL to NULL
0:00:46.404043483 18590      0x2075060 DEBUG                    bin gstbin.c:2712:gst_bin_change_state_func:<playbin0> clearing all cached messages
0:00:46.404048128 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playbin0> 0x364d330 ref 1->2
0:00:46.404053294 18590      0x2075060 DEBUG                    bin gstbin.c:2195:gst_bin_sort_iterator_resync:<playbin0> resync
0:00:46.404057144 18590      0x2075060 DEBUG                    bin gstbin.c:1981:add_to_queue:<playbin0> adding 'playsink' to queue
0:00:46.404061247 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playsink> 0x3664210 ref 1->2
0:00:46.404066290 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playbin0> element playsink not linked on any sinkpads
0:00:46.404071147 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playsink> 0x3664210 unref 3->2
0:00:46.404075802 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playbin0> queue head gives playsink
0:00:46.404079832 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playbin0> element playsink not linked on any sinkpads
0:00:46.404083933 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<playsink> current NULL pending VOID_PENDING, desired next NULL
0:00:46.404089014 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playbin0> no message found matching types 00100000
0:00:46.404093552 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playbin0>   async-start
0:00:46.404097533 18590      0x2075060 DEBUG                    bin gstbin.c:2411:gst_bin_element_set_state:<playbin0> setting element playsink to NULL, base_time 0:00:00.000000000
0:00:46.404103643 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2501:gst_element_set_state_func:<playsink> set_state to NULL
0:00:46.404107957 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2539:gst_element_set_state_func:<playsink> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS
0:00:46.404113347 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2573:gst_element_set_state_func:<playsink> final: setting state from NULL to NULL
0:00:46.404118842 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2664:gst_bin_change_state_func:<playsink> changing state of children from NULL to NULL
0:00:46.404123204 18590      0x2075060 DEBUG                    bin gstbin.c:2712:gst_bin_change_state_func:<playsink> clearing all cached messages
0:00:46.404127025 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:254:gst_object_ref:<playsink> 0x3664210 ref 2->3
0:00:46.404131724 18590      0x2075060 DEBUG                    bin gstbin.c:2195:gst_bin_sort_iterator_resync:<playsink> resync
0:00:46.404135621 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playsink> no message found matching types 00001000
0:00:46.404139814 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playsink>   structure-change
0:00:46.404143828 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element audiotee not linked on any sinkpads
0:00:46.404147827 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element streamsynchronizer0 not linked on any sinkpads
0:00:46.404152370 18590      0x2075060 DEBUG                    bin gstbin.c:2167:gst_bin_sort_iterator_next:<playsink> queue empty, next best: audiotee
0:00:46.404156639 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playsink> queue head gives audiotee
0:00:46.404160421 18590      0x2075060 DEBUG                    bin gstbin.c:882:find_message:<playsink> no message found matching types 00001000
0:00:46.404164301 18590      0x2075060 DEBUG                    bin gstbin.c:889:find_message:<playsink>   structure-change
0:00:46.404167966 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element audiotee not linked on any sinkpads
0:00:46.404172071 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<audiotee> current NULL pending VOID_PENDING, desired next NULL
0:00:46.404176752 18590      0x2075060 INFO              GST_STATES gstbin.c:2433:gst_bin_element_set_state:<audiotee> skipping transition from NULL to  NULL
0:00:46.404181121 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'audiotee' changed state to 1(NULL) successfully
0:00:46.404186193 18590      0x2075060 DEBUG                    bin gstbin.c:2167:gst_bin_sort_iterator_next:<playsink> queue empty, next best: streamsynchronizer0
0:00:46.404190386 18590      0x2075060 DEBUG                    bin gstbin.c:2182:gst_bin_sort_iterator_next:<playsink> queue head gives streamsynchronizer0
0:00:46.404194211 18590      0x2075060 DEBUG                    bin gstbin.c:2121:update_degree:<playsink> element streamsynchronizer0 not linked on any sinkpads
0:00:46.404198513 18590      0x2075060 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<streamsynchronizer0> current NULL pending VOID_PENDING, desired next NULL
0:00:46.404203454 18590      0x2075060 INFO              GST_STATES gstbin.c:2433:gst_bin_element_set_state:<streamsynchronizer0> skipping transition from NULL to  NULL
0:00:46.404207947 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'streamsynchronizer0' changed state to 1(NULL) successfully
0:00:46.404212982 18590      0x2075060 DEBUG                    bin gstbin.c:2171:gst_bin_sort_iterator_next:<playsink> queue empty, elements exhausted
0:00:46.404216679 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2823:gst_bin_change_state_func:<playsink> iterator done
0:00:46.404220652 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2890:gst_element_change_state_func:<playsink> element is already in the NULL state
0:00:46.404225008 18590      0x2075060 DEBUG                    bin gstbin.c:2213:gst_bin_sort_iterator_free:<playsink> free
0:00:46.404228586 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playsink> 0x3664210 unref 3->2
0:00:46.404233387 18590      0x2075060 DEBUG                    bin gstbin.c:2858:gst_bin_change_state_func:<playsink> no async elements
0:00:46.404236806 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2892:gst_bin_change_state_func:<playsink> done changing bin's state from NULL to NULL, now in NULL, ret SUCCESS
0:00:46.404241859 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2662:gst_element_change_state:<playsink> element changed state SUCCESS
0:00:46.404245557 18590      0x2075060 INFO              GST_STATES gstelement.c:2350:gst_element_continue_state:<playsink> completed state change to NULL
0:00:46.404249795 18590      0x2075060 LOG               GST_STATES gstelement.c:2678:gst_element_change_state:<playsink> exit state change 1
0:00:46.404253812 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2585:gst_element_set_state_func:<playsink> returned SUCCESS
0:00:46.404257828 18590      0x2075060 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<playbin0> child 'playsink' changed state to 1(NULL) successfully
0:00:46.404262524 18590      0x2075060 DEBUG                    bin gstbin.c:2171:gst_bin_sort_iterator_next:<playbin0> queue empty, elements exhausted
0:00:46.404266106 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2823:gst_bin_change_state_func:<playbin0> iterator done
0:00:46.404269683 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2890:gst_element_change_state_func:<playbin0> element is already in the NULL state
0:00:46.404273753 18590      0x2075060 DEBUG                    bin gstbin.c:2213:gst_bin_sort_iterator_free:<playbin0> free
0:00:46.404277153 18590      0x2075060 TRACE        GST_REFCOUNTING gstobject.c:280:gst_object_unref:<playbin0> 0x364d330 unref 2->1
0:00:46.404281729 18590      0x2075060 DEBUG                    bin gstbin.c:2858:gst_bin_change_state_func:<playbin0> no async elements
0:00:46.404284996 18590      0x2075060 DEBUG             GST_STATES gstbin.c:2892:gst_bin_change_state_func:<playbin0> done changing bin's state from NULL to NULL, now in NULL, ret SUCCESS
0:00:46.404289923 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2662:gst_element_change_state:<playbin0> element changed state SUCCESS
0:00:46.404293583 18590      0x2075060 INFO              GST_STATES gstelement.c:2350:gst_element_continue_state:<playbin0> completed state change to NULL
0:00:46.404297733 18590      0x2075060 LOG               GST_STATES gstelement.c:2678:gst_element_change_state:<playbin0> exit state change 1
0:00:46.404301713 18590      0x2075060 DEBUG             GST_STATES gstelement.c:2585:gst_element_set_state_func:<playbin0> returned SUCCESS
(00:37:50) [0x2075060] [start_state_change] rb-player-gst.c:410: state change succeeded synchronously
(00:37:50) [0x2075060] [rb_shell_player_sync_with_source] rb-shell-player.c:1882: playing source: 0x265a270, active entry: 0x7f834c02f480
0:00:46.404328427 18590      0x2075060 TRACE              structure gststructure.c:152:gst_structure_new_id_empty_with_size: created structure 0x23b7780
0:00:46.404333935 18590      0x2075060 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x7f8324001630 position
0:00:46.404338564 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playbin0
0:00:46.404344070 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playbin0> Sending query 0x7f8324001630 (type position) to sink children
0:00:46.404349431 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playbin0> child playsink is sink
0:00:46.404354420 18590      0x2075060 DEBUG       GST_ELEMENT_PADS gstelement.c:1676:gst_element_query: send query on element playsink
0:00:46.404358987 18590      0x2075060 DEBUG                    bin gstbin.c:4176:gst_bin_query:<playsink> Sending query 0x7f8324001630 (type position) to sink children
0:00:46.404363964 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child audiotee is not sink
0:00:46.404368704 18590      0x2075060 DEBUG             GST_STATES gstbin.c:1797:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:46.404373945 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playsink> query 0x7f8324001630 result 0
0:00:46.404378932 18590      0x2075060 DEBUG                    bin gstbin.c:4198:gst_bin_query:<playbin0> query 0x7f8324001630 result 0
0:00:46.404382987 18590      0x2075060 TRACE        GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0x7f8324001630 unref 1->0
0:00:46.404387992 18590      0x2075060 TRACE              structure gststructure.c:390:gst_structure_free: free structure 0x23b7780
(00:37:50) [0x2075060] [rb_shell_set_window_title] rb-shell.c:2426: setting title to ""
(00:37:50) [0x2075060] [rb_shell_player_sync_buttons] rb-shell-player.c:1974: syncing with source 0x265a270
(00:37:50) [0x2075060] [playing_changed_cb] rb-mpris-plugin.c:1206: emitting PlaybackStatus change
(00:37:50) [0x2075060] [rb_shell_player_error] rb-shell-player.c:2443: playback error while playing: Problem occurred without error being set. This is a bug in Rhythmbox or GStreamer.
(00:37:50) [0x2075060] [rb_shell_player_handle_eos] rb-shell-player.c:498: called to simulate EOS for playing entry, but nothing is playing
(00:37:51) [0x2075060] [uninhibit] rb-power-manager-plugin.c:113: Was going to uninhibit session manager, but we haven't inhibited it
(00:38:01) [0x1183000] [electromagnetic_shotgun] rb-metadata-dbus-service.c:176: shutting down (45s idle)