GStreamer Troubleshooting?

General
1

I’m running Mopidy, Mopidy-http, a custom UI of mine, and Icecast in Docker. Everything works smoothly most of the time but after queuing a bunch of tracks eventually the queuing fails and I see this in the Mopidy logs:

ERROR 2020-04-19 23:32:30,442 [1:MainThread] mopidy.audio.gst,
GStreamer error: Could not connect to server

I tried launching with mopidy -vvvv and using the environment variable GST_DEBUG="3 mopidy -v" but neither of these is resulting in any more diagnostic information. Any idea how I can diagnose why GStreamer is sporadically failing?

WARNING  2020-04-20 00:44:13,153 [129:MainThread] mopidy.config
  Ignoring config section 'local' because no matching extension was found
WARNING  2020-04-20 00:44:13,153 [129:MainThread] mopidy.config
  Ignoring config section 'webhooks' because no matching extension was found
[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]
verbosity = 0
format = %(levelname)-8s %(asctime)s [%(process)d:%(threadName)s] %(name)s\n  %(message)s
color = true
config_file =

[audio]
mixer = none
mixer_volume = 
output = lamemp3enc ! shout2send async=false mount=mopidy ip=icecast port=8000 password=xxxx
buffer_time = 

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

[iris]
enabled = true
country = NZ
locale = en_NZ
spotify_authorization_url = https://jamesbarnsley.co.nz/iris/auth_spotify.php
lastfm_authorization_url = https://jamesbarnsley.co.nz/iris/auth_lastfm.php
genius_authorization_url = https://jamesbarnsley.co.nz/iris/auth_genius.php
data_dir = $XDG_DATA_DIR/iris

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

[http]
enabled = true
hostname = ::
port = 6680
zeroconf = Mopidy HTTP server on $hostname
allowed_origins = 
  xxx:3000
  xxx:3880
  xxx.net
  xxx.com
csrf_protection = true
default_app = mopidy

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

[softwaremixer]
enabled = true

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

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

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

Not heard of this before. Just queuing tracks doesn’t involve Gstreamer. You are setting GST_DEBUG to an odd value there, where did you get that from? If I had to guess, I’d say that “could not connect to server” was referring to the icecast server and wasn’t related to actually queuing tracks.

3

Just queuing tracks doesn’t involve Gstreamer

The tracks get queued, but when I see this error I also see totally glitched playback. The track will keep restarting playback every ~5 seconds and no sound ever gets output. It looks like Mopidy is panicking that it’s not actually able to output the stream and decides to just restart the track (over and over). I can upload a gif of Iris’ UI when this happens if you’re curious.

You are setting GST_DEBUG to an odd value there, where did you get that from?

https://docs.mopidy.com/en/latest/troubleshooting/#debugging-gstreamer

If I had to guess, I’d say that “could not connect to server” was referring to the icecast server and wasn’t related to actually queuing tracks.

I believe it’s caused by a sporadic communication failure between Mopidy and Icecast but I can’t imagine how that’s possible, since both services are docker containers in the same stack.

Mopidy could possibly handle this error case better and not glitch the playback, but also I think it’s not unreasonable that it spazes out and I should just fix the underlying issue with why Mopidy and Icecast occasionally fail to communicate.

4

Are you sure it’s not just the iris UI that is confused? I don’t think we ever restart the same track on failure, we should be moving to the next track in the tracklist in that situation.

Your gst debug env value does not match what is in the docs. You’ve added quotes.

It would be helpful if you could share your debug log.

5

Apologies, I was adopting it from the Docker config. It doesn’t have quotes in reality:

mopidy@2d7dead0a0aa:/$ env
...
GST_DEBUG=3 mopidy -v

Are you sure it’s not just the iris UI that is confused?

