Mopidy is not playing with icecast2

Here’s the Arch Linux debug log with output = autoaudiosink.

Everything works as expected without the GStreamer redirection to icecast.

However I’ve noticed a different sequence of state transitions:

Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_PLAYING new=GST_STATE_PAUSED pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING

EDIT:

On the old Ubuntu installation I still have three state transitions when I do mpc play, without the PAUSED->PLAYING->PAUSED->PLAYING apparent glitch that occurs with the newer GStreamer version. Debug logs with autoaudiosink on Ubuntu 16.04: https://pastebin.com/PdLJmzxJ

Traces:

Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING

EDIT 2:

The GST pipeline I have used for mopidy works flawlessly on the same machine if I test it through gst-launch (meaning that I can both hear the audio from the default sink and see the mountpoint on Icecast):

gst-launch-1.0 audiotestsrc ! tee name=t ! queue ! audioresample ! autoaudiosink t. ! queue ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme

I have another experiment if you are game:
The original test (autoaudiosink and shout2send) but with a local (mp3?) file. I.e is it specifically the buffering handling that’s going wrong when coupled with icecast?

Same behaviour when playing a local file through mopidy-file: it works on the newer installation with autoaudiosink, it breaks with the icecast pipeline, while it works on both cases on the older installation.

Debug logs on Arch with autoaudiosink (working)
Debug logs on Arch with the Icecast pipeline (not working)
Debug logs on Ubuntu 16.04 with the Icecast pipeline (working)

States sequence on Ubuntu with the Icecast pipeline:

Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING

States sequence on Arch with the Icecast pipeline:

Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING

And then it seems that, like in the other cases, the newer installation of mopidy isn’t able to receive the PAUSED/PLAYING GStreamer message.

I finally upgraded my system and setup icecast and I’m not sure I am seeing this with my local mp3 files. Playing from the stopped state seems to work fine, so does gapless switching from song to song. The only thing I am seeing is the known issue when manually skipping songs (described in our docs and here). Not sure what I am doing differently here.

  • Ubuntu 18.10
  • mopidy 2.2.2
  • icecast 2.4.3
  • GStreamer 1.14.4

https://pastebin.com/R8JPdpQR

We did once upon a time have an Arch specific bug that was related to the slightly different way they were compiling a system library. I hope it’s not that.

EDIT: Just making my way through all your logs and I see you used APC as your local test file too. I didn’t even open that log until now. This is getting weird…

@blacklight

Your log:

Just ends at

DEBUG 2019-01-03 20:33:35,417 [22147:MainThread] mopidy.audio.gst
Got TAG bus message: tags={‘album’: [u’Mer De Noms’], ‘track-number’: [4], ‘has-crc’: [False], ‘artist’: [u’A Perfect Circle’], ‘nominal-bitrate’: [192000], ‘datetime’: [u’1999’], ‘genre’: [u’Alternative Rock’], ‘title’: [u’Judith’], ‘container-format’: [u’ID3 tag’], ‘audio-codec’: [u’MPEG-1 Layer 3 (MP3)‘], ‘channel-mode’: [u’stereo’]}

Why is that? That’s pretty much exactly the point at which mine goes on to change READY->PAUSED and then PAUSED->PLAYING.

BLACKLIGHT
========
DEBUG    2019-01-03 20:33:35,300 [22147:MpdSession-15] mopidy.mpd.session
  Request from [[::ffff:127.0.0.1]:6600]: play
DEBUG    2019-01-03 20:33:35,318 [22147:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2019-01-03 20:33:35,318 [22147:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING

DEBUG    2019-01-03 20:33:35,338 [22147:Audio-2] mopidy.audio.gst
  Got source-setup signal: element=GstFileSrc
DEBUG    2019-01-03 20:33:35,340 [22147:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC

DEBUG    2019-01-03 20:33:35,389 [22147:MainThread] mopidy.audio.gst
  Got STREAM_START bus message
DEBUG    2019-01-03 20:33:35,389 [22147:MainThread] mopidy.audio.actor
  Audio event: stream_changed(uri='file:///mnt/hd/media/music/A%20Perfect%20Circle/Mer%20De%20Noms/04%20Judith.mp3')
DEBUG    2019-01-03 20:33:35,389 [22147:MainThread] mopidy.listener
  Sending stream_changed to AudioListener: {'uri': 'file:///mnt/hd/media/music/A%20Perfect%20Circle/Mer%20De%20Noms/04%20Judith.mp3'}
DEBUG    2019-01-03 20:33:35,389 [22147:Core-9] mopidy.core.playback
  Changing state: stopped -> playing
DEBUG    2019-01-03 20:33:35,389 [22147:Core-9] mopidy.core.playback
  Triggering playback state change event

DEBUG    2019-01-03 20:33:35,395 [22147:Dummy-16] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2019-01-03 20:33:35,395 [22147:Dummy-16] mopidy.audio.actor
  Audio event: position_changed(position=0)
DEBUG    2019-01-03 20:33:35,408 [22147:Dummy-16] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0}

DEBUG    2019-01-03 20:33:35,417 [22147:MainThread] mopidy.audio.gst
  Got TAG bus message:
  
<EOF> ?????

ME
===
DEBUG    2019-01-03 23:18:07,943 [19552:MpdSession-12] mopidy.mpd.session
  Request from [[::ffff:127.0.0.1]:6601]: play
DEBUG    2019-01-03 23:18:07,961 [19552:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2019-01-03 23:18:07,962 [19552:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING

DEBUG    2019-01-03 23:18:07,978 [19552:Audio-2] mopidy.audio.gst
  Got source-setup signal: element=GstFileSrc
DEBUG    2019-01-03 23:18:07,981 [19552:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC

DEBUG    2019-01-03 23:18:08,091 [19552:MainThread] mopidy.audio.gst
  Got STREAM_START bus message
DEBUG    2019-01-03 23:18:08,091 [19552:MainThread] mopidy.audio.actor
  Audio event: stream_changed(uri='file:///home/nick/Music/A%20Perfect%20Circle%20-%20Mer%20de%20Noms/04%20Judith.mp3')
DEBUG    2019-01-03 23:18:08,092 [19552:MainThread] mopidy.listener
  Sending stream_changed to AudioListener: {'uri': 'file:///home/nick/Music/A%20Perfect%20Circle%20-%20Mer%20de%20Noms/04%20Judith.mp3'}
DEBUG    2019-01-03 23:18:08,092 [19552:Core-7] mopidy.core.playback
  Changing state: stopped -> playing
DEBUG    2019-01-03 23:18:08,092 [19552:Core-7] mopidy.core.playback
  Triggering playback state change event

DEBUG    2019-01-03 23:18:08,103 [19552:Dummy-13] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2019-01-03 23:18:08,103 [19552:Dummy-13] mopidy.audio.actor
  Audio event: position_changed(position=0)
DEBUG    2019-01-03 23:18:08,103 [19552:Dummy-13] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0}

DEBUG    2019-01-03 23:18:08,112 [19552:MainThread] mopidy.audio.gst
  Got TAG bus message:

DEBUG    2019-01-03 23:18:08,115 [19552:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
DEBUG    2019-01-03 23:18:08,115 [19552:MainThread] mopidy.audio.gst
  Got ASYNC_DONE bus message.
DEBUG    2019-01-03 23:18:08,116 [19552:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
DEBUG    2019-01-03 23:18:08,116 [19552:MainThread] mopidy.audio.actor
  Audio event: state_changed(old_state=stopped, new_state=playing, target_state=None)

The logs stops on that line because nothing gets logged after that trace. After the mpc add+play sequence I see the track status switching to “playing” from any mpd client, but it stay stuck on 0:00, no audio comes from the sink and no mountpoint is created on icecast2. It seems that for some reason the event handler just misses the GST state transition messages and doesn’t go any further.

It’s quite strange that it works fine on Ubuntu 18.10 though - I’ll find some time to set up another VirtualBox tomorrow to test it. I’ve also done another test on a Raspbian Jessie installation and shout2send actually seems to work fine over there. But that might also be due to the fact that Jessie is still using GStreamer 1.10.4 and that shouldn’t include the change on the non-blocking I/O that has been introduced in 1.14. If I can manage to make it work on Ubuntu 18.10 with the same version of GStreamer the Arch-specific option might be a possibility at this point.

If it can help, I have generated more debug logs on both Arch and Ubuntu 16.04 with GST_DEBUG=5 to get more insights on what’s happening under the hood. On Arch GStreamer seems to be doing everything fine indeed (I can see the state transitioning to PAUSED and PLAYING), and I also see the queue being correctly populated, but it seems like for some reason mopidy’s event handler just misses the messages after some point. Do you have some reference of the Arch-specific bug you mentioned?

p.s. I remember btw that the icecast2 setup used to work well on these Arch boxes until some months ago. GStreamer 1.14 was rolled out to Arch around April/May, around the same time this issue was opened, that might explain the breakage too maybe? The original author of this post used Xubuntu 18.04 and seems to have the same symptoms I’m experiencing, although I can say it better once I test on Ubuntu 18.10.

p.p.s. Nice musical taste!

One difference so far between those two logs is that the Ubuntu one fails to open the Pulsesink and then falls back to ALSA. The Arch one opens and uses the Pulsesink. I guess having the tee is complicating things a bit.
There is also the difference of mad and mpg123 being used. This isn’t a straightforward comparison unfortunately.

I don’t think Mopidy is missing anything. I don’t see the icecast side of the tee being prerolled in the broken case.
I would say the next steps are:

  • Try an Ogg Vorbis pipeline
  • Reproduce with the simplest pipeline possible (can use GST_DEBUG_DUMP_DOT_DIR=. mopidy to get a full description).
  • Maybe try reproducing with a simple non-Mopidy testcase. I think @adamcik used to work like this for these problems.

I have just installed Ubuntu 18.10 on VirtualBox and I can replicate the exact same issue there as well: when adding and playing a track, either remote or local, the mopidy status changes to play but the playback remains stuck at 0:00 - no audio on the sink, no icecast2 mountpoint created.

Configuration:

  • Ubuntu Server 18.10
  • mopidy 2.1.0
  • icecast 2.4.3
  • GStreamer 1.14.4

Debug logs: https://pastebin.com/j0DvwcJz

Btw the issue occurs on Arch even if I disable Pulse and switch to plain ALSA. If the sound server or the lame encoder were the issue I’d have expected the pipeline not to work through gst-launch-1.0 either, but that’s not the case.

I have also tried a simpler pipeline without tee (just dumping to icecast2):

output = audioresample ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme

and this doesn’t work either: debug logs.

I can try and see what happens with an Ogg pipeline to understand whether it’s an issue with encoding or something else.

Thanks. Can you update Mopidy to 2.2.2. I’m not sure if anything changed in that area but lets have everything the same where we can.

vorbisenc pipelines seem to be affected by the same issue: debug logs. Pipeline I have used:

output = audioresample ! audioconvert ! vorbisenc ! oggmux ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme

I have also tried to use snapcast instead of icecast2 but it’s affected by the same issue:

output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo

I have update mopidy to 2.2.1 on Ubuntu 18.10 (that’s the latest version available on apt.mopidy.com) and that’s still affected by the issue: debug logs.

When I run mopidy with GST_DEBUG_DUMP_DOT_DIR and any shout2send pipeline no dot files are generated at all.

When I run mopidy with GST_DEBUG_DUMP_DOT_DIR and the autoaudiosink alone I get this graph instead.

Interestingly, when I do add+play and then do an mpc seek 1 to force the playback to proceed then the player seems to get “unstuck” and the playback starts correctly, just like @elle2 pointed out.

So I guess that both the users on the Reddit channel and all the users in this discussion are affected by the same bug: mopidy and GStreamer seem to get out of sync when a custom pipeline is specified and they need something like a seek command to get back in sync.

Debug log of the scenario with mpc seek
GStreamer graph

Do you have a pipeline other than one involving icecast that has this issue?

Edit: Sorry completely missed your snapcast example above.

Yes, as I mentioned the issue also occurs with a snapcast pipeline:

output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo
1 Like

– Correction:

The snapcast pipeline actually works fine (my mistake, I had the snapserver misconfigured).

Pipeline:

output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo

Debug logs

So I guess that the investigation narrows down either to lamemp3enc/vorbisenc (snapcast uses wavenc), icecast2 (but that code hasn’t been changed for a while from what I see), or to the GStreamer shout2send async I/O changes, since snapcast uses filesink instead of shout2send and that still works.

@kingosticks could you try and install a vanilla Ubuntu 18.10 on Virtualbox, just install mopidy and icecast2 through apt and try to replicate the scenario with shout2send? That was sufficient for me to replicate the issue.

Could we try replacing wavenc in the snapcast example with lamemp3enc or vorbisenc. I appreciate snapcast won’t like that but will it still work sufficiently to check those two elements?

I can try an install on Virtualbox but I did a full re-install when I upgraded my system so I am not sure it can be much more vanilla other than not using the develop version of Mopidy (no interesting changes there that I can see).

Interestingly, when I try this pipeline:

output = audioresample ! audioconvert ! lamemp3enc ! filesink location=/tmp/snapfifo

I experience the same issue that I experience with shout2send: playing status but stuck on 0:00. When I send mpc seek 1 snapcast obviously doesn’t work (it’s not compatible with mp3) but at least the mopidy playback starts, just like in the shout2send scenario. Could the issue be indeed related to changes in the GStreamer lame/ogg encoders?

Debug logs of the scenario above on Arch

–EDIT–

Just to validate that the issue is not with tee, I have tested this pipeline too:

output = tee name=t ! queue ! audioresample ! autoaudiosink t. ! queue ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo

and this also works as expected.

I’ve been digging into the GST_DEBUG logs some more and I’m just thinking out loud here. Might be a wild goose chase… I am still not sure if this is a shout2send or encoder issue. But I do think the pipeline is way too complicated and we need a simpler testcase.

It seems like in both cases everything except the sinks reaches PAUSED state as expected. Sinks can’t transition to PAUSED until the upstream pipeline has filled up and there’s a buffer queued ready and waiting on the input pad - AKA prerolling. When they get that buffer, they go PAUSED, the bin follows along with everything else. At which point everything can then quickly go PLAYING.

In the working Ubuntu case, autoaudiosink0 goes PAUSED, which seems to be enough to make everything else go PAUSED despite the fact shout2send0 didn’t post it’s notification (last state-change it posted was only to READY). It seems it did actually go PAUSED, it just didn’t tell anyone - I don’t know if this is a bug or not. Once the pipeline is all PAUSED everything can then go PLAYING (and this time shout2send0 even notifies us properly).

In the non-working Arch case, autoaudiosink0 goes PAUSED but then the bin doesn’t follow it this time. We get stuck instead. Maybe we are waiting for shout2send0 to send it’s notification? I guess that flushing (like what happens when you seek) would be equivalent to giving it a poke. Shout2send’s pre-rolling behaviour changed in 1.14 but I don’t know if it’s significant.

The simplest pipeline I have managed to put together to replicate the issue is the one only with one encoder and output to shout2send:

output = audioresample ! lamemp3enc ! shout2send mount=/mopidy.mp3 ip=127.0.0.1 port=8000 password=hackme

I have added some local changes to audio.actor.on_message so that it always traces the received state changes even when they’re not targeted to self._element and I have reconstructed the following sequence of status changes on Arch.

This is instead the sequence of state transitions I see on Ubuntu 16.04, with the same pipeline working.

I indeed see that the GstPlayBin goes from NULL to READY on Arch but it doesn’t move from there (even though the other elements in the pipeline go further) until I do a seek.

Debug logs on Ubuntu 18.10 with the same pipeline and also affected by the issue.