No chunk received for 5000ms. Closing ALSA.

[ajw685]

Hi,

I have 2 fresh installs of Volumio on 2 of the same devices with Volumio installed on both. They are Rock64 units and I followed this guide: https://forum.pine64.org/showthread.php?tid=6502 I'm trying to get multi-room audio running.

I have Volumio up and running and AirPlay works on both devices and I am able to hear the AirPlay audio through the headphone jack on the Rock64.

I am having issues with the SnapCast plugin. I have removed the -d parameter from opts on both 'client' and 'server' and have to re-remove it every time I use the GUI to start and stop snapclient/snapserver.

When I restart my snapclient plugin on my 'client' machine, I get connected but then no audio; in the log I end up with:

No chunks available
Failed to get chunk
diff to server [ms]: 2.66011e+06
No chunk received for 5000ms. Closing ALSA.

Both devices are on ethernet. I get the same error when the 'client' is on wifi with a 2.4ghz connection (EDImax usb unit) but the 'diff to server' is like ~5200ms instead of x10^6. I'm not sure what is wrong. I've done a lot of googling with the 'chunk' term and keep ending up at the same ~6 threads on the internet. I feel like I'm missing some configuration parameter or something simple like that.

Server & Client Information

volumio@volumio-kitchen:~$ cat /proc/cpuinfo
processor       : 0
model name      : ARMv8 Processor rev 4 (v8l)
BogoMIPS        : 48.00
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x41
CPU architecture: 8
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 1
model name      : ARMv8 Processor rev 4 (v8l)
BogoMIPS        : 48.00
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x41
CPU architecture: 8
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 2
model name      : ARMv8 Processor rev 4 (v8l)
BogoMIPS        : 48.00
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x41
CPU architecture: 8
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 3
model name      : ARMv8 Processor rev 4 (v8l)
BogoMIPS        : 48.00
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x41
CPU architecture: 8
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

volumio@volumio-kitchen:~$ uname -a
Linux volumio-kitchen 4.4.154 #1 SMP Tue Oct 13 11:37:38 CEST 2020 aarch64 GNU/Linux

volumio@volumio-kitchen:~$ snapclient -v                                        snapclient v0.25.0 (rev 2af5292f)
Copyright (C) 2014-2021 BadAix ([email protected]).
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Written by Johannes M. Pohl and contributors <https://github.com/badaix/snapcast/graphs/contributors>.

volumio@volumio-kitchen:~$ snapclient -l
0: null
Discard all samples (playback) or generate zero samples (capture)

1: pulse
PulseAudio Sound Server

2: snapConverter


3: writeFile


4: snapcast


5: default:CARD=HDMI
HDMI,
Default Audio Device

6: sysdefault:CARD=HDMI
HDMI,
Default Audio Device

7: dmix:CARD=HDMI,DEV=0
HDMI,
Direct sample mixing device

8: dsnoop:CARD=HDMI,DEV=0
HDMI,
Direct sample snooping device

9: hw:CARD=HDMI,DEV=0
HDMI,
Direct hardware device without any conversions

10: plughw:CARD=HDMI,DEV=0
HDMI,
Hardware device with all software conversions

11: default:CARD=I2S
I2S,
Default Audio Device

12: sysdefault:CARD=I2S
I2S,
Default Audio Device

13: dmix:CARD=I2S,DEV=0
I2S,
Direct sample mixing device

14: dmix:CARD=I2S,DEV=1
I2S,
Direct sample mixing device

15: dsnoop:CARD=I2S,DEV=0
I2S,
Direct sample snooping device

16: dsnoop:CARD=I2S,DEV=1
I2S,
Direct sample snooping device

17: hw:CARD=I2S,DEV=0
I2S,
Direct hardware device without any conversions

18: hw:CARD=I2S,DEV=1
I2S,
Direct hardware device without any conversions

19: plughw:CARD=I2S,DEV=0
I2S,
Hardware device with all software conversions

20: plughw:CARD=I2S,DEV=1
I2S,
Hardware device with all software conversions

21: default:CARD=SPDIF
SPDIF,
Default Audio Device

22: sysdefault:CARD=SPDIF
SPDIF,
Default Audio Device

23: dmix:CARD=SPDIF,DEV=0
SPDIF,
Direct sample mixing device

24: dsnoop:CARD=SPDIF,DEV=0
SPDIF,
Direct sample snooping device

25: hw:CARD=SPDIF,DEV=0
SPDIF,
Direct hardware device without any conversions

26: plughw:CARD=SPDIF,DEV=0
SPDIF,
Hardware device with all software conversions

