FHEM > Automatisierung

DbLog - Cache, MemCache und mysql Fehler

(1/2) > >>

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

--- Ende Code ---
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: ---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

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


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

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

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:

--- Zitat ---ich denke dein Problem kannst du mit dem Attr:

  useCharfilter = 1

beseitigen
--- Ende Zitat ---
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: ---    my $flags = Encode::FB_CROAK | Encode::LEAVE_SRC;
    my $void = eval {
        Encode::decode( 'utf-8', $EVENT, $flags );
    } || $IGNORE=1

--- Ende Code ---


--- Zitat ---commitMode = basic_ta:off
--- Ende Zitat ---
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.

--- Ende Zitat ---
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).

--- Ende Zitat ---
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:

--- Zitat ---Wenn FHEM abschmiert steht doch bestimmt im Log ein etwaiger Hinweis auf die Ursache, oder ?

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

--- Ende Code ---
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 ?

--- Ende Zitat ---
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: ---#!/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);
}

--- Ende Code ---

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.

Navigation

[0] Themen-Index

[#] Nächste Seite

Zur normalen Ansicht wechseln