supervisor icon indicating copy to clipboard operation
supervisor copied to clipboard

Host info API returns corrupted timestamps

Open thomersch opened this issue 6 months ago • 5 comments

Describe the issue you are experiencing

A fresh install (HAOS 15.2 on bhyve) fails to start the hassio integration.

Error message in homeassistant:

2025-05-25 13:30:51.162 ERROR (MainThread) [homeassistant.setup] Error during setup of component hassio: unexpected control character in string: line 1 column 578 (char 577)

Upon further digging it seems that supervisor returns corrupt timestamps (see the dt_utc property):

curl -H "Authorization: Bearer XXX" 172.30.32.2/host/info --output -
{"result":"ok","data":{"agent_version":"1.7.2","apparmor_version":"3.1.2","chassis":"vm","virtualization":"bhyve","cpe":"cpe:2.3:o:home-assistant:haos:15.2:*:production:*:*:*:ova:*","deployment":"production","disk_free":26
.2,"disk_total":30.8,"disk_used":3.3,"disk_life_time":null,"features":["reboot","shutdown","services","network","hostname","timedate","os_agent","haos","resolved","journal","disk","mount"],"hostname":"homeassistant","llmnr_hostname":"homeassistant11","kernel":"6.12.23-haos","operating_system":"Home Assistant OS 15.2","timezone":"Etc/UTC","dt_utc":"2025-0-T::.768564+00:00","dt_synchronized":true,"use_ntp":true,"startup_time":2.459115,"boot_timestamp":1748172098855183,"broadcast_llmnr":true,"broadcast_mdns":true}}

I have observed this behaviour after I realised that my production Home Assistant install stopped offering updates with 2024.11. Thus, I have created a fresh VM install which exhibits the aforementioned problem.

HAOS itself doesn't seem to have a problem to retrieve the correct date:

# date -Iseconds
2025-05-25T16:34:49+00:00
# timedatectl 
               Local time: Sun 2025-05-25 16:41:34 UTC
           Universal time: Sun 2025-05-25 16:41:34 UTC
                 RTC time: Sun 2025-05-25 16:41:34
                Time zone: Etc/UTC (UTC, +0000)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

What type of installation are you running?

Home Assistant OS

Which operating system are you running on?

Home Assistant Operating System

Steps to reproduce the issue

  1. Install HAOS 15.2 (ova image with bhyve supervisor)
  2. Wait for Homeassistant to install on first boot
  3. hassio never starts

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

