[gelöst] Falsche Datenreihenfolge bei dbLog

[WW]

Hallo zusammen,
mit Hilfe der Sonoff-Zigbee-Bridge nehme ich Daten von einem Sonoff-Door-Window-Kontakt auf:

Code Auswählen Erweitern


defmod DgBueroZbDwFS MQTT2_DEVICE DgBueroZbDwFS
attr DgBueroZbDwFS DbLogExclude .*
attr DgBueroZbDwFS DbLogInclude Reed
attr DgBueroZbDwFS IODev Mqqt2Client
attr DgBueroZbDwFS alarmDevice Sensor
attr DgBueroZbDwFS alarmSettings |DgBueroZbDwFS:Reed:.1|Dachgeschoß Fenster Süd offen|on
attr DgBueroZbDwFS alias DG-Büro: Fenster Süd
attr DgBueroZbDwFS devStateIcon A.1:fts_window_roof_open_2@red A.0:fts_window_roof
attr DgBueroZbDwFS event-min-interval Reed:7200
attr DgBueroZbDwFS event-on-change-reading Reed
attr DgBueroZbDwFS group Tür-Fenster-Kontakte
attr DgBueroZbDwFS icon tuer_fenster_kontakt
attr DgBueroZbDwFS jsonMap ZbReceived_DgBueroZbDwFS_LinkQuality:LinkQuality\
ZbReceived_DgBueroZbDwFS_ZoneStatusChange:Reed
attr DgBueroZbDwFS readingList tele/sonoff115/DgBueroZbDwFS/SENSOR:.* { json2nameValue($EVENT, '', $JSONMAP) }
attr DgBueroZbDwFS room Bewegungsmelder,System->MQTT2_DEVICE,System->Zigbee
attr DgBueroZbDwFS setList clear_readings:noArg {fhem("deletereading -q $NAME (?!associatedWith).*");;return undef}
attr DgBueroZbDwFS stateFormat A:[$name:Reed]\
Link-Quality: [$name:LinkQuality] ([$name:Reed:t])

setstate DgBueroZbDwFS A:0\
Link-Quality: 26 (2021-06-22 15:29:44)
setstate DgBueroZbDwFS 2021-06-22 17:39:26 LinkQuality 26
setstate DgBueroZbDwFS 2021-06-22 15:29:44 Reed 0
setstate DgBueroZbDwFS 2021-06-22 15:29:44 ZbReceived_DgBueroZbDwFS_0500_00 000000010000
setstate DgBueroZbDwFS 2021-06-22 17:39:26 ZbReceived_DgBueroZbDwFS_BatteryPercentage 100
setstate DgBueroZbDwFS 2021-06-22 17:39:26 ZbReceived_DgBueroZbDwFS_BatteryVoltage 3.2
setstate DgBueroZbDwFS 2021-06-22 15:29:44 ZbReceived_DgBueroZbDwFS_Contact 0
setstate DgBueroZbDwFS 2021-06-22 17:39:26 ZbReceived_DgBueroZbDwFS_Device 0x8C7E
setstate DgBueroZbDwFS 2021-06-22 17:39:26 ZbReceived_DgBueroZbDwFS_Endpoint 1
setstate DgBueroZbDwFS 2021-06-22 17:39:26 ZbReceived_DgBueroZbDwFS_Name DgBueroZbDwFS
setstate DgBueroZbDwFS 2021-06-22 15:29:44 ZbReceived_DgBueroZbDwFS_ZoneStatusChangeZone 1


Den Wert von "Reed" logge ich in eine dbLog-Datenbank (mySql):

Code Auswählen Erweitern


defmod DBLogging DbLog /opt/fhem/contrib/configDB/configDB.conf .*:.*
attr DBLogging DbLogExclude .*
attr DBLogging DbLogSelectionMode Exclude/Include
attr DBLogging DbLogType Current/History
attr DBLogging asyncMode 1
attr DBLogging cacheEvents 2
attr DBLogging event-on-change-reading countHistory
attr DBLogging group Logging
attr DBLogging icon system_backup
attr DBLogging room System->Logs
attr DBLogging syncInterval 60
attr DBLogging timeout 86400
attr DBLogging verbose 2

