home-assistant / supervisor

:house_with_garden: Home Assistant Supervisor
https://home-assistant.io/hassio/
Apache License 2.0
1.75k stars 639 forks source link

'AddonManager.update' blocked from execution, no host internet connection #3011

Closed Masterz69 closed 2 years ago

Masterz69 commented 3 years ago

Describe the issue you are experiencing

On Supervisor reload internet connection is good enough - no errosrs:

21-07-15 17:21:28 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
HA manage to get list of updates (show available new versions), but fails to proceed with actual add-on update:
21-07-15 17:21:49 WARNING (MainThread) [supervisor.jobs] 'AddonManager.update' blocked from execution, no host internet connection

Supervisor getting list of new versions and show available updates in UI. But fails to proceed with actual update.

After full HOST restart - Supervisor managed to update one add-on. Next day message

'AddonManager.update' blocked from execution, no host internet connection

appears again !!!

What is the used version of the Supervisor?

supervisor-2021.06.8

What type of installation are you running?

Home Assistant OS

Which operating system are you running on?

Home Assistant Operating System

What is the version of your installed operating system?

6.1

What version of Home Assistant Core is installed?

core-2021.6.6

Steps to reproduce the issue

Just trying to update add-on.

Supervisor restart not helping. HOST restarts - help, for some time.

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

21-07-15 17:21:28 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
21-07-15 17:21:28 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-07-15 17:21:49 INFO (MainThread) [supervisor.snapshots] Creating new partial-snapshot with slug c63238c1
21-07-15 17:21:49 INFO (MainThread) [supervisor.snapshots] Snapshotting c63238c1 store Add-ons
21-07-15 17:21:49 INFO (MainThread) [supervisor.addons.addon] Building snapshot for add-on a0d7b954_phpmyadmin
21-07-15 17:21:49 INFO (MainThread) [supervisor.addons.addon] Finish snapshot for addon a0d7b954_phpmyadmin
21-07-15 17:21:49 INFO (MainThread) [supervisor.snapshots] Creating partial-snapshot with slug c63238c1 completed
21-07-15 17:21:49 WARNING (MainThread) [supervisor.jobs] 'AddonManager.update' blocked from execution, no host internet connection

21-07-16 17:29:26 INFO (MainThread) [supervisor.misc.scheduler] Shutting down scheduled tasks
21-07-16 17:29:26 INFO (MainThread) [supervisor.api] Stopping API on 172.30.32.2
21-07-16 17:29:26 INFO (MainThread) [supervisor.hardware.monitor] Stopped Supervisor hardware monitor
21-07-16 17:29:26 INFO (MainThread) [supervisor.core] Supervisor is down - 100
21-07-16 17:29:26 INFO (MainThread) [__main__] Closing Supervisor
21-07-16 14:29:30 INFO (MainThread) [__main__] Initializing Supervisor setup
21-07-16 14:29:30 INFO (MainThread) [supervisor.bootstrap] Initializing Supervisor Sentry
21-07-16 17:29:30 INFO (MainThread) [supervisor.bootstrap] Seting up coresys for machine: raspberrypi4-64
21-07-16 17:29:30 INFO (SyncWorker_0) [supervisor.docker.supervisor] Attaching to Supervisor homeassistant/aarch64-hassio-supervisor with version 2021.06.8
21-07-16 17:29:30 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-07-16 17:29:30 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.INITIALIZE
21-07-16 17:29:30 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-07-16 17:29:30 INFO (MainThread) [__main__] Setting up Supervisor
21-07-16 17:29:31 INFO (MainThread) [supervisor.api] Starting API on 172.30.32.2
21-07-16 17:29:31 INFO (MainThread) [supervisor.hardware.monitor] Started Supervisor hardware monitor
21-07-16 17:29:32 INFO (MainThread) [supervisor.host.info] Updating local host information
21-07-16 17:29:32 INFO (MainThread) [supervisor.host.services] Updating service information
21-07-16 17:29:32 INFO (MainThread) [supervisor.host.network] Updating local network information
21-07-16 17:29:45 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-16 17:29:45 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
21-07-16 17:29:45 INFO (MainThread) [supervisor.host] Host information reload completed
21-07-16 17:29:45 INFO (MainThread) [supervisor.host.apparmor] Loading AppArmor Profiles: {'hassio-supervisor'}
21-07-16 17:29:45 INFO (MainThread) [supervisor.host.services] Reloading local service hassos-apparmor.service
21-07-16 17:29:46 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-dns with version 2021.06.0
21-07-16 17:29:46 INFO (MainThread) [supervisor.plugins.dns] Updated /etc/resolv.conf
21-07-16 17:29:46 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to homeassistant/aarch64-hassio-audio with version 2021.04.0
21-07-16 17:29:46 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to homeassistant/aarch64-hassio-cli with version 2021.05.1
21-07-16 17:29:46 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-observer with version 2021.06.0
21-07-16 17:29:46 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to homeassistant/aarch64-hassio-multicast with version 2021.04.0
21-07-16 17:29:46 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
21-07-16 17:29:52 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/raspberrypi4-64-homeassistant with version 2021.6.6
21-07-16 17:29:52 INFO (MainThread) [supervisor.homeassistant.secrets] Loaded 5 Home Assistant secrets
21-07-16 17:29:52 INFO (MainThread) [supervisor.hassos] Detect Home Assistant Operating System 6.1 / BootSlot A
21-07-16 17:29:53 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/core repository
21-07-16 17:29:53 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/a0d7b954 repository
21-07-16 17:29:53 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/cebe7a76 repository
21-07-16 17:29:53 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/15d21743 repository
21-07-16 17:29:53 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/45df7312 repository
21-07-16 17:29:54 INFO (MainThread) [supervisor.store] Loading add-ons from store: 66 all - 66 new - 0 remove
21-07-16 17:29:54 INFO (MainThread) [supervisor.addons] Found 9 installed add-ons
21-07-16 17:29:54 INFO (SyncWorker_3) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-mariadb with version 2.4.0
21-07-16 17:29:54 INFO (SyncWorker_4) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-mosquitto with version 5.1.1
21-07-16 17:29:54 INFO (SyncWorker_2) [supervisor.docker.interface] Attaching to thomasmauerer/samba-backup-aarch64 with version 4.5.0
21-07-16 17:29:54 INFO (SyncWorker_1) [supervisor.docker.interface] Attaching to ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.4.3
21-07-16 17:29:54 INFO (SyncWorker_6) [supervisor.docker.interface] Attaching to ghcr.io/hassio-addons/zwavejs2mqtt/aarch64 with version 0.19.0
21-07-16 17:29:54 INFO (SyncWorker_7) [supervisor.docker.interface] Attaching to ghcr.io/hassio-addons/ssh/aarch64 with version 8.2.3
21-07-16 17:29:54 INFO (SyncWorker_5) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-samba with version 9.5.0
21-07-16 17:29:54 INFO (SyncWorker_0) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-configurator with version 5.3.1
21-07-16 17:29:54 INFO (SyncWorker_3) [supervisor.docker.interface] Attaching to zigbee2mqtt/zigbee2mqtt-aarch64 with version 1.18.2-1
21-07-16 17:29:54 INFO (MainThread) [supervisor.snapshots] Found 14 snapshot files
21-07-16 17:29:55 INFO (MainThread) [supervisor.discovery] Loaded 2 messages
21-07-16 17:29:55 INFO (MainThread) [supervisor.ingress] Loaded 5 ingress sessions
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state CoreState.SETUP
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.check] System checks complete
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.SETUP
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-07-16 17:29:55 INFO (MainThread) [supervisor.jobs] 'ResolutionFixup.run_autofix' blocked from execution, system is not running - CoreState.SETUP
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.SETUP
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-07-16 17:29:55 INFO (MainThread) [__main__] Running Supervisor
21-07-16 17:29:55 INFO (MainThread) [supervisor.hassos] Rauc: A - marked slot kernel.0 as good
21-07-16 17:29:55 INFO (MainThread) [supervisor.addons] Phase 'AddonStartup.INITIALIZE' starting 0 add-ons
21-07-16 17:29:55 INFO (MainThread) [supervisor.core] Supervisor reboot detected
21-07-16 17:29:55 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
21-07-16 17:29:55 INFO (MainThread) [supervisor.core] Supervisor is up and running
21-07-16 17:29:55 INFO (MainThread) [supervisor.host.info] Updating local host information
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state CoreState.RUNNING
21-07-16 17:29:55 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.PWNED/ContextType.ADDON
21-07-16 17:29:55 INFO (MainThread) [supervisor.host.services] Updating service information
21-07-16 17:29:56 INFO (MainThread) [supervisor.host.network] Updating local network information
21-07-16 17:29:56 WARNING (MainThread) [supervisor.addons.options] Option 'interface' does not exist in the schema for Samba share (core_samba)
21-07-16 17:29:56 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.FREE_SPACE/ContextType.SYSTEM
21-07-16 17:29:56 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.SECURITY/ContextType.CORE
21-07-16 17:29:56 INFO (MainThread) [supervisor.resolution.check] System checks complete
21-07-16 17:29:56 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.RUNNING
21-07-16 17:30:02 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-07-16 17:30:02 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state CoreState.RUNNING
21-07-16 17:30:02 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
21-07-16 17:30:09 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-16 17:30:09 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
21-07-16 17:30:09 INFO (MainThread) [supervisor.host] Host information reload completed
21-07-16 17:30:35 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-16 17:30:45 INFO (MainThread) [supervisor.snapshots] Creating new partial-snapshot with slug d5b556cc
21-07-16 17:30:45 INFO (MainThread) [supervisor.snapshots] Snapshotting d5b556cc store Add-ons
21-07-16 17:30:45 INFO (MainThread) [supervisor.addons.addon] Building snapshot for add-on core_configurator
21-07-16 17:30:45 INFO (MainThread) [supervisor.addons.addon] Finish snapshot for addon core_configurator
21-07-16 17:30:45 INFO (MainThread) [supervisor.snapshots] Creating partial-snapshot with slug d5b556cc completed
21-07-16 17:30:45 WARNING (MainThread) [supervisor.jobs] 'AddonManager.update' blocked from execution, no host internet connection

Additional information

No such a problem occured till supervisor-6.8, starting from Year 2021 ~January.

Masterz69 commented 3 years ago
➜  ~ ha network info
docker:
  address: 172.30.32.0/23
  dns: 172.30.32.3
  gateway: 172.30.32.1
  interface: hassio
host_internet: false
interfaces:
- connected: true
  enabled: true
  interface: eth0
  ipv4:
    address:
    - 192.168.1.11/24
    gateway: 192.168.1.1
    method: static
    nameservers:
    - 192.168.1.9
  ipv6:
    address:
    - fe80::11f4:96e4:752a:46f1/64
    gateway: fe80::76d2:1dff:febe:6653
    method: auto
    nameservers:
    - fe80::76d2:1dff:febe:6653
  primary: false
  type: ethernet
  vlan: null
  wifi: null
- connected: true
  enabled: true
  interface: wlan0
  ipv4:
    address:
    - 192.168.1.11/24
    gateway: 192.168.1.1
    method: static
    nameservers:
    - 192.168.1.9
  ipv6:
    address:
    - fe80::4979:b09a:2173:3e6f/64
    gateway: fe80::76d2:1dff:febe:6653
    method: auto
    nameservers:
    - fe80::76d2:1dff:febe:6653
  primary: true
  type: wireless
  vlan: null
  wifi:
    auth: wpa-psk
    mode: infrastructure
    signal: 70
    ssid: FANCY
supervisor_internet: true
➜  ~

See

host_internet: false
supervisor_internet: true

at a same time. How to fix it ?

Masterz69 commented 3 years ago
➜  ~ ha network reload

Command completed successfully.
➜  ~
➜  ~ ha network info
docker:
  address: 172.30.32.0/23
  dns: 172.30.32.3
  gateway: 172.30.32.1
  interface: hassio
host_internet: false

host network reload not changing status. No any DNS/DHCP add-ons installed.

Supervisor Add-n update works fine 2 weeks ago - on core 2021.6.4 & OS 5.smth (do not remember).

Masterz69 commented 3 years ago
➜  ~ ping 192.168.1.1
PING 192.168.1.1 (192.168.1.1): 56 data bytes
64 bytes from 192.168.1.1: seq=0 ttl=64 time=1.499 ms
64 bytes from 192.168.1.1: seq=1 ttl=64 time=2.687 ms
64 bytes from 192.168.1.1: seq=2 ttl=64 time=2.129 ms
^C
--- 192.168.1.1 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.499/2.105/2.687 ms

➜  ~ ping www.hp.com
PING www.hp.com (2.23.84.144): 56 data bytes
64 bytes from 2.23.84.144: seq=0 ttl=56 time=51.102 ms
64 bytes from 2.23.84.144: seq=1 ttl=56 time=68.526 ms
^C
--- www.hp.com ping statistics ---
2 packets transmitted, 2 packets received, 0% packet loss
round-trip min/avg/max = 51.102/59.814/68.526 ms

From HA SSH console - local gateway ICMP ping fine, Internet host too (as well as DNS looks functional).

Masterz69 commented 3 years ago

Adding available DNS logs: Supervisor -> System -> DNS

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] corefile.sh: executing... 
[cont-init.d] corefile.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
.:53
.:5553
CoreDNS-1.8.4
linux/arm64, go1.15.13, 053c4d5-dirty
[INFO] 127.0.0.1:43604 - 16315 "AAAA IN shelly-25-eu.shelly.cloud. udp 54 true 2048" NOERROR - 0 5.003002127s
[ERROR] plugin/errors: 2 shelly-25-eu.shelly.cloud. AAAA: tls: DialWithDialer timed out
[INFO] 127.0.0.1:54476 - 46478 "A IN www.local.hass.io. udp 46 true 2048" NOERROR - 0 0.000087184s
[ERROR] plugin/errors: 2 www.local.hass.io. A: plugin/forward: no next plugin found
[INFO] 172.30.32.1:38720 - 46478 "A IN www.local.hass.io. udp 35 false 512" SERVFAIL qr,rd 35 0.00108965s
[INFO] 172.30.32.1:38720 - 46478 "A IN www.local.hass.io. udp 35 false 512" SERVFAIL qr,aa,rd 35 0.000159293s
[INFO] 172.30.32.1:38720 - 46478 "A IN www.local.hass.io. udp 35 false 512" SERVFAIL qr,aa,rd 35 0.000099684s
[INFO] 172.30.32.1:38720 - 46478 "A IN www.local.hass.io. udp 35 false 512" SERVFAIL qr,aa,rd 35 0.000080888s
[INFO] 172.30.32.1:38720 - 46478 "A IN www.local.hass.io. udp 35 false 512" SERVFAIL qr,aa,rd 35 0.000076258s
[INFO] 127.0.0.1:45905 - 58670 "PTR IN 2.0.17.172.in-addr.arpa. udp 52 true 2048" NXDOMAIN qr,rd,ra 41 0.093882563s
[INFO] 172.30.32.1:35487 - 58670 "PTR IN 2.0.17.172.in-addr.arpa. udp 41 false 512" NXDOMAIN qr,rd,ra 41 0.096324005s
[INFO] 127.0.0.1:45905 - 37723 "PTR IN 211.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.030999958s
[INFO] 172.30.32.1:42680 - 37723 "PTR IN 211.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.034251682s
[INFO] 127.0.0.1:45905 - 8522 "PTR IN 235.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.033054961s
[INFO] 172.30.32.1:49006 - 8522 "PTR IN 235.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.035711362s
[INFO] 127.0.0.1:45905 - 22691 "PTR IN 224.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.02799997s
[INFO] 172.30.32.1:39733 - 22691 "PTR IN 224.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.031256287s
[INFO] 127.0.0.1:45905 - 12888 "PTR IN 241.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.086706606s
[INFO] 172.30.32.1:44656 - 12888 "PTR IN 241.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.089287138s
[INFO] 127.0.0.1:45905 - 49759 "PTR IN 208.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.025600786s
[INFO] 172.30.32.1:52052 - 49759 "PTR IN 208.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.027227204s
[INFO] 127.0.0.1:45905 - 36632 "PTR IN 201.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.030871053s
[INFO] 172.30.32.1:33187 - 36632 "PTR IN 201.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.033215403s
[INFO] 127.0.0.1:45905 - 29375 "PTR IN 2.0.17.172.in-addr.arpa. udp 52 true 2048" NXDOMAIN qr,rd,ra 41 0.026444625s
[INFO] 172.30.32.1:49476 - 29375 "PTR IN 2.0.17.172.in-addr.arpa. udp 41 false 512" NXDOMAIN qr,rd,ra 41 0.028212282s
[INFO] 127.0.0.1:45905 - 63396 "PTR IN 211.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.025569102s
[INFO] 172.30.32.1:50854 - 63396 "PTR IN 211.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.027852102s
[INFO] 127.0.0.1:45905 - 51612 "PTR IN 235.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.025847301s
[INFO] 172.30.32.1:36559 - 51612 "PTR IN 235.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.027860398s
[INFO] 127.0.0.1:45905 - 8262 "PTR IN 224.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.034678343s
[INFO] 172.30.32.1:59949 - 8262 "PTR IN 224.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.037131266s
[INFO] 127.0.0.1:45905 - 34241 "PTR IN 241.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.026029854s
[INFO] 172.30.32.1:46854 - 34241 "PTR IN 241.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.028646275s
[INFO] 127.0.0.1:45905 - 43878 "PTR IN 208.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.026898543s
[INFO] 172.30.32.1:54860 - 43878 "PTR IN 208.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.029587s
[INFO] 127.0.0.1:45905 - 8110 "PTR IN 201.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.027722067s
[INFO] 172.30.32.1:44464 - 8110 "PTR IN 201.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.029885532s
Masterz69 commented 3 years ago

Today happened:

Masterz69 commented 3 years ago

