logdb - Error table history - FHEM nicht mehr erreichbar/bleibt hängen

[bismosa]

Hallo!

Ich richte mir gerade ein neues FHEM ein. Dabei stelle ich auch von FileLog auf LogDB um.
Um die Datenbank (auch testweise) erstmal mit ordentlich Daten zu füllen, lasse ich derzeit noch ALLES Protokollieren.
Sobald die Installation fertig ist, werde ich dann eh neu anfangen.
Ich nutze eine MariaDB10 auf einer Synology für die Datenbank.

Code Auswählen Erweitern

attr logdb DbLogType Current/History
attr logdb asyncMode 1

Nun ist mir mein FHEM schon 2x "Abgestürzt". Jeweils am Abend und ich habe  es erst einen Tag später bemerkt.
Die letzten Logeinträge sind:

Code Auswählen Erweitern

...
2024.11.21 00:22:51 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 64298 generated 304 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:22:56 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 1694 generated 7 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:23:29 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 64436 generated 305 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:23:34 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 1721 generated 7 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:24:07 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 64459 generated 305 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:24:12 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 1858 generated 8 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:24:45 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 64491 generated 305 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:24:50 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 1880 generated 8 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:25:22 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 64633 generated 306 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
2024.11.21 00:25:27 2: logdb - Error table history - DBD::MariaDB::st execute_array failed: executing 1923 generated 8 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
Das geht einige Stunden...aber hört dann irgendwann auf. FHEM ist dann auch nicht mehr erreichbar. Es laufen aber 2 FHEM Prozesse weiterhin auf dem System (mit 0% CPU-Last)
Kille ich den letzten (nach PID) gibt es wieder einige Logeinträge...aber FHEM bleibt nicht erreichbar. Dafür muss ich alle FHEM Prozesse killen und neu starten.

Nun stellt sich mir die Frage, wie ich den Fehler weiter eingrenzen kann. Ich habe nun testweise Verbose auf 4 vom logDB-Device gesetzt und lasse auch die cachefiles schreiben. Vielleicht kann ich beim nächsten Problem hier etwas finden?

Da es jedes Mal abends zu dem Problem kam (wenn ich auch an der Einrichtung des Systems gearbeitet habe) kann ich mir auch vorstellen, das ich das Problem selbst verursache? Ich hatte jetzt z.B. auch mit DBeaver in die Datenbank geschaut und hatte das noch offen. Ich hoffe aber nicht, das ich dann exclusiv-Zugriff hatte und die Datenbank für FHEM nicht erreichbar war?
Oder habe ich beim Anlegen neuer Devices Logeinträge verursacht, die von der Datenbank nicht verarbeitet werden können?

Vielleicht ist der "Fehler" bzw. das Problem auch bekannt hier?

Gruß
Bismosa

[fhem024]

Hallo bismosa,
kommst Du denn auf die Datenbank als solche drauf und kannst die relevanten Tabellen (history) lesen und schreiben? dbVisualizer ist z.B. ein hilfreiches Tool dafür.

[bismosa]

Hallo!

Ja, die Datenbank kann ich öffnen und bearbeiten. Ich nutze dafür bisher Dbeaver. Geht wunderbar.
Nur ab Problembeginn wird nichts mehr der Datenbank hinzugefügt...

Gruß
Bismosa

[fhem024]

Hallo bismosa,
ok - hattest Du ja eigentlich schon im OP geschrieben. So ist das, wenn man nur quer liest.

Leider ist die Fehlermeldung von fhem hier nicht sonderlich aussagekräftig. Die grundsätzlichen Bedingungen sind erfüllt: Erreichbarkeit der DB zu jeder Zeit? Bleibt fhem immer zum gleichen / ähnlichen Zeitpunkt hängen? Läuft da evtl. etwas parallel auf den beteiligten Systemen, was dazu führt, dass andere Prozesse nicht mehr wie erwartet performen und dann einer drüberstolpert?
Im DBeaver, mit dem Du ja arbeitest, hast Du autocommit on - nur, um locking-Probleme auszuschließen?

[bismosa]

Hallo!

Ich bin wieder dabei ein paar Definition in FHEM zu importieren (RAW)...da ist es schon wieder passiert...

Derzeit passiert es auch nach einem Neustart des Systems gleich wieder.

In den Logs kann ich nun nichts ungewöhnliches entdecken...vielleicht auch weil ich nicht weiß, wonach ich genau suchen muss.
Im Verdacht habe ich vielleicht irgendwas an Sonderzeichen, die nicht in die Datenbank eingetragen werden können?

Wenn ich mir den cache anschaue habe ich z.B:

Code Auswählen Erweitern

9771 => 2024-11-21 18:39:49|LMS|SB_SERVER|scandb: ?|scandb|?|
oder auch

Code Auswählen Erweitern

9801 => 2024-11-21 18:39:50|SB_Spielzimmer|SB_PLAYER|connected: ?|connected|?|
9802 => 2024-11-21 18:39:50|SB_Spielzimmer|SB_PLAYER|connected: 0|connected|0|
oder

Code Auswählen Erweitern

9811 => 2024-11-21 18:39:50|SB_Spielzimmer|SB_PLAYER|currentAlbum: |currentAlbum||
oder

Code Auswählen Erweitern

9914 => 2024-11-21 18:39:54|echo|ECHODEVICE|.csrf-token: xxxxxxx+xxxxxxxxx+xxxxxx/xxxxxx|.csrf-token|xxxxxx+xxxxxx/xxxxxx|
oder (nicht selbst abgeschnitten)

Code Auswählen Erweitern

10054 => 2024-11-21 18:40:19|logdb|DBLOG|state: DBD::MariaDB::st execute_array failed: executing 316 generated 1 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.
|state|DBD::MariaDB::st execute_array failed: executing 316 generated 1 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, |
Ist hier etwas problematisches dabei?

Die DB ist problemlos erreichbar. Ich habe derzeit den DBeaver auch nicht laufen. Nur noch eine andere FHEM Instanz, die aber weiterhin brav in eine andere Tabelle loggt.

Gruß
Bismosa

[fhem024]

Reden die überhaupt miteinander? Kannst Du da parallel mal einen tcpdump mitlaufen lassen? Ich würde auch mal am DB-Server (mariaDB) selbst das Logging / Tracing aktivieren. Vielleicht wirst Du dann ja schlauer?

[bismosa]

Hallo!

Ja, natürlich. Sind schon über 1.000.000 Einträge vorhanden.

Ich habe mittlerweile das logging in der DB aktiviert. Hier konnte ich jetzt 2 Hinweise auf das Problem finden:

Code Auswählen Erweitern

3 Query INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('1970-01-01 01:00:00','Echo_2','ECHODEVICE','voice_person: Max','voice_person','Max','\n')

Code Auswählen Erweitern

3 Query INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('','state','DBD::MariaDB::st execute_array failed: executing 382 generated 1 errors [for Statement \"INSERT INTO history (TIMESTAMP, DEVICE, ','\n',NULL,NULL,NULL)

Erstmal scheint die DB das Datum 1970-01-01 01:00:00 nicht zu mögen. (warum auch immer es bei den EchoDevices öfter dazu kommt)
Zusätzlich scheint sich der Fehler dann im laufe der Zeit zu potenzieren, da das Fehlerreading im DBLog-Device gar kein Zeitstempel bekommt.

Nur warum?

Gruß
Bismosa

[bismosa]

Hallo!

Es liegt wirklich am Datum "1970-01-01 01:00:00"
Gültig wäre nur ein "1970-01-01 01:00:01"

Hab das ganze mal mit einem dummy nachgestellt. Log nur für das Device "mydummy:.*" aktiviert und ein

Code Auswählen Erweitern

setreading mydummy 1970-01-01 01:00:00 hallo abcdefbringt diesen Effekt.

@DS-Starter
Lässt sich im Modul eine "Idiotensicherung" einbauen, die einen ungültigen Zeitstempel (oder einen fehlenden) mit dem aktuellen Datum ergänzt?

Wenn es zu einem Ausführungsfehlern kommt, wird wohl immer wieder versucht der Datensatz hinzuzufügen. Ich konnte es nur unterbrechen mit einem reboot des Systems (gerade im asyncMode = 1)
Können nicht alle anderen Einträge außer dem fehlerhaften übernommen werden? (Und der fehlerhafte verworfen)

Ich habe jetzt erstmal das Logging der Echo-Devices deaktiviert...aber da kann man schnell drauf herein fallen.

Gruß
Bismosa

[DS_Starter]

Hallo zusammen,

wenn man bessere Ausschriften bei Fehlern bekommen möchte, kann das Attribut insertMode=1 hilfreich sein.
Dann werden die einzufügenden Datensätze sequentiell abgearbeitet.

Noch tiefer kommt man mit den Attributen traceFlag, traceLevel.

Wenn es zu einem Ausführungsfehlern kommt, wird wohl immer wieder versucht der Datensatz hinzuzufügen. Ich konnte es nur unterbrechen mit einem reboot des Systems (gerade im asyncMode = 1)
Können nicht alle anderen Einträge außer dem fehlerhaften übernommen werden? (Und der fehlerhafte verworfen)

Das geht schon. Dazu muß man das Attr commitMode auf Transaktion "aus" stellen, z.B. "ac:on_ta:off".

Lässt sich im Modul eine "Idiotensicherung" einbauen, die einen ungültigen Zeitstempel (oder einen fehlenden) mit dem aktuellen Datum ergänzt?

Ein fehlender Timstamp wird bereits behandelt.
Das Datum 1970-01-01 01:00:00 entspricht UTC 1970-01-01 00:00:00 und somit dem Unix Timestamp 0, dem Urknall der Unix Zeitrechnung. 

Ich weiß nicht ob das ein generelles Problem ist oder von der DB bzw. dem DB-Perltreiber abhängt.
Versuche es bei mir auch mal zu provozieren.

LG,
Heiko

[betateilchen]

Das Datum 1970-01-01 01:00:00 entspricht UTC 1970-01-01 00:00:00 und somit dem Unix Timestamp 0, dem Urknall der Unix Zeitrechnung. 

Und zu diesem Zeitpunkt kann es somit - logisch betrachtet - noch gar nichts geben, das überhaupt gelogged werden könnte.
Man sollte den Timestamp 0 somit ignorieren und einen Datensatz, der mit diesem Timestamp daherkommt, einfach verwerfen.

[bismosa]

Hallo!

Und zu diesem Zeitpunkt kann es somit - logisch betrachtet - noch gar nichts geben, das überhaupt gelogged werden könnte.
Man sollte den Timestamp 0 somit ignorieren und einen Datensatz, der mit diesem Timestamp daherkommt, einfach verwerfen.

Das wäre toll und würde den Fehler der durch die Echo Devices ausgelöst wird auf jeden Fall verhindern 

Das Attribut insertMode=1 werde ich beim nächsten Problem auf jeden Fall probieren. Auf die Idee war ich nicht gekommen.
Die Fehlersuche über das Protokoll der Datenbank war machbar, aber nicht gerade einfach. 
Ich denke aber im Normalfall sollte dies nicht notwendig sein.

Das geht schon. Dazu muß man das Attr commitMode auf Transaktion "aus" stellen, z.B. "ac:on_ta:off".

Dieses Attribut ist ein advanced feature und sollte nur im konkreten Bedarfs- bzw. Supportfall geändert werden.

Gut das ich keine Ahnung habe, was dies bewirkt. Ich hatte nur den Kommentar in der Commandref gelesen und habe lieber die Finger davon gelassen.

Vielen Dank für die Hilfe!

Gruß
Bismosa

[DS_Starter]

Ich habe eine entsprechende Prüfung eingebaut.
Die Version liegt in meinem contrib zum Test.
Ich lasse die Version bei mir auch erstmal einige Zeit im Test laufen, sieht aber gut aus bei meinen diversen Testszenarien.

Grüße,
Heiko

[bismosa]

Hallo!

Ich habe die Änderung ebenfalls getestet. Läuft auch bei mir mit meinem Test einwandfrei 
Vielen Dank für den tollen Support!

Gruß
Bismosa

[DS_Starter]

Danke für deine Rückmeldung 
Auch bei mir keine ungewünschten Nebenwirkungen feststellbar.
Checke die neue V nachher noch ein.

Grüße,
Heiko