Git Product home page Git Product logo

Comments (10)

schniepp avatar schniepp commented on August 16, 2024

This sounds a bit similar to #926, which was apparently resolved by changing mpd settings. However, I don't have mpd installed here.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

When I run snapclient --logfilter debug in "good state" before playing, it looks like this:

024-06-18 06-02-50.069 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-06-18 06-02-50.742 [Info] (Snapclient) Version 0.27.0
2024-06-18 06-02-50.781 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2024-06-18 06-02-51.116 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2024-06-18 06-02-51.123 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2024-06-18 06-02-51.123 [Info] (Avahi)  homeserver.local:1704 (192.168.0.200)
2024-06-18 06-02-51.124 [Debug] (Avahi)         TXT="is_mass=true"
2024-06-18 06-02-51.124 [Debug] (Avahi)         Proto=0
2024-06-18 06-02-51.125 [Debug] (Avahi)         cookie is 0
2024-06-18 06-02-51.125 [Debug] (Avahi)         is_local: 0
2024-06-18 06-02-51.125 [Debug] (Avahi)         our_own: 0
2024-06-18 06-02-51.125 [Debug] (Avahi)         wide_area: 0
2024-06-18 06-02-51.125 [Debug] (Avahi)         multicast: 1
2024-06-18 06-02-51.125 [Debug] (Avahi)         cached: 1
2024-06-18 06-02-51.133 [Info] (Controller) Found server 192.168.0.200:1704
2024-06-18 06-02-51.133 [Info] (Connection) Resolving host IP for: 192.168.0.200
2024-06-18 06-02-51.133 [Info] (Connection) Connecting
2024-06-18 06-02-51.135 [Notice] (Connection) Connected to 192.168.0.200
2024-06-18 06-02-51.136 [Info] (Connection) My MAC: "d8:3a:dd:92:34:3e", socket: 8
2024-06-18 06-02-51.296 [Debug] (Connection) outstanding async_write
2024-06-18 06-02-51.315 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 12, muted: 0
2024-06-18 06-02-51.335 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2024-06-18 06-02-51.335 [Info] (Player) Player name: alsa, device: default, description: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
2024-06-18 06-02-51.335 [Info] (Player) Mixer mode: software, parameters: <none>
2024-06-18 06-02-51.335 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2024-06-18 06-02-51.335 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2024-06-18 06-02-51.360 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2024-06-18 06-02-51.360 [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
2024-06-18 06-02-51.360 [Debug] (Alsa) SUBFORMAT:  STD MSBITS_MAX MSBITS_20 MSBITS_24
2024-06-18 06-02-51.360 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2024-06-18 06-02-51.360 [Debug] (Alsa) FRAME_BITS: [4 640000]
2024-06-18 06-02-51.360 [Debug] (Alsa) CHANNELS: [1 10000]
2024-06-18 06-02-51.360 [Debug] (Alsa) RATE: [4000 4294967295)
2024-06-18 06-02-51.360 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2024-06-18 06-02-51.360 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2024-06-18 06-02-51.360 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2024-06-18 06-02-51.360 [Debug] (Alsa) PERIODS: (0 17247242)
2024-06-18 06-02-51.360 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2024-06-18 06-02-51.360 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2024-06-18 06-02-51.360 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2024-06-18 06-02-51.360 [Debug] (Alsa) TICK_TIME: ALL
2024-06-18 06-02-51.362 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2024-06-18 06-02-51.362 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024
2024-06-18 06-02-51.363 [Debug] (Player) setVolume exp with base 10: 0.12 => 0.0353619
2024-06-18 06-02-51.364 [Debug] (Alsa) Resizing buffer from 0 to 16384
2024-06-18 06-02-51.365 [Info] (Alsa) Wrote 34 bytes to socket
2024-06-18 06-02-51.365 [Info] (Alsa) Failed to get chunk
2024-06-18 06-02-51.465 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-02-51.661 [Info] (Controller) diff to server [ms]: 1.4701e+08
2024-06-18 06-02-53.470 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-02-55.474 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-02-56.376 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2024-06-18 06-02-57.487 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-02-59.493 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-01.497 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-03.501 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-05.506 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-07.511 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-09.516 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-11.520 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-13.525 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-15.530 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-17.534 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-03-19.539 [Debug] (Alsa) Waiting for chunk
^C2024-06-18 06-03-21.296 [Info] (Snapclient) Received signal 2: Interrupt
2024-06-18 06-03-21.344 [Notice] (Snapclient) Snapclient terminated.

It reports "waiting for chunk" very 2 seconds until I killed it with ^C.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

I did some more research, and even in the "stuck" state, I sometimes find "closing ALSA" in the log, but the card is does still not play using aplay. Any idea what could be going on here?

FYI, I used the same USB sound card when I tested this system on the Pi5, where the problem was not there.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

Interesting, the system seems to go bad on the restart of a new radio channel, not so much after stopping the previous station. Here is my reasoning:

If I start a radio station after reboot, it plays music, and I can issue an aplay command, and it will play it on top of the playing radio music. If I stop the radio channel (say, by turning off the player), aplay still works. Only if I restart the radio with a different station, then there is no music, and aplay does not work any more.

from snapcast.

badaix avatar badaix commented on August 16, 2024

This looks rather like the server stops sending audio. Maybe music assistant stops feeding audio to the server.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

This is what the log looks like while it is playing normally (at 06:52:34 AM I stopped the player):

2024-06-18 06-51-58.651 [Info] (Snapclient) Version 0.27.0
2024-06-18 06-51-58.685 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2024-06-18 06-51-59.059 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2024-06-18 06-51-59.065 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2024-06-18 06-51-59.065 [Info] (Avahi)  homeserver.local:1704 (192.168.0.200)
2024-06-18 06-51-59.065 [Debug] (Avahi)         TXT="is_mass=true"
2024-06-18 06-51-59.065 [Debug] (Avahi)         Proto=0
2024-06-18 06-51-59.065 [Debug] (Avahi)         cookie is 0
2024-06-18 06-51-59.065 [Debug] (Avahi)         is_local: 0
2024-06-18 06-51-59.065 [Debug] (Avahi)         our_own: 0
2024-06-18 06-51-59.065 [Debug] (Avahi)         wide_area: 0
2024-06-18 06-51-59.065 [Debug] (Avahi)         multicast: 1
2024-06-18 06-51-59.066 [Debug] (Avahi)         cached: 1
2024-06-18 06-51-59.072 [Info] (Controller) Found server 192.168.0.200:1704
2024-06-18 06-51-59.072 [Info] (Connection) Resolving host IP for: 192.168.0.200
2024-06-18 06-51-59.072 [Info] (Connection) Connecting
2024-06-18 06-51-59.076 [Notice] (Connection) Connected to 192.168.0.200
2024-06-18 06-51-59.076 [Info] (Connection) My MAC: "d8:3a:dd:92:34:3e", socket: 8
2024-06-18 06-51-59.235 [Debug] (Connection) outstanding async_write
2024-06-18 06-51-59.255 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 32, muted: 0
2024-06-18 06-51-59.278 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2024-06-18 06-51-59.278 [Info] (Player) Player name: alsa, device: default, description: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
2024-06-18 06-51-59.278 [Info] (Player) Mixer mode: software, parameters: <none>
2024-06-18 06-51-59.278 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2024-06-18 06-51-59.279 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2024-06-18 06-51-59.304 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2024-06-18 06-51-59.304 [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
2024-06-18 06-51-59.304 [Debug] (Alsa) SUBFORMAT:  STD MSBITS_MAX MSBITS_20 MSBITS_24
2024-06-18 06-51-59.304 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2024-06-18 06-51-59.304 [Debug] (Alsa) FRAME_BITS: [4 640000]
2024-06-18 06-51-59.304 [Debug] (Alsa) CHANNELS: [1 10000]
2024-06-18 06-51-59.304 [Debug] (Alsa) RATE: [4000 4294967295)
2024-06-18 06-51-59.304 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2024-06-18 06-51-59.304 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2024-06-18 06-51-59.304 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2024-06-18 06-51-59.304 [Debug] (Alsa) PERIODS: (0 17247242)
2024-06-18 06-51-59.304 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2024-06-18 06-51-59.304 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2024-06-18 06-51-59.304 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2024-06-18 06-51-59.304 [Debug] (Alsa) TICK_TIME: ALL
2024-06-18 06-51-59.308 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2024-06-18 06-51-59.309 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024
2024-06-18 06-51-59.310 [Debug] (Player) setVolume exp with base 10: 0.32 => 0.121033
2024-06-18 06-51-59.312 [Debug] (Alsa) Resizing buffer from 0 to 16384
2024-06-18 06-51-59.912 [Info] (Controller) diff to server [ms]: 1.50616e+08
2024-06-18 06-52-00.127 [Debug] (Stream) Silent frames: 1116, frames: 2016, age: -23.251
2024-06-18 06-52-00.149 [Debug] (Stats) Chunk: 0        0       0       0       1       63      0
2024-06-18 06-52-01.023 [Debug] (Stats) Chunk: 1        0       0       0       28      43      0
2024-06-18 06-52-02.005 [Debug] (Stats) Chunk: 0        0       0       0       59      63      0
2024-06-18 06-52-03.007 [Debug] (Stats) Chunk: 1        0       0       0       90      43      0
2024-06-18 06-52-04.031 [Debug] (Stats) Chunk: 1        0       0       0       122     43      0
2024-06-18 06-52-05.013 [Debug] (Stats) Chunk: 0        0       0       0       153     63      0
2024-06-18 06-52-06.015 [Debug] (Stats) Chunk: 0        0       0       0       184     43      0
2024-06-18 06-52-07.039 [Debug] (Stats) Chunk: 0        0       0       0       216     43      0
2024-06-18 06-52-08.021 [Debug] (Stats) Chunk: 1        0       0       0       247     63      0
2024-06-18 06-52-09.023 [Debug] (Stats) Chunk: 1        0       0       0       278     43      0
2024-06-18 06-52-10.005 [Debug] (Stats) Chunk: 2        0       0       0       309     63      0
2024-06-18 06-52-11.007 [Debug] (Stats) Chunk: 2        0       0       0       340     43      0
2024-06-18 06-52-12.031 [Debug] (Stats) Chunk: 1        0       0       0       372     43      0
2024-06-18 06-52-13.013 [Debug] (Stats) Chunk: 0        0       0       0       403     63      0
2024-06-18 06-52-14.015 [Debug] (Stats) Chunk: 1        0       0       0       434     43      0
2024-06-18 06-52-15.039 [Debug] (Stats) Chunk: 0        0       0       0       466     43      0
2024-06-18 06-52-16.021 [Debug] (Stats) Chunk: 0        0       0       0       497     63      0
2024-06-18 06-52-17.023 [Debug] (Stats) Chunk: 0        0       0       0       500     43      0
2024-06-18 06-52-18.005 [Debug] (Stats) Chunk: 2        0       0       0       500     63      0
2024-06-18 06-52-19.007 [Debug] (Stats) Chunk: 0        0       0       0       500     43      0
2024-06-18 06-52-20.031 [Debug] (Stats) Chunk: 1        0       0       0       500     43      0
2024-06-18 06-52-21.013 [Debug] (Stats) Chunk: 0        0       0       0       500     63      0
2024-06-18 06-52-22.015 [Debug] (Stats) Chunk: 0        0       0       0       500     43      0
2024-06-18 06-52-23.039 [Debug] (Stats) Chunk: 0        0       0       0       500     43      0
2024-06-18 06-52-24.021 [Debug] (Stats) Chunk: 0        0       0       0       500     63      0
2024-06-18 06-52-25.023 [Debug] (Stats) Chunk: 0        0       0       0       500     43      0
2024-06-18 06-52-26.005 [Debug] (Stats) Chunk: -1       -1      0       0       500     63      0
2024-06-18 06-52-27.007 [Debug] (Stats) Chunk: -2       -3      -1      0       500     43      0
2024-06-18 06-52-28.031 [Debug] (Stats) Chunk: -1       -2      -2      0       500     43      2
2024-06-18 06-52-29.012 [Debug] (Stats) Chunk: -2       -3      -2      0       500     63      5
2024-06-18 06-52-30.014 [Debug] (Stats) Chunk: -2       -2      -2      0       500     43      5
2024-06-18 06-52-31.038 [Debug] (Stats) Chunk: -2       -3      -2      0       500     43      4
2024-06-18 06-52-32.020 [Debug] (Stats) Chunk: -2       -2      -2      0       500     63      5
2024-06-18 06-52-33.022 [Debug] (Stats) Chunk: -2       -2      -2      -1      500     43      4
2024-06-18 06-52-34.004 [Debug] (Stats) Chunk: 0        -1      -2      -1      500     63      4
2024-06-18 06-52-34.558 [Info] (Stream) Exception: Not enough frames available, requested frames: 2016, available: 1531
2024-06-18 06-52-34.558 [Info] (Alsa) Failed to get chunk
2024-06-18 06-52-34.658 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-52-36.663 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-52-38.667 [Debug] (Alsa) Waiting for chunk
2024-06-18 06-52-39.570 [Notice] (Alsa) No chunk received for 5000ms. Closing ALSA.
2024-06-18 06-52-40.681 [Debug] (Alsa) Waiting for chunk
^C2024-06-18 06-52-41.451 [Info] (Snapclient) Received signal 2: Interrupt
2024-06-18 06-52-41.484 [Notice] (Snapclient) Snapclient terminated.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

I should also mention that I am using another snapclient in the same network without problems, which is why I am thinking the problem is on the side of the client described here.

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

This looks rather like the server stops sending audio. Maybe music assistant stops feeding audio to the server.

Hi @badaix ! Thanks so much for looking into this so quickly.

Do you think it is possible that a problem on the server side would lead to aplay no longer working (actually freezing) on the client side? When things go well, I can run aplay even on top of the playing stream from the server, but when the problem occurs, aplay just stops working on the client side whatsoever. Not only is there no sound coming out of the system, but the aplay command actually never finishes and appears to be stuck.

Also, this problem does not appear with another client. Obviously, the two clients could be sending something slightly different to the server, so that it only causes a problem with one client. I can even try with a third client.

Any idea for how to further debug this? Server logs?

from snapcast.

schniepp avatar schniepp commented on August 16, 2024

On my installation, I am running Music Assistant as a container, which includes the snapcast server. I was poking around inside the container but wasn't able to find any snapserver logs. Snapserver inside the container seems to be running entirely with default settings; pretty much everything in snapserver.conf is commented out. In particular, it says this for logging: # when left empty: if running as daemon "system" else "stdout". I can't tell whether it's running as daemon or not. There is nothing in /var/log, and I can't find anything anywhere else. (Not sure whether stdout would go anywhere I can capture it.)

from snapcast.

wambs avatar wambs commented on August 16, 2024

Hi,
I'm having am similar issue with snapcleint. I'm using Music Assistant (from Home assiatnt).
When I change songs by skipping to next song, most of the time snapclient just exits.

2024-07-24 22-28-55.459 [Debug] (Player) setVolume exp with base 10: 0.68 => 0.4207
2024-07-24 22-28-55.461 [Info] (WASAPI) Device accepts format: 48000:32:2
2024-07-24 22-28-55.466 [Info] (WASAPI) Initializing WASAPI in shared mode
2024-07-24 22-28-55.582 [Debug] (WASAPI) New session state = active
2024-07-24 22-28-56.204 [Info] (Controller) diff to server [ms]: -1.72011e+12
2024-07-24 22-28-57.081 [Debug] (Stream) Silent frames: 417, frames: 480, age: -8.703
2024-07-24 22-28-57.091 [Debug] (Stats) Chunk: 0 0 0 0 1 31 0
2024-07-24 22-28-58.002 [Debug] (Stats) Chunk: 0 0 0 0 92 30 0
2024-07-24 22-28-59.002 [Debug] (Stats) Chunk: 0 0 0 0 192 30 0
2024-07-24 22-29-00.001 [Debug] (Stats) Chunk: 0 0 0 0 292 31 0
2024-07-24 22-29-01.003 [Debug] (Stats) Chunk: 0 0 0 0 392 30 0
2024-07-24 22-29-02.001 [Debug] (Stats) Chunk: 0 0 0 0 492 31 0
2024-07-24 22-29-03.001 [Debug] (Stats) Chunk: 0 0 0 0 500 31 0
2024-07-24 22-29-04.001 [Debug] (Stats) Chunk: 0 0 0 0 500 31 0
2024-07-24 22-29-05.001 [Debug] (Stats) Chunk: 0 0 0 0 500 32 0
2024-07-24 22-29-06.002 [Debug] (Stats) Chunk: 0 0 0 0 500 30 0
2024-07-24 22-29-06.652 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2024-07-24 22-29-06.652 [Info] (Player) Player name: wasapi, device: default, description: Speakers (Realtek(R) Audio), idx: 0, sharing mode: shared, parameters:
2024-07-24 22-29-06.652 [Info] (Player) Mixer mode: software, parameters:
2024-07-24 22-29-06.652 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2024-07-24 22-29-06.653 [Debug] (Player) setVolume exp with base 10: 0.68 => 0.4207
2024-07-24 22-29-06.654 [Info] (WASAPI) Device accepts format: 48000:32:2
2024-07-24 22-29-06.656 [Info] (WASAPI) Initializing WASAPI in shared mode
2024-07-24 22-29-06.701 [Info] (Stream) No chunks available
2024-07-24 22-29-06.702 [Info] (WASAPI) Failed to get chunk
2024-07-24 22-29-08.625 [Info] (WASAPI) Waiting for chunk

from snapcast.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.