Host logs:

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.000000] Linux version 5.10.17-v8 (builder@b8cfa64352be) (aarch64-buildroot-linux-gnu-gcc.br_real (Buildroot -g20f02d28) 9.3.0, GNU ld (GNU Binutils) 2.35.2) #1 SMP PREEMPT Mon Jun 21 12:55:38 UTC 2021
[    0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.2
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created CMA memory pool at 0x000000002ac00000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000003fffffff]
[    0.000000]   DMA32    [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000003b2fffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000] Zeroed struct page in unavailable ranges: 256 pages
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
[    0.000000] On node 0 totalpages: 1012480
[    0.000000]   DMA zone: 3788 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 242432 pages, LIFO batch:63
[    0.000000]   DMA32 zone: 12032 pages used for memmap
[    0.000000]   DMA32 zone: 770048 pages, LIFO batch:63
[    0.000000] percpu: Embedded 32 pages/cpu s91352 r8192 d31528 u131072
[    0.000000] pcpu-alloc: s91352 r8192 d31528 u131072 alloc=32*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] CPU features: detected: Spectre-v2
[    0.000000] CPU features: detected: Spectre-v4
[    0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 996660
[    0.000000] Kernel command line: zram.enabled=1 zram.num_devices=3 apparmor=1 security=apparmor rootwait systemd.machine_id=052aed2ee2cb4157a26231a68dffbb98 cgroup_enable=memory fsck.repair=yes coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=E4:5F:01:05:EE:6E vc_mem.mem_base=0x3eb00000 vc_mem.mem_size=0x3ff00000  dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=8d3d53e3-6d49-4c38-8349-aff6859e82fd rootfstype=squashfs ro rauc.slot=A
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x0000000037300000-0x000000003b300000] (64MB)
[    0.000000] Memory: 3814556K/4049920K available (12096K kernel code, 1962K rwdata, 4160K rodata, 3840K init, 1261K bss, 169828K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 39239 entries in 154 pages
[    0.000000] ftrace: allocated 154 pages with 4 groups
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU event tracing is enabled.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000]  Trampoline variant of Tasks RCU enabled.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] random: get_random_bytes called from start_kernel+0x3b8/0x578 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000006] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000257] Console: colour dummy device 80x25
[    0.000808] printk: console [tty1] enabled
[    0.000868] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
[    0.000911] pid_max: default: 32768 minimum: 301
[    0.001061] LSM: Security Framework initializing
[    0.001185] AppArmor: AppArmor initialized
[    0.001403] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.001479] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.004595] rcu: Hierarchical SRCU implementation.
[    0.005626] EFI services will not be available.
[    0.006140] smp: Bringing up secondary CPUs ...
[    0.007134] Detected PIPT I-cache on CPU1
[    0.007208] CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
[    0.008372] Detected PIPT I-cache on CPU2
[    0.008418] CPU2: Booted secondary processor 0x0000000002 [0x410fd083]
[    0.009503] Detected PIPT I-cache on CPU3
[    0.009549] CPU3: Booted secondary processor 0x0000000003 [0x410fd083]
[    0.009699] smp: Brought up 1 node, 4 CPUs
[    0.009787] SMP: Total of 4 processors activated.
[    0.009812] CPU features: detected: 32-bit EL0 Support
[    0.009835] CPU features: detected: CRC32 instructions
[    0.009858] CPU features: detected: 32-bit EL1 Support
[    0.047371] CPU: All CPU(s) started at EL2
[    0.047456] alternatives: patching kernel code
[    0.049033] devtmpfs: initialized
[    0.059721] Enabled cp15_barrier support
[    0.059786] Enabled setend support
[    0.059994] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.060039] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.062099] pinctrl core: initialized pinctrl subsystem
[    0.062873] DMI not present or invalid.
[    0.063282] NET: Registered protocol family 16
[    0.066584] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[    0.066859] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.067795] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.067879] audit: initializing netlink subsys (disabled)
[    0.068266] audit: type=2000 audit(0.068:1): state=initialized audit_enabled=0 res=1
[    0.068761] thermal_sys: Registered thermal governor 'step_wise'
[    0.069215] cpuidle: using governor menu
[    0.069728] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.069915] ASID allocator initialised with 65536 entries
[    0.070049] Serial: AMBA PL011 UART driver
[    0.099606] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.108322] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-02-25T12:10:40, variant start
[    0.112338] raspberrypi-firmware soc:firmware: Firmware hash is 564e5f9b852b23a330b1764bcf0b2d022a20afd0
[    0.146851] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[    0.150846] vgaarb: loaded
[    0.151262] SCSI subsystem initialized
[    0.151491] usbcore: registered new interface driver usbfs
[    0.151568] usbcore: registered new interface driver hub
[    0.151645] usbcore: registered new device driver usb
[    0.151973] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.152351] mc: Linux media interface: v0.10
[    0.154068] clocksource: Switched to clocksource arch_sys_counter
[    1.171117] VFS: Disk quotas dquot_6.6.0
[    1.171241] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.171417] FS-Cache: Loaded
[    1.171680] CacheFiles: Loaded
[    1.172436] AppArmor: AppArmor Filesystem Enabled
[    1.182753] NET: Registered protocol family 2
[    1.183917] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[    1.183984] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    1.184204] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[    1.184639] TCP: Hash tables configured (established 32768 bind 32768)
[    1.184896] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    1.184983] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    1.185305] NET: Registered protocol family 1
[    1.186265] RPC: Registered named UNIX socket transport module.
[    1.186293] RPC: Registered udp transport module.
[    1.186314] RPC: Registered tcp transport module.
[    1.186334] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.186367] PCI: CLS 0 bytes, default 64
[    1.188856] hw perfevents: enabled with armv8_cortex_a72 PMU driver, 7 counters available
[    1.189147] kvm [1]: IPA Size Limit: 44 bits
[    1.190389] kvm [1]: vgic interrupt IRQ9
[    1.190684] kvm [1]: Hyp mode initialized successfully
[    1.192820] Initialise system trusted keyrings
[    1.193172] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    1.199470] zbud: loaded
[    1.201180] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    1.201448] FS-Cache: Netfs 'nfs' registered for caching
[    1.202140] NFS: Registering the id_resolver key type
[    1.202204] Key type id_resolver registered
[    1.202227] Key type id_legacy registered
[    1.202360] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.203553] Key type asymmetric registered
[    1.203579] Asymmetric key parser 'x509' registered
[    1.203639] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[    1.203894] io scheduler mq-deadline registered
[    1.203919] io scheduler kyber registered
[    1.208077] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    1.208124] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[    1.208213] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[    1.208308] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000
[    1.256164] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[    1.256552] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    1.256584] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.256614] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[    1.256716] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    1.256966] pci 0000:00:00.0: PME# supported from D0 D3hot
[    1.260933] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    1.261069] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    1.261501] pci 0000:01:00.0: PME# supported from D0 D3cold
[    1.273341] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.273379] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.273431] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.273464] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.274144] bcm2708_fb soc:fb: Unable to determine number of FBs. Disabling driver.
[    1.274195] bcm2708_fb: probe of soc:fb failed with error -2
[    1.281143] iproc-rng200 fe104000.rng: hwrng registered
[    1.281496] vc-mem: phys_addr:0x00000000 mem_base=0x3eb00000 mem_size:0x3ff00000(1023 MiB)
[    1.282362] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.282780] cacheinfo: Unable to detect cache hierarchy for CPU 0
[    1.293723] brd: module loaded
[    1.305827] loop: module loaded
[    1.306462] zram: Added device: zram0
[    1.307006] zram: Added device: zram1
[    1.307511] zram: Added device: zram2
[    1.309066] Loading iSCSI transport class v2.0-870.
[    1.312104] libphy: Fixed MDIO Bus: probed
[    1.313039] tun: Universal TUN/TAP device driver, 1.6
[    1.313900] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[    1.326099] libphy: bcmgenet MII bus: probed
[    1.374191] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[    1.375255] usbcore: registered new interface driver r8152
[    1.375332] usbcore: registered new interface driver lan78xx
[    1.376933] pci 0000:00:00.0: enabling device (0000 -> 0002)
[    1.376980] xhci_hcd 0000:01:00.0: enabling device (0000 -> 0002)
[    1.377088] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.377133] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    1.377899] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000030000000890
[    1.378909] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[    1.378944] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.378971] usb usb1: Product: xHCI Host Controller
[    1.378995] usb usb1: Manufacturer: Linux 5.10.17-v8 xhci-hcd
[    1.379019] usb usb1: SerialNumber: 0000:01:00.0
[    1.379727] hub 1-0:1.0: USB hub found
[    1.379834] hub 1-0:1.0: 1 port detected
[    1.380464] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.380499] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    1.380537] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    1.380977] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[    1.381008] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.381035] usb usb2: Product: xHCI Host Controller
[    1.381058] usb usb2: Manufacturer: Linux 5.10.17-v8 xhci-hcd
[    1.381081] usb usb2: SerialNumber: 0000:01:00.0
[    1.381710] hub 2-0:1.0: USB hub found
[    1.381788] hub 2-0:1.0: 4 ports detected
[    1.383400] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.383682] dwc_otg: FIQ enabled
[    1.383693] dwc_otg: NAK holdoff enabled
[    1.383704] dwc_otg: FIQ split-transaction FSM enabled
[    1.383717] Module dwc_common_port init
[    1.384237] usbcore: registered new interface driver uas
[    1.384345] usbcore: registered new interface driver usb-storage
[    1.384495] usbcore: registered new interface driver usbserial_generic
[    1.384551] usbserial: USB Serial support registered for generic
[    1.384767] mousedev: PS/2 mouse device common for all mice
[    1.386734] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    1.389959] sdhci: Secure Digital Host Controller Interface driver
[    1.389988] sdhci: Copyright(c) Pierre Ossman
[    1.390697] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[    1.391226] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.397148] ledtrig-cpu: registered to indicate activity on CPUs
[    1.397269] hid: raw HID events driver (C) Jiri Kosina
[    1.397355] usbcore: registered new interface driver usbhid
[    1.397364] usbhid: USB HID core driver
[    1.401655] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[    1.401716] IPVS: Connection hash table configured (size=4096, memory=64Kbytes)
[    1.401974] IPVS: ipvs loaded.
[    1.401992] IPVS: [rr] scheduler registered.
[    1.402839] NET: Registered protocol family 10
[    1.403904] Segment Routing with IPv6
[    1.404007] NET: Registered protocol family 17
[    1.404072] Bridge firewalling registered
[    1.404157] Key type dns_resolver registered
[    1.404709] registered taskstats version 1
[    1.404737] Loading compiled-in X.509 certificates
[    1.405052] Key type ._fscrypt registered
[    1.405070] Key type .fscrypt registered
[    1.405085] Key type fscrypt-provisioning registered
[    1.405181] AppArmor: AppArmor sha1 policy hashing enabled
[    1.412748] uart-pl011 fe201000.serial: there is not valid maps for state default
[    1.412982] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    1.413071] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 21, base_baud = 0) is a PL011 rev2
[    1.420119] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    1.420561] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    1.420574] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    1.449435] printk: console [netcon0] enabled
[    1.449467] netconsole: network logging started
[    1.449531] of_cfs_init
[    1.449665] of_cfs_init: OK
[    1.464575] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.466137] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.467691] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.470546] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.472114] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.489544] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[    1.490380] Waiting for root device PARTUUID=8d3d53e3-6d49-4c38-8349-aff6859e82fd...
[    1.505089] random: fast init done
[    1.535768] mmc1: new high speed SDIO card at address 0001
[    1.714114] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.864726] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    1.864761] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.864787] usb 1-1: Product: USB2.0 Hub
[    1.866351] hub 1-1:1.0: USB hub found
[    1.866688] hub 1-1:1.0: 4 ports detected
[    2.162182] usb 1-1.1: new full-speed USB device number 3 using xhci_hcd
[    2.269087] usb 1-1.1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[    2.269122] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.354182] usb 1-1.2: new full-speed USB device number 4 using xhci_hcd
[    2.460234] usb 1-1.2: New USB device found, idVendor=1a86, idProduct=7523, bcdDevice= 2.64
[    2.460268] usb 1-1.2: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[    2.460296] usb 1-1.2: Product: USB Serial
[    2.542098] usb 1-1.4: new high-speed USB device number 5 using xhci_hcd
[    2.687917] usb 1-1.4: New USB device found, idVendor=174c, idProduct=1153, bcdDevice= 0.01
[    2.687952] usb 1-1.4: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[    2.687979] usb 1-1.4: Product: AS2115
[    2.688001] usb 1-1.4: Manufacturer: ASMedia
[    2.688023] usb 1-1.4: SerialNumber: 00000000000000000000
[    2.690283] usb-storage 1-1.4:1.0: USB Mass Storage device detected
[    2.691015] scsi host0: usb-storage 1-1.4:1.0
[    3.710965] scsi 0:0:0:0: Direct-Access     ASMT     2115             0    PQ: 0 ANSI: 6
[    3.712086] sd 0:0:0:0: [sda] 117231408 512-byte logical blocks: (60.0 GB/55.9 GiB)
[    3.712852] sd 0:0:0:0: [sda] Write Protect is off
[    3.712884] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[    3.713630] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    3.723498]  sda: sda1 sda2 sda3 sda4 sda5 sda6 sda7 sda8
[    3.726875] sd 0:0:0:0: [sda] Attached SCSI disk
[    3.733762] VFS: Mounted root (squashfs filesystem) readonly on device 8:3.
[    3.735466] devtmpfs: mounted
[    3.741432] Freeing unused kernel memory: 3840K
[    3.758172] Run /sbin/init as init process
[    3.758197]   with arguments:
[    3.758208]     /sbin/init
[    3.758218]   with environment:
[    3.758228]     HOME=/
[    3.758238]     TERM=linux
[    4.040648] systemd[1]: System time before build time, advancing clock.
[    4.099917] systemd[1]: systemd 247 running in system mode. (+PAM -AUDIT -SELINUX -IMA +APPARMOR -SMACK -SYSVINIT -UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS -ACL -XZ -LZ4 -ZSTD -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[    4.100573] systemd[1]: Detected architecture arm64.
[    4.121485] systemd[1]: Set hostname to <homeassistant>.
[    4.121808] systemd[1]: Installed transient /etc/machine-id file.
[    4.561807] systemd[1]: Queued start job for default target Multi-User System.
[    4.562776] random: systemd: uninitialized urandom read (16 bytes read)
[    4.590147] systemd[1]: Created slice system-ha\x2dcli.slice.
[    4.590526] random: systemd: uninitialized urandom read (16 bytes read)
[    4.592147] systemd[1]: Created slice system-modprobe.slice.
[    4.592371] random: systemd: uninitialized urandom read (16 bytes read)
[    4.593893] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    4.596063] systemd[1]: Created slice system-systemd\x2dgrowfs.slice.
[    4.597693] systemd[1]: Created slice User and Session Slice.
[    4.598165] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    4.598491] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    4.598801] systemd[1]: Reached target Local Encrypted Volumes.
[    4.599012] systemd[1]: Reached target HassOS zram targets.
[    4.599220] systemd[1]: Reached target Paths.
[    4.599389] systemd[1]: Reached target Remote Encrypted Volumes.
[    4.599556] systemd[1]: Reached target Remote File Systems.
[    4.599725] systemd[1]: Reached target Slices.
[    4.601207] systemd[1]: Listening on D-Bus System Message Bus Socket.
[    4.601559] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[    4.604817] systemd[1]: Listening on Process Core Dump Socket.
[    4.606227] systemd[1]: Listening on Journal Audit Socket.
[    4.606750] systemd[1]: Listening on Journal Socket (/dev/log).
[    4.607283] systemd[1]: Listening on Journal Socket.
[    4.609524] systemd[1]: Listening on udev Control Socket.
[    4.609992] systemd[1]: Listening on udev Kernel Socket.
[    4.610762] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    4.614271] systemd[1]: Mounting POSIX Message Queue File System...
[    4.618770] systemd[1]: Mounting Kernel Debug File System...
[    4.623450] systemd[1]: Mounting Kernel Trace File System...
[    4.627557] systemd[1]: Starting Availability of block devices...
[    4.631766] systemd[1]: Started D-Bus System Message Bus.
[    4.640952] systemd[1]: Starting Home Assistant OS Agent...
[    4.659134] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    4.664982] systemd[1]: Starting Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling...
[    4.668960] systemd[1]: Starting Load Kernel Module configfs...
[    4.672823] systemd[1]: Starting Load Kernel Module drm...
[    4.677000] systemd[1]: Starting Load Kernel Module fuse...
[    4.683629] systemd[1]: Starting Journal Service...
[    4.687681] systemd[1]: Starting Remount Root and Kernel File Systems...
[    4.691642] systemd[1]: Starting Wait Until Kernel Time Synchronized...
[    4.695661] systemd[1]: Starting Coldplug All udev Devices...
[    4.699660] systemd[1]: Starting Disk Manager...
[    4.704275] systemd[1]: Starting HassOS ZRAM swap...
[    4.708272] systemd[1]: Starting HassOS ZRAM tmp...
[    4.713925] systemd[1]: Starting HassOS ZRAM var...
[    4.721138] systemd[1]: Mounted POSIX Message Queue File System.
[    4.721733] systemd[1]: Mounted Kernel Debug File System.
[    4.722261] systemd[1]: Mounted Kernel Trace File System.
[    4.725031] systemd[1]: Finished Create list of static device nodes for the current kernel.
[    4.725653] systemd[1]: lvm2-monitor.service: Main process exited, code=exited, status=203/EXEC
[    4.726228] systemd[1]: lvm2-monitor.service: Failed with result 'exit-code'.
[    4.728498] systemd[1]: Failed to start Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
[    4.729719] systemd[1]: modprobe@configfs.service: Succeeded.
[    4.731180] systemd[1]: Finished Load Kernel Module configfs.
[    4.733855] systemd[1]: Finished Remount Root and Kernel File Systems.
[    4.738266] systemd[1]: Mounting Kernel Configuration File System...
[    4.743378] systemd[1]: Starting Create Static Device Nodes in /dev...
[    4.747361] systemd[1]: Mounted Kernel Configuration File System.
[    4.865312] systemd[1]: Finished Availability of block devices.
[    4.867254] systemd[1]: Started Journal Service.
[    4.946294] zram2: detected capacity change from 0 to 16777216
[    4.950685] fuse: init (API version 7.32)
[    4.951556] zram0: detected capacity change from 0 to 994287616
[    5.020856] zram1: detected capacity change from 0 to 33554432
[    5.238365] audit: type=1334 audit(1612279788.195:2): prog-id=5 op=LOAD
[    5.238570] audit: type=1334 audit(1612279788.195:3): prog-id=6 op=LOAD
[    5.609735] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000
[    5.610231] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000
[    5.610540] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000
[    5.610785] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000
[    5.645001] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    5.646560] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    5.646590] [vc_sm_connected_init]: start
[    5.650827] [vc_sm_connected_init]: installed successfully
[    5.694629] i2c i2c-11: Added multiplexed i2c bus 0
[    5.694820] i2c i2c-11: Added multiplexed i2c bus 10
[    5.721937] cdc_acm 1-1.1:1.0: ttyACM0: USB ACM device
[    5.724562] usbcore: registered new interface driver ch341
[    5.724654] usbserial: USB Serial support registered for ch341-uart
[    5.724758] ch341 1-1.2:1.0: ch341-uart converter detected
[    5.725508] usbcore: registered new interface driver cdc_acm
[    5.725532] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[    5.751752] usb 1-1.2: ch341-uart converter now attached to ttyUSB0
[    5.867288] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    5.870758] bcm2835_audio bcm2835_audio: card created with 8 channels
[    5.878654] videodev: Linux video capture interface: v2.00
[    5.899644] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.937683] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    5.938692] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    5.941108] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    5.941571] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    5.948679] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    5.949071] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    5.949278] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    5.949286] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    5.949309] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    5.949484] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    5.949521] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    5.949541] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    5.949555] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    5.949568] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    5.949861] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    5.958613] rtc-ds1307 1-0068: registered as rtc0
[    5.976631] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    5.976676] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    5.979507] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    5.979598] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    5.995082] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    6.086266] Adding 970980k swap on /dev/zram0.  Priority:-2 extents:1 across:970980k SSFS
[    6.111901] brcmfmac: F1 signature read @0x18000000=0x15264345
[    6.117419] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    6.117992] usbcore: registered new interface driver brcmfmac
[    6.221802] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,4-model-b.txt failed with error -2
[    6.370800] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[    6.414687] random: crng init done
[    6.414712] random: 7 urandom warning(s) missed due to ratelimiting
[    6.445224] EXT4-fs (zram2): mounted filesystem without journal. Opts: nobarrier
[    6.445310] ext4 filesystem being mounted at /tmp supports timestamps until 2038 (0x7fffffff)
[    6.447504] EXT4-fs (zram1): mounted filesystem without journal. Opts: nobarrier
[    6.447547] ext4 filesystem being mounted at /var supports timestamps until 2038 (0x7fffffff)
[    6.453486] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    6.466029] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar 23 2020 02:19:54 version 7.45.206 (r725000 CY) FWID 01-88ee44ea
[    6.485204] EXT4-fs (sda7): mounted filesystem with ordered data mode. Opts: (null)
[    6.485288] ext4 filesystem being mounted at /mnt/overlay supports timestamps until 2038 (0x7fffffff)
[    6.735170] i2c /dev entries driver
[    7.243319] EXT4-fs (sda8): mounted filesystem with ordered data mode. Opts: (null)
[    7.309964] EXT4-fs (sda8): resizing filesystem from 14475489 to 14475489 blocks
[    7.382983] systemd-journald[116]: Received client request to flush runtime journal.
[    7.396897] systemd-journald[116]: File /var/log/journal/052aed2ee2cb4157a26231a68dffbb98/system.journal corrupted or uncleanly shut down, renaming and replacing.
[    8.263506] audit: type=1334 audit(1612279791.219:4): prog-id=7 op=LOAD
[    8.263658] audit: type=1334 audit(1612279791.219:5): prog-id=8 op=LOAD
[    8.477173] audit: type=1400 audit(1612279791.423:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor" pid=388 comm="apparmor_parser"
[    8.477200] audit: type=1400 audit(1612279791.423:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=388 comm="apparmor_parser"
[    8.477216] audit: type=1400 audit(1612279791.423:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=388 comm="apparmor_parser"
[    8.629938] Bluetooth: Core ver 2.22
[    8.630081] NET: Registered protocol family 31
[    8.630091] Bluetooth: HCI device and connection manager initialized
[    8.630112] Bluetooth: HCI socket layer initialized
[    8.630127] Bluetooth: L2CAP socket layer initialized
[    8.630151] Bluetooth: SCO socket layer initialized
[    8.806724] uart-pl011 fe201000.serial: no DMA platform data
[    8.975070] systemd-journald[116]: File /var/log/journal/052aed2ee2cb4157a26231a68dffbb98/user-1001.journal corrupted or uncleanly shut down, renaming and replacing.
[    8.982232] audit: type=1334 audit(1612279791.939:7): prog-id=9 op=LOAD
[    8.982411] audit: type=1334 audit(1612279791.939:8): prog-id=10 op=LOAD
[    9.232882] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
[    9.233121] bcmgenet fd580000.ethernet eth0: Link is Down
[    9.276966] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[    9.381123] Bluetooth: HCI UART driver ver 2.3
[    9.381137] Bluetooth: HCI UART protocol H4 registered
[    9.381203] Bluetooth: HCI UART protocol Three-wire (H5) registered
[    9.381351] Bluetooth: HCI UART protocol Broadcom registered
[    9.508718] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    9.508730] Bluetooth: BNEP filters: protocol multicast
[    9.508745] Bluetooth: BNEP socket layer initialized
[    9.528948] NET: Registered protocol family 38
[    9.554120] cryptd: max_cpu_qlen set to 1000
[   11.262199] bcmgenet fd580000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[   11.262234] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   14.619921] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   16.618200] audit: type=1400 audit(1612279799.571:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker-default" pid=497 comm="apparmor_parser"
[   18.818210] audit: type=1325 audit(1612279801.755:10): table=nat family=2 entries=5 op=xt_replace pid=533 subj==unconfined comm="iptables"
[   18.842160] audit: type=1325 audit(1612279801.779:11): table=filter family=2 entries=4 op=xt_replace pid=535 subj==unconfined comm="iptables"
[   18.878140] audit: type=1325 audit(1612279801.811:12): table=filter family=2 entries=6 op=xt_replace pid=537 subj==unconfined comm="iptables"
[   18.918141] audit: type=1325 audit(1612279801.839:13): table=filter family=2 entries=8 op=xt_replace pid=539 subj==unconfined comm="iptables"
[   18.946155] audit: type=1325 audit(1612279801.879:14): table=filter family=2 entries=10 op=xt_replace pid=541 subj==unconfined comm="iptables"
[   18.982143] audit: type=1325 audit(1612279801.911:15): table=filter family=2 entries=11 op=xt_replace pid=543 subj==unconfined comm="iptables"
[   19.002152] audit: type=1325 audit(1612279801.943:16): table=filter family=2 entries=12 op=xt_replace pid=544 subj==unconfined comm="iptables"
[   19.024846] Initializing XFRM netlink socket
[   19.094155] audit: type=1325 audit(1612279802.023:17): table=nat family=2 entries=7 op=xt_replace pid=552 subj==unconfined comm="iptables"
[   19.126142] audit: type=1325 audit(1612279802.055:18): table=nat family=2 entries=8 op=xt_replace pid=554 subj==unconfined comm="iptables"
[   22.498258] kauditd_printk_skb: 40 callbacks suppressed
[   22.498269] audit: type=1325 audit(1612279805.427:59): table=nat family=2 entries=23 op=xt_replace pid=828 subj==unconfined comm="iptables"
[   22.526292] audit: type=1325 audit(1612279805.467:60): table=filter family=2 entries=30 op=xt_replace pid=830 subj==unconfined comm="iptables"
[   22.554287] audit: type=1325 audit(1612279805.495:61): table=nat family=2 entries=22 op=xt_replace pid=832 subj==unconfined comm="iptables"
[   24.570278] audit: type=1325 audit(1612279807.503:62): table=nat family=2 entries=21 op=xt_replace pid=966 subj==unconfined comm="iptables"
[   24.618248] audit: type=1325 audit(1612279807.543:63): table=filter family=2 entries=29 op=xt_replace pid=968 subj==unconfined comm="iptables"
[   24.650208] audit: type=1325 audit(1612279807.587:64): table=nat family=2 entries=20 op=xt_replace pid=970 subj==unconfined comm="iptables"
[   24.694274] audit: type=1325 audit(1612279807.623:65): table=nat family=2 entries=19 op=xt_replace pid=973 subj==unconfined comm="iptables"
[   24.730266] audit: type=1325 audit(1612279807.663:66): table=filter family=2 entries=28 op=xt_replace pid=975 subj==unconfined comm="iptables"
[   24.766265] audit: type=1325 audit(1612279807.699:67): table=nat family=2 entries=18 op=xt_replace pid=977 subj==unconfined comm="iptables"
[   24.818274] audit: type=1325 audit(1612279807.739:68): table=nat family=2 entries=17 op=xt_replace pid=980 subj==unconfined comm="iptables"
[   27.039957] hassio: port 1(vethfa28919) entered blocking state
[   27.039973] hassio: port 1(vethfa28919) entered disabled state
[   27.040168] device vethfa28919 entered promiscuous mode
[   27.771300] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[   28.130227] kauditd_printk_skb: 30 callbacks suppressed
[   28.130234] audit: type=1325 audit(1612279811.071:99): table=nat family=2 entries=0 op=xt_register pid=1202 subj==unconfined comm="iptables"
[   28.162214] audit: type=1325 audit(1612279811.099:100): table=filter family=2 entries=0 op=xt_register pid=1203 subj==unconfined comm="iptables"
[   28.206220] audit: type=1325 audit(1612279811.135:101): table=nat family=2 entries=5 op=xt_replace pid=1206 subj==unconfined comm="iptables"
[   28.230173] audit: type=1325 audit(1612279811.171:102): table=nat family=2 entries=7 op=xt_replace pid=1207 subj==unconfined comm="iptables"
[   28.266219] audit: type=1325 audit(1612279811.195:103): table=nat family=2 entries=8 op=xt_replace pid=1209 subj==unconfined comm="iptables"
[   28.298210] audit: type=1325 audit(1612279811.227:104): table=nat family=2 entries=10 op=xt_replace pid=1210 subj==unconfined comm="iptables"
[   28.330288] audit: type=1325 audit(1612279811.267:105): table=nat family=2 entries=11 op=xt_replace pid=1211 subj==unconfined comm="iptables"
[   28.370323] audit: type=1325 audit(1612279811.295:106): table=nat family=2 entries=12 op=xt_replace pid=1212 subj==unconfined comm="iptables"
[   28.398312] audit: type=1325 audit(1612279811.335:107): table=nat family=2 entries=13 op=xt_replace pid=1213 subj==unconfined comm="iptables"
[   28.422197] audit: type=1325 audit(1612279811.363:108): table=nat family=2 entries=14 op=xt_replace pid=1214 subj==unconfined comm="iptables"
[   28.467964] eth0: renamed from vethf6fcea8
[   28.491816] IPv6: ADDRCONF(NETDEV_CHANGE): vethfa28919: link becomes ready
[   28.491991] hassio: port 1(vethfa28919) entered blocking state
[   28.492005] hassio: port 1(vethfa28919) entered forwarding state
[   28.492247] IPv6: ADDRCONF(NETDEV_CHANGE): hassio: link becomes ready
[   31.710141] vcc-sd: disabling
[   39.666002] docker0: port 1(veth873bb8f) entered blocking state
[   39.666019] docker0: port 1(veth873bb8f) entered disabled state
[   39.666668] device veth873bb8f entered promiscuous mode
[   39.666737] audit: type=1700 audit(1626517985.944:109): dev=veth873bb8f prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   39.730265] hassio: port 2(veth3867531) entered blocking state
[   39.730281] hassio: port 2(veth3867531) entered disabled state
[   39.730476] device veth3867531 entered promiscuous mode
[   39.730556] audit: type=1700 audit(1626517986.012:110): dev=veth3867531 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   39.730840] hassio: port 2(veth3867531) entered blocking state
[   39.730852] hassio: port 2(veth3867531) entered forwarding state
[   40.208808] eth0: renamed from veth4a9e54c
[   40.231946] hassio: port 2(veth3867531) entered disabled state
[   40.232111] IPv6: ADDRCONF(NETDEV_CHANGE): veth873bb8f: link becomes ready
[   40.232245] docker0: port 1(veth873bb8f) entered blocking state
[   40.232255] docker0: port 1(veth873bb8f) entered forwarding state
[   40.232497] IPv6: ADDRCONF(NETDEV_CHANGE): docker0: link becomes ready
[   40.366279] audit: type=1325 audit(1626517986.624:111): table=nat family=2 entries=0 op=xt_register pid=1558 subj==unconfined comm="iptables"
[   40.402197] audit: type=1325 audit(1626517986.668:112): table=filter family=2 entries=0 op=xt_register pid=1559 subj==unconfined comm="iptables"
[   40.446243] audit: type=1325 audit(1626517986.696:113): table=nat family=2 entries=5 op=xt_replace pid=1563 subj==unconfined comm="iptables"
[   40.474284] audit: type=1325 audit(1626517986.732:114): table=nat family=2 entries=7 op=xt_replace pid=1564 subj==unconfined comm="iptables"
[   40.498309] audit: type=1325 audit(1626517986.760:115): table=nat family=2 entries=8 op=xt_replace pid=1572 subj==unconfined comm="iptables"
[   40.522175] audit: type=1325 audit(1626517986.784:116): table=nat family=2 entries=10 op=xt_replace pid=1575 subj==unconfined comm="iptables"
[   40.554310] audit: type=1325 audit(1626517986.808:117): table=nat family=2 entries=11 op=xt_replace pid=1576 subj==unconfined comm="iptables"
[   40.582229] audit: type=1325 audit(1626517986.844:118): table=nat family=2 entries=12 op=xt_replace pid=1578 subj==unconfined comm="iptables"
[   40.692541] eth1: renamed from vethfa8d2ec
[   40.720772] IPv6: ADDRCONF(NETDEV_CHANGE): veth3867531: link becomes ready
[   40.720972] hassio: port 2(veth3867531) entered blocking state
[   40.720988] hassio: port 2(veth3867531) entered forwarding state
[   46.456397] kauditd_printk_skb: 4 callbacks suppressed
[   46.456402] audit: type=1334 audit(1626517992.736:123): prog-id=11 op=LOAD
[   46.456458] audit: type=1334 audit(1626517992.736:124): prog-id=12 op=LOAD
[   46.666137] audit: type=1334 audit(1626517992.944:125): prog-id=13 op=LOAD
[   46.666651] audit: type=1334 audit(1626517992.948:126): prog-id=14 op=LOAD
[   49.376940] audit: type=1400 audit(1626517995.648:127): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor" pid=2258 comm="apparmor_parser"
[   49.376966] audit: type=1400 audit(1626517995.648:127): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=2258 comm="apparmor_parser"
[   49.376981] audit: type=1400 audit(1626517995.648:127): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=2258 comm="apparmor_parser"
[   50.550470] hassio: port 3(veth799d31c) entered blocking state
[   50.550485] hassio: port 3(veth799d31c) entered disabled state
[   50.551032] device veth799d31c entered promiscuous mode
[   50.551109] audit: type=1700 audit(1626517996.832:128): dev=veth799d31c prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   51.110258] audit: type=1325 audit(1626517997.360:129): table=nat family=2 entries=0 op=xt_register pid=2330 subj==unconfined comm="iptables"
[   51.158315] audit: type=1325 audit(1626517997.412:130): table=filter family=2 entries=0 op=xt_register pid=2332 subj==unconfined comm="iptables"
[   51.511268] eth0: renamed from vethf930656
[   51.535380] IPv6: ADDRCONF(NETDEV_CHANGE): veth799d31c: link becomes ready
[   51.535528] hassio: port 3(veth799d31c) entered blocking state
[   51.535538] hassio: port 3(veth799d31c) entered forwarding state
[   52.352941] hassio: port 4(vethb81dcaf) entered blocking state
[   52.352957] hassio: port 4(vethb81dcaf) entered disabled state
[   52.355369] device vethb81dcaf entered promiscuous mode
[   52.355437] kauditd_printk_skb: 8 callbacks suppressed
[   52.355442] audit: type=1700 audit(1626517998.632:139): dev=vethb81dcaf prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   52.926247] audit: type=1325 audit(1626517999.180:140): table=nat family=2 entries=0 op=xt_register pid=2655 subj==unconfined comm="iptables"
[   52.954310] audit: type=1325 audit(1626517999.220:141): table=filter family=2 entries=0 op=xt_register pid=2656 subj==unconfined comm="iptables"
[   52.994252] audit: type=1325 audit(1626517999.256:142): table=nat family=2 entries=5 op=xt_replace pid=2663 subj==unconfined comm="iptables"
[   53.014201] audit: type=1325 audit(1626517999.280:143): table=nat family=2 entries=7 op=xt_replace pid=2666 subj==unconfined comm="iptables"
[   53.042250] audit: type=1325 audit(1626517999.304:144): table=nat family=2 entries=8 op=xt_replace pid=2668 subj==unconfined comm="iptables"
[   53.066273] audit: type=1325 audit(1626517999.328:145): table=nat family=2 entries=10 op=xt_replace pid=2669 subj==unconfined comm="iptables"
[   53.090194] audit: type=1325 audit(1626517999.356:146): table=nat family=2 entries=11 op=xt_replace pid=2670 subj==unconfined comm="iptables"
[   53.126374] audit: type=1325 audit(1626517999.380:147): table=nat family=2 entries=12 op=xt_replace pid=2671 subj==unconfined comm="iptables"
[   53.158239] audit: type=1325 audit(1626517999.416:148): table=nat family=2 entries=13 op=xt_replace pid=2672 subj==unconfined comm="iptables"
[   53.244028] eth0: renamed from vethdfbd9ad
[   53.263110] IPv6: ADDRCONF(NETDEV_CHANGE): vethb81dcaf: link becomes ready
[   53.263218] hassio: port 4(vethb81dcaf) entered blocking state
[   53.263225] hassio: port 4(vethb81dcaf) entered forwarding state
[   53.814519] hassio: port 5(vethad2fdeb) entered blocking state
[   53.814535] hassio: port 5(vethad2fdeb) entered disabled state
[   53.815187] device vethad2fdeb entered promiscuous mode
[   54.717276] eth0: renamed from veth0b4c279
[   54.740425] IPv6: ADDRCONF(NETDEV_CHANGE): vethad2fdeb: link becomes ready
[   54.740609] hassio: port 5(vethad2fdeb) entered blocking state
[   54.740621] hassio: port 5(vethad2fdeb) entered forwarding state
[   56.917579] Bluetooth: RFCOMM TTY layer initialized
[   56.917693] Bluetooth: RFCOMM socket layer initialized
[   56.917726] Bluetooth: RFCOMM ver 1.11
[   68.754250] hassio: port 6(vetha7a4cd7) entered blocking state
[   68.754264] hassio: port 6(vetha7a4cd7) entered disabled state
[   68.754573] device vetha7a4cd7 entered promiscuous mode
[   68.754651] kauditd_printk_skb: 12 callbacks suppressed
[   68.754657] audit: type=1700 audit(1626518015.036:161): dev=vetha7a4cd7 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[   68.842263] audit: type=1325 audit(1626518015.084:162): table=nat family=2 entries=15 op=xt_replace pid=3756 subj==unconfined comm="iptables"
[   68.878289] audit: type=1325 audit(1626518015.136:163): table=filter family=2 entries=30 op=xt_replace pid=3758 subj==unconfined comm="iptables"
[   68.926316] audit: type=1325 audit(1626518015.172:164): table=nat family=2 entries=16 op=xt_replace pid=3760 subj==unconfined comm="iptables"
[   68.978434] audit: type=1325 audit(1626518015.240:165): table=nat family=2 entries=17 op=xt_replace pid=3778 subj==unconfined comm="iptables"
[   69.018330] audit: type=1325 audit(1626518015.272:166): table=filter family=2 entries=31 op=xt_replace pid=3780 subj==unconfined comm="iptables"
[   69.046338] audit: type=1325 audit(1626518015.312:167): table=nat family=2 entries=18 op=xt_replace pid=3782 subj==unconfined comm="iptables"
[   69.098324] audit: type=1325 audit(1626518015.356:168): table=nat family=2 entries=19 op=xt_replace pid=3801 subj==unconfined comm="iptables"
[   69.142268] audit: type=1325 audit(1626518015.392:169): table=filter family=2 entries=32 op=xt_replace pid=3803 subj==unconfined comm="iptables"
[   69.178240] audit: type=1325 audit(1626518015.436:170): table=nat family=2 entries=20 op=xt_replace pid=3805 subj==unconfined comm="iptables"
[   70.176905] eth0: renamed from veth5962311
[   70.195579] IPv6: ADDRCONF(NETDEV_CHANGE): vetha7a4cd7: link becomes ready
[   70.195728] hassio: port 6(vetha7a4cd7) entered blocking state
[   70.195739] hassio: port 6(vetha7a4cd7) entered forwarding state
[   70.802344] hassio: port 7(veth1203a6a) entered blocking state
[   70.802359] hassio: port 7(veth1203a6a) entered disabled state
[   70.802576] device veth1203a6a entered promiscuous mode
[   70.803004] hassio: port 7(veth1203a6a) entered blocking state
[   70.803014] hassio: port 7(veth1203a6a) entered forwarding state
[   71.198245] hassio: port 7(veth1203a6a) entered disabled state
[   71.740035] eth0: renamed from vethe448ba7
[   71.768963] IPv6: ADDRCONF(NETDEV_CHANGE): veth1203a6a: link becomes ready
[   71.769105] hassio: port 7(veth1203a6a) entered blocking state
[   71.769112] hassio: port 7(veth1203a6a) entered forwarding state
[   72.596160] hassio: port 8(vethb98c2ac) entered blocking state
[   72.596175] hassio: port 8(vethb98c2ac) entered disabled state
[   72.596386] device vethb98c2ac entered promiscuous mode
[   73.770667] eth0: renamed from vethfd4ac37
[   73.795026] IPv6: ADDRCONF(NETDEV_CHANGE): vethb98c2ac: link becomes ready
[   73.795177] hassio: port 8(vethb98c2ac) entered blocking state
[   73.795185] hassio: port 8(vethb98c2ac) entered forwarding state
[   77.290956] kauditd_printk_skb: 35 callbacks suppressed
[   77.290963] audit: type=1334 audit(1626518023.495:206): prog-id=12 op=UNLOAD
[   77.290983] audit: type=1334 audit(1626518023.495:207): prog-id=11 op=UNLOAD
[   77.333139] audit: type=1334 audit(1626518023.535:208): prog-id=14 op=UNLOAD
[   77.333165] audit: type=1334 audit(1626518023.535:209): prog-id=13 op=UNLOAD
[  123.616599] hassio: port 9(veth390ef3a) entered blocking state
[  123.616611] hassio: port 9(veth390ef3a) entered disabled state
[  123.618914] device veth390ef3a entered promiscuous mode
[  123.618996] audit: type=1700 audit(1626518069.900:210): dev=veth390ef3a prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[  124.420137] audit: type=1325 audit(1626518070.670:211): table=nat family=2 entries=0 op=xt_register pid=8263 subj==unconfined comm="iptables"
[  124.468129] audit: type=1325 audit(1626518070.722:212): table=filter family=2 entries=0 op=xt_register pid=8264 subj==unconfined comm="iptables"
[  124.496350] audit: type=1325 audit(1626518070.770:213): table=nat family=2 entries=5 op=xt_replace pid=8267 subj==unconfined comm="iptables"
[  124.536965] audit: type=1325 audit(1626518070.790:214): table=nat family=2 entries=7 op=xt_replace pid=8268 subj==unconfined comm="iptables"
[  124.576757] audit: type=1325 audit(1626518070.834:215): table=nat family=2 entries=8 op=xt_replace pid=8270 subj==unconfined comm="iptables"
[  124.620800] audit: type=1325 audit(1626518070.866:216): table=nat family=2 entries=10 op=xt_replace pid=8272 subj==unconfined comm="iptables"
[  124.651805] audit: type=1325 audit(1626518070.914:217): table=nat family=2 entries=11 op=xt_replace pid=8273 subj==unconfined comm="iptables"
[  124.675724] audit: type=1325 audit(1626518070.942:218): table=nat family=2 entries=12 op=xt_replace pid=8274 subj==unconfined comm="iptables"
[  124.708618] audit: type=1325 audit(1626518070.966:219): table=nat family=2 entries=13 op=xt_replace pid=8275 subj==unconfined comm="iptables"
[  124.789914] eth0: renamed from veth809d2f1
[  124.830034] IPv6: ADDRCONF(NETDEV_CHANGE): veth390ef3a: link becomes ready
[  124.830201] hassio: port 9(veth390ef3a) entered blocking state
[  124.830210] hassio: port 9(veth390ef3a) entered forwarding state
[  125.909343] hassio: port 10(vethcf66fa6) entered blocking state
[  125.909357] hassio: port 10(vethcf66fa6) entered disabled state
[  125.910268] device vethcf66fa6 entered promiscuous mode
[  127.063678] eth0: renamed from vethae33ee6
[  127.077692] IPv6: ADDRCONF(NETDEV_CHANGE): vethcf66fa6: link becomes ready
[  127.077920] hassio: port 10(vethcf66fa6) entered blocking state
[  127.077929] hassio: port 10(vethcf66fa6) entered forwarding state
[  128.106666] hassio: port 11(veth02269dc) entered blocking state
[  128.106680] hassio: port 11(veth02269dc) entered disabled state
[  128.106997] device veth02269dc entered promiscuous mode
[  129.482845] kauditd_printk_skb: 16 callbacks suppressed
[  129.482854] audit: type=1325 audit(1626518075.749:236): table=nat family=2 entries=0 op=xt_register pid=8900 subj==unconfined comm="iptables"
[  129.532997] audit: type=1325 audit(1626518075.797:237): table=filter family=2 entries=0 op=xt_register pid=8901 subj==unconfined comm="iptables"
[  129.588920] audit: type=1325 audit(1626518075.853:238): table=nat family=2 entries=5 op=xt_replace pid=8904 subj==unconfined comm="iptables"
[  129.632787] audit: type=1325 audit(1626518075.901:239): table=nat family=2 entries=7 op=xt_replace pid=8905 subj==unconfined comm="iptables"
[  129.664631] audit: type=1325 audit(1626518075.937:240): table=nat family=2 entries=8 op=xt_replace pid=8910 subj==unconfined comm="iptables"
[  129.693226] audit: type=1325 audit(1626518075.969:241): table=nat family=2 entries=10 op=xt_replace pid=8914 subj==unconfined comm="iptables"
[  129.728751] audit: type=1325 audit(1626518076.005:242): table=nat family=2 entries=11 op=xt_replace pid=8915 subj==unconfined comm="iptables"
[  129.752629] audit: type=1325 audit(1626518076.029:243): table=nat family=2 entries=12 op=xt_replace pid=8916 subj==unconfined comm="iptables"
[  129.788739] audit: type=1325 audit(1626518076.061:244): table=nat family=2 entries=13 op=xt_replace pid=8917 subj==unconfined comm="iptables"
[  129.816619] audit: type=1325 audit(1626518076.093:245): table=nat family=2 entries=14 op=xt_replace pid=8918 subj==unconfined comm="iptables"
[  129.862167] eth0: renamed from veth221a1a3
[  129.879028] IPv6: ADDRCONF(NETDEV_CHANGE): veth02269dc: link becomes ready
[  129.879198] hassio: port 11(veth02269dc) entered blocking state
[  129.879207] hassio: port 11(veth02269dc) entered forwarding state
[  130.988340] hassio: port 12(veth6481e89) entered blocking state
[  130.988356] hassio: port 12(veth6481e89) entered disabled state
[  130.989274] device veth6481e89 entered promiscuous mode
[  132.731186] eth0: renamed from veth6369292
[  132.759812] IPv6: ADDRCONF(NETDEV_CHANGE): veth6481e89: link becomes ready
[  132.759972] hassio: port 12(veth6481e89) entered blocking state
[  132.759981] hassio: port 12(veth6481e89) entered forwarding state
[  138.054082] kauditd_printk_skb: 11 callbacks suppressed
[  138.054090] audit: type=1334 audit(1626518084.353:257): prog-id=15 op=LOAD
[  138.054338] audit: type=1334 audit(1626518084.353:258): prog-id=16 op=LOAD
[  138.659134] audit: type=1334 audit(1626518084.957:259): prog-id=17 op=LOAD
[  138.660427] audit: type=1334 audit(1626518084.957:260): prog-id=18 op=LOAD
[  168.656626] audit: type=1334 audit(1626518114.954:261): prog-id=16 op=UNLOAD
[  168.656654] audit: type=1334 audit(1626518114.954:262): prog-id=15 op=UNLOAD
[  169.104332] audit: type=1334 audit(1626518115.402:263): prog-id=18 op=UNLOAD
[  169.104388] audit: type=1334 audit(1626518115.402:264): prog-id=17 op=UNLOAD
[  595.201724] hassio: port 7(veth1203a6a) entered disabled state
[  595.202072] vethe448ba7: renamed from eth0
[  595.279059] hassio: port 7(veth1203a6a) entered disabled state
[  595.280273] device veth1203a6a left promiscuous mode
[  595.280329] audit: type=1700 audit(1626518541.553:265): dev=veth1203a6a prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
[  595.281210] hassio: port 7(veth1203a6a) entered disabled state
[  595.502004] audit: type=1325 audit(1626518541.793:266): table=nat family=2 entries=15 op=xt_unregister pid=73 subj==unconfined comm="kworker/u8:1"
[  595.502031] audit: type=1325 audit(1626518541.793:267): table=filter family=2 entries=4 op=xt_unregister pid=73 subj==unconfined comm="kworker/u8:1"
[  595.925535] hassio: port 7(veth15ee9a7) entered blocking state
[  595.925550] hassio: port 7(veth15ee9a7) entered disabled state
[  595.926556] device veth15ee9a7 entered promiscuous mode
[  595.926806] audit: type=1700 audit(1626518542.217:268): dev=veth15ee9a7 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[  595.929435] hassio: port 7(veth15ee9a7) entered blocking state
[  595.929448] hassio: port 7(veth15ee9a7) entered forwarding state
[  596.212867] hassio: port 7(veth15ee9a7) entered disabled state
[  596.496549] audit: type=1325 audit(1626518542.753:269): table=nat family=2 entries=0 op=xt_register pid=11856 subj==unconfined comm="iptables"
[  596.544744] audit: type=1325 audit(1626518542.801:270): table=filter family=2 entries=0 op=xt_register pid=11857 subj==unconfined comm="iptables"
[  596.600648] audit: type=1325 audit(1626518542.861:271): table=nat family=2 entries=5 op=xt_replace pid=11860 subj==unconfined comm="iptables"
[  596.628532] audit: type=1325 audit(1626518542.897:272): table=nat family=2 entries=7 op=xt_replace pid=11861 subj==unconfined comm="iptables"
[  596.668715] audit: type=1325 audit(1626518542.933:273): table=nat family=2 entries=8 op=xt_replace pid=11863 subj==unconfined comm="iptables"
[  596.688539] audit: type=1325 audit(1626518542.965:274): table=nat family=2 entries=10 op=xt_replace pid=11864 subj==unconfined comm="iptables"
[  596.844242] eth0: renamed from vethd161138
[  596.867508] IPv6: ADDRCONF(NETDEV_CHANGE): veth15ee9a7: link becomes ready
[  596.867708] hassio: port 7(veth15ee9a7) entered blocking state
[  596.867721] hassio: port 7(veth15ee9a7) entered forwarding state
[ 7738.123327] kauditd_printk_skb: 4 callbacks suppressed
[ 7738.123335] audit: type=1334 audit(1626525684.305:279): prog-id=19 op=LOAD
[ 7738.123794] audit: type=1334 audit(1626525684.305:280): prog-id=20 op=LOAD
[ 7738.476221] audit: type=1334 audit(1626525684.657:281): prog-id=21 op=LOAD
[ 7738.476620] audit: type=1334 audit(1626525684.657:282): prog-id=22 op=LOAD
[ 7768.501938] audit: type=1334 audit(1626525714.685:283): prog-id=20 op=UNLOAD
[ 7768.501984] audit: type=1334 audit(1626525714.685:284): prog-id=19 op=UNLOAD
[ 7768.845715] audit: type=1334 audit(1626525715.029:285): prog-id=22 op=UNLOAD
[ 7768.845738] audit: type=1334 audit(1626525715.029:286): prog-id=21 op=UNLOAD
[14212.569651] hassio: port 7(veth15ee9a7) entered disabled state
[14212.570149] vethd161138: renamed from eth0
[14212.653330] hassio: port 7(veth15ee9a7) entered disabled state
[14212.654594] device veth15ee9a7 left promiscuous mode
[14212.654617] hassio: port 7(veth15ee9a7) entered disabled state
[14212.654653] audit: type=1700 audit(1626532158.713:287): dev=veth15ee9a7 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
[14212.826791] audit: type=1325 audit(1626532158.905:288): table=nat family=2 entries=15 op=xt_unregister pid=39656 subj==unconfined comm="kworker/u8:2"
[14212.826825] audit: type=1325 audit(1626532158.905:289): table=filter family=2 entries=4 op=xt_unregister pid=39656 subj==unconfined comm="kworker/u8:2"
[14213.274658] hassio: port 7(vethef828b5) entered blocking state
[14213.274676] hassio: port 7(vethef828b5) entered disabled state
[14213.277840] device vethef828b5 entered promiscuous mode
[14213.277903] audit: type=1700 audit(1626532159.353:290): dev=vethef828b5 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
[14213.279345] hassio: port 7(vethef828b5) entered blocking state
[14213.279357] hassio: port 7(vethef828b5) entered forwarding state
[14213.577518] hassio: port 7(vethef828b5) entered disabled state
[14213.817448] audit: type=1325 audit(1626532159.881:291): table=nat family=2 entries=0 op=xt_register pid=44501 subj==unconfined comm="iptables"
[14213.857490] audit: type=1325 audit(1626532159.917:292): table=filter family=2 entries=0 op=xt_register pid=44503 subj==unconfined comm="iptables"
[14213.885507] audit: type=1325 audit(1626532159.949:293): table=nat family=2 entries=5 op=xt_replace pid=44506 subj==unconfined comm="iptables"
[14213.913472] audit: type=1325 audit(1626532159.969:294): table=nat family=2 entries=7 op=xt_replace pid=44507 subj==unconfined comm="iptables"
[14213.945497] audit: type=1325 audit(1626532160.005:295): table=nat family=2 entries=8 op=xt_replace pid=44509 subj==unconfined comm="iptables"
[14213.977480] audit: type=1325 audit(1626532160.029:296): table=nat family=2 entries=10 op=xt_replace pid=44510 subj==unconfined comm="iptables"
[14214.154576] eth0: renamed from veth500084b
[14214.174365] IPv6: ADDRCONF(NETDEV_CHANGE): vethef828b5: link becomes ready
[14214.174494] hassio: port 7(vethef828b5) entered blocking state
[14214.174502] hassio: port 7(vethef828b5) entered forwarding state
Masterz69 commented 3 years ago

