Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Next track is loaded in currently playing track / Mopidy never changes track #1528

Closed
jludwig opened this issue Jun 13, 2016 · 37 comments

Comments

@jludwig
Copy link

commented Jun 13, 2016

I'm having an issue where the track never changes track. The next track just starts playing after the current track ends, but continues past the total time of the current track. Eventually, it realizes that the track it finished and just stops playing. This happens no matter what output or mixer I use. It might be hard to picture what I'm saying, so attached is a picture of what it looks like from ncmpcpp.

Note: mopidy is currently playing the next track, Unsre Stärke heißt zu schwach, despite displaying the previous track, Verstummt!

2016-06-13-141459_1146x63_scrot

Unfortunately, I can't track down relevant data from the mopidy log. It seems to simply not realize that the track has changed, thus it does not log any change there.

Note that I can manually change the track with mpc next etc. Also, if it reaches the end of the playlist while still displaying the first song selected, it will end normally with this in the log:

DEBUG 2016-06-13 14:13:34,350 [29984:MpdSession-13] mopidy.mpd.session
Request from [::ffff:50.76.48.109]:5684: idle

Version: Mopidy 2.0.0

Extensions tested:

  • Mopidy-GMusic (1.0.0)
  • Mopidy-SoundCloud (2.0.2)
  • Mopidy-Youtube (2.0.2)

Edit: It eventually gets to this:

DEBUG    2016-06-13 14:47:26,482 [29984:MpdSession-18] mopidy.mpd.session
  Request from [::ffff:50.76.48.109]:25131: status
DEBUG    2016-06-13 14:47:26,486 [29984:MpdSession-18] mopidy.mpd.session
  Response to [::ffff:50.76.48.109]:25131: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 7
    playlistlength: 4
    xfade: 0
    state: play
    song: 0
    songid: 3
    time: 523:215
    elapsed: 523.607
    bitrate: 320
    OK
DEBUG    2016-06-13 14:47:26,582 [29984:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'bitrate': [320000], 'has-crc': [False], 'channel-mode': [u'stereo']}
DEBUG    2016-06-13 14:47:26,584 [29984:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'bitrate': [320000], 'channel-mode': [u'joint-stereo']}
DEBUG    2016-06-13 14:47:26,620 [29984:MpdSession-18] mopidy.mpd.session
  Request from [::ffff:50.76.48.109]:25131: idle
DEBUG    2016-06-13 14:47:26,791 [29984:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [320031], 'bitrate': [320000], 'maximum-bitrate': [320031], 'channel-mode': [u'joint-stereo']}
DEBUG    2016-06-13 14:47:26,843 [29984:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [319725], 'bitrate': [320000], 'maximum-bitrate': [320031], 'channel-mode': [u'joint-stereo']}
DEBUG    2016-06-13 14:47:27,624 [29984:MpdSession-18] mopidy.mpd.session
  Request from [::ffff:50.76.48.109]:25131: noidle
DEBUG    2016-06-13 14:47:27,627 [29984:MpdSession-18] mopidy.mpd.session
  Response to [::ffff:50.76.48.109]:25131: OK
DEBUG    2016-06-13 14:47:27,755 [29984:MpdSession-18] mopidy.mpd.session
  Request from [::ffff:50.76.48.109]:25131: status
DEBUG    2016-06-13 14:47:27,759 [29984:MpdSession-18] mopidy.mpd.session
  Response to [::ffff:50.76.48.109]:25131: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 7
    playlistlength: 4
    xfade: 0
    state: play
    song: 0
    songid: 3
    time: 2:215
    elapsed: 2.194
    bitrate: 320
    OK

where the song that it started playing initially just restarts.

@jludwig jludwig changed the title Next track doesn't Next track is loaded in currently playing track / Mopidy never changes track Jun 13, 2016

@adamcik

This comment has been minimized.

Copy link
Member

commented Jul 15, 2016

This is typically due to a race condition with when the idle command gets send out, or it not getting out at all. I seem to remember having tried to fix this when doing the gapless work, but might have missed on case.

@lilmike

This comment has been minimized.

Copy link

commented Jul 25, 2016

Hi,
I just noticed this, although in my case mpd doesn't update tracks, unless I do mpc next, and then after that it plays two songs, and starts repeating the second one over and over. I only experienced it when I uncommented (and changed) the output parameter. Before, when it was set to default, this didn't happen. Fwiw, I'm using the output parameter to play and stream my output.
-Michael.

@lilmike

This comment has been minimized.

Copy link

commented Jul 25, 2016

Just verified, issue goes away when output parameter is commented (using builtin default).
-Michael.

@adamcik

This comment has been minimized.

Copy link
Member

commented Jul 25, 2016

What do you mean by output parameter in this case?

@lilmike

This comment has been minimized.

Copy link

commented Jul 26, 2016

I mean the output option in xdg-config/mopidy/mopidy.conf

Sent from my iPhone

On Jul 25, 2016, at 3:26 PM, Thomas Adamcik notifications@github.com wrote:

What do you mean by output parameter in this case?


You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

@lilmike

This comment has been minimized.

Copy link

commented Aug 5, 2016

Any news on this one? :-)

@lilmike

This comment has been minimized.

Copy link

commented Oct 17, 2016

Any updates? I'm really looking forward to a fix :D.
-Michael.

@monokles

This comment has been minimized.

Copy link

commented Oct 30, 2016

I'm having the same issue, although I'm not using the MPD frontend but the web frontend.
Not sure what I can add here that might be of help, but I'd be more than happy to provide information on my setup.

@kingosticks

This comment has been minimized.

Copy link
Member

commented Nov 2, 2016

@lilmike I think the question is what our parameter are you using that is different from the built in default? Are you trying to use a file sink?

@monokles The web frontend doesn't have idle commands. Could you provide the output of mopidy deps, mopidy config and a debug log when this happens (on dpaste or similar)? And what web client are you using?

@lilmike

This comment has been minimized.

Copy link

commented Nov 12, 2016

Hi,
I'm using an output parameter that takes a tee, and then splits it into output to my speakers, and stream to an icecast server. If I comment the output parameter, the problem goes away. If I have it set, it happens.
-Michael.

@monokles

This comment has been minimized.

Copy link

commented Nov 21, 2016

Hi!
Sorry for the late reply @kingosticks , been a very busy time here.

Quick summary of what happens on my side when having more than one track in the queue:

  1. mopidy plays the first track
  2. mopidy plays the second track (although this change is not updated on any frontend i.e. they still show the first track as the one that's being played)
  3. mopidy gets stuck in a loop where the second track keeps getting played over and over again

I'm using the musicbox web frontend, but it shows up moped as well (and possibly other frontends).
mopidy config
mopidy deps
For some reason mopidy didn't generate a debug log... I'm not sure why, but
here is the normal log if that's of any use.
Note that I'm not using icecast, but liquidsoap, with this script running.

If there's any more I can provide (or if you can tell me why the debug log is not being generated), let me know!

@lolorc

This comment has been minimized.

Copy link

commented Mar 23, 2017

Hi there.
I've only started using mopidy for few hours and I'm already affected by this bug.
exactly same behavior as @monokles (the loop happened with the 3rd song in my case)
how guys have you circumvented this huge bug ?

@kingosticks

This comment has been minimized.

Copy link
Member

commented Mar 23, 2017

Could you (or anyone) please provide their output for mopidy deps, mopidy config and the exact steps required to reproduce this. Thanks.

@lolorc

This comment has been minimized.

Copy link

commented Mar 23, 2017

what about those provided 2 posts earlier ?

@kingosticks

This comment has been minimized.

Copy link
Member

commented Mar 23, 2017

There are no steps for anyone to reproduce the issue.... If I add 3 Spotify tracks to my queue using a HTTP client and play them I don't see any of what is described here.

If you provide your config then perhaps we could see if you are also seeing something related to a non-standard configured output.

@lilmike

This comment has been minimized.

Copy link

commented Mar 23, 2017

Hi,
From what I can tell it only happens for me when I have [audio]->output set to something other than default. For example,

mopidy config (when it's working):
[core]
cache_dir = $XDG_CACHE_DIR/mopidy
config_dir = $XDG_CONFIG_DIR/mopidy
data_dir = $XDG_DATA_DIR/mopidy
max_tracklist_length = 10000
restore_state = false

[logging]
color = true
console_format = %(levelname)-8s %(message)s
debug_format = %(levelname)-8s %(asctime)s [%(process)d:%(threadName)s] %(name)s\n %(message)s
debug_file = mopidy.log
config_file =

[audio]
mixer = software
mixer_volume =
output = autoaudiosink
buffer_time =

[proxy]
scheme =
hostname =
port =
username =
password =

[mpd]
enabled = true
hostname = 127.0.0.1
port = 6600
password =
max_connections = 20
connection_timeout = 60
zeroconf = Mopidy MPD server on $hostname
command_blacklist =
listall
listallinfo
default_playlist_scheme = m3u

[http]
enabled = true
hostname = 127.0.0.1
port = 6680
static_dir =
zeroconf = Mopidy HTTP server on $hostname

[stream]
enabled = true
protocols =
http
https
mms
rtmp
rtmps
rtsp
metadata_blacklist =
timeout = 5000

[m3u]
enabled = true
base_dir =
default_encoding = latin-1
default_extension = .m3u8
playlists_dir =

[softwaremixer]
enabled = true

[file]
enabled = true
media_dirs =
$XDG_MUSIC_DIR|Music
~/|Home
excluded_file_extensions =
.jpg
.jpeg
show_dotfiles = false
follow_symlinks = false
metadata_timeout = 1000

[local]
enabled = true
library = sqlite
media_dir = /home/lilmike/Music
scan_timeout = 1000
scan_flush_threshold = 100
scan_follow_symlinks = false
excluded_file_extensions =
.directory
.html
.jpeg
.jpg
.log
.nfo
.png
.txt

[spotify]
enabled = false ; Extension disabled by user config.

[qsaver]
enabled = true
backup_file = ./tracklist_backup.json

[local-sqlite]
enabled = true
directories =
Albums local:directory?type=album
Artists local:directory?type=artist
Composers local:directory?type=artist&role=composer
Genres local:directory?type=genre
Performers local:directory?type=artist&role=performer
Release Years local:directory?type=date&format=%25Y
Tracks local:directory?type=track
Last Week's Updates local:directory?max-age=604800
Last Month's Updates local:directory?max-age=2592000
timeout = 10
use_album_mbid_uri = true
use_artist_mbid_uri = false
use_artist_sortname = false

To get it to break, at least for me, uncomment this:

#output = tee name=t t. ! queue ! audioconvert ! audioresample ! autoaudiosink t. ! queue ! audioresample ! audioconvert ! vorbisenc ! oggmux ! shout2send ip=xxx port=8000 password=xxx mount=mopidy

mopidy deps:
Executable: /usr/bin/mopidy
Platform: Linux-4.10.3-1-ARCH-x86_64-with-glibc2.2.5
Python: CPython 2.7.13 from /usr/lib/python2.7
Mopidy: 2.1.0 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
requests>=2.0: 2.13.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
tornado>=3.2: 4.4.2 from /usr/lib/python2.7/site-packages
singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Mopidy-Local-SQLite: 1.0.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
Mopidy>=1.1: 2.1.0 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
requests>=2.0: 2.13.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
tornado>=3.2: 4.4.2 from /usr/lib/python2.7/site-packages
singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
uritools>=1.0: 1.0.1 from /usr/lib/python2.7/site-packages
ipaddress>=1.0.6: 1.0.18 from /usr/lib/python2.7/site-packages
ipaddress>=1.0.6: 1.0.18 from /usr/lib/python2.7/site-packages
Mopidy-Qsaver: 0.1.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
Mopidy>=1.0: 2.1.0 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
requests>=2.0: 2.13.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
tornado>=3.2: 4.4.2 from /usr/lib/python2.7/site-packages
singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
Mopidy-Spotify: 3.0.0 from /usr/lib/python2.7/site-packages
Mopidy>=2.0: 2.1.0 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
requests>=2.0: 2.13.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
tornado>=3.2: 4.4.2 from /usr/lib/python2.7/site-packages
singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/site-packages
pyspotify>=2.0.5: 2.0.5 from /usr/lib/python2.7/site-packages
cffi>=1.0.0: 1.9.1 from /usr/lib/python2.7/site-packages
pycparser: 2.17 from /usr/lib/python2.7/site-packages
requests>=2.0: 2.13.0 from /usr/lib/python2.7/site-packages
setuptools: 34.3.2 from /usr/lib/python2.7/site-packages
packaging>=16.8: 16.8 from /usr/lib/python2.7/site-packages
pyparsing: 2.2.0 from /usr/lib/python2.7/site-packages
six: 1.10.0 from /usr/lib/python2.7/site-packages
six>=1.6.0: 1.10.0 from /usr/lib/python2.7/site-packages
appdirs>=1.4.0: 1.4.3 from /usr/lib/python2.7/site-packages
GStreamer: 1.10.4.0 from /usr/lib/python2.7/site-packages/gi
Detailed information:
Python wrapper: python-gi 3.22.0
Relevant elements:
Found:
uridecodebin
souphttpsrc
appsrc
alsasink
osssink
oss4sink
pulsesink
id3demux
id3v2mux
lamemp3enc
mad
mpegaudioparse
mpg123audiodec
vorbisdec
vorbisenc
vorbisparse
oggdemux
oggmux
oggparse
flacdec
flacparse
shout2send
Not found:
flump3dec

-Michael.

@lolorc

This comment has been minimized.

Copy link

commented Mar 24, 2017

steps to reproduce here:

  • add tracks to an empty queue from a Local album (fresh mopidy start)
  • start to play with first track
  • observe at the end of 1st track the current track is not updated, neither is the playing progress
    (this can be observed from any http client, from the api and from a mpd client)

I don't have spotify to try and reproduce with it.
At the moment I'm going to try the debian package to see if I can reproduce with it.
mopidy.deps.txt
mopidy.conf.txt

edit: confirmed with debian/stretch package as well

# lsof -p $(pgrep mopidy)|grep mp3
mopidy  6856 mopidy   19r   REG              253,1  3700844 15990956 /data/media/mp3/Archive/Londinium/02 - All Time.mp3
mopidy  6856 mopidy   20r   REG              253,1  3700844 15990956 /data/media/mp3/Archive/Londinium/02 - All Time.mp3

two file handles for the same track

edit 2:

  • first track: one file handle (the one to the current track)
# lsof -p $(pgrep mopidy)|grep mp3
mopidy  6856 mopidy   19r   REG              253,1  5953883 15990957 /data/media/mp3/Archive/Londinium/03 - So Few Words.mp3
  • 2nd track: 2 file handles, (the one from the previous track which was not closed, and a new one to the
    2nd track)
# lsof -p $(pgrep mopidy)|grep mp3
mopidy  6856 mopidy   19r   REG              253,1  5953883 15990957 /data/media/mp3/Archive/Londinium/03 - So Few Words.mp3
mopidy  6856 mopidy   22r   REG              253,1  4051133 15990958 /data/media/mp3/Archive/Londinium/04 - Headspace.mp3
  • after 2nd track it loops
# lsof -p $(pgrep mopidy)|grep mp3
mopidy  6856 mopidy   19r   REG              253,1  4051133 15990958 /data/media/mp3/Archive/Londinium/04 - Headspace.mp3
mopidy  6856 mopidy   22r   REG              253,1  4051133 15990958 /data/media/mp3/Archive/Londinium/04 - Headspace.mp3

I haven't looked at the code, but I'm pretty sure it should give you some pretty good hint ;-)

@danielwhite

This comment has been minimized.

Copy link

commented Mar 26, 2017

I've been seeing the same behaviour for some time.

Using a custom container, I have a playlist of 5 items. If I skip from track 4 to track 5 (with repeat on), then we see the following series of events:

INFO     2017-03-26 08:46:07,205 [1:MpdSession-33] mopidy.mpd.session
  New MPD connection from [::ffff:172.18.0.1]:35692
DEBUG    2017-03-26 08:46:07,208 [1:MpdSession-33] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35692: next
DEBUG    2017-03-26 08:46:07,212 [1:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PLAYING new=GST_STATE_PAUSED pending=GST_STATE_READY
DEBUG    2017-03-26 08:46:07,215 [1:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2017-03-26 08:46:07,216 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested change of track; loading and starting Spotify player
DEBUG    2017-03-26 08:46:07,221 [1:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
DEBUG    2017-03-26 08:46:07,224 [1:Audio-2] mopidy.audio.gst
  Sending TAG event for track 'spotify:track:3n52npc7FPjG4dBZcgLjmD': 'taglist, artist=(string)Silverstein, title=(string)"My\\ Heroine\\ -\\ Acoustic", album=(string)"18\\ Candles:\\ The\\ Early\\ Years";'
DEBUG    2017-03-26 08:46:07,226 [1:Audio-2] mopidy.audio.gst
  Got source-setup signal: element=__main__.GstAppSrc
DEBUG    2017-03-26 08:46:07,228 [1:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC
DEBUG    2017-03-26 08:46:07,229 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested seek to 0
DEBUG    2017-03-26 08:46:07,233 [1:SpotifyBackend-6] mopidy_spotify.playback
  Skipping seek due to issue mopidy/mopidy#300
DEBUG    2017-03-26 08:46:07,233 [1:MpdSession-33] mopidy.mpd.session
  Response to [::ffff:172.18.0.1]:35692: OK
DEBUG    2017-03-26 08:46:07,235 [1:MpdSession-33] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35692: command_list_ok_begin
DEBUG    2017-03-26 08:46:07,237 [1:MpdSession-33] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35692: status
DEBUG    2017-03-26 08:46:07,238 [1:MpdSession-33] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35692: currentsong
DEBUG    2017-03-26 08:46:07,240 [1:MpdSession-33] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35692: command_list_end
DEBUG    2017-03-26 08:46:07,248 [1:Audio-2] mopidy.audio.actor
  Position query failed
DEBUG    2017-03-26 08:46:07,257 [1:MpdSession-33] mopidy.mpd.session
  Response to [::ffff:172.18.0.1]:35692: 
    volume: 100
    repeat: 1
    random: 0
    single: 0
    consume: 0
    playlist: 5
    playlistlength: 5
    xfade: 0
    state: play
    song: 2
    songid: 3
    nextsong: 3
    nextsongid: 4
    time: 0:212
    elapsed: 0.000
    bitrate: 160
    list_OK
    file: spotify:track:5W12R96LKHS0MxBjs6TQep
    Time: 212
    Artist: Silverstein
    Album: Ghost
    Title: Ghost
    Date: 2016
    Track: 1
    Pos: 2
    Id: 3
    AlbumArtist: Silverstein
    X-AlbumUri: spotify:album:1EZDUjQkJy65ecY1DZDstN
    list_OK
    OK
DEBUG    2017-03-26 08:46:07,260 [1:MpdSession-33] mopidy.internal.network
  Client most likely disconnected.
DEBUG    2017-03-26 08:46:07,262 [1:MpdSession-33] mopidy.internal.network
  Already stopping: Actor is shutting down.
DEBUG    2017-03-26 08:46:07,706 [1:Dummy-17] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2017-03-26 08:46:07,707 [1:Dummy-17] mopidy.audio.actor
  Audio event: position_changed(position=0L)
DEBUG    2017-03-26 08:46:07,708 [1:Dummy-17] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0L}
DEBUG    2017-03-26 08:46:07,904 [1:MainThread] mopidy.audio.gst
  Got STREAM_START bus message
DEBUG    2017-03-26 08:46:07,904 [1:MainThread] mopidy.audio.actor
  Audio event: stream_changed(uri=u'appsrc://')
DEBUG    2017-03-26 08:46:07,905 [1:MainThread] mopidy.listener
  Sending stream_changed to AudioListener: {'uri': u'appsrc://'}
DEBUG    2017-03-26 08:46:07,908 [1:Core-8] mopidy.core.playback
  Triggering track playback ended event
DEBUG    2017-03-26 08:46:07,910 [1:Core-8] mopidy.listener
  Sending track_playback_ended to CoreListener: {'time_position': 468981L, 'tl_track': TlTrack(tlid=3, track=Track(album=Album(artists=[Artist(name=u'Silverstein', uri='spotify:artist:1Tsag5J854qxeOo2apszug')], date=u'2016', name=u'Ghost', uri='spotify:album:1EZDUjQkJy65ecY1DZDstN'), artists=[Artist(name=u'Silverstein', uri='spotify:artist:1Tsag5J854qxeOo2apszug')], bitrate=160, date=u'2016', disc_no=0, length=212000, name=u'Ghost', track_no=1, uri='spotify:track:5W12R96LKHS0MxBjs6TQep'))}
DEBUG    2017-03-26 08:46:07,914 [1:Core-8] mopidy.core.playback
  Changing state: playing -> playing
DEBUG    2017-03-26 08:46:07,915 [1:Core-8] mopidy.core.playback
  Triggering playback state change event
DEBUG    2017-03-26 08:46:07,917 [1:Core-8] mopidy.listener
  Sending playback_state_changed to CoreListener: {'old_state': u'playing', 'new_state': u'playing'}
DEBUG    2017-03-26 08:46:07,918 [1:MpdFrontend-11] mopidy.listener
  Sending player to MpdSession: {}
DEBUG    2017-03-26 08:46:07,920 [1:Core-8] mopidy.core.playback
  Triggering track playback started event
DEBUG    2017-03-26 08:46:07,922 [1:Core-8] mopidy.listener
  Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=5, track=Track(album=Album(artists=[Artist(name=u'Silverstein', uri='spotify:artist:1Tsag5J854qxeOo2apszug')], date=u'2006', name=u'18 Candles: The Early Years', uri='spotify:album:5wwo3iPJ93pElRfHs97bea'), artists=[Artist(name=u'Silverstein', uri='spotify:artist:1Tsag5J854qxeOo2apszug')], bitrate=160, date=u'2006', disc_no=0, length=214000, name=u'My Heroine - Acoustic', track_no=13, uri='spotify:track:3n52npc7FPjG4dBZcgLjmD'))}
DEBUG    2017-03-26 08:46:07,926 [1:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
DEBUG    2017-03-26 08:46:07,928 [1:MainThread] mopidy.audio.gst
  Got ASYNC_DONE bus message.
DEBUG    2017-03-26 08:46:07,935 [1:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
DEBUG    2017-03-26 08:46:07,938 [1:MainThread] mopidy.audio.actor
  Audio event: state_changed(old_state=playing, new_state=playing, target_state=None)
DEBUG    2017-03-26 08:46:07,940 [1:MainThread] mopidy.listener
  Sending state_changed to AudioListener: {'old_state': u'playing', 'target_state': None, 'new_state': u'playing'}
DEBUG    2017-03-26 08:46:08,230 [1:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'album': [u'18 Candles: The Early Years'], 'artist': [u'Silverstein'], 'title': [u'My Heroine - Acoustic']}
DEBUG    2017-03-26 08:46:08,231 [1:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['album', 'title', 'artist'])
DEBUG    2017-03-26 08:46:08,232 [1:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['album', 'title', 'artist']}

Once the previous track ends, then we get the following series of events where we seem to happily move to the next track.

DEBUG    2017-03-26 08:49:34,022 [1:SpotifyEventLoop] mopidy_spotify.playback
  End of track reached
DEBUG    2017-03-26 08:49:34,022 [1:Audio-2] mopidy.audio.gst
  Sending appsrc end-of-stream event.
DEBUG    2017-03-26 08:49:34,310 [1:SpotifyEventLoop] mopidy_spotify.playback
  End of track already received; ignoring callback
DEBUG    2017-03-26 08:49:38,743 [1:Dummy-27] mopidy.audio.gst
  Got about-to-finish event.
DEBUG    2017-03-26 08:49:38,743 [1:Dummy-27] mopidy.audio.actor
  Running about-to-finish callback.
DEBUG    2017-03-26 08:49:38,744 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested change of track; loading and starting Spotify player
DEBUG    2017-03-26 08:49:38,746 [1:Audio-2] mopidy.audio.gst
  Sending TAG event for track 'spotify:track:5U2p81vdlp2saDTIvk0Lnb': 'taglist, artist=(string)Silverstein, title=(string)"My\\ Heroine", album=(string)"Discovering\\ the\\ Waterfront";'
DEBUG    2017-03-26 08:49:38,748 [1:Dummy-27] mopidy.audio.gst
  Got source-setup signal: element=__main__.GstAppSrc
DEBUG    2017-03-26 08:49:38,751 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested seek to 0
DEBUG    2017-03-26 08:49:38,752 [1:SpotifyBackend-6] mopidy_spotify.playback
  Skipping seek due to issue mopidy/mopidy#300
DEBUG    2017-03-26 08:49:40,880 [1:Dummy-17] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2017-03-26 08:49:40,881 [1:Dummy-17] mopidy.audio.actor
  Audio event: position_changed(position=0L)
DEBUG    2017-03-26 08:49:40,881 [1:Dummy-17] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0L}

However, at the end of this, we see the track start again:

DEBUG    2017-03-26 08:53:02,619 [1:SpotifyEventLoop] mopidy_spotify.playback
  End of track reached
DEBUG    2017-03-26 08:53:02,620 [1:Audio-2] mopidy.audio.gst
  Sending appsrc end-of-stream event.
DEBUG    2017-03-26 08:53:02,810 [1:SpotifyEventLoop] mopidy_spotify.playback
  End of track already received; ignoring callback
DEBUG    2017-03-26 08:53:06,840 [1:Dummy-31] mopidy.audio.gst
  Got about-to-finish event.
DEBUG    2017-03-26 08:53:06,840 [1:Dummy-31] mopidy.audio.actor
  Running about-to-finish callback.
DEBUG    2017-03-26 08:53:06,842 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested change of track; loading and starting Spotify player
DEBUG    2017-03-26 08:53:06,843 [1:Audio-2] mopidy.audio.gst
  Sending TAG event for track 'spotify:track:5U2p81vdlp2saDTIvk0Lnb': 'taglist, artist=(string)Silverstein, title=(string)"My\\ Heroine", album=(string)"Discovering\\ the\\ Waterfront";'
DEBUG    2017-03-26 08:53:06,844 [1:Dummy-31] mopidy.audio.gst
  Got source-setup signal: element=__main__.GstAppSrc
DEBUG    2017-03-26 08:53:06,847 [1:SpotifyBackend-6] mopidy_spotify.playback
  Audio requested seek to 0
DEBUG    2017-03-26 08:53:06,849 [1:SpotifyBackend-6] mopidy_spotify.playback
  Skipping seek due to issue mopidy/mopidy#300
DEBUG    2017-03-26 08:53:08,975 [1:Dummy-17] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2017-03-26 08:53:08,975 [1:Dummy-17] mopidy.audio.actor
  Audio event: position_changed(position=0L)
DEBUG    2017-03-26 08:53:08,976 [1:Dummy-17] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0L}

It's worth noting here that if you query the state with the client, then Mopidy appears to think that we're still on the track from the first example:

INFO     2017-03-26 08:55:15,437 [1:MpdSession-34] mopidy.mpd.session
  New MPD connection from [::ffff:172.18.0.1]:35696
DEBUG    2017-03-26 08:55:15,439 [1:MpdSession-34] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35696: command_list_ok_begin
DEBUG    2017-03-26 08:55:15,440 [1:MpdSession-34] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35696: status
DEBUG    2017-03-26 08:55:15,441 [1:MpdSession-34] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35696: currentsong
DEBUG    2017-03-26 08:55:15,442 [1:MpdSession-34] mopidy.mpd.session
  Request from [::ffff:172.18.0.1]:35696: command_list_end
DEBUG    2017-03-26 08:55:15,449 [1:MpdSession-34] mopidy.mpd.session
  Response to [::ffff:172.18.0.1]:35696: 
    volume: 100
    repeat: 1
    random: 0
    single: 0
    consume: 0
    playlist: 5
    playlistlength: 5
    xfade: 0
    state: play
    song: 4
    songid: 5
    nextsong: 0
    nextsongid: 1
    time: 547:214
    elapsed: 547.989
    bitrate: 160
    list_OK
    file: spotify:track:3n52npc7FPjG4dBZcgLjmD
    Time: 214
    Artist: Silverstein
    Album: 18 Candles: The Early Years
    Title: My Heroine - Acoustic
    Date: 2006
    Track: 13
    Pos: 4
    Id: 5
    AlbumArtist: Silverstein
    X-AlbumUri: spotify:album:5wwo3iPJ93pElRfHs97bea
    list_OK
    OK
DEBUG    2017-03-26 08:55:15,451 [1:MpdSession-34] mopidy.internal.network
  Client most likely disconnected.
DEBUG    2017-03-26 08:55:15,453 [1:MpdSession-34] mopidy.internal.network
  Already stopping: Actor is shutting down.

The major thing that stands out here is that in the case where it behaves as expected, we see:

DEBUG    2017-03-26 08:46:07,224 [1:Audio-2] mopidy.audio.gst
  Sending TAG event for track 'spotify:track:3n52npc7FPjG4dBZcgLjmD': 'taglist, artist=(string)Silverstein, title=(string)"My\\ Heroine\\ -\\ Acoustic", album=(string)"18\\ Candles:\\ The\\ Early\\ Years";'
[...]
DEBUG    2017-03-26 08:46:08,230 [1:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'album': [u'18 Candles: The Early Years'], 'artist': [u'Silverstein'], 'title': [u'My Heroine - Acoustic']}

But in the case that doesn't work as expected, we only see the "Sending TAG event" message.

@lilmike

This comment has been minimized.

Copy link

commented Mar 26, 2017

@danielwhite

This comment has been minimized.

Copy link

commented Mar 26, 2017

I might also note that I was seeing this both with and without repeat. It just happened that I was testing it against repeat when I gathered these logs.

@lilmike

This comment has been minimized.

Copy link

commented Mar 26, 2017

Hi,
I just did some tests with really short files (so I wouldn't have to listen to really long songs to see if it was working or not) and my findings:

  1. When I had the output parameter commented out, it happened after about 4 or 5 tracks.
  2. When I had the output parameter uncommented and set to something else, it happened right after the second track.
  3. It's also worth noticing I don't usually notice it on my music library with the commented output parameter, so perhaps if songs are long (and not short sounds) and the output parameter is unset in the config file, it doesn't happen or doesn't happen as often?
  4. logs are here (I couldn't get my screen reader to work with the attach dialog, otherwise I would've done that) (#1 when output was set explicitly, #2 when it was commented). https://mtserver.mwtd.net/mopidy1.txt, https://mtserver.mwtd.net/mopidy2.txt

-Michael.

@lolorc

This comment has been minimized.

Copy link

commented Mar 28, 2017

can this bug be tagged as a bug ?
there has been 2 releases since this bug has been filled and it has yet to get attention...
I'm a newcomer, for a simple use case which is replacing MPD, this bug is a major blocker.

@danielwhite

This comment has been minimized.

Copy link

commented May 8, 2017

I've done a little more experimentation with my container, and initially removed Moped to help rule out any conflicts, but that did nothing.

What did help was removing the following line from my configuration:

output = audioresample ! audioconvert ! vorbisenc ! oggmux ! shout2send mount=stream.ogg ip=icecast port=8000 password=hackme

I was able to check the status with MPC and see the tracks progressing as expected.

Adding the following line allowed me to restore output with Icecast, and without this bug occurring.

output = lamemp3enc ! shout2send mount=stream.mp3 ip=icecast port=8000 password=hackme

So my conclusion at this point is that there is some bad interaction with the Ogg Vorbis encoding of the output. I wonder if it's worth removing that example from https://docs.mopidy.com/en/latest/audio/#streaming-through-icecast, as it feels rather misleading.

@JustArchi

This comment has been minimized.

Copy link

commented Jun 7, 2017

I can confirm issue with oggmux, I reproduced it with using opusenc instead of vorbis. Could anybody look into this?

can this bug be tagged as a bug ?
there has been 2 releases since this bug has been filled and it has yet to get attention...
I'm a newcomer, for a simple use case which is replacing MPD, this bug is a major blocker.

Thank you in advance.

@agg23

This comment has been minimized.

Copy link

commented Sep 16, 2018

This is still an issue, but it doesn't appear to be limited to Icecast, as it occurs for me with the default configuration.

@gjabell

This comment has been minimized.

Copy link

commented Nov 29, 2018

Have there been any updates on this issue? I've had the same problem with mopidy-subidy, and am also having it with a backend plugin I'm working on. It looks like the same issue happens with the Gmusic plugin #183.

EDIT: I am having this issue with both MPD and HTTP (with Mopidy-Material-Webclient). In MPD I can skip to the next song by quickly tapping <> (back-forward), so I'm guessing it's a race condition or timing issue? Also might be worth noting that songs will occasionally reach their end and won't automatically go to the next song.

@pv

This comment has been minimized.

Copy link

commented Dec 5, 2018

I'm also seeing similar failures to change track (this is a blocker for me), with default output to local machine current session (pulseaudio/Ubuntu18.10). Track change hangs in the same way as described above especially when playing ogg files, whereas mp3 / spotify works fine. I don't know anything, but is the following (fixed!) Clementine bug similar? clementine-player/Clementine#6103 In my case, I indeed have ogg files with different sample rates.

@kingosticks

This comment has been minimized.

Copy link
Member

commented Dec 5, 2018

I think it's the gstreamer version that's the key here. Be good if someone with the issue could try downgrading that.

@gjabell

This comment has been minimized.

Copy link

commented Dec 5, 2018

I can try downgrading; is there a specific version I should try?

@kingosticks

This comment has been minimized.

Copy link
Member

commented Dec 5, 2018

v1.10 perhaps.

@gjabell

This comment has been minimized.

Copy link

commented Dec 6, 2018

Alright, looks like it's gstreamer after all; I couldn't get v1.10 to work with Mopidy, but v1.12.2 doesn't have any problems. Any version past that seems to have the same issue described above.

@kingosticks

This comment has been minimized.

Copy link
Member

commented Jan 11, 2019

@pv that Clementine issue is interesting and it'd be easy to hack the same switch from queue to queue2 into your Mopidy code and try it out. I've been unable to reproduce it so far myself but perhaps different sample rates is the key.

@pv

This comment has been minimized.

Copy link

commented Jan 13, 2019

@kingosticks: thanks for the suggestion. I confirm that with the following changes (to mopidy 2.2.2):

--- mopidy/audio/actor.py.old	2019-01-13 14:22:34.377491564 +0200
+++ mopidy/audio/actor.py	2019-01-13 14:22:55.836419833 +0200
@@ -134,7 +134,10 @@
         logger.info('Audio output set to "%s"', description)
 
     def _add(self, element):
-        queue = Gst.ElementFactory.make('queue')
+        if os.environ.get('MOPIDY_QUEUE2', '0').strip() == '1':
+            queue = Gst.ElementFactory.make('queue2')
+        else:
+            queue = Gst.ElementFactory.make('queue')
         self.add(element)
         self.add(queue)
         queue.link(element)
@@ -492,7 +495,10 @@
 
     def _setup_audio_sink(self):
         audio_sink = Gst.ElementFactory.make('bin', 'audio-sink')
-        queue = Gst.ElementFactory.make('queue')
+        if os.environ.get('MOPIDY_QUEUE2', '0').strip() == '1':
+            queue = Gst.ElementFactory.make('queue2')
+        else:
+            queue = Gst.ElementFactory.make('queue')
         volume = Gst.ElementFactory.make('volume')
 
         # Queue element to buy us time between the about-to-finish event and

the issue is present 100% of the time when running MOPIDY_QUEUE2=0 mopidy and never present with MOPIDY_QUEUE2=1 mopidy.

The smallest repro I found is the two ogg files attached --- they have to be both added to the now playing, and the playback with queue (gstreamer 1.14.4) hangs when switching from a.ogg to b.ogg whereas queue2 seems to switch fine. a-b-ogg.zip

Perhaps there are multiple issues causing similar looking problems, but the queue/queue2 thing at least seems reproducible here, and was at fault for the problems I was seeing.

@kingosticks

This comment has been minimized.

Copy link
Member

commented Jan 15, 2019

Nice one. Thanks for trying that out and for those files are great for reproducing. I've also found elsewhere that removing the fakesink seems to fix problems with the latest Gstreamer version. So if I combine those two together and just use queue2 for the fakesink then everything except appsrc (Spotify) seems to work again. If I want to also get appsrc working reliably then removing the fakesink seems to to be the only way - but maybe that's an entirely different problem.

@kingosticks

This comment has been minimized.

Copy link
Member

commented Jan 16, 2019

OK. So I think I have a handle on this now. There seems to be multiple issues going on when changing tracks.

  1. When using shout2send. A workaround that fixes all pipeline variants I have tried is to set the async=false sink parameter. i.e.
output = tee name=t ! queue ! autoaudiosink t. ! queue ! lamemp3enc ! shout2send async=false mount=mopidy ip=127.0.0.1 port=8000 password=hackme
  1. Tacks with different sample rates as seen by @pv.
    Fixed by swapping our queue elements for queue2 elements or by removing our always connected fakesink. The latter is preferable since it's currently redundant. Also, queue and queue2 behave slightly differently and appsrc is very sensitive to buffering changes.

  2. Streams that require buffering (#1722). The log will contain "Race condition happened. See #1222 and #1430 " messages.

kingosticks added a commit to kingosticks/mopidy that referenced this issue Jan 16, 2019

audio: removed unused fakesink. (Fixes mopidy#1528)
The 'always connected fakesink' is causing problems when switching
between tracks with different sample rates and with some custom
output pipelines. Since it's only there to support dynamic outputs,
which we don't yet support, we might as well remove it for now.

kingosticks added a commit that referenced this issue Jan 16, 2019

@jodal jodal added this to the v2.2.3 milestone Jan 16, 2019

kingosticks added a commit that referenced this issue Jan 30, 2019

@kingosticks

This comment has been minimized.

Copy link
Member

commented Jan 30, 2019

The fix for this will be in the upcoming v2.2.3 release.

@kingosticks kingosticks added C-bug and removed A-mpd labels Jan 30, 2019

@EliotBerriot

This comment has been minimized.

Copy link

commented May 3, 2019

I can confirm installing from the master branch (with pip install --user git+https://github.com/mopidy/mopidy.git) fixes some playback issues I encountered with the Mopidy plugin I maintain. The exact issue was that tracks were changing properly, but regardless of the track metadata, the audio stream itself was always the same (the one from the first track).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.