Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Server continually sending data even when not playing #729

Closed
fatg3erman opened this issue Nov 24, 2020 · 11 comments
Closed

Server continually sending data even when not playing #729

fatg3erman opened this issue Nov 24, 2020 · 11 comments
Labels
bug next release fixed in develop branch and will be part of the next release

Comments

@fatg3erman
Copy link

fatg3erman commented Nov 24, 2020 •
edited
Loading

Describe the bug
Snapserver is sending audio to all connected clients even when nothing is playing. This means all clients are permanently using the sound card of the machine they are running on and no other application can play audio on them.

Steps to Reproduce

  1. Start snapserver and connect a client on another machine. I am using the ALSA loopback device to receive audio from Mopidy. Mopidy does not need to be running.
  2. I'm simply observing the activity lights on my ethernet switch. They all go crazy. Muting clients stops the activity on those ports, indicating it is definitely snapcast traffic.

Environment details

  • OS: Raspbian Buster
  • Snapcast version 0.22
  • Installed from package downloaded from here.

I don't know whether this is possible to fix - what's the difference between "nothing playing" and "a bit of silence in a track"? - but it's definitely undesirable behaviour. I have 3 clients connected by wifi and my router is getting hot!
@fatg3erman fatg3erman added the bug label Nov 24, 2020
@badaix
Copy link
Owner

badaix commented Nov 24, 2020

Your router is getting hot from three compressed audio streams?

The server is only sending audio when the source is active. When the source is idle, the client will not receive any audio and release the PCM device after 5s, as you can see in the client logs:

2020-11-24 21-54-33.773 [Info] (Connection) Resolving host IP for: 192.168.0.3
2020-11-24 21-54-33.774 [Info] (Connection) Connecting
2020-11-24 21-54-33.780 [Notice] (Connection) Connected to 192.168.0.3
2020-11-24 21-54-33.780 [Info] (Connection) My MAC: "00:21:6a:7d:74:fc", socket: 8
2020-11-24 21-54-33.861 [Debug] (Connection) outstanding async_write
2020-11-24 21-54-33.865 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 75, muted: 0
metadata:{"STREAM":"Meta"}
2020-11-24 21-54-33.865 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2020-11-24 21-54-33.865 [Info] (Player) Player name: alsa, device: hw:CARD=Intel,DEV=0, description: HDA Intel, CX20561 Analog
2020-11-24 21-54-33.865 [Info] (Player) Direct hardware device without any conversions, idx: 32, sharing mode: unspecified, parameters: <none>
2020-11-24 21-54-33.865 [Info] (Player) Mixer mode: software, parameters: <none>
2020-11-24 21-54-33.865 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2020-11-24 21-54-33.865 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2020-11-24 21-54-33.865 [Debug] (Alsa) PCM name: hw:CARD=Intel,DEV=0
2020-11-24 21-54-33.865 [Debug] (Alsa) PCM state: PREPARED
2020-11-24 21-54-33.866 [Debug] (Alsa) channels: 2
2020-11-24 21-54-33.866 [Debug] (Alsa) rate: 48000 bps
2020-11-24 21-54-33.866 [Debug] (Alsa) frames: 960
2020-11-24 21-54-33.866 [Debug] (Alsa) buffer time: 80000
2020-11-24 21-54-33.866 [Debug] (Alsa) period time: 20000
2020-11-24 21-54-33.866 [Debug] (Alsa) periods: 4
2020-11-24 21-54-33.866 [Debug] (Player) setVolume exp with base 10: 0.75 => 0.513713
2020-11-24 21-54-33.866 [Debug] (Alsa) Resizing buffer from 0 to 15360
2020-11-24 21-54-33.866 [Info] (Stream) no chunks available
2020-11-24 21-54-33.866 [Info] (Alsa) Failed to get chunk
2020-11-24 21-54-34.130 [Info] (Controller) diff to server [ms]: 5.95066e+09
2020-11-24 21-54-34.774 [Debug] (Stream) Silent frames: 437, frames: 960, age: -9.105
2020-11-24 21-54-34.794 [Debug] (Stats) Chunk: 0	0	0	0	1	60	0
2020-11-24 21-54-35.014 [Debug] (Stats) Chunk: 0	0	0	0	12	60	0
2020-11-24 21-54-36.014 [Debug] (Stats) Chunk: 0	0	0	0	58	60	0
2020-11-24 21-54-37.014 [Debug] (Stats) Chunk: 0	0	0	0	105	60	0
2020-11-24 21-54-38.014 [Debug] (Stats) Chunk: 0	0	0	0	146	60	0
2020-11-24 21-54-39.034 [Debug] (Stats) Chunk: 0	0	0	0	187	40	0
2020-11-24 21-54-40.034 [Debug] (Stats) Chunk: 0	0	0	0	231	40	0
2020-11-24 21-54-41.014 [Debug] (Stats) Chunk: 0	0	0	0	275	60	0
2020-11-24 21-54-42.014 [Debug] (Stats) Chunk: 0	0	0	0	314	60	0
2020-11-24 21-54-43.014 [Debug] (Stats) Chunk: 0	0	0	0	359	60	0
2020-11-24 21-54-44.034 [Debug] (Stats) Chunk: 0	0	0	0	397	40	0
2020-11-24 21-54-45.014 [Debug] (Stats) Chunk: 0	0	0	0	440	60	0
2020-11-24 21-54-46.014 [Debug] (Stats) Chunk: 0	0	0	0	479	60	0
2020-11-24 21-54-47.014 [Debug] (Stats) Chunk: 0	0	0	0	500	60	0
2020-11-24 21-54-48.014 [Debug] (Stats) Chunk: -1	0	0	0	500	60	0
2020-11-24 21-54-49.034 [Debug] (Stats) Chunk: 0	0	0	0	500	40	0
2020-11-24 21-54-50.014 [Debug] (Stats) Chunk: 0	0	0	0	500	60	0
2020-11-24 21-54-51.014 [Debug] (Stats) Chunk: 0	0	0	0	500	60	0
2020-11-24 21-54-52.014 [Debug] (Stats) Chunk: -1	0	0	0	500	60	0
2020-11-24 21-54-53.014 [Debug] (Stats) Chunk: 0	0	0	0	500	60	0

