DbLog - Cache, MemCache und mysql Fehler

[SusisStrolch]

Erst mal vorab - ich bin mit DbLog und DbRep höchst zufrieden.

Umgebung:
- fhem auf einer CuBox
- MariaDB10 auf Synology
- Struktur der history Tabelle:

Code Auswählen Erweitern

    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:

Code Auswählen Erweitern


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.

[DS_Starter]

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.

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

[SusisStrolch]

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

Code Auswählen Erweitern

    my $flags = Encode::FB_CROAK | Encode::LEAVE_SRC;
    my $void = eval {
        Encode::decode( 'utf-8', $EVENT, $flags );
    } || $IGNORE=1


commitMode = basic_ta:off

Genau das wollte ich eigentlich aus Performance-Gründen vermeiden...

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.

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"

[DS_Starter]

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.

[SusisStrolch]

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.

Code Auswählen Erweitern

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...

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):

Code Auswählen Erweitern

#!/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.

[DS_Starter]

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 ...

[SusisStrolch]

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.

[SusisStrolch]

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

Scheint so   
Bisher läuft es ohne Nebenwirkungen.
Wird ein IGNORE explizit im Log aufgeführt?

[DS_Starter]

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, ....