Ein Tag Home-Assistant-Log: 775 Fehler, sieben Befunde

Mein produktives Home Assistant läuft seit 2024 als Docker-Container auf einer kleinen Cloud-VM, auf Version 2024.11.1, mit etwa 570 Entitäten, 73 Automationen und einem KNX-Bus dahinter. Das Log hatte ich seit Monaten nicht gelesen. Im September habe ich mich gezwungen, es ordentlich zu tun: ein voller Tag Log, jeder Fehler und jede Warnung gezählt und gruppiert, bevor irgendetwas angefasst wird, und erst danach eine Reparaturliste nach Priorität. Dieser Post ist diese Liste. Darin sind zwei Befunde, bei denen nichts zu reparieren war, und ein Template, das das Garagentor kurz als offen gemeldet hat.

Die Zahlen für die 24 Stunden vom 12. September, 15:25 Uhr, bis zum 13. September, 15:25 Uhr: 10.490 Logzeilen, 775 ERROR-Einträge, 5.077 WARNING-Einträge. Viele Einträge haben dieselbe Ursache. Bevor ich einen davon gelesen habe, habe ich sie deshalb nach dem Logger-Namen in eckigen Klammern gruppiert, der in diesem Logformat im fünften Feld steht:

# ein Tag Log, gezählt bevor irgendetwas gelesen wird
docker logs --since 24h homeassistant 2>&1 | wc -l          # 10490
docker logs --since 24h homeassistant 2>&1 | grep -c ' ERROR '   # 775
docker logs --since 24h homeassistant 2>&1 | grep -c ' WARNING ' # 5077
# nach Logger-Name (Feld 5) gruppieren, häufigste zuerst
docker logs --since 24h homeassistant 2>&1 \
  | grep -E ' (ERROR|WARNING) ' \
  | awk '{print $5}' | sort | uniq -c | sort -rn | head -20

Grundlagen prüfen, bevor ein einziger Fehler gelesen wird

Bevor ich etwas interpretiere, prüfe ich die Dinge, die das Log wertlos machen würden, wenn sie nicht stimmen. Container läuft seit dem 27. August, ein historischer Neustart, nicht OOM-gekillt. Host mit 3,8 GiB RAM, 2,3 GiB frei, der Container bei etwa 800 MiB. Swap 4 GiB, davon 1 MiB belegt. Platte zu 63 Prozent voll. Die Recorder-Datenbank bei 60 MiB mit 4,3 MiB Write-Ahead-Log, ein lesender SQLite-quick_check mit ok. Eine Konfigurationsprüfung im Container ohne Fehler. Die vier Konfigurationsdateien auf der VM stimmen per SHA-256 mit dem Repository überein. Außerdem habe ich die Entitätsreferenzen aller 73 Automationen mit der Entity-Registry abgeglichen. Eine nicht registrierte Entität habe ich dabei nicht automatisch als fehlend gewertet.

Das dauerte zwanzig Minuten und schloss die langweiligen Erklärungen aus. RAM und Plattenplatz reichten, die Datenbankprüfung lief durch, und die Konfiguration auf der Maschine stimmte mit dem Repository überein.

Befund 1: die Kameras verursachten 4.524 der 5.077 Warnungen

Die meisten Warnungen gingen auf die Kameras zurück. 2.886 waren Warnungen über langsame Updates der zwei Tapo-Kameras. Weitere 1.638 kamen von zwei Automationen, die die Bewegungserkennung dieser Kameras einstellen. Ihr Trigger war ein Zeitmuster auf Sekunde 10, das einmal pro Minute auslöst, und sie schrieben jedes Mal dieselben Einstellungen. Beide laufen in mode single. Ein Aufruf an die Kamera-Integration blieb hängen, und ab diesem Moment wurde jeder weitere Lauf mit einer Already-running-Warnung abgewiesen, 1.440-mal bei der einen Kamera und 198-mal bei der anderen. Der Trace des letzten angenommenen Laufs der ersten Automation stammte vom 6. September, sie war also seit einer Woche nicht mehr gelaufen und hatte in dieser Zeit einmal pro Minute eine Warnung geschrieben.

Repariert habe ich das am selben Nachmittag in zwei Schritten. Ein Neuladen der Config-Einträge der beiden Kameras hat die hängenden Aufrufe beendet, ohne Neustart von Home Assistant oder der Kameras. In den Automationen wird eine Einstellung jetzt nur noch geschrieben, wenn die Entität den Sollwert noch nicht meldet, das waren 24 Stellen in der Datei. Trigger und Modus sind geblieben. Ein Wechsel auf mode parallel oder das Abschalten der Warnung hätte den hängenden Aufruf bestehen lassen und den einzigen Hinweis darauf entfernt. Einen Timeout um die Kamera-Aufrufe habe ich nicht eingebaut. Ein Aufruf, der in der Bibliothek hängt, kann die Automationen also wieder blockieren, und bemerken würde ich das an der Already-running-Warnung. Das Beispiel unten zeigt die Bedingung.

# vorher: feuert jede Minute bei Sekunde 10, mode single,
# und schreibt jedes Mal dieselben Erkennungseinstellungen
triggers:
  - trigger: time_pattern
    seconds: "10"
mode: single

# nachher: nur schreiben, wenn die Einstellung wirklich abweicht
conditions:
  - condition: template
    value_template: >
      {{ not is_state('switch.camera_motion_detection', 'on') }}

Befund 2: eine Cloud-Integration, die loaded meldete und nichts lieferte

Die FusionSolar-Integration fragt Huaweis Cloud-Kiosk nach Tages-, Monats- und Jahresenergie. 144 fehlgeschlagene Abrufe in 24 Stunden, einer alle zehn Minuten, jeder gefolgt von drei Fehlern über fehlende Energiefelder, insgesamt 576 Logeinträge. Alle vier Sensoren standen auf unknown. Auf der Integrationsseite stand trotzdem loaded, in der Oberfläche war also nichts zu sehen.

Die lokalen Modbus-Sensoren am selben Wechselrichter meldeten zur gleichen Zeit weiterhin 22,63 kWh Tagesertrag. Lokal konnte ich den Ertrag also ablesen, während die Cloud-Sensoren auf unknown standen. Bevor ich den Kioskbezug repariere, habe ich geprüft, ob irgendetwas diese vier Sensoren benutzt: keine Automation, kein Dashboard, nicht die Energiekonfiguration. Ich habe die Integration deaktiviert statt repariert. Home Assistant antwortete mit require_restart und failed_unload, so sagt es, dass die Deaktivierung erst nach einem Neustart vollständig ist. Ich nehme daraus mit, dass loaded nur die Einrichtung der Integration beschreibt. Ob ihre Daten ankommen, muss man an den Sensoren prüfen. Meine Werte liefern hier seit einem Jahr die lokalen Modbus-Register, und die Cloud-Integration war noch eingerichtet, obwohl nichts ihre Sensoren benutzte.

Befund 3: 123 Fehler von einem REST-Sensor, der null nicht verarbeiten konnte

Der my-PV-Heizstab liefert seinen Zustand über einen lokalen HTTP-Endpunkt, gelesen nach dem REST-Sensor-Muster. 123 Updatefehler an diesem Tag, 110 davon beim Sensor für die Batterieladung: die API lieferte für ein Feld null, das Template reichte es durch, und Home Assistant lehnte den String None als Wert mit Einheit W ab. Dazu acht Timeouts auf demselben Endpunkt. Die Korrektur behandelt fehlende Daten als nicht verfügbar, statt einen Fehler auszulösen:

# rest.yaml, der Sensor, der an einem Tag 110-mal fehlschlug
- name: "Batterieladung"
  unit_of_measurement: W
  # die API liefert null, während das Gerät neu startet; "None" ist keine Zahl
  value_template: >
    {{ value_json.m2sum | default(0, true) | float(0) }}
  availability: >
    {{ value_json.m2sum is number }}

Ein Detail kostete eine Extrarunde: meine erste Version fiel auf den String unknown zurück, was denselben Konvertierungsfehler erzeugte, weil Home Assistant 2024.11 den nativen Wert schreibt, bevor es die Verfügbarkeit neu bewertet. Die Version oben, ein numerischer Fallback plus ein separates Availability-Template, ging per rest.reload ohne Neustart durch, und der Sensor zeigte eine Minute später 0 W. Auf dieser Core-Version kann beim Übergang kurz der numerische Fallback geschrieben werden. Getestet habe ich das nur auf 2024.11.

Befund 4: elf KNX-Adressen, die nie antworten würden

Etwa stündlich loggte die KNX-Integration Lese-Timeouts für elf Gruppenadressen, die Betriebsart-Statusadressen von elf Thermostaten. Die Fehler sind älter als alles andere im Log, das war also nichts Neues. Ich habe die Adressen im ETS-Projekt nachgeschlagen: sie gehören zu einem Zwangsführungs-Objekt, dessen Lese-Flag deaktiviert ist. Home Assistant schickte eine Leseanfrage an ein Objekt, das so konfiguriert ist, dass es nie antwortet. Eine lesbare Betriebsart-Rückmeldung gibt es an diesen Geräten nicht.

Ich habe die elf Statusadressen aus dem YAML entfernt, statt Ersatzadressen zu raten oder die Statussynchronisation global abzuschalten. Betriebsartbefehle, Temperatur- und Sollwert-Rückmeldungen bleiben unverändert. Home Assistant hat jetzt keine unabhängige Bestätigung, in welcher Betriebsart ein Thermostat steht. Dafür müsste in ETS ein echtes Rückmeldeobjekt bereitgestellt werden. Es ist dasselbe Problem wie damals, als die Thermostate nach jedem Neustart auf Standby fielen.

Befund 5: 100 nicht verfügbare Entitäten, und warum die Zahl wenig bedeutet

100 von 570 Entitäten standen auf unavailable. 38 davon waren aus der Registry wiederhergestellt worden und bekamen keine aktuellen Daten. Gruppiert: 44 Tapo-Entitäten von einer Kamera, die absichtlich abgeschaltet ist, 19 aus der Mobile-App auf Handys, 13 TP-Link, 11 Automationen, die deaktivierte Altbestände sind, und eine Handvoll Templates und Helfer. Bei zwei davon war etwas zu tun: Eine smarte Steckdose steht seit dem 28. August auf setup_in_progress und ist auf ihren Ports nicht erreichbar, und HACS verlangt seit dem 8. September eine erneute Anmeldung. Die anderen rund 90 waren zu erwarten.

Ich erwähne das, weil das Massenlöschen nicht verfügbarer Entitäten ein beliebter Aufräumschritt ist, und es hätte hier Entitäten entfernt, auf die Automationen verweisen. Ich habe jede Gruppe auf Nutzung geprüft, bevor ich etwas entfernt habe.

Befund 6: das Garagentor, das als offen gemeldet wurde

Dieser kam ein paar Tage später, beim Neustart für die KNX-Änderungen, und ich halte ihn für den schwerwiegendsten. Der rohe Türkontakt war für einen Moment unavailable, während die KNX-Integration hochkam. Ein Template-Sensor leitete daraus den Torzustand ab, mit dem Ausdruck not is_state(kontakt, 'on'). Unavailable ist nicht on, für diesen Moment meldete das Template das Garagentor also als offen, und das Dashboard zeigte es.

Ich habe die Recorder-Daten aus der Zeit kurz vor und nach dem Neustart geprüft. Ich fand keinen Schaltbefehl für das Tor, kein knx.send an seine Adresse und keine ausgelöste Automation. Ein Beweis, dass Home Assistant nichts gesendet hat, ist das nicht, weil ich nicht geprüft habe, ob das alles aufgezeichnet worden wäre. Ob sich das Tor bewegt hat, kann ich weder beweisen noch ausschließen, weil die Bustelegramme nicht aufgezeichnet wurden. Das Template hat jetzt eine Availability-Bedingung und wird zusammen mit seiner Quelle nicht verfügbar, statt einen Zustand zu erfinden. Die Änderung ging per Template-Reload live, ohne Neustart.

# vorher: unavailable zählte als „offen“
- binary_sensor:
    - name: "Garagentor offen"
      state: "{{ not is_state('binary_sensor.garage_contact', 'on') }}"

# nachher: das Template wird zusammen mit seiner Quelle nicht verfügbar
- binary_sensor:
    - name: "Garagentor offen"
      state: "{{ not is_state('binary_sensor.garage_contact', 'on') }}"
      availability: >
        {{ states('binary_sensor.garage_contact') not in ['unknown', 'unavailable'] }}

Befund 7: was der Neustart selbst zutage brachte

Der Neustart am 16. September, erst gemacht, nachdem die Änderungen oben vorbereitet und geprüft waren, brachte zwei weitere. Die alte Shelly-Custom-Integration warf beim Herunterfahren einen TypeError, machte blockierende Aufrufe im Event-Loop und hinterließ WebSocket-Fehler. Der Sensor für die Boilertemperatur hatte zwei Probleme. Sein Template benutzte float ohne Fallback für eine nicht verfügbare Quelle, und er veröffentlichte 701, wo der präzise Sensor 70,1 Grad zeigte, ein Skalierungsfehler. Drei deaktivierte Automationen vergleichen diesen Sensor mit 50 und 55 Grad, er musste also korrigiert sein, bevor eine davon wieder eingeschaltet wird.

Das Boiler-Template prüft jetzt, ob seine Quelle verfügbar und numerisch ist, verwendet float(0), und die Skalierung ist um den Faktor zehn korrigiert. Nach dem Neuladen zeigte der Sensor 66,1 statt 661 Grad. Für die Shelly-Integration habe ich ein kleines Kompatibilitätsmodul geschrieben, das Bibliotheksimport und Herunterfahren in den Executor verlegt, die Verbindungsprüfungen serialisiert und die Sockets mit begrenzter Wartezeit schließt, dazu vier Regressionstests. Es ist ein lokaler Patch über einer Custom Component und muss nach jedem HACS-Update dieser Integration neu geprüft werden. Der zweite Neustart kam mit null ERROR-Zeilen hoch, Boiler bei 66,2 Grad, Garagentor geschlossen.

Reihenfolge der Reparaturen und der Neustart am Ende

Die Reparaturreihenfolge war: die Kamera-Automationen entblocken, die tote Cloud-Integration deaktivieren und Steckdose und HACS-Anmeldung klären, die null-Behandlung korrigieren, die KNX-Adressen entfernen, die nicht antworten können, und erst dann die deaktivierten Altbestände nach tatsächlicher Nutzung aufräumen. Zwei Dinge kamen als Diagnoseschritte nicht in Frage: ein pauschaler Neustart und ein pauschales Löschen nicht verfügbarer Entitäten. Der Neustart kam zuletzt, nach den Änderungen, und er war der Schritt, der Befund 6 und 7 fand.

Drei der sieben Befunde betrafen den Betrieb: die hängenden Kameraaufrufe, die null-Behandlung und das Template, das aus unavailable ein offenes Tor machte. Die KNX-Lese-Timeouts und die Fehler aus dem Neustart betrafen den Betrieb nicht, hatten aber Ursachen, die ich beseitigen konnte. Die Cloud-Integration war ungenutzt, und die meisten der 100 nicht verfügbaren Entitäten waren zu erwarten. Die Kamera-Automation schrieb ihre Warnung seit dem 6. September ins Log, und gesehen habe ich sie erst beim Lesen. Mein Update-Workflow sieht vor, dass ich nach jedem Update ein paar Minuten ins Log schaue. Zwischen den Updates habe ich es bisher nicht gelesen.

Häufige Fragen

Sind 775 Fehler am Tag viel für Home Assistant?

Bei mir gingen die meisten auf vier wiederkehrende Ursachen zurück. Ich beurteile die Zahl nach den Ursachen dahinter und danach, was nicht mehr funktioniert hat, und das waren drei Dinge.

Soll ich Home Assistant neu starten, wenn das Log volläuft?

Nicht als ersten Schritt. Ich würde zuerst das Log und die Automations-Traces sichern und die wiederkehrenden Einträge ansehen, weil ein Neustart den Zustand verändert, den ich untersuchen will.

Warum meldet ein Template einen Zustand, wenn seine Quelle nicht verfügbar ist?

Weil not is_state(x, 'on') auch bei unknown und unavailable wahr ist. Ein Availability-Template, das diese beiden Zustände der Quelle ausschließt, behebt das.