Pause pressed in MPD

2020-11-24 21-54-54.194 [Info] (Stream) Exception: 0
2020-11-24 21-54-54.194 [Info] (Alsa) Failed to get chunk
2020-11-24 21-54-54.294 [Debug] (Alsa) Waiting for chunk
....
2020-11-24 21-54-59.208 [Debug] (Alsa) Waiting for chunk
2020-11-24 21-54-59.208 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2020-11-24 21-54-59.308 [Debug] (Alsa) Waiting for chunk
2020-11-24 21-54-59.409 [Debug] (Alsa) Waiting for chunk
...

On the server:

Nov 24 21:54:53 raspberrypi snapserver[32557]: State changed: default, state: 2 => 1
Nov 24 21:54:53 raspberrypi snapserver[32557]: onStateChanged (default): 1
Nov 24 21:54:53 raspberrypi snapserver[32557]: State changed: Meta, state: 2 => 1

with 1 = ilde, 2 = playing

enum class ReaderState
{
    kUnknown = 0,
    kIdle = 1,
    kPlaying = 2,
    kDisabled = 3
};

So it rather seems that your stream source is continuously playing.

@fatg3erman
Copy link
Author

fatg3erman commented Nov 24, 2020 via email

@fatg3erman
Copy link
Author

To follow up, I tried using a pipe sink instead, and that behaves as you describe. So it seems this is only occurring with the alsa loopback sink.

Sadly the pipe sink does not work well with Mopidy. The alsa loopback works very well apart from this.

@badaix
Copy link
Owner

badaix commented Nov 24, 2020

yes, you're right. The Alsa stream plugin has a silence detection:

        if (std::memcmp(chunk_->payload, silent_chunk_.data(), silent_chunk_.size()) == 0)
        {
            silence_ += chunk_->duration<std::chrono::microseconds>();
            if (silence_ > 100ms)
            {
                setState(ReaderState::kIdle);
            }
        }

And this is working: after 100ms of silence, the stream state switches to "idle", but the silence is actually sent to the clients, which is not intended.

@badaix
Copy link
Owner

badaix commented Nov 25, 2020

fixed 4b7c313

@badaix badaix added the next release fixed in develop branch and will be part of the next release label Nov 25, 2020
@quantenschaum
Copy link

quantenschaum commented Nov 25, 2020 •
edited
Loading

I have the same/similar problem. I run snapclient together with mpd on several RaspberryPis. They share the soundcard (plughw), so only one of them can play at a time. And I wrote a little daemon that watches /proc/asound/card*/*p/sub*/status and turn the amp on/off when something is played. The snapserver is fed by mpd (running on Ubuntu) via a fifo (the standard setup).

My observation is, that since some version (I didn't trac down which) the client acquires the soundcard even when nothing is played back (empty playlist in mpd), which blocks mpd from playing and the amp is powered all the time.

The workaround currently is to start playback on the server for second, then stop it and the snapclients will free the soundcard.

@quantenschaum
Copy link

btw: What do the numbers in [Debug] (Stats) Chunk: 0 0 0 0 500 60 0 mean?

@quantenschaum
Copy link

I just encountered the described situation again. The process using the soundcard is snapclient, no playback is running on the server and the is no audible sound output, but the soundcard is blocked by snapclient.

for i in /proc/[0-9]*/fd/*; do echo ${i%/fd/*} $(readlink $i); done | grep /dev/snd
/proc/285 /dev/snd/pcmC0D0p

ps 285
  285 ?        S<sl  12:35 /usr/bin/snapclient -s plughw:CARD=sndrpihifiberry,DEV=0

Then I did systemctl restart mpd on the server side, the soundcard is released and in the client's logs appears

Nov 30 14:48:39 kitchen snapclient[285]: 2020-11-30 14-48-39.717 [Info] (Stream) Exception: 0
Nov 30 14:48:40 kitchen snapclient[285]: 2020-11-30 14-48-40.493 [Error] (Alsa) XRUN: Broken pipe
Nov 30 14:48:43 kitchen snapclient[285]: 2020-11-30 14-48-43.398 [Info] (Stream) Exception: 0
Nov 30 14:48:43 kitchen snapclient[285]: 2020-11-30 14-48-43.402 [Info] (Alsa) Failed to get chunk
Nov 30 14:48:48 kitchen snapclient[285]: 2020-11-30 14-48-48.421 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.

What does that tell us? Is mpd feeding silence or invalid data into the fifo or is snapserver sending something even though nothing is actually played?

@douardda
Copy link

douardda commented Dec 12, 2020 •
edited
Loading

FTR I have the same kind of setup, and the same problem.

In my case, I have a nas (debian+openmediavault) on which is my music collection as well as an mpd server feeding a local snapserver via the /tmp/snapfifo fifo.

On the client side I have orangepilite (armbian) driving a pcm5142 DAC and a small python daemon watching the /proc/asound/card*/*p/sub*/status to turn the power amp on or off (via a relay driven by a GPIO pin).

When I stop the music, after a few seconds, the alsa card is properly closed, as expected (then the power amp is shut down). But any now and them the alsa card is "woken up" for no apparent reasons (note that the owner PID in the status file of the alsa card is a thread of the snapclient process, I guess the playerThread from client/player/player.hpp)

I'll try to gather debug level logs and put them here ASAP.

I am using snapclient and snapserver 0.23 from develop_snapshot_armhf-99f76263d0edfd5cff327a0c4d711fb8ae321b3f.zip

@douardda
Copy link

Here are some logs

My daemon that indirectly shows when the alsa card is activated:

root@orangepilite:~# journalctl -u mpd-relay -f
-- Logs begin at Sat 2020-12-12 16:58:30 CET. --
Dec 12 17:11:06 orangepilite systemd[1]: Started MPD Relay.
Dec 12 17:11:06 orangepilite python[6701]: DEBUG:root:Register atexit callback
Dec 12 17:11:06 orangepilite python[6701]: DEBUG:root:Using ALSA card /proc/asound/card0/pcm0p/sub0
Dec 12 17:11:06 orangepilite python[6701]: DEBUG:root:Configure pin 19 as output
Dec 12 17:11:06 orangepilite python[6701]: power  OFF
Dec 12 17:20:45 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:20:45 orangepilite python[6701]: power  ON
Dec 12 17:20:56 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:20:56 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:20:57 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:20:57 orangepilite python[6701]: power  ON
Dec 12 17:21:58 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:21:58 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:21:59 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:21:59 orangepilite python[6701]: power  ON
Dec 12 17:22:01 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:22:01 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:22:04 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:22:04 orangepilite python[6701]: power  ON
Dec 12 17:22:30 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:22:30 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:22:30 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:22:30 orangepilite python[6701]: power  ON
Dec 12 17:23:01 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:23:01 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:23:02 orangepilite python[6701]: DEBUG:root:new state is True
Dec 12 17:23:02 orangepilite python[6701]: power  ON
Dec 12 17:27:10 orangepilite python[6701]: DEBUG:root:new state is False
Dec 12 17:27:10 orangepilite python[6701]: Will power off in 30 s.
Dec 12 17:27:40 orangepilite python[6701]: power  OFF

The logs of snapclient:

snapclient.txt

You can see that when the daemon detects activity on the alsa card, at timestamp 17:20:45, the snapclient logs show:

2020-12-12 17-20-44.972 [Debug] (Alsa) Waiting for chunk
2020-12-12 17-20-45.072 [Debug] (Alsa) Waiting for chunk
2020-12-12 17-20-45.098 [Info] (Alsa) PCM name: default:CARD=I2Smaster, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
2020-12-12 17-20-45.098 [Debug] (Alsa) Failed to start PCM: Broken pipe
2020-12-12 17-20-45.978 [Debug] (Stream) Silent frames: 769, frames: 960, age: -16.028
2020-12-12 17-20-45.998 [Debug] (Stats) Chunk: -1       -1      -1      -1      1       60      0
2020-12-12 17-20-46.018 [Debug] (Stats) Chunk: 0        0       0       0       2       60      0
2020-12-12 17-20-47.018 [Debug] (Stats) Chunk: -2       -2      -1      -1      52      60      0

Note that in this session, I've hit "play" the "pause" on mpd at timestamp 17:27:xx (to force snapclient to close the alsa card), as can be seen in the logs of my custom daemon.

The logs of snapserver shows nothing special at that timestamp (not in debug mode however).

@badaix badaix mentioned this issue Dec 12, 2020
Closed
@badaix
Copy link
Owner

badaix commented Dec 12, 2020

@douardda @quantenschaum this is a different issue (that I don't fully understand yet, it seems like the device is blocked/released when playing/paused in @douardda logs). Please stop posting here, I've opened issue #741 for you. The original issue is about the server sending silence when the (alsa) audio source becomes idle, and this is fixed.

@badaix badaix closed this as completed Jan 10, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug next release fixed in develop branch and will be part of the next release
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@fatg3erman @douardda @quantenschaum @badaix