Snapcast: Snapclient blocks audio device when idle

[badaix]

@quantenschaum wrote

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.

[badaix]

@quantenschaum wrote

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?

[badaix]

@douardda wrote

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

[badaix]

@douardda wrote

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).

[douardda]

Thanks for creating this issue, sorry for mixing unrelated problems.

During last "active idle" session I noticed a pretty active TCP connection (using tcpdump), which makes sense according to the logs on the client side (if I understand them correctly). Once again, nothing visible in the logs of the server, but it looks to me the problem is server side rather than client side. I'll try to get more logs on the server, see if something is visibly wrong there.

David

[quantenschaum]

Or is this more an mpd issue? Maybe mpd is sending data to the pipe while stopped? Let's test if this occurs when mpd is not running (no process piping data into the server input pipe).

[douardda]

I'll give a try without mpd running, but when mpd starts or stops sending a stream, snapserver logs shows this by:

2020-12-13 19-09-21.369 [Info] (PcmStream) State changed: default, state: 2 => 1
2020-12-13 19-09-21.369 [Info] (Server) onStateChanged (default): 1

Which I don't see when snapserver starts sending data to the client for no apparent reason.

Anyway I've stopped mpd, let's see if it fails again...

[douardda]

I does not happen when mpd is not running. I've tried to strace mpd but nothing obvious stoke me.

Meanwhile, I've upgraded the odroid on which mpd and snapserver are running from stretch to buster, so mpd got upgraded from 0.19.21 to 0.21.5, will see if it changes something.

[douardda]

The issue just happened again, so no, not fixed by updated system and mpd...

[quantenschaum]

for the record: I'am using Music Player Daemon 0.21.20 on Ubuntu 20.04.

But did it happen again with mpd not running?

[badaix]

Still cannot reproduce it.

1. Start Snapclient (using default alsa device which is PulseAudio under the hood), while MPD is running (connected via /tmp/snapfifo pipe, playing web radio)

2021-01-02 22-03-00.282 [Info] (Connection) Resolving host IP for: 192.168.0.3
2021-01-02 22-03-00.282 [Info] (Connection) Connecting
2021-01-02 22-03-00.286 [Notice] (Connection) Connected to 192.168.0.3
2021-01-02 22-03-00.286 [Info] (Connection) My MAC: "5c:3a:45:56:e2:b7", socket: 8
2021-01-02 22-03-00.344 [Debug] (Connection) outstanding async_write
2021-01-02 22-03-00.348 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 80, muted: 0
metadata:{"STREAM":"default"}
2021-01-02 22-03-00.348 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2021-01-02 22-03-00.348 [Info] (Player) Player name: alsa, device: default, description: Playback/recording through the PulseAudio sound server, idx: 0, sharing mode: unspecified, parameters: <none>
2021-01-02 22-03-00.348 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-02 22-03-00.348 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2021-01-02 22-03-00.348 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-02 22-03-00.421 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
2021-01-02 22-03-00.422 [Debug] (Player) setVolume exp with base 10: 0.8 => 0.589953
2021-01-02 22-03-00.422 [Debug] (Alsa) Resizing buffer from 0 to 30716
2021-01-02 22-03-00.422 [Info] (Stream) no chunks available
2021-01-02 22-03-00.422 [Info] (Alsa) Failed to get chunk
2021-01-02 22-03-01.111 [Debug] (Stream) Silent frames: 1123, frames: 1453, age: -23.413
2021-01-02 22-03-01.141 [Debug] (Stats) Chunk: 0    0   0   0   1   203 0
2021-01-02 22-03-01.275 [Info] (Controller) diff to server [ms]: 2.47846e+09
2021-01-02 22-03-02.031 [Debug] (Stats) Chunk: -3   0   0   0   33  203 0
2021-01-02 22-03-03.027 [Debug] (Stats) Chunk: -2   -5  -3  -3  69  203 0
2021-01-02 22-03-04.024 [Debug] (Stats) Chunk: -16  -14 -4  -4  105 202 0
...
2021-01-02 22-03-25.032 [Debug] (Stats) Chunk: 0    0   1   0   500 201 -2
2021-01-02 22-03-26.028 [Debug] (Stats) Chunk: 0    0   0   0   500 201 -1
2021-01-02 22-03-27.025 [Debug] (Stats) Chunk: 0    0   0   0   500 202 0

PCM device is active:

watch -n 1 cat /proc/asound/card*/*p/sub*/status
Alle 1,0s: cat /proc/asound/card0/pcm3p/sub0/status /proc/asound/card1/pcm0p/sub0/status                                                                  Laptop: Sat Jan  2 22:07:08 2021

closed
state: RUNNING
owner_pid   : 998
trigger_time: 73854.469362920
tstamp      : 73882.950686742
delay       : 4155
avail       : 293
avail_max   : 293
-----
hw_ptr      : 1367070
appl_ptr    : 1371193

1. Pause MPD

2021-01-02 22-03-27.086 [Info] (Stream) Exception: 0
2021-01-02 22-03-27.086 [Info] (Alsa) Failed to get chunk
2021-01-02 22-03-27.187 [Debug] (Alsa) Waiting for chunk
...
2021-01-02 22-03-32.098 [Debug] (Alsa) Waiting for chunk
2021-01-02 22-03-32.098 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2021-01-02 22-03-32.200 [Debug] (Alsa) Waiting for chunk
...
2021-01-02 22-03-37.215 [Debug] (Alsa) Waiting for chunk
2021-01-02 22-03-37.316 [Debug] (Alsa) Waiting for chunk

After 5s Snapclient releases the PCM device (No chunk received for 5000ms. Closing ALSA.). Another 5s later PulseAudio releases the PCM device (it's pure coincidence that both are having a 5s idle timeout):

Alle 1,0s: cat /proc/asound/card0/pcm3p/sub0/status /proc/asound/card1/pcm0p/sub0/status                                                                  Laptop: Sat Jan  2 22:05:38 2021

closed
closed

1. Resume MPD playback, Snapclient continues playback, the device is reactived.

2021-01-02 22-03-42.334 [Debug] (Alsa) Waiting for chunk
2021-01-02 22-03-42.485 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
2021-01-02 22-03-42.485 [Debug] (Stream) age > 0: 15178ms, dropping old chunks
2021-01-02 22-03-42.485 [Debug] (Stream) age: -780, requested chunk_duration: 159, duration: 24
2021-01-02 22-03-42.485 [Debug] (Stream) Silent frames: 7679, frames: 7679, age: -780.786
2021-01-02 22-03-43.037 [Debug] (Stream) Silent frames: 1255, frames: 1463, age: -26.155
2021-01-02 22-03-43.068 [Debug] (Stats) Chunk: 1    1   1   1   1   202 0
2021-01-02 22-03-44.003 [Debug] (Stats) Chunk: 4    6   6   6   35  212 0
2021-01-02 22-03-45.015 [Debug] (Stats) Chunk: 5    1   3   3   71  201 0

Variations, I've tested:

1. When Snapclient is started using a direct alsa access (e.g. -s sysdefault:CARD=sndrpihifiberry), the device is released after 5s on pause, there is no additional PulseAudio idle timer
2. If MPD is idle when snapclient is started, the device is active and released 5s later:

2021-01-02 22-24-40.358 [Info] (Connection) Resolving host IP for: 192.168.0.3
2021-01-02 22-24-40.358 [Info] (Connection) Connecting
2021-01-02 22-24-40.363 [Notice] (Connection) Connected to 192.168.0.3
2021-01-02 22-24-40.363 [Info] (Connection) My MAC: "5c:3a:45:56:e2:b7", socket: 8
2021-01-02 22-24-40.414 [Debug] (Connection) outstanding async_write
2021-01-02 22-24-40.419 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 80, muted: 0
metadata:{"STREAM":"default"}
2021-01-02 22-24-40.419 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2021-01-02 22-24-40.419 [Info] (Player) Player name: alsa, device: default, description: Playback/recording through the PulseAudio sound server, idx: 0, sharing mode: unspecified, parameters: <none>
2021-01-02 22-24-40.419 [Info] (Player) Mixer mode: software, parameters: <none>
2021-01-02 22-24-40.419 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2021-01-02 22-24-40.419 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2021-01-02 22-24-40.493 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
2021-01-02 22-24-40.494 [Debug] (Player) setVolume exp with base 10: 0.8 => 0.589953
2021-01-02 22-24-40.494 [Debug] (Alsa) Resizing buffer from 0 to 30716
2021-01-02 22-24-40.494 [Info] (Stream) no chunks available
2021-01-02 22-24-40.494 [Info] (Alsa) Failed to get chunk
2021-01-02 22-24-40.594 [Debug] (Alsa) Waiting for chunk
2021-01-02 22-24-40.685 [Info] (Controller) diff to server [ms]: 2.47846e+09
2021-01-02 22-24-40.695 [Debug] (Alsa) Waiting for chunk
...
2021-01-02 22-24-45.509 [Debug] (Alsa) Waiting for chunk
2021-01-02 22-24-45.509 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2021-01-02 22-24-45.611 [Debug] (Alsa) Waiting for chunk
...

In the last messages of this thread you saying "it does not happen, the issue happened, ...", once again please, what is "the issue"? Is it But any now and them the alsa card is "woken up" for no apparent reasons?
When snapclient closes the device, it will log No chunk received for 5000ms. Closing ALSA. and call uninitAlsa, it will not open the device without logging PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960 (when initAlsa is called).
If you don't see this line, it will not be Snapclient waking up the device.

[douardda]

The problem is that the server seem that with mpd (writing in /tmp/snapfifo) paused or stopped, the snapserver will wake clients up after a while for no apparent reason. It can take a few minutes or a few hours, but it will happen for sure. This does not happen if mpd is not running, so I cannot say for sure if the problem comes from snapserver, mpd or a unfortunate combination of both...

I am now pretty sure the problem is not coming from the client but the server (as I said in a comment above, I do see the alsa device being open in the logs of the client (PCM name: [...]) ).

One difficulty to debug this problem is the server is not very chatty on what it does. I've not been able to make it write something in the logs when this event occurs.

I'm currently running strace on mpd and snapserver to try to catch the thing...

[douardda]

Still trying to figure what's going on.

edit: see the comment below for a better trace where the problem appears instead of being "fixed" by restarting mpd

Here (restart_mpd.trace.txt) is the result of a strace -tt -f -p 17778 -e 'trace=file,read,network' (where 17778 is the pid of snapserver) during the following situation:

• at the beginning of this trace session, the snapserver sends messages to the snapclient, making it keep the alsa card open, while mpd is running but paused (aka the bogus situation).
• around timestamp 23:22:56.649797 (not sure about the milliseconds), mpd is restarted.
  As a result of this mpd restart, the snapclient detects that no content is sent and close the alsa card after a few seconds:

Jan 04 23:20:11 orangepilite snapclient[20703]: PCM name: default:CARD=I2Smaster, sample rate: 48
000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
Jan 04 23:20:11 orangepilite snapclient[20703]: no chunks available                             
Jan 04 23:20:11 orangepilite snapclient[20703]: Failed to get chunk                             
Jan 04 23:20:11 orangepilite snapclient[20703]: diff to server [ms]: 8.68917e+08                                                                                                                
Jan 04 23:22:57 orangepilite snapclient[20703]: Exception: 0                                    
Jan 04 23:22:57 orangepilite snapclient[20703]: Failed to get chunk                             
Jan 04 23:22:58 orangepilite snapclient[20703]: XRUN while waiting for PCM: Broken pipe         
Jan 04 23:23:00 orangepilite snapclient[20703]: Exception: 0                                    
Jan 04 23:23:00 orangepilite snapclient[20703]: Failed to get chunk                             
Jan 04 23:23:05 orangepilite snapclient[20703]: No chunk received for 5000ms. Closing ALSA.     

You may notice the very different "pattern" soon after the restart of mpd (from timestamp 23:23:00.069229) where there are no more messages sent to the client, just the reading of the /tmp/snapfifo that fails with EAGAIN.

This may help also:

ls -l /proc/17778/fd
total 0
lr-x------ 1 snapserver snapserver 64 Jan  4 19:15 0 -> /dev/null
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 1 -> 'socket:[3277622]'
lr-x------ 1 snapserver snapserver 64 Jan  4 19:15 10 -> /tmp/snapfifo
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 11 -> 'socket:[3276319]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 12 -> 'socket:[3276320]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 13 -> 'socket:[3276323]'
lr-x------ 1 snapserver snapserver 64 Jan  4 19:15 14 -> 'pipe:[3276325]'
l-wx------ 1 snapserver snapserver 64 Jan  4 19:15 15 -> 'pipe:[3276325]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:25 16 -> 'socket:[6496208]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 2 -> 'socket:[3277622]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 3 -> 'socket:[3277623]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 4 -> 'anon_inode:[eventfd]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 5 -> 'anon_inode:[eventpoll]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 6 -> 'anon_inode:[timerfd]'
lr-x------ 1 snapserver snapserver 64 Jan  4 19:15 7 -> 'pipe:[3277624]'
l-wx------ 1 snapserver snapserver 64 Jan  4 19:15 8 -> 'pipe:[3277624]'
lrwx------ 1 snapserver snapserver 64 Jan  4 19:15 9 -> 'socket:[3277625]'

And:

lsof -i -a -p 17778
COMMAND     PID       USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
snapserve 17778 snapserver   11u  IPv4 3276319      0t0  TCP *:1705 (LISTEN)
snapserve 17778 snapserver   12u  IPv4 3276320      0t0  TCP *:1780 (LISTEN)
snapserve 17778 snapserver   13u  IPv4 3276323      0t0  TCP *:1704 (LISTEN)
snapserve 17778 snapserver   16u  IPv4 6496208      0t0  TCP nas2:1704->192.168.2.4:56516 (ESTABLISHED)

So fd 10 is indeed the /tmp/snapfifo file and fd 16 is the tcp connection with the snapclient.

Also note how the how the threads "share" the trace pattern... All of them do read() and sendmsg() in the fd 16 for example (which I find a bit odd without looking at the source code).

I'm now trying to catch the more interesting transition: from ok (mpd paused, snapclient keeps the sound card closed) to non ok (mpd paused, snapclient keeps the sound card open), but being a random process, it's harder to catch (and these trace session quickly get really big)...

Hope this helps.

[douardda]

Here is a strace when the problem appears (here at timestamp 02:43:34):
snapserver-trace-with-error-ts_02:42-44.log

Before the problem, we can see this pattern being repeated over and over:

17782 02:42:06.797170 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17781 02:42:06.818334 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17778 02:42:06.840394 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17780 02:42:06.861866 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17779 02:42:06.883996 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17781 02:42:06.894114 recv(16, "\4\0S\10\0\0\272e\7\0\367y\0\0\272e\7\0ky\0\0\10\0\0\0", 26, 0) = 26
17781 02:42:06.894834 recv(16, "\272e\7\0ry\0\0", 8, 0) = 8
17781 02:42:06.896680 recv(16, 0xb4403cc8, 26, 0) = -1 EAGAIN (Resource temporarily unavailable)
17782 02:42:06.897513 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\4\0S\10S\10\356\247\24\0\200}\r\0\356\247\24\0007z\r\0\10\0\0\0004B\r\0@\0"..., iov_len=34}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 34
17778 02:42:06.905502 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17781 02:42:06.927386 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17782 02:42:06.949407 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17778 02:42:06.971800 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17780 02:42:06.993513 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)

So the snapfifo file is read constantly but always generates EAGAIN, and every second, the snapclient send something which results in sending back the msg like "\40S\10S\10\356\247\240\200}\r0\3[...]" (size 34).

When the problem occurs, we see:

17778 02:43:33.700084 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17779 02:43:33.709073 recv(16, "\4\0\251\10\0\0\20f\7\0z\357\f\0\20f\7\0\367\356\f\0\10\0\0\0", 2
6, 0) = 26
17779 02:43:33.709925 recv(16, "\20f\7\0\376\356\f\0", 8, 0) = 8
17780 02:43:33.711913 recv(16, 0xb4403cc8, 26, 0) = -1 EAGAIN (Resource temporarily unavailable)
17782 02:43:33.712780 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\4\0\251\10\251\10E\250\24\0\275\253\n\0E\250\24\0x\250\n\0\10\0\0\0004B\r\0>\373"..., iov_len=34}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 34
17779 02:43:33.721452 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)

[...]

17780 02:43:34.180911 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17782 02:43:34.202500 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17778 02:43:34.224479 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17780 02:43:34.226719 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\2\0\0\0\0\0F\250\24\0#C\3\0Dy\24\0\5\225\0\0\36\0\0\0F\250\24\0002\361"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 56
17782 02:43:34.245574 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17779 02:43:34.247377 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\2\0\0\0\0\0F\250\24\0O\223\3\0F\250\24\0qE\3\0\36\0\0\0F\250\24\0\362N"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 56
17780 02:43:34.265986 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17779 02:43:34.267575 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\2\0\0\0\0\0F\250\24\0h\342\3\0F\250\24\0$\225\3\0\36\0\0\0F\250\24\0\262\254"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 56
17781 02:43:34.285775 read(10, 0x321c98, 3840) = -1 EAGAIN (Resource temporarily unavailable)
17782 02:43:34.287133 sendmsg(16, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\2\0\0\0\0\0F\250\24\0\215/\4\0F\250\24\0\32\344\3\0\36\0\0\0F\250\24\0r\n"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 56

So before we receive data from the snapclient (read(16, ...), which would have been expected around 02:43:34.700000) the server sends a different message to the snapclient (starts with "\2", iov_len is now 56).

But no clue why the behavior changes (obviously nothing changed on the snapfifo side).

[douardda]

So if I get this right, first byte in messages is the message type as defined in common/message/message.hpp (enum message_type), so when everything is fine, the server sends "kTime" messages once a second, but suddenly starts to send pcm chuncks (\2: kWireChunk) messages so the client wakes up and open the alsa card as expected. The thing is to figure why the snapserver suddenly decides to send (empty) PCM chunks...

For testing purpose, I've restarted the snapserver with 'threads=0' in the config.

I also have an unfiltered strace file with the transition (ok -> not ok) captured as well as the trace-level logging, if it can help (I have found nothing obvious in there).

edit: I'm trying to run snapserver with no "extra" thread because I'm starting to think some race condition between (PipeStream) streamreader threads could be in cause here

update: the problem occurred also with with no extra threads :-(

[douardda]

@badaix BTW you wrote that you

Still cannot reproduce it.

I want to point out that the whole stack (mpd -> snapserver -> snapclient -> alsa) works OK for a while then falls in a "buggy" state where the server sends silence chucks to the client making this later wake the sound card up. The problem is this behavior seems pretty random, so a "quick test" won't allow to reproduce it.

Hopefully I am clear enough and you have now a better idea of the issue :-)

[douardda]

Fun fact: looks like the problem occurs (more or less) exactly every 3 hours and 10mn (snapserver still running with threads=0):

Jan 06 00:07:18 orangepilite python[550]: DEBUG:root:new state is False  <=== when snapserver has been restarted
Jan 06 00:07:18 orangepilite python[550]: Will power off in 30 s.
Jan 06 00:07:19 orangepilite python[550]: DEBUG:root:new state is True
Jan 06 00:07:19 orangepilite python[550]: power  ON
Jan 06 00:07:21 orangepilite python[550]: DEBUG:root:new state is False
Jan 06 00:07:21 orangepilite python[550]: Will power off in 30 s.
Jan 06 00:07:51 orangepilite python[550]: power  OFF
Jan 06 03:17:19 orangepilite python[550]: DEBUG:root:new state is True   <==== when the problem occurs
Jan 06 03:17:20 orangepilite python[550]: power  ON
Jan 06 06:23:47 orangepilite python[550]: DEBUG:root:new state is False  <==== the problem disappears (by itself)
Jan 06 06:23:47 orangepilite python[550]: Will power off in 30 s.
Jan 06 06:24:17 orangepilite python[550]: power  OFF
Jan 06 09:33:48 orangepilite python[550]: DEBUG:root:new state is True   <==== the problem occurs again
Jan 06 09:33:48 orangepilite python[550]: power  ON

[badaix]

Interesting!
I was trying to reproduce the issue reported by @quantenschaum:

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

Thought it is about initial playback after client or server or mpd start.
So you think that mpd is not writing to the pipe? Did you try to cat the pipe and check if there is data coming when mpd is paused?
Also interesting: seems that it's not a single "burst" (i.e. chunk) waking up your soundcard, but the same 3h duration as the "idle" period.
I will also try to reproduce and debug this.

[badaix]

Think I've found the problem: the server counts the "idle-bytes" when no audio is read from the pipe and stops sending audio when the idle bytes exceed the dryout_ms parameter (default is 2s). The idle bytes are counted with a signed int (4 bytes) that will eventually overflow and flip from 2147483647 (which is larger than 2s dryout timer) to -2147483648 (which is smaller than 2s dryout).
So when will it reach 2147483647? At 48000:16:2 the server expects to read 192000 bytes per second from the pipe. If mpd is paused, the idle-byte counter is incremented by 192000 every second, causing an overflow after 186min 24s. This will cause the server to send silence until the counter reaches 0 (well, actually 2*192000 = 2s). And so on...
This should be easy to fix, the easiest fix would be using an 8 byte counter, but then the issue will be reported again in 1523287 years ;)

[badaix]

Should be fixed 6ec5785, update available in actions
Can you please test this?

[douardda]

Think I've found the problem: the server counts the "idle-bytes" when no audio is read from the pipe and stops sending audio when the idle bytes exceed the dryout_ms parameter (default is 2s). The idle bytes are counted with a signed int (4 bytes) that will eventually overflow and flip from 2147483647 (which is larger than 2s dryout timer) to -2147483648 (which is smaller than 2s dryout).

I was thinking about something like this yesterday evening, so I tried with a much smaller dryout_ms value (2ms instead of 2000) but it did not change the 3h10 "delay" I saw in my logs... not sure why.

Anyway, let me try the fix you made. Thanks a lot!

[badaix]

It will change to 3h10 - 1998ms, will be hard to notice :)

[douardda]

It will change to 3h10 - 1998ms, will be hard to notice :)

Oh yes sure! The problem coming from the overflow, makes sense! Thanks

[douardda]

looks good (so far): 6+ hours without the issue!

[badaix]

I didn't make the counter larger, but stop incrementing when dryout_ms is exceeded, and thus prevent an overflow

[douardda]

I didn't make the counter larger, but stop incrementing when dryout_ms is exceeded, and thus prevent an overflow

Yes I've seen that, nice trick :-)

[douardda]

I think this issue can now be closed.

[quantenschaum]

Thank you! :1st_place_medal: