Dummy über Notify aktualisiert schreibt kein Log in DBlog

litronics · 08 Februar 2018, 11:04:33

OK, dann habe ich ja zumindest das Prinzip richtig verstanden

Jetzt scheitere ich aber an meinen Programmierkenntnissen.

Auf FHEM Ebene müsste das ja in etwas so aussehen:

		  fhem "sleep 0.1; setreading Oeltank Oelstand $new_oelstand"; 
		  fhem "sleep 0.1; setreading Oeltank last_Runtime1 $currentRuntime1"; 
		  fhem "sleep 0.1; setreading Oeltank last_Runtime2 $currentRuntime2"; 
		  fhem "sleep 0.1; setreading Oeltank last_consumption $verbrauch"; 
		  fhem "sleep 0.1; setreading Oeltank verbrauch_seit_auffuellen $new_verbrauch";

Wenn ich aber jetzt auf Perl-Ebene mit Begin und End Update bleiben möchte, muss ich alle Update-Anweisungen ja in ein "InternalTimer($timestamp, $functionName, $arg);" Statement packen.

Als $functionName kann ich da doch schlecht die Liste mit Anweisungen reinpacken und muss wohl eine eigenen Funktion dafür bauen.
In etwa so:

Code Auswählen


.
.
.
InternalTimer(gettimeofday()+1, "UpdateMyReadings", $arg);
}
sub UpdateMyReadings($)
{
		  readingsBeginUpdate($defs{Oeltank}); 
		  readingsBulkUpdate($defs{Oeltank},"Oelstand",$new_oelstand); 
		  readingsBulkUpdate($defs{Oeltank},"last_Runtime1",$currentRuntime1); 
		  readingsBulkUpdate($defs{Oeltank},"last_Runtime2",$currentRuntime2); 
		  readingsBulkUpdate($defs{Oeltank},"last_consumption",$verbrauch; 
		  readingsBulkUpdate($defs{Oeltank},"verbrauch_seit_auffuellen",$new_verbrauch);
                  readingsEndUpdate($defs{Oeltank},1)
}

Was mir hier noch nicht so klar ist, was ich als $arg übergeben muss, damit die Funktion bei späterer Ausführung auch noch die Variablen mit den passenden Werten hat?

Wzut · 08 Februar 2018, 12:49:30

denke nicht zu umständlich, du bist doch heute schon fast dran mit deinem notify , lösche einfach den Block

Code Auswählen


fhem "setreading Oeltank Oelstand $new_oelstand"; 
fhem "setreading Oeltank last_Runtime1 $currentRuntime1"; 
fhem "setreading Oeltank last_Runtime2 $currentRuntime2"; 
fhem "setreading Oeltank last_consumption $verbrauch"; 
fhem "setreading Oeltank verbrauch_seit_auffuellen $new_verbrauch";

und setzte dafür dein Beispiel von oben ein

Code Auswählen


readingsBeginUpdate($defs{Oeltank}); 
 readingsBulkUpdate($defs{Oeltank},"Oelstand",$new_oelstand); 
 readingsBulkUpdate($defs{Oeltank},"last_Runtime1",$currentRuntime1); 
 readingsBulkUpdate($defs{Oeltank},"last_Runtime2",$currentRuntime2); 
 readingsBulkUpdate($defs{Oeltank},"last_consumption",$verbrauch; 
 readingsBulkUpdate($defs{Oeltank},"verbrauch_seit_auffuellen",$new_verbrauch);
readingsEndUpdate($defs{Oeltank},1)

beim EndUpdate fehlt allerdings auf jeden Fall das ; am Ende -> readingsEndUpdate($defs{Oeltank},1);
kein sleep oder timer notwendig, das ,1 am Ende von EndUpdate sorgt schon für die Events

litronics · 08 Februar 2018, 14:25:33

Zitat von: Wzut am 08 Februar 2018, 12:49:30
denke nicht zu umständlich, du bist doch heute schon fast dran mit deinem notify , lösche einfach den Block
...
kein sleep oder timer notwendig, das ,1 am Ende von EndUpdate sorgt schon für die Events

Wenn das so einfach wäre.
Den Block hatte ich gestern schon ausgetauscht - aber der hat auch keine Logeinträge im DBLog erzeugt.

Heute habe ich dann auf die FHEM-Variante mit sleep umgebaut und ein paar Stunden laufen lassen.

Code Auswählen

		  fhem "sleep 0.1; setreading Oeltank Oelstand $new_oelstand"; 
		  fhem "sleep 0.1; setreading Oeltank last_Runtime1 $currentRuntime1"; 
		  fhem "sleep 0.1; setreading Oeltank last_Runtime2 $currentRuntime2"; 
		  fhem "sleep 0.1; setreading Oeltank last_consumption $verbrauch"; 
		  fhem "sleep 0.1; setreading Oeltank verbrauch_seit_auffuellen $new_verbrauch";

Aber auch mit der bekomme ich keine Logeinträge im DBLog

Parallel hab ich mittlerweile immer ein Fenster mit dem Event-Monitor offen und beobachte die Events. Da kommen regelmäßig Events zu meinem Oeltank - die werden übrigens auch in das Filelog geschrieben - aber eben nicht in das DBLog.

Hat vielleicht noch jemand eine Idee woran das noch liegen kann?

Wzut · 08 Februar 2018, 14:55:25

Dann schau dir mal das an in deiner config aus dem ersten Post :

Code Auswählen

Attributes: 
   DbLogSelectionMode Include

stell das mal um auf Exclude/Include oder Exclude , denn laut command.ref :

ZitatInclude: Nothing will be logged, except the readings specified via regex in the DbLogInclude attribute

litronics · 08 Februar 2018, 15:44:55

Das wäre ja auch das gewünschte Verhalten.
Ich möchte generell keine Logeinträge und an jedem Device festlegen, welche Werte in das Log geschrieben werden. Und bei meinen HTTPMOD Devices funktioniert das so bestens.

In den Attributen meines Oeltanks hab ich folgendes stehen:

Code Auswählen

DbLogInclude
Oelstand,last_consumption,statistik_OelstandDay1,statistik_OelstandDay30,statistik_OelstandDay5

event-min-interval
.*:300

event-on-change-reading
.*

damit sollte er eigentlich wenn eines der Readings geändert wird aber spätestens alle 300 Sekunden ein Event getriggert werden das dann geloggt wird.
Das mit den 300 Sekunden funktioniert überhaupt nicht (auch nicht im FileLog) aber bei Änderungen gibt es die Events.

Aber da fällt mir noch was anderes ein. Könnte es sein, das das DbLogInclude auf dem falschen Device ist. Müsste das an dem Notify hängen??

automatisierer · 08 Februar 2018, 15:58:16

event-min-interval hast du falsch interpretiert. Das ist der geringste Abstand in dem Events generiert werden. Kommt also nach 150 Sekunden ein geänderter Wert, dann wird kein Event generiert. Erst wenn die 300 Sekundenn rum sind, werden bei Änderungen (bei gemeinsamer verwendung mit event-on-change-reading) wieder Events erzeugt.

CoolTux · 08 Februar 2018, 16:39:04

Zitat von: litronics am 08 Februar 2018, 15:44:55
Das wäre ja auch das gewünschte Verhalten.
Ich möchte generell keine Logeinträge und an jedem Device festlegen, welche Werte in das Log geschrieben werden. Und bei meinen HTTPMOD Devices funktioniert das so bestens.

In den Attributen meines Oeltanks hab ich folgendes stehen:
Code Auswählen Erweitern
DbLogInclude Oelstand,last_consumption,statistik_OelstandDay1,statistik_OelstandDay30,statistik_OelstandDay5 event-min-interval .*:300 event-on-change-reading .*

damit sollte er eigentlich wenn eines der Readings geändert wird aber spätestens alle 300 Sekunden ein Event getriggert werden das dann geloggt wird.
Das mit den 300 Sekunden funktioniert überhaupt nicht (auch nicht im FileLog) aber bei Änderungen gibt es die Events.

Aber da fällt mir noch was anderes ein. Könnte es sein, das das DbLogInclude auf dem falschen Device ist. Müsste das an dem Notify hängen??

Am besten erstmal ohne Modifikation testen um zu sehen das es überhaupt geht.

litronics · 08 Februar 2018, 17:17:47

Zitat von: automatisierer am 08 Februar 2018, 15:58:16
event-min-interval hast du falsch interpretiert. Das ist der geringste Abstand in dem Events generiert werden. Kommt also nach 150 Sekunden ein geänderter Wert, dann wird kein Event generiert. Erst wenn die 300 Sekundenn rum sind, werden bei Änderungen (bei gemeinsamer verwendung mit event-on-change-reading) wieder Events erzeugt.

Danke für den Hinweis - das hatte ich tatsächlich falsch verstanden.

Zitat von: CoolTux am 08 Februar 2018, 16:39:04
Am besten erstmal ohne Modifikation testen um zu sehen das es überhaupt geht.

Grundsätzlich funktioniert das DBlog - ich hab ja HTTPMOD Devices (drei Stück an der Zahl) und die loggen fein säuberlich in das FileLog und das DBlog parallel. Nur so lange das DBlog noch nicht so funktioniert, wie ich das mit dem FileLog habe, möchte ich das nicht abschalten.

Ich hab jetzt mal event-min-interval gelöscht und DbLogInclude auf .* gesetzt.
Hoffentlich funktioniert das...

Wenn nicht, werde ich im DBlog mal den DbLogSelectionMode auf exclude stellen. Wenn ich die commandref richtig interpretiere, dann müssten damit ALLE Events in der LogDB landen. OK so lange sie nicht mit DbLogExclude am Device ausgeschlossen werden - aber nachdem es dieses Attribut nicht ein einziges Mal in meiner Config gibt, müsste jedes Event im Log landen.

Bin gespannt ob spätestens dann das Dummy geloggt wird...

CoolTux · 08 Februar 2018, 17:58:01

Sorry ich meinte damit das du event-on-* Mal komplett vom Dummy weg nehmen solltest.

litronics · 08 Februar 2018, 18:26:27

Nachdem die letzten Änderungen auch nicht die Lösung gebracht haben, hab ich jetzt alle event-on* Attribute gelöscht.

Danach bleibt mir jetzt nur noch DbLogSelectionMode auf Exclude zu stellen und zu hoffen, dass zumindest dann was geloggt wird.

litronics · 09 Februar 2018, 07:28:22

Jetzt bin ich komplett ratlos und brauche eure Hilfe!

Gestern Aband habe ich noch mein DBlog auf DbLogSelectionMode Exclude gestellt.
Heute Morgen schaue ich rein und siehe da im DBlog sind so ziemlich (ich hab die nicht nachgezählt) alle anderen Readings enthalten - aber nicht ein Einziges von dem Oeltank!

Ich verwende zu meiner Rolladensteuerung auch Dummies - sogar für die wurde der State geloggt.
Der Unterschied ist, dass ich bei den Rolladen-Dummies nur den State verwende und keine Userreadings. Bei dem Oeltank verwende ich NUR Userreadings und der State ist mir egal.

An der Stelle bin ich jetzt mit meinem Latein echt am Ende - hat von euch noch jemand eine Idee?

DS_Starter · 09 Februar 2018, 12:44:38

Jetzt benötigt man etwas mehr Einblick.
Setze dir bitte das Attr "verbose4Devs = Oeltank", also den Deviceamen und danach verbose 5 im DbLog. Das Attribut erhöht die Übersichtlichkeit um nur das interessierende Device im Log zu finden.

Dann schau mal nach solchen Abschnitten:

Code Auswählen


2018.02.09 12:31:30.722 4: DbLog LogDB -> ################################################################
2018.02.09 12:31:30.724 4: DbLog LogDB -> ###              start of new Logcycle                       ###
2018.02.09 12:31:30.724 4: DbLog LogDB -> ################################################################
2018.02.09 12:31:30.725 4: DbLog LogDB -> number of events received: 5 for device: MySTP_5000
2018.02.09 12:31:30.729 4: DbLog LogDB -> check Device: MySTP_5000 , Event: modulstate: normal
2018.02.09 12:31:30.730 5: DbLog LogDB -> parsed Event: MySTP_5000 , Event: modulstate: normal
2018.02.09 12:31:30.731 4: DbLog LogDB -> check Device: MySTP_5000 , Event: etotal: 18701.847
2018.02.09 12:31:30.732 5: DbLog LogDB -> parsed Event: MySTP_5000 , Event: etotal: 18701.847
2018.02.09 12:31:30.733 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:31:30, Device: MySTP_5000, Type: SMAINVERTER, Event: etotal: 18701.847, Reading: etotal, Value: 18701.847, Unit: 
2018.02.09 12:31:30.734 4: DbLog LogDB -> check Device: MySTP_5000 , Event: etoday: 10.374
2018.02.09 12:31:30.735 5: DbLog LogDB -> parsed Event: MySTP_5000 , Event: etoday: 10.374
2018.02.09 12:31:30.736 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:31:30, Device: MySTP_5000, Type: SMAINVERTER, Event: etoday: 10.374, Reading: etoday, Value: 10.374, Unit: 
2018.02.09 12:31:30.737 4: DbLog LogDB -> check Device: MySTP_5000 , Event: total_pac: 4.549
2018.02.09 12:31:30.738 5: DbLog LogDB -> parsed Event: MySTP_5000 , Event: total_pac: 4.549
2018.02.09 12:31:30.739 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:31:30, Device: MySTP_5000, Type: SMAINVERTER, Event: total_pac: 4.549, Reading: total_pac, Value: 4.549, Unit: 
2018.02.09 12:31:30.740 4: DbLog LogDB -> check Device: MySTP_5000 , Event: 4.549
2018.02.09 12:31:30.741 5: DbLog LogDB -> parsed Event: MySTP_5000 , Event: 4.549
2018.02.09 12:31:30.741 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:31:30, Device: MySTP_5000, Type: SMAINVERTER, Event: 4.549, Reading: state, Value: 4.549, Unit:

"check Device:" heißt DbLog hat einen Event von Device x erhalten.
"parsed Event:" zeigt das was nach dem Eventparserdurchlauf vom Event geblieben ist.
"added Event:" heißt der Eintrag wurde nach Regex-Bewertung, Exlude/Include-Bewertung dem Cache zugefügt und wird demnächst in die DB geschrieben.

(Die Meldungen setzen ein recht aktuelles DbLog voraus, am Besten updaten falls recht lange her)

Das ist ein Beispiel für den asynchronen Betriebsmodus. Schau mal ob deine Events vom Öltank hier auftauchen.
Ich selbst logge genügend Dummy-Events, also am Dummy-Device als solches liegt es sicher nicht.

Hier noch ein Beispiel für einen Dummy-Eintrag:

Code Auswählen


2018.02.09 12:56:30.487 4: DbLog LogDB -> ################################################################
2018.02.09 12:56:30.488 4: DbLog LogDB -> ###              start of new Logcycle                       ###
2018.02.09 12:56:30.488 4: DbLog LogDB -> ################################################################
2018.02.09 12:56:30.489 4: DbLog LogDB -> number of events received: 2 for device: Dum.Energy
2018.02.09 12:56:30.492 4: DbLog LogDB -> check Device: Dum.Energy , Event: PV: 1412.0
2018.02.09 12:56:30.493 5: DbLog LogDB -> parsed Event: Dum.Energy , Event: PV: 1412.0
2018.02.09 12:56:30.493 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:56:30, Device: Dum.Energy, Type: DUMMY, Event: PV: 1412.0, Reading: PV, Value: 1412.0, Unit: 
2018.02.09 12:56:30.494 4: DbLog LogDB -> check Device: Dum.Energy , Event: T: 614.5
2018.02.09 12:56:30.495 5: DbLog LogDB -> parsed Event: Dum.Energy , Event: T: 614.5
2018.02.09 12:56:30.495 4: DbLog LogDB -> added event - Timestamp: 2018-02-09 12:56:30, Device: Dum.Energy, Type: DUMMY, Event: T: 614.5, Reading: T, Value: 614.5, Unit:

Grüße
Heiko

litronics · 09 Februar 2018, 13:34:25

Hallo Heiko,

ich hab jetzt wieder ein paar neue Erkenntnisse gewonnen

Tatsächlich ist es so, dass DBlog meinen Oeltank Dummy NUR in die history-Tabelle schreibt und NICHT in die current-Tabelle.
Ich hab immer in der current-Tabelle gesucht, weil da laut Doku immer die letzten Werte drin stehen (was ja bei den anderen Readings auch so ist).

Gerade habe ich meine beiden Tabellen mal wieder geleert und werde das nochmal beobachten.
Das Logging schraube ich dann auch mal hoch - vielleicht sieht man ja darin was.

DS_Starter · 09 Februar 2018, 13:44:29

Ok, und jetzt mach bitte noch einen set configCheck. Schön wäre es wenn du die aktellste Version einsetzt.
Achja ... damit in die current geschrieben wird, musst du das Attr "DbLogType = Current/History" setzen !

EDIT: mit version 3.2.0 am 6.12.2017 hatte ich mal einen Bugfix bzgl. current-Update eingebaut. Vllt. ist es das bei dir weil du nach 2.x.x hattest
# 3.2.0 06.12.2017 change attribute "autocommit" to "commitMode", activate choice of autocommit/transaction in logging
# Addlog/addCacheLine change $TIMESTAMP check,
# rebuild DbLog_Push/DbLog_PushAsync due to bugfix in update current (Forum:#80519),

Grüße
Heiko

litronics · 09 Februar 2018, 15:13:05

Ich hatte DbLogType auf Current/History gesetzt und bin eben davon ausgegangen, dass die Werte in beide geschrieben werden.

Der ConfigCheck hat auch bei allen Punkten sein OK gegeben und da sollte auch kein Problem gewesen sein.

Was jetzt aber mega seltsam ist...

Es funktioniert jetzt aktuell anscheinend einwandfrei - genau so, wie ich es eigentlich ursprünglich haben wollte.

Um die Änderungen und die Ergebnisse nochmal chronologisch zusammenzufassen:

1. Ändern von DbLogSelectionMode von Internal auf External --> es wurden alle Events geloggt - aber der Oeltank (und evtl. noch ein paar andere Events) NUR in die history nicht in current
2. Ändern von DbLogSelectionMode zurück auf Internal, verbose Logging aktiviert und SQL Tabellen geleert (mit DELETE * from history / current where timestamp >1)
3. Jetzt wird das Dummy in Current und History geloggt - aber es sind noch nicht alle anderen Readings (die vorher auch da waren) in current.

Das mit dem Versionshinweis war auch nicht falsch. Da war tatsächlich eine uralte Version (2.22.14) installiert - kann es sein, dass die im Installations-Repository nicht aktuell ist? Im November hatte ich erst ein update all gemacht und bin eigentlich davon ausgegangen, dass ich recht aktuell unterwegs bin.

Wie auch immer - jetzt läuft die 3.8.4.
Welchen Einfluss jetzt die alte Version hatte, kann ich natürlich nicht sagen - aber ich hoffe, dass jetzt alles funktioniert, auch wenn ich nicht verstehe, wo das Problem war.