Home Assistant crashing (Supervisor stays up)

Configuration
1

For the second time in the last week or so, I’ve woken up to see my Home Assistant is no longer running. I’m running “Home Assistant Supervised” on a NUC clone, on (latest as I post) 115.6, with Supervisor 245.

Rather than just a reboot which got it working last time I thought I’d first make some effort to work out why it did it! I can still ssh into the box and I can see all the hassio_* containers are up and running, but home assistant itself and all the addons have died:

root@zbox:~# docker ps -a
CONTAINER ID        IMAGE                                            COMMAND                  CREATED             STATUS                      PORTS                  NAMES
1a632a08ccc9        homeassistant/amd64-hassio-multicast:3           "/init"                  11 hours ago        Up 11 hours                                        hassio_multicast
199b3d59d750        homeassistant/amd64-hassio-cli:26                "/init /bin/bash -c …"   11 hours ago        Up 11 hours                                        hassio_cli
beb5cab91229        homeassistant/amd64-hassio-audio:17              "/init"                  11 hours ago        Up 11 hours                                        hassio_audio
fe7053a9f2fa        homeassistant/amd64-hassio-dns:9                 "/init coredns -conf…"   11 hours ago        Up 11 hours                                        hassio_dns
5c81a637ba5b        hassioaddons/log-viewer-amd64:0.8.1              "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_a0d7b954_logviewer
8e7d59162259        homeassistant/amd64-addon-configurator:5.0.0     "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_core_configurator
b869801fdb40        esphome/esphome-hassio-amd64:1.14.5              "/init"                  39 hours ago        Exited (129) 11 hours ago                          addon_15ef4d2f_esphome
66374ad3583b        hassioaddons/vscode-amd64:2.7.1                  "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_a0d7b954_vscode
d87878e5aa79        hassioaddons/portainer-amd64:1.2.2               "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_a0d7b954_portainer
7c9a5e938871        hassioaddons/grafana-amd64:5.3.0                 "/init"                  39 hours ago        Exited (129) 11 hours ago                          addon_a0d7b954_grafana
f5973c66ecd0        hassioaddons/influxdb-amd64:3.7.6                "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_a0d7b954_influxdb
f46d447ce251        hassioaddons/glances-amd64:0.8.0                 "/init"                  39 hours ago        Exited (0) 11 hours ago                            addon_a0d7b954_glances
6eb15ac5e24e        homeassistant/qemux86-64-homeassistant:0.115.6   "/init"                  46 hours ago        Exited (0) 11 hours ago                            homeassistant
38579fe29ad3        homeassistant/amd64-hassio-supervisor            "/init"                  2 weeks ago         Up 11 hours                                        hassio_supervisor
9571021e706c        homeassistant/amd64-hassio-observer:3            "/init"                  2 weeks ago         Up 11 hours                 0.0.0.0:4357->80/tcp   hassio_observer
6cc2a33384e0        homeassistant/amd64-addon-check_config:3.3.0     "/init"                  4 months ago        Exited (0) 4 months ago                            addon_core_check_config

I can see the web page for the observer, but it simply tells me that the Supervisor is connected.

This is what the end of the home assistant log looks like:

2020-10-03 00:46:19 ERROR (SyncWorker_17) [homeassistant.components.influxdb] InfluxDB database is not accessible due to '404: {"error":"database not found: \"home_assistant\""}
'. Please check that the database, username and password are correct and that the specified user has the correct permissions set. Retrying in 60 seconds.
2020-10-03 00:47:19 ERROR (SyncWorker_1) [homeassistant.components.influxdb] InfluxDB database is not accessible due to '404: {"error":"database not found: \"home_assistant\""}
'. Please check that the database, username and password are correct and that the specified user has the correct permissions set. Retrying in 60 seconds.
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
2020-10-03 00:48:04 WARNING (MainThread) [homeassistant.components.onvif] Failed to fetch ONVIF PullPoint subscription messages for '9c:14:63:87:cf:ad'
2020-10-03 00:48:04 WARNING (MainThread) [homeassistant.components.onvif] Failed to fetch ONVIF PullPoint subscription messages for '18:68:cb:28:bb:d7'
2020-10-03 00:48:06 ERROR (MainThread) [homeassistant] Error doing job: Future exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
TypeError: stop() takes 1 positional argument but 2 were given
Update for binary_sensor.ping_8_8_8_8 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 469, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/ping/binary_sensor.py", line 117, in async_update
    await self._ping.async_update()
  File "/usr/src/homeassistant/homeassistant/components/ping/binary_sensor.py", line 138, in async_update
    data = await self.hass.async_add_executor_job(
  File "/usr/src/homeassistant/homeassistant/core.py", line 350, in async_add_executor_job
    task = self.loop.run_in_executor(None, target, *args)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 783, in run_in_executor
    executor.submit(func, *args), loop=self)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 179, in submit
    raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
Update for media_player.squeezebox_radio fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 469, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 311, in async_update
    await self._player.async_update()
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 255, in async_update
    response = await self.async_query("status", "-", "1", f"tags:{tags}")
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 246, in async_query
    return await self._lms.async_query(*parameters, player=self._id)
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/server.py", line 156, in async_query
    response = await self.session.post(url, data=data, auth=auth)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client.py", line 357, in _request
    raise RuntimeError('Session is closed')
RuntimeError: Session is closed
Update for media_player.squeezebox_touch fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 469, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 311, in async_update
    await self._player.async_update()
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 255, in async_update
    response = await self.async_query("status", "-", "1", f"tags:{tags}")
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 246, in async_query
    return await self._lms.async_query(*parameters, player=self._id)
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/server.py", line 156, in async_query
    response = await self.session.post(url, data=data, auth=auth)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client.py", line 357, in _request
    raise RuntimeError('Session is closed')
RuntimeError: Session is closed
Update for binary_sensor.ping_8_8_8_8 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 469, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/ping/binary_sensor.py", line 117, in async_update
    await self._ping.async_update()
  File "/usr/src/homeassistant/homeassistant/components/ping/binary_sensor.py", line 138, in async_update
    data = await self.hass.async_add_executor_job(
  File "/usr/src/homeassistant/homeassistant/core.py", line 350, in async_add_executor_job
    task = self.loop.run_in_executor(None, target, *args)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 783, in run_in_executor
    executor.submit(func, *args), loop=self)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 179, in submit
    raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
Update for switch.l_subwoofer_248 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 471, in async_device_update
    await self.hass.async_add_executor_job(self.update)  # type: ignore
  File "/usr/src/homeassistant/homeassistant/core.py", line 350, in async_add_executor_job
    task = self.loop.run_in_executor(None, target, *args)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 783, in run_in_executor
    executor.submit(func, *args), loop=self)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 179, in submit
    raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
Update for light.h_lamp_79 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 278, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 471, in async_device_update
    await self.hass.async_add_executor_job(self.update)  # type: ignore
  File "/usr/src/homeassistant/homeassistant/core.py", line 350, in async_add_executor_job
    task = self.loop.run_in_executor(None, target, *args)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 783, in run_in_executor
    executor.submit(func, *args), loop=self)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 179, in submit
    raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
s6-svscanctl: fatal: unable to control /var/run/s6/services: supervisor not listening
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
root@zbox:~#

I see that “supervisor not listening” error is mentioned here:

Could that be my issue?

There were lots of those InfluxDB errors before this. I’d been having issues getting connection to the InfluxDB addon working yesterday. Had abandoned it to have another look today.

Here’s the log from the Supervisor, from before until after the crash:

20-10-02 23:48:04 INFO (MainThread) [supervisor.misc.scheduler] Shutdown scheduled tasks
20-10-02 23:48:04 INFO (MainThread) [supervisor.api] Stop API on 172.30.32.2
20-10-02 23:48:04 INFO (MainThread) [supervisor.misc.hwmon] Stop Supervisor hardware monitor
20-10-02 23:48:04 INFO (MainThread) [supervisor.core] Supervisor is down
[cont-finish.d] executing container finish scripts...
20-10-02 23:48:04 INFO (MainThread) [__main__] Close Supervisor
[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] udev.sh: executing...
[23:48:09] INFO: Update udev information
[cont-init.d] udev.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
[23:48:09] INFO: Start local supervisor watchdog...
20-10-02 23:48:10 INFO (MainThread) [supervisor.bootstrap] Use the old homeassistant repository for machine extraction
20-10-02 23:48:10 INFO (MainThread) [__main__] Initialize Supervisor setup
20-10-02 23:48:10 INFO (MainThread) [supervisor.bootstrap] Initialize Supervisor Sentry
20-10-02 23:48:10 INFO (MainThread) [supervisor.bootstrap] Setup coresys for machine: qemux86-64
20-10-02 23:48:10 INFO (SyncWorker_0) [supervisor.docker.supervisor] Attach to Supervisor homeassistant/amd64-hassio-supervisor with version 245
20-10-02 23:48:10 ERROR (MainThread) [supervisor.docker] Docker logging driver json-file is not supported!
20-10-02 23:48:10 INFO (MainThread) [__main__] Setup Supervisor
20-10-02 23:48:16 WARNING (MainThread) [supervisor.dbus.rauc] Host has no rauc support. OTA updates have been disabled.
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.info] Update local host information
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.services] Update service information
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.network] Update local network information
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.sound] Update PulseAudio information
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.apparmor] Load AppArmor Profiles: {'hassio-supervisor'}
20-10-02 23:48:16 INFO (MainThread) [supervisor.host.services] Reload local service hassio-apparmor.service
20-10-02 23:48:16 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-hassio-dns with version 9
20-10-02 23:48:16 INFO (MainThread) [supervisor.plugins.dns] Start CoreDNS plugin
20-10-02 23:48:16 INFO (SyncWorker_0) [supervisor.docker.interface] Clean hassio_dns application
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.dns] Start DNS homeassistant/amd64-hassio-dns with version 9 - 172.30.32.3
20-10-02 23:48:17 INFO (MainThread) [supervisor.plugins.dns] Updated /etc/resolv.conf
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-hassio-audio with version 17
20-10-02 23:48:17 INFO (MainThread) [supervisor.plugins.audio] Start Audio plugin
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.interface] Clean hassio_audio application
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.audio] Start Audio homeassistant/amd64-hassio-audio with version 17 - 172.30.32.4
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-hassio-cli with version 26
20-10-02 23:48:17 INFO (MainThread) [supervisor.plugins.cli] Start cli plugin
20-10-02 23:48:17 INFO (SyncWorker_0) [supervisor.docker.interface] Clean hassio_cli application
20-10-02 23:48:18 INFO (SyncWorker_0) [supervisor.docker.cli] Start CLI homeassistant/amd64-hassio-cli with version 26 - 172.30.32.5
20-10-02 23:48:18 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-hassio-observer with version 3
20-10-02 23:48:18 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-hassio-multicast with version 3
20-10-02 23:48:18 INFO (MainThread) [supervisor.plugins.multicast] Start Multicast plugin
20-10-02 23:48:18 INFO (SyncWorker_0) [supervisor.docker.interface] Clean hassio_multicast application
20-10-02 23:48:18 INFO (SyncWorker_0) [supervisor.docker.multicast] Start Multicast homeassistant/amd64-hassio-multicast with version 3 - Host
20-10-02 23:48:18 INFO (MainThread) [supervisor.updater] Fetch update data from https://version.home-assistant.io/stable.json
20-10-02 23:48:19 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/qemux86-64-homeassistant with version 0.115.6
20-10-02 23:48:19 INFO (MainThread) [supervisor.homeassistant.secrets] Load Home Assistant secrets: 1
20-10-02 23:48:19 INFO (MainThread) [supervisor.hassos] No Home Assistant Operating System found
20-10-02 23:48:19 INFO (MainThread) [supervisor.store.git] Load add-on /data/addons/core repository
20-10-02 23:48:19 INFO (MainThread) [supervisor.store.git] Load add-on /data/addons/git/a0d7b954 repository
20-10-02 23:48:19 INFO (MainThread) [supervisor.store.git] Load add-on /data/addons/git/15ef4d2f repository
20-10-02 23:48:19 INFO (MainThread) [supervisor.store] Load add-ons from store: 69 all - 69 new - 0 remove
20-10-02 23:48:19 INFO (MainThread) [supervisor.addons] Found 10 installed add-ons
20-10-02 23:48:19 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to hassioaddons/influxdb-amd64 with version 3.7.6
20-10-02 23:48:19 INFO (SyncWorker_4) [supervisor.docker.interface] Attach to hassioaddons/glances-amd64 with version 0.8.0
20-10-02 23:48:19 INFO (SyncWorker_2) [supervisor.docker.interface] Attach to hassioaddons/portainer-amd64 with version 1.2.2
20-10-02 23:48:19 INFO (SyncWorker_1) [supervisor.docker.interface] Attach to hassioaddons/vscode-amd64 with version 2.7.1
20-10-02 23:48:19 INFO (SyncWorker_3) [supervisor.docker.interface] Attach to hassioaddons/log-viewer-amd64 with version 0.8.1
20-10-02 23:48:19 INFO (SyncWorker_5) [supervisor.docker.interface] Attach to esphome/esphome-hassio-amd64 with version 1.14.5
20-10-02 23:48:19 INFO (SyncWorker_7) [supervisor.docker.interface] Attach to hassioaddons/grafana-amd64 with version 5.3.0
20-10-02 23:48:19 INFO (SyncWorker_0) [supervisor.docker.interface] Attach to homeassistant/amd64-addon-configurator with version 5.0.0
20-10-02 23:48:19 INFO (SyncWorker_4) [supervisor.docker.interface] Attach to homeassistant/amd64-addon-check_config with version 3.3.0
20-10-02 23:48:19 INFO (SyncWorker_6) [supervisor.docker.interface] Attach to homeassistant/amd64-addon-samba with version 9.2.0
20-10-02 23:48:19 INFO (MainThread) [supervisor.snapshots] Found 0 snapshot files
20-10-02 23:48:19 INFO (MainThread) [supervisor.discovery] Load 0 messages
20-10-02 23:48:19 INFO (MainThread) [supervisor.ingress] Load 10 ingress session
20-10-02 23:48:19 INFO (MainThread) [__main__] Run Supervisor
20-10-02 23:48:19 INFO (MainThread) [supervisor.api] Start API on 172.30.32.2
20-10-02 23:48:19 CRITICAL (MainThread) [supervisor.core] System running in a unsupported environment!
20-10-02 23:48:19 INFO (MainThread) [supervisor.addons] Phase 'AddonStartup.INITIALIZE' start 0 add-ons
20-10-02 23:48:19 INFO (MainThread) [supervisor.core] Supervisor reboot detected
20-10-02 23:48:19 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
20-10-02 23:48:19 INFO (MainThread) [supervisor.misc.hwmon] Started Supervisor hardware monitor
20-10-02 23:48:19 INFO (MainThread) [supervisor.core] Supervisor is up and running
20-10-02 23:48:19 INFO (MainThread) [supervisor.host.info] Update local host information
20-10-02 23:48:19 INFO (MainThread) [supervisor.host.services] Update service information
20-10-02 23:48:19 INFO (MainThread) [supervisor.host.network] Update local network information
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
20-10-03 01:48:19 INFO (MainThread) [supervisor.updater] Fetch update data from https://version.home-assistant.io/stable.json
 
