Mopidy stops playing randomly

Mopidy stops playing randomly. The logs say stuff like this:

2019-10-25 07:58:10,811 ERROR [27139:MainThread] mopidy.audio.gst: GStreamer error: gst-resource-error-quark: Resource not found. (3)

Looking at ‘ncmpcpp’ the playback is stuck on 0:00. If I do ‘mpc pause’ / ‘mpc play’ then the playback starts up again.

Can we get more information e.g. what system, deps, config, debug log (see: https://docs.mopidy.com/en/latest/troubleshooting/ and if running as a service also see: https://docs.mopidy.com/en/latest/service/).

Hi!

[core]
cache_dir = /var/cache/mopidy
config_dir = /etc/mopidy
data_dir = /var/lib/mopidy
max_tracklist_length = 10000
restore_state = true

[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 = /var/log/mopidy/mopidy-debug.log
config_file = /etc/mopidy/logging.conf

[audio]
mixer = alsamixer
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
allowed_origins =
csrf_protection = true

[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 = /var/lib/mopidy/playlists

[softwaremixer]
enabled = true

[file]
enabled = true
media_dirs =
  $XDG_MUSIC_DIR|Music
  ~/|Home
excluded_file_extensions =
  .directory
  .html
  .jpeg
  .jpg
  .log
  .nfo
  .pdf
  .png
  .txt
  .zip
show_dotfiles = false
follow_symlinks = false
metadata_timeout = 1000

[local]
enabled = true
library = sqlite
media_dir = /data/audio
scan_timeout = 1000
scan_flush_threshold = 100
scan_follow_symlinks = false
excluded_file_extensions =
  .directory
  .html
  .jpeg
  .jpg
  .log
  .nfo
  .pdf
  .png
  .txt
  .zip

[spotify]
enabled = true
username = XXXXXXXXXXXXXXXXX
password = ********
client_id = XXXXXXXXXXXXXXXXXXX
client_secret = ********
bitrate = 160
volume_normalization = true
private_session = false
timeout = 10
allow_cache = true
allow_network = true
allow_playlists = true
search_album_count = 20
search_artist_count = 10
search_track_count = 50
toplist_countries =

[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

[alsamixer]
enabled = true
card = 0
control = PCM

I’m currently running on Ubuntu 18.04.3 with the following packages installed:

ii  mopidy                                2.2.3-1                           all          music server with support for MPD/HTTP clients
ii  mopidy-alsamixer                      1.0.3-3                           all          Mopidy extension for extension for ALSA volume control
ii  mopidy-local-sqlite                   1.0.0-2                           all          Mopidy extension for keeping your local library in SQLite
ii  mopidy-spotify                        3.1.0-0mopidy1                    all          Mopidy extension for playing music from Spotify
ii  python-spotify                        2.0.5-0mopidy1                    amd64        Python bindings for libspotify (Python 2)

How do I turn on debugging information when running as a service?

And the output of sudo mopidyctl deps please, so we know exactly what gstreamer versions and plugins you have installed.

Change the level line in /etc/mopidy/logging.conf to DEBUG:

[handler_fileHandler]
class = FileHandler
formatter = simpleFormatter
level = DEBUG
args = ('/var/log/mopidy/mopidy.log',)

Then restart the service, reproduce the issue, and find the log in /var/log/mopidy/mopidy.log.

Running "/usr/bin/mopidy --config /usr/share/mopidy/conf.d:/etc/mopidy/mopidy.conf deps" as user mopidy
Executable: /usr/bin/mopidy
Platform: Linux-4.15.0-55-generic-x86_64-with-Ubuntu-18.04-bionic
Python: CPython 2.7.15+ from /usr/lib/python2.7
Mopidy: 2.2.3 from /usr/lib/python2.7/dist-packages
Mopidy-ALSAMixer: 1.0.3 from /usr/lib/python2.7/dist-packages
  Mopidy>=0.19: 2.2.3 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/dist-packages
  pyalsaaudio: 0.7 from /usr/lib/python2.7/dist-packages
Mopidy-Local-SQLite: 1.0.0 from /usr/lib/python2.7/dist-packages
Mopidy-Spotify: 3.1.0 from /usr/lib/python2.7/dist-packages
  Mopidy>=2.0: 2.2.3 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/dist-packages
  pyspotify>=2.0.5: 2.0.5 from /usr/lib/python2.7/dist-packages
    cffi>=1.0.0: 1.11.5 from /usr/lib/python2.7/dist-packages
  requests>=2.0: 2.18.4 from /usr/lib/python2.7/dist-packages
GStreamer: 1.14.5.0 from /usr/lib/python2.7/dist-packages/gi
  Detailed information:
    Python wrapper: python-gi 3.26.1
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsasink
        osssink
        oss4sink
        pulsesink
        id3demux
        id3v2mux
        lamemp3enc
        mpegaudioparse
        mpg123audiodec
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        flump3dec
        mad

I have turned on debugging now, will let you know my findings once it happens again.

But one quick question, is this a HTTP stream like https://github.com/mopidy/mopidy/issues/1749 ?

No, but the audio files are NFS mounted. So there’s network involved.

Ok, got it:

2019-10-31 06:37:51,377 DEBUG [4740:Dummy-22] mopidy.audio.gst: Got about-to-finish event.
2019-10-31 06:37:51,377 DEBUG [4740:Dummy-22] mopidy.audio.actor: Running about-to-finish callback.
2019-10-31 06:37:51,378 DEBUG [4740:LocalBackend-7] mopidy.backend: Backend translated URI from local:track:arbs/musikk/talking_heads_-_once_in_a_lifetime.mp3 to file:///data/audio/arbs/musikk/talking_heads_-_once_in_a_lifetime.mp3
2019-10-31 06:37:51,382 DEBUG [4740:Dummy-22] mopidy.audio.gst: Got source-setup signal: element=GstFileSrc
2019-10-31 06:37:51,383 DEBUG [4740:MainThread] mopidy.audio.gst: Got ERROR bus message: error=u'gst-resource-error-quark: Resource not found. (3)' debug=u'gstfilesrc.c(533): gst_file_src_start (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstFileSrc:source:\nNo such file "/data/audio/arbs/musikk/talking_heads_-_once_in_a_lifetime.mp3"'
2019-10-31 06:37:51,383 ERROR [4740:MainThread] mopidy.audio.gst: GStreamer error: gst-resource-error-quark: Resource not found. (3)
2019-10-31 06:37:51,402 DEBUG [4740:MainThread] mopidy.audio.gst: Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS

Mopidy is now stuck waiting to finish playing the previous song.

EDIT: Oh, I see this is in fact a file that has been removed since the last time it was played. So it’s basically a file that’s not found. But why does mopidy stop playing when this happens? It should just move on?