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

[RalfRog]

......
21:31 Uhr
na super wieder die PERL Warning - ich halte es hier schon mal fest Zusammenfassung später in einer Antwort
.....

Siehe auch Antwort #1646

Nach dem FHEM Update und einem Reboot ist die Warning heute wieder aufgetreten. Bei einem execNow auf das "at" eine Stunde später nicht. 
Nun habe ich einen korrekten und einen fehlerhaften (weil weitgehend leer) DB-Eintrag.
Dieser "Fehler" ist sowas von komisch.

Wenn Du eine Idee hast füge ich im Code (z.B. im Umfeld der relevaten Zeilen) gern ein paar Kommandos ein um z.B. den Inhalt von Variablen ins Log zu schreiben. Mir fehlt da dann doch Wissen.
.....und warum war das die letzen Tage weg...   

[DS_Starter]

Hallo Ralf,

schreibe in die Zeile 965:

Code: [Auswählen]

Log3 ($name, 5, "DbRep $name - all: $prop, dev: $i_device, reading: $i_reading, value: $i_value");
(reload 93_DbRep in der Kommandozeile ausführen. Das bringt evtl. Tippfehler gleich raus.)

Mit verbose 5 wird das ausgeschrieben.
Vllt sehen wir dann mehr.

Komische Sachen machst du ... 

[RalfRog]

Codezeile seit gestern drin und Reload gemacht.
Code im Modul Zeile 965:

Code: [Auswählen]

964       $hash->{LASTCMD} = $prop ? "$opt $prop" : "$opt";
965 Log3 ($name, 5, "DbRep $name - all: $prop, dev: $i_device, reading: $i_reading, value: $i_value"); # Zeile zum Debuggen da einige DB Eintraege verkorkst
966       if ($dbmodel ne 'SQLITE') {                          # Daten auf maximale Länge (entsprechend der Feldlänge in DbLog) beschneiden wenn nicht SQLite
967           $i_device  = substr($i_device,  0, $hash->{HELPER}{DBREPCOL}{DEVICE});
968           $i_reading = substr($i_reading, 0, $hash->{HELPER}{DBREPCOL}{READING});
969           $i_value   = substr($i_value,   0, $hash->{HELPER}{DBREPCOL}{VALUE});
970           $i_unit    = substr($i_unit,    0, $hash->{HELPER}{DBREPCOL}{UNIT});
971       }

Ergebnis (Codezeile liefert gewünschte Ausgabe):

Code: [Auswählen]

2022.05.13 21:31:00.010 5: DbRep DBRepPow - all: 2022-05-13,21:31:00,0, dev: shelly_plug_s_df2674, reading: power, value: 0
2022.05.13 21:31:00.024 4: DbRep DBRepPow - -------- New selection ---------
2022.05.13 21:31:00.024 4: DbRep DBRepPow - Command: insert 2022-05-13 21:31:00,shelly_plug_s_df2674,power,0,
2022.05.13 21:31:00.051 5: DbRep DBRepPow - BlockingCall with PID "12729" started
2022.05.13 21:31:00.097 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.13 21:31:00.171 5: DbRep DBRepPow -> Primary Key used in fhem.history: 1 (TIMESTAMP,DEVICE,READING)
2022.05.13 21:31:00.171 5: DbRep DBRepPow -> Primary Key used in fhem.current: 1 (DEVICE,READING)
2022.05.13 21:31:00.172 5: DbRep DBRepPow -> data to insert Timestamp: 2022-05-13 21:31:00, Device: shelly_plug_s_df2674, Type: manual, Event: manual, Reading: power, Value: 0, Unit:
2022.05.13 21:31:00.172 4: DbRep DBRepPow - SQL prepare: INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)
2022.05.13 21:31:00.174 4: DbRep DBRepPow - begin transaction
2022.05.13 21:31:00.180 4: DbRep DBRepPow - transaction committed
2022.05.13 21:31:00.181 4: DbRep DBRepPow - Inserted into fhem.history: 2022-05-13 21:31:00, shelly_plug_s_df2674, manual, manual, power, 0,
2022.05.13 21:31:00.191 5: DbRep DBRepPow - BlockingCall PID "12729" finished

...wie immer erstmal wieder kein PERL Error 

Ich beobachte...   provoziere nochmal mit Restart FHEM und auch kompletter Reboot    ...mal sehen

Die Frage ist, ob ich gleich auf deinen Vorschlag " CommandSet(undef, "DBRepPow insert $today,05:29:00,0") " umsteige in der Hoffnung, dass die PERL Warning wegbleibt.
Andererseits ist ein soches Problem besonders in komplexeren Szenarien doof, wenn man die Datenbankeinträge ohne Inhalt zu spät bemerkt. Insofern ist es interessant die Ursache zu finden/erkennen.

[RalfRog]

Nach einem versehentlichen Shutdown gestern Abend ist es heute morgen wieder zum dem Effekt mit "leeren" Datenbankeinträgen gekommen. Heute Abend war es allerdings wieder ok.
Hier das Logfile:

Code: [Auswählen]

2022.05.15 05:29:00.014 5: DbRep DBRepPow - all: 2022-05-15,05:29:00,0, dev: shelly_plug_s_df2674, reading: power, value: 0
2022.05.15 05:29:00.016 1: PERL WARNING: Use of uninitialized value in substr at ./FHEM/93_DbRep.pm line 967.
2022.05.15 05:29:00.016 3: eval: my $SELF=   $evalSpecials->{'%SELF'};{ fhem("set DBRepPow insert $today,05:29:00,0") }
2022.05.15 05:29:00.017 1: PERL WARNING: Use of uninitialized value in substr at ./FHEM/93_DbRep.pm line 968.
2022.05.15 05:29:00.018 3: eval: my $SELF=   $evalSpecials->{'%SELF'};{ fhem("set DBRepPow insert $today,05:29:00,0") }
2022.05.15 05:29:00.018 1: PERL WARNING: Use of uninitialized value in substr at ./FHEM/93_DbRep.pm line 969.
2022.05.15 05:29:00.019 3: eval: my $SELF=   $evalSpecials->{'%SELF'};{ fhem("set DBRepPow insert $today,05:29:00,0") }
2022.05.15 05:29:00.019 1: PERL WARNING: Use of uninitialized value in substr at ./FHEM/93_DbRep.pm line 970.
2022.05.15 05:29:00.020 3: eval: my $SELF=   $evalSpecials->{'%SELF'};{ fhem("set DBRepPow insert $today,05:29:00,0") }
2022.05.15 05:29:00.021 3: DbRep DBRepPow - get initial structure information of database "fhem", remaining attempts: 3
2022.05.15 05:29:00.023 3: DbRep DBRepPow - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2022.05.15 05:29:00.059 5: DbRep DBRepPow - start BlockingCall with PID "3384"
2022.05.15 05:29:00.105 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.15 05:29:00.119 4: DbRep DBRepPow - Oldest timestamp determined: 2019-02-17 12:00:00
2022.05.15 05:29:00.131 4: DbRep DBRepPow - Encoding of database determined: utf8
2022.05.15 05:29:00.135 3: DbRep DBRepPow - Index Report_Idx exists. Check ok
2022.05.15 05:29:00.139 4: DbRep DBRepPow - Grants determined: SELECT,FILE,DELETE,INSERT,UPDATE
2022.05.15 05:29:00.152 5: DbRep DBRepPow - getInitData finished PID "3384"
2022.05.15 05:29:00.153 3: DbRep DBRepPow - Initial data information retrieved - total time used: 0.0364 seconds
2022.05.15 05:29:00.170 3: DbRep DBRepPow - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2022.05.15 05:29:00.179 4: DbRep DBRepPow - -------- New selection ---------
2022.05.15 05:29:00.180 4: DbRep DBRepPow - Command: insert 2022-05-15 05:29:00,,,,
2022.05.15 05:29:00.198 5: DbRep DBRepPow - BlockingCall with PID "3386" started
2022.05.15 05:29:00.234 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.15 05:29:00.296 5: DbRep DBRepPow -> Primary Key used in fhem.history: 1 (TIMESTAMP,DEVICE,READING)
2022.05.15 05:29:00.297 5: DbRep DBRepPow -> Primary Key used in fhem.current: 1 (DEVICE,READING)
2022.05.15 05:29:00.297 5: DbRep DBRepPow -> data to insert Timestamp: 2022-05-15 05:29:00, Device: , Type: manual, Event: manual, Reading: , Value: , Unit:
2022.05.15 05:29:00.298 4: DbRep DBRepPow - SQL prepare: INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)
2022.05.15 05:29:00.299 4: DbRep DBRepPow - begin transaction
2022.05.15 05:29:00.305 4: DbRep DBRepPow - transaction committed
2022.05.15 05:29:00.307 4: DbRep DBRepPow - Inserted into fhem.history: 2022-05-15 05:29:00, , manual, manual, , ,
2022.05.15 05:29:00.318 5: DbRep DBRepPow - BlockingCall PID "3386" finished

