Closed pprkut closed 7 years ago
Wow; that is pretty weird. The pattern where this happens for the first album in a season, but no others, indicates that we may be using the GStreamer API incorrectly—or, of course, it might just be a GStreamer bug that is no fault of our own. And yes, your experience with the GStreaemer debug output match my own: it’s extremely difficult to glean anything from those dumps.
Maybe it would be useful to ask the GStreamer developers whether there’s anything obvious that might cause this?
I debugged a bit more. Put what I found here so I don't forget, and maybe someone already sees what's wrong :)
track replaygain calculation:
$ GST_DEBUG="*:3" beet replaygain "Streets of Gold"
replaygain: analyzing 3OH!3 - Streets of Gold - Beaumont
0:00:00.073055320 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:00.076635547 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_4d357fcf> Locking on pts 0:00:00.561632653
replaygain: analyzing 3OH!3 - Streets of Gold - I Can Do Anything
0:00:00.397637734 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:00.398671696 8148 0x1291ca0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_250b52df> Locking on pts 0:00:00.227845804
replaygain: analyzing 3OH!3 - Streets of Gold - Déjà Vu
0:00:01.277041526 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:01.299258292 8148 0x7f0b980028a0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_30175c91> Locking on pts 0:00:00.431020408
replaygain: analyzing 3OH!3 - Streets of Gold - We Are Young
0:00:02.178861473 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:02.191666329 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_71a3c3ab> Locking on pts 0:00:00.422312925
replaygain: analyzing 3OH!3 - Streets of Gold - Touchin on My
0:00:03.103999988 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:03.116223733 8148 0x1291ca0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_489fe3da> Locking on pts 0:00:00.291700680
replaygain: analyzing 3OH!3 - Streets of Gold - House Party
0:00:03.940102489 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:03.953153871 8148 0x7f0b980028a0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_6e8bda6a> Locking on pts 0:00:00.370068027
replaygain: analyzing 3OH!3 - Streets of Gold - R.I.P.
0:00:04.816350532 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:04.828841124 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_214a63e3> Locking on pts 0:00:00.403446712
replaygain: analyzing 3OH!3 - Streets of Gold - I Know How to Say
0:00:05.859268288 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:05.863948698 8148 0x1291ca0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_5194b3b0> Locking on pts 0:00:00.338140589
replaygain: analyzing 3OH!3 - Streets of Gold - Double Vision
0:00:06.736331333 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:06.737028850 8148 0x7f0b980028a0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_5268eee8> Locking on pts 0:00:00.230748299
replaygain: analyzing 3OH!3 - Streets of Gold - I'm Not the One
0:00:07.595986014 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:07.638609260 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_57b47281> Locking on pts 0:00:00.407800453
replaygain: analyzing 3OH!3 - Streets of Gold - Streets of Gold
0:00:08.758974337 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:08.772357930 8148 0x1291ca0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_2a763b8a> Locking on pts 0:00:00.259773242
replaygain: analyzing 3OH!3 - Streets of Gold - See You Go
0:00:09.636434776 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:09.649144677 8148 0x7f0b980028a0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_0a8ff6cb> Locking on pts 0:00:00.436825396
replaygain: analyzing 3OH!3 - Streets of Gold - Love 2012
0:00:10.406368375 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:10.414001781 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_7d031d58> Locking on pts 0:00:00.401995464
replaygain: analyzing 3OH!3 - Streets of Gold - Don't Trust Me
0:00:11.579824598 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:11.593140637 8148 0x1291ca0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_4002d0c9> Locking on pts 0:00:00.352653061
replaygain: analyzing 3OH!3 feat. Kesha - Streets of Gold - My First Kiss
0:00:12.504251218 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:12.515322381 8148 0x7f0b980028a0 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_0be981d2> Locking on pts 0:00:00.268480725
replaygain: analyzing 3OH!3 feat. Katy Perry - Streets of Gold - Starstrukk
0:00:13.413872398 8148 0xfd7e00 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:13.449435403 8148 0x7f0b9c061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_7397eed0> Locking on pts 0:00:00.288798185
album replaygain calculation:
$ GST_DEBUG="*:3" beet replaygain -a "Streets of Gold"
replaygain: analyzing 3OH!3 - Streets of Gold
0:00:00.078810551 8162 0x22ad000 WARN basesrc gstbasesrc.c:3480:gst_base_src_start_complete:<src> pad not activated yet
0:00:00.082716887 8162 0x7fba00061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_4d357fcf> Locking on pts 0:00:00.561632653
0:00:00.413721849 8162 0x7fba00061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_250b52df> Locking on pts 0:00:00.227845804
0:00:00.416838434 8162 0x7fb9f80028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<rg:src> could not send sticky events
0:00:00.416880367 8162 0x7fb9f80028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<rg:src> could not send sticky events
0:00:00.417025992 8162 0x7fba00061370 WARN oggdemux gstoggdemux.c:1303:gst_ogg_pad_stream_out:<oggdemux1> could not submit packet for stream 250b52df, error: -5
0:00:00.417048879 8162 0x7fba00061370 WARN oggdemux gstoggdemux.c:4883:gst_ogg_demux_loop:<oggdemux1> error: Internal data stream error.
0:00:00.417057657 8162 0x7fba00061370 WARN oggdemux gstoggdemux.c:4883:gst_ogg_demux_loop:<oggdemux1> error: streaming stopped, reason error (-5)
0:00:00.418069422 8162 0x22ad000 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<oggdemux1:src_250b52df> Locking on pts 0:00:00.227845804
replaygain: ReplayGain error: Error GLib.Error('Internal data stream error.', 'gst-stream-error-quark', 1) - 'gstoggdemux.c(4883): gst_ogg_demux_loop (): /GstPipeline:pipeline0/GstDecodeBin:decbin/GstOggDemux:oggdemux1:\nstreaming stopped, reason error (-5)' on file '/mnt/media/Music/Vorbis/3OH!3 - Streets of Gold/02 - 3OH!3 - I Can Do Anything.ogg'
What's happening is that oggdemux1 can't continue sending audio data because the pipeline is blocked. That in turn is caused by the "could not send sticky events" error before. My guess is that there is some multi-threading issue here. Track replaygain calculation does one file after another, while album replaygain calculation seems to do at least 2 at once. If I read the messages correctly, they are blocking each other, or some such.
The "could not send sticky events" error might be a red herring. Not sure. I added tracing to see what functions get called to close in on where the problem might be happening, and naturally with tracing output the processing succeeds. So most likely some kind of race condition. This is not getting easier to debug :(
Edit: Nevermind. Accidentally installed with python2 instead of python3. So unrelated to the added tracing, but rather caused by different python versions.
Ok, so according to the tracing I added, the error happens in _set_file
or _set_next_file
within _on_eos
.
The associated tracing output with python3 I have is
------------> call function _on_eos
--------------> call function _set_next_file
----------------> call function __getattr__
<---------------- exit function __getattr__
----------------> call function _set_file
------------------> call function _on_pad_removed
<------------------ exit function _on_pad_removed
------------------> call function __getattr__
--------------------> call function __getitem__
----------------------> call function _getters
------------------------> call function item_field_getters
--------------------------> call function find_plugins
----------------------------> call function load_plugins
<---------------------------- exit function load_plugins
<-------------------------- exit function find_plugins
<------------------------ exit function item_field_getters
<---------------------- exit function _getters
----------------------> call function _type
<---------------------- exit function _type
----------------------> call function null
<---------------------- exit function null
<-------------------- exit function __getitem__
<------------------ exit function __getattr__
------------------> call function syspath
<------------------ exit function syspath
------------------> call function py3_path
--------------------> call function fsdecode
<-------------------- exit function fsdecode
<------------------ exit function py3_path
0:00:01.008148752 15956 0x7fcb000028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<src:src> could not send sticky events
0:00:01.009005109 15956 0x7fcafc061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_250b52df> Locking on pts 0:00:00.227845804
<---------------- exit function _set_file
----------------> call function __getattr__
0:00:01.011702073 15956 0x7fcb000028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<rg:src> could not send sticky events
0:00:01.011733003 15956 0x7fcb000028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<rg:src> could not send sticky events
0:00:01.011840474 15956 0x7fcafc061370 WARN oggdemux gstoggdemux.c:1303:gst_ogg_pad_stream_out:<oggdemux1> could not submit packet for stream 250b52df, error: -5
0:00:01.011859469 15956 0x7fcafc061370 WARN oggdemux gstoggdemux.c:4883:gst_ogg_demux_loop:<oggdemux1> error: Internal data stream error.
0:00:01.011866947 15956 0x7fcafc061370 WARN oggdemux gstoggdemux.c:4883:gst_ogg_demux_loop:<oggdemux1> error: streaming stopped, reason error (-5)
<---------------- exit function __getattr__
----------------> call function __getattr__
<---------------- exit function __getattr__
0:00:01.013097499 15956 0x14de600 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<oggdemux1:src_250b52df> Locking on pts 0:00:00.227845804
<-------------- exit function _set_next_file
<------------ exit function _on_eos
------------> call function _on_error
and with python2 it's
------------> call function _on_eos
--------------> call function _set_next_file
----------------> call function __getattr__
<---------------- exit function __getattr__
----------------> call function _set_file
------------------> call function _on_pad_removed
<------------------ exit function _on_pad_removed
------------------> call function __getattr__
--------------------> call function __getitem__
----------------------> call function _getters
------------------------> call function item_field_getters
--------------------------> call function find_plugins
----------------------------> call function load_plugins
<---------------------------- exit function load_plugins
<-------------------------- exit function find_plugins
<------------------------ exit function item_field_getters
<---------------------- exit function _getters
----------------------> call function _type
<---------------------- exit function _type
----------------------> call function null
<---------------------- exit function null
<-------------------- exit function __getitem__
<------------------ exit function __getattr__
------------------> call function syspath
<------------------ exit function syspath
------------------> call function py3_path
<------------------ exit function py3_path
0:00:00.874941685 16314 0x7f6a440028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<src:src> could not send sticky events
0:00:00.875844650 16314 0x7f6a48061370 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<'':src_250b52df> Locking on pts 0:00:00.227845804
<---------------- exit function _set_file
----------------> call function __getattr__
<---------------- exit function __getattr__
----------------> call function __getattr__
<---------------- exit function __getattr__
0:00:00.879249490 16314 0x7f6a440028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<vorbisdec1:src> could not send sticky events
0:00:00.879310272 16314 0x7f6a440028a0 WARN GST_PADS gstpad.c:4109:gst_pad_peer_query:<vorbisdec1:src> could not send sticky events
0:00:00.879556973 16314 0x2b56c00 WARN oggdemux gstoggdemux.c:3330:gst_ogg_demux_do_seek:<oggdemux1:src_250b52df> Locking on pts 0:00:00.227845804
<-------------- exit function _set_next_file
<------------ exit function _on_eos
------------> call function _on_tag
Huh! As a GStreamer non-expert, I still don't exactly see what's wrong, but this does really help narrow things down.
As far as I can tell, the GStreamerBackend (which I did not write) seems to try to process one track at a time. The _on_eos
callback gets invoked when one file finishes "playing" through the analysis. It then calls _set_next_file
to consume the next track in the queue. It does this, apparently, by pausing the stream and then loading up a new file before playing again.
As far as I can tell, the error happens when the first track finishes and _set_next_track
tries to cue things up for a second track. Is that right? If so, we should carefully look at each of the arcane API calls in _set_file
, which collectively do the dance to switch from one file to the next.
Problem
I tried calculating replaygain values for all albums in my collection and encountered a very weird problem. I tried figuring out myself what's going on, but I'm pretty much stumped. Maybe someone else can point me in a good direction...
yields
Yet
works just fine:
My first thought was corrupted files (I just recently copied them over from a dying ssd). However, nothing seems to indicate the files themselves are corrupt, with the prime example being track replaygain calculation working just fine. I played the file it errors out on and that too worked fine, so did a quick check with
ogginfo
. But it gets even weirder.I noticed that the above error (or similar) happens with pretty much every album I have. However, if I calculate the album replaygain value of multiple albums at once, it will only hit a fraction, but always the first one in the list. So in my example, if "Streets of Gold" is the second album in the processing list, it succeeds.
I have absolutely no idea what could be causing this and gstreamer's debugging output isn't really helping (it's like searching for a needle in a haystack. The debugging output for the above
replaygain -a
command is above 3GB)Setup
My configuration (output of
beet config
) is: