operating-system icon indicating copy to clipboard operation
operating-system copied to clipboard

Published 20 hours ago • verified publisher icon home-assistant

Hostname homeassistant.local not resolved + errors in avahi browser

Open prog8 opened this issue 2 years ago • 7 comments
trafficstars

Describe the issue you are experiencing

I have home assistant running in my local network. OS is running on virtual machine on Qemu. After changing network settings through UI (switching IPv4 settings from static to dhcp) there is homeassistant.local visible through avahi-browse -alrt. I run this on another machine in the local network.

=   eno1 IPv4 homeassistant [5bc0a1a4ee0b490123123108cc6f55] Workstation          local
   hostname = [homeassistant.local]
   address = [192.168.0.59]

When this hostname is properly resolved the same time avahi-browse reports a set of errors as below

Failed to resolve service '_homeconnect' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_home-assistant' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_workstation' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_workstation' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_homeconnect' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_smb' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_wd' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_privet' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_uscans' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_uscan' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_http-alt' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_scanner' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_printer' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_pdl-datastream' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_ipp' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_http' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_home-assistant' of type '_tcp' in domain 'local': Invalid service type
Failed to resolve service '_hap' of type '_tcp' in domain 'local': Invalid service type

But after a couple minutes homeassistant.local disappears for IPv4 and so the errors in avahi-browse. homeassistant.local is still visible for IPv6

