Calculating album replaygain with gstreamer causes error

[pprkut]

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...

beet replaygain -a "Streets of Gold"

yields

replaygain: analyzing 3OH!3 - Streets of Gold
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'

Yet

beet replaygain "Streets of Gold"

works just fine:

replaygain: analyzing 3OH!3 - Streets of Gold - Beaumont
replaygain: analyzing 3OH!3 - Streets of Gold - I Can Do Anything
replaygain: analyzing 3OH!3 - Streets of Gold - Déjà Vu
replaygain: analyzing 3OH!3 - Streets of Gold - We Are Young
replaygain: analyzing 3OH!3 - Streets of Gold - Touchin on My
replaygain: analyzing 3OH!3 - Streets of Gold - House Party
replaygain: analyzing 3OH!3 - Streets of Gold - R.I.P.
replaygain: analyzing 3OH!3 - Streets of Gold - I Know How to Say
replaygain: analyzing 3OH!3 - Streets of Gold - Double Vision
replaygain: analyzing 3OH!3 - Streets of Gold - I'm Not the One
replaygain: analyzing 3OH!3 - Streets of Gold - Streets of Gold
replaygain: analyzing 3OH!3 - Streets of Gold - See You Go
replaygain: analyzing 3OH!3 - Streets of Gold - Love 2012
replaygain: analyzing 3OH!3 - Streets of Gold - Don't Trust Me
replaygain: analyzing 3OH!3 feat. Kesha - Streets of Gold - My First Kiss
replaygain: analyzing 3OH!3 feat. Katy Perry - Streets of Gold - Starstrukk

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

• OS: Slackware Linux
• Python version: 3.6.1
• beets version: beets 1.4.6 (e742f86)

My configuration (output of beet config) is:

lyrics:
    bing_lang_from: []
    auto: yes
    bing_client_secret: REDACTED
    bing_lang_to:
    google_API_key: REDACTED
    google_engine_ID: REDACTED
    genius_api_key: REDACTED
    fallback:
    force: no
    sources: [google, lyricwiki, musixmatch]
directory: /mnt/media/Music
library: ~/data/beets.blb

import:
    move: yes
    write: no
    languages: en
    timid: yes
threaded: yes
per_disc_numbering: yes

plugins: mbsync lyrics info inline missing metasync replaygain
item_fields:
    format_name: u'Vorbis' if format == u'OGG' else format[0].upper() + format[1:].lower()
    full_album: album + (u'' if albumdisambig == u'' else u' (' + albumdisambig + ')')
    disc_folder: (u'Disc ' + str(disc).zfill(2)) if disctotal > 1 else u''

paths:
    default: $format_name/$albumartist - $full_album%aunique{albumartist album albumdisambig,albumtype year country label catalognum}/%if{$disc_folder, $disc_folder/}$track - $artist - $title
    singleton: $format_name/$albumartist - $full_album%aunique{albumartist album albumdisambig,albumtype year country label catalognum}/%if{$disc_folder, $disc_folder/}$track - $artist - $title
    comp: $format_name/$full_album%aunique{albumartist album albumdisambig,albumtype year country label catalognum}/%if{$disc_folder, $disc_folder/}$track - $artist - $title
metasync:
    source: amarok
replaygain:
    backend: gstreamer
    overwrite: yes
    auto: yes
    targetlevel: 89
    r128: [Opus]
pathfields: {}
album_fields: {}
missing:
    count: no
    total: no
    album: no

[sampsyo]

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?

[pprkut]

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.

[pprkut]

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.

[pprkut]

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

[sampsyo]

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.