2025-05-25 17:42:04.045 INFO (MainThread) [supervisor.dbus.manager] Connected to system D-Bus.
2025-05-25 17:42:04.103 INFO (MainThread) [supervisor.dbus.agent] Load dbus interface io.hass.os
2025-05-25 17:42:04.127 INFO (MainThread) [supervisor.dbus.hostname] Load dbus interface org.freedesktop.hostname1
2025-05-25 17:42:04.152 INFO (MainThread) [supervisor.dbus.logind] Load dbus interface org.freedesktop.login1
2025-05-25 17:42:04.191 INFO (MainThread) [supervisor.dbus.network] Load dbus interface org.freedesktop.Network
Manager
2025-05-25 17:42:04.235 INFO (MainThread) [supervisor.dbus.rauc] Load dbus interface de.pengutronix.rauc
2025-05-25 17:42:04.255 INFO (MainThread) [supervisor.dbus.resolved] Load dbus interface org.freedesktop.resolv
e1
2025-05-25 17:42:04.290 INFO (MainThread) [supervisor.dbus.systemd] Load dbus interface org.freedesktop.systemd1
2025-05-25 17:42:04.365 INFO (MainThread) [supervisor.dbus.timedate] Load dbus interface org.freedesktop.timedate1
2025-05-25 17:42:04.790 WARNING (MainThread) [asyncio] Executing <Handle _message_reader(<dbus_fast._p...x7fe091938660>, <bound method...7fe09192be60>>, <bound method...7fe09192be60>>, False)() created at /usr/local/lib/py
thon3.13/asyncio/selector_events.py:276> took 0.362 seconds
2025-05-25 17:42:05.784 WARNING (MainThread) [asyncio] Executing <Handle _message_reader(<dbus_fast._p...x7fe09
1938660>, <bound method...7fe09192be60>>, <bound method...7fe09192be60>>, False)() created at /usr/local/lib/python3.13/asyncio/selector_events.py:276> took 0.115 seconds
2025-05-25 17:42:07.310 INFO (MainThread) [supervisor.host.services] Updating service information
2025-05-25 17:42:07.362 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
2025-05-25 17:42:08.066 WARNING (MainThread) [asyncio] Executing <Handle _message_reader(<dbus_fast._p...x7fe09
1938660>, <bound method...7fe09192be60>>, <bound method...7fe09192be60>>, False)() created at /usr/local/lib/python3.13/asyncio/selector_events.py:276> took 0.265 seconds
2025-05-25 17:42:08.441 INFO (MainThread) [supervisor.host.network] Updating local network information
2025-05-25 17:42:08.746 INFO (MainThread) [supervisor.host.apparmor] Loading AppArmor Profiles: {'hassio-superv
isor'}
2025-05-25 17:42:08.856 INFO (MainThread) [supervisor.docker.monitor] Started docker events monitor
2025-05-25 17:42:08.865 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
2025-05-25 17:42:09.039 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/amd64-hassio-cli with version 2025.04.0
2025-05-25 17:42:09.244 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/amd64-hassio-dns with version 2025.02.0
2025-05-25 17:42:09.323 INFO (MainThread) [supervisor.plugins.dns] Updated /etc/resolv.conf
2025-05-25 17:42:09.463 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/amd64-hassio-audio with version 2025.02.0
2025-05-25 17:42:09.570 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/amd64-hassio-observer with version 2025.02.0
2025-05-25 17:42:09.739 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/amd64-hassio-multicast with version 2025.02.0
2025-05-25 17:42:10.073 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-163' coro=<HomeAssistantCore.load() running at /usr/src/supervisor/supervisor/homeassistant/core.py:95> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/lib/python3.13/asyncio/futures.py:384, Task.task_wakeup()] created at /usr/local/lib/python3.13/asyncio/base_events.py:459> cb=[_wait.<locals>._on_completion() at /usr/local/lib/python3.13/asyncio/tasks.py:521] created at /usr/src/supervisor/supervisor/coresys.py:626> took 0.206 seconds
2025-05-25 17:42:10.140 INFO (MainThread) [supervisor.homeassistant.secrets] Loaded 1 Home Assistant secrets
2025-05-25 17:42:10.178 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/qemux86-64-homeassistant with version 2025.5.3
2025-05-25 17:42:10.428 INFO (MainThread) [supervisor.os.manager] Detect Home Assistant Operating System 15.2 / BootSlot A
2025-05-25 17:42:10.541 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/core repository
2025-05-25 17:42:10.565 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/a0d7b954 repository
2025-05-25 17:42:10.570 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/d5369777 repository
2025-05-25 17:42:10.589 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/5c53de3b repository
2025-05-25 17:42:12.276 INFO (MainThread) [supervisor.store] Loading add-ons from store: 82 all - 82 new - 0 re
move
2025-05-25 17:42:12.694 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-13' coro=<Core.setup() running at /usr/src/supervisor/supervisor/core.py:188> wait_for=<_GatheringFuture pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.13/asyncio/tasks.py:765> cb=[_run_until_complete_cb() at /usr/local/lib/python3.13/asyncio/base_events.py:181] created at /usr/local/lib/python3.13/asyncio/tasks.py:748> took 0.421 seconds
2025-05-25 17:42:13.166 INFO (MainThread) [supervisor.addons.manager] Found 0 installed add-ons
2025-05-25 17:42:13.181 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-13' coro=<Core.setup() running at /usr/src/supervisor/supervisor/core.py:188> wait_for=<_GatheringFuture pending cb=[Task.task_wakeu
p()] created at /usr/local/lib/python3.13/asyncio/tasks.py:765> cb=[_run_until_complete_cb() at /usr/local/lib/python3.13/asyncio/base_events.py:181] created at /usr/local/lib/python3.13/asyncio/tasks.py:748> took 0.397 seconds
2025-05-25 17:42:13.284 INFO (MainThread) [supervisor.backups.manager] Found 0 backup files
2025-05-25 17:42:13.285 INFO (MainThread) [supervisor.discovery] Loaded 0 messages
2025-05-25 17:42:13.285 INFO (MainThread) [supervisor.ingress] Loaded 0 ingress sessions
2025-05-25 17:42:13.285 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state setup
2025-05-25 17:42:13.287 INFO (MainThread) [supervisor.resolution.checks.base] Run check for detached_addon_remo
ved/addon
2025-05-25 17:42:13.287 INFO (MainThread) [supervisor.resolution.checks.base] Run check for disabled_data_disk/system
2025-05-25 17:42:13.288 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks/system
2025-05-25 17:42:13.288 INFO (MainThread) [supervisor.resolution.checks.base] Run check for detached_addon_missing/addon
2025-05-25 17:42:13.289 INFO (MainThread) [supervisor.resolution.check] System checks complete
2025-05-25 17:42:13.289 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
2025-05-25 17:42:13.297 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
2025-05-25 17:42:13.300 INFO (MainThread) [supervisor.jobs] 'ResolutionFixup.run_autofix' blocked from execution, system is not running - setup
2025-05-25 17:42:13.301 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
2025-05-25 17:42:13.303 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
2025-05-25 17:42:13.309 INFO (MainThread) [__main__] Running Supervisor
2025-05-25 17:42:13.408 INFO (MainThread) [supervisor.os.manager] Rauc: slot A - activated slot kernel.0, marked slot kernel.0 as good
2025-05-25 17:42:13.465 INFO (MainThread) [supervisor.addons.manager] Phase 'initialize' starting 0 add-ons
2025-05-25 17:42:13.498 INFO (MainThread) [supervisor.core] Detected Supervisor restart
2025-05-25 17:42:13.558 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
2025-05-25 17:42:13.567 INFO (MainThread) [supervisor.host.info] Updating local host information
2025-05-25 17:42:13.584 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state running
2025-05-25 17:42:13.603 INFO (MainThread) [supervisor.resolution.checks.base] Run check for trust/supervisor
2025-05-25 17:42:13.695 INFO (MainThread) [supervisor.core] Supervisor is up and running
2025-05-25 17:42:13.819 INFO (MainThread) [supervisor.resolution.checks.base] Run check for disabled_data_disk/system
2025-05-25 17:42:13.820 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks/system
2025-05-25 17:42:13.821 INFO (MainThread) [supervisor.resolution.checks.base] Run check for ipv4_connection_problem/system
2025-05-25 17:42:13.821 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_ipv6_error/dns_server
2025-05-25 17:42:14.088 INFO (MainThread) [supervisor.resolution.checks.base] Run check for security/core
2025-05-25 17:42:14.095 INFO (MainThread) [supervisor.resolution.checks.base] Run check for no_current_backup/system
2025-05-25 17:42:14.096 INFO (MainThread) [supervisor.resolution.module] Create new suggestion create_full_backup - system / None
2025-05-25 17:42:14.097 INFO (MainThread) [supervisor.resolution.module] Create new issue no_current_backup - system / None
2025-05-25 17:42:14.128 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_failed/dns_server
2025-05-25 17:42:14.187 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
2025-05-25 17:42:14.509 INFO (MainThread) [supervisor.host.services] Updating service information
2025-05-25 17:42:14.557 INFO (MainThread) [supervisor.resolution.checks.base] Run check for pwned/addon
2025-05-25 17:42:14.588 INFO (MainThread) [supervisor.resolution.checks.base] Run check for docker_config/system
2025-05-25 17:42:14.589 INFO (MainThread) [supervisor.resolution.checks.base] Run check for free_space/system
2025-05-25 17:42:14.738 INFO (MainThread) [supervisor.resolution.check] System checks complete
2025-05-25 17:42:14.738 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state running
2025-05-25 17:42:14.773 INFO (MainThread) [supervisor.host.network] Updating local network information
2025-05-25 17:42:16.884 WARNING (MainThread) [asyncio] Executing <Handle _message_reader(<dbus_fast._p...x7fe091938660>, <bound method...7fe09192be60>>, <bound method...7fe09192be60>>, False)() created at /usr/local/lib/python3.13/asyncio/selector_events.py:276> took 0.106 seconds
2025-05-25 17:42:16.886 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
2025-05-25 17:42:16.893 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state running
2025-05-25 17:42:16.895 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
2025-05-25 17:42:17.292 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
2025-05-25 17:42:17.478 INFO (MainThread) [supervisor.host.manager] Host information reload completed
2025-05-25 18:12:14.595 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
2025-05-25 18:42:13.308 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state running
2025-05-25 18:42:13.309 INFO (MainThread) [supervisor.resolution.checks.base] Run check for trust/supervisor
2025-05-25 18:42:13.364 INFO (MainThread) [supervisor.resolution.checks.base] Run check for disabled_data_disk/system
2025-05-25 18:42:13.365 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks
/system
2025-05-25 18:42:13.365 INFO (MainThread) [supervisor.resolution.checks.base] Run check for ipv4_connection_problem/system
2025-05-25 18:42:13.366 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_ipv6_error/dns_server
2025-05-25 18:42:13.501 INFO (MainThread) [supervisor.resolution.checks.base] Run check for security/core
2025-05-25 18:42:13.502 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_failed/dns_server
2025-05-25 18:42:13.504 INFO (MainThread) [supervisor.resolution.checks.base] Run check for pwned/addon
2025-05-25 18:42:13.507 INFO (MainThread) [supervisor.resolution.checks.base] Run check for docker_config/system
2025-05-25 18:42:13.507 INFO (MainThread) [supervisor.resolution.checks.base] Run check for free_space/system
2025-05-25 18:42:13.536 INFO (MainThread) [supervisor.resolution.check] System checks complete
2025-05-25 18:42:13.537 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with stat
e running
2025-05-25 18:42:14.006 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
2025-05-25 18:42:14.014 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state running
2025-05-25 18:42:14.015 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
2025-05-25 18:42:15.580 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token

System information

arch: amd64 channel: stable docker: 28.0.4 features:

  • reboot
  • shutdown
  • services
  • network
  • hostname
  • timedate
  • os_agent
  • haos
  • resolved
  • journal
  • disk
  • mount hassos: "15.2" homeassistant: 2025.5.3 hostname: homeassistant logging: info machine: qemux86-64 operating_system: Home Assistant OS 15.2 state: running supervisor: 2025.05.1 supported: true supported_arch:
  • amd64
  • i386 timezone: Europe/Berlin

Supervisor diagnostics

No response

Additional information

No response

thomersch avatar May 25 '25 16:05 thomersch

After attaching my debugger, it seems to be a bug in orjson, somebody else has observed it: https://github.com/ijl/orjson/issues/538

thomersch avatar May 27 '25 14:05 thomersch

Uh interesting find, so FreeBSD virtualization somehow triggers a orjson bug then? 🤔 Orjson does use some native code optimization, I guess the CPU detection fails and/or the optimized code doesn't run correctly on FreeBSD. Do you know what CPU model FreeBSD/bhyve emulates?

/cc @bdraco

agners avatar May 27 '25 19:05 agners

https://github.com/ijl/orjson/commit/f1cbc0a

Likely regressed in that commit

Maybe some type of buffer alignment issue.

