search

badaix / snapcast

Synchronous multiroom audio player
GNU General Public License v3.0
6.18k stars 457 forks source link

music dropouts/block completely on snapserver #1233

Open amigthea opened 5 months ago

amigthea commented 5 months ago

I'm trying to get snapserver to source from my alsa device but I get this kind of logs, what it could be? a resample problem?

snapcast source configuration

source = alsa://?device=default&name=default
sampleformat = 44100:16:2
codec = pcm

if I record to a file and then play it on my pc it has no problem arecord -D default -f S16_LE -r 44100 capture.wav

logs

snapcast  | 2024-05-11 08-43-49.448 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.448 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.464 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.464 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.481 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.481 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.497 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.497 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.513 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.513 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.529 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.529 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.545 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.545 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.561 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.561 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.577 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.577 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.593 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.593 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.609 [Info] (AlsaStream) Not enough data available: 14 ms, missing: 6 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.609 [Info] (Server) onResync (default): 16 ms
snapcast  | 2024-05-11 08-43-49.646 [Info] (AlsaStream) Not enough data available: 17 ms, missing: 3 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.646 [Info] (Server) onResync (default): 13 ms
snapcast  | 2024-05-11 08-43-49.659 [Info] (AlsaStream) Too many frames available, fast forwarding from 2839 frames (64.3764 ms) to 1323 frames (30 ms)
snapcast  | 2024-05-11 08-43-49.679 [Info] (AlsaStream) Not enough data available: 10 ms, missing: 10 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.679 [Info] (Server) onResync (default): 20 ms
snapcast  | 2024-05-11 08-43-49.739 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.739 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-49.753 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.753 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-49.807 [Info] (PcmStream) State changed: default, state: playing => idle
snapcast  | 2024-05-11 08-43-49.807 [Info] (Server) onStateChanged (default): idle
snapcast  | 2024-05-11 08-43-49.827 [Info] (PcmStream) State changed: default, state: idle => playing
snapcast  | 2024-05-11 08-43-49.827 [Info] (Server) onStateChanged (default): playing
snapcast  | 2024-05-11 08-43-49.927 [Info] (AlsaStream) Not enough data available: 18 ms, missing: 2 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.927 [Info] (Server) onResync (default): 12 ms
snapcast  | 2024-05-11 08-43-49.939 [Info] (AlsaStream) Too many frames available, fast forwarding from 2885 frames (65.4195 ms) to 1323 frames (30 ms)
snapcast  | 2024-05-11 08-43-49.959 [Info] (AlsaStream) Not enough data available: 10 ms, missing: 10 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-49.959 [Info] (Server) onResync (default): 20 ms
snapcast  | 2024-05-11 08-43-50.000 [Info] (AlsaStream) Not enough data available: 13 ms, missing: 7 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.000 [Info] (Server) onResync (default): 17 ms
snapcast  | 2024-05-11 08-43-50.037 [Info] (AlsaStream) Too many frames available, fast forwarding from 2773 frames (62.8798 ms) to 1323 frames (30 ms)
snapcast  | 2024-05-11 08-43-50.837 [Info] (AlsaStream) Not enough data available: 19 ms, missing: 1 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.837 [Info] (Server) onResync (default): 11 ms
snapcast  | 2024-05-11 08-43-50.848 [Info] (AlsaStream) Not enough data available: 19 ms, missing: 1 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.848 [Info] (Server) onResync (default): 11 ms
snapcast  | 2024-05-11 08-43-50.879 [Info] (AlsaStream) Too many frames available, fast forwarding from 3049 frames (69.1383 ms) to 1323 frames (30 ms)
snapcast  | 2024-05-11 08-43-50.919 [Info] (AlsaStream) Not enough data available: 13 ms, missing: 7 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.919 [Info] (Server) onResync (default): 17 ms
snapcast  | 2024-05-11 08-43-50.956 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.956 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-50.970 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.970 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-50.984 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.984 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-50.999 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-50.999 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.013 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.013 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.027 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.027 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.041 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.041 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.055 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.055 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.069 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.069 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.083 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.083 [Info] (Server) onResync (default): 14 ms
snapcast  | 2024-05-11 08-43-51.097 [Info] (AlsaStream) Not enough data available: 16 ms, missing: 4 ms, needed: 20 ms
snapcast  | 2024-05-11 08-43-51.097 [Info] (Server) onResync (default): 14 ms

I tried to change those values from the default but to no avail:

chunk_ms = 20
buffer = 1000

I can ear the audio problem both on software snapclients and snapweb clients.

I'm sure I'm missing something out, would be really glad if someone helps me out Thank you and keep up with this amazing project!

amigthea commented 5 months ago

I confirmed that every time that a dropout appear it's because the PcmStream goes from idle to playing and back

snapcast  | 2024-05-17 20-01-55.312 [Info] (PcmStream) State changed: default, state: idle => playing
snapcast  | 2024-05-17 20-01-55.312 [Info] (Server) onStateChanged (default): playing
snapcast  | bluealsa-aplay: [12] D: aplay.c:739: ALSA playback PCM underrun
snapcast  | 2024-05-17 20-01-59.292 [Info] (PcmStream) State changed: default, state: playing => idle
snapcast  | 2024-05-17 20-01-59.292 [Info] (Server) onStateChanged (default): idle
snapcast  | 2024-05-17 20-02-00.352 [Info] (PcmStream) State changed: default, state: idle => playing
snapcast  | 2024-05-17 20-02-00.352 [Info] (Server) onStateChanged (default): playing
snapcast  | bluealsa-aplay: [12] D: aplay.c:739: ALSA playback PCM underrun
snapcast  | 2024-05-17 20-02-01.552 [Info] (PcmStream) State changed: default, state: playing => idle
snapcast  | 2024-05-17 20-02-01.552 [Info] (Server) onStateChanged (default): idle
snapcast  | 2024-05-17 20-02-02.372 [Info] (PcmStream) State changed: default, state: idle => playing
snapcast  | 2024-05-17 20-02-02.372 [Info] (Server) onStateChanged (default): playing
snapcast  | 2024-05-17 20-02-59.192 [Info] (PcmStream) State changed: default, state: playing => idle
snapcast  | 2024-05-17 20-02-59.192 [Info] (Server) onStateChanged (default): idle
snapcast  | bluealsa-aplay: [12] D: aplay.c:739: ALSA playback PCM underrun
snapcast  | 2024-05-17 20-03-00.352 [Info] (PcmStream) State changed: default, state: idle => playing
snapcast  | 2024-05-17 20-03-00.352 [Info] (Server) onStateChanged (default): playing

I'm streaming from a smartphone via bluetooth adapter -> bluez-alsa -> alsa loopback in -> alsa loopback out -> snapserver alsa stream