setstate DBLogging connected
setstate DBLogging 2021-06-22 19:39:54 CacheOverflowLastNum 0
setstate DBLogging 2021-04-25 19:31:24 CacheOverflowLastState normal
setstate DBLogging 2021-06-22 19:40:25 CacheUsage 14
setstate DBLogging 2021-06-22 19:39:54 NextSync 2021-06-22 19:40:54 or if CacheUsage 500 reached
setstate DBLogging 2021-06-22 19:39:54 state connected


Wenn ich den Fensterkontakt nun schnell öffne und sofort wieder schließe, dann erkenne ich folgendes: Der Wert des Readings "Reed" ist stets in Ordnung, in der SQL-Datenbank sind jedoch öfter die Werte des Readings vertauscht. In einem solchen Fall ist dann stets der Timestamp der beiden aufeinanderfolgenden(vertauschten) Einträge identisch. Meine Vermutung: Werden in der gleichen Sekunde mehrere Werte eines Readings in die Datenbank geschrieben, so ist die Reihenfolge beim Schreiben (bzw. beim Auslesen) nicht immer in der richtigen Reihenfolge. Aufgefallen ist mir dies bei der Betrachtung von SVG-Plots.

Um 12:22:07 habe ich kurz das bis dahin geschlossene Fenster geöffnet und sofort wieder geschlossen. In der Datenbank sind die Werte vertauscht (phpmyadmin):

Code Auswählen Erweitern


2021-06-22 12:22:07 DgBueroZbDwFS MQTT2_DEVICE Reed: 1 Reed 1
2021-06-22 12:22:07 DgBueroZbDwFS MQTT2_DEVICE Reed: 0 Reed 0
2021-06-20 22:58:18 DgBueroZbDwFS MQTT2_DEVICE Reed: 0 Reed 0


Entsprechend stimmt dann die SVG-Grafik natürlich auch nicht. Ich wäre dankbar für Tipps zur Behebung meines Problems.

[betateilchen]

Code Auswählen Erweitern


defmod DBLogging DbLog /opt/fhem/contrib/configDB/configDB.conf .*:.*


Nur mal nebenbei gefragt:

Wieso nimmst Du für DbLog eine Konfigurationsdatei, die eigentlich für configDB vorgesehen ist?

Bist Du Dir sicher, dass Du verstanden hast, was Du eigentlich tust?

[WW]

Nur mal nebenbei gefragt:

Wieso nimmst Du für DbLog eine Konfigurationsdatei, die eigentlich für configDB vorgesehen ist?

Bist Du Dir sicher, dass Du verstanden hast, was Du eigentlich tust?

Vermutlich war ich nur bei der Festlegung des Namens der Konfigurationsdatei etwas unklar:

Code Auswählen Erweitern


Define
    define <name> DbLog <configfilename> <regexp>

    <configfilename> ist die vorbereitete Konfigurationsdatei.
    <regexp> ist identisch FileLog der Filelog-Definition.

    Beispiel:
        define myDbLog DbLog /etc/fhem/db.conf .*:.*
        speichert alles in der Datenbank


Hier der Inhalt meiner Konfigurationsdatei:

Code Auswählen Erweitern

%dbconfig= (
    connection => "mysql:database=fhem;host=nas-2;port=3306",
    user => "xxxxx",
    password => "yyyyyyyy"
);


Die SQL-Verbindung funktioniert auch. Da sind inzwischen ca 8.000.000 Einträge drin.

[betateilchen]

Du bist hier trotzdem im falschen Forumbereich für Deine DbLog-Probleme.
Für DbLog ist das Unterforum "Automatisierung" die richtige Stelle.

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

Du kannst den Thread mit dem Button weit unten auf der Seite entsprechend verschieben.

(Edit: danke fürs Verschieben)

[betateilchen]

Du könntest mal mit verbose=5 testen, damit man die gesamte Eventverarbeitung im FHEM Log sehen kann.
Eventuell kann man daraus erkennen, an welcher Stelle die Reihenfolge durcheinander kommt.

Vergiß nicht, den Loglevel hinterher wieder runterzusetzen, mit 5 wird echt viel Output erzeugt 

[DS_Starter]