I’m definitely not sure what’s going on, but I’m sure this indicates more than Iris going crazy. The Icecast stream itself stops outputting audio (I am confirming by directly opening the stream in a browser window outside my app and outside Iris) and my app, which listens to Mopidy http events, stops receiving playback events. The tracklist never advances when in this state. At least, the websocket never sends an event saying otherwise.

6

Sure, I agree something in Mopidy has gone wrong. I’m just trying to separate the actual Mopidy behaviour from the multiple other pieces here. I think we need logs to make progress. If you have GST_DEBUG=3 you should have an enormous amount of gstreamer logging and there will hopefully be more info about icecast in there. Finding the relevant lines is a fun task. You can also go more verbose if you need (good luck!).

7

Yeah definitely need more logs. Sounds good, I’ll try GST_DEBUG=3 and see if that gives me more logs. I’ll also look into getting more verbose logging from Icecast (which is currently not returning any errors)

8

EDIT: My issue was resolved by downgrading to libshout 2.4.1!

I’m encountering similar errors. Here is the relevant bit obtained with running with GST_DEBUG=3 mopidy -v

DEBUG    [MainThread] mopidy.audio.gst Got ERROR bus message: error=GLib.Error('Could not connect to server', 'gst-resource-error-quark', 6) debug='gstshout2.c(620): gst_shout2send_connect (): /GstPlayBin:playbin0/GstPlaySink:playsink/GstBin:abin/GstBin:audio-sink/mopidy+audio+actor+_Outputs:mopidy+audio+actor+_outputs0/GstBin:bin0/GstShout2send:shout2send0:\nshout_open() failed: err=Please retry current operation.'

I’ve used others’ docker containers that did not exhibit this issue. However, I had other problems with them so am trying to create my own. I’ve not yet been able to narrow down the key differences that are leading to this error in my container but not others.

I’m interested in outputting to icecast and snapcast simultaneously. This is my config:

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

[logging]
verbosity = 0
format = %(levelname)-8s [%(threadName)s] %(name)s %(message)s
color = false
config_file =

[audio]
mixer = software
mixer_volume =
output = tee name=t ! queue ! audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapcast/snapfifo t. ! queue ! lamemp3enc bitrate=320 ! shout2send async=false mount=mopidy ip=icecast port=8000 password=hackme
buffer_time =

[moped]
enabled = true

[iris]
enabled = true
country = US
locale = en_US
spotify_authorization_url = https://jamesbarnsley.co.nz/iris/auth_spotify.php
lastfm_authorization_url = https://jamesbarnsley.co.nz/iris/auth_lastfm.php
genius_authorization_url = https://jamesbarnsley.co.nz/iris/auth_genius.php
data_dir = $XDG_DATA_DIR/iris

[file]
enabled = true
media_dirs =
  /home/mopidy/music|Music
excluded_file_extensions =
  .directory
  .html
  .jpeg
  .jpg
  .log
  .nfo
  .pdf
  .png
  .txt
  .zip
show_dotfiles = false
follow_symlinks = true
metadata_timeout = 1000

and output of mopidyctl deps:

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-112-generic-x86_64-with-glibc2.29
Python: CPython 3.8.2 from /usr/lib/python3.8
Mopidy: 3.0.1 from /usr/lib/python3/dist-packages
Mopidy-Iris: 3.51.0 from /usr/local/lib/python3.8/dist-packages
  Mopidy: 3.0.1 from /usr/lib/python3/dist-packages
  Pykka: 2.0.2 from /usr/lib/python3/dist-packages
  setuptools: 45.2.0 from /usr/lib/python3/dist-packages
GStreamer: 1.16.2.0 from /usr/lib/python3/dist-packages/gi
  Detailed information:
    Python wrapper: python-gi 3.36.0
    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 suspect the issue is related to the libshout version being used. See: https://jc-lan.org/2020/05/26/mopidy-fails-to-connect-to-icecast2-server-with-ubuntu-20-04/, and https://bugs.launchpad.net/mixxx/+bug/1833225. I will update if this is the case.