VirtualBox - Lots of issues after system crash

Installation Home Assistant OS
1

The host here is Ubuntu 20.04.4.
VirtualBox 6.1.34.
Guest is the HA OVA release, 2022.9.6.

I’ve been running HA in this VM for a year or more at this point without much issue.

The other night the host crashed (I have not figured out why yet, it has never happened before).

Since then, HA has been acting strange. At first it started right up, but after a few hours it stopped responding. When I checked the console I saw this:

VirtualBox_homeassistant_26_09_2022_08_11_32
VirtualBox_homeassistant_26_09_2022_08_11_321024×768 11.7 KB

The end line here says “A start job is running for Docker Application Container Engine (4h 43min 20s / no limit)”.

I’ve seen this happen a few times now. In fact, HA has been restarting/needing to be restarted a lot recently:

Screen Shot 2022-09-27 at 12.08.43 PM
Screen Shot 2022-09-27 at 12.08.43 PM1964×1264 448 KB

I had also installed the Uptime Integration yesterday as I was suspicious of some logs. Now I’m seeing that HA core seems to keep restarting:

Screen Shot 2022-09-27 at 11.55.54 AM
Screen Shot 2022-09-27 at 11.55.54 AM3104×316 43.3 KB

Some of these were me, but for example the last tiny sliver here is a restart that happened while I was typing this out.

I am SSH’d in to the HA VM (OS) and I didn’t lose connection, and checking the docker containers running I can see nothing has restarted - so it’s most likely a core crash/reboot for some reason…

I looked over many of the log files using journalctl, but I’m not really any closer to figuring out what is causing the problem.

I did see ZwaveJS having a lot of trouble

Some random sections of the logs from the first boot after the failure where I saw things that didn't look right, but could be completely expected, I don't know... 
Sep 25 03:20:52 homeassistant audit[15807]: SYSCALL arch=c000003e syscall=321 success=yes exit=16 a0=5 a1=c000195f30 a2=78 a3=c000293128 items=0 ppid=15797 pid=15807 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Sep 25 03:20:52 homeassistant audit: PROCTITLE proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F7661722F72756E2F646F636B65722F636F6E7461696E6572642F6461656D6F6E2F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F30663037383131
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime: failed mSpanList.insert 0x7f41c8a33a48 0x40 0x0 0x0
Sep 25 03:20:52 homeassistant dockerd[15833]: fatal error: mSpanList.insert
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime stack:
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.throw({0x2c0fbed, 0x0})
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/panic.go:1198 +0x71
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.(*mSpanList).insert(0x7f41cb2aab70, 0x7f41c8a33a48)
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mheap.go:1601 +0xe5
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.getempty()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgcwork.go:381 +0x105
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.(*gcWork).put(0xc000062698, 0xc0005c6de0)
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgcwork.go:127 +0x67
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.greyobject(0xc0005c6de0, 0x7f41cb2aac90, 0x7f41cb2aac78, 0xf13c05, 0x0, 0xc000000ea0)
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgcmark.go:1450 +0x19b
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.scanobject(0xc000062698, 0xc000062698)
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgcmark.go:1281 +0x1b2
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.gcDrain(0xc000062698, 0xb)
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgcmark.go:1047 +0x1ba
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.gcBgMarkWorker.func2()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgc.go:1286 +0x85
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.systemstack()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/asm_amd64.s:383 +0x49
Sep 25 03:20:52 homeassistant dockerd[15833]: goroutine 6 [GC worker (idle)]:
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.systemstack_switch()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/asm_amd64.s:350 fp=0xc00006c760 sp=0xc00006c758 pc=0xf577a0
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.gcBgMarkWorker()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/mgc.go:1256 +0x1b1 fp=0xc00006c7e0 sp=0xc00006c760 pc=0xf0a071
Sep 25 03:20:52 homeassistant dockerd[15833]: runtime.goexit()
Sep 25 03:20:52 homeassistant dockerd[15833]:         runtime/asm_amd64.s:1581 +0x1 fp=0xc00006c7e8 sp=0xc00006c7e0 pc=0xf599c1


...


Sep 25 03:21:35 homeassistant kernel: kauditd_printk_skb: 15 callbacks suppressed
Sep 25 03:21:35 homeassistant kernel: audit: type=1701 audit(1664076095.948:560): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=docker-default (enforce) pid=16024 comm="node" exe="/usr/bin/node" sig=11 res=1
Sep 25 03:21:35 homeassistant audit[16024]: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 subj=docker-default (enforce) pid=16024 comm="node" exe="/usr/bin/node" sig=11 res=1
Sep 25 03:21:35 homeassistant audit: BPF prog-id=131 op=LOAD
Sep 25 03:21:35 homeassistant audit: BPF prog-id=132 op=LOAD
Sep 25 03:21:35 homeassistant audit: BPF prog-id=133 op=LOAD
Sep 25 03:21:35 homeassistant kernel: audit: type=1334 audit(1664076095.960:561): prog-id=131 op=LOAD
Sep 25 03:21:35 homeassistant kernel: audit: type=1334 audit(1664076095.960:562): prog-id=132 op=LOAD
Sep 25 03:21:35 homeassistant kernel: audit: type=1334 audit(1664076095.960:563): prog-id=133 op=LOAD
Sep 25 03:21:35 homeassistant systemd[1]: Started Process Core Dump (PID 16111/UID 0).
Sep 25 03:21:36 homeassistant systemd-coredump[16112]: Process 16024 (node) of user 0 dumped core.
Sep 25 03:21:36 homeassistant systemd[1]: [email protected]: Deactivated successfully.
Sep 25 03:21:36 homeassistant kernel: audit: type=1334 audit(1664076096.080:564): prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant kernel: audit: type=1334 audit(1664076096.080:565): prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant kernel: audit: type=1334 audit(1664076096.080:566): prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant audit: BPF prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant audit: BPF prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant audit: BPF prog-id=0 op=UNLOAD
Sep 25 03:21:36 homeassistant homeassistant[386]: 2022-09-24 23:21:36.061 INFO (MainThread) [homeassistant.components.zwave_js] Disconnected from server. Reloading integration
Sep 25 03:21:36 homeassistant homeassistant[386]: 2022-09-24 23:21:36.062 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Sep 25 03:21:36 homeassistant homeassistant[386]: Traceback (most recent call last):
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/local/lib/python3.10/site-packages/zwave_js_server/client.py", line 103, in async_send_command
Sep 25 03:21:36 homeassistant homeassistant[386]:     return await future
Sep 25 03:21:36 homeassistant homeassistant[386]: asyncio.exceptions.CancelledError
Sep 25 03:21:36 homeassistant homeassistant[386]:
Sep 25 03:21:36 homeassistant homeassistant[386]: During handling of the above exception, another exception occurred:
Sep 25 03:21:36 homeassistant homeassistant[386]:
Sep 25 03:21:36 homeassistant homeassistant[386]: Traceback (most recent call last):
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/src/homeassistant/homeassistant/components/zwave_js/update.py", line 176, in _async_update
Sep 25 03:21:36 homeassistant homeassistant[386]:     await self.driver.controller.async_get_available_firmware_updates(
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/local/lib/python3.10/site-packages/zwave_js_server/model/controller/__init__.py", line 719, in async_get_available_firmware_updates
Sep 25 03:21:36 homeassistant homeassistant[386]:     data = await self.client.async_send_command(
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/local/lib/python3.10/site-packages/zwave_js_server/client.py", line 105, in async_send_command
Sep 25 03:21:36 homeassistant homeassistant[386]:     self._result_futures.pop(message_id)
Sep 25 03:21:36 homeassistant homeassistant[386]: KeyError: '27367b34f0d74282825cc99e79cb2193'
Sep 25 03:21:36 homeassistant homeassistant[386]: 2022-09-24 23:21:36.072 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Sep 25 03:21:36 homeassistant homeassistant[386]: Traceback (most recent call last):
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/local/lib/python3.10/site-packages/zwave_js_server/client.py", line 103, in async_send_command
Sep 25 03:21:36 homeassistant homeassistant[386]:     return await future
Sep 25 03:21:36 homeassistant homeassistant[386]: asyncio.exceptions.CancelledError
Sep 25 03:21:36 homeassistant homeassistant[386]:
Sep 25 03:21:36 homeassistant homeassistant[386]: During handling of the above exception, another exception occurred:
Sep 25 03:21:36 homeassistant homeassistant[386]:
Sep 25 03:21:36 homeassistant homeassistant[386]: Traceback (most recent call last):
Sep 25 03:21:36 homeassistant homeassistant[386]:   File "/usr/src/homeassistant/homeassistant/components/zwave_js/update.py", line 176, in _async_update








Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.214 ERROR ZWAVE-SERVER: Cannot check for firmware updates for node 7: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: ZWaveError: Cannot check for firmware updates for node 7: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at ZWaveController.getAvailableFirmwareUpdates (/opt/node_modules/zwave-js/src/lib/controller/Controller.ts:4575:10)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at runMicrotasks (<anonymous>)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Function.handle (/opt/node_modules/@zwave-js/server/dist/lib/controller/message_handler.js:203:30)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Client.receiveMessage (/opt/node_modules/@zwave-js/server/dist/lib/server.js:96:62)
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.400 INFO ZWAVE: Node 15: value updated: 114-0-manufacturerId 786 => 786
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.401 INFO ZWAVE: Node 15: value updated: 114-0-productType 7936 => 7936
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.402 INFO ZWAVE: Node 15: value updated: 114-0-productId 7936 => 7936
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.650 INFO ZWAVE: Node 15: value updated: 134-0-libraryType 3 => 3
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.651 INFO ZWAVE: Node 15: value updated: 134-0-protocolVersion 4.61 => 4.61
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.651 INFO ZWAVE: Node 15: value updated: 134-0-firmwareVersions 1.3 => 1.3
Sep 25 03:21:54 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:54.652 INFO ZWAVE: Node 15: value updated: 134-0-hardwareVersion 1 => 1
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:55.884 ERROR ZWAVE-SERVER: Cannot check for firmware updates for node 12: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: ZWaveError: Cannot check for firmware updates for node 12: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at ZWaveController.getAvailableFirmwareUpdates (/opt/node_modules/zwave-js/src/lib/controller/Controller.ts:4575:10)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at runMicrotasks (<anonymous>)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Function.handle (/opt/node_modules/@zwave-js/server/dist/lib/controller/message_handler.js:203:30)
Sep 25 03:21:55 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Client.receiveMessage (/opt/node_modules/@zwave-js/server/dist/lib/server.js:96:62)
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.069 INFO ZWAVE: Node 16: value updated: 114-0-manufacturerId 786 => 786
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.070 INFO ZWAVE: Node 16: value updated: 114-0-productType 7936 => 7936
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.070 INFO ZWAVE: Node 16: value updated: 114-0-productId 7936 => 7936
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.374 INFO ZWAVE: Node 16: value updated: 134-0-libraryType 3 => 3
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.374 INFO ZWAVE: Node 16: value updated: 134-0-protocolVersion 4.61 => 4.61
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.375 INFO ZWAVE: Node 16: value updated: 134-0-firmwareVersions 1.3 => 1.3
Sep 25 03:21:56 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:56.375 INFO ZWAVE: Node 16: value updated: 134-0-hardwareVersion 1 => 1
Sep 25 03:21:58 homeassistant addon_core_deconz[386]: 23:21:58:520 ZCL attribute report 0x00124B0023A53814 for cluster: 0x0405, ep: 0x01, frame control: 0x18, mfcode: 0x0000
Sep 25 03:21:59 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-25T03:21:59.220Z DRIVER   Could not check for config updates: Failed to download package information! (Z
Sep 25 03:21:59 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:                                   W0343)
Sep 25 03:21:59 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:21:59.224 INFO ZWAVE: Next update scheduled for: Sun Sep 25 2022 00:00:00 GMT-0400 (Eastern Daylight Time)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:00.905 ERROR ZWAVE-SERVER: Cannot check for firmware updates for node 13: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: ZWaveError: Cannot check for firmware updates for node 13: getaddrinfo EAI_AGAIN firmware.zwave-js.io (ZW0261)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at ZWaveController.getAvailableFirmwareUpdates (/opt/node_modules/zwave-js/src/lib/controller/Controller.ts:4575:10)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at runMicrotasks (<anonymous>)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Function.handle (/opt/node_modules/@zwave-js/server/dist/lib/controller/message_handler.js:203:30)
Sep 25 03:22:00 homeassistant addon_a0d7b954_zwavejs2mqtt[386]:     at Client.receiveMessage (/opt/node_modules/@zwave-js/server/dist/lib/server.js:96:62)
Sep 25 03:22:01 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:01.321 INFO ZWAVE: Node 17: value updated: 114-0-manufacturerId 786 => 786
Sep 25 03:22:01 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:01.324 INFO ZWAVE: Node 17: value updated: 114-0-productType 7936 => 7936
Sep 25 03:22:01 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:01.326 INFO ZWAVE: Node 17: value updated: 114-0-productId 7936 => 7936
Sep 25 03:22:02 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:02.220 INFO ZWAVE: Node 17: value updated: 134-0-libraryType 3 => 3
Sep 25 03:22:02 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:02.223 INFO ZWAVE: Node 17: value updated: 134-0-protocolVersion 4.61 => 4.61
Sep 25 03:22:02 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:02.224 INFO ZWAVE: Node 17: value updated: 134-0-firmwareVersions 1.3 => 1.3
Sep 25 03:22:02 homeassistant addon_a0d7b954_zwavejs2mqtt[386]: 2022-09-24 23:22:02.226 INFO ZWAVE: Node 17: value updated: 134-0-hardwareVersion 1 => 1
Sep 25 03:22:03 homeassistant addon_core_deconz[386]: 23:22:03:256 0x00178801095C21D0 error APSDE-DATA.confirm: 0xE9 on task

Any help would be appreciated.

2

Yesterday I tried to downgrade to 2022.9.5. At first, things seemed better, a missing zwave device seemingly came back from nowhere.

But when I woke up today it had crashed again.
And now, the supervisor isn’t working - so I can’t access any add-ons, backups, etc.

I have logs on logs on logs, but I have no idea what to be looking for in them…
I do see some concerning things, but I don’t know if they are real problems (my problem), and if so, how to resolve them.

Full log from the last boot can be seen here: home-assistant-logs-2022-09-28.txt

(it was 1MB or so, so I couldn’t include it here, and PasteBin apparently has a max of 512kb).

…

UPDATE:
Ok, so I went ahead and updated core to 2022.9.7 (via command line) and as of right now, it’s returned the addons that were missing. Time will tell if the crashes continue or not.