Modul 93_DbRep - Reporting und Management von Datenbankinhalten (DbLog)

elektron-bbs · 07 Mai 2024, 16:14:13

Seit meinem letzten Update von FHEM habe ich ein Problem mit dem Modul 93_DbRep.pm auf zwei Raspberry Pi. Auf beiden Pi werden Daten in einer SQLITE-Datenbank gespeichert. Ich lasse jeden Tag Daten, die älter als 367 Tage sind aus der Datenbank löschen. Um die Datenbank zu verkleinern läuft einmal monatlich "set dbRep vacuum". Dieses bricht neuerdings auf beiden System ab:

Code Auswählen

Raspberry Pi 3:
# $Id: 93_DbRep.pm 28714 2024-03-27 21:40:03Z DS_Starter $
2024.05.02 01:15:00 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.02 01:15:00 3: DbRep myDbRep_Vacuum - ###          New optimize table / vacuum execution           ###
2024.05.02 01:15:00 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.02 01:15:00 3: DbRep myDbRep_Vacuum - execute command before optimize: 'set myDbLog reopen 3600' 
2024.05.02 01:15:00 2: myDbLog - Connection closed until 02:15:00 (3600 seconds).
2024.05.02 01:15:00 3: myDbLog - Database disconnected by request.
2024.05.02 01:15:00 3: DbRep myDbRep_Vacuum - Size of database /opt/fhem/fhem.db before optimize (MB): 2616
2024.05.02 01:45:31 1: DbRep myDbRep_Vacuum -> BlockingCall HASH(0x466cf48)}{fn} pid:DEAD:26397 Process died prematurely
2024.05.02 01:45:31 3: DbRep myDbRep_Vacuum - execute command after optimize: 'set myDbLog reopen' 
2024.05.02 01:45:31 3: myDbLog - Reopen requested
2024.05.02 01:45:31 3: DbRep myDbRep_Vacuum - command message after optimize: >Reopen executed.<
2024.05.02 01:45:31 2: DbRep myDbRep_Vacuum - Database optimize aborted: "Process died prematurely" 
2024.05.02 01:45:40 3: myDbLog - Database disconnected by request.
2024.05.02 01:45:48 3: myDbLog - SubProcess connected to /opt/fhem/fhem.db

Raspberry Pi 2:
# $Id: 93_DbRep.pm 28714 2024-03-27 21:40:03Z DS_Starter $
2024.04.08 04:01:00 3: DbRep myDbRep_Vacuum - ################################################################
2024.04.08 04:01:00 3: DbRep myDbRep_Vacuum - ###          New optimize table / vacuum execution           ###
2024.04.08 04:01:00 3: DbRep myDbRep_Vacuum - ################################################################
2024.04.08 04:01:00 3: DbRep myDbRep_Vacuum - execute command before optimize: 'set myDbLog reopen 7200' 
2024.04.08 04:01:00 2: myDbLog - Connection closed until 06:01:00 (7200 seconds).
2024.04.08 04:01:00 3: DbRep myDbRep_Vacuum - Size of database /opt/fhem/fhem.db before optimize (MB): 1717
2024.04.08 04:01:00 3: myDbLog - Database disconnected by request.
2024.04.08 04:39:55 1: DbRep myDbRep_Vacuum -> BlockingCall HASH(0x2961da8)}{fn} pid:DEAD:9923 Process died prematurely
2024.04.08 04:39:55 3: DbRep myDbRep_Vacuum - execute command after optimize: 'set myDbLog reopen' 
2024.04.08 04:39:55 3: myDbLog - Reopen requested
2024.04.08 04:39:55 3: DbRep myDbRep_Vacuum - command message after optimize: >Reopen executed.<
2024.04.08 04:39:55 2: DbRep myDbRep_Vacuum - Database optimize aborted: "Process died prematurely" 
2024.04.08 04:39:56 3: myDbLog - Database disconnected by request.
2024.04.08 04:39:59 3: myDbLog - SubProcess connected to /opt/fhem/fhem.db

Die Datenbanken haben folgende Größen:

Code Auswählen

Raspberry Pi 2:   SQLITE_FILE_SIZE_MB   1712
Raspberry Pi 3:   SQLITE_FILE_SIZE_MB   2569

Die Version vom Februar läuft noch durch:

Code Auswählen

Raspberry Pi 2:
# $Id: 93_DbRep.pm 28525 2024-02-16 20:57:30Z DS_Starter $
2024.05.07 13:13:28 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.07 13:13:28 3: DbRep myDbRep_Vacuum - ###          New optimize table / vacuum execution           ###
2024.05.07 13:13:28 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.07 13:13:28 3: DbRep myDbRep_Vacuum - execute command before optimize: 'set myDbLog reopen 7200' 
2024.05.07 13:13:28 2: myDbLog - Connection closed until 15:13:28 (7200 seconds).
2024.05.07 13:13:28 3: myDbLog - Database disconnected by request.
2024.05.07 13:13:29 3: DbRep myDbRep_Vacuum - Size of database /opt/fhem/fhem.db before optimize (MB): 1711
2024.05.07 14:00:00 3: DbRep myDbRep_Size - connection myDbLog to db /opt/fhem/fhem.db is closed until 15:13:28 - svrinfo postponed
2024.05.07 14:21:57 3: DbRep myDbRep_Vacuum - Size of database /opt/fhem/fhem.db after optimize (MB): 1711
2024.05.07 14:22:01 3: DbRep myDbRep_Vacuum - Optimize tables of /opt/fhem/fhem.db finished - total time (hh:mm:ss): 01:08:31
2024.05.07 14:22:01 3: DbRep myDbRep_Vacuum - Optimize tables finished successfully. 
2024.05.07 14:22:01 3: DbRep myDbRep_Vacuum - execute command after optimize: 'set myDbLog reopen' 
2024.05.07 14:22:02 3: myDbLog - Reopen requested
2024.05.07 14:22:02 2: DbRep myDbRep_Vacuum - command message after optimize: >Reopen executed.<
2024.05.07 14:22:03 3: myDbLog - Database disconnected by request.
2024.05.07 14:22:04 3: myDbLog - SubProcess connected to /opt/fhem/fhem.db

Probiert habe ich dann noch die erste Version vom März. Damit hängt sich der Pi offensichtlich auf, bzw. FHEM antwortet nicht mehr und der Pi ist aus dem WLAN abgemeldet. Nach knapp zwei Stunden habe ich ihn dann neu gestartet:

Code Auswählen

Raspberry Pi 3:
# $Id: 93_DbRep.pm 28627 2024-03-09 10:38:48Z DS_Starter $
Messages collected while initializing FHEM:configfile: Device "myDbRep_Vacuum" -> The attribute 'allowDeletion' is obsolete and will be deleted soon. Please press "save config" when FHEM start is finished.
Device "myDbRep_delEntries" -> The attribute 'allowDeletion' is obsolete and will be deleted soon. Please press "save config" when FHEM start is finished.
Device "myDbRep_delDevice" -> The attribute 'allowDeletion' is obsolete and will be deleted soon. Please press "save config" when FHEM start is finished.
Device "myDbRep_delReadings" -> The attribute 'allowDeletion' is obsolete and will be deleted soon. Please press "save config" when FHEM start is finished.
2024.05.07 11:38:25 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.07 11:38:25 3: DbRep myDbRep_Vacuum - ###          New optimize table / vacuum execution           ###
2024.05.07 11:38:25 3: DbRep myDbRep_Vacuum - ################################################################
2024.05.07 11:38:25 3: DbRep myDbRep_Vacuum - execute command before optimize: 'set myDbLog reopen 3600' 
2024.05.07 11:38:25 2: myDbLog - Connection closed until 12:38:25 (3600 seconds).
2024.05.07 11:38:25 3: DbRep myDbRep_Vacuum - Size of database /opt/fhem/fhem.db before optimize (MB): 2568
2024.05.07 11:38:25 3: myDbLog - Database disconnected by request.
2024.05.07 11:39:01 3: Timer: time difference too large! interval=59, Sekunde=01
2024.05.07 11:41:03 3: Timer: time difference too large! interval=57, Sekunde=03
2024.05.07 11:43:04 3: Timer: time difference too large! interval=57, Sekunde=03
2024.05.07 11:45:01 3: Timer: time difference too large! interval=59, Sekunde=01
Neustart weil keine Reaktion mehr
2024.05.07 11:22:39 1: Including fhem.cfg
...
2024.05.07 11:23:06 3: sduinoESP8266_1: StartInit, get version, retry = 1
2024.05.07 13:16:39 1: sduinoESP8266_1: CheckVersionResp, Not an SIGNALduino device, got for V: undef

DS_Starter · 09 Mai 2024, 09:27:20

Ich habe das vacuum bei mir mit der aktuellsten Version gestestet und konnte kein Problem feststellen:

Code Auswählen

2024.05.09 09:13:35.933 3: DbRep Rep.SQLite1 - ################################################################
2024.05.09 09:13:35.934 3: DbRep Rep.SQLite1 - ###          New optimize table / vacuum execution           ###
2024.05.09 09:13:35.935 3: DbRep Rep.SQLite1 - ################################################################
2024.05.09 09:13:36.009 3: DbRep Rep.SQLite1 - Size of database /opt/fhem1.db before optimize (MB): 5615
2024.05.09 09:15:32.462 3: DbRep Rep.SQLite1 - Size of database /opt/fhem1.db after optimize (MB): 1781
2024.05.09 09:15:32.477 3: DbRep Rep.SQLite1 - Optimize tables of /opt/fhem1.db finished - total time (hh:mm:ss): 00:01:56
2024.05.09 09:15:32.484 3: DbRep Rep.SQLite1 - Optimize tables finished successfully.

Auch nochmal mit schließen der Datenbank:

Code Auswählen

2024.05.09 09:20:35.127 3: DbRep Rep.SQLite1 - ################################################################
2024.05.09 09:20:35.127 3: DbRep Rep.SQLite1 - ###          New optimize table / vacuum execution           ###
2024.05.09 09:20:35.128 3: DbRep Rep.SQLite1 - ################################################################
2024.05.09 09:20:35.128 3: DbRep Rep.SQLite1 - execute command before optimize: 'set LogSQLITE1 reopen 3600' 
2024.05.09 09:20:35.129 2: LogSQLITE1 - Connection closed until 10:20:35 (3600 seconds).
2024.05.09 09:20:35.207 3: DbRep Rep.SQLite1 - Size of database /opt/fhem1.db before optimize (MB): 1781
2024.05.09 09:21:43.106 3: DbRep Rep.SQLite1 - Size of database /opt/fhem1.db after optimize (MB): 1781
2024.05.09 09:21:43.356 3: DbRep Rep.SQLite1 - Optimize tables of /opt/fhem1.db finished - total time (hh:mm:ss): 00:01:08
2024.05.09 09:21:43.359 3: DbRep Rep.SQLite1 - Optimize tables finished successfully. 
2024.05.09 09:21:43.360 3: DbRep Rep.SQLite1 - execute command after optimize: 'set LogSQLITE1 reopen' 
2024.05.09 09:21:43.389 3: DbRep Rep.SQLite1 - command message after optimize: >Reopen executed.<

Ist natürlich jetzt schwierig wenn ich das Problem nicht nachvollziehen kann.
Hast du diesen Hinweis beachtet?

ZitatBei der Ausführung des vacuum Kommandos wird bei SQLite Datenbanken automatisch das PRAGMA auto_vacuum = FULL angewendet.
Das vacuum Kommando erfordert zusätzlichen temporären Speicherplatz. Sollte der Platz im Standard TMPDIR Verzeichnis nicht ausreichen, kann SQLite durch setzen der Umgebungsvariable SQLITE_TMPDIR ein ausreichend großes Verzeichnis zugewiesen werden.
(siehe: www.sqlite.org/tempfiles)

Grüße,
Heiko

DS_Starter · 09 Mai 2024, 09:54:29

Ich habe möglicherweise die Ursache gefunden.
Lade dir bitte die Version aus meinem contrib (Link im Fußtext), restarte FHEM und teste mal bei dir.

Mit verbose 4 sieht das Log nun so aus:

Code Auswählen

2024.05.09 09:41:22.310 3: DbRep Rep.Test - ################################################################
2024.05.09 09:41:22.311 3: DbRep Rep.Test - ###          New optimize table / vacuum execution           ###
2024.05.09 09:41:22.312 3: DbRep Rep.Test - ################################################################
2024.05.09 09:41:22.313 3: DbRep Rep.Test - execute command before optimize: 'set LogSQLITE reopen 3600' 
2024.05.09 09:41:22.314 2: LogSQLITE - Connection closed until 10:41:22 (3600 seconds).
2024.05.09 09:41:22.382 4: DbRep Rep.Test - Database Model: SQLITE
2024.05.09 09:41:22.384 4: DbRep Rep.Test - Database connect - user: no, UTF-8 option set: no
2024.05.09 09:41:22.401 4: DbRep Rep.Test - simple do statement: PRAGMA temp_store=FILE
2024.05.09 09:41:22.402 4: DbRep Rep.Test - simple do statement: PRAGMA synchronous=FULL
2024.05.09 09:41:22.432 3: DbRep Rep.Test - Size of database /opt/fhem.db before optimize (MB): 868
2024.05.09 09:41:22.434 4: DbRep Rep.Test - Exec PRAGMA Statement: PRAGMA auto_vacuum = FULL;
2024.05.09 09:41:22.437 4: DbRep Rep.Test - VACUUM database /opt/fhem.db....
2024.05.09 09:41:45.121 3: DbRep Rep.Test - Size of database /opt/fhem.db after optimize (MB): 867
2024.05.09 09:41:45.364 3: DbRep Rep.Test - Optimize tables of /opt/fhem.db finished - total time (hh:mm:ss): 00:00:22
2024.05.09 09:41:45.368 3: DbRep Rep.Test - Optimize tables finished successfully. 
2024.05.09 09:41:45.369 3: DbRep Rep.Test - execute command after optimize: 'set LogSQLITE reopen' 
2024.05.09 09:41:45.424 3: DbRep Rep.Test - command message after optimize: >Reopen executed.<

Relevant ist dabei "PRAGMA temp_store=FILE". Im Verlauf der letzten Changes war temp_store=MEMORY eingeflossen was bei wenig verfügbaren Speicher im Vergleich zur DB Größe möglicherweise zu Engpässen führen könnte.

betateilchen · 09 Mai 2024, 11:45:25

Zitat von: DS_Starter am 09 Mai 2024, 09:54:29Relevant ist dabei "PRAGMA temp_store=FILE". Im Verlauf der letzten Changes war temp_store=MEMORY eingeflossen was bei wenig verfügbaren Speicher im Vergleich zur DB Größe möglicherweise zu Engpässen führen könnte.

Gilt natürlich in gleichem Maße auch für den Speicherplatz im Dateisystem. Mit einer fast vollen Speicherkarte oder Festplatte sollte man es besser nicht probieren.

elektron-bbs · 09 Mai 2024, 12:55:53

Den Hinweis mit "SQLITE_TMPDIR" hatte ich gelesen, es als Ursache aber eigentlich ausgeschlossen, da sich am Dateisystem ja nichts geändert hat.

Die Änderung "PRAGMA temp_store=FILE" war aber auf jeden Fall erfolgreich. Jetzt läuft "VACUUM" wieder durch.

Evtl. könnte man ja ein neues Attribut einfügen: tempStore:FILE,MEMORY
Im RAM dürfte der Prozess ja erheblich schneller durchgeführt werden.