bdraco avatar May 27 '25 19:05 bdraco

I dug a bit further and I don't think it's either FreeBSD or the virtualisation, but rather some kind of (missing) CPU feature.

I installed orjson on the affected host, but on the metal without the virt and it dumps some memory as well:

>>> orjson.dumps(datetime.now())
b'"2025-0\x88-\x9c\x88T0\x88:\x9c\x88:\x9c\x88.635621"'

On a different FreeBSD VM host with HAOS in bhyve, it behaves correctly.

The broken host runs old hardware (AMD E-350, anno 2010), while the other one has a slightly newer CPU (AMD Opteron X3216). If you tell me "just buy a newer server, you cheapskate" that's fine, but it makes me a bit queasy that it seems to dump memory.

Based on ijl's behaviour, I do not expect them to fix this any time soon and I also assume that you don't want an option to disable orjson, right?

thomersch avatar May 30 '25 08:05 thomersch

I dug a bit further and I don't think it's either FreeBSD or the virtualisation, but rather some kind of (missing) CPU feature.

We did run into this previously with some ISA extensions missing.

I installed orjson on the affected host, but on the metal without the virt and it dumps some memory as well:

Hm, ok so this is also reproducible with the orjson PyPI builds then. At this point it is probably worth opening an issue on orjson side along with the note what CPU this is reproducible (also if you have the list of ISA extensions available, e.g. a /proc/cpuinfo equivalent of FreeBSD).

If you tell me "just buy a newer server, you cheapskate" that's fine, but it makes me a bit queasy that it seems to dump memory.

I'd say probably worth investing in some new hardware, you probably get quite a bit better performance/power usage ratio nowadays 😄

agners avatar Jun 16 '25 10:06 agners

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

github-actions[bot] avatar Jul 16 '25 11:07 github-actions[bot]