Ich lese im ersten Logeintrag um "05:29:00.014", dass die Variablen ($prop, $i_device, $i_reading, $i_value) Werte haben die gut aussehen 
Aber was geht dann in Zeile 967ff und eval schief...   und auch nur manchmal... 

[DS_Starter]

Ich lese im ersten Logeintrag um "05:29:00.014", dass die Variablen ($prop, $i_device, $i_reading, $i_value) Werte haben die gut aussehen 

Da hast völlig Recht. Aber ich habe vllt. eine Idee. Möglicherweise sind bestimmte Hash-Werte nicht gesetzt die aus DbLog übernommen werden. Das passiert beim ersten DB-Connect. Jetzt kann es sein, dass du das Device auch für andere Operationen verwendest. Dabei werden die Hash-Werte initial übernommen. Das würde die Unregelmäßigkeit des Fehlers erklären.

Um meine Vermutung zu verifizieren ändere doch bitte mal die Logzeile in:

Code: [Auswählen]

Log3 ($name, 5, "DbRep $name - all: $prop, dev_colsize: $hash->{HELPER}{DBREPCOL}{DEVICE}), reading_colsize: $hash->{HELPER}{DBREPCOL}{READING}, value_colsize: $hash->{HELPER}{DBREPCOL}{VALUE}");

Falls ich richtig liege weiß ich wo ich ansetzen kann um das Problem zu fixen.

Grüße,
Heiko

[RalfRog]

Hallo
Habe die Codezeile zusätzlich eingefügt und die vorherige noch davor stehen lassen.

Code: [Auswählen]

964       $hash->{LASTCMD} = $prop ? "$opt $prop" : "$opt";
965 Log3 ($name, 5, "DbRep $name - all: $prop, dev: $i_device, reading: $i_reading, value: $i_value"); # 2 Zeilen zum Debuggen da einige DB Eintraege verkorkst
966 Log3 ($name, 5, "DbRep $name - all: $prop, dev_colsize: $hash->{HELPER}{DBREPCOL}{DEVICE}), reading_colsize: $hash->{HELPER}{DBREPCOL}{READING}, value_colsize: $hash->{HELPER}{DBREPCOL}{VALUE}");
967       if ($dbmodel ne 'SQLITE') {                                                                               # Daten auf maximale Länge (entsprechend der Feldl$
968           $i_device  = substr($i_device,  0, $hash->{HELPER}{DBREPCOL}{DEVICE});
969           $i_reading = substr($i_reading, 0, $hash->{HELPER}{DBREPCOL}{READING});
970           $i_value   = substr($i_value,   0, $hash->{HELPER}{DBREPCOL}{VALUE});
971           $i_unit    = substr($i_unit,    0, $hash->{HELPER}{DBREPCOL}{UNIT});
972       }

dann "reload 93_DbRep" und Test des AT über execNow. Ergebnis im Log sieht gut aus und ist parat für den Problemfall:

Code: [Auswählen]

2022.05.16 12:40:01.212 5: DbRep DBRepPow - all: 2022-05-16,21:31:00,0, dev: shelly_plug_s_df2674, reading: power, value: 0
2022.05.16 12:40:01.213 5: DbRep DBRepPow - all: 2022-05-16,21:31:00,0, dev_colsize: 64), reading_colsize: 64, value_colsize: 128
2022.05.16 12:40:01.227 4: DbRep DBRepPow - -------- New selection ---------
2022.05.16 12:40:01.228 4: DbRep DBRepPow - Command: insert 2022-05-16 21:31:00,shelly_plug_s_df2674,power,0,
2022.05.16 12:40:01.250 5: DbRep DBRepPow - BlockingCall with PID "14960" started
2022.05.16 12:40:01.519 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.16 12:40:01.587 5: DbRep DBRepPow -> Primary Key used in fhem.history: 1 (TIMESTAMP,DEVICE,READING)
2022.05.16 12:40:01.588 5: DbRep DBRepPow -> Primary Key used in fhem.current: 1 (DEVICE,READING)
2022.05.16 12:40:01.589 5: DbRep DBRepPow -> data to insert Timestamp: 2022-05-16 21:31:00, Device: shelly_plug_s_df2674, Type: manual, Event: manual, Reading: power, Value: 0, Unit:
2022.05.16 12:40:01.589 4: DbRep DBRepPow - SQL prepare: INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)
2022.05.16 12:40:01.592 4: DbRep DBRepPow - begin transaction
2022.05.16 12:40:01.604 4: DbRep DBRepPow - transaction committed
2022.05.16 12:40:01.607 4: DbRep DBRepPow - Inserted into fhem.history: 2022-05-16 21:31:00, shelly_plug_s_df2674, manual, manual, power, 0,
2022.05.16 12:40:01.665 5: DbRep DBRepPow - BlockingCall PID "14960" finished

Werde jetzt einen Restart von  FHEM veranlassen um die Warning heute Abend zu provozieren.

Hinweis:
Das Device Anfang Mai für die beiden AT um 5:29 und 21:31 Uhr verwendet um per insert die "0" in die Datenbank zu schreiben.
Letzte Woche lief es ja morgens sauber und bis ich es gemerkt habe dreimal in Folge Abends falsch (zwischendurch kein Restart FHEM oder Reboot).

Habe mal die FHEM-Logs von diesem Jahr durch gegrept. Keine PERL Warnings mit "93_DbLog.pm"

[DS_Starter]

Hallo Ralf, @all,

ich habe das insert Kommando intern umgebaut um die identifizierte potentielle Fehlerquelle zu beseitigen.
Mit der neuen Version dürfte nach meinem Ermessen dein Problemfall nicht mehr auftreten.