Just upgraded core 6.6 -> 7.3. And woila:

➜  ~ date
Sat Jul 17 18:05:11 EEST 2021
➜  ~ ha network info
docker:
  address: 172.30.32.0/23
  dns: 172.30.32.3
  gateway: 172.30.32.1
  interface: hassio
host_internet: false

again false.... WT.

21-07-17 17:41:58 INFO (MainThread) [supervisor.homeassistant.core] Detect a running Home Assistant instance
21-07-17 17:41:58 INFO (MainThread) [supervisor.homeassistant.core] Successful started Home Assistant 2021.7.3
21-07-17 17:41:58 INFO (SyncWorker_2) [supervisor.docker.interface] Cleanup images: ['ghcr.io/home-assistant/raspberrypi4-64-homeassistant:2021.6.6']
21-07-17 17:48:18 INFO (MainThread) [supervisor.host.info] Updating local host information
21-07-17 17:48:19 INFO (MainThread) [supervisor.host.services] Updating service information
21-07-17 17:48:19 INFO (MainThread) [supervisor.host.network] Updating local network information
21-07-17 17:48:22 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
21-07-17 17:48:22 INFO (MainThread) [supervisor.host] Host information reload completed
21-07-17 17:51:03 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-17 17:51:43 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
Masterz69 commented 3 years ago

