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.
This is getting frustrating. Seems that neither queue2 nor removing Mopidy’s fakesink help with Spotify (appsrc) playback when using the following pipeline:
output = tee name=t ! queue ! autoaudiosink t. ! queue ! lamemp3enc ! shout2send mount=mopidy ip=127.0.0.1 port=8000 password=hackme
The one thing that fixes that (and all other pipelines I’ve tried involving shout2send, even without using gstreamer1.0-libav) is to set async=false 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
The “async” property can be used to instruct the sink to never perform an ASYNC state change. This feature is mostly usable when dealing with non-synchronized streams or sparse streams.
When async is disabled, the sink will immediately go to PAUSED instead of waiting for a preroll buffer. This feature is useful if the sink does not synchronize against the clock or when it is dealing with sparse streams.
It doesn’t change the data flow, but it tells the pipeline to ignore this sink for preroll/state-change purposes. This means that the pipeline will preroll even if that sink never receives any data.
I do not understand if the above is a problem, sounds OK to me. I’m coming full circle and just saying the shout2send element is a bit crap.
I confirm that async=false fixes the shout2send pipelines on all of my bugged systems.
That explains what got broken after GStreamer 1.14:
shout2send now uses non-blocking I/O and has a configurable network operations timeout.
as I guess that async=false restores the old synchronous behaviour. However, that doesn’t yet explain why the issue occurs also when using encoders in the pipeline even without shout2send.
The async=false workaround serves my purpose for now but the more I investigate the more I feel like something stinks on the latest GStreamer.
I’m understanding it that async=false allows a sink to transition to PAUSED even though some upstream element didn’t provide the preroll buffer that’s normally required for this transition to occur. Once the sink goes PAUSED it can go PLAYING, then the pipeline goes PLAYING and the upstream element starts co-operating.
I’m not convinced this is related to changes in shout2send specifically. Testing some more older versions would help clarify this. Here is my survey of different pipelines which shows filesink and shout2send behave the same. Note these results probably don’t hold for Spotify playback (appsrc), that’s a whole different mess and it’s not what I am concentrating on here.
#Using gst-launch-1.0 playbin uri=https://archive.org/download/testmp3testfile/mpthreetest.mp3 audio-sink=
# Everything works with a single sink
"tee name=t ! queue ! lamemp3enc ! shout2send" YES
"tee name=t ! queue ! vorbisenc ! oggmux ! shout2send" YES
"tee name=t ! queue ! waveenc ! shout2send" YES
"tee name=t ! queue ! lamemp3enc ! filesink" YES
"tee name=t ! queue ! vorbisenc ! oggmux ! filesink" YES
"tee name=t ! queue ! waveenc ! filesink" YES
"tee name=t ! queue ! filesink" YES
"tee name=t ! queue ! autoaudiosink" YES
# Breaks when introduce another sink
"tee name=t ! queue ! lamemp3enc ! shout2send t. ! queue ! autoaudiosink" STUCK
"tee name=t ! queue ! vorbisenc ! oggmux ! shout2send t. ! queue ! autoaudiosink" STUCK
"tee name=t ! queue ! waveenc ! shout2send t. ! queue ! autoaudiosink" STUCK
# Concentrating on filesink since it doesn't *need* an encoder like shout2send
"tee name=t ! queue ! lamemp3enc ! filesink t. ! queue ! autoaudiosink" STUCK
"tee name=t ! queue ! vorbisenc ! oggmux ! filesink t. ! queue ! autoaudiosink" STUCK
"tee name=t ! queue ! waveenc ! filesink t. ! queue ! autoaudiosink" STUCK
# Removing the encoder fixes things
"tee name=t ! queue ! filesink t. ! queue ! autoaudiosink" YES
"tee name=t ! queue ! filesink t. ! queue ! fakesink" YES
# async=false fixes some things (same applies to shout2send)
"tee name=t ! queue ! lamemp3enc ! filesink async=false t. ! queue ! autoaudiosink" YES
"tee name=t ! queue ! vorbisenc ! oggmux ! filesink async=false t. ! queue ! autoaudiosink" YES
"tee name=t ! queue ! waveenc ! filesink async=false t. ! queue ! autoaudiosink" STUCK
# queue2 also fixes the same things (same applies to shout2send)
"tee name=t ! queue2 ! lamemp3enc ! filesink t. ! queue ! autoaudiosink" YES
"tee name=t ! queue2 ! vorbisenc ! oggmux ! filesink t. ! queue ! autoaudiosink" YES
"tee name=t ! queue2 ! waveenc ! filesink t. ! queue ! autoaudiosink" STUCK