20-10-03 01:54:59 INFO (MainThread) [supervisor.host.info] Update local host information
20-10-03 01:54:59 INFO (MainThread) [supervisor.host.services] Update service information
20-10-03 01:55:00 INFO (MainThread) [supervisor.host.network] Update local network information
20-10-03 01:55:00 INFO (MainThread) [supervisor.host.sound] Update PulseAudio information
 
 
 
 
 
 
 
 
 
 
 
20-10-03 02:48:19 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/hassio-addons/repository repository
20-10-03 02:48:19 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/home-assistant/hassio-addons repository
20-10-03 02:48:19 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/esphome/hassio repository
20-10-03 02:48:21 INFO (MainThread) [supervisor.store] Load add-ons from store: 69 all - 0 new - 0 remove
 
 
 
 
 
 
 
 
 
 
 
 
20-10-03 03:48:19 INFO (MainThread) [supervisor.updater] Fetch update data from https://version.home-assistant.io/stable.json
 
 
20-10-03 04:01:40 INFO (MainThread) [supervisor.host.info] Update local host information
20-10-03 04:01:40 INFO (MainThread) [supervisor.host.services] Update service information
20-10-03 04:01:40 INFO (MainThread) [supervisor.host.network] Update local network information
20-10-03 04:01:40 INFO (MainThread) [supervisor.host.sound] Update PulseAudio information
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
20-10-03 05:48:19 INFO (MainThread) [supervisor.updater] Fetch update data from https://version.home-assistant.io/stable.json
20-10-03 05:48:21 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/esphome/hassio repository
20-10-03 05:48:21 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/home-assistant/hassio-addons repository
20-10-03 05:48:21 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/hassio-addons/repository repository
20-10-03 05:48:22 INFO (MainThread) [supervisor.store] Load add-ons from store: 69 all - 0 new - 0 remove
 
 
 
 
20-10-03 06:08:20 INFO (MainThread) [supervisor.host.info] Update local host information
20-10-03 06:08:21 INFO (MainThread) [supervisor.host.services] Update service information
20-10-03 06:08:21 INFO (MainThread) [supervisor.host.network] Update local network information
20-10-03 06:08:21 INFO (MainThread) [supervisor.host.sound] Update PulseAudio information

I think the restart at the beginning was from me - I did a few yesterday while battling with the InfluxDB connection attempt. I’ve left all the empty lines in - is this normal?

Nothing too much in the observer log:

2020/10/01 16:19:19 Start webserver on http://0.0.0.0:80
[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] done.
[services.d] starting services
[services.d] done.
2020/10/01 20:56:11 Start webserver on http://0.0.0.0:80
[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] done.
[services.d] starting services
[services.d] done.
2020/10/03 00:48:08 Start webserver on http://0.0.0.0:80

