WIP: snapclient 0.28.0 (armbian/armv7l) despite repeated attempts cannot connect to snapserver 0.28.0 (openwrt/arm64) after some time.

davidandreoletti commented 5 months ago

Note: The information needed to figure out what's happening is still being gathered. Relevant fields will be updated as discovery process progresses.

Describe the bug

After a hardware reboot, both snapcast client and server are started, the client can connect to the server and receives music.
Then upon an unknown set of conditions, the snapcast client cannot connect to the server.
- the IPs (IPv4 / IPv6) resolved by snapclient matches the snapserver IPs.
- Snapserver machine is reachable:
  - over ICMP (ping)
  - netstat reports the server is still listening on port 1704/1705/1780.
  - nc can reach snapserver (and snapserver accepts the connection!)

Steps to Reproduce

No confirmed step available at the moment
(suspected) Snapserver or snapclient idle for 2+ days

Environment details

snapserver machine

OS: (server) OpenWRT SNAPSHOT
Architecture: aarch64
snapserver version: 0.28.0

snapclient machine

armbian 23.05 (debian bookworm)
Architecture: armv7l (distro packages from 'armhf')
snapclient version: 0.28.0

Log files

Snapserver logs after --hardware-- reboot: client can connect to the server

Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Version 0.28.0
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Adding source: pipe:///tmp/snapfifo?name=default
Mon Jun  3 14:59:56 2024 user.notice snapserver[10312]: Settings file: "//.config/snapserver/server.json"
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Adding service 'Snapcast'
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Using HTTP host name: davida-router-hw1
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: PcmStream: default, sampleFormat: 48000:16:2
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: PipeStream mode: create
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: 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"}
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Init - compression level: 2
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Creating TCP acceptor for address: 0.0.0.0, port: 1705
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Creating HTTP acceptor for address: 0.0.0.0, port: 1780
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Creating stream acceptor for address: 0.0.0.0, port: 1704
Mon Jun  3 14:59:56 2024 user.info snapserver[10312]: Number of threads: 4, hw threads: 6
Mon Jun  3 14:59:56 2024 user.err snapserver[10312]: Error reading message: End of file, length: 0, ec: asio.misc:2
Mon Jun  3 14:59:57 2024 user.info snapserver[10312]: Service 'Snapcast' successfully established.
Mon Jun  3 15:00:05 2024 user.notice snapserver[10312]: StreamServer::NewConnection: 192.168.3.137
Mon Jun  3 15:00:05 2024 user.info snapserver[10312]: Hello from davida-audiospeaker-hw0, host: davida-audiospeaker-hw0, v0.28.0, ClientName: Snapclient, OS: Armbian-unofficial 24.5.0-trunk bookworm, Arch: armv7l, Protocol version: 2

Snapserver logs after --snapserver-- restart and unknown set of conditions triggered: client still cannot connect to the server

Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Version 0.28.0
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Adding source: pipe:///tmp/snapfifo?name=default
Sun Aug 18 13:45:27 2024 user.notice snapserver[2894]: Settings file: "//.config/snapserver/server.json"
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Adding service 'Snapcast'
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Using HTTP host name: davida-router-hw1
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: PcmStream: default, sampleFormat: 48000:16:2
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: PipeStream mode: create
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: 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"}
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Init - compression level: 2
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Creating TCP acceptor for address: 0.0.0.0, port: 1705
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Creating HTTP acceptor for address: 0.0.0.0, port: 1780
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Creating stream acceptor for address: 0.0.0.0, port: 1704
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: Number of threads: 4, hw threads: 6
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: State changed: default, state: idle => playing
Sun Aug 18 13:45:27 2024 user.info snapserver[2894]: onStateChanged (default): playing
Sun Aug 18 13:45:28 2024 user.info snapserver[2894]: Service 'Snapcast' successfully established.
Sun Aug 18 13:46:46 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:46:46 2024 user.info snapserver[2894]: State changed: default, state: playing => idle
Sun Aug 18 13:46:46 2024 user.info snapserver[2894]: onStateChanged (default): idle
Sun Aug 18 13:46:50 2024 user.err snapserver[2894]: Error reading message: End of file, length: 3460, ec: asio.misc:2
Sun Aug 18 13:46:50 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:46:50 2024 user.info snapserver[2894]: State changed: default, state: idle => playing
Sun Aug 18 13:46:50 2024 user.info snapserver[2894]: onStateChanged (default): playing
Sun Aug 18 13:47:29 2024 user.info snapserver[2894]: onResync (default): 1.36914 ms
Sun Aug 18 13:51:44 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:51:44 2024 user.info snapserver[2894]: State changed: default, state: playing => idle
Sun Aug 18 13:51:44 2024 user.info snapserver[2894]: onStateChanged (default): idle
Sun Aug 18 13:51:47 2024 user.err snapserver[2894]: Error reading message: End of file, length: 3328, ec: asio.misc:2
Sun Aug 18 13:51:47 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:51:47 2024 user.info snapserver[2894]: State changed: default, state: idle => playing
Sun Aug 18 13:51:47 2024 user.info snapserver[2894]: onStateChanged (default): playing
Sun Aug 18 13:53:25 2024 user.info snapserver[2894]: onResync (default): 0.143769 ms
Sun Aug 18 13:53:58 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:53:58 2024 user.info snapserver[2894]: State changed: default, state: playing => idle
Sun Aug 18 13:53:58 2024 user.info snapserver[2894]: onStateChanged (default): idle
Sun Aug 18 13:54:01 2024 user.err snapserver[2894]: Error reading message: End of file, length: 952, ec: asio.misc:2
Sun Aug 18 13:54:01 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:54:01 2024 user.info snapserver[2894]: State changed: default, state: idle => playing
Sun Aug 18 13:54:01 2024 user.info snapserver[2894]: onStateChanged (default): playing
Sun Aug 18 13:55:37 2024 user.info snapserver[2894]: onResync (default): 6.79598 ms
Sun Aug 18 13:56:25 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:56:25 2024 user.info snapserver[2894]: State changed: default, state: playing => idle
Sun Aug 18 13:56:25 2024 user.info snapserver[2894]: onStateChanged (default): idle
Sun Aug 18 13:56:28 2024 user.err snapserver[2894]: Error reading message: End of file, length: 1524, ec: asio.misc:2
Sun Aug 18 13:56:29 2024 user.info snapserver[2894]: No data since 120 ms, switching to idle
Sun Aug 18 13:56:29 2024 user.info snapserver[2894]: State changed: default, state: idle => playing
Sun Aug 18 13:56:29 2024 user.info snapserver[2894]: onStateChanged (default): playing
Sun Aug 18 13:57:11 2024 user.info snapserver[2894]: onResync (default): 10.9063 ms

Snapclient logs when the reconnection fails:

Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.111 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.126 [Debug] (Connection) Resolved IP: fd24:f3fd:b0e5::1
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.126 [Debug] (Connection) Resolved IP: 192.168.3.1
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.126 [Info] (Connection) Connecting to [fd24:f3fd:b0e5::1]:1704
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.130 [Info] (Connection) Connecting to 192.168.3.1:1704
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.133 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.134 [Error] (Controller) Error: Connection refused
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.134 [Debug] (Connection) Disconnecting
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.134 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected
Aug 18 13:34:22 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-22.134 [Debug] (Connection) Disconnected
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.135 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.153 [Debug] (Connection) Resolved IP: fd24:f3fd:b0e5::1
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.153 [Debug] (Connection) Resolved IP: 192.168.3.1
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.153 [Info] (Connection) Connecting to [fd24:f3fd:b0e5::1]:1704
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.157 [Info] (Connection) Connecting to 192.168.3.1:1704
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.160 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.160 [Error] (Controller) Error: Connection refused
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.161 [Debug] (Connection) Disconnecting
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.161 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected
Aug 18 13:34:23 davida-audiospeaker-hw0 snapclient[1410]: 2024-08-18 13-34-23.161 [Debug] (Connection) Disconnected

When the reconnection fails from snapclient, the snapcast server is definitely reachable by other means

nc snapserver.audio.mediacenter.home 1704

...non intelligble output as expected...

+L%(lD*LZ)*E"<2PH(`d    Cf$A %7d&bE*
          %9+f-Jn*-Y*(=%XB"Qn
RUbEm.[|VB[QѺY
              8P
                @@f -h57b-JByB-a=B"&jK !Bdf$Bf&
                                               f=DU!
                                                    "'lBQ       y@YP$$px 3O,t$  JlyS)pAa!(L!lܤjB)|HG
                                                                                                    !#V!x
...

Upon receiving the nc initiated TCP connection, snapserver accept a new 'plain' connection and outputs:

Sun Aug 18 13:40:54 2024 user.notice snapserver[1747]: StreamServer::NewConnection: 192.168.3.137
Sun Aug 18 13:40:55 2024 user.err snapserver[1747]: Error reading message header of length 0: End of file
Sun Aug 18 13:40:55 2024 user.info snapserver[1747]: onDisconnect:
... no more logs...

gpayer commented 5 months ago

I have kind of the same problem, not sure. As soon as the music is stopped no new chunks are recognized, it's always "waiting for new chunks". Only a restart gets the music playing.

davidandreoletti commented 5 months ago

The issue described is different:

The snapcast server (machine A) is up
The snapcast client (machine B) is up and connected to the snapcast server. I can play music
Stop playing music for a few days
Try playing music again ... no music played because the snapcast client can't connect to the snapcast server (still up / no network issue nor firewall problem).

badaix commented 4 months ago

Note: The information needed to figure out what's happening is still being gathered. Relevant fields will be updated as discovery process progresses.

Please reopen, when you've gathered all data. Client logs would help. I've once seen a client failing to resolve the MDNS-broadcasted server IP, so it might help to pass the server's IP to the client with --host.

davidandreoletti commented 3 months ago

@badaix I updated the ticket's details with the requested logs. Now waiting for you to reopen it - please.

badaix / snapcast

WIP: snapclient 0.28.0 (armbian/armv7l) despite repeated attempts cannot connect to snapserver 0.28.0 (openwrt/arm64) after some time. #1243