[Gelöst] DBLog logged einige Werte nicht mehr

[Mad-at]

Hallo!

Ich würde ein wenig Hilfe bei der Fehlersuche benötigen. Ich musste mein komplettes System wiederherstellen, dabei auch die MariaDB in die ich logge. Ohne Änderungen an der FHEM Konfiguration werden jetzt einige Readings nicht mehr geloggt. Der Status ist aber korrekt und ändert sich stetig. An DBlog exclude/include hat sich nichts geändert. Ich bekomme für mich kryptische Fehlermeldungen im FHEM Log:

Code Auswählen Erweitern


2023.01.04 12:15:22 2: DbLog DBLogging - Error table history - DBD::mysql::st execute failed: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '' at line 1 [for Statement "INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES"] at ./FHEM/93_DbLog.pm line 2757.

2023.01.04 12:15:22 2: DbLog DBLogging - Transaction is switched off. Transferred data is lost.


Danke!
Matthias

[betateilchen]

Das ist keine Anfängerfrage, sondern eine Problembeschreibung zu DbLog.
Das solltest Du im richtigen Unterforum schreiben bzw. diesen Thread dorthin verschieben, damit der Modulautor davon auch etwas mitbekommt.

https://forum.fhem.de/index.php/topic,13092.0.html

[Mad-at]

Sorry ich fühl mich immernoch so anfängerig   
Ich versuches...

[DS_Starter]

Hallo Matthias,

bitte ein list deines DbLog Devices posten.

[Mad-at]

Hallo DS_Starter,

vielen Dank, anbei:

Code Auswählen Erweitern


Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION /opt/fhem/db.conf
   DEF        /opt/fhem/db.conf .*:.*
   FD         5
   FUUID      5d595aca-f33f-db1a-9fae-2143ffbee32056c7
   FVERSION   93_DbLog.pm:v5.5.9-s26923/2022-12-29
   MODE       asynchronous
   MODEL      MYSQL
   NAME       DBLogging
   NR         2
   NTFY_ORDER 50-DBLogging
   PID        5869
   REGEXP     .*:.*
   SBP_PID    5870
   SBP_STATE  running
   STATE      Another operation is in progress - resync at NextSync
   TYPE       DbLog
   UTF8       0
   dbconn     mysql:database=fhem;host=192.168.1.2;port=19648
   dbuser     fhemuser
   eventCount 29
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     LASTLIMITRUNTIME 1672837151.60521
     LONGRUN_PID 1672837151.60489
     OLDSTATE   Another operation is in progress - resync at NextSync
     PACKAGE    main
     READINGCOL 64
     TC         current
     TH         history
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     VERSION    5.5.9
   Helper:
     DBLOG:
       CacheOverflowLastState:
         DBLogging:
           TIME       1672837181.58673
           VALUE      normal
       DBD::mysql::st execute failed:
         DBLogging:
           TIME       1672837025.06969
           VALUE      You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '' at line 1 [for Statement "INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES"] at ./FHEM/93_DbLog.pm line 2755.
       state:
         DBLogging:
           TIME       1672837181.59546
           VALUE      Another operation is in progress - resync at NextSync
   OLDREADINGS:
   READINGS:
     2023-01-04 13:59:41   CacheOverflowLastNum 0
     2023-01-04 13:59:41   CacheOverflowLastState normal
     2023-01-04 13:59:46   CacheUsage      180
     2023-01-04 13:59:41   NextSync        2023-01-04 14:00:11 or when CacheUsage 250 is reached
     2023-01-04 13:59:41   state           Another operation is in progress - resync at NextSync
Attributes:
   DbLogExclude CacheOverflowLastNum.*
   DbLogSelectionMode Exclude/Include
   DbLogType  Current/History
   addStateEvent 0
   asyncMode  1
   bulkInsert 1
   cacheLimit 250
   commitMode basic_ta:off
   event-on-change-reading .*
   room       System
   useCharfilter 1
   verbose    3


[DS_Starter]

Löche das Attr commitMode, setze  bulkInsert = 0 (evtl. bessere Fehlermitteilung) und verbose = 4.

Wenn der Fehler wieder auftaucht, bitte den Logausschnitt posten und den Inhalt von "set ... listCache".

[Mad-at]

Danke, hab ich gemacht, seit einem "shutdown restart" läuft es jetzt erstmal fehlerfrei (meine Log wird halt beängstigend groß grad...). Aber das Nicht-Loggen hat sich nicht gebessert. Im FHEM Log steht aber dass er es übermittelt

Code Auswählen Erweitern


2023.01.04 15:09:49 4: DbLog DBLogging - ################################################################
2023.01.04 15:09:49 4: DbLog DBLogging - ###              start of new Logcycle                       ###
2023.01.04 15:09:49 4: DbLog DBLogging - ################################################################
2023.01.04 15:09:49 4: DbLog DBLogging - number of events received: 2 of device: AlleBewegungsmelderSperren
2023.01.04 15:09:49 4: DbLog DBLogging - check Device: AlleBewegungsmelderSperren , Event: setG1: on
2023.01.04 15:09:49 4: DbLog DBLogging - added event - Timestamp: 2023-01-04 15:09:49, Device: AlleBewegungsmelderSperren, Type: KNX, Event: setG1: on, Reading: setG1, Value: on, Unit:
2023.01.04 15:09:49 4: DbLog DBLogging - check Device: AlleBewegungsmelderSperren , Event: on
2023.01.04 15:09:49 4: DbLog DBLogging - added event - Timestamp: 2023-01-04 15:09:49, Device: AlleBewegungsmelderSperren, Type: KNX, Event: on, Reading: on, Value: , Unit:

[...]

2023.01.04 15:10:02 4: DbLog DBLogging - ################################################################
2023.01.04 15:10:02 4: DbLog DBLogging - ###              start of new Logcycle                       ###
2023.01.04 15:10:02 4: DbLog DBLogging - ################################################################
2023.01.04 15:10:02 4: DbLog DBLogging - number of events received: 2 of device: AlleBewegungsmelderSperren
2023.01.04 15:10:02 4: DbLog DBLogging - check Device: AlleBewegungsmelderSperren , Event: setG1: off
2023.01.04 15:10:02 4: DbLog DBLogging - added event - Timestamp: 2023-01-04 15:10:02, Device: AlleBewegungsmelderSperren, Type: KNX, Event: setG1: off, Reading: setG1, Value: off, Unit:
2023.01.04 15:10:02 4: DbLog DBLogging - check Device: AlleBewegungsmelderSperren , Event: off
2023.01.04 15:10:02 4: DbLog DBLogging - added event - Timestamp: 2023-01-04 15:10:02, Device: AlleBewegungsmelderSperren, Type: KNX, Event: off, Reading: off, Value: , Unit:


bzw.:

Code Auswählen Erweitern


2023.01.04 15:10:40 4: DbLog DBLogging - ################################################################
2023.01.04 15:10:40 4: DbLog DBLogging - ###              start of new Logcycle                       ###
2023.01.04 15:10:40 4: DbLog DBLogging - ################################################################
2023.01.04 15:10:40 4: DbLog DBLogging - number of events received: 2 of device: Aussentemperatur
2023.01.04 15:10:40 4: DbLog DBLogging - check Device: Aussentemperatur , Event: getG1: 8.16
2023.01.04 15:10:40 4: DbLog DBLogging - check Device: Aussentemperatur , Event: 8.16
2023.01.04 15:10:40 4: DbLog DBLogging - added event - Timestamp: 2023-01-04 15:10:40, Device: Aussentemperatur, Type: KNX, Event: 8.16, Reading: 8.16, Value: , Unit:


Also offenbar hat das eine mit dem anderen nichts zu tun?

[DS_Starter]

Kannst wieder auf verbose 3 wechseln.

Das Thema ist halt das berühmt / berüchtigte loggen von Reading "state".
Der Datensatz kommt ohne Readingname im Event :