See (strong?) correlation. Again restarted ZWaveJS add-on and again host_internet become true.

21-07-17 18:06:30 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-17 18:07:11 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-17 18:07:14 INFO (SyncWorker_7) [supervisor.docker.interface] Stopping addon_a0d7b954_zwavejs2mqtt application
21-07-17 18:07:18 INFO (SyncWorker_7) [supervisor.docker.interface] Cleaning addon_a0d7b954_zwavejs2mqtt application
21-07-17 18:07:19 INFO (SyncWorker_1) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/zwavejs2mqtt/aarch64 with version 0.19.0
➜  ~ date
Sat Jul 17 18:08:00 EEST 2021
➜  ~ ha network info
docker:
  address: 172.30.32.0/23
  dns: 172.30.32.3
  gateway: 172.30.32.1
  interface: hassio
host_internet: true
Masterz69 commented 3 years ago

And after some time with NO intervention from my side - no changes, nothing:

➜  ~ date
Sat Jul 17 20:12:00 EEST 2021
➜  ~ ha network info
docker:
  address: 172.30.32.0/23
  dns: 172.30.32.3
  gateway: 172.30.32.1
  interface: hassio
host_internet: false

it again failse. WHY !?!?!?!!?

Finne75 commented 3 years ago

Hello,

I had the same problem (running home assistant os). I found out that in my case, Network Manager on the host system showed the connection status as "limited", which is translated to host_internet: false by the supervisor.

I am not sure why this was the case. In the host system, I could resolve the connectivity check host name "version.home-assistant.io" using nslookup. However, when I tried to fetch the URL "http://version.home-assistant.io/online.txt" via curl, it failed with an error message that the host could not be resolved.

What resolved the issue in the end was to switch off IPv6 for the (WLAN) connection via nmcli:

nmcli c modify <connection> ipv6.method "disabled"

followed by

nmcli connection up <connection>.

After that, "nmcli g status" showed full connectivity again, and so did "ha network info", and I could update add-ons and the core.

It would still be nice to find out what the problem is, I suspect some issue with my DNS configuration.

Masterz69 commented 3 years ago

Now I have: OS 6.1, supervisor-2021.06.8, core-2021.7.3, Z-Wave JS to MQTT 0.22.1

➜  ~ date
Sun Jul 18 11:38:37 EEST 2021
➜  ~ ha network info | grep internet
host_internet: false
supervisor_internet: true
➜  ~ date
Sun Jul 18 11:39:35 EEST 2021
➜  ~ ha network info | grep internet
host_internet: true
supervisor_internet: true

In between - ZWave add-on restart:

21-07-18 11:38:51 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-18 11:39:09 INFO (SyncWorker_3) [supervisor.docker.interface] Stopping addon_a0d7b954_zwavejs2mqtt application
21-07-18 11:39:14 INFO (SyncWorker_3) [supervisor.docker.interface] Cleaning addon_a0d7b954_zwavejs2mqtt application
21-07-18 11:39:16 INFO (SyncWorker_2) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/zwavejs2mqtt/aarch64 with version 0.22.1
Masterz69 commented 3 years ago
➜  ~ date
Mon Jul 19 15:28:43 EEST 2021
➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled
➜  ~ ha network info | grep internet
host_internet: false
supervisor_internet: true

21-07-19 15:29:11 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-19 15:29:12 INFO (SyncWorker_1) [supervisor.docker.interface] Cleaning addon_a0d7b954_zwavejs2mqtt application
21-07-19 15:29:14 INFO (SyncWorker_6) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/zwavejs2mqtt/aarch64 with version 0.22.1
21-07-19 15:29:16 WARNING (MainThread) [supervisor.misc.tasks] Watchdog found a problem with a0d7b954_zwavejs2mqtt application!
21-07-19 15:29:16 INFO (SyncWorker_0) [supervisor.docker.interface] Stopping addon_a0d7b954_zwavejs2mqtt application
21-07-19 15:29:20 INFO (SyncWorker_0) [supervisor.docker.interface] Cleaning addon_a0d7b954_zwavejs2mqtt application
21-07-19 15:29:22 INFO (SyncWorker_3) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/zwavejs2mqtt/aarch64 with version 0.22.1

➜  ~ date
Mon Jul 19 15:30:20 EEST 2021
➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled
➜  ~ ha network info | grep internet
host_internet: true
supervisor_internet: true

^^ As You can see - host Internet connectivity restored to FULL as soon as ZWaveJS add-on was restarted. Next time will try to restart some other add-on.

Pls point me - where I can see some logs: why & when connectivity changes. Would be nice to check some docs: how this connectivity is determined.

Masterz69 commented 3 years ago

Adding some output, is it Ok - eth0 & wlan0 actually connected to same network, but is looks like:

➜  ~ nmcli con show
NAME              UUID                                  TYPE      DEVICE
Supervisor wlan0  21dbd546-0045-49cb-9838-2f6726e0e575  wifi      wlan0
fancy             d55165b4-6132-4710-9812-8f4c50d84afa  ethernet  eth0
➜
Masterz69 commented 3 years ago

Samba Backup add-on restart also affects host_internet.

➜  ~ date
Tue Jul 20 13:17:55 EEST 2021
➜  ~ ha network info | grep internet
host_internet: false
supervisor_internet: true

21-07-20 13:18:19 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-20 13:18:39 INFO (SyncWorker_2) [supervisor.docker.interface] Stopping addon_15d21743_samba_backup application
21-07-20 13:18:39 INFO (SyncWorker_2) [supervisor.docker.interface] Cleaning addon_15d21743_samba_backup application
21-07-20 13:18:41 INFO (SyncWorker_3) [supervisor.docker.addon] Starting Docker add-on thomasmauerer/samba-backup-aarch64 with version 4.5.0

➜  ~ date
Tue Jul 20 13:18:53 EEST 2021
➜  ~ ha network info | grep internet
host_internet: true
supervisor_internet: true
➜
Masterz69 commented 3 years ago

Disabled wlan0 IPv6 via GUI. As many versions before - it disabled IPv4 too. After ha host reload - wlan0 become as it must be - see #2639:

- connected: true
  enabled: true
  interface: wlan0
  ipv4:
    address:
    - 192.168.1.11/24
    gateway: 192.168.1.1
    method: static
    nameservers:
    - 192.168.1.9
  ipv6:
    address: []
    gateway: null
    method: disabled
    nameservers: []

but even now

➜  ~ date
Wed Jul 21 21:51:01 EEST 2021
➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled

Restarting phpMyAdmin add-on

21-07-21 21:51:58 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-21 21:52:34 INFO (SyncWorker_4) [supervisor.docker.interface] Stopping addon_a0d7b954_phpmyadmin application
21-07-21 21:52:38 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-07-21 21:52:38 INFO (SyncWorker_4) [supervisor.docker.interface] Cleaning addon_a0d7b954_phpmyadmin application
21-07-21 21:52:40 INFO (SyncWorker_3) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.4.3

hurai - again full connectivity

➜  ~ date
Wed Jul 21 21:53:16 EEST 2021
➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled
Masterz69 commented 3 years ago

SSH & Web Terminal add-on restart - NOT fixed connectivity issue. phpMyAdmin add-on restart - full connectivity again.

Masterz69 commented 3 years ago

wlan0 IPv6 disables by HA UI. After some time connectivity becomes limited.

➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled

Today eth0 IPv6 disabled by HA UI. W/out any other intervention connectivity state changes to full.

➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled

Will monitor situation further.

After couple of hours connectivity again become limited.

Masterz69 commented 3 years ago

HACS update working well even while connectivity = limited.

DexterityGerm commented 3 years ago

In my case, this message appears due to the fact that when contacting https://version.home-assistant.io/online.txt , it issues hCAPTCHA, so HAOS does not receive the desired response “NetworkManager is online”.

This is my problem. Having connected via VPN, everything works correctly.

Question: how to convince hCAPTCHA that I am not a bot and remove my IP from blocking?

Masterz69 commented 3 years ago

After upgrade to recent versions:

  OS Version:               Home Assistant OS 6.2
  Home Assistant Core:      2021.7.3

➜  ~
➜  ~
➜  ~ date
Tue Aug 10 11:33:19 EEST 2021
➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled
➜  ~ date
Tue Aug 10 13:52:24 EEST 2021
➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled

Connectivity still FULL for couple of hours, then become LIMITED.

Masterz69 commented 3 years ago

~16 hours on Core 2021.8.8 - connectivity still 'full'.

Masterz69 commented 3 years ago

But no, same stuff happens.

Masterz69 commented 3 years ago

Connectivity restores after HA DNS server restart.

➜  ~ ha dns logs
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] corefile.sh: executing...
[cont-init.d] corefile.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
.:53
.:5553
CoreDNS-1.8.4
linux/arm64, go1.15.13, 053c4d5-dirty
[INFO] 127.0.0.1:59516 - 28411 "AAAA IN mobile-apps.home-assistant.io. udp 58 true 2048" NOERROR - 0 5.00246087s
[ERROR] plugin/errors: 2 mobile-apps.home-assistant.io. AAAA: dial tcp 1.1.1.1:853: i/o timeout
[INFO] 127.0.0.1:38470 - 27985 "A IN mobile-apps.home-assistant.io. udp 58 true 2048" NOERROR - 0 5.003864765s
[ERROR] plugin/errors: 2 mobile-apps.home-assistant.io. A: dial tcp 1.0.0.1:853: i/o timeout
[INFO] 127.0.0.1:33566 - 9125 "NS IN . udp 17 false 512" NOERROR - 0 5.002463192s
[ERROR] plugin/errors: 2 . NS: dial tcp 1.0.0.1:853: i/o timeout
➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled
➜  ~ ha dns restart
Processing... Done.

Command completed successfully.
➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled
➜  ~ ha dns logs
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] corefile.sh: executing...
[cont-init.d] corefile.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
.:53
.:5553
CoreDNS-1.8.4
linux/arm64, go1.15.13, 053c4d5-dirty
[INFO] 127.0.0.1:59516 - 28411 "AAAA IN mobile-apps.home-assistant.io. udp 58 true 2048" NOERROR - 0 5.00246087s
[ERROR] plugin/errors: 2 mobile-apps.home-assistant.io. AAAA: dial tcp 1.1.1.1:853: i/o timeout
[INFO] 127.0.0.1:38470 - 27985 "A IN mobile-apps.home-assistant.io. udp 58 true 2048" NOERROR - 0 5.003864765s
[ERROR] plugin/errors: 2 mobile-apps.home-assistant.io. A: dial tcp 1.0.0.1:853: i/o timeout
[INFO] 127.0.0.1:33566 - 9125 "NS IN . udp 17 false 512" NOERROR - 0 5.002463192s
[ERROR] plugin/errors: 2 . NS: dial tcp 1.0.0.1:853: i/o timeout
[INFO] SIGTERM: Shutting down servers then terminating
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] corefile.sh: executing...
[cont-init.d] corefile.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
.:53
.:5553
CoreDNS-1.8.4
linux/arm64, go1.15.13, 053c4d5-dirty
➜  ~
RubenKelevra commented 3 years ago

I can confirm this issue, but I'm not using Z-Wave.

It's super annoying having to reboot the host before any update can be done.

RubenKelevra commented 3 years ago

I can confirm this issue for Home Assistant OS 6.5 / supervisor-2021.10.0 / core-2021.10.4

agners commented 3 years ago

@Masterz69 just to summarize your findings: After a while host_internet goes to false. Any add-on or plugin restart seems to fix the problem (temporarily) and host_internet becomes true again?

Now host_internet is really about the Home Assistant OS internet connectivity. It uses systemd-resolved to resolve IP addresses. My theory is that it somehow causes trouble with your local network. I am not sure why an Add-on restart recovers from that situation. What would be interesting is to get the logs of systemd-resolved. For that you would need to enable SSH on the host system (see SSH access to the host). Then use the following command:

journalctl -u systemd-resolved -b 0

Probably also worth trying to connect to the URL we use to check connectivity:

curl https://version.home-assistant.io/online.txt
Masterz69 commented 3 years ago

@Masterz69 just to summarize your findings: After a while host_internet goes to false. Any add-on or plugin restart seems to fix the problem (temporarily) and host_internet becomes true again? Yes.

Not checked all and every add-on/plugin, but only some. F.e. phpmyadmin add-on restart always restore internet connectivity. At moment running OS 6.3. Last add-on restart (Z2M) was 7 hours ago, host internet connectivity still 'full'. Will check later.

BTW when host internet connectivity is 'limited' and add-on manager does not allow any updates, HACS have no issues.

Masterz69 commented 3 years ago

Probably also worth trying to connect to the URL we use to check connectivity:

➜  log date
Tue Oct 19 12:00:42 EEST 2021
➜  log nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled
➜  log curl https://version.home-assistant.io/online.txt
NetworkManager is online
Masterz69 commented 3 years ago

It uses systemd-resolved to resolve IP addresses.

At least DNS client seems works fine when connectivity is limited.

➜  log nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled
➜  log nslookup www.hp.com
Server:         172.30.32.3
Address:        172.30.32.3#53

Non-authoritative answer:
www.hp.com      canonical name = www.hp.com.edgekey.net.
www.hp.com.edgekey.net  canonical name = e40715.dsca.akamaiedge.net.
. . . 
➜  log ping www.hp.com
PING www.hp.com (2.23.172.185): 56 data bytes
64 bytes from 2.23.172.185: seq=0 ttl=54 time=60.704 ms
64 bytes from 2.23.172.185: seq=1 ttl=54 time=51.779 ms
^C
--- www.hp.com ping statistics ---
2 packets transmitted, 2 packets received, 0% packet loss
round-trip min/avg/max = 51.779/56.241/60.704 ms

At same time Supervisor log:

21-10-19 12:05:58 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-10-19 12:06:38 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-10-19 12:07:19 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached

Last records shown in 'DNS' in Supervisor->System:

[INFO] 127.0.0.1:58656 - 63052 "PTR IN 239.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.024100215s
[INFO] 172.30.32.1:58366 - 63052 "PTR IN 239.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.026482589s
[INFO] 127.0.0.1:58656 - 21826 "PTR IN 176.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.031094715s
[INFO] 172.30.32.1:49457 - 21826 "PTR IN 176.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.033246707s
[INFO] 127.0.0.1:58656 - 38417 "PTR IN 77.1.168.192.in-addr.arpa. udp 54 true 2048" NXDOMAIN qr,rd,ra 43 0.029864129s
[INFO] 172.30.32.1:59494 - 38417 "PTR IN 77.1.168.192.in-addr.arpa. udp 43 false 512" NXDOMAIN qr,rd,ra 43 0.03177259s
[INFO] 127.0.0.1:58656 - 22307 "PTR IN 202.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.024758681s
[INFO] 172.30.32.1:37955 - 22307 "PTR IN 202.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.026717308s
[INFO] 127.0.0.1:58656 - 47675 "PTR IN 206.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.031159473s
[INFO] 172.30.32.1:40031 - 47675 "PTR IN 206.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.033444202s
[INFO] 127.0.0.1:58656 - 13965 "PTR IN 234.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.02606721s
[INFO] 172.30.32.1:33107 - 13965 "PTR IN 234.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.028009447s
[INFO] 127.0.0.1:58656 - 29644 "PTR IN 201.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.028055075s
[INFO] 172.30.32.1:52609 - 29644 "PTR IN 201.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.030267732s
[INFO] 127.0.0.1:58656 - 56643 "PTR IN 2.0.17.172.in-addr.arpa. udp 52 true 2048" NXDOMAIN qr,rd,ra 41 0.034370257s
[INFO] 172.30.32.1:35393 - 56643 "PTR IN 2.0.17.172.in-addr.arpa. udp 41 false 512" NXDOMAIN qr,rd,ra 41 0.036471602s
[INFO] 127.0.0.1:58656 - 51332 "PTR IN 178.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.024861309s
[INFO] 172.30.32.1:47759 - 51332 "PTR IN 178.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.027538457s
agners commented 3 years ago

Essentially, we have two DNS resolvers in the system:

The second is only required for Docker itself, since CoreDNS is in a container. Otherwise we end up in a chicken-egg problem.

Now NetworkManager itself uses the host DNS resolver (systemd-resolved). Core, HACS etc. all use the CoreDNS resolver. It seems that in your case the CoreDNS resolver works without problem. The SSH & Web Terminal Add-on uses CoreDNS too (the DNS server mentioned in the nslookup command is 172.30.32.3, which is the IP of the CoreDNS container).

To further debug this issue I need some logs from HAOS itself. For that you would need to enable SSH on the host system (see SSH access to the host). Then use the following command:

journalctl -u systemd-resolved -b 0

Also worth trying to connect to the URL from the host shell, while the connectivity check is limited:

nslookup version.home-assistant.io
curl https://version.home-assistant.io/online.txt
Masterz69 commented 3 years ago

Hi, @agners.

Getting "Failed to install add-on 'AddonManager.install' blocked from execution, no host internet connection".

Same time in consoles: 22 & 22222:

➜  ~ date
Fri Oct 22 09:44:32 EEST 2021
➜  ~ nmcli g status
STATE                  CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected (site only)  limited       enabled  enabled  enabled  enabled
# date
Fri Oct 22 06:45:12 UTC 2021
# nslookup version.home-assistant.io
Server:         192.168.1.9
Address:        192.168.1.9:53

Non-authoritative answer:
Name:   version.home-assistant.io
Address: 104.26.5.238
Name:   version.home-assistant.io
Address: 172.67.68.90
Name:   version.home-assistant.io
Address: 104.26.4.238

Non-authoritative answer:
Name:   version.home-assistant.io
Address: 2606:4700:20::ac43:445a
Name:   version.home-assistant.io
Address: 2606:4700:20::681a:5ee
Name:   version.home-assistant.io
Address: 2606:4700:20::681a:4ee

# curl https://version.home-assistant.io/online.txt
NetworkManager is online
# journalctl -u systemd-resolved -b 0
-- Journal begins at Sun 2021-09-26 22:46:14 UTC, ends at Fri 2021-10-22 06:45:36 UTC. --
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Positive Trust Anchors:
Oct 21 21:16:17 homeassistant systemd-resolved[358]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa corp home internal intranet lan local private test
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Using system hostname 'homeassistant'.
Oct 21 21:16:17 homeassistant systemd[1]: Started Network Name Resolution.
Oct 21 21:16:21 ha systemd-resolved[358]: System hostname changed to 'ha'.

Performing phpMyAdmin add-on restart.

21-10-22 09:50:05 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
21-10-22 09:50:35 INFO (SyncWorker_6) [supervisor.docker.interface] Stopping addon_a0d7b954_phpmyadmin application
21-10-22 09:50:39 INFO (SyncWorker_6) [supervisor.docker.interface] Cleaning addon_a0d7b954_phpmyadmin application
21-10-22 09:50:41 INFO (SyncWorker_7) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.5.0
21-10-22 09:50:45 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached

now

➜  ~ date
Fri Oct 22 09:51:25 EEST 2021
➜  ~ nmcli g status
STATE      CONNECTIVITY  WIFI-HW  WIFI     WWAN-HW  WWAN
connected  full          enabled  enabled  enabled  enabled

No changes in requested output from 22222 console:

# date
Fri Oct 22 06:51:48 UTC 2021
# nslookup version.home-assistant.io
Server:         192.168.1.9
Address:        192.168.1.9:53

Non-authoritative answer:
Name:   version.home-assistant.io
Address: 104.26.5.238
Name:   version.home-assistant.io
Address: 172.67.68.90
Name:   version.home-assistant.io
Address: 104.26.4.238

Non-authoritative answer:
Name:   version.home-assistant.io
Address: 2606:4700:20::681a:5ee
Name:   version.home-assistant.io
Address: 2606:4700:20::681a:4ee
Name:   version.home-assistant.io
Address: 2606:4700:20::ac43:445a

# curl https://version.home-assistant.io/online.txt
NetworkManager is online
# journalctl -u systemd-resolved -b 0
-- Journal begins at Sun 2021-09-26 22:46:14 UTC, ends at Fri 2021-10-22 06:51:57 UTC. --
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Positive Trust Anchors:
Oct 21 21:16:17 homeassistant systemd-resolved[358]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa corp home internal intranet lan local private test
Oct 21 21:16:17 homeassistant systemd-resolved[358]: Using system hostname 'homeassistant'.
Oct 21 21:16:17 homeassistant systemd[1]: Started Network Name Resolution.
Oct 21 21:16:21 ha systemd-resolved[358]: System hostname changed to 'ha'.

And now add-on install goes fine:

21-10-22 09:53:06 INFO (MainThread) [supervisor.addons] Add-on '1f3d020e_hassos_ssh_configurator_addon' successfully installed
Masterz69 commented 3 years ago

BTW during limited connectivity - Supervisor able to add new add-on repository, but not to install add-on from it.

Masterz69 commented 3 years ago

@agners - let's see full log for last boot, except Z2M & ZWAVE debug messages. I believe they not relevant to case.

HA_dbg_20211022_01.log

Happening during phpMyAdmin add-on restart:

Oct 22 06:50:35 ha hassos-supervisor[969]: 21-10-22 09:50:35 INFO (SyncWorker_6) [supervisor.docker.interface] Stopping addon_a0d7b954_phpmyadmin application
Oct 22 06:50:35 ha 0ca75d1521b1[472]: 21-10-22 09:50:35 INFO (SyncWorker_6) [supervisor.docker.interface] Stopping addon_a0d7b954_phpmyadmin application
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] executing container finish scripts...
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] 99-message.sh: executing... 
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] 99-message.sh: exited 0.
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] done.
Oct 22 06:50:35 ha becd14c1b965[472]: [s6-finish] waiting for services.
Oct 22 06:50:35 ha becd14c1b965[472]: [s6-finish] sending all processes the TERM signal.
Oct 22 06:50:38 ha becd14c1b965[472]: [s6-finish] sending all processes the KILL signal and exiting.
Oct 22 06:50:39 ha dockerd[472]: time="2021-10-22T06:50:39.144367560Z" level=info msg="ignoring event" container=becd14c1b9655e189e31a2228315f7f6a730606487a1a341d48b33ec47c39438 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Oct 22 06:50:39 ha dockerd[481]: time="2021-10-22T06:50:39.147584301Z" level=info msg="shim disconnected" id=becd14c1b9655e189e31a2228315f7f6a730606487a1a341d48b33ec47c39438
Oct 22 06:50:39 ha dockerd[481]: time="2021-10-22T06:50:39.147825187Z" level=error msg="copy shim log" error="read /proc/self/fd/74: file already closed"
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha kernel: vethf873d95: renamed from eth0
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2299] manager: (vethf873d95): new Veth device (/org/freedesktop/NetworkManager/Devices/33)
Oct 22 06:50:39 ha systemd-udevd[36136]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 22 06:50:39 ha systemd-udevd[36136]: Using default interface naming scheme 'v247'.
Oct 22 06:50:39 ha audit: ANOM_PROMISCUOUS dev=vethc610432 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha kernel: device vethc610432 left promiscuous mode
Oct 22 06:50:39 ha kernel: audit: type=1700 audit(1634885439.241:261): dev=vethc610432 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2770] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2779] device (vethc610432): released from master device hassio
Oct 22 06:50:39 ha systemd-udevd[36136]: vethf873d95: Failed to query device driver: No such device
Oct 22 06:50:39 ha systemd-udevd[36136]: vethf873d95: Failed to get link config: No such device
Oct 22 06:50:39 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 22 06:50:39 ha systemd[1]: Starting Network Manager Script Dispatcher Service...
Oct 22 06:50:39 ha systemd[1]: run-docker-netns-69aa3ee9a89e.mount: Succeeded.
Oct 22 06:50:39 ha systemd[1]: var-lib-docker-overlay2-9062136e37022c9fdc0430617cbdf29ece87efb692dc8196f44560141d642573-merged.mount: Succeeded.
Oct 22 06:50:39 ha systemd[1]: mnt-data-docker-overlay2-9062136e37022c9fdc0430617cbdf29ece87efb692dc8196f44560141d642573-merged.mount: Succeeded.
Oct 22 06:50:39 ha audit[35769]: NETFILTER_CFG table=nat family=2 entries=15 op=xt_unregister pid=35769 subj==unconfined comm="kworker/u8:0"
Oct 22 06:50:39 ha audit[35769]: NETFILTER_CFG table=filter family=2 entries=4 op=xt_unregister pid=35769 subj==unconfined comm="kworker/u8:0"
Oct 22 06:50:39 ha kernel: audit: type=1325 audit(1634885439.449:262): table=nat family=2 entries=15 op=xt_unregister pid=35769 subj==unconfined comm="kworker/u8:0"
Oct 22 06:50:39 ha kernel: audit: type=1325 audit(1634885439.449:263): table=filter family=2 entries=4 op=xt_unregister pid=35769 subj==unconfined comm="kworker/u8:0"
Oct 22 06:50:39 ha dbus-daemon[108]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 22 06:50:39 ha systemd[1]: Started Network Manager Script Dispatcher Service.
Oct 22 06:50:39 ha 0ca75d1521b1[472]: 21-10-22 09:50:39 INFO (SyncWorker_6) [supervisor.docker.interface] Cleaning addon_a0d7b954_phpmyadmin application
Oct 22 06:50:39 ha hassos-supervisor[969]: 21-10-22 09:50:39 INFO (SyncWorker_6) [supervisor.docker.interface] Cleaning addon_a0d7b954_phpmyadmin application
Oct 22 06:50:40 ha systemd[1]: var-lib-docker-overlay2-77d6162dee0b0c16beaee1087eb6e3e69b1d8cf083d65fe0ea79b5c8561136d0\x2dinit-merged.mount: Succeeded.
Oct 22 06:50:40 ha systemd[1]: mnt-data-docker-overlay2-77d6162dee0b0c16beaee1087eb6e3e69b1d8cf083d65fe0ea79b5c8561136d0\x2dinit-merged.mount: Succeeded.
Oct 22 06:50:40 ha systemd[1]: var-lib-docker-overlay2-77d6162dee0b0c16beaee1087eb6e3e69b1d8cf083d65fe0ea79b5c8561136d0-merged.mount: Succeeded.
Oct 22 06:50:40 ha systemd[1]: mnt-data-docker-overlay2-77d6162dee0b0c16beaee1087eb6e3e69b1d8cf083d65fe0ea79b5c8561136d0-merged.mount: Succeeded.
Oct 22 06:50:40 ha systemd-udevd[36139]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 22 06:50:40 ha systemd-udevd[36139]: Using default interface naming scheme 'v247'.
Oct 22 06:50:40 ha NetworkManager[362]: <info>  [1634885440.3666] manager: (veth7aeb7be): new Veth device (/org/freedesktop/NetworkManager/Devices/34)
Oct 22 06:50:40 ha audit: ANOM_PROMISCUOUS dev=veth271d2f7 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:40 ha kernel: hassio: port 12(veth271d2f7) entered blocking state
Oct 22 06:50:40 ha kernel: hassio: port 12(veth271d2f7) entered disabled state
Oct 22 06:50:40 ha kernel: device veth271d2f7 entered promiscuous mode
Oct 22 06:50:40 ha kernel: audit: type=1700 audit(1634885440.369:264): dev=veth271d2f7 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:40 ha NetworkManager[362]: <info>  [1634885440.3757] manager: (veth271d2f7): new Veth device (/org/freedesktop/NetworkManager/Devices/35)
Oct 22 06:50:40 ha systemd-udevd[36138]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 22 06:50:40 ha systemd-udevd[36138]: Using default interface naming scheme 'v247'.
Oct 22 06:50:40 ha dockerd[481]: time="2021-10-22T06:50:40.492216596Z" level=info msg="starting signal loop" namespace=moby path=/run/docker/containerd/daemon/io.containerd.runtime.v2.task/moby/86d17a3fd39ee5a42b72c49686ad3fa5e6cb46961f497696bffecf5ecca37ea7 pid=36155
Oct 22 06:50:40 ha systemd[1]: run-docker-runtime\x2drunc-moby-86d17a3fd39ee5a42b72c49686ad3fa5e6cb46961f497696bffecf5ecca37ea7-runc.f7L4Np.mount: Succeeded.
Oct 22 06:50:40 ha audit[36207]: NETFILTER_CFG table=nat family=2 entries=0 op=xt_register pid=36207 subj==unconfined comm="iptables"
Oct 22 06:50:40 ha kernel: audit: type=1325 audit(1634885440.969:265): table=nat family=2 entries=0 op=xt_register pid=36207 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36210]: NETFILTER_CFG table=filter family=2 entries=0 op=xt_register pid=36210 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: audit: type=1325 audit(1634885441.017:266): table=filter family=2 entries=0 op=xt_register pid=36210 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36213]: NETFILTER_CFG table=nat family=2 entries=5 op=xt_replace pid=36213 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: audit: type=1325 audit(1634885441.061:267): table=nat family=2 entries=5 op=xt_replace pid=36213 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36214]: NETFILTER_CFG table=nat family=2 entries=7 op=xt_replace pid=36214 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: audit: type=1325 audit(1634885441.081:268): table=nat family=2 entries=7 op=xt_replace pid=36214 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36216]: NETFILTER_CFG table=nat family=2 entries=8 op=xt_replace pid=36216 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: audit: type=1325 audit(1634885441.125:269): table=nat family=2 entries=8 op=xt_replace pid=36216 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36217]: NETFILTER_CFG table=nat family=2 entries=10 op=xt_replace pid=36217 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: audit: type=1325 audit(1634885441.157:270): table=nat family=2 entries=10 op=xt_replace pid=36217 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36218]: NETFILTER_CFG table=nat family=2 entries=11 op=xt_replace pid=36218 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36219]: NETFILTER_CFG table=nat family=2 entries=12 op=xt_replace pid=36219 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36220]: NETFILTER_CFG table=nat family=2 entries=13 op=xt_replace pid=36220 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha audit[36221]: NETFILTER_CFG table=nat family=2 entries=14 op=xt_replace pid=36221 subj==unconfined comm="iptables"
Oct 22 06:50:41 ha kernel: eth0: renamed from veth7aeb7be
Oct 22 06:50:41 ha kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth271d2f7: link becomes ready
Oct 22 06:50:41 ha kernel: hassio: port 12(veth271d2f7) entered blocking state
Oct 22 06:50:41 ha kernel: hassio: port 12(veth271d2f7) entered forwarding state
Oct 22 06:50:41 ha NetworkManager[362]: <info>  [1634885441.3680] device (veth271d2f7): carrier: link connected
Oct 22 06:50:41 ha 0ca75d1521b1[472]: 21-10-22 09:50:41 INFO (SyncWorker_7) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.5.0
Oct 22 06:50:41 ha hassos-supervisor[969]: 21-10-22 09:50:41 INFO (SyncWorker_7) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.5.0
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [s6-init] making user provided files available at /var/run/s6/etc...exited 0.
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [s6-init] ensuring user provided files have correct perms...exited 0.
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [fix-attrs.d] applying ownership & permissions fixes...
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [fix-attrs.d] done.
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [cont-init.d] executing container initialization scripts...
Oct 22 06:50:41 ha 86d17a3fd39e[472]: [cont-init.d] 00-banner.sh: executing... 
Oct 22 06:50:42 ha 86d17a3fd39e[472]: 
Oct 22 06:50:42 ha 86d17a3fd39e[472]: -----------------------------------------------------------
Oct 22 06:50:42 ha 86d17a3fd39e[472]:  Add-on: phpMyAdmin
Oct 22 06:50:42 ha 86d17a3fd39e[472]:  A web interface for the official MariaDB add-on
Oct 22 06:50:42 ha 86d17a3fd39e[472]: -----------------------------------------------------------
Oct 22 06:50:42 ha 86d17a3fd39e[472]:  Add-on version: 0.5.0
Oct 22 06:50:43 ha 86d17a3fd39e[472]:  You are running the latest version of this add-on.
Oct 22 06:50:43 ha 86d17a3fd39e[472]:  System: Home Assistant OS 6.3  (aarch64 / raspberrypi4-64)
Oct 22 06:50:43 ha 86d17a3fd39e[472]:  Home Assistant Core: 2021.10.3
Oct 22 06:50:44 ha 86d17a3fd39e[472]:  Home Assistant Supervisor: 2021.10.0
Oct 22 06:50:44 ha 86d17a3fd39e[472]: -----------------------------------------------------------
Oct 22 06:50:44 ha 86d17a3fd39e[472]:  Please, share the above information when looking for help
Oct 22 06:50:44 ha 86d17a3fd39e[472]:  or support in, e.g., GitHub, forums or the Discord chat.
Oct 22 06:50:44 ha 86d17a3fd39e[472]: -----------------------------------------------------------
Oct 22 06:50:44 ha 86d17a3fd39e[472]: [cont-init.d] 00-banner.sh: exited 0.
Oct 22 06:50:44 ha 86d17a3fd39e[472]: [cont-init.d] 01-log-level.sh: executing... 
Oct 22 06:50:44 ha 86d17a3fd39e[472]: [cont-init.d] 01-log-level.sh: exited 0.
Oct 22 06:50:44 ha 86d17a3fd39e[472]: [cont-init.d] phpmyadmin.sh: executing... 
Oct 22 06:50:45 ha 86d17a3fd39e[472]: [cont-init.d] phpmyadmin.sh: exited 0.
Oct 22 06:50:45 ha 86d17a3fd39e[472]: [cont-init.d] done.
Oct 22 06:50:45 ha 86d17a3fd39e[472]: [services.d] starting services
Oct 22 06:50:45 ha 86d17a3fd39e[472]: [services.d] done.
Oct 22 06:50:45 ha 86d17a3fd39e[472]: [09:50:45] INFO: Starting PHP-FPM...
Oct 22 06:50:45 ha hassos-supervisor[969]: 21-10-22 09:50:45 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
Oct 22 06:50:45 ha 0ca75d1521b1[472]: 21-10-22 09:50:45 WARNING (MainThread) [supervisor.host.network] Can't update connectivity information: Error: Timeout was reached
Oct 22 06:50:46 ha 86d17a3fd39e[472]: [09:50:46] INFO: Starting NGinx....
Oct 22 06:50:50 ha systemd[1]: NetworkManager-dispatcher.service: Succeeded.

