search

badaix / snapcast

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

`snapclient --host='some.cname.dns.record'` fails to connect while `snapclient --host='ip.of.server'` succeeds #1216

Closed davidandreoletti closed 7 months ago

davidandreoletti commented 8 months ago

Describe the bug snapclient fails to connect to snapserver when the hostname is a CNAME while using snapserver's host IP connects successfully.

Steps to Reproduce

  1. snapclient --host='some.cname.dns.record'
    • cannot connect to the snapserver
  2. snapclient --host='ip.of.server'
    • can connect to the snapserver

Environment details

Attach logfile if applicable Generate logs with snapclient --logfilter debug or snapserver --logging.filter debug if possible and paste them in the following codeblock

Logs when connections fails

snapclient --host="snapserver.audio.mediacenter.home" --port=1704 --logfilter='*:debug'
2024-03-27 16-10-56.098 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-03-27 16-10-56.141 [Info] (Snapclient) Version 0.26.0
2024-03-27 16-10-56.141 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-03-27 16-10-56.150 [Info] (Connection) Connecting
2024-03-27 16-10-56.152 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
2024-03-27 16-10-56.153 [Error] (Controller) Error: Connection refused
2024-03-27 16-10-56.153 [Debug] (Connection) Disconnecting
2024-03-27 16-10-56.153 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected
2024-03-27 16-10-56.153 [Debug] (Connection) Disconnected
2024-03-27 16-10-57.153 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-03-27 16-10-57.158 [Info] (Connection) Connecting
2024-03-27 16-10-57.161 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
2024-03-27 16-10-57.161 [Error] (Controller) Error: Connection refused
2024-03-27 16-10-57.161 [Debug] (Connection) Disconnecting
2024-03-27 16-10-57.161 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected
2024-03-27 16-10-57.161 [Debug] (Connection) Disconnected
^C2024-03-27 16-10-57.170 [Info] (Snapclient) Received signal 2: Interrupt
2024-03-27 16-10-57.171 [Debug] (Connection) Disconnecting
2024-03-27 16-10-57.171 [Debug] (Connection) Not connected
2024-03-27 16-10-57.171 [Notice] (Snapclient) Snapclient terminated.

Logs when connections succeeds

snapclient --host="192.168.3.1" --port=1704 --logfilter='*:debug'

2024-03-27 16-11-24.230 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-03-27 16-11-24.273 [Info] (Snapclient) Version 0.26.0
2024-03-27 16-11-24.274 [Info] (Connection) Resolving host IP for: 192.168.3.1
2024-03-27 16-11-24.274 [Info] (Connection) Connecting
2024-03-27 16-11-24.356 [Notice] (Connection) Connected to 192.168.3.1
2024-03-27 16-11-24.357 [Info] (Connection) My MAC: "02:51:03:41:2e:99", socket: 8
2024-03-27 16-11-24.440 [Debug] (Connection) outstanding async_write
2024-03-27 16-11-24.458 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 80, muted: 0

DNS record:

dig snapserver.audio.mediacenter.home

; <<>> DiG 9.18.24-1-Debian <<>> snapserver.audio.mediacenter.home
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 24255
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;snapserver.audio.mediacenter.home. IN  A

;; ANSWER SECTION:
snapserver.audio.mediacenter.home. 0 IN CNAME   my-machine-hw1.lan.
my-machine-hw1.lan. 0   IN  A   192.168.3.1

;; Query time: 8 msec
;; SERVER: 192.168.3.1#53(192.168.3.1) (UDP)
;; WHEN: Wed Mar 27 16:15:47 UTC 2024
;; MSG SIZE  rcvd: 113

Investigation

Looks like snapclient's performs no name resolution by default due to numeric_service.html

badaix commented 8 months ago

Does ping resolve the name?

davidandreoletti commented 8 months ago

Does ping resolve the name?

Yes

ping snapserver.audio.mediacenter.home
PING my-machine-hw1.lan (192.168.3.1): 56 data bytes
64 bytes from 192.168.3.1: icmp_seq=0 ttl=64 time=2.232 ms
badaix commented 8 months ago

Please try the latest version of the develop branch, it will log all resolved IP addresses.

davidandreoletti commented 7 months ago

I installed this snapcast_armhf-debian-bookworm-1184cf1db39e6106a3442ae92e92f5b872ac1b62's snapclient binary

Logs with CNAME record:

/usr/bin/snapclient --host=snapserver.audio.mediacenter.home --port=1704 --hostID='davida-audiospeaker-hw0' --instance=1 --priority=-6 --logsink=stdout --logfilter='*:debug'
2024-03-28 04-23-56.876 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-03-28 04-23-56.960 [Info] (Snapclient) Version 0.28.0.1, revision 1184cf1d
2024-03-28 04-23-56.960 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-03-28 04-23-56.968 [Debug] (Connection) Resolved IP: fd5e:29da:e475::1
2024-03-28 04-23-56.968 [Debug] (Connection) Resolved IP: 192.168.3.1
2024-03-28 04-23-56.968 [Info] (Connection) Connecting to [fd5e:29da:e475::1]:1704
2024-03-28 04-23-56.972 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
2024-03-28 04-23-56.972 [Error] (Controller) Error: Connection refused
2024-03-28 04-23-56.972 [Debug] (Connection) Disconnecting
2024-03-28 04-23-56.972 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected

Log without CNAME record:

 /usr/bin/snapclient --host=192.168.3.1 --port=1704 --hostID='davida-audiospeaker-hw0' --instance=1 --priority=-6 --logsink=stdout --logfilter='*:debug'
024-03-28 04-25-57.667 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-03-28 04-25-57.711 [Info] (Snapclient) Version 0.28.0.1, revision 1184cf1d
2024-03-28 04-25-57.712 [Info] (Connection) Resolving host IP for: 192.168.3.1
2024-03-28 04-25-57.712 [Debug] (Connection) Resolved IP: 192.168.3.1
2024-03-28 04-25-57.712 [Info] (Connection) Connecting to 192.168.3.1:1704
2024-03-28 04-25-57.715 [Notice] (Connection) Connected to 192.168.3.1
2024-03-28 04-25-57.716 [Info] (Connection) My MAC: "02:51:03:41:2e:99", socket: 8

So the snapclient is connecting with a IPv6 address fd5e.... to the snapserver and the snapserver is not listening on IPv6 by default.

I configured IPv6 support for snapserver (v0.28.0 beta1) and the client can now connect successfully.

/usr/bin/snapclient --host=snapserver.audio.mediacenter.home --port=1704 --hostID='davida-audiospeaker-hw0' --instance=1 --priority=-6 --logsink=stdout --logfilter='*:debug'
2024-03-28 04-41-52.536 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-03-28 04-41-52.654 [Info] (Snapclient) Version 0.28.0.1, revision 1184cf1d
2024-03-28 04-41-52.654 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-03-28 04-41-52.670 [Debug] (Connection) Resolved IP: fd5e:29da:e475::1
2024-03-28 04-41-52.670 [Debug] (Connection) Resolved IP: 192.168.3.1
2024-03-28 04-41-52.670 [Info] (Connection) Connecting to [fd5e:29da:e475::1]:1704
2024-03-28 04-41-52.677 [Notice] (Connection) Connected to fd5e:29da:e475::1
2024-03-28 04-41-52.678 [Info] (Connection) My MAC: "02:51:03:41:2e:99", socket

@badaix What do you suggest to get the snapclient to prefer IPv4 over IPv6 when both IPs are resolved ?

badaix commented 7 months ago

I don't know what the best practice is to give a hint to a client on what kind of IP address to resolve, but I think it doesn't make sense to not try other resolved addresses, if the first one is not working. So I've added a loop through all IP addresses, in case a connection attempt failed. You can find packages here: https://github.com/badaix/snapcast/actions/runs/8465628529

davidandreoletti commented 7 months ago

I don't know what the best practice is to give a hint to a client on what kind of IP address to resolve, but I think it doesn't make sense to not try other resolved addresses, if the first one is not working. So I've added a loop through all IP addresses, in case a connection attempt failed. You can find packages here: https://github.com/badaix/snapcast/actions/runs/8465628529

Both resolved IPs are tried and eventually one succeeds.

024-04-01 09-14-28.926 [Debug] (Connection) Disconnected
2024-04-01 09-14-29.926 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-04-01 09-14-29.929 [Debug] (Connection) Resolved IP: fdd1:f583:cc37::1
2024-04-01 09-14-29.929 [Debug] (Connection) Resolved IP: 192.168.3.1
2024-04-01 09-14-29.929 [Info] (Connection) Connecting to [fdd1:f583:cc37::1]:1704
2024-04-01 09-14-29.930 [Info] (Connection) Connecting to 192.168.3.1:1704
2024-04-01 09-14-29.932 [Error] (Connection) Failed to connect to host 'snapserver.audio.mediacenter.home', error: Connection refused
2024-04-01 09-14-29.932 [Error] (Controller) Error: Connection refused
2024-04-01 09-14-29.932 [Debug] (Connection) Disconnecting
2024-04-01 09-14-29.932 [Error] (Connection) Error in socket shutdown: Transport endpoint is not connected
2024-04-01 09-14-29.932 [Debug] (Connection) Disconnected
2024-04-01 09-14-30.933 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-04-01 09-15-06.620 [Error] (Connection) Failed to resolve host 'snapserver.audio.mediacenter.home', error: Host not found (authoritative)
2024-04-01 09-15-06.620 [Error] (Controller) Error: Host not found (authoritative)
2024-04-01 09-15-06.620 [Debug] (Connection) Disconnecting
2024-04-01 09-15-06.621 [Debug] (Connection) Not connected
2024-04-01 09-15-07.621 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-04-01 09-15-19.919 [Error] (Connection) Failed to resolve host 'snapserver.audio.mediacenter.home', error: Host not found (authoritative)
2024-04-01 09-15-19.919 [Error] (Controller) Error: Host not found (authoritative)
2024-04-01 09-15-19.919 [Debug] (Connection) Disconnecting
2024-04-01 09-15-19.919 [Debug] (Connection) Not connected
2024-04-01 09-15-20.920 [Info] (Connection) Resolving host IP for: snapserver.audio.mediacenter.home
2024-04-01 09-15-20.929 [Debug] (Connection) Resolved IP: 192.168.3.1
2024-04-01 09-15-20.930 [Info] (Connection) Connecting to 192.168.3.1:1704
2024-04-01 09-15-20.936 [Notice] (Connection) Connected to 192.168.3.1

Bug resolved. Thank you @badaix