volumio@volumio1:~$ snapclient -l
0: null
Discard all samples (playback) or generate zero samples (capture)

1: pulse
PulseAudio Sound Server

2: softvolume


3: softvol


4: default:CARD=HDMI
HDMI,
Default Audio Device

5: sysdefault:CARD=HDMI
HDMI,
Default Audio Device

6: dmix:CARD=HDMI,DEV=0
HDMI,
Direct sample mixing device

7: dsnoop:CARD=HDMI,DEV=0
HDMI,
Direct sample snooping device

8: hw:CARD=HDMI,DEV=0
HDMI,
Direct hardware device without any conversions

9: plughw:CARD=HDMI,DEV=0
HDMI,
Hardware device with all software conversions

10: default:CARD=I2S
I2S,
Default Audio Device

11: sysdefault:CARD=I2S
I2S,
Default Audio Device

12: dmix:CARD=I2S,DEV=0
I2S,
Direct sample mixing device

13: dmix:CARD=I2S,DEV=1
I2S,
Direct sample mixing device

14: dsnoop:CARD=I2S,DEV=0
I2S,
Direct sample snooping device

15: dsnoop:CARD=I2S,DEV=1
I2S,
Direct sample snooping device

16: hw:CARD=I2S,DEV=0
I2S,
Direct hardware device without any conversions

17: hw:CARD=I2S,DEV=1
I2S,
Direct hardware device without any conversions

18: plughw:CARD=I2S,DEV=0
I2S,
Hardware device with all software conversions

19: plughw:CARD=I2S,DEV=1
I2S,
Hardware device with all software conversions

20: default:CARD=SPDIF
SPDIF,
Default Audio Device

21: sysdefault:CARD=SPDIF
SPDIF,
Default Audio Device

22: dmix:CARD=SPDIF,DEV=0
SPDIF,
Direct sample mixing device

23: dsnoop:CARD=SPDIF,DEV=0
SPDIF,
Direct sample snooping device

24: hw:CARD=SPDIF,DEV=0
SPDIF,
Direct hardware device without any conversions

25: plughw:CARD=SPDIF,DEV=0
SPDIF,
Hardware device with all software conversions

Server Log:

info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
Starting Live Log...
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
process exited with code nullinfo: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: Killing previous LiveLog session
info: Live Log process terminated: null
error: Cannot download Available plugins list: Error: ETIMEDOUT
Accepted password for volumio from 192.168.1.229 port 54707 ssh2
pam_unix(sshd:session): session opened for user volumio by (uid=0)
Starting user-1000.slice.
Created slice user-1000.slice.
Starting User Manager for UID 1000...
Starting Session 2 of user volumio.
New session 2 of user volumio.
pam_unix(systemd-user:session): session opened for user volumio by (uid=0)
Started Session 2 of user volumio.
Starting Paths.
Reached target Paths.
Starting Timers.
Reached target Timers.
Starting Sockets.
Reached target Sockets.
Starting Basic System.
Reached target Basic System.
Starting Default.
Reached target Default.
Startup finished in 22ms.
Started User Manager for UID 1000.
lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl restart snapserver
pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Stopping Snapcast server...
Received signal 15: Terminated
Stopping streamServer
done
Snapserver terminated.
Starting Snapcast server...
Ignoring invalid environment 'SNAPSERVER_OPTS=-s pipe:///tmp/snapfifo?name=music&sampleformat=48000:16:2
': /etc/default/snapserver
Started Snapcast server.
pam_unix(sudo:session): session closed for user root
Version 0.25.0, revision 2af5292f
Adding source: pipe:///tmp/snapfifo?name=default
Settings file: "/var/lib/snapserver/server.json"
Adding service 'Snapcast'
PcmStream: default, sampleFormat: 48000:16:2
Stream: default, metadata={
"STREAM": "default"
}
onMetaChanged (default)
PipeStream mode: create
Stream: {"fragment":"","host":"","path":"/tmp/snapfifo","query":{"chunk_ms":"20","codec":"flac","name":"default","sampleformat":"48000:16:2"},"raw":"pipe:////tmp/snapfifo?chunk_ms=20&codec=flac&name=default&sampleformat=48000:16:2","scheme":"pipe"}
Init - compression level: 2
Creating TCP acceptor for address: 0.0.0.0, port: 1705
Creating TCP acceptor for address: ::, port: 1705
error creating TCP acceptor: bind: Address already in use, code: system:98
Creating HTTP acceptor for address: 0.0.0.0, port: 1780
Creating HTTP acceptor for address: ::, port: 1780
error creating HTTP acceptor: bind: Address already in use, code: system:98
Creating stream acceptor for address: 0.0.0.0, port: 1704
Creating stream acceptor for address: ::, port: 1704
error creating TCP acceptor: bind: Address already in use, code: system:98
Number of threads: 4, hw threads: 4
Service 'Snapcast' successfully established.
StreamServer::NewConnection: 192.168.1.210
Hello from 2a:f9:2c:22:14:b5, host: volumio1, v0.25.0, ClientName: Snapclient, OS: Debian GNU/Linux 8 (jessie), Arch: aarch64, Protocol version: 2
Error reading message header of length 0: End of file
onDisconnect: 2a:f9:2c:22:14:b5
StreamServer::NewConnection: 192.168.1.210
Hello from 2a:f9:2c:22:14:b5, host: volumio1, v0.25.0, ClientName: Snapclient, OS: Debian GNU/Linux 8 (jessie), Arch: aarch64, Protocol version: 2