See bunches of failed

Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 172.30.32.1:55251 - 58027 "PTR IN 211.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.043936743s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 127.0.0.1:40091 - 12215 "PTR IN 174.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.022541189s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 172.30.32.1:36919 - 12215 "PTR IN 174.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.02407904s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 127.0.0.1:40091 - 753 "PTR IN 27.1.168.192.in-addr.arpa. udp 54 true 2048" NXDOMAIN qr,rd,ra 43 0.023887154s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 172.30.32.1:33126 - 753 "PTR IN 27.1.168.192.in-addr.arpa. udp 43 false 512" NXDOMAIN qr,rd,ra 43 0.026467937s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 127.0.0.1:40091 - 52445 "PTR IN 239.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.023574973s
Oct 22 07:00:15 ha db021ea784ec[472]: [INFO] 172.30.32.1:55588 - 52445 "PTR IN 239.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.026042479s

Looks some peace of code tries to resolve LAN addresses on some DNS server, which not forwarding requests to configured HA DNS server, but returning NXDOMAIN. It happening during both full & limited connectivity, as far I see.

Masterz69 commented 3 years ago

As far I see - revolver have no issues nor in limited nor in full connectivity case. It works anyway and have no errors.

Here is a history of NetworkManager state for last boot.

Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.7957] policy: auto-activating connection 'Supervisor wlan0' (21dbd546-0045-49cb-9838-2f6726e0e575)
Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.7972] device (wlan0): Activation: starting connection 'Supervisor wlan0' (21dbd546-0045-49cb-9838-2f6726e0e575)
Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.7975] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.7984] manager: NetworkManager state is now CONNECTING
Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.8013] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 21 21:16:20 homeassistant NetworkManager[362]: <info>  [1634850980.8022] device (wlan0): Activation: (wifi) access point 'Supervisor wlan0' has security, but secrets are required.

Oct 21 21:16:21 ha systemd-hostnamed[416]: Changed hostname to 'ha'
Oct 21 21:16:21 ha systemd-resolved[358]: System hostname changed to 'ha'.
Oct 21 21:16:21 ha NetworkManager[362]: <info>  [1634850981.3076] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 21 21:16:21 ha rngd[369]: [jitter]: Enabling JITTER rng support
Oct 21 21:16:21 ha rngd[369]: [jitter]: Initialized
Oct 21 21:16:23 ha wpa_supplicant[376]: wlan0: Associated with f8:32:e4:92:73:28
Oct 21 21:16:23 ha wpa_supplicant[376]: wlan0: CTRL-EVENT-CONNECTED - Connection to f8:32:e4:92:73:28 completed [id=0 id_str=]
Oct 21 21:16:23 ha kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

Oct 21 21:17:38 ha 0a8dd02b5c49[472]: [00:17:38] INFO: Starting MariaDB
Oct 21 21:17:38 ha 0b446a0de4c5[472]:  Add-on version: 0.26.0
Oct 21 21:17:38 ha NetworkManager[362]: <info>  [1634851058.3694] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 21:17:38 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 21 21:17:38 ha NetworkManager[362]: <info>  [1634851058.3717] manager: NetworkManager state is now CONNECTED_LOCAL
Oct 21 21:17:38 ha NetworkManager[362]: <info>  [1634851058.3724] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 21:17:38 ha NetworkManager[362]: <info>  [1634851058.3729] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS
Oct 21 21:17:38 ha systemd[1]: Starting Network Manager Script Dispatcher Service...

Oct 21 21:18:24 ha NetworkManager[362]: <info>  [1634851104.7848] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 21 21:18:24 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 21 21:18:24 ha systemd[1]: Starting Network Manager Script Dispatcher Service...
Oct 21 21:18:24 ha NetworkManager[362]: <info>  [1634851104.8047] policy: set 'Supervisor eth0' (eth0) as default for IPv4 routing and DNS
Oct 21 21:18:24 ha dbus-daemon[108]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 21 21:18:24 ha systemd[1]: Started Network Manager Script Dispatcher Service.

Oct 21 21:29:10 ha NetworkManager[362]: <info>  [1634851750.3686] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 21:29:10 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 21 21:29:10 ha NetworkManager[362]: <info>  [1634851750.3735] manager: NetworkManager state is now CONNECTED_LOCAL
Oct 21 21:29:10 ha NetworkManager[362]: <info>  [1634851750.3744] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 21:29:10 ha NetworkManager[362]: <info>  [1634851750.3749] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS
Oct 21 21:29:10 ha systemd[1]: Starting Network Manager Script Dispatcher Service...
Oct 21 21:29:10 ha dbus-daemon[108]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 21 21:29:10 ha systemd[1]: Started Network Manager Script Dispatcher Service.
Oct 21 21:29:20 ha systemd[1]: NetworkManager-dispatcher.service: Succeeded.

Oct 21 23:02:16 ha 0ca75d1521b1[472]: 
Oct 21 23:02:31 ha NetworkManager[362]: <info>  [1634857351.3468] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 21 23:02:31 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 21 23:02:31 ha NetworkManager[362]: <info>  [1634857351.3519] policy: set 'Supervisor eth0' (eth0) as default for IPv4 routing and DNS
Oct 21 23:02:31 ha systemd[1]: Starting Network Manager Script Dispatcher Service...
Oct 21 23:02:31 ha dbus-daemon[108]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 21 23:02:31 ha systemd[1]: Started Network Manager Script Dispatcher Service.
Oct 21 23:02:41 ha systemd[1]: NetworkManager-dispatcher.service: Succeeded.

Oct 21 23:07:17 ha 0ca75d1521b1[472]: 
Oct 21 23:07:51 ha NetworkManager[362]: <info>  [1634857671.3689] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 23:07:51 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 21 23:07:51 ha NetworkManager[362]: <info>  [1634857671.3759] manager: NetworkManager state is now CONNECTED_LOCAL
Oct 21 23:07:51 ha NetworkManager[362]: <info>  [1634857671.3771] manager: NetworkManager state is now CONNECTED_SITE
Oct 21 23:07:51 ha NetworkManager[362]: <info>  [1634857671.3780] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS
Oct 21 23:07:51 ha systemd[1]: Starting Network Manager Script Dispatcher Service...
Oct 21 23:07:51 ha dbus-daemon[108]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 21 23:07:51 ha systemd[1]: Started Network Manager Script Dispatcher Service.
Oct 21 23:08:01 ha systemd[1]: NetworkManager-dispatcher.service: Succeeded.

Oct 22 06:50:35 ha 0ca75d1521b1[472]: 21-10-22 09:50:35 INFO (SyncWorker_6) [supervisor.docker.interface] Stopping addon_a0d7b954_phpmyadmin application
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] executing container finish scripts...
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] 99-message.sh: executing... 
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] 99-message.sh: exited 0.
Oct 22 06:50:35 ha becd14c1b965[472]: [cont-finish.d] done.
Oct 22 06:50:35 ha becd14c1b965[472]: [s6-finish] waiting for services.
Oct 22 06:50:35 ha becd14c1b965[472]: [s6-finish] sending all processes the TERM signal.
Oct 22 06:50:38 ha becd14c1b965[472]: [s6-finish] sending all processes the KILL signal and exiting.
Oct 22 06:50:39 ha dockerd[472]: time="2021-10-22T06:50:39.144367560Z" level=info msg="ignoring event" container=becd14c1b9655e189e31a2228315f7f6a730606487a1a341d48b33ec47c39438 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Oct 22 06:50:39 ha dockerd[481]: time="2021-10-22T06:50:39.147584301Z" level=info msg="shim disconnected" id=becd14c1b9655e189e31a2228315f7f6a730606487a1a341d48b33ec47c39438
Oct 22 06:50:39 ha dockerd[481]: time="2021-10-22T06:50:39.147825187Z" level=error msg="copy shim log" error="read /proc/self/fd/74: file already closed"
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha kernel: vethf873d95: renamed from eth0
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2299] manager: (vethf873d95): new Veth device (/org/freedesktop/NetworkManager/Devices/33)
Oct 22 06:50:39 ha systemd-udevd[36136]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 22 06:50:39 ha systemd-udevd[36136]: Using default interface naming scheme 'v247'.
Oct 22 06:50:39 ha audit: ANOM_PROMISCUOUS dev=vethc610432 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha kernel: device vethc610432 left promiscuous mode
Oct 22 06:50:39 ha kernel: audit: type=1700 audit(1634885439.241:261): dev=vethc610432 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
Oct 22 06:50:39 ha kernel: hassio: port 12(vethc610432) entered disabled state
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2770] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 22 06:50:39 ha NetworkManager[362]: <info>  [1634885439.2779] device (vethc610432): released from master device hassio
Oct 22 06:50:39 ha systemd-udevd[36136]: vethf873d95: Failed to query device driver: No such device
Oct 22 06:50:39 ha systemd-udevd[36136]: vethf873d95: Failed to get link config: No such device
Oct 22 06:50:39 ha dbus-daemon[108]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=362 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 22 06:50:39 ha systemd[1]: Starting Network Manager Script Dispatcher Service...

On each ... ha systemd[1]: NetworkManager-dispatcher.service: Succeeded. it flapping between interfaces: ha NetworkManager[362]: <info> [1634851750.3749] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS , next is ha NetworkManager[362]: <info> [1634857351.3519] policy: set 'Supervisor eth0' (eth0) as default for IPv4 routing and DNS and again wlan ....

agners commented 3 years ago

On each ... ha systemd[1]: NetworkManager-dispatcher.service: Succeeded. it flapping between interfaces: ha NetworkManager[362]: <info> [1634851750.3749] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS , next is ha NetworkManager[362]: <info> [1634857351.3519] policy: set 'Supervisor eth0' (eth0) as default for IPv4 routing and DNS and again wlan ....

Interesting find, I guess NetworkManager somehow sees them as "equally good" and due to some algorithm chooses the other one on every network change. It's a bit strange behavior, I need to check if I can tweak that.

Changing the primary network should not be problematic when two network connection exist.

However, what I just realize now, what is problematic is to assign the same IP on two different network interfaces. From your configuration it seems that Ethernet and WiFi are using 192.168.1.11:

interfaces:
- connected: true
  enabled: true
  interface: eth0
  ipv4:
    address:
    - 192.168.1.11/24
    gateway: 192.168.1.1
    method: static
    nameservers:
    - 192.168.1.9
...
- connected: true
  enabled: true
  interface: wlan0
  ipv4:
    address:
    - 192.168.1.11/24
    gateway: 192.168.1.1
    method: static
    nameservers:
    - 192.168.1.9
...

This is not a correct network setup: Each interface needs its own unique address. In theory there are methods to do this kind of setups (with bonding). but that is not supported at the moment.

Masterz69 commented 3 years ago

This is not a correct network setup: Each interface needs its own unique address. In theory there are methods to do this kind of setups (with bonding). but that is not supported at the moment.

Will change wlan0 IP address and see how it will behaves.

BTW using same IP on both interfaces from 1st time installed HA in ~January 2021, but issue with Addon Manager appears only in OS 6.x if I remember correctly. Have totally no issues in OS 5.x.

Masterz69 commented 3 years ago

Changed wlan0 IP address to 192.168.1.12/24 and restarted add-on, getting full connectivity. Let see some hours later.

agners commented 3 years ago

BTW using same IP on both interfaces from 1st time installed HA in ~January 2021, but issue with Addon Manager appears only in OS 6.x if I remember correctly. Have totally no issues in OS 5.x.

Hm, that could be related with the swap of primary interface. I'll check that.

Changed wlan0 IP address to 192.168.1.12/24 and restarted add-on, getting full connectivity. Let see some hours later.

Ok, let's see :crossed_fingers:

Masterz69 commented 2 years ago

So far looks good. 24hours after wlan0/eth0 have no more the same IP address - host internet connectivity still full.

As well on phpMyAdmin add-on restart - looks no default interface flapping anymore happens.

Oct 23 17:52:48 ha hassos-supervisor[969]: 21-10-23 20:52:48 INFO (SyncWorker_1) [supervisor.docker.addon] Starting Docker add-on ghcr.io/hassio-addons/phpmyadmin/aarch64 with version 0.5.0

, but las flap happened yesterday:

Oct 22 18:46:36 ha NetworkManager[362]: <info>  [1634928396.4549] policy: set 'Supervisor eth0' (eth0) as default for IPv4 routing and DNS
Oct 22 18:46:44 ha NetworkManager[362]: <info>  [1634928404.8360] policy: set 'Supervisor wlan0' (wlan0) as default for IPv4 routing and DNS

======= ======= ======= ======= ======= ======= =======

During this small investigation managed to found a source of following log entries for almost all IP in my LAN:

. . .
Oct 23 17:52:18 ha db021ea784ec[472]: [INFO] 172.30.32.1:33091 - 43541 "PTR IN 27.1.168.192.in-addr.arpa. udp 43 false 512" NXDOMAIN qr,rd,ra 43 0.034694301s
Oct 23 17:52:18 ha db021ea784ec[472]: [INFO] 127.0.0.1:49165 - 21069 "PTR IN 239.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.030182847s
Oct 23 17:52:18 ha db021ea784ec[472]: [INFO] 172.30.32.1:44768 - 21069 "PTR IN 239.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.031783879s
. . .
Oct 23 17:54:22 ha db021ea784ec[472]: [INFO] 127.0.0.1:57382 - 8489 "PTR IN 27.1.168.192.in-addr.arpa. udp 54 true 2048" NXDOMAIN qr,rd,ra 43 0.585325217s
Oct 23 17:54:22 ha db021ea784ec[472]: [INFO] 172.30.32.1:42381 - 8489 "PTR IN 27.1.168.192.in-addr.arpa. udp 43 false 512" NXDOMAIN qr,rd,ra 43 0.587059322s
Oct 23 17:54:22 ha db021ea784ec[472]: [INFO] 127.0.0.1:57382 - 60202 "PTR IN 239.1.168.192.in-addr.arpa. udp 55 true 2048" NXDOMAIN qr,rd,ra 44 0.036719124s
Oct 23 17:54:22 ha db021ea784ec[472]: [INFO] 172.30.32.1:50011 - 60202 "PTR IN 239.1.168.192.in-addr.arpa. udp 44 false 512" NXDOMAIN qr,rd,ra 44 0.038761577s

Root cause is a command line sensor:

    - platform: command_line
      name: ARP Count Total
      command: "arp | grep eth0 | wc -l"
      scan_interval: 120

To get rid of NXDOMAIN logging - will use arp -n from now.

Thank You very much, @agners.