DBLog und DBRep Problem (SQLite)

[DS_Starter]

Und wie sieht es mit SVGcache im FHEMWEB aus ?
Im FHEMWEB schon set ... clearSvgCache probiert ?

[rudolfkoenig]

Laut Stefan (https://forum.fhem.de/index.php/topic,98517.msg919556.html#msg919556) liefert bereits "get dblog ..." die falschen Daten.
Das Problem muss im DbLog-Modul, DB-Interface oder DB sein.

[DS_Starter]

Danke Rudi,  Stefans Ergebnisse dazu sind teils widersprüchlich bzw. nicht nachvollziehbar. Ich bräuchte irgendeinen brauchbaren Ansatzpunkt.
Gehe gerne jeder Spur nach, aber brauch irgendeinen Hebel, ein Statement was falsche Werte liefert o.ä.

EDIT: Stefan hat DbLog / SVG bis auf den Stand Anfang 2018 zurück gerollt ohne Änderung. Wenn ein Fehler in den Modulen vorliegt, muß der aber schon sehr lange drin sein. Dann ist es aber auch wieder unwahrscheinlich dass es erst jetzt jemanden auffällt. Also so richtig bekomme ich da keinen Zusammenhang hergestellt.

[DS_Starter]

@Stefan, doch Trace liefert jede Menge:

z.B.

traceFlag     DBD
traceLevel   5

Code Auswählen Erweitern


2   <- execute= ( 1 ) [1 items] at /usr/lib/x86_64-linux-gnu/perl5/5.24/DBI.pm line 2020 via  at ./FHEM/93_DbLog.pm line 2094
2   -> execute for DBD::SQLite::st (DBI::st=HASH(0x5653c139aa20)~INNER '2019-03-16 18:25:01' 'USV' 'NUT' 'state: OL' 'state' 'OL' '') thr#5653b5937010
sqlite trace: bind into 0x5653c2396fe0: 1 => 2019-03-16 18:25:01 (0) pos 0 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 2 => USV (0) pos 2 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 3 => NUT (0) pos 4 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 4 => state: OL (0) pos 6 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 5 => state (0) pos 8 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 6 => OL (0) pos 10 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 7 =>  (0) pos 12 at dbdimp.c line 1442
sqlite trace: executing INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?) at dbdimp.c line 923
sqlite trace: bind 0 type 5 as 2019-03-16 18:25:01 at dbdimp.c line 940
sqlite trace: bind 1 type 5 as USV at dbdimp.c line 940
sqlite trace: bind 2 type 5 as NUT at dbdimp.c line 940
sqlite trace: bind 3 type 5 as state: OL at dbdimp.c line 940
sqlite trace: bind 4 type 5 as state at dbdimp.c line 940
sqlite trace: bind 5 type 5 as OL at dbdimp.c line 940
sqlite trace: bind 6 type 5 as  at dbdimp.c line 940
sqlite trace: Execute returned 0 cols at dbdimp.c line 1036
2   <- execute= ( 1 ) [1 items] at /usr/lib/x86_64-linux-gnu/perl5/5.24/DBI.pm line 2020 via  at ./FHEM/93_DbLog.pm line 2094
2   -> execute for DBD::SQLite::st (DBI::st=HASH(0x5653c139aa20)~INNER '2019-03-16 18:25:01' 'USV' 'NUT' 'current: 238.0' 'current' '238.0' '') thr#5653b5937010
sqlite trace: bind into 0x5653c2396fe0: 1 => 2019-03-16 18:25:01 (0) pos 0 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 2 => USV (0) pos 2 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 3 => NUT (0) pos 4 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 4 => current: 238.0 (0) pos 6 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 5 => current (0) pos 8 at dbdimp.c line 1442
sqlite trace: bind into 0x5653c2396fe0: 6 => 238.0 (0) pos 10 at dbdimp.c line 1442


[stefanru]

Hmmm,

bei mir gings jetzt erst nachdem ich den async modus aus hatte und durchgestartet.
Habs nochmal verifiziert, mit async auf 1 wird nichts getraced.

Also mit async 0 kommt jetzt was.

Hier mal der Aufbau des SVG Plots mit traceLevel 7 und traceFlag all, ich hoffe du kannst da was erkennen.

Code Auswählen Erweitern


    -> ping for DBD::SQLite::db (DBI::db=HASH(0x66f6900)~0x66f6828) thr#1d16008
    >> sqlite_db_filename DISPATCH (DBI::db=HASH(0x66f6828) rc1/2 @1 g2 ima4 pid#31086) at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 241 via  at ./FHEM/93_DbLog.pm line 2629
1   -> sqlite_db_filename for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER) thr#1d16008
1   <- sqlite_db_filename= ( '/opt/fhem/fhem.db' ) [1 items] at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 241 via  at ./FHEM/93_DbLog.pm line 2629
    >> FETCH       DISPATCH (DBI::db=HASH(0x66f6828) rc1/2 @2 g2 ima404 pid#31086) at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 245 via  at ./FHEM/93_DbLog.pm line 2629
1   -> FETCH for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER 'Active') thr#1d16008
    .. FETCH DBI::db=HASH(0x66f6828) 'Active' = 1
1   <- FETCH= ( 1 ) [1 items] at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 245 via  at ./FHEM/93_DbLog.pm line 2629
    <- ping= ( 1 ) [1 items] at ./FHEM/93_DbLog.pm line 2629 via  at fhem.pl line 3695
    -> disconnect for DBD::SQLite::db (DBI::db=HASH(0x66f6900)~0x66f6828) thr#1d16008
sqlite trace: Closing DB at dbdimp.c line 640
sqlite trace: rc = 0 at dbdimp.c line 642
    <- disconnect= ( 1 ) [1 items] at ./FHEM/93_DbLog.pm line 2637 via  at fhem.pl line 3695
    -> DESTROY for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER) thr#1d16008
    <- DESTROY= ( undef ) [1 items] at ./FHEM/93_DbLog.pm line 2643 via  at ./FHEM/93_DbLog.pm line 2643
2019.03.16 18:45:43 1: PERL WARNING: Use of uninitialized value $data{"min2"} in concatenation (.) or string at (eval 5547) line 1.
2019.03.16 18:45:43 3: eval: { "Heizung Min $data{min2}, Max $data{max2}, Last $data{currval2}" }
2019.03.16 18:45:43 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at (eval 5547) line 1.
2019.03.16 18:45:43 3: eval: { "Heizung Min $data{min2}, Max $data{max2}, Last $data{currval2}" }


Die Perl Warnings kommen nur weil ich nur noch den graph drin habe der die Probleme macht.

Ich hoffe das hilft, wenn nicht sag mir was ich noch schauen kann. Bin ziemlich ratlos.
Kann dir auch anbieten per TeamViewer oder so auf das System zu schauen wenn das hilft.

Gruß,
Stefan

[DS_Starter]

Bei mir gehts mit asynch = 1 , aber soll jetzt egal sein.

Naja, da sehe ich auch nichts 
Versuche doch mal Ausschriften mit Selects zu finden. Es kommt ja im Prinzip darauf an dass die richtigen Statements gemäß SVG Vorgabe abgesetzt werden bzw. die richtigen Daten geliefert werden.
Wenn du ein Beispielstatement hättest welches nicht die richtigen Daten zurückliefert und was ich dann bei mir nachstellen könnte wäre schon etwas geholfen.

TeamViewer  können wir gerne mal machen, aber nicht am WE ... meine bessere Hälfte kündigt mir sonst 

[stefanru]

Ok,

ich bekomme aber kein SQL zurück mit traceLevel 7 und traceFlag all?
Dachte da würde so etwas kommen.

Ich mache jetzt nochmal mit Verbose 5 dazu.
Das SQL vom Verbose ist aber leider in Ordnung wenn ich es an die Datenbank schicke.
Ansonsten weiß ich nicht wie ich dir das liefern soll was du sehen willst.

Code Auswählen Erweitern








2019.03.16 19:03:45 5: DbLog logdb: Table current present : 0 (0 = not present or no content)
    -> ping for DBD::SQLite::db (DBI::db=HASH(0x66f6900)~0x66f6828) thr#1d16008
    >> sqlite_db_filename DISPATCH (DBI::db=HASH(0x66f6828) rc1/2 @1 g2 ima4 pid#5188) at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 241 via  at ./FHEM/93_DbLog.pm line 2629
1   -> sqlite_db_filename for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER) thr#1d16008
1   <- sqlite_db_filename= ( '/opt/fhem/fhem.db' ) [1 items] at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 241 via  at ./FHEM/93_DbLog.pm line 2629
    >> FETCH       DISPATCH (DBI::db=HASH(0x66f6828) rc1/2 @2 g2 ima404 pid#5188) at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 245 via  at ./FHEM/93_DbLog.pm line 2629
1   -> FETCH for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER 'Active') thr#1d16008
    .. FETCH DBI::db=HASH(0x66f6828) 'Active' = 1
1   <- FETCH= ( 1 ) [1 items] at /usr/lib/arm-linux-gnueabihf/perl5/5.24/DBD/SQLite.pm line 245 via  at ./FHEM/93_DbLog.pm line 2629
    <- ping= ( 1 ) [1 items] at ./FHEM/93_DbLog.pm line 2629 via  at fhem.pl line 3695
    -> disconnect for DBD::SQLite::db (DBI::db=HASH(0x66f6900)~0x66f6828) thr#1d16008
sqlite trace: Closing DB at dbdimp.c line 640
sqlite trace: rc = 0 at dbdimp.c line 642
    <- disconnect= ( 1 ) [1 items] at ./FHEM/93_DbLog.pm line 2637 via  at fhem.pl line 3695
    -> DESTROY for DBD::SQLite::db (DBI::db=HASH(0x66f6828)~INNER) thr#1d16008
    <- DESTROY= ( undef ) [1 items] at ./FHEM/93_DbLog.pm line 2643 via  at ./FHEM/93_DbLog.pm line 2643
2019.03.16 19:03:46 4: Processing Statement: SELECT
                  TIMESTAMP,
                  DEVICE,
                  READING,
                  VALUE
                   FROM history WHERE 1=1 AND DEVICE  = 'ESPEasy_Heizungs_Pumpe_Relay' AND READING = 'state' AND TIMESTAMP >= '2019-03-16 00:00:00' AND TIMESTAMP <= '2019-03-17 00:00:00' ORDER BY TIMESTAMP
2019.03.16 19:03:46 4: Processing Statement: SELECT
                  TIMESTAMP,
                  DEVICE,
                  READING,
                  VALUE
                   FROM history WHERE 1=1 AND DEVICE  = 'TempAussen' AND READING = 'state' AND TIMESTAMP >= '2019-03-16 00:00:00' AND TIMESTAMP <= '2019-03-17 00:00:00' ORDER BY TIMESTAMP


Wie gesagt TeamViewer kann ich anbieten. Klar muss nicht am WE sein.

Ich danke dir auf jedenfall mal für deine Mühe. Ist echt ein drecks Problem.

Gruß,
Stefan

[stefanru]

Ok ich glaub jetzt hab ich was.

Im Anhang ein Log vom Preprocessed output mit Verbose 5, traceLevel 7 und traceFlag all.
Man sieht dass die falschen Daten zurück kommen.
Sie sollten nur von heute 16.03. sein es kommt aber viel mehr, hier z.B. auch vom 09.03.:
Select war dieses für heute:

Code Auswählen Erweitern

sqlite trace: executing SELECT
                  TIMESTAMP,
                  DEVICE,
                  READING,
                  VALUE
                   FROM history WHERE 1=1 AND DEVICE  = 'ESPEasy_Heizungs_Pumpe_Relay' AND READING = 'state' AND TIMESTAMP >= '2019-03-16 00:00:00' AND TIMESTAMP <= '2019-03-17 00:00:00' ORDER BY TIMESTAMP at dbdimp.c line 923

Im Log erscheint aber auch:

Code Auswählen Erweitern


    -> fetch for DBD::SQLite::st (DBI::st=HASH(0x6e84788)~0x6f48870) thr#1d16008
sqlite trace: numFields == 4, nrow == 3311 at dbdimp.c line 1110
sqlite trace: fetch column 0 as text at dbdimp.c line 1160
sqlite trace: fetch column 1 as text at dbdimp.c line 1160
sqlite trace: fetch column 2 as text at dbdimp.c line 1160
sqlite trace: fetch column 3 as text at dbdimp.c line 1160
    <- fetch= ( [ '2019-03-09 00:50:00' 'ESPEasy_Warmwasserpumpe_Relay' 'state' 'off' ] ) [1 items] row3312 at ./FHEM/93_DbLog.pm line 2804 via  at fhem.pl line 3695


Gruß,
Stefan

[DS_Starter]

Na das ist doch mal ein Hinweis.

Vorschlag:
Mach doch mal bitte mit DbRep einen Export der Daten des relevanten Devices von zum Beispiel der letzten Woche. Das CSV-File kannst du mir irgendwie zukommen lassen, zur Not per Email je nach Größe. Dann noch deine exakte SVG-Definition.
Die Daten kann ich dann bei mir importieren und versuchen das Problem nachzustellen wenn du mir genau sagst was du wie angibst. Dann kommen wir vllt. weiter.

[DS_Starter]

Also jetzt habe ich mir mal das Tracefile angeschaut.
Ich kann es eigentlich nicht glauben, aber es sieht tatsächlich so aus dass die DB trotz eines korrekten Select-Statements auch Daten ausserhalb des angeforderten Bereiches liefert. 
Sowas hab ich noch nie gesehen und ich würde es befürworten wenn sich jemand anderes das File auch nochmal anschaut.

@Stefan, Als Vergleichtest wäre mein Vorschlag dann auch geeignet.

[stefanru]

Für mich sieht das auch so aus.
Das seltsame ist das macht sie nur in FHEM.

Führe ich genau das select mit meinem phpLiteAdmin aus kommt genau das richtige.
Insofern habe ich irgendwo doch FHEM in Verdacht.

Gruß,
Stefan

[DS_Starter]

Nur wüßte ich nicht wo ich da suchen sollte, denn das Modul kann nicht mehr tun als das korrekte Statement der Datenbank bzw. Datenbankschnittstelle zu übergeben.
Und das passiert ja. Da könnte ich im Modul nichts ändern.
Jetzt würde ich der Vermutung von Rudi folgen und evtl. einen Bug im Perl-Datenbanktreiber vermuten/unterstellen. Denn phpLiteAdmin verwendet diesen Treiber ganz bestimmt nicht.
Wenn du mir die Daten senden würdest, könnte ich die auch mal in MySQL importieren und schauen wie es damit aussieht.

[stefanru]

Ok, Perl DB Treiber könnte ich mir vorstellen.
Habe beim Raspberry ein update gemacht.
Könnte zeitlich zum Auftreten des Problems passen.

Ja die Daten bekommst du noch. Bin dran...

Gruß,
Stefan

[stefanru]

Ok,
hab den Export gemacht und es hat einwandfrei geklappt.
Was mich eigentlich wundert, hätte der nicht auch Probleme mit der Zeit haben müssen wenn es am Perl DB Treiber liegt.
Er Hat aber genau die Sätze selektiert die ich wollte... Sehr komisch.
Im Anhang hängt das CSV.

Hier das list eine Plots der den Fehler Zeigt:

Code Auswählen Erweitern

Internals:
   DEF        logdb:SVG_logdb_1:HISTORY
   FUUID      5c8d2e37-f33f-0c45-5aaf-921004795c3c04b8
   GPLOTFILE  SVG_logdb_1
   LOGDEVICE  logdb
   LOGFILE    HISTORY
   NAME       SVG_logdb_1
   NOTIFYDEV  global
   NR         1190
   STATE      initialized
   TYPE       SVG
Attributes:

Und die Gplot Datei ist im Anhang.
Genauso wie ein Bild von meinem Gplot.

Gruß und Danke,
Stefan

[DS_Starter]

Da hast du auch wieder recht. Aber hast ja selbst gesehen dass der Select auf die DB korrekt war.
Sehr undurchsichtig.....
Ich werde die Daten importieren und dann sehen wir weiter.
Vermutlich gehts aber erst morgen weiter ...

Grüße
Heiko