Hallo WW,

Meine Vermutung: Werden in der gleichen Sekunde mehrere Werte eines Readings in die Datenbank geschrieben, so ist die Reihenfolge beim Schreiben (bzw. beim Auslesen) nicht immer in der richtigen Reihenfolge.

Das hast du richtig erkannt. DbLog arbeitet mit dem Timestamp ohne Millisekunden, demzufolge sind die Datensätze mit gleichem Timestamp gleichwertig bezüglich der Leseorder "BY TIMESTAMP" so wie sie zur Lieferung an SVG verwendet wird.
Ich bin selbst schon darüber gestolpert. Es ist relativ einfach das Modul (wie bei Filelog) diesbezüglich zu erweitern.
Aber ich bin mir add hoc unsicher ob es dann noch weitere Aktivitäten in Richtung SVG, grundsätzlichem Setup /Definition der Datenbank und andere Dinge (DbRep) nach sich ziehen würde.

Mit anderen Worten ... eine schnelle Änderung kann ich nicht anbieten, sondern würde so etwas nur nach ausführlichen Tests umsetzen.

Meiner Meinung käme für dich aktuell nur ein Workaround in Frage.
Erste Frage die ich mir stellen würde wäre ob das Loggen von Statuswechsel von < 1 Sekunde sinnvoll ist und benötigt wird ?
Wenn ja, müsstest du für genau diese Werte auf Fileog (mit mseclog) ausweichen.
Wenn nein, könnte man z.B. mit dem Zeitfilter, die die Attribute DbLogInclude / DbLogExclude bieten, arbeiten.

Grüße,
Heiko

[WW]

Hallo DS_Starter,

danke für die Bestätigung meiner Vermutung.

... Wenn nein, könnte man z.B. mit dem Zeitfilter, die die Attribute DbLogInclude / DbLogExclude bieten, arbeiten.
...

Damit komme ich allerdings nicht klar.

Code Auswählen Erweitern

DbLogInclude

    attr <device> DbLogInclude regex:MinInterval[:force],[regex:MinInterval[:force]] ...
    Wird DbLog genutzt, wird in allen Devices das Attribut DbLogInclude propagiert. DbLogInclude funktioniert im Endeffekt genau wie DbLogExclude, ausser dass Readings mit diesen RegExp in das Logging eingeschlossen statt ausgeschlossen werden koennen.
    Ist MinIntervall angegeben, wird der Logeintrag nicht geloggt, wenn das Intervall noch nicht erreicht und der Wert des Readings sich nicht verändert hat. Ist der optionale Parameter "force" hinzugefügt, wird der Logeintrag auch dann nicht geloggt, wenn sich der Wert des Readings verändert hat.
    Siehe auch die DbLog Attribute defaultMinInterval und DbLogSelectionMode. Es beeinflußt wie DbLogExclude und DbLogInclude ausgewertet werden.


Um in meinem Beispiel zu bleiben: Das Fenster ist zu (0), wird geöffnet (1) und in der gleichen Sekunde wieder geschlossen (0). Mit DbLogInclude ohne "force" erreiche ich nichts, mit "force" geht das Schliessen verloren und das Fenster bleibt scheinbar offen.

Ich sehe im Moment nur eine Möglichkeit als Workaround: Event auf das Reading "Reed" abfangen. Wenn die Zeit zwischen dem Event und dem letzten Event kleiner als eine Sekunde ist, dann z.B. 2 Sekunden warten und den Wert des Readings auslesen und nochmal von Hand in die Datenbank schreiben. Hier wäre ich für einen Tipp dankbar: Notify oder DOIF. Und wie kriege ich den Wert am besten in die Datenbank. Wegen

Code Auswählen Erweitern

attr DgBueroZbDwFS event-on-change-reading Reed würde der Wert beim Neusetzen des Readings ja nicht geschrieben.

MfG Willi

[DS_Starter]

Hallo Willi,

ich persönlich nutze nur notify.
Allerdings kannst du das wahrscheinlich direkt in DbLog erledigen, mit dem Attr valueFn in Verbindung mit der Perl-Funktion OldReadingsTimestamp. Sieh dir dazu die Erläuterungen in https://fhem.de/commandref_DE.html#perl an.

In dem Attr valueFn  kannst du Code hinterlegen und auch auf DEVICE, READING bzw. TIMESTAMP des Events zugreifen.
Zum Beispiel kannst du den empfangenen TIMESTAMP des Reading "Reed" mit dem alten Timestamp des Reedings vergleichen (OldReadingsTimestamp) und wenn diese gleich sind, d.h. Event ist innerhalb einer Sekunde, addierst du zu dem empfangenen TIMESTAMP eine Sekunde dazu.

Da muss man noch etwas Gehirnschmalz reinstecken damit hinten auch immer eine valide Zeit herauskommt und nicht 80 Sekunden oder so etwas und man muß den TIMESTAMP  in Sekunden umwandeln um damit rechnen zu können bzw. danach wieder in einen TIMESTAMP wandeln.  TIMESTAMP heißt hier die Form YYYY-MM-TT hh:mm:ss.
Aber wenn man ein bisschen drüber nachdenkt bekommt man das sicher praktikabel gelöst.

LG

[WW]

Hallo Heiko,
angeregt durch Deinen Hinweis

...
Allerdings kannst du das wahrscheinlich direkt in DbLog erledigen
...

habe ich nun folgendes umgesetzt:

Code Auswählen Erweitern


...
attr EgKuZbDwTS DbLogExclude .*
attr EgKuZbDwTS DbLogInclude Reed
attr EgKuZbDwTS DbLogValueFn {\
my $akt = time_str2num($TIMESTAMP);;\
return if (($akt - int($LASTTIMESTAMP)) > 0 );;\
\
my $ts0 = $TIMESTAMP;;\
my $TIMESTAMP = FmtDateTime($akt + 1);;\
Log 1, "$DEVICE (TIMESTAMP erhöht): , $READING: $VALUE, org: $ts0, neu: $TIMESTAMP";; \
}
...


Es scheint so zu funktionieren. Ich werde die LOG-Files und meine SVG-Plots weiter beobachten.
Ein Dankeschön an Dich und betateilchen. Dank Eurer Anregungen habe ich einiges dazu lernen können.

LG Willi

[WW]

Jetzt habe ich mich zu früh gefreut. Ich habe wie im letzten Post geschrieben das Attribut "DbLogValueFn" gesetzt. Jetzt habe ich im Log den Fall gefunden, wo in der gleichen Sekunde zwei Werte vorliegen:

Code Auswählen Erweitern


2021.07.04 21:02:58.711 1: DgBueroZbDwFS (TIMESTAMP erhöht): , Reed: 0, org: 2021-07-04 21:02:58, neu: 2021-07-04 21:02:59


Demnach hätte ich für 21:02:59 Uhr einen Eintrag mit Reed: 0 in der Datenbank erwartet. Obwohl die Variable $TIMESTAMP erhöht wurde (siehe Log), steht in der Datenbank der Wert mit der ursprünglichen Zeit (21:02:28):

Code Auswählen Erweitern


2021-07-04 21:02:58 DgBueroZbDwFS MQTT2_DEVICE Reed: 1 Reed 1
2021-07-04 21:02:58 DgBueroZbDwFS MQTT2_DEVICE Reed: 0 Reed 0
2021-07-04 21:02:57 DgBueroZbDwFS MQTT2_DEVICE Reed: 0 Reed 0
2021-07-04 21:02:54 DgBueroZbDwFS MQTT2_DEVICE Reed: 1 Reed 1


Das Reading "Reed" hat den richtigen Wert.

Was mache ich jetzt noch falsch?

LG
Willi

[DS_Starter]

Mir fällt gerade auf, dass du mit "my"

Code Auswählen Erweitern


my $TIMESTAMP = FmtDateTime($akt + 1);;\


eine eigene Variable verwendest, statt die intern übergebene Var $TIMESTAMP zu nutzen.
Benutze einfach:

Code Auswählen Erweitern


$TIMESTAMP = FmtDateTime($akt + 1);;\


LG,
Heiko

[WW]

Hallo Heiko,
da hätte ich eigentlich selber drauf kommen müssen.
Danke, werde ich ändern und weiter beobachten.

LG Willi