DS_Starter · 09 Mai 2024, 13:02:45

Prima! Danke für den Test.
Die Version checke ich ein und ist dann morgen früh im Regelupdate.

Das mit dem Attribut überlege ich mir noch. Eventuell wird es auch eine DbLog-Einstellung die sich dann ebenfalls im DbRep auswirkt. Aber das lasse ich erstmal offen.

Schönen Feiertag!

LG

DS_Starter · 11 Mai 2024, 11:15:29

Sorry, der Post war für einen anderen Thread bestimmt -> SolarForecast.

LG

dennisk · 12 Mai 2024, 16:49:27

Leider habe ich nach wie vor diese Warnung im Log. Ich habe gerade mal ein print in der Zeile davor eingebaut, d.h. da steht nun folgendes:

Code Auswählen

  print STDERR $dir;
  while (my $file = readdir(DIR)) {
      next unless (-f "$dir/$file");
      next unless ($file =~ /^$sd/);
      push @bkps,$file;
  }
  closedir(DIR);

Dann habe ich mittels reload 93_DbRep.pm das Modul neugeladen. Anschließend hatte ich im Log wieder, ohne vorher die Seite mit dem DbRep Device zu öffnen:

Code Auswählen

/usr/share/fhem/log/2024.05.12 16:39:52 1: PERL WARNING: readdir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 559.
2024.05.12 16:39:52 1: PERL WARNING: closedir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 564.
/var/lib/fhem/dblog/

Wenn ich dann die Seite für das DbRep Device öffne, erhalte ich den Pfad erneut 2x ausgegeben:

Code Auswählen

/usr/share/fhem/log/2024.05.12 16:39:52 1: PERL WARNING: readdir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 559.
2024.05.12 16:39:52 1: PERL WARNING: closedir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 564.
/var/lib/fhem/dblog//var/lib/fhem/dblog//var/lib/fhem/dblog/

Das wiederholt sich dann so für jedes Öffnen oder Neuladen der Seite für das DbRep Device, sprich es kommt immer 2x die Ausgabe des Pfads dazu.

Eine Idee, woran die Warnung nach dem initialen Laden liegen könnte?

Nachtrag 13.05.2024:
Ich habe ein paar Zeilen darüber mal ein print eingebaut und lasse mir die Variable $dir ausgeben. Diese scheint beim allerersten Aufrufen, also Neustart oder Reload, nicht den Wert aus dumpDirLocal zu beinhalten, sondern etwas anderes. Zumindest deutet der Output für mich darauf hin. Folgende Änderung habe ich eingebaut:

Code Auswählen

opendir(DIR,$dir) or print(qq{Unable to open directory $dir: $!});

Daraufhin erhalte ich dann folgende Ausgabe:

Code Auswählen

Unable to open directory /usr/share/fhem/log/: No such file or directory2024.05.13 10:48:37 1: PERL WARNING: readdir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 558.
2024.05.13 10:48:37 1: PERL WARNING: closedir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 563.

Woran könnte es liegen, dass die Variable zunächst den falschen Wert beinhaltet und dann erst in den folgenden Aufrufen korrekt auf dumpDirLocal gesetzt ist?

Zitat von: dennisk am 20 April 2024, 18:16:46
Zitat von: DS_Starter am 21 März 2024, 23:30:17
ZitatAber dumpDirLocal ist doch gesetzt.
Wenn es gesetzt ist, wird das angegebene Verzeichnis benutzt.
Wenn die Fehlerausschrift in diesem Fall auftritt, kann das angegebene Verzeichnis nicht gelesen werden.

