Closed kerta1n closed 7 months ago
I think the audio output from librespot is taken from stdout and it seems that librespot outputs other data as well to stdout, like a log line, which would cause exactly what you have.
Sounds good. Is there any way to change librespot to output to a Pipe instead of STDOUT? And if so, does this mean that I need to find a Librespot container that does so? Or is there any other way I should go about fixing this
Are you running the latest version of librespot. If so, this sounds like a bug to be fixed in librespot and should be reported to them.
Yeah, I think 0.4.1 from my modified image, but that also seems to be the default version in the image from djmaze. I'll gather more info later, on the road for another few hours
Don't know if this will work, but you could try to start librespot in a terminal with the --backend pipe
option and pipe the output to strings
. If there are debug logs written to stdout, it should show up in your terminal:
librespot --backend pipe|strings
The headline of this issue describes the problem of my snapcast installation at it's best. But I don't think, it's a snapclient problem. Stop playing music and to start playing noise until I stop playing on spotify occurs on several clients at the same time. After restart playing on spotify, it's playing music again. The problem occurs randomly. It's not predictable.
The attached file shows such an event. While playing music the state changes from 'playing' to 'idle' (timestamp: Oct 31 13:48:49) and back to 'playing' again (timestamp: Oct 31 13:48:50). After changing back to state 'playing' just noise is played until stopping the playing (timestamp: Oct 31 13:49:05).
I'm now using the newest version of snapcast (0.27.0 - debian bookworm testing). But this problem has happened since using 0.24.0).
But I don't think, it's a snapclient problem
Great, then you are on the same page as everyone else. We are saying the problem might be back on the snapserver, in librespot's --backend pipe
implementation. If you read the post before yours you'll see an experiment you could try to help narrow down the issue.
Is there any way to change librespot to output to a Pipe instead of STDOUT
You can modify the code in snapcast where librespot is launched and use
--backend pipe --device your_pipe_name_here
Hi,
If I can help : I'm also facing this issue.
Very annoying and scary because
It's quite easy to reproduce, I just have to play spotify (spotify -> librespot -> snapserver -> snapclient -> etc), then change the currently played track, OR move to a different time in the track. Doing this a tens times produces the bug.
When this occurs, I can see the two log lines :
This stops when I manually PAUSE the track with spotify, then RUN it again.
As suggested, I tried to change the librespot backend to pipe (¶ms=--backend%20pipe), and I still see the bug occur.
I also ran librespot alone with backend to pipe, not revelant since librespot detects that there is not audio sink then stops.
As suggested, I tried to change the librespot backend to pipe (¶ms=--backend%20pipe), and I still see the bug occur.
My suggestion involved more than that. Your change doesn't do anything.
As suggested, I tried to change the librespot backend to pipe (¶ms=--backend%20pipe), and I still see the bug occur.
My suggestion involved more than that. Your change doesn't do anything.
Yes that's something I understood after I posted ;-) See my last line
As suggested, I tried to change the librespot backend to pipe (¶ms=--backend%20pipe), and I still see the bug occur.
My suggestion involved more than that. Your change doesn't do anything.
Yes that's something I understood after I posted ;-) See my last line
I don't understand. There's still nothing in your post where you did what I suggested.
Running librespot standalone is a good idea. Pipe the audio to VLC, or something, and try to reproduce with your recipe.
Do you have to do it exactly 10 times. Or did you mean 'up to 10 times'? What if you let two tracks play through and then switch between the same two tracks many times I.e. does it have to be different tracks to cause the problem?
I did the test you proposed (btw not easy to find the good vlc option set to read from stdout at correct rate)
librespot -n "Librespot Speaker" --backend pipe | tee /tmp/file | cvlc -vvv --novideo -A alsa --demux=rawaud -
I did not see any issue after I ran and ran again my recipe. Sees there is nothing STDOUTed from librespot except the audio.
Could a log be emited by snapserver ?
Do you have to do it exactly 10 times. Or did you mean 'up to 10 times'? What if you let two tracks play through and then switch between the same two tracks many times I.e. does it have to be different tracks to cause the problem?
I meant 'up to 10' yes, sometimes the first jump in one and only one track is enough to produce the bug. I'm quite sure it does not depend on what track is currenty played, or how many tracks have been played before.
I'm not sure if it's the same problem. But I also had these problems from time to time. What helped me was the following patch. Never had any problems since then:
diff --git a/src/main.rs b/src/main.rs
index 11574d9..f7f4430 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -65,7 +65,7 @@ fn setup_logging(quiet: bool, verbose: bool) {
}
Err(_) => {
if verbose {
- builder.parse_filters("libmdns=info,librespot=trace");
+ builder.parse_filters("libmdns=info,librespot=info");
} else if quiet {
builder.parse_filters("libmdns=warn,librespot=warn");
} else {
I'm not sure if it's the same problem. But I also had these problems from time to time. What helped me was the following patch. Never had any problems since then:
diff --git a/src/main.rs b/src/main.rs index 11574d9..f7f4430 100644 --- a/src/main.rs +++ b/src/main.rs @@ -65,7 +65,7 @@ fn setup_logging(quiet: bool, verbose: bool) { } Err(_) => { if verbose { - builder.parse_filters("libmdns=info,librespot=trace"); + builder.parse_filters("libmdns=info,librespot=info"); } else if quiet { builder.parse_filters("libmdns=warn,librespot=warn"); } else {
It's a patch regarding librespot, I guess. I think reducing the loglevel in the snapserver call to librespot or deactivating the logging of librespot can achieve the same ...
Since the problem mentioned in the title occures to often, I changed my setup. Snapclient and snapserver were running on the same raspberry pi (3). At the same time a kodi was running on the pi. The pi was connected to the network via WiFi. A few days after my post above I changed the setup. I choose a dedicated pi4 as home for the snapserver, connected to the network over LAN. On the via WiFi connected pi only the snapclient is startetd. But beside the snapclient kodi is still running.
After changing the setup, the problem hasn't occured yet.
The solution for the problem in my case seem to be, to run the snapserver and snapclient on different devices and to run the snapserver on a device connected to the network via LAN.
I'm not sure if it's the same problem. But I also had these problems from time to time. What helped me was the following patch. Never had any problems since then:
diff --git a/src/main.rs b/src/main.rs index 11574d9..f7f4430 100644 --- a/src/main.rs +++ b/src/main.rs @@ -65,7 +65,7 @@ fn setup_logging(quiet: bool, verbose: bool) { } Err(_) => { if verbose { - builder.parse_filters("libmdns=info,librespot=trace"); + builder.parse_filters("libmdns=info,librespot=info"); } else if quiet { builder.parse_filters("libmdns=warn,librespot=warn"); } else {
It's a patch regarding librespot, I guess. I think reducing the loglevel in the snapserver call to librespot or deactivating the logging of librespot can achieve the same ...
Yes, librespot has a "quiet" logging mode switch, although I don't know if that then breaks the metadata support.
Librespot is configured to log everything to stderr so it seems unlikely that changing the logging verbosity would help but worth a try.
Thanks @rage2dev, however since guys at librespot confirmed (as well as a test I did) that nothing is emited on STDOUT, I doubt that adjusting the loglevel would fix my point.
@schniefus, interesting point you mention : the bug could be related to network performances. (I already have snapserver and snapclient on different pi, but everything uses wifi)
The title is pure gold.
I have been living with these random blasts of sound for quite some time. They don't occur as often since I usually play background music, but the issue seems to occur sometimes when I play media, skip to the next track or just move through the current track, though as I said, it doesn't happen every time.
I have 3 snapclients (2x rpi wireless, 1x desktop wired) The snapserver is on Home Assistant, which is also wired, so I doubt these issues are related to network performance.
Did anyone else try custom compiling librespot with the trace->info change? Is that the only lead for now?
I meant 'up to 10' yes, sometimes the first jump in one and only one track is enough to produce the bug. I'm quite sure it does not depend on what track is currenty played, or how many tracks have been played before.
Where I was going with this, is to try and determine if is's related to snapcast trying to use data that librespot hasn't provided yet (because it's still loading it). Normally librespot caches audio data, so the idea was if you let a few songs play through normally you could be sure all the data is cached and readily available. Then do your recipe of skipping between only those same few tracks and/or skipping within those tracks and see if you can trigger the issue. My guess is you won't be able to.
I started to dig the code and TRACE logs. I think I understand we are facing a bug related to the way the LibrespotStream object goes back from pause.
snapserver detects an actual librespot pause when this latter stops emitting samples on it's stdout. (When we switch between tracks or inside a track, and librespot does not have enough samples quick enough, it self goes to pause, then back to running a few ms after)
I think that when librespot goes back to running and starts emiting samples again, something weird happens somewhere in the AsioStream class that make it play garbage.
note: A better connection could avoid librespot going to pause, thus hide the issue.
Same issue. It seems to hit me on the first track after the system has been idle for an extended period of time like overnight.
Environment details
This same problem has been showing up with varying frequency on both of my setups (for quite some time, with different versions of snapcast and librespot).
I modified snapcast to also tee the stdout from librespot to a file. Importing this file into Audacity shows no problems with the stream after this bug has been triggered.
While this noise is playing it's possible to reduce the volume in Spotify/librespot to around 10%, and the music comes back. Looking at the raw audio file with a hex editor shows that this volume level corresponds to one byte being 00/FF for all (16-bit) samples, while the full range is roughly utilised of the other byte. So I guess this suggests that the problem is with the byte order getting mixed up somehow.
Adding more debug logging to posix_stream.cpp, I noticed that there often are an uneven number of bytes read so far for the current chunk when librespot stops emitting data (for whatever reason – but mostly after skips/seeks with cache disabled). And this is when the problem occurs.
If I add this line to the top of the code block handling the no data from read() case the problem appears to get a lot more difficult to reproduce:
len -= len % 2;
If I'm onto something here, similar adjustment might also be needed when resuming from playing silence. (And 4 would maybe be a more correct number if we also have a bug where the stereo channels gets swapped.)
diff --git a/playback/src/audio_backend/pipe.rs b/playback/src/audio_backend/pipe.rs
index e0e8a77..0a0d152 100644
--- a/playback/src/audio_backend/pipe.rs
+++ b/playback/src/audio_backend/pipe.rs
@@ -94,12 +94,17 @@ impl Sink for StdoutSink {
impl SinkAsBytes for StdoutSink {
fn write_bytes(&mut self, data: &[u8]) -> SinkResult<()> {
- self.output
+ let out = self.output
.as_deref_mut()
- .ok_or(StdoutError::NoOutput)?
- .write_all(data)
+ .ok_or(StdoutError::NoOutput)?;
+
+
+ out.write_all(data)
.map_err(StdoutError::OnWrite)?;
+ out.flush()
+ .map_err(StdoutError::FlushFailure)?;
+
Ok(())
}
}
After applying this patch to librespot I have not been able to reproduce this bug. It appears that Stdout in Rust's std::io is line buffered internally, even if stdout itself is set to be unbuffered or fully-buffered. This is obviously not great in our use case, as it at a minimum introduces unnecessary latency and jitter.
I don't know how librespot behaves if asked to use a named pipe instead of outputting to stdout. If it avoids this buffering I guess it can be an option to update snapcast to use pipes instead, to get around this problem also for unpatched versions of librespot.
Snapcast should maybe also be updated to better handle cases where "silence is detected" when the stream is in the middle of a sample, if for no other reason than as a defensive programming measure. Although I'm not sure what would be the best way to go about doing this.
After applying this patch to librespot I have not been able to reproduce this bug.
It now reappeared when librespot must have ran out of data in the middle of a song (?). Still haven't been able to trigger it from skips and seeks.
So unfortunate but I have the same problem.
diff --git a/playback/src/audio_backend/pipe.rs b/playback/src/audio_backend/pipe.rs index e0e8a77..0a0d152 100644 --- a/playback/src/audio_backend/pipe.rs +++ b/playback/src/audio_backend/pipe.rs @@ -94,12 +94,17 @@ impl Sink for StdoutSink { impl SinkAsBytes for StdoutSink { fn write_bytes(&mut self, data: &[u8]) -> SinkResult<()> { - self.output + let out = self.output .as_deref_mut() - .ok_or(StdoutError::NoOutput)? - .write_all(data) + .ok_or(StdoutError::NoOutput)?; + + + out.write_all(data) .map_err(StdoutError::OnWrite)?; + out.flush() + .map_err(StdoutError::FlushFailure)?; + Ok(()) } }
Confirming this patch has worked for me to stop random noise on track skip
Oddly, ever since this issue was opened, I haven't had this occur more than 2-3 times. Whereas it happened regularly during 2023.
On the other hand, completely irrelevant to the topic, I wish we just had a decent replacement for Spotify. All the issues I'm having with home music, Spotify seems to be the culprit behind micro changes in their API, which keep breaking things. Yes, I am aware of MPD and local audio files, but it's the recommendation algorithm I'm talking about...
diff --git a/playback/src/audio_backend/pipe.rs b/playback/src/audio_backend/pipe.rs index e0e8a77..0a0d152 100644 --- a/playback/src/audio_backend/pipe.rs +++ b/playback/src/audio_backend/pipe.rs @@ -94,12 +94,17 @@ impl Sink for StdoutSink { impl SinkAsBytes for StdoutSink { fn write_bytes(&mut self, data: &[u8]) -> SinkResult<()> { - self.output + let out = self.output .as_deref_mut() - .ok_or(StdoutError::NoOutput)? - .write_all(data) + .ok_or(StdoutError::NoOutput)?; + + + out.write_all(data) .map_err(StdoutError::OnWrite)?; + out.flush() + .map_err(StdoutError::FlushFailure)?; + Ok(()) } }
After applying this patch to librespot I have not been able to reproduce this bug. It appears that Stdout in Rust's std::io is line buffered internally, even if stdout itself is set to be unbuffered or fully-buffered. This is obviously not great in our use case, as it at a minimum introduces unnecessary latency and jitter.
I don't know how librespot behaves if asked to use a named pipe instead of outputting to stdout. If it avoids this buffering I guess it can be an option to update snapcast to use pipes instead, to get around this problem also for unpatched versions of librespot.
Snapcast should maybe also be updated to better handle cases where "silence is detected" when the stream is in the middle of a sample, if for no other reason than as a defensive programming measure. Although I'm not sure what would be the best way to go about doing this.
Can you please submit a PR to librespot? I can't think of an application where line buffered output is useful so seems reasonable to fix what appears to be a bug.
Can you please submit a PR to librespot? I can't think of an application where line buffered output is useful so seems reasonable to fix what appears to be a bug.
Yes, I will take a look at it and submit a PR. I assume this isn't a problem when librespot is told to output to a named pipe instead of stdout, but that this write_bytes function is used for both. This new flush call would be redundant in that case, so a little more code might be needed to keep things performant.
I guess snapserver could be made more robust by managing a byte counter for the received stream, and then discard 1-3 bytes if the stream isn't aligned on a sample boundary when starting a new chunk. Is this something that could be wanted? Should I try to write some code also for this, test it and submit a PR?
The latest release of librespot (v0.4.2) was released one and a half years ago. I don't know how far away v0.5.0 is, but I suspect there will still be some time before a release is made where this bug has been patched.
Any updates?
Guys,
Does someone know why the PosixStream
re-implements the do_read()
method ?
(already implemented by the AsioStream
class (it's parent class))
The code in PosixStream
is not very graceful, and seems to use the boost:asyncio:read function the bad way.
To answer myself my above question, I just removed this method PosixStream:do_read
and let AsioStream:do_read
do the job.
-> Works like a charm !! And I'm not able to reproduce the bug
@cdtx Interesting finding!
I don't really remember why I've introduced the PosixStream class as a sandwich layer between the AsioStream and a bunch of other streams (File, Librespot, Process, ...). Before this commit 6d7e25e9af8720743d4b197e41d271b169be3e29 all of these streams were inheriting from the AsioStream. The PosixStream only introduces the dryout_ms
timer, which could also be implemented in the AsioStream itself.
I have to carefully read and compare the code, maybe I will remember the reason for the PosixStream, but it looks redundant. Also reading the stream with the asio library instead of using the the raw file descriptor makes more sense to me. Not sure what you mean with "not very graceful", but the PosixStream should read only whole PCM frames, and should not drop single bytes. If there is a bug in some buffer-under-run corner case, all Stream implementations would benefit from a single robust reader implementation.
My memories are slowly coming back: the async_read
will call the read callback until the requested amount of data is read or it is canceled. To work around this, the PosixStream does a read
on the file descriptor, which will return < 0
, if there is no data available. So it will return immediately, and Snapcast can properly handle the situation, and change the stream state to idle or continue sending silence to the client. Using asio async_read
, the server will simply stop sending data to the client.
Then the client has to deal with an interrupted stream, and continue playing the stream in a synced manner as soon as the new data is received. Issue #205 was dealing with this: a few years ago the Snapcast client needed a few seconds to get in sync again and librespot was introducing pauses between songs, causing an interrupted stream. For this the dryout_ms
parameter has been introduced: when there is no data to be read from the stream, silence will be sent for the duration of this timeout.
Both issues have meanwhile been resolved: Librespot is playing continuously and the Snapclient plays instantly in sync.
I'm currently removing the PosixStream
and test if the dryout_ms
is really no longer needed.
WoW, glad to read this ! Thank you
Guys,
Does someone know why the
PosixStream
re-implements thedo_read()
method ? (already implemented by theAsioStream
class (it's parent class))The code in
PosixStream
is not very graceful, and seems to use the boost:asyncio:read function the bad way.To answer myself my above question, I just removed this method
PosixStream:do_read
and letAsioStream:do_read
do the job.-> Works like a charm !! And I'm not able to reproduce the bug
This worked for me also. I have been having the problem for a few months. Tried reverting to a older setup I had and it did not fix the problem. It is definitely on the Spotify side. I did this, and now I have snapcast back! I am not sure if this is the best way to do it, but it works.
Removed 'void PosixStream::do_read()' from 'snapcast/server/streamreader/posix_stream.cpp'
Removed 'void do_read() override;' from 'snapcast/server/streamreader/posix_stream.hpp'
Commented out 'LOG(ERROR, "AsioStream") << "Error reading message: " << ec.message() << ", length: " << length << "\n";' from 'snapcast/server/streamreader/asio_stream.hpp' (This was causing the log file to fill up and take up all space on the device)
is this fix going to be implemented? having this issue and do not have the knowledge to build/compile from scratch
I have a fix available which I haven't pushed yet. Will push it very soon and build Debian packages.
thanks! Glad something is ready, was super shocked when i went to play something today and thought the antichrist was coming out of my speakers.
The branch is here: https://github.com/badaix/snapcast/tree/1170-refactor-streamreader
Debian packages of the v0.28.0-beta.1 are here: https://github.com/badaix/snapcast/actions/runs/8271126028
I didn't test the packages yet, just a locally compiled binary.
This is a draft of the changelog:
running in docker here. Anyone successfully built for Alpine?
I've got a Dockerfile that builds for Alpine: https://github.com/mill1000/docker-snapcast-server/blob/main/Dockerfile
I used @mill1000's dockerfile to compile the debug branch and so far it seems to work! I had a very severe case of /dev/random-disco going on that would start right away and switching to this newly-built image, none of this has happened for an hour or so so far. Thank you all!
Thank you so much badaix! Version 0.28.0-beta.1 lowered the CPU usage compared to the fix I did with the rough removal of PosixStream do_read(). Huge positive with my rhasspy/snapcast satellites.
I used @mill1000's dockerfile to compile the debug branch and so far it seems to work! I had a very severe case of /dev/random-disco going on that would start right away and switching to this newly-built image, none of this has happened for an hour or so so far. Thank you all!
any chance you can share your snapserver apk? I tried to get this working via docker on unraid and was having sha issues on the snapcast.patch step of the build
I used @mill1000's dockerfile to compile the debug branch and so far it seems to work! I had a very severe case of /dev/random-disco going on that would start right away and switching to this newly-built image, none of this has happened for an hour or so so far. Thank you all!
any chance you can share your snapserver apk? I tried to get this working via docker on unraid and was having sha issues on the snapcast.patch step of the build
That patch is a hack for #891. You can remove it if it gives you grief.
I used @mill1000's dockerfile to compile the debug branch and so far it seems to work! I had a very severe case of /dev/random-disco going on that would start right away and switching to this newly-built image, none of this has happened for an hour or so so far. Thank you all!
any chance you can share your snapserver apk? I tried to get this working via docker on unraid and was having sha issues on the snapcast.patch step of the build
That patch is a hack for #891. You can remove it if it gives you grief.
now I get stuck here:
`CMake Warning: Ignoring extra path from command line:
".."
CMake Error: The source directory "/snapcast" does not appear to contain CMakeLists.txt. Specify --help for usage, or press the help button on the CMake GUI.`
EDIT: Got this working by building directly using the github URL instead of cloning the repo and building from there.
If you're talking about my repo its probably because it has submodules and they need to be initialized.
git submodule update --init --recursive
Great that it's fixed. I am wondering what will happen now instead of the random noise? Would there be something like a silence, or does it playback like usual?
Describe the bug On occasion, all Snapclients's FIFO pipe breaks and it sounds like static at max volume.
Steps to Reproduce
Environment details
docker compose plugin
, BOTH snapclient and snapserver dockerfiles were updated and built with Snapcast 0.27.0, unlike what djmaze' repo reflectslog from Snapserver:
log from a snapclient: