Audio suddenly stops after 5 minutes on Raspberry 2 Zero W

[audas]

I have been struggling with this for almost a week and am getting quite desperate. I am a beginner so please excuse me for my ignorance and poor formatting etc.

I will try and post as much relevant info as possible.

The problem is that I have multiple Raspberry Pi's set up - I am running Mopidy and/or spotify which delivers stream/pipe to snapcast. This works on my Pi 4B+ with a IqadAudioAmp Hat, it works with a 4B+ and even a 3, but I have TWO Pi 2 Zero W and BOTH are consistently failing.

The first one works well and then stops after about 5 minutes. This is consistent and happens no matter what, including doing nothing.

They will both start and perform on reboot, however nothing will get them to work again once they go silent.

The second one was output the below when trying to connect to the Snapserver. (Edit: reinstalled, no longer doing this, instead behaving same as first)

I have reinstalled snapserver, tried it with the github build 0.27, reverted back to the .26 nothing is working.

I have reinstalled the snapclient on the Rpi2wh which works for a short time, and will try and reinstall it again on the one that permanently fails. Strangley the one that always fails was working for a short time and then stopping the same as the first one.

Honestly its like something "fills up" and it can no longer continue??

Thanks for your help - I am old and slow and will try and do whatever you ask.

I ensured to set this as well
sudo sysctl fs.protected_fifos=0

Thanks.

EDIT :

I purged and reinstalled snapclient the RPI 2 ZERO W , it now behaves exactly as its sibling. Running from system as daemon with user set -

START_SNAPCLIENT=true
SNAPCLIENT_OPTS=" --logfilter debug --user guzzbinkles:audio -d"

This was the old output.

2023-10-16 15-01-29.380 [Error] (StreamSessionTCP) Error reading message header of length 0: End of file
2023-10-16 15-01-29.380 [Info] (StreamServer) onDisconnect: d8:3a:dd:55:43:33
2023-10-16 15-01-29.381 [Error] (StreamSessionTCP) Error in socket shutdown: Transport endpoint is not connected
2023-10-16 15-01-29.774 [Notice] (StreamServer) StreamServer::NewConnection: 192.168.20.12
2023-10-16 15-01-29.836 [Info] (Server) Hello from d8:3a:dd:55:43:33, host: raspberrypi-z1, v0.26.0, ClientName: Snapclient, OS: Raspbian GNU/Linux 12 (bookworm), Arch: armv7l, P
rotocol version: 2
2023-10-16 15-01-29.852 [Error] (StreamSessionTCP) Error reading message header of length 0: End of file
2023-10-16 15-01-29.853 [Info] (StreamServer) onDisconnect: d8:3a:dd:55:43:33
2023-10-16 15-01-29.854 [Error] (StreamSessionTCP) Error in socket shutdown: Transport endpoint is not connected
2023-10-16 15-01-30.234 [Notice] (StreamServer) StreamServer::NewConnection: 192.168.20.12
2023-10-16 15-01-30.277 [Info] (Server) Hello from d8:3a:dd:55:43:33, host: raspberrypi-z1, v0.26.0, ClientName: Snapclient, OS: Raspbian GNU/Linux 12 (bookworm), Arch: armv7l, P
rotocol version: 2
2023-10-16 15-01-30.296 [Error] (StreamSessionTCP) Error reading message header of length 0: End of file
2023-10-16 15-01-30.296 [Info] (StreamServer) onDisconnect: d8:3a:dd:55:43:33

Here are the log files from that Pi2zw

Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 4.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: Stopped snapclient.service - Snapcast client.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: Started snapclient.service - Snapcast client.
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Version 0.26.0
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: (Browser) CACHE_EXHAUSTED
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]:         raspberrypi.local:1704 (192.168.20.26)
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Found server 192.168.20.26:1704
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Resolving host IP for: 192.168.20.26
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Connecting
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Connected to 192.168.20.26
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: My MAC: "d8:3a:dd:55:43:33", socket: 9
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: ServerSettings - buffer: 1000, latency: 0, volume: 72, muted: 0
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Codec: flac, sampleformat: 48000:16:2
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Player name: alsa, device: default, description: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Mixer mode: software, parameters: <none>
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Sampleformat: 48000:16:2, stream: 48000:16:2
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Using default buffer_time: 80 ms, default fragments: 4
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Exception: Can't open default, error: Unknown error 524, code: -524
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Exception: Can't open default, error: Unknown error 524
Oct 16 15:01:15 raspberrypi-z1 snapclient[942]: Snapclient terminated.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Failed with result 'exit-code'.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 5.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: Stopped snapclient.service - Snapcast client.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Start request repeated too quickly.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: snapclient.service: Failed with result 'exit-code'.
Oct 16 15:01:15 raspberrypi-z1 systemd[1]: Failed to start snapclient.service - Snapcast client.

Here is the output from the pi2z which works for a short while then stops. (EDIT: They are both like this now) It appears that it is continuing to get data from the stream but nothing is playing.

I have tried to set the device to HDMI using alsamixer, and the advice in the readme - however nothing appears to work. I have been through every id number and they will fail to run snapclient, however the default etc DOES - but there is no audio

2023-10-16 13-51-06.257 [Info] (Snapclient) Version 0.26.0
2023-10-16 13-51-06.277 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2023-10-16 13-51-06.278 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2023-10-16 13-51-06.558 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2023-10-16 13-51-06.558 [Info] (Avahi)  raspberrypi.local:1704 (192.168.20.26)
2023-10-16 13-51-06.561 [Info] (Controller) Found server 192.168.20.26:1704
2023-10-16 13-51-06.561 [Info] (Connection) Resolving host IP for: 192.168.20.26
2023-10-16 13-51-06.561 [Info] (Connection) Connecting
2023-10-16 13-51-06.564 [Notice] (Connection) Connected to 192.168.20.26
2023-10-16 13-51-06.564 [Info] (Connection) My MAC: "d8:3a:dd:64:07:bb", socket: 8
2023-10-16 13-51-06.608 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 16, muted: 0
2023-10-16 13-51-06.611 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2023-10-16 13-51-06.611 [Info] (Player) Player name: alsa, device: default, description: Playback/recording through the PulseAudio sound server, idx: 1, sharing mode: unspecified, parameters: <none
>
2023-10-16 13-51-06.611 [Info] (Player) Mixer mode: software, parameters: <none>
2023-10-16 13-51-06.611 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2023-10-16 13-51-06.611 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2023-10-16 13-51-06.668 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2023-10-16 13-51-06.671 [Info] (Stream) No chunks available
2023-10-16 13-51-06.671 [Info] (Alsa) Failed to get chunk
2023-10-16 13-51-06.898 [Info] (Controller) diff to server [ms]: 2.51899e+08
2023-10-16 13-51-11.679 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2023-10-16 13-51-14.693 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2023-10-16 13-51-18.040 [Info] (Stream) pShortBuffer->full() && (abs(shortMedian_) > 5): 6135
2023-10-16 13-51-28.750 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): -2519
2023-10-16 13-53-03.601 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 32, muted: 0
2023-10-16 13-53-04.518 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 56, muted: 0
2023-10-16 13-54-41.927 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 24, muted: 0
2023-10-16 13-54-43.228 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 48, muted: 0
2023-10-16 13-54-43.719 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 72, muted: 0
2023-10-16 13-55-29.561 [Info] (Controller) ServerSettings - buffer: 1000, latency: 4, volume: 92, muted: 0

Here is my config in snapserver

[http]
# enable HTTP Json RPC (HTTP POST and websockets)
enabled = true

# address to listen on, can be specified multiple times
# use "0.0.0.0" to bind to any IPv4 address or :: to bind to any IPv6 address
# or "127.0.0.1" or "::1" to bind to localhost IPv4 or IPv6, respectively
# use the address of a specific network interface to just listen to and accept
# connections from that interface
bind_to_address = 0.0.0.0
bind_to_address = ::
# which port the server should listen to
port = 1780

# serve a website from the doc_root location
# disabled if commented or empty
doc_root = /usr/share/snapserver/snapweb

# Hostname or IP under which clients can reach this host
# used to serve cached cover art
# use <hostname> as placeholder for your actual host name
#host = <hostname>

#
###############################################################################


# TCP RPC #####################################################################
#

[stream]
source = pipe:///tmp/snapfifo?name=mopidy
stream = spotify:///librespot?name=Spotify&username=guzzbinkles&password=Finn05092013&devicename=Snapcast&bitrate=320&volume=100

[audas]

Ultimately I could not get it to work on Raspberry pi 2 zero W with the latest operating 32 Bit system Bookworm - I installed Bullseye lite 32 Bit and it is now working.

[audas]

Ok the error has returned and is now occurring after several hours of testing - CACHE_EXHAUSTED looks to be the issue here?

avahi/avahi#159

Although its clearly the ALSA fault.

[Error] (Alsa) Exception: Can't open default, error: Unknown error 524, code: -524

2023-10-17 17-07-26.052 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2023-10-17 17-07-26.054 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2023-10-17 17-07-26.451 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2023-10-17 17-07-26.451 [Info] (Avahi)  raspberrypi.local:1704 (192.168.20.26)
2023-10-17 17-07-26.454 [Info] (Controller) Found server 192.168.20.26:1704
2023-10-17 17-07-26.454 [Info] (Connection) Resolving host IP for: 192.168.20.26
2023-10-17 17-07-26.454 [Info] (Connection) Connecting
2023-10-17 17-07-26.495 [Notice] (Connection) Connected to 192.168.20.26
2023-10-17 17-07-26.495 [Info] (Connection) My MAC: "d8:3a:dd:55:43:33", socket: 8
2023-10-17 17-07-26.745 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 96, muted: 0
2023-10-17 17-07-26.747 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2023-10-17 17-07-26.747 [Info] (Player) Player name: alsa, device: default, description: Default Audio Device, idx: 1, s
haring mode: unspecified, parameters: <none>
2023-10-17 17-07-26.748 [Info] (Player) Mixer mode: software, parameters: <none>
2023-10-17 17-07-26.748 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2023-10-17 17-07-26.748 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2023-10-17 17-07-26.758 [Error] (Alsa) Exception: Can't open default, error: Unknown error 524, code: -524
2023-10-17 17-07-26.760 [Fatal] (Snapclient) Exception: Can't open default, error: Unknown error 524
2023-10-17 17-07-26.760 [Notice] (Snapclient) Snapclient terminated.

[audas]

After all my work and pain - corrupted SD card. Thanks.