Continuing in a follow-up post as I can’t post any more in one go…

2

The OS log around this time:

00:00:35 zbox rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="424" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
00:48:06 zbox kernel: [100343.352238] hassio: port 7(veth9e225db) entered disabled state
00:48:06 zbox kernel: [100343.357096] device veth9e225db left promiscuous mode
00:48:06 zbox kernel: [100343.357099] hassio: port 7(veth9e225db) entered disabled state
00:48:06 zbox NetworkManager[428]: <info>  [1601682486.4116] device (veth9e225db): released from master device hassio
00:48:07 zbox kernel: [100344.670359] hassio: port 10(veth12bd22f) entered disabled state
00:48:07 zbox kernel: [100344.672997] hassio: port 1(veth4eca4a4) entered disabled state
00:48:07 zbox kernel: [100344.675567] hassio: port 5(veth1a7a9e4) entered disabled state
00:48:07 zbox kernel: [100344.678034] hassio: port 4(veth616947c) entered disabled state
00:48:07 zbox kernel: [100344.682387] hassio: port 3(veth6396024) entered disabled state
00:48:07 zbox kernel: [100344.688127] device veth12bd22f left promiscuous mode
00:48:07 zbox kernel: [100344.688132] hassio: port 10(veth12bd22f) entered disabled state
00:48:07 zbox kernel: [100344.698664] device veth4eca4a4 left promiscuous mode
00:48:07 zbox kernel: [100344.698668] hassio: port 1(veth4eca4a4) entered disabled state
00:48:07 zbox kernel: [100344.727143] device veth1a7a9e4 left promiscuous mode
00:48:07 zbox kernel: [100344.727146] hassio: port 5(veth1a7a9e4) entered disabled state
00:48:07 zbox kernel: [100344.756052] device veth616947c left promiscuous mode
00:48:07 zbox kernel: [100344.756055] hassio: port 4(veth616947c) entered disabled state
00:48:07 zbox kernel: [100344.774571] device veth6396024 left promiscuous mode
00:48:07 zbox kernel: [100344.774575] hassio: port 3(veth6396024) entered disabled state
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8439] device (veth12bd22f): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8443] device (hassio): bridge port veth12bd22f was detached
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8443] device (veth12bd22f): released from master device hassio
00:48:07 zbox kernel: [100344.814317] hassio: port 1(vethe7973f1) entered blocking state
00:48:07 zbox kernel: [100344.814319] hassio: port 1(vethe7973f1) entered disabled state
00:48:07 zbox kernel: [100344.814399] device vethe7973f1 entered promiscuous mode
00:48:07 zbox kernel: [100344.814488] IPv6: ADDRCONF(NETDEV_UP): vethe7973f1: link is not ready
00:48:07 zbox kernel: [100344.814491] hassio: port 1(vethe7973f1) entered blocking state
00:48:07 zbox kernel: [100344.814492] hassio: port 1(vethe7973f1) entered forwarding state
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8902] device (veth4eca4a4): released from master device hassio
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8912] device (veth1a7a9e4): released from master device hassio
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8961] device (veth616947c): released from master device hassio
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.8974] device (veth6396024): released from master device hassio
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9037] manager: (vethaded35b): new Veth device (/org/freedesktop/NetworkManager/Devices/30)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9094] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 2.nmconnection (da26b314-6a05-3b78-8c26-c6b93c7b6873,"Wired connection 2")
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9110] settings: (vethaded35b): created default wired connection 'Wired connection 2'
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9139] device (vethaded35b): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
00:48:07 zbox kernel: [100344.885945] IPv6: ADDRCONF(NETDEV_UP): vethaded35b: link is not ready
00:48:07 zbox kernel: [100344.886106] IPv6: ADDRCONF(NETDEV_CHANGE): vethe7973f1: link becomes ready
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9242] device (vethaded35b): carrier: link connected
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9275] device (vethe7973f1): carrier: link connected
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9280] manager: (vethe7973f1): new Veth device (/org/freedesktop/NetworkManager/Devices/31)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9366] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 4.nmconnection (1afbca34-ced1-3bdb-a957-ab5262a14a19,"Wired connection 4")
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9376] settings: (vethe7973f1): created default wired connection 'Wired connection 4'
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9396] keyfile: add connection /run/NetworkManager/system-connections/vethe7973f1.nmconnection (f7265cb5-ea68-45cb-9a30-49ab15601555,"vethe7973f1")
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9405] device (vethe7973f1): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9425] device (vethe7973f1): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9443] device (vethe7973f1): Activation: starting connection 'vethe7973f1' (f7265cb5-ea68-45cb-9a30-49ab15601555)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9464] device (vethe7973f1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9481] device (vethaded35b): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9491] device (vethe7973f1): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9501] policy: auto-activating connection 'Wired connection 2' (da26b314-6a05-3b78-8c26-c6b93c7b6873)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9509] device (vethe7973f1): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9514] device (hassio): bridge port vethe7973f1 was attached
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9515] device (vethe7973f1): Activation: connection 'vethe7973f1' enslaved, continuing activation
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9519] device (vethe7973f1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9559] device (vethaded35b): Activation: starting connection 'Wired connection 2' (da26b314-6a05-3b78-8c26-c6b93c7b6873)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9561] device (vethaded35b): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9570] device (vethe7973f1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9574] device (vethaded35b): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9583] device (vethe7973f1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9629] device (vethe7973f1): Activation: successful, device activated.
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9638] device (vethaded35b): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9644] dhcp4 (vethaded35b): activation: beginning transaction (timeout in 45 seconds)
00:48:07 zbox NetworkManager[428]: <info>  [1601682487.9718] dhcp4 (vethaded35b): dhclient started with pid 5119
00:48:08 zbox kernel: [100345.000820] hassio: port 2(veth6259cd1) entered disabled state
00:48:08 zbox kernel: [100345.005626] docker0: port 1(vethc0d13b6) entered disabled state
00:48:08 zbox kernel: [100345.012490] hassio: port 8(veth064852f) entered disabled state
00:48:08 zbox kernel: [100345.019589] hassio: port 9(veth5fb2317) entered disabled state
00:48:08 zbox kernel: [100345.025399] hassio: port 6(vethafc73d6) entered disabled state
00:48:08 zbox kernel: [100345.031105] hassio: port 11(vethc9dbb5a) entered disabled state
00:48:08 zbox kernel: [100345.034386] device veth6259cd1 left promiscuous mode
00:48:08 zbox kernel: [100345.034389] hassio: port 2(veth6259cd1) entered disabled state
00:48:08 zbox kernel: [100345.050561] device vethc0d13b6 left promiscuous mode
00:48:08 zbox kernel: [100345.050565] docker0: port 1(vethc0d13b6) entered disabled state
00:48:08 zbox kernel: [100345.070776] device veth064852f left promiscuous mode
00:48:08 zbox kernel: [100345.070779] hassio: port 8(veth064852f) entered disabled state
00:48:08 zbox kernel: [100345.103114] device veth5fb2317 left promiscuous mode
00:48:08 zbox kernel: [100345.103121] hassio: port 9(veth5fb2317) entered disabled state
00:48:08 zbox kernel: [100345.136029] device vethafc73d6 left promiscuous mode
00:48:08 zbox kernel: [100345.136041] hassio: port 6(vethafc73d6) entered disabled state
00:48:08 zbox kernel: [100345.167590] device vethc9dbb5a left promiscuous mode
00:48:08 zbox kernel: [100345.167600] hassio: port 11(vethc9dbb5a) entered disabled state
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2556] device (vethc9dbb5a): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2560] device (hassio): bridge port vethc9dbb5a was detached
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2560] device (vethc9dbb5a): released from master device hassio
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2650] device (veth6259cd1): released from master device hassio
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2663] device (vethc0d13b6): released from master device docker0
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2674] device (veth064852f): released from master device hassio
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2680] device (veth5fb2317): released from master device hassio
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.2704] device (vethafc73d6): released from master device hassio
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4420] manager: (veth7349df7): new Veth device (/org/freedesktop/NetworkManager/Devices/32)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4465] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 3.nmconnection (7c825787-4e00-3ab3-aacf-36e815cd19bc,"Wired connection 3")
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4475] settings: (veth7349df7): created default wired connection 'Wired connection 3'
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4485] device (veth7349df7): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
00:48:08 zbox kernel: [100345.420228] IPv6: ADDRCONF(NETDEV_UP): veth7349df7: link is not ready
00:48:08 zbox kernel: [100345.420320] IPv6: ADDRCONF(NETDEV_UP): veth7349df7: link is not ready
00:48:08 zbox kernel: [100345.425201] docker0: port 1(vethe3fc4f2) entered blocking state
00:48:08 zbox kernel: [100345.425203] docker0: port 1(vethe3fc4f2) entered disabled state
00:48:08 zbox kernel: [100345.425338] device vethe3fc4f2 entered promiscuous mode
00:48:08 zbox kernel: [100345.425553] docker0: port 1(vethe3fc4f2) entered blocking state
00:48:08 zbox kernel: [100345.425555] docker0: port 1(vethe3fc4f2) entered forwarding state
00:48:08 zbox kernel: [100345.425584] IPv6: ADDRCONF(NETDEV_CHANGE): veth7349df7: link becomes ready
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4549] manager: (vethe3fc4f2): new Veth device (/org/freedesktop/NetworkManager/Devices/33)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4618] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 5.nmconnection (8eda9256-7e3d-3573-9ff5-8bae1ff669b1,"Wired connection 5")
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4638] settings: (vethe3fc4f2): created default wired connection 'Wired connection 5'
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4661] device (vethe3fc4f2): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4687] device (vethe3fc4f2): carrier: link connected
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4756] device (veth7349df7): carrier: link connected
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4767] device (docker0): carrier: link connected
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4768] device (veth7349df7): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4780] device (vethe3fc4f2): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4801] policy: auto-activating connection 'Wired connection 3' (7c825787-4e00-3ab3-aacf-36e815cd19bc)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4807] policy: auto-activating connection 'Wired connection 5' (8eda9256-7e3d-3573-9ff5-8bae1ff669b1)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4819] device (veth7349df7): Activation: starting connection 'Wired connection 3' (7c825787-4e00-3ab3-aacf-36e815cd19bc)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4823] device (vethe3fc4f2): Activation: starting connection 'Wired connection 5' (8eda9256-7e3d-3573-9ff5-8bae1ff669b1)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4825] device (veth7349df7): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4834] device (vethe3fc4f2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4841] device (veth7349df7): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4848] device (vethe3fc4f2): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4855] device (veth7349df7): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4861] dhcp4 (veth7349df7): activation: beginning transaction (timeout in 45 seconds)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4879] dhcp4 (veth7349df7): dhclient started with pid 5297
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4902] device (vethe3fc4f2): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4913] dhcp4 (vethe3fc4f2): activation: beginning transaction (timeout in 45 seconds)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.4950] dhcp4 (vethe3fc4f2): dhclient started with pid 5299
00:48:08 zbox kernel: [100345.467047] hassio: port 2(veth17fe090) entered blocking state
00:48:08 zbox kernel: [100345.467049] hassio: port 2(veth17fe090) entered disabled state
00:48:08 zbox kernel: [100345.467138] device veth17fe090 entered promiscuous mode
00:48:08 zbox kernel: [100345.467224] IPv6: ADDRCONF(NETDEV_UP): veth17fe090: link is not ready
00:48:08 zbox kernel: [100345.467226] hassio: port 2(veth17fe090) entered blocking state
00:48:08 zbox kernel: [100345.467228] hassio: port 2(veth17fe090) entered forwarding state
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5074] manager: (veth245a501): new Veth device (/org/freedesktop/NetworkManager/Devices/34)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5120] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 6.nmconnection (3fe73d1d-6034-3157-aed7-6fca67a1b754,"Wired connection 6")
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5133] settings: (veth245a501): created default wired connection 'Wired connection 6'
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5144] device (veth245a501): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
00:48:08 zbox kernel: [100345.486123] IPv6: ADDRCONF(NETDEV_UP): veth245a501: link is not ready
00:48:08 zbox kernel: [100345.486375] IPv6: ADDRCONF(NETDEV_CHANGE): veth17fe090: link becomes ready
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5157] device (veth245a501): carrier: link connected
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5186] device (veth17fe090): carrier: link connected
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5215] manager: (veth17fe090): new Veth device (/org/freedesktop/NetworkManager/Devices/35)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5310] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 7.nmconnection (fc4728c4-682e-3625-a530-6d04b6514914,"Wired connection 7")
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5336] settings: (veth17fe090): created default wired connection 'Wired connection 7'
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5353] keyfile: add connection /run/NetworkManager/system-connections/veth17fe090.nmconnection (1d483d50-6e24-4096-b002-587f1026075a,"veth17fe090")
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5365] device (veth17fe090): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5385] device (veth17fe090): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5401] device (veth17fe090): Activation: starting connection 'veth17fe090' (1d483d50-6e24-4096-b002-587f1026075a)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5443] device (veth17fe090): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5464] device (vethe3fc4f2): ipv6: duplicate address check failed for the fe80::720b:3343:e170:a86f/64 lft forever pref forever lifetime 100326-0[4294967295,4294967295] dev 33 flags permanent,noprefixroute,tentative src kernel address
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5498] device (veth245a501): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5514] device (veth17fe090): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5519] device (vethe3fc4f2): ipv6: duplicate address check failed for the fe80::822a:75ab:b387:3f57/64 lft forever pref forever lifetime 100326-0[4294967295,4294967295] dev 33 flags permanent,noprefixroute,tentative src kernel address
00:48:08 zbox NetworkManager[428]: <warn>  [1601682488.5519] device (vethe3fc4f2): linklocal6: failed to generate an address: Too many DAD collisions
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5525] policy: auto-activating connection 'Wired connection 6' (3fe73d1d-6034-3157-aed7-6fca67a1b754)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5533] device (veth17fe090): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5541] device (hassio): bridge port veth17fe090 was attached
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5542] device (veth17fe090): Activation: connection 'veth17fe090' enslaved, continuing activation
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5545] device (veth17fe090): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5616] device (veth245a501): Activation: starting connection 'Wired connection 6' (3fe73d1d-6034-3157-aed7-6fca67a1b754)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5619] device (veth245a501): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5626] device (veth17fe090): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5632] device (veth245a501): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5638] device (veth17fe090): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.5697] device (veth17fe090): Activation: successful, device activated.
00:48:08 zbox kernel: [100345.570618] hassio: port 1(vethe7973f1) entered disabled state
00:48:08 zbox kernel: [100345.570848] eth0: renamed from vethaded35b
00:48:08 zbox kernel: [100345.595628] hassio: port 1(vethe7973f1) entered blocking state
00:48:08 zbox kernel: [100345.595637] hassio: port 1(vethe7973f1) entered forwarding state
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6287] device (vethaded35b): state change: ip-config -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6613] dhcp4 (vethaded35b): canceled DHCP transaction, DHCP client pid 5119
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6614] dhcp4 (vethaded35b): state changed unknown -> done
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6638] device (veth245a501): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6644] dhcp4 (veth245a501): activation: beginning transaction (timeout in 45 seconds)
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.6661] dhcp4 (veth245a501): dhclient started with pid 5379
00:48:08 zbox kernel: [100345.754788] eth0: renamed from veth7349df7
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.8103] device (veth7349df7): state change: ip-config -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
00:48:08 zbox kernel: [100345.778547] docker0: port 1(vethe3fc4f2) entered disabled state
00:48:08 zbox kernel: [100345.779505] docker0: port 1(vethe3fc4f2) entered blocking state
00:48:08 zbox kernel: [100345.779508] docker0: port 1(vethe3fc4f2) entered forwarding state
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.8760] dhcp4 (veth7349df7): canceled DHCP transaction, DHCP client pid 5297
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.8760] dhcp4 (veth7349df7): state changed unknown -> done
00:48:08 zbox NetworkManager[428]: <warn>  [1601682488.8787] device (vethe3fc4f2): linklocal6: failed to generate an address: Too many DAD collisions
00:48:08 zbox kernel: [100345.899529] eth1: renamed from veth245a501
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.9459] device (veth245a501): state change: ip-config -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
00:48:08 zbox kernel: [100345.914740] hassio: port 2(veth17fe090) entered disabled state
00:48:08 zbox kernel: [100345.915817] hassio: port 2(veth17fe090) entered blocking state
00:48:08 zbox kernel: [100345.915819] hassio: port 2(veth17fe090) entered forwarding state
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.9787] dhcp4 (veth245a501): canceled DHCP transaction, DHCP client pid 5379
00:48:08 zbox NetworkManager[428]: <info>  [1601682488.9788] dhcp4 (veth245a501): state changed unknown -> done
00:48:09 zbox NetworkManager[428]: <warn>  [1601682489.7871] device (vethe3fc4f2): linklocal6: failed to generate an address: Too many DAD collisions
00:48:16 zbox kernel: [100353.603970] audit: type=1400 audit(1601682496.628:17): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor" pid=6094 comm="apparmor_parser"
00:48:16 zbox kernel: [100353.603980] audit: type=1400 audit(1601682496.628:18): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/gdbus" pid=6094 comm="apparmor_parser"
00:48:16 zbox kernel: [100353.603985] audit: type=1400 audit(1601682496.628:19): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/git" pid=6094 comm="apparmor_parser"
00:48:16 zbox kernel: [100353.603991] audit: type=1400 audit(1601682496.628:20): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="hassio-supervisor///usr/bin/socat" pid=6094 comm="apparmor_parser"
00:48:16 zbox kernel: [100353.795128] hassio: port 3(veth207652d) entered blocking state
00:48:16 zbox kernel: [100353.795132] hassio: port 3(veth207652d) entered disabled state
00:48:16 zbox kernel: [100353.795197] device veth207652d entered promiscuous mode
00:48:16 zbox kernel: [100353.795274] IPv6: ADDRCONF(NETDEV_UP): veth207652d: link is not ready
00:48:16 zbox NetworkManager[428]: <info>  [1601682496.8274] manager: (vethb0821c4): new Veth device (/org/freedesktop/NetworkManager/Devices/36)
00:48:16 zbox NetworkManager[428]: <info>  [1601682496.8287] manager: (veth207652d): new Veth device (/org/freedesktop/NetworkManager/Devices/37)
00:48:17 zbox kernel: [100354.124298] eth0: renamed from vethb0821c4
00:48:17 zbox kernel: [100354.164929] IPv6: ADDRCONF(NETDEV_CHANGE): veth207652d: link becomes ready
00:48:17 zbox kernel: [100354.165004] hassio: port 3(veth207652d) entered blocking state
00:48:17 zbox kernel: [100354.165008] hassio: port 3(veth207652d) entered forwarding state
00:48:17 zbox NetworkManager[428]: <info>  [1601682497.1972] device (veth207652d): carrier: link connected
00:48:17 zbox NetworkManager[428]: <info>  [1601682497.4797] manager: (vethbfe01b2): new Veth device (/org/freedesktop/NetworkManager/Devices/38)
00:48:17 zbox NetworkManager[428]: <info>  [1601682497.4817] manager: (vethe910d01): new Veth device (/org/freedesktop/NetworkManager/Devices/39)
00:48:17 zbox kernel: [100354.456656] hassio: port 4(vethe910d01) entered blocking state
00:48:17 zbox kernel: [100354.456659] hassio: port 4(vethe910d01) entered disabled state
00:48:17 zbox kernel: [100354.456832] device vethe910d01 entered promiscuous mode
00:48:17 zbox kernel: [100354.457036] IPv6: ADDRCONF(NETDEV_UP): vethe910d01: link is not ready
00:48:17 zbox kernel: [100354.457040] hassio: port 4(vethe910d01) entered blocking state
00:48:17 zbox kernel: [100354.457042] hassio: port 4(vethe910d01) entered forwarding state
00:48:17 zbox kernel: [100354.760698] eth0: renamed from vethbfe01b2
00:48:17 zbox kernel: [100354.792890] IPv6: ADDRCONF(NETDEV_CHANGE): vethe910d01: link becomes ready
00:48:17 zbox NetworkManager[428]: <info>  [1601682497.8247] device (vethe910d01): carrier: link connected
00:48:18 zbox NetworkManager[428]: <info>  [1601682498.0249] manager: (vethc3b5c1e): new Veth device (/org/freedesktop/NetworkManager/Devices/40)
00:48:18 zbox NetworkManager[428]: <info>  [1601682498.0265] manager: (veth9819d11): new Veth device (/org/freedesktop/NetworkManager/Devices/41)
00:48:18 zbox kernel: [100355.001998] hassio: port 5(veth9819d11) entered blocking state
00:48:18 zbox kernel: [100355.002000] hassio: port 5(veth9819d11) entered disabled state
00:48:18 zbox kernel: [100355.002091] device veth9819d11 entered promiscuous mode
00:48:18 zbox kernel: [100355.002189] IPv6: ADDRCONF(NETDEV_UP): veth9819d11: link is not ready
00:48:18 zbox kernel: [100355.002192] hassio: port 5(veth9819d11) entered blocking state
00:48:18 zbox kernel: [100355.002193] hassio: port 5(veth9819d11) entered forwarding state
00:48:18 zbox kernel: [100355.352627] eth0: renamed from vethc3b5c1e
00:48:18 zbox NetworkManager[428]: <info>  [1601682498.4137] device (veth9819d11): carrier: link connected
00:48:18 zbox kernel: [100355.384874] IPv6: ADDRCONF(NETDEV_CHANGE): veth9819d11: link becomes ready
00:48:53 zbox NetworkManager[428]: <warn>  [1601682533.7351] dhcp4 (vethe3fc4f2): request timed out
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7353] dhcp4 (vethe3fc4f2): state changed unknown -> timeout
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7680] dhcp4 (vethe3fc4f2): canceled DHCP transaction, DHCP client pid 5299
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7682] dhcp4 (vethe3fc4f2): state changed timeout -> done
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7696] device (vethe3fc4f2): state change: ip-config -> failed (reason 'ip-config-unavailable', sys-iface-state: 'managed')
00:48:53 zbox NetworkManager[428]: <warn>  [1601682533.7722] device (vethe3fc4f2): Activation: failed for connection 'Wired connection 5'
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7780] device (vethe3fc4f2): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7800] policy: auto-activating connection 'Wired connection 5' (8eda9256-7e3d-3573-9ff5-8bae1ff669b1)
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7807] device (vethe3fc4f2): Activation: starting connection 'Wired connection 5' (8eda9256-7e3d-3573-9ff5-8bae1ff669b1)
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7809] device (vethe3fc4f2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7816] device (vethe3fc4f2): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7823] device (vethe3fc4f2): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7827] dhcp4 (vethe3fc4f2): activation: beginning transaction (timeout in 45 seconds)
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7840] dhcp4 (vethe3fc4f2): dhclient started with pid 7591
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7861] device (vethe3fc4f2): ipv6: duplicate address check failed for the fe80::720b:3343:e170:a86f/64 lft forever pref forever lifetime 100372-0[4294967295,4294967295] dev 33 flags permanent,noprefixroute,tentative src kernel address
00:48:53 zbox NetworkManager[428]: <info>  [1601682533.7868] device (vethe3fc4f2): ipv6: duplicate address check failed for the fe80::822a:75ab:b387:3f57/64 lft forever pref forever lifetime 100372-0[4294967295,4294967295] dev 33 flags permanent,noprefixroute,tentative src kernel address

Lots of repeats beyond here.

This box has been running solidly for months before these last two crashes. The most recent things I’ve touched have been updating to the latest HA version a few times (completely up to date now), plus I have installed the latest OS patches after the first crash.

Any thoughts on what might be causing my issues?

3

A restart of the host worked again an it is staying up for now. Really keen to get to the bottom of this though, as obviously I have no confidence in my HA’s resilience at the moment.

4

It’s just crashed again, 4 days after the last crash. Same symptoms:

root@zbox:~# docker ps -a
CONTAINER ID        IMAGE                                            COMMAND                  CREATED             STATUS                        PORTS                  NAMES
1bdca5e032b1        homeassistant/amd64-hassio-multicast:3           "/init"                  15 minutes ago      Up 15 minutes                                        hassio_multicast
d5c8fc7e2523        homeassistant/amd64-hassio-cli:26                "/init /bin/bash -c …"   15 minutes ago      Up 15 minutes                                        hassio_cli
c9e412e91358        homeassistant/amd64-hassio-audio:17              "/init"                  15 minutes ago      Up 15 minutes                                        hassio_audio
645fc0ba7f17        homeassistant/amd64-hassio-dns:9                 "/init coredns -conf…"   15 minutes ago      Up 15 minutes                                        hassio_dns
2cbb3e6822f2        homeassistant/amd64-hassio-supervisor            "/init"                  13 hours ago        Up 15 minutes                                        hassio_supervisor
feae0422f0a5        hassioaddons/log-viewer-amd64:0.8.1              "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_a0d7b954_logviewer
f4e94e531d33        homeassistant/amd64-addon-configurator:5.0.0     "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_core_configurator
bdf5a178ca7d        esphome/esphome-hassio-amd64:1.14.5              "/init"                  4 days ago          Exited (129) 15 minutes ago                          addon_15ef4d2f_esphome
ad44dfe99680        hassioaddons/vscode-amd64:2.7.1                  "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_a0d7b954_vscode
b97570101a6c        hassioaddons/portainer-amd64:1.2.2               "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_a0d7b954_portainer
b3c8cc684b0c        hassioaddons/grafana-amd64:5.3.0                 "/init"                  4 days ago          Exited (129) 15 minutes ago                          addon_a0d7b954_grafana
14e80f96739f        hassioaddons/influxdb-amd64:3.7.6                "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_a0d7b954_influxdb
bdf8aa0e24f4        hassioaddons/glances-amd64:0.8.0                 "/init"                  4 days ago          Exited (0) 15 minutes ago                            addon_a0d7b954_glances
6eb15ac5e24e        homeassistant/qemux86-64-homeassistant:0.115.6   "/init"                  6 days ago          Exited (0) 15 minutes ago                            homeassistant
9571021e706c        homeassistant/amd64-hassio-observer:3            "/init"                  3 weeks ago         Up 15 minutes                 0.0.0.0:4357->80/tcp   hassio_observer
6cc2a33384e0        homeassistant/amd64-addon-check_config:3.3.0     "/init"                  4 months ago        Exited (0) 4 months ago                              addon_core_check_config