Weiterhin habe ich den insert Setter erweitert (siehe den Request von Bernd in #1647).
Es ist nun möglich im insert Kommando das Device, Reading direkt mitzugeben. Eventuell per Attribut device, reading gesetzte Werte werden in diesem Fall übersteuert.

insert <Datum>,<Zeit>,<Value>,[<Unit>],[<Device>],[<Reading>]
Manuelles Einfügen eines Datensatzes in die Tabelle "history". Obligatorisch sind Eingabewerte für Datum, Zeit und Value. Die Werte für die DB-Felder TYPE bzw. EVENT werden mit "manual" gefüllt.
Werden Device, Reading nicht gesetzt, werden diese Werte aus den entsprechenden Attributen device bzw. reading genommen.

Hinweis:
Nicht belegte Felder innerhalb des insert Kommandos müssen innerhalb des Strings in "," eingeschlossen werden.

    Beispiel:
    set <name> insert 2016-08-01,23:00:09,12.03,kW
    set <name> insert 2021-02-02,10:50:00,value with space
    set <name> insert 2022-05-16,10:55:00,1800,,SMA_Wechselrichter,etotal
    set <name> insert 2022-05-16,10:55:00,1800,,,etotal


Die neue Version legt zunächst in meinem contrib zum Test.
Zum Download in der FHEMWEB Kommandozeile inklusive der Anführungszeichen angeben und danach FHEM restarten:

Code: [Auswählen]

"wget -qO ./FHEM/93_DbRep.pm https://svn.fhem.de/fhem/trunk/fhem/contrib/DS_Starter/93_DbRep.pm"

LG

[RalfRog]

.....
ich habe das insert Kommando intern umgebaut um die identifizierte potentielle Fehlerquelle zu beseitigen.

Super ich werde es ausprobieren.
Dein Vorschlag für die neue Logzeile ging leider schief. Problem Value in Concatenation. Der erste zusätzliche Logentrag läuft natürlich noch richtig.

Code: [Auswählen]

2022.05.16 21:31:00.012 5: DbRep DBRepPow - all: 2022-05-16,21:31:00,0, dev: shelly_plug_s_df2674, reading: power, value: 0
2022.05.16 21:31:00.013 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/93_DbRep.pm line 966.
2022.05.16 21:31:00.014 3: eval: my $SELF=   $evalSpecials->{'%SELF'};{ fhem("set DBRepPow insert $today,21:31:00,0") }

Spielt aber keine Rolle. Neue Version wird getestet :-)

[DS_Starter]

Dein Vorschlag für die neue Logzeile ging leider schief.....

Eigentlich nicht.  Da der "uninitialized value" Fehler nun bei dem Log3 Befehl auftritt bedeutet es dass die Hash Values tatsächlich nicht gesetzt sind. Wir können nun optimistisch sein dass die neue Version das Problem behebt.

[RalfRog]

Eigentlich nicht.  Da der "uninitialized value" Fehler nun bei dem Log3 Befehl auftritt...

Auch wieder wahr 

Der erste Aufruf heute morgen war sauber. Datenbank korrekt befüllt (lasse Verbose 5 weiter mitlaufen).

Mal sehen was Bernd zu berichten hat wenn er den "insert" verwendet.

Danke tolle Arbeit.

Der Vollständigkeit halber hie noch der Log:

Code: [Auswählen]

2022.05.17 05:29:00.012 3: DbRep DBRepPow - get initial structure information of database "fhem", remaining attempts: 3
2022.05.17 05:29:00.014 3: DbRep DBRepPow - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2022.05.17 05:29:00.055 5: DbRep DBRepPow - start BlockingCall with PID "11671"
2022.05.17 05:29:00.098 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.17 05:29:00.112 4: DbRep DBRepPow - Oldest timestamp determined: 2019-02-17 12:00:00
2022.05.17 05:29:00.122 4: DbRep DBRepPow - Encoding of database determined: utf8
2022.05.17 05:29:00.126 3: DbRep DBRepPow - Index Report_Idx exists. Check ok
2022.05.17 05:29:00.131 4: DbRep DBRepPow - Grants determined: DELETE,UPDATE,INSERT,SELECT,FILE
2022.05.17 05:29:00.143 5: DbRep DBRepPow - getInitData finished PID "11671"
2022.05.17 05:29:00.144 3: DbRep DBRepPow - Initial data information retrieved - total time used: 0.0343 seconds
2022.05.17 05:29:00.164 3: DbRep DBRepPow - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2022.05.17 05:29:00.173 4: DbRep DBRepPow - -------- New selection ---------
2022.05.17 05:29:00.174 4: DbRep DBRepPow - Command: insert 2022-05-17 05:29:00,shelly_plug_s_df2674,power,0,
2022.05.17 05:29:00.194 5: DbRep DBRepPow - BlockingCall with PID "11673" started
2022.05.17 05:29:00.228 4: DbRep DBRepPow - Database connect - user: fhemuser, UTF-8 option set: yes
2022.05.17 05:29:00.286 5: DbRep DBRepPow -> Primary Key used in fhem.history: 1 (TIMESTAMP,DEVICE,READING)
2022.05.17 05:29:00.286 5: DbRep DBRepPow -> Primary Key used in fhem.current: 1 (DEVICE,READING)
2022.05.17 05:29:00.287 5: DbRep DBRepPow -> data to insert Timestamp: 2022-05-17 05:29:00, Device: shelly_plug_s_df2674, Type: manual, Event: manual, Reading: power, Value: 0, Unit:
2022.05.17 05:29:00.288 4: DbRep DBRepPow - SQL prepare: INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)
2022.05.17 05:29:00.289 4: DbRep DBRepPow - begin transaction
2022.05.17 05:29:00.296 4: DbRep DBRepPow - transaction committed
2022.05.17 05:29:00.297 4: DbRep DBRepPow - Inserted into fhem.history: 2022-05-17 05:29:00, shelly_plug_s_df2674, manual, manual, power, 0,
2022.05.17 05:29:00.308 5: DbRep DBRepPow - BlockingCall PID "11673" finished


[DS_Starter]

Danke Ralf für die Info. Sieht ja schon gut aus 

[frober]

Mal sehen was Bernd zu berichten hat wenn er den "insert" verwendet.

Ich habe momentan wenig Zeit. Mal schauen ob ich diese Woche wenigstens alles einrichten kann...

@Heiko danke für die schnelle Umsetzung 

Melde mich wenn ich erste Ergebnisse habe...

[DS_Starter]

@Bernd, solltest du bis Donnerstag Abend Ergebnisse haben, kann ich die neue Modulversion noch vor meinem Urlaub einchecken und per Update zur Verfügung stellen.

LG

[frober]

@Bernd, solltest du bis Donnerstag Abend Ergebnisse haben, kann ich die neue Modulversion noch vor meinem Urlaub einchecken und per Update zur Verfügung stellen.

LG

Da du mich so lieb darum gebeten hast, habe ich gleich getestet. 
Spaß, bin ungeplant früher nach Hause gekommen...

Funktioniert wie erwartet...ich musste nur mein Notify etwas überarbeiten -> $EVTPART letztes Zeichen entfernen (status:)

Erste Zeile stammt von insert.

Code: [Auswählen]

setstate fetchROWs 2022-05-17 16:46:00 2022-05-17_16-43-47__1__MYSENSOR_3__status4 off
setstate fetchROWs 2022-05-17 16:46:00 2022-05-17_16-43-47__1__MYSENSOR_3__status4_1 on


Zur Vollständigkeit (mit Debugausgabe):

Code: [Auswählen]

defmod n_MYSENSOR_Plot notify MYSENSOR_(2|3):(status(1|2|3|4)|status):.on {my $e = chop($EVTPART0);; my $t = ReadingsTimestamp($NAME,$EVTPART0,'undef');; my @T = split(/ /, $t);; Log3 ('n_MYSENSOR_Plot', 1, "$NAME, $EVTPART0, $e, $t, $T[0], $T[1]");; fhem("set insertDB insert $T[0],$T[1],off,,$NAME,$EVTPART0")}

und die insertDB:

Code: [Auswählen]

defmod insertDB DbRep logdb
attr insertDB allowDeletion 1
attr insertDB fastStart 1
attr insertDB room System->DbLog
attr insertDB showproctime 1
attr insertDB verbose 1

PS: Fhem upgedatet, also direkt nach einem Neustart getestet...

Grüße Bernd

[DS_Starter]

Prima Bernd. 

Ich habe die neue Version eingescheckt und ist ab morgen früh im Update enthalten.

LG