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.
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– 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
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.
So I’ve eventually found a workaround for my use case for now that works on all the systems that I’ve tested so far. I have eventually fallen back to snapcast with a wavenc pipeline instead of icecast2:
output = tee name=t ! queue ! audioresample ! autoaudiosink t. ! queue ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo
That pipeline together with snapserver listening on the fifo for now allows me to walk around the issues with icecast2.
Note however that if I try to set up any other encoder than wavenc (either flacenc or vorbisenc) in that pipeline I fall back into the same issue, while wave pcm works both on Arch and Ubuntu 18.10.
I really start to believe that the event chain got broken somewhere from GStreamer 1.14 but I can’t say where unless I dig into the GStreamer side too.
Let me know in the meantime if I can provide you with logs for any other scenario.
Btw did you manage to reproduce the issue on your system? Which pipeline are you using?
Yep I reproduced it with Ubuntu 18.10 running in Virtualbox. I am still looking into the logs.
So, my working Ubuntu system uses avdec (from gstreamer1.0-libav) for decoding the mp3 whereas the broken Ubuntu system uses mpg123. I can fix the broken system by installing gstreamer1.0-libav; and break the working system by removing it.
mpg123 logs a couple of the following messages which might be relevant:
cannot decode yet, need more data -> no output buffer to push
Perhaps the manual seek operation puts enough data through the decoder that it can get going. Or maybe the seek has some other affect.
So then I tried to reproduce it with gst-launch:
gst-launch-1.0 playbin uri=file:///home/nick/Music/Architects/Daybreaker/The_Bitter_End.mp3 audio-sink="tee name=t ! queue ! fakesink sync=true t. ! queue ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme"
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Redistribute latency...
^Chandling interrupt.
Interrupt: Stopping pipeline ...
ERROR: pipeline doesn't want to preroll.
Setting pipeline to NULL ...
Freeing pipeline ...
So that didn’t work out. But removing the fakesink does and it plays just fine:
gst-launch-1.0 playbin uri=file:///home/nick/Music/Architects/Daybreaker/The_Bitter_End.mp3 audio-sink="tee name=t ! queue ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme"
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Redistribute latency...
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
^Chandling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:21.681471553
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...
So I hacked the fakesink out of Mopidy’s pipeline and that worked too. I don’t think we actually need the fakesink since we don’t (currently) support dynamic outputs. So that might be a reasonable work-around. But we still need to understand why that is. @adamcik, are you around?
EDIT:
And for completeness:
... audio-sink="tee name=t ! queue ! fakesink sync=true t. ! queue ! autoaudiosink"
... audio-sink="tee name=t ! queue ! fakesink sync=true t. ! queue ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme"
@kingosticks I can confirm that installing gst-libav on Arch or gstreamer1.0-libav on Ubuntu fixes the problem, thanks! Not only for mp3, I’ve tested it with ogg and flac as well and the problem is solved.
So is the issue with the presence of the fakesink that breaks the pipeline when encoding is involved, or with internal vs. external encoder that makes the pipeline out of sync? I’m not sure yet whether this could be a regression on GStreamer or it’s just the mopidy fakesink that broke the encoding on the latest version.
p.s. Interestingly, the only physical system I’ve tested where the encoding was always working was a Raspbian that already had gstreamer1.0-libav installed.
I’m still learning about Gstreamer but nothing I’ve seen would suggest there is anything wrong with the fakesink in our pipeline. To me it seems like a regression. My next step is to take the examples to the Gstreamer devs.
I have done a couple of tests with the simplest shout2cast pipeline I could come up with:
output = audioresample ! audioconvert ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme
Oddly, this pipeline works on all of my devices if I play local files, it breaks if I try to play a Spotify track. Some debug logs.
In this debug logs I have tried a couple of sequences:
mpc add spotify:track:<track_id> works in this particular case (not always though)DEBUG 2019-01-14 16:06:35,332 [2278:Dummy-15] spotify.session
Audio buffer stats requested, but no listener
Following up: I’ve tried that pipeline on all of the previously bugged systems after installing gstreamer1.0-libav.
Tested with local files, SoundCloud, TuneIn, SomaFM and Spotify.
It works well with all the types except Spotify tracks. When I try to play any Spotify track I encounter the same symptoms I experienced with GStreamer 1.14 without libav (playback stuck at 0:00), plus the Audio buffer stats requests, but no listener traces during the failed playback.
I’m not sure if it’s an issue with any additional encoding performed by libspotify, but it sounds to me like the GStreamer pipelines that involve encoding have become quite brittle/unstable after 1.14 (could it be related to the changes to the async logic?) and it’s probably worth a bit more investigation from the devs.
It seemed that it was the usage of avdec over mpg123 that helped. Spotify audio goes through a slightly different pipeline which doesn’t have a decoder since libspotify already gives us raw audio data. So it seems reasonable that it’d be different. I’ll try and reproduce this.
You can ignore those ‘audio buffer stats requested’ messages.
I reproduced this. Removing the fakesink also fixed it (using output = lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme).
And interestingly also fixed by changing to use queue2 instead of queue (see here).
EDIT: Not quite. appsrc (Spotify) playback is not reliable unless the fakesink is removed. Normal playback seems solid with just the queue2 change. I expect these are two different problems.
Hmm the pipeline you posted above doesn’t quite fix in on Spotify yet. Same if I try to replace queue with queue2 in the audio actor. By “removing the fakesink” do you mean removing the audioresample part from the GStreamer pipeline or removing it from the pipeline in the code?
I mean remove the fakesink element from mopidy.audio. Looks like that’s the way we need to go. Finding out why we need to go thay way is a bit academic but I will try.