Autor Thema: DbLog - Cache, MemCache und mysql Fehler  (Gelesen 463 mal)

Offline SusisStrolch

  • Full Member
  • ***
  • Beiträge: 242
DbLog - Cache, MemCache und mysql Fehler
« am: 02 Dezember 2022, 18:09:30 »
Erst mal vorab - ich bin mit DbLog und DbRep höchst zufrieden.

Umgebung:
- fhem auf einer CuBox
- MariaDB10 auf Synology
- Struktur der history Tabelle:
    TIMESTAMP: timestamp(2)
    DEVICE: varchar(64), utf8_bin
    TYPE: varchar(64), utf8_bin
    EVENT: varchar(512), utf_8bin
    READING: varchar(64), utf8_bin
    VALUE: varchar(128), utf8_bin
    UNIT: varchar(64), utf8_bin
Und hier mein Problemchen:
Mein EMS_Boiler schickt ab und an (über MQTT) ein ungültiges Zeichen (0xFC) im Event.
Dies führt dazu, dass beim Schreiben in die Datenbank ein Fehler auftritt:
2022.12.02 00:10:30.444 5: DbLog logdb -> Start DbLog_PushAsync
2022.12.02 00:10:30.445 5: DbLog logdb -> DbLogType is: Current/History
2022.12.02 00:10:30.457 4: DbLog logdb -> AutoCommit mode: ON, Transaction mode: ON
2022.12.02 00:10:30.457 4: DbLog logdb -> Insert mode: Array
2022.12.02 00:10:30.496 4: DbLog logdb -> Primary Key used in history: none
2022.12.02 00:10:30.497 4: DbLog logdb -> Primary Key used in current: DEVICE,READING
...
2022.12.02 00:10:30.506 5: DbLog logdb -> processing event Timestamp: 2022-12-02 00:10:06, Device: EMS_Boiler, Type: MQTT2_DEVICE, Event: serviceCode: 0<FC>, Reading: serviceCode, Value: 0<FC>, Unit:
2022.12.02 00:10:30.506 5: DbLog logdb -> processing event Timestamp: 2022-12-02 00:10:06, Device: Verbrauch.Homeoffice, Type: EC3000, Event: power: 167.075975574276, Reading: power, Value: 167.075975574276, Unit:
2022.12.02 00:10:30.506 5: DbLog logdb -> processing event Timestamp: 2022-12-02 00:10:06, Device: EMS_Boiler, Type: MQTT2_DEVICE, Event: serviceCode: 0Y, Reading: serviceCode, Value: 0Y, Unit:
...
2022.12.02 00:10:31.556 2: DbLog logdb -> Error table history - DBD::mysql::st execute_array failed: executing 54 generated 1 errors at ./FHEM/93_DbLog.pm line 2904.
2022.12.02 00:10:31.602 5: DbLog logdb -> DbLog_PushAsync finished
2022.12.02 00:10:31.657 5: DbLog logdb -> Start DbLog_PushAsyncDone
2022.12.02 00:10:31.673 5: DbLog logdb -> DbLog_PushAsyncDone finished
Der weitere Effekt ist der, das der DbLog-Cache auf Grund des commit gelöscht wird, allerdings der MemCache unverändert bleibt und beim nächsten Commit genau das gleiche Problem auftritt.
Passiert das während einer längeren Abwesenheit sind die Daten fort (außer man betreibt DbLog im loglevel 5  ???)

Ja, ich kann diesen speziellen Fehler mit "DbLogValueFN" in der Griff bekommen.
Aber das Problem bleibt bestehen das bei einem Datenbank-Fehler der Cache verloren ist, jedoch der MemCache immer weiter anwächst.
Selbst ein "reopen" purged den MemCache nicht.

Was ich mir DbLog-seitig vorstelle wäre ein Enhancement, welches in einem derartigen Fehlerfall den MemCache (ähnlich dem cache_dblog_*) wegschreibt und den MemCache purged.


Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