Client Log:

info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
Starting Live Log...
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
process exited with code nullinfo: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: Killing previous LiveLog session
info: Live Log process terminated: null
Accepted password for volumio from 192.168.1.229 port 54706 ssh2
pam_unix(sshd:session): session opened for user volumio by (uid=0)
Starting user-1000.slice.
Created slice user-1000.slice.
Starting User Manager for UID 1000...
Starting Session 2 of user volumio.
New session 2 of user volumio.
pam_unix(systemd-user:session): session opened for user volumio by (uid=0)
Started Session 2 of user volumio.
Starting Paths.
Reached target Paths.
Starting Timers.
Reached target Timers.
Starting Sockets.
Reached target Sockets.
Starting Basic System.
Reached target Basic System.
Starting Default.
Reached target Default.
Startup finished in 25ms.
Started User Manager for UID 1000.
lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
Error reading message header of length 0: End of file
Resolving host IP for: 192.168.1.233
Connecting
Connected to 192.168.1.233
My MAC: "2a:f9:2c:22:14:b5", socket: 9
ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Codec: flac, sampleformat: 48000:16:2
Player name: alsa, device: default:CARD=I2S, description: I2S,
Default Audio Device, idx: 10, sharing mode: unspecified, parameters: 
Mixer mode: software, parameters: 
Sampleformat: 48000:16:2, stream: 48000:16:2
Using default buffer_time: 80 ms, default fragments: 4
metadata:{"STREAM":"default"}
PCM name: default:CARD=I2S, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
diff to server [ms]: 2.66011e+06
volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl restart snapclient
pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Stopping Snapcast client...
Received signal 15: Terminated
Snapclient terminated.
Starting Snapcast client...
Started Snapcast client.
pam_unix(sudo:session): session closed for user root
Version 0.25.0, revision 2af5292f
Resolving host IP for: 192.168.1.233
Connecting
Connected to 192.168.1.233
My MAC: "2a:f9:2c:22:14:b5", socket: 9
ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Codec: flac, sampleformat: 48000:16:2
Player name: alsa, device: default:CARD=I2S, description: I2S,
Default Audio Device, idx: 10, sharing mode: unspecified, parameters: 
Mixer mode: software, parameters: 
Sampleformat: 48000:16:2, stream: 48000:16:2
Using default buffer_time: 80 ms, default fragments: 4
metadata:{"STREAM":"default"}
PCM name: default:CARD=I2S, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
No chunks available
Failed to get chunk
diff to server [ms]: 2.66011e+06
No chunk received for 5000ms. Closing ALSA.

[badaix]

Please open an issue in the volumio project or the Snapcast plugin project.
For me it seems like volumio is not sending audio to the Snapserver and thus the server cannot send audio to the clients, which will release the audio device after 5s.

This line looks suspicious:
Ignoring invalid environment 'SNAPSERVER_OPTS=-s pipe:///tmp/snapfifo?name=music&sampleformat=48000:16:2 ': /etc/default/snapserver

[ajw685]

Requesting issue on Volumio Snapcast Plugin project.

[ajw685]

FWIW i had to add ' enabled="yes" ' in mpd.conf for alsa and fofo. now everything works freakin amazing!

[badaix]

👍

[brindhaapsiwifi]

I couldn't find this mpd.conf in /etc/alsa or anywhere in the system..!! Can you please help?

[schniepp]

@brindhaapsiwifi : you probably couldn't find mpd.conf because you may not have mpd installed? I also don't have mpd.conf (or volumino) installed, but I have a similar problem with snapcast. I opened a new bug #1249.