Mopidy randomly brings over the previous track title to the next track

[voidmann]

Hi,

After letting Mopidy finish a track and going to the next one, the track title is not properly updated, resulting in the next track having the same title as the previous one. This issue slowly seems to grow worse, and the entire playlist becomes skewed.
For the record; the audio plays fine, the artist is updated fine, the track number is updated fine, and so is the track length and progress.

Steps to reproduce:

1. Fill the playlist with a few tracks,
2. Play one, without skipping or seeking (as it seems to happen when you let a track play out for a while)
3. Let the track finish, and watch as the title is not changed when moving to the next track.
   I'm running Arch Linux, with the following versions of Mopidy and its extensions:

• mopidy 3.0.1-2
• mopidy-local 3.1.0-1
• mopidy-mpd 3.0.0-1
• mopidy-soundcloud 3.0.0-1
  These are all updated to the latest known version on Arch and the AUR.

I've been dealing with this since updating to Mopidy 3 somewhere last year, whereas 2 never had this behavior.
This issue seems similar to #1528 #1528 , however that one talks about Mopidy 2.

The tracks shown below are played from mopidy-local.

In ncmpcpp:
Incorrect track listing https://camo.githubusercontent.com/fa91261107d7af341374ef03a1ab2a774e813e9f/68747470733a2f2f692e696d6775722e636f6d2f5547674830477a2e706e67

And in polybar's MPD extension:
Polybar MPD https://camo.githubusercontent.com/5b6207e174cd0cce829d2164aba91868c451d50b/68747470733a2f2f692e696d6775722e636f6d2f374d5a69367a4a2e706e67

This is the actual track listing:
Correct track listing https://camo.githubusercontent.com/c99c327c9505f563f9f96a92b2b54df2a4f02a28/68747470733a2f2f692e696d6775722e636f6d2f384d53666665422e706e67

With a different album, I tried to capture the logs with mopidy -v during the time it happened.
Log https://camo.githubusercontent.com/76bb6011e2138c5ca800ac2b7d18618e46a8ca75/68747470733a2f2f692e696d6775722e636f6d2f6d5339375a49702e706e67

DEBUG 2020-01-15 14:07:06,594 [79919:MainThread] mopidy.audio.actor
Audio event: tags_changed(tags=['minimum-bitrate', 'bitrate'])
DEBUG 2020-01-15 14:07:06,594 [79919:MainThread] mopidy.listener
Sending tags_changed to AudioListener: {'tags': ['minimum-bitrate', 'bitrate']}
DEBUG 2020-01-15 14:07:06,644 [79919:MpdSession-11] mopidy_mpd.session
Request from [::ffff:127.0.0.1]:34768: noidle
DEBUG 2020-01-15 14:07:06,644 [79919:MpdSession-11] mopidy_mpd.session
Response to [::ffff:127.0.0.1]:34768: OK
DEBUG 2020-01-15 14:07:06,644 [79919:MpdSession-11] mopidy_mpd.session
Request from [::ffff:127.0.0.1]:34768: status
DEBUG 2020-01-15 14:07:06,647 [79919:MpdSession-11] mopidy_mpd.session
Response to [::ffff:127.0.0.1]:34768:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 5
playlistlength: 8
xfade: 0
state: play
song: 2
songid: 12
nextsong: 3
nextsongid: 13
time: 1:270
elapsed: 1.412
bitrate: 0
OK
DEBUG 2020-01-15 14:07:06,648 [79919:MpdSession-11] mopidy_mpd.session
Request from [::ffff:127.0.0.1]:34768: idle
DEBUG 2020-01-15 14:07:06,656 [79919:MainThread] mopidy.audio.gst
Got TAG bus message: tags={'artist': ['Ben Lukas Boysen'], 'title': ['Sleepers Beat Theme'], 'track-number': [3], 'track-count': [8], 'album': ['Spells'], 'datetime': ['2016'], 'album-artist': ['Ben Lukas Boysen'], 'organization': ['Erased Tapes Records'], 'genre': ['Ambient/Modern Classical'], 'isrc': ['ERATP085'], 'image':
There was a lot of noise in the debug output (from images) and it quickly went beyond my terminal's buffer size.
If any additional information is needed, please tell me and I'll do what I can.

Thank you.

[jodal]

This looks related to mopidy/mopidy-mpd#23.

[jodal]

No problem! Both reports came within hours, and we still don't know what component the root cause is in.

[kingosticks]

I'd have said it was maybe something to do with #1751 if it wasn't for the statement saying this issue wasn't present in Mopidy 2.x.

[leaty]

Got the same issue I believe, but I've had this issue for months. Also Arch here, everything updated.

Mopidy retains the previous track title as the current. I.e track finishes - ncmpcpp and polybar extension shows previous track name (simply as "Eminem - In Too Deep"). While mpc shows "Godzilla: Eminem - In Too Deep", where Godzilla is the current song and In Too Deep was the previous. That's kinda freaky, one is a bug but why does mpc show both?

[kingosticks]

This is a combination of things brought to light by #1751 and so it's also present in Mopidy v2.3.0.

The first two tracks in my playlist are (1) 'Set Guitars To Kill' followed by (2) 'A Little Bit Of Solidarity Goes A Long Way'. The below log shows that after the track change from (1) to (2), we get a tag changed event but but we end up sending stream_title_changed using the old track data.

Dummy-21 DEBUG    2020-01-17 23:58:44,257 Got about-to-finish event.
Dummy-21 DEBUG    2020-01-17 23:58:44,257 Running about-to-finish callback.
LocalBackend-8 DEBUG    2020-01-17 23:58:44,259 Backend translated URI from local:track:And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/02-and_so_i_watch_you_from_afar-a_little_bit_of_solidarity_goes_a_long_way.mp3 to file:///home/nick/Music/And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/02-and_so_i_watch_you_from_afar-a_little_bit_of_solidarity_goes_a_long_way.mp3
Dummy-21 DEBUG    2020-01-17 23:58:44,262 Got source-setup signal: element=GstFileSrc
MainThread DEBUG    2020-01-17 23:58:44,574 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [95856], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:44,853 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [79931], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:45,062 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [63700], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:45,342 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [55737], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:45,481 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [47775], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:46,251 Got TAG bus message: tags={'title': ['Set Guitars To Kill'], 'artist': ['And So I Watch You From Afar'], 'album': ['Self Titled'], 'datetime': ['2009-04-13'], 'track-number': [1], 'genre': ['Instrumental Rock'], 'container-format': ['ID3 tag'], 'private-id3v2-frame': [b'TLAN\x00\x00\x00\x04\x00\x00\x00eng', b'TXXX\x00\x00\x00\x14\x00\x00\x00Rip date\x002009-04-14', b'TXXX\x00\x00\x00\n\x00\x00\x00Source\x00CD', b'TXXX\x00\x00\x00\x1c\x00\x00\x00Release type\x00Normal release'], 'track-count': [11], 'encoder': ['LAME 3.97 (-V2 --vbr-new)'], 'publisher': ['Smalltown America'], 'private-data': [b'\x02\x00\xfb1K\x00'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [31850], 'maximum-bitrate': [319725], 'bitrate': [252000]}
MainThread DEBUG    2020-01-17 23:58:47,429 Got STREAM_START bus message
Dummy-20 DEBUG    2020-01-17 23:58:47,430 Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
MainThread DEBUG    2020-01-17 23:58:47,431 Audio event: stream_changed(uri='file:///home/nick/Music/And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/02-and_so_i_watch_you_from_afar-a_little_bit_of_solidarity_goes_a_long_way.mp3')
Dummy-20 DEBUG    2020-01-17 23:58:47,431 Audio event: position_changed(position=0)
MainThread DEBUG    2020-01-17 23:58:47,432 Sending stream_changed to AudioListener: {'uri': 'file:///home/nick/Music/And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/02-and_so_i_watch_you_from_afar-a_little_bit_of_solidarity_goes_a_long_way.mp3'}
Dummy-20 DEBUG    2020-01-17 23:58:47,432 Sending position_changed to AudioListener: {'position': 0}
MainThread DEBUG    2020-01-17 23:58:47,433 Audio event: tags_changed(tags=dict_keys(['title', 'artist', 'album', 'datetime', 'track-number', 'genre', 'container-format', 'private-id3v2-frame', 'track-count', 'encoder', 'publisher', 'private-data', 'has-crc', 'channel-mode', 'audio-codec', 'minimum-bitrate', 'maximum-bitrate', 'bitrate']))
Core-10 DEBUG    2020-01-17 23:58:47,434 Triggering track playback ended event
Core-10 DEBUG    2020-01-17 23:58:47,437 Sending track_playback_ended to CoreListener: {'tl_track': TlTrack(tlid=10, track=Track(album=Album(date='2009-04-13', name='Self Titled', num_tracks=11, uri='local:album:md5:5bdacb653bbd94bd6d1cbc68dc1854da'), artists=[Artist(name='And So I Watch You From Afar', uri='local:artist:md5:f69d2a608336108f1d645744c63d6dea')], date='2009-04-13', genre='Instrumental Rock', last_modified=1310599762000, length=329639, name='Set Guitars To Kill', track_no=1, uri='local:track:And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/01-and_so_i_watch_you_from_afar-set_guitars_to_kill.mp3')), 'time_position': 329639}
Core-10 DEBUG    2020-01-17 23:58:47,438 Changing state: playing -> playing
Core-10 DEBUG    2020-01-17 23:58:47,439 Triggering playback state change event
MainThread DEBUG    2020-01-17 23:58:47,435 Sending tags_changed to AudioListener: {'tags': dict_keys(['title', 'artist', 'album', 'datetime', 'track-number', 'genre', 'container-format', 'private-id3v2-frame', 'track-count', 'encoder', 'publisher', 'private-data', 'has-crc', 'channel-mode', 'audio-codec', 'minimum-bitrate', 'maximum-bitrate', 'bitrate'])}
Core-10 DEBUG    2020-01-17 23:58:47,440 Sending playback_state_changed to CoreListener: {'old_state': 'playing', 'new_state': 'playing'}
Core-10 DEBUG    2020-01-17 23:58:47,451 Triggering track playback started event
Core-10 DEBUG    2020-01-17 23:58:47,453 Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=11, track=Track(album=Album(date='2009-04-13', name='Self Titled', num_tracks=11, uri='local:album:md5:5bdacb653bbd94bd6d1cbc68dc1854da'), artists=[Artist(name='And So I Watch You From Afar', uri='local:artist:md5:f69d2a608336108f1d645744c63d6dea')], date='2009-04-13', genre='Instrumental Rock', last_modified=1310599762000, length=205871, name='A Little Bit Of Solidarity Goes A Long Way', track_no=2, uri='local:track:And%20So%20I%20Watch%20You%20From%20Afar%20-%20Self%20Titled%20%282009%29/02-and_so_i_watch_you_from_afar-a_little_bit_of_solidarity_goes_a_long_way.mp3'))}
MpdFrontend-13 DEBUG    2020-01-17 23:58:47,452 Sending player to MpdSession: {}
Core-10 DEBUG    2020-01-17 23:58:47,458 Sending stream_title_changed to CoreListener: {'title': 'Set Guitars To Kill'}

This is because our call to self.audio.get_current_tags().get() to get the new tag values for (2), hasn't been update yet and still holds the tag values for (1). So we end up comparing current_track.name of (2) against title of (1), finding they are different, and then erroneously emitting the stream_title_changed event using (1).

It seems to be a race condition between get_current_tags and get_current_track. If I put a sleep(1) before get_current_tags then it works. I can also work-around the issue by changing Mopidy-MPD to emit a player idle event on track_playback_started. On top of that, we never wanted stream_title_changed events for regular tracks (I screwed that up in #1751).

[leaty]

Having a race condition here seems wrong, it should be one synchronous action when switching tracks - whether manual or not. But I admit I don't know enough of how mopidy works, so maybe there's some reason as to why.

[kingosticks]

It's more complicated than that, but yes, if I wasn't clear, this is a bug.

[leaty]

I didn't mean to come off rude, it was a late night. I think I just reacted to sleep(1) as a solution (no pun intended).

[kingosticks]

No worries. I only mentioned sleep as it proves it's a race condition.

EDIT: It's not exactly a race condition.

[kingosticks]

@adamcik, why do we care about the tag updates we got between receiving about-to-finish and STREAM_START?

[adamcik]

Better late than never, re tag updates and all these events it gets complicated since it's all async. And it's been ages since I've been looking at this stuff in detail. But here goes with a horribly over simplified pipeline diagram:

[SRC] --> [DECODER] --> [SINK]

• about-to-finish triggers when SRC runs out of data
• Tag updates might still be flowing through intermediate nodes in the pipeline at this point
• Audio for current track is still flowing at this stage
• For cases like Icecast streaming these tags getting to SINK is when they go live (I think this is where we pick them up as well)
• STREAM_START - I honestly don't remember if we get this event when it gets to SINK or when it happens at SRC - this is probably key to getting this right. Looking at https://gstreamer.freedesktop.org/documentation/gstreamer/gstmessage.html?gi-language=c#gst_message_new_stream_start it seems the pipeline/bin probably forwards this to the message bus once all the sinks see it.

So think we can have cases where there are meaningful tags in between about-to-finish and the next track starting. If getting this right is tricky we could consider ignoring them, but adding a TODO in the code and filing an other bug to followup, if that is less broken than the current state?