Offline DS_Starter

  • Developer
  • Hero Member
  • ****
  • Beiträge: 8770
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #1 am: 02 Dezember 2022, 18:53:16 »
Guten Abend,

ich denke dein Problem kannst du mit dem Attr:

  useCharfilter = 1

beseitigen.
Ungeachtet dessen kannst du mit dem Attr

  commitMode = basic_ta:off

einstellen dass der Cache nicht innerhalb einer Transaktion (d.h. ganz oder garnicht) in die DB geschrieben wird, sondern jeder einzelne Event für sich.

Zitat
Was ich mir DbLog-seitig vorstelle wäre ein Enhancement, welches in einem derartigen Fehlerfall den MemCache (ähnlich dem cache_dblog_*) wegschreibt und den MemCache purged.
Das gibt es schon in Form des Attr cacheOverflowThreshold. Damit kann man einen worst case Fall vermeiden und die Daten zur späteren Verwendung in ein/mehrere Files schreiben lassen.

Ansonsten bist du gern eingeladen die Weiterentwicklung in dem Thread https://forum.fhem.de/index.php/topic,130588.0.html zu beachten und evtl. auch mitzuwirken falls es möglich ist (Fehlertoleranz).

LG,
Heiko
ESXi 6.5 @NUC6i5SYH mit FHEM auf Debian 10, DbLog/DbRep mit MariaDB auf VM
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Offline SusisStrolch

  • Full Member
  • ***
  • Beiträge: 242
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #2 am: 03 Dezember 2022, 11:35:39 »
Zitat
ich denke dein Problem kannst du mit dem Attr:

  useCharfilter = 1

beseitigen
Na, das ist mir ein wenig zu grob (zumindest auf Grund dessen, wie ich die Filterdefinition in der Beschreibung lese).
Da ich teilweise UTF-8 Daten bekomme denke ich eher an eine DbLogValueFN in der Form
    my $flags = Encode::FB_CROAK | Encode::LEAVE_SRC;
    my $void = eval {
        Encode::decode( 'utf-8', $EVENT, $flags );
    } || $IGNORE=1

Zitat
commitMode = basic_ta:off
Genau das wollte ich eigentlich aus Performance-Gründen vermeiden...

Zitat
Das gibt es schon in Form des Attr cacheOverflowThreshold. Damit kann man einen worst case Fall vermeiden und die Daten zur späteren Verwendung in ein/mehrere Files schreiben lassen.
Habe ich wohl überlesen...
Momentan (und suche ich noch die Ursache - ich verwende configDB) schmiert mir FHEM komplett ab wenn ich die geänderte Konfiguration speichern will.
Deshalb muss ich da einiges hinten anstellen.

Zitat
Ansonsten bist du gern eingeladen die Weiterentwicklung in dem Thread https://forum.fhem.de/index.php/topic,130588.0.html zu beachten und evtl. auch mitzuwirken falls es möglich ist (Fehlertoleranz).
Danke, da hatte ich schon ein Auge drauf geworfen, allerdings wollte ich erst die aktuellen Probleme lösen bevor ich einen Developer-Test starte.

Edit: Klarstellung wg "abschmieren"
« Letzte Änderung: 03 Dezember 2022, 11:42:42 von SusisStrolch »
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

Offline DS_Starter

  • Developer
  • Hero Member
  • ****
  • Beiträge: 8770
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #3 am: 03 Dezember 2022, 12:23:08 »
Wenn FHEM abschmiert steht doch bestimmt im Log ein etwaiger Hinweis auf die Ursache, oder ?
Das globale stacktrace könnte helfen.

Ich habe mir die Encode::FB_CROAK | Encode::LEAVE_SRC jetzt nicht genauer angeschaut, aber FB_CROAK riecht sehr nach "Abschuß" der Perl Schleife bei entsprechenden Bedingungen. FB_CROAK/LEAVE_SRC müssste auch geladen sein. Im DbLog selbst wird nur Encode::encode_utf8 geladen. Vllt. fehlt das ?

Bzgl. der neuen Version ... ich verwende nicht mehr base64 zur Datenserialisierung im Log-Vorgang.
Deswegen hatte ich die Hoffnung dein Problem damit "nebenbei" mit zu beseitigen und deswegen der Hinweis auf die Weiterentwicklung.
« Letzte Änderung: 03 Dezember 2022, 12:34:30 von DS_Starter »
ESXi 6.5 @NUC6i5SYH mit FHEM auf Debian 10, DbLog/DbRep mit MariaDB auf VM
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Offline SusisStrolch

  • Full Member
  • ***
  • Beiträge: 242
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #4 am: 03 Dezember 2022, 12:41:50 »
Zitat
Wenn FHEM abschmiert steht doch bestimmt im Log ein etwaiger Hinweis auf die Ursache, oder ?
Ja - leider konnte ich mir erst heute die Zeit dafür nehmen - und das Problem mit dem Save trat erst seit gestern auf. Anyway...
Die Ursache ist in der configDB  bzw. den config-Daten zu finden. Auch hier muss ich mich erst mal zur eigentlichen Ursache durchwühlen.
2022.12.03 12:26:16.194 1: PERL WARNING: DBD::mysql::st execute failed: Data too long for column 'content' at row 1 at configDB.pm line 434.
2022.12.03 12:26:16.195 1: stacktrace:
2022.12.03 12:26:16.195 1:     main::__ANON__                      called by configDB.pm (434)
2022.12.03 12:26:16.195 1:     main::cfgDB_FileWrite               called by configDB.pm (601)
2022.12.03 12:26:16.196 1:     main::cfgDB_SaveState               called by fhem.pl (1610)
2022.12.03 12:26:16.196 1:     main::WriteStatefile                called by fhem.pl (1728)
2022.12.03 12:26:16.196 1:     main::CommandSave                   called by fhem.pl (1274)
2022.12.03 12:26:16.196 1:     main::AnalyzeCommand                called by fhem.pl (1125)
2022.12.03 12:26:16.197 1:     main::AnalyzeCommandChain           called by ./FHEM/98_telnet.pm (263)
2022.12.03 12:26:16.197 1:     main::telnet_Read                   called by fhem.pl (3972)
2022.12.03 12:26:16.197 1:     main::CallFn                        called by fhem.pl (782)
DBD::mysql::st execute failed: Data too long for column 'content' at row 1 at configDB.pm line 434.
2022.12.03 12:26:16.208 1: PERL WARNING: Issuing rollback() due to DESTROY without explicit disconnect() of DBD::mysql::db handle database=fhem_configDB;host=192.168.254.20;port=3307 at configDB.pm line 434.
2022.12.03 12:26:16.209 1: stacktrace:
2022.12.03 12:26:16.209 1:     main::__ANON__                      called by configDB.pm (434)
2022.12.03 12:26:16.209 1:     (eval)                              called by configDB.pm (434)
2022.12.03 12:26:16.210 1:     main::cfgDB_FileWrite               called by configDB.pm (601)
2022.12.03 12:26:16.210 1:     main::cfgDB_SaveState               called by fhem.pl (1610)
2022.12.03 12:26:16.210 1:     main::WriteStatefile                called by fhem.pl (1728)
2022.12.03 12:26:16.210 1:     main::CommandSave                   called by fhem.pl (1274)
2022.12.03 12:26:16.211 1:     main::AnalyzeCommand                called by fhem.pl (1125)
2022.12.03 12:26:16.211 1:     main::AnalyzeCommandChain           called by ./FHEM/98_telnet.pm (263)
2022.12.03 12:26:16.211 1:     main::telnet_Read                   called by fhem.pl (3972)
2022.12.03 12:26:16.211 1:     main::CallFn                        called by fhem.pl (782)
Die Spalte "fhemb64filesave:content" wird von configDB als "mediumblob" angelegt. Und das sollten 16,777,215 * 2^24 -1 bytes sein... hüstel...

Zitat
Ich habe mir die Encode::FB_CROAK | Encode::LEAVE_SRC jetzt nicht genauer angeschaut, aber FB_CROAK richt sehr nach "Abschuß" der Perl Schleife bei entsprechenden Bedingungen. FB_CROAK/LEAVE_SRC müssste auch geladen sein. Im DbLog selbst wird nur Encode::encode_utf8 geladen. Vllt. fehlt das ?
Nö, eigentlich fehlt da nix - so wie ich das verstanden habe. Es wir lediglich überprüft, ob es sich um einen korrekten UTF-8 String handelt. Das Ergebnis des decode spielt da keine Rolle.
Mein Test-Script (mit dem ich die gegreppten MemCache gefiltert habe):
#!/usr/bin/perl
#
use strict;
use warnings;

use Encode;

my $enc_flags = Encode::FB_CROAK | Encode::LEAVE_SRC;

binmode STDOUT, ':encoding(utf-8)';

while ( my $line = <> ) {
    chomp $line;

    my $decoded = eval {
        Encode::decode( 'utf-8', $line, $enc_flags );
    };
    print $decoded, "\n" if length($decoded);
}

Sobald ich die Ursache für das configDB gefunden und beseitig habe werde ich mir mal direkt die neue Version anschauen und einen fehlerhaften Datensatz zum Testen einspielen.
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

Offline DS_Starter

  • Developer
  • Hero Member
  • ****
  • Beiträge: 8770
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #5 am: 03 Dezember 2022, 12:54:22 »
Zitat
Nö, eigentlich fehlt da nix - so wie ich das verstanden habe
Da wirst du recht haben ... du verwendest

   use Encode;

im Testscript und lädst Encode komplett. Ich wollte nur darauf hinweisen, dass ich im DbLog nur Encode::encode_utf8 lade.
Aber irgendwo in main:: wird sicherlich Encode komplett geladen.  ;)

Und so wie es aussieht ist das ja auch nicht an der Absturzursache beteiligt ...
ESXi 6.5 @NUC6i5SYH mit FHEM auf Debian 10, DbLog/DbRep mit MariaDB auf VM
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Offline SusisStrolch

  • Full Member
  • ***
  • Beiträge: 242
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #6 am: 04 Dezember 2022, 10:03:30 »
Zitat
Und so wie es aussieht ist das ja auch nicht an der Absturzursache beteiligt ...
Jep. Der m2s war die Ursache.
Genauer: ein abartig großes RETAIN reading im kB Bereich. Und die retains selbst.
Nach Löschen des Readings und einem clearRetain fluppt es wieder.

Wenn wir mit Plätzchen backen durch sind werde ich mal ´nen Blick auf die 5.x. werfen.
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

Offline SusisStrolch

  • Full Member
  • ***
  • Beiträge: 242
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #7 am: 07 Dezember 2022, 18:48:49 »

Aber irgendwo in main:: wird sicherlich Encode komplett geladen.  ;)

Scheint so   :D
Bisher läuft es ohne Nebenwirkungen.
Wird ein IGNORE explizit im Log aufgeführt?
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

Offline DS_Starter

  • Developer
  • Hero Member
  • ****
  • Beiträge: 8770
Antw:DbLog - Cache, MemCache und mysql Fehler
« Antwort #8 am: 07 Dezember 2022, 18:55:47 »
Zitat
Wird ein IGNORE explizit im Log aufgeführt?

Ja mit verbose 4:

Log3 ($name, 4, "DbLog $name - Event ignored by device \"$dev_name\" specific DbLogValueFn - TS: $timestamp, Device: $dev_name, Type: $dev_type, Event: $event, Reading: $reading, Value: $value, Unit: $unit");

bzw.

Log3 ($name, 4, "DbLog $name - Event ignored by valueFn - TS: $timestamp, Device: $dev_name, ....
ESXi 6.5 @NUC6i5SYH mit FHEM auf Debian 10, DbLog/DbRep mit MariaDB auf VM
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter