Snapcast: latency is forgotten after volume adjustment

[flowolf]

Thanks for this great project! I'm really enjoying it. Easy to setup and it works :-)

setup:

• server: raspberry Pi snapserver, also snapclient with wired speakers
• client: raspberry Pi zero W snapclient (with bluetooth speaker)

snapcast v0.15.0 (server and client)

The bluetooth speaker of the client has a delay of about 250 ms, which I set with the --latency flag.
The speakers seem in sync, which is expected.

issue:
After adjusting the snapclient volume on the client with the HomeAssistant integration (https://www.home-assistant.io/components/snapcast/), the --latency setting seems to be forgotten and the server and client run out of sync. The client lags again. Only restarting the snapclient sets the latency setting again.

[herrwusel]

Do you still see the latency log when you run the client in console? Whenever I read about a Pi zero W running simultaneously wifi and bluetooth I suspect the Pi itself to do something wrong - just guessing though!

[flowolf]

@herrwusel I actually never see the latency set correctly...
Just on initialization:
$ /usr/bin/snapclient --latency 250 --user snapclient:audio --soundcard 1 -e | grep -i latency 2019-09-16 11-03-22 [Info] Latency: 250 <---- this seems ok 2019-09-16 11-03-23 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 65, muted: 0 2019-09-16 11-03-29 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 48, muted: 0 2019-09-16 11-03-33 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 30, muted: 0 2019-09-16 11-03-38 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 78, muted: 0 2019-09-16 11-03-40 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 47, muted: 0 2019-09-16 11-03-40 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 26, muted: 0
I regulate the volume and it's adjusted, but latency seems to be set to zero.
Has the latency be updated with every volume adjustment?

[herrwusel]

Never used latency but I will try when getting home.
Did you try to set the volume with the snapcast android app (just to see if it is a general behaviour)?

EDIT: In the android app you can also set the latency.

[flowolf]

I tried setting the value with python-snapcast directly. It shows the same behavior.

>>> loop.run_until_complete(server.client_volume(client.identifier, {'percent': 22, 'muted': False}))
...
2019-09-16 12-40-23 [Info] ServerSettings - buffer: 1000, latency: 0, volume: 22, muted: 0

will set the volume.
but

>>> loop.run_until_complete(server.client_latency(client.identifier, 250))
...
2019-09-16 12-40-37 [Info] ServerSettings - buffer: 1000, latency: 250, volume: 22, muted: 0

will set the latency.
At that point the server knows about the latency of the client and it stays set after volume updates.

I'm not sure where the right spot would be to address this issue. On the one hand snapclient should know about latency and keep it set the way it was started with the user inputs. It should not be altered when an 'update volume' is received.
On the other hand it's nice if the server can configure latency later on.

So it might be necessary to configure latency in HomeAssistant, so the server knows about it.

[herrwusel]

I'm not sure where the right spot would be to address this issue.

Snapcast definitely shouldn't change the latency if not told otherwise. Else every other input needs to determine if it is the 'first' time of communication with snapcast.

[flowolf]

so is this a bug in python-snapcast or in snapcast?

[BarrettLowe]

Any follow up on this issue? I can confirm that it exists in the current master - ad83323

[BarrettLowe]

Also for reference, this also happens when switching streams. How about anyone else?

[badaix]

Didn't find the time to track it down yet, but it feels like it's not a snapcast issue. Snapdroid works well and also the webinterface doesn't change the latency.

[BarrettLowe]

So the more I poke around, the more I learn. From snapdroid if I mute then unmute, latency seems to be reset eventhough the log on the client has the correct latency. Setting latency in snapdroid again fixes the problem. Looks like volume adjustment in snapdroid is fine though. So maybe I need to open a different issue and we can close this one?

I only briefly looked at the client code last night. When getting unmuted (when I hear the problem), the client log output does report the correct latency. Not sure if this gives you any ideas or not. I'll look into this a little more but I've got a steep learning curve since I have no experience with this project yet. 😄

Should I make a new issue and let you close this one since it doesn't seem to be a volume problem?

[badaix]

Without checking the code, I would trust the log messages, but maybe it's overwritten somewhere, who knows...
Maybe it's because the server doesn't send audio to muted clients (it's a configuration parameter in snapserver.conf: [stream] send_to_muted = false.
And when unmuted, the client might take some seconds until he is fully resynced (although the resync should work instantly or at least much quicker in v0.19 compared to earlier releases). You can test this by changing send_to_muted to true.
Let me check this before you close the issue. I will try to reproduce it.

[badaix]

This should be fixed now in master: 827cfb7985e5c2e7e6d1725f3e33bbf81ac8ab9e
Can you please test it?
I was actually tricked by the log lines

2020-04-19 14-30-42.409 [Info] (onMessageReceived) ServerSettings - buffer: 1000, latency: 10, volume: 44, muted: 0

which are always reporting the configured latency, but actually they were not always correctly passed to the player.

[BarrettLowe]

Sure! I'll get to it tonight

[BarrettLowe]

My problem has been solved. Looks like this may close #588 also? I'm not the owner of either of these issues or I would close them myself :)

[BarrettLowe]

Next question is when will this go into the android app?

[badaix]

With the next release