=   eno1 IPv6 homeassistant [5bc0a1a4ee0b490123123108cc6f55] Workstation          local
   hostname = [homeassistant.local]
   address = [fe80::ce52:7b89:2ca5:ebe

Is it some misconfiguration of Homeassistant OS or a bug?

What operating system image do you use?

generic-x86-64 (Generic UEFI capable x86-64 systems)

What version of Home Assistant Operating System is installed?

11.1

Did you upgrade the Operating System.

Yes

Steps to reproduce the issue

  1. Start Operating system in Qemu installed on Debian
  2. Start avahi-browse on another machine and see homeassistant.local being properly resolved
  3. Wait N minutes
  4. Start avahi-browse on another machine again and see no more homeassistant.local resolved on IPv4

Anything in the Supervisor logs that might be useful for us?

ov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7164] audit: op="connection-update" uuid="29791942-35e8-36bb-a530-67dfd3601095" name="Supervisor enp1s0" args="connection.timestamp,ipv4.addresses,ipv4.method,ipv4.dns,ipv4.gateway" pid=129946 uid=0 result="success"
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7202] device (enp1s0): state change: activated -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7209] manager: NetworkManager state is now DISCONNECTING
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7239] device (enp1s0): disconnecting for new activation request.
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7248] audit: op="connection-activate" uuid="29791942-35e8-36bb-a530-67dfd3601095" name="Supervisor enp1s0" pid=129946 uid=0 result="success"
Nov 10 07:31:39 homeassistant systemd[1]: Starting Network Manager Script Dispatcher Service...
Nov 10 07:31:39 homeassistant systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7536] device (enp1s0): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7548] dhcp6 (enp1s0): canceled DHCP transaction
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7549] dhcp6 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7549] dhcp6 (enp1s0): state changed no lease
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client set default route setting: no
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client set MulticastDNS setting: no
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client reset DNS server list.
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7684] manager: NetworkManager state is now DISCONNECTED
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7688] device (enp1s0): Activation: starting connection 'Supervisor enp1s0' (29791942-35e8-36bb-a530-67dfd3601095)
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7699] device (enp1s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7702] manager: NetworkManager state is now CONNECTING
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7704] device (enp1s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7721] device (enp1s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.7735] dhcp4 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client set MulticastDNS setting: yes
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8150] dhcp4 (enp1s0): state changed new lease, address=192.168.0.59
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8156] policy: set 'Supervisor enp1s0' (enp1s0) as default for IPv4 routing and DNS
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client set default route setting: yes
Nov 10 07:31:39 homeassistant systemd-resolved[351]: enp1s0: Bus client set DNS server list to: 8.8.8.8
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8348] device (enp1s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8379] device (enp1s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8388] device (enp1s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8397] manager: NetworkManager state is now CONNECTED_SITE
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.8409] device (enp1s0): Activation: successful, device activated.
Nov 10 07:31:39 homeassistant hassio_supervisor[449]: 23-11-10 08:31:39 INFO (MainThread) [supervisor.host.network] Updating local network information
Nov 10 07:31:39 homeassistant NetworkManager[361]: <info>  [1699601499.9109] manager: NetworkManager state is now CONNECTED_GLOBAL
Nov 10 07:31:41 homeassistant NetworkManager[361]: <info>  [1699601501.3351] dhcp6 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 10 07:31:41 homeassistant NetworkManager[361]: <info>  [1699601501.3643] dhcp6 (enp1s0): state changed new lease
Nov 10 07:31:51 homeassistant systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Nov 10 07:32:00 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:32:00,242:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:32:30 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:32:30,408:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:32:59 homeassistant homeassistant[449]:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
Nov 10 07:32:59 homeassistant homeassistant[449]:                                  Dload  Upload   Total   Spent    Left  Speed
Nov 10 07:32:59 homeassistant homeassistant[449]: [158B blob data]
Nov 10 07:33:00 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:33:00,582:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:33:26 homeassistant hassio_supervisor[449]: 
Nov 10 07:33:30 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:33:30,772:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:34:00 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:34:00,944:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:34:31 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:34:31,088:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:35:01 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:35:01,254:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:35:31 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:35:31,437:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:36:01 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-03250ddad61431931404ec44b3cc949296066aed8df123ea4e9509cc85bdd797-runc.vYFeM6.mount: Deactivated successfully.
Nov 10 07:36:01 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:36:01,579:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:36:01 homeassistant addon_core_duckdns[449]: [08:36:01] INFO: OK
Nov 10 07:36:01 homeassistant addon_core_duckdns[449]: 7.53.3.45
Nov 10 07:36:01 homeassistant addon_core_duckdns[449]: 
Nov 10 07:36:01 homeassistant addon_core_duckdns[449]: NOCHANGE
Nov 10 07:36:31 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:36:31,744:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:36:42 homeassistant hassio_supervisor[449]: 23-11-10 08:36:42 INFO (MainThread) [supervisor.host.info] Updating local host information
Nov 10 07:36:42 homeassistant audit: BPF prog-id=459 op=LOAD
Nov 10 07:36:42 homeassistant kernel: audit: type=1334 audit(1699601802.851:1575): prog-id=459 op=LOAD
Nov 10 07:36:42 homeassistant kernel: audit: type=1334 audit(1699601802.852:1576): prog-id=460 op=LOAD
Nov 10 07:36:42 homeassistant kernel: audit: type=1334 audit(1699601802.853:1577): prog-id=461 op=LOAD
Nov 10 07:36:42 homeassistant audit: BPF prog-id=460 op=LOAD
Nov 10 07:36:42 homeassistant audit: BPF prog-id=461 op=LOAD
Nov 10 07:36:42 homeassistant systemd[1]: Starting Hostname Service...
Nov 10 07:36:43 homeassistant systemd[1]: Started Hostname Service.
Nov 10 07:36:43 homeassistant audit: BPF prog-id=462 op=LOAD
Nov 10 07:36:43 homeassistant audit: BPF prog-id=463 op=LOAD
Nov 10 07:36:43 homeassistant audit: BPF prog-id=464 op=LOAD
Nov 10 07:36:43 homeassistant kernel: audit: type=1334 audit(1699601803.197:1578): prog-id=462 op=LOAD
Nov 10 07:36:43 homeassistant kernel: audit: type=1334 audit(1699601803.198:1579): prog-id=463 op=LOAD
Nov 10 07:36:43 homeassistant kernel: audit: type=1334 audit(1699601803.198:1580): prog-id=464 op=LOAD
Nov 10 07:36:43 homeassistant systemd[1]: Starting Time & Date Service...
Nov 10 07:36:43 homeassistant systemd[1]: Started Time & Date Service.
Nov 10 07:36:43 homeassistant hassio_supervisor[449]: 23-11-10 08:36:43 INFO (MainThread) [supervisor.host.services] Updating service information
Nov 10 07:36:43 homeassistant hassio_supervisor[449]: 23-11-10 08:36:43 INFO (MainThread) [supervisor.host.network] Updating local network information
Nov 10 07:36:43 homeassistant hassio_supervisor[449]: 23-11-10 08:36:43 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
Nov 10 07:36:43 homeassistant hassio_supervisor[449]: 23-11-10 08:36:43 INFO (MainThread) [supervisor.host.manager] Host information reload completed
Nov 10 07:37:01 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-03250ddad61431931404ec44b3cc949296066aed8df123ea4e9509cc85bdd797-runc.eQIHPM.mount: Deactivated successfully.
Nov 10 07:37:01 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:37:01,913:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:37:13 homeassistant systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Nov 10 07:37:13 homeassistant audit: BPF prog-id=461 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.264:1581): prog-id=461 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.264:1582): prog-id=460 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.264:1583): prog-id=459 op=UNLOAD
Nov 10 07:37:13 homeassistant audit: BPF prog-id=460 op=UNLOAD
Nov 10 07:37:13 homeassistant audit: BPF prog-id=459 op=UNLOAD
Nov 10 07:37:13 homeassistant systemd[1]: systemd-timedated.service: Deactivated successfully.
Nov 10 07:37:13 homeassistant audit: BPF prog-id=464 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.523:1584): prog-id=464 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.523:1585): prog-id=463 op=UNLOAD
Nov 10 07:37:13 homeassistant kernel: audit: type=1334 audit(1699601833.523:1586): prog-id=462 op=UNLOAD
Nov 10 07:37:13 homeassistant audit: BPF prog-id=463 op=UNLOAD
Nov 10 07:37:13 homeassistant audit: BPF prog-id=462 op=UNLOAD
Nov 10 07:37:32 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-03250ddad61431931404ec44b3cc949296066aed8df123ea4e9509cc85bdd797-runc.xRL6ZD.mount: Deactivated successfully.
Nov 10 07:37:32 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:37:32,110:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:38:02 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:38:02,277:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:38:26 homeassistant hassio_supervisor[449]: 
Nov 10 07:38:32 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:38:32,456:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:38:32 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-03250ddad61431931404ec44b3cc949296066aed8df123ea4e9509cc85bdd797-runc.uqBtqY.mount: Deactivated successfully.
Nov 10 07:39:02 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:39:02,650:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
Nov 10 07:39:02 homeassistant systemd[1]: run-docker-runtime\x2drunc-moby-03250ddad61431931404ec44b3cc949296066aed8df123ea4e9509cc85bdd797-runc.WxykgI.mount: Deactivated successfully.
Nov 10 07:39:32 homeassistant addon_core_configurator[449]: INFO:2023-11-10 08:39:32,821:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -

Anything in the Host logs that might be useful for us?

nothing

System information

System Information

version core-2023.11.1
installation_type Home Assistant OS
dev false
hassio true
docker true
user root
virtualenv false
python_version 3.11.6
os_name Linux
os_version 6.1.59
arch x86_64
timezone Europe/Warsaw
config_dir /config
Home Assistant Cloud
logged_in false
can_reach_cert_server ok
can_reach_cloud_auth ok
can_reach_cloud ok
Home Assistant Supervisor
host_os Home Assistant OS 11.1
update_channel stable
supervisor_version supervisor-2023.11.0
agent_version 1.6.0
docker_version 24.0.6
disk_total 30.8 GB
disk_used 5.4 GB
healthy true
supported true
board ova
supervisor_api ok
version_api ok
installed_addons Terminal & SSH (9.7.1), NGINX Home Assistant SSL proxy (3.5.0), Duck DNS (1.15.0), File editor (5.6.0), Google Assistant SDK (2.5.0), Samba Backup (5.2.0)
Dashboards
dashboards 1
resources 0
views 2
mode storage
Recorder
oldest_recorder_run 31 października 2023 09:19
current_recorder_run 8 listopada 2023 18:42
estimated_db_size 10.70 MiB
database_engine sqlite
database_version 3.41.2