Also nach einem Update und Neustart habe ich nun wieder folgendes im Log - ohne, dass ich DbRep im UI aufgerufen hätte:
Code Auswählen Erweitern
2024.04.20 17:57:57 1: PERL WARNING: readdir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 558. 2024.04.20 17:57:57 1: PERL WARNING: closedir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 563.
Das DEF sieht wie gesagt so aus:
Code Auswählen Erweitern
defmod globalDbLog_DbRep DbRep globalDbLog attr globalDbLog_DbRep dumpDirLocal /var/lib/fhem/dblog/ setstate globalDbLog_DbRep initialized setstate globalDbLog_DbRep 2024-04-20 17:53:33 state initialized setstate globalDbLog_DbRep 2024-03-24 07:56:37 timestamp_oldest_dataset 2023-09-25 20:37:40+02
dumpDirLocal ist also gesetzt. Und wenn ich in fhem den Befehl
Code Auswählen Erweitern
{qx(echo "test" > /var/lib/fhem/dblog/testfile)} ausführe, wird die Datei anstandslos erstellt. Unter /var/lib/fhem/dblog existiert auch das Unterverzeichnis log, auch dort kann fhem reinschreiben. Lesen mittels in fhem ausgeführtem
Code Auswählen Erweitern
{qx(ls /var/lib/fhem/dblog/)} bzw.
Code Auswählen Erweitern
{qx(ls /var/lib/fhem/dblog/log)} funktioniert ebenso. Kann ich irgendwas tun, um rauszufinden, warum gerade beim Neustart von fhem diese Fehlermeldungen auftauchen?

bertl · 14 Mai 2024, 10:00:55

Hallo Leute,

bezüglch dem Attribut suppressAddLogV3 habe ich folgende Frage:

Laut Beschreibung, werden verbose 3 Logeinträge durch die addLog-Funktion unterdrückt.
Nun bekomme ich trotz gesetztem Attribut folgende Logeinträge:

Code Auswählen

2024.05.14 09:26:24 3: myDbLog - addLog WARNING - Device: 'mdbsSDM630M' -> Reading 'Energy_heating_year_kWh' not found - add it as new reading.

Kann das bitte auch unterdrückt werden?

Danke, Robert

betateilchen · 14 Mai 2024, 12:35:37

Solche Meldungen, die auf ein mögliches Problem hindeuten, sollten bitte NICHT unterdrückt werden.

dennisk · 17 Mai 2024, 11:23:39

Wenn ich es im Code richtig verstehe, dann ist /usr/share/fhem/log das Resultat aus dieser Zeile: https://github.com/mhop/fhem-mirror/blob/27bd6260cd3318f787b1e377b95039cd173cdd37/fhem/FHEM/93_DbRep.pm#L377C1-L377C118
modpath ist bei mir im global auf /usr/share/fhem gesetzt.

Ich habe aber immer noch keine Idee, warum beim erstmaligen Aufruf immer der default genommen wird, und dann erst dumpDirLocal. Hat jemand eine Idee dazu, der tiefer im Code drinsteckt?

Zitat von: dennisk am 12 Mai 2024, 16:49:27Nachtrag 13.05.2024:
Ich habe ein paar Zeilen darüber mal ein print eingebaut und lasse mir die Variable $dir ausgeben. Diese scheint beim allerersten Aufrufen, also Neustart oder Reload, nicht den Wert aus dumpDirLocal zu beinhalten, sondern etwas anderes. Zumindest deutet der Output für mich darauf hin. Folgende Änderung habe ich eingebaut:
Code Auswählen Erweitern
Code Auswählen Erweitern
opendir(DIR,$dir) or print(qq{Unable to open directory $dir: $!});Daraufhin erhalte ich dann folgende Ausgabe:
Code Auswählen Erweitern
Code Auswählen Erweitern
Unable to open directory /usr/share/fhem/log/: No such file or directory2024.05.13 10:48:37 1: PERL WARNING: readdir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 558. 2024.05.13 10:48:37 1: PERL WARNING: closedir() attempted on invalid dirhandle DIR at /usr/share/fhem/FHEM/93_DbRep.pm line 563.
Woran könnte es liegen, dass die Variable zunächst den falschen Wert beinhaltet und dann erst in den folgenden Aufrufen korrekt auf dumpDirLocal gesetzt ist?