I’m really stuck for where else to look now!

I’d be really grateful for any help!

5

Well, I thought that maybe one of the most recent updates might have fixed my issues, as it had stayed up for a while, but it’s just crashed again :(.

From /var/syslog1 this seems to correspond to start of the issue:

Oct 27 04:11:32 zbox dockerd[539]: unexpected fault address 0x0
Oct 27 04:11:32 zbox dockerd[539]: fatal error: fault
Oct 27 04:11:32 zbox dockerd[539]: [signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x56462daafbf3]
Oct 27 04:11:32 zbox dockerd[539]: goroutine 496518 [running]:
Oct 27 04:11:32 zbox dockerd[539]: runtime.throw(0x56462f1ca73e, 0x5)
Oct 27 04:11:32 zbox dockerd[539]: #011/usr/local/go/src/runtime/panic.go:774 +0x74 fp=0xc0013f6628 sp=0xc0013f65f8 pc=0x56462d9206e4
Oct 27 04:11:32 zbox dockerd[539]: runtime.sigpanic()
Oct 27 04:11:32 zbox dockerd[539]: #011/usr/local/go/src/runtime/signal_unix.go:401 +0x3e2 fp=0xc0013f6658 sp=0xc0013f6628 pc=0x56462d936552
Oct 27 04:11:32 zbox dockerd[539]: encoding/json.unquoteBytes(0xc0014db0eb, 0x22, 0x2194, 0xc0007d6700, 0x0, 0x0, 0x0)
Oct 27 04:11:32 zbox dockerd[539]: #011/usr/local/go/src/encoding/json/decode.go:1247 +0x133 fp=0xc0013f66f0 sp=0xc0013f6658 pc=0x56462daafbf3
Oct 27 04:11:32 zbox dockerd[539]: encoding/json.(*decodeState).literalStore(0xc0004a3080, 0xc0014db0eb, 0x22, 0x2195, 0x56462fb8b3c0, 0xc000baec40, 0x198, 0x1000, 0x3080, 0xc0004a30a8)

then lots of similar lines
Does this suggest a hardware issue?

I’ve run badblocks (and a SMART utility) on my SSD and that all comes back clean.
I’ve put memtest on a USB stick and kicked off the suite of tests against the memory - I’ll leave that running overnight.

I’d still be super-grateful for any thoughts!

6

My memory test ran for five and a half hours and came back with no errors, so that seems pretty good (or bad, as it means I still have no idea what the issue is).

7

Hi @SadGamerGeek ,

I experience a very similar issue with HASSOS on a RPI4B+ with SSD. Does the VSCode integration works for you or do you get errors about disconnects? I removed the integration now a couple of days ago. No crashes so far, but I’ll wait a bit longer. Maybe you give it a try too. Or did you solve your problem in the meantime?

8

Thank you. Actually my VSCode add-in has been rather broken recently! Unfortunately, my crashes are actually quite infrequent, so it’s really hard to see if any changes actually fix it or not!

9

I think i’m getting issues too with visual code. though can’t find any evidence.

my system appears stable until I use the integration. Then when I check configuration or check logs the web controls hang.

I think it recovers if I leave it for long enough. or a server reboot will do it.

my system is running on a 4 Core VM with a XEON E5-1650v4 and 16GB memory. So I’d be surprised if it’s a resource issue, which might be the thought running on RPi.

As much as I’ve loved using it. Gonna try removing it cause the system is just not stable ATM.