Additional information

No response

prog8 avatar Nov 10 '23 07:11 prog8

OS is running on virtual machine on Qemu.

generic-x86-64 (Generic UEFI capable x86-64 systems)

We have a specific image for virtualization, named "ova". I recommend using this over generic-x86-64.

I am not very familiar with avahi-browse, but from what I understand it is mostly useful to browse services. What you attempt is to resolve host name. Both, services and host name resolving use the mDNS mechanism to communicate, but these things are not the same. Maybe avahi-browse output just hides certain information/messages? :thinking:

To test if Home Assistant properly announces IPv4 and IPv6 addressing via mDNS try using:

avahi-resolve -4 --name homeassistant.local

avahi-resolve -6 --name homeassistant.local

FWIW, HAOS uses systemd as mDNS responder.

agners avatar Dec 05 '23 10:12 agners

That's what I get this

$ avahi-resolve -4 --name homeassistant.local                  
Failed to resolve host name 'homeassistant.local': Timeout reached
$ avahi-resolve -6 --name homeassistant.local                  
homeassistant.local	fe80::ce52:7b89:2ca5:ebe2

But then after I reboot machine I see IP address for IPv4 for a moment

$ avahi-resolve -4 --name homeassistant.local                  
homeassistant.local	192.168.0.59

And then it disappears again.

prog8 avatar Dec 05 '23 10:12 prog8

Do you have a second instance named homeassistant in your home maybe (e.g. a test instance?).

Maybe ha host logs --identifier systemd-resolved has clues?

It isn't reproducible here: I have a (renamed) instance I can query using -4 and -6 even hours after startup.

agners avatar Dec 05 '23 14:12 agners

I don't have any more instances but logs you requested look very suspicious

Dec 05 11:25:51 homeassistant systemd-resolved[345]: enp1s0: Bus client set default route setting: yes
Dec 05 11:25:51 homeassistant systemd-resolved[345]: enp1s0: Bus client set MulticastDNS setting: yes
Dec 05 11:25:51 homeassistant systemd-resolved[345]: enp1s0: Bus client set DNS server list to: 8.8.8.8
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client set default route setting: no
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client set MulticastDNS setting: no
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client reset DNS server list.
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client set default route setting: yes
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client set MulticastDNS setting: yes
Dec 05 11:25:59 homeassistant systemd-resolved[345]: enp1s0: Bus client set DNS server list to: 8.8.8.8

So it seems MulticastDNS setting: yes is then switched after a couple seconds to MulticastDNS setting: no. Could it be our problem? If yes how the setting could have been changed automatically?

prog8 avatar Dec 05 '23 14:12 prog8

I do have similar logs, but it always ends with a yes, so I don't think that is the problem. :thinking:

Nov 28 17:54:24 ha-shelf1-rpi3plus systemd-resolved[391]: eth0: Bus client set MulticastDNS setting: no
Nov 28 17:54:24 ha-shelf1-rpi3plus systemd-resolved[391]: eth0: Bus client reset DNS server list.
Nov 28 17:54:24 ha-shelf1-rpi3plus systemd-resolved[391]: eth0: Bus client set MulticastDNS setting: yes

agners avatar Dec 06 '23 07:12 agners

Can you change the hostname and see if that changes the behavior for you (under Settings > System > Network)?

agners avatar Dec 06 '23 07:12 agners

Hi @agners thank you for new suggestions. I changed the hostname to ha but still doesn't see ha.local in my network. The funny thing is that I see this hostname = [35f8df4618044e8ab08ae504f933aaac.local] address = [192.168.0.59] which points to home assistant. Not sure what this identifier is about but for sure is related to HA.

prog8 avatar Dec 06 '23 08:12 prog8

There hasn't been any activity on this issue recently. To keep our backlog manageable we have to clean old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant OS version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] avatar Mar 06 '24 05:03 github-actions[bot]