snapcast icon indicating copy to clipboard operation
snapcast copied to clipboard
verified publisher icon badaix

Consistent "[Info] (Alsa) Failed to get chunk error", no sound.

Open matteobrusa opened this issue 1 year ago • 3 comments

Describe the bug The client fails to play the streamed data after the first playback session, and throws [Info] (Alsa) Failed to get chunk.

Steps to Reproduce

  1. Start the server snapserver --logging.filter debug -c /opt/snapserver/snapserver.conf with the following config:
[stream]
source = pipe:///opt/snapserver/snapfifo?name=fifo
sampleformat = 44100:16:2
chunk_ms = 50
buffer = 1000
  1. Start the client snapclient --logfilter debug --host <server ip> --soundcard plughw:0,0
  2. Stream some data to it cat /dev/urandom > /opt/snapserver/snapfifo
  3. the client plays ok
  4. Stop the source, wait for the [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA. message.
  5. restart the streaming
  6. The client produces no audio, throws the following errors:
2024-12-25 22-53-57.439 [Info] (Alsa) PCM name: plughw:0,0, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2024-12-25 22-53-57.439 [Debug] (Stream) age > 0: 53051ms, dropping old chunks
2024-12-25 22-53-57.439 [Debug] (Stream) age: 2913, requested chunk_duration: 80, duration: 26
2024-12-25 22-53-57.439 [Info] (Alsa) Failed to get chunk
2024-12-25 22-53-57.454 [Debug] (Stream) age > 0: 2928ms, dropping old chunks
2024-12-25 22-53-57.455 [Debug] (Stream) age: 2902, requested chunk_duration: 80, duration: 26
2024-12-25 22-53-57.455 [Info] (Alsa) Failed to get chunk
2024-12-25 22-53-57.473 [Debug] (Stream) age > 0: 2921ms, dropping old chunks
2024-12-25 22-53-57.474 [Debug] (Stream) age: 2895, requested chunk_duration: 80, duration: 26
2024-12-25 22-53-57.474 [Info] (Alsa) Failed to get chunk
2024-12-25 22-53-57.494 [Debug] (Stream) age > 0: 2915ms, dropping old chunks
2024-12-25 22-53-57.494 [Debug] (Stream) age: 2889, requested chunk_duration: 80, duration: 26
2024-12-25 22-53-57.494 [Info] (Alsa) Failed to get chunk
2024-12-25 22-53-57.537 [Debug] (Stream) age > 0: 2932ms, dropping old chunks
2024-12-25 22-53-57.537 [Debug] (Stream) age: 2906, requested chunk_duration: 80, duration: 26
2024-12-25 22-53-57.537 [Info] (Alsa) Failed to get chunk
  1. killing and restarting the client fixes the problem and continues the streaming.

Environment details

  • OS: RaspberryOS 64 bit bullseye on both server (RPI 4) and client (RPIZ2W)
  • Snapcast version 0.29 installed from the release .deb arm64 files

what I've tried

  • chunk_ms below 30ms won't work
  • changing codec, changing source from pipe to alsa loopback, using librespot instead of urandom

It seems more like an audio init issue. I'm using the Waveshare WM8960 audio HAT.

Thanks for your effort in creating this non-trivial piece of software. Please let me know if any detail is missing.

matteobrusa avatar Dec 25 '24 22:12 matteobrusa

I have the same issue with snapclient 0.30 on a RPI 4 on NixOS for several months now. My server is Music-Assistant.

zoechi avatar Mar 20 '25 06:03 zoechi

In my case it looks like this was caused by radvd (IPv6 Router Advertisement service). It seems to be an old and not uncommon problem https://forum.opnsense.org/index.php?topic=34661.0

When I first installed snapclient it worked fine for a few weeks but suddenly it started causing this issue and required me to restart the Raspberry or at least the snapclient service every time to make sound play again.

At approximately that time (in hindsight) I started having weird network issues. It turned out that restarting Unbound and Radvd once every 2-3 days fixed the issues. After a lot of debugging I gave in and configured a cron service that restarts radvd every hour.

Since then the networking issues are gone and, to me very suprising, snapclient started playing again without any manual intervention (restarting the service or the device).

I would have never figured that connection out directly. When snapclient didn't play, the first thing was to check the network connectivity and it always worked. If the network were broken, why would restarting the service or device solve the problem? Anyway, now snapclient works again 🚀

zoechi avatar Apr 11 '25 05:04 zoechi

I got pretty much the same problem, running snapclient v27 and also tried v31,

snapclient is running on a RPI 3b , snapcast server is running, can listen to music in brave browser via Mopidy-Iris, and snapcast android app.

Here is my latest debug from RPi3b snapclient v27

snapclient --logfilter debug --host 192.168.1.140 --soundcard plughw:0,0 2025-05-13 18-15-11.226 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: plughw:0,0 2025-05-13 18-15-11.267 [Error] (Snapclient) PCM device "plughw:0,0" not found 2025-05-13 18-15-11.267 [Info] (Snapclient) Version 0.27.0, revision 54a3d862 2025-05-13 18-15-11.268 [Info] (Connection) Resolving host IP for: 192.168.1.140 2025-05-13 18-15-11.268 [Info] (Connection) Connecting 2025-05-13 18-15-11.276 [Notice] (Connection) Connected to 192.168.1.140 2025-05-13 18-15-11.276 [Info] (Connection) My MAC: "b8:27:eb:1e:0e:61", socket: 8 2025-05-13 18-15-11.537 [Debug] (Connection) outstanding async_write 2025-05-13 18-15-11.540 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 12, muted: 0 2025-05-13 18-15-11.540 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2 2025-05-13 18-15-11.540 [Info] (Player) Player name: alsa, device: plughw:0,0, description: <none>, idx: -1, sharing mode: unspecified, parameters: <none> 2025-05-13 18-15-11.541 [Info] (Player) Mixer mode: software, parameters: <none> 2025-05-13 18-15-11.541 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2 2025-05-13 18-15-11.541 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4 2025-05-13 18-15-11.543 [Debug] (Alsa) ACCESS: MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED 2025-05-13 18-15-11.543 [Debug] (Alsa) FORMAT: S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE 2025-05-13 18-15-11.543 [Debug] (Alsa) SUBFORMAT: STD 2025-05-13 18-15-11.543 [Debug] (Alsa) SAMPLE_BITS: [4 64] 2025-05-13 18-15-11.543 [Debug] (Alsa) FRAME_BITS: [4 640000] 2025-05-13 18-15-11.543 [Debug] (Alsa) CHANNELS: [1 10000] 2025-05-13 18-15-11.543 [Debug] (Alsa) RATE: [4000 4294967295) 2025-05-13 18-15-11.543 [Debug] (Alsa) PERIOD_TIME: (5 8192000] 2025-05-13 18-15-11.543 [Debug] (Alsa) PERIOD_SIZE: (0 4294967295) 2025-05-13 18-15-11.543 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295) 2025-05-13 18-15-11.543 [Debug] (Alsa) PERIODS: (0 4294967295] 2025-05-13 18-15-11.543 [Debug] (Alsa) BUFFER_TIME: [1 4294967295] 2025-05-13 18-15-11.543 [Debug] (Alsa) BUFFER_SIZE: [1 4294967294] 2025-05-13 18-15-11.543 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295] 2025-05-13 18-15-11.543 [Debug] (Alsa) TICK_TIME: ALL 2025-05-13 18-15-11.559 [Info] (Alsa) PCM name: plughw:0,0, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960 2025-05-13 18-15-11.560 [Debug] (Alsa) Failed to start PCM: Broken pipe 2025-05-13 18-15-11.560 [Debug] (Alsa) setVolume exp with base 10: 0.12 => 0.0353619 2025-05-13 18-15-11.560 [Debug] (Alsa) Resizing buffer from 0 to 15360 2025-05-13 18-15-11.561 [Info] (Stream) No chunks available 2025-05-13 18-15-11.561 [Info] (Alsa) Failed to get chunk 2025-05-13 18-15-11.661 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-11.768 [Info] (Controller) diff to server [ms]: 4.25389e+08 2025-05-13 18-15-13.663 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-15.665 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-16.566 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA. 2025-05-13 18-15-17.671 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-19.674 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-21.678 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-23.681 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-25.684 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-27.687 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-29.691 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-31.694 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-33.697 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-35.700 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-37.704 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-39.708 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-41.711 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-43.714 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-45.718 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-47.721 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-49.725 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-15-51.728 [Debug] (Alsa) Waiting for chunk

and here is a debug with a raspbian os upgraded latest and snapclient v31 snapserver still running and working

chilloutcorner@chilloutcorner:~ $ snapclient --logfilter debug --host 192.168.1.140 2025-05-13 18-37-47.709 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default 2025-05-13 18-37-47.758 [Info] (Snapclient) Version 0.31.0, revision cf2be071 2025-05-13 18-37-47.759 [Info] (Connection) Resolving host IP for: 192.168.1.140 2025-05-13 18-37-47.759 [Debug] (Connection) Resolved IP: 192.168.1.140 2025-05-13 18-37-47.759 [Info] (Connection) Connecting to 192.168.1.140:1704 2025-05-13 18-37-47.765 [Notice] (Connection) Connected to 192.168.1.140 2025-05-13 18-37-47.765 [Info] (Connection) My MAC: "b8:27:eb:1e:0e:61", socket: 8 2025-05-13 18-37-48.025 [Debug] (Connection) outstanding async_write 2025-05-13 18-37-48.027 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 12, muted: 0 2025-05-13 18-37-48.029 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2 2025-05-13 18-37-48.029 [Info] (Player) Player name: alsa, device: default, description: <none>, idx: 1, sharing mode: unspecified, parameters: <none> 2025-05-13 18-37-48.029 [Info] (Player) Mixer mode: software, parameters: <none> 2025-05-13 18-37-48.029 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2 2025-05-13 18-37-48.029 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4 2025-05-13 18-37-48.031 [Debug] (Alsa) ACCESS: MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED 2025-05-13 18-37-48.031 [Debug] (Alsa) FORMAT: S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE 2025-05-13 18-37-48.031 [Debug] (Alsa) SUBFORMAT: STD 2025-05-13 18-37-48.031 [Debug] (Alsa) SAMPLE_BITS: [4 64] 2025-05-13 18-37-48.031 [Debug] (Alsa) FRAME_BITS: [4 640000] 2025-05-13 18-37-48.031 [Debug] (Alsa) CHANNELS: [1 10000] 2025-05-13 18-37-48.031 [Debug] (Alsa) RATE: [4000 4294967295) 2025-05-13 18-37-48.031 [Debug] (Alsa) PERIOD_TIME: (5 8192000] 2025-05-13 18-37-48.031 [Debug] (Alsa) PERIOD_SIZE: (0 4294967295) 2025-05-13 18-37-48.031 [Debug] (Alsa) PERIOD_BYTES: (0 4294967295) 2025-05-13 18-37-48.031 [Debug] (Alsa) PERIODS: (0 4294967295] 2025-05-13 18-37-48.031 [Debug] (Alsa) BUFFER_TIME: [1 4294967295] 2025-05-13 18-37-48.031 [Debug] (Alsa) BUFFER_SIZE: [1 4294967294] 2025-05-13 18-37-48.031 [Debug] (Alsa) BUFFER_BYTES: [1 4294967295] 2025-05-13 18-37-48.031 [Debug] (Alsa) TICK_TIME: ALL 2025-05-13 18-37-48.047 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960 2025-05-13 18-37-48.048 [Debug] (Alsa) Failed to start PCM: Broken pipe 2025-05-13 18-37-48.048 [Debug] (Alsa) setVolume exp with base 10: 0.12 => 0.0353619 2025-05-13 18-37-48.048 [Debug] (Alsa) Resizing buffer from 0 to 15360 2025-05-13 18-37-48.049 [Info] (Stream) No chunks available 2025-05-13 18-37-48.049 [Info] (Alsa) Failed to get chunk 2025-05-13 18-37-48.149 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-37-48.182 [Info] (Controller) diff to server [ms]: 4.26446e+08 2025-05-13 18-37-50.151 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-37-52.153 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-37-53.054 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA. 2025-05-13 18-37-54.159 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-37-56.164 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-37-58.168 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-00.171 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-02.175 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-04.179 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-06.182 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-08.186 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-10.189 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-12.193 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-14.196 [Debug] (Alsa) Waiting for chunk 2025-05-13 18-38-16.200 [Debug] (Alsa) Waiting for chunk

Never mind, snapclient started again and works for now, I dont know exactly what a I did , couple of reebots of pi and restarts of snapclient service.

dnj0104 avatar May 13 '25 16:05 dnj0104