added event - Timestamp: 2023-01-04 15:09:49, Device: AlleBewegungsmelderSperren, Type: KNX, Event: on, Reading: on, Value: , Unit:

Dadurch klappt das parsen nicht.
Das KNX-Modul hat dankenswerter Weise eine sogenannte DbLog-SplitFn eingebaut (KNX_DbLog_split).
Die scheint aber das Reading "state" nicht richtig zu behandeln. Das solltest du dem Maintainer des Moduls melden.

Übergangsweise kannst du versuchen ob im DbLog das Attr addStateEvent = 0 dir hilft.

[Mad-at]

Ah cool, das hat es gebracht. Dann muss das ein Problem mit der Version ab 30.12. sein, denn bis dahin hat es problemlos ohne addStateEvent geklappt.

Vielen vielen lieben Dank!
Jetzt hoffe ich nur dass der Database Error auch weg ist und weg bleibt 

[DS_Starter]

Dann muss das ein Problem mit der Version ab 30.12. sein, denn bis dahin hat es problemlos ohne addStateEvent geklappt.

Ich glaube es dir, allerdings ist die Eventverarbeitung identisch zur V4.... so ganz gehe ich über diese Brücke noch nicht.

Jetzt hoffe ich nur dass der Database Error auch weg ist und weg bleibt 

Das denke ich. Allerdings mache ich mir noch Gedanken weil ein undefined Value-Feld nicht zu einem solchen Fehler führen darf.
Ich habe auch schon eine Idee die ich teste und wenn es klappt ins nächste Release kommt.

LG

[erwin]

Sorry Mad-at,
ja ich habe da etwas im KNX-modul geändert, was das Problem ausgelöst hat - sorry!

@Heiko:
ich war mir sicher, das ich das checken auf state / nostate nicht mehr brauche, weil in deiner DbLog_Log folgendes vorkommt:

Code Auswählen Erweitern

my $events = deviceEvents($dev_hash, AttrVal($name, "addStateEvent", 1));
  return if(!$events);
... und wenn ich das richtig verstehe, ergibt AttrVal  '1'  falls KEIN attr im DbLog-device gesetzt ist...
... und deviceEvents($hash,1) sollte lt. wiki das "state" im array liefern ? https://wiki.fhem.de/wiki/DevelopmentModuleAPI#deviceEvents
Wo ist der Wurm ?
PS: ich kann natürlich die Änderung im KNX Modul jederzeit zurückdrehen- kein Problem!
l.g. erwin

[DS_Starter]

Moin erwin,

also ich finde erstmal wirklich gut dass du eine DbLog_SplitFn drin hast. 

Die sieht so aus:

Code Auswählen Erweitern


sub KNX_DbLog_split {
my ($event, $device) = @_;

my $unit = q{}; # default

# split event into reading & value
my ($reading, $value) = split(/:\s/x, $event, 2);
if (! defined($reading)) {
$reading = 'state';
$value   = $event;
}
.....


"state" geht verloren, wenn DbLog deine Fn aufruft und in $event "state" enthält , z.B.  "state: 34".
EDIT: das war Unsinn von mir ... Knoten im Hirn . 
Wenn Mad-at im KNX verbose 5 einstellt, müsste man das Split-Ergebnis sehen.

[erwin]

Hi Heiko,
ja state geht verloren, da funktioniert das split nicht! - mein Fehler!
.. ich werde das heute noch fixen.
Die Frage bleibt: ist das wiki falsch bez. deviceEvents ... oder...?
offen gesagt, den code deviceEvents (in der fhem.pl) durchschau ich nicht.
l.g. erwin

[DS_Starter]

ja state geht verloren, da funktioniert das split nicht! - mein Fehler!

... also nach zweimal hingucken dachte ich, dass meine Schlußfolgerung falsch war ...

Ich schaue mir die deviceEvents sub auch mal an.

[erwin]

So Mad-at & Heiko,
fix für KNX-modul ist am SVN,
bitte morgen um update & test!

sorry Heiko, dass das Problem bei dir aufgeschlagen ist.... .
l.g. erwin