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.
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
Zitatich 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
ZitatcommitMode = basic_ta:off
Genau das wollte ich eigentlich aus Performance-Gründen vermeiden...
ZitatDas 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.
ZitatAnsonsten 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"
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.
ZitatWenn 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.
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 ...
ZitatUnd 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.
Zitat von: DS_Starter am 03 Dezember 2022, 12:54:22
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?
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, ....