93_DbLog: unartiges Verhalten von set ... addLog

[betateilchen]

Code Auswählen Erweitern


set dbLog addLog mqtt_GW1:warnstatus 50


führt dazu, dass ganz merkwürdige Dinge gespeichert werden, sofern das reading "warnstatus" (noch) nicht existiert.

Für mich ist das ein klarer Bug.
Entweder sollte in diesem Fall

• trotzdem der Wert 50 im explizit angegeben Reading gespeichert werden
• oder eine entsprechende Fehlermeldung im Log ausgegeben werden, dass das Reading nicht existiert

Das hier ist für mich keine Fehlermeldung, schon gar nicht, wenn sie im Loglevel 4 auftritt:

Code Auswählen Erweitern

2018.04.13 20:06:55 4: DbLog dbLog -> no Reading of device 'mqtt_GW1' selected from 'warnstatus' used by addLog !

Für mich wäre das erste Verhalten die beste Lösung. Wenn ich ein Reading mit einem beliebigen Namen geloggt haben möchte, dann will ich das wirklich.

Den Wert einfach in state zu schreiben, kann u.U. zu sehr unschönen Ergebnissen führen.

Code Auswählen Erweitern


2018.04.13 20:06:55 1: DEBUG>set dbLog addLog mqtt_GW1:warnstatus 50
2018.04.13 20:06:55 4: DbLog dbLog -> Addlog known devices by devspec: mqtt_GW1
2018.04.13 20:06:55 4: DbLog dbLog -> Readings extracted from Regex:
2018.04.13 20:06:55 4: DbLog dbLog -> no Reading of device 'mqtt_GW1' selected from 'warnstatus' used by addLog !
2018.04.13 20:06:55 4: DbLog dbLog -> ################################################################
2018.04.13 20:06:55 4: DbLog dbLog -> ###              start of new Logcycle                       ###
2018.04.13 20:06:55 4: DbLog dbLog -> ################################################################
2018.04.13 20:06:55 4: DbLog dbLog -> number of events received: 1 for device: dbLog
2018.04.13 20:06:55 4: DbLog dbLog -> check Device: dbLog , Event: addLog mqtt_GW1:warnstatus 50
2018.04.13 20:06:55 5: DbLog dbLog -> parsed Event: dbLog , Event: addLog mqtt_GW1:warnstatus 50
2018.04.13 20:06:55 4: DbLog dbLog -> added event - Timestamp: 2018-04-13 20:06:55, Device: dbLog, Type: DBLOG, Event: addLog mqtt_GW1:warnstatus 50, Reading: state, Value: addLog mqtt_GW1:warnstatus 50, Unit:
2018.04.13 20:06:55 4: DbLog dbLog -> ################################################################
2018.04.13 20:06:55 4: DbLog dbLog -> ###         New database processing cycle - synchronous      ###
2018.04.13 20:06:55 4: DbLog dbLog -> ################################################################
2018.04.13 20:06:55 4: DbLog dbLog -> DbLogType is: Current/History
2018.04.13 20:06:55 4: DbLog dbLog -> AutoCommit mode: ON, Transaction mode: ON
2018.04.13 20:06:55 5: DbLog dbLog -> Primary Key used in fhemaws.history: none
2018.04.13 20:06:55 5: DbLog dbLog -> Primary Key used in fhemaws.current: none
2018.04.13 20:06:55 4: DbLog dbLog -> processing event Timestamp: 2018-04-13 20:06:55, Device: dbLog, Type: DBLOG, Event: addLog mqtt_GW1:warnstatus 50, Reading: state, Value: addLog mqtt_GW1:warnstatus 50, Unit:
2018.04.13 20:06:55 4: DbLog dbLog -> 1 of 1 events inserted into table history
2018.04.13 20:06:55 4: DbLog dbLog -> insert table history committed by autocommit
2018.04.13 20:06:55 4: DbLog dbLog -> 1 of 1 events updated in table current
2018.04.13 20:06:55 4: DbLog dbLog -> insert / update table current committed by autocommit
2018.04.13 20:06:55 5: DbLog dbLog -> DbLog_Push Returncode: 0


[betateilchen]

ich habe im Eingangs-Post den Text in ein real existierendes Beispiel geändert.

Wenn ich im device mqtt_GW1 das reading warnstatus anlege, funktioniert alles wie gewünscht.

[DS_Starter]

Hallo Udo,

dass die Meldung bzgl. kein gefundenes Reading nur mit Level 4 kommt, resultiert daraus, dass dies eher als Hinweis zu verstehen war und nicht als Fehlermeldung.  Das wiederum kam aus der Überlegung heraus, dass der User nur Readings loggen wird, die es tatsächlich auch gibt.

Aber du hast recht dies eher als Fehler zu werten. Das Level kann ich gerne nach 2 ändern ... mach ich.

Den Wert einfach in state zu schreiben, kann u.U. zu sehr unschönen Ergebnissen führen.

Das war nicht geplant und ich bin auch gerade beim suchen wieso das passiert bzw. ein Event mit addlog generiert wird.
Das passiert nämlich nur wenn das Reading nicht existiert und auch nur im synchronen Modus. Wenn ich das gefunden habe gibts auch keine unschönen DB-Einträge in einem solchen Fall.

Grüße
Heiko

[DS_Starter]

Habe erstmal die Änderung bzgl. des verbose level eingecheckt.
Die Geschichte mit dem addlog-Event in der speziellen Situation blicke ich heute nicht mehr und schaue morgen nochmal danach.

Als Workaround kann man im DbLog zunächst das Attribut

Code Auswählen Erweitern


excludeDevs <DbLog-name>


setzen um Events des DbLog-Device selbst vom Logging auszuschließen.

LG,
Heiko

[betateilchen]

Als Workaround kann man im DbLog zunächst das Attribut
setzen um Events des DbLog-Device selbst vom Logging auszuschließen.

Danke fürs Kümmern. Der Workaround bei mir war, das reading im device einfach einmal per setreading manuell anzulegen.

Der (wenn auch falsche) Eintrag zum DbLog stört mich nicht so sehr. Was mich viel mehr stört, ist die Tatsache, dass die Werte für "warnstatus" nicht im Log stehen und ich gestern zwei Stunden gebraucht habe, um herauszufinden, warum addLog zwar korrekt aufgerufen wird, die Werte aus dem device aber trotzdem nicht geplottet werden konnten 

[DS_Starter]

Ja, das war schlecht ... jetzt mit verbose 2 ist es sicher besser.
Also ich habe schon den ganzen Vormittag damit zugebracht die Ursache für die Eventgenerierung des state in dem (falschen) Fall zu finden und habe dabei fast die letzten grauen Haare verloren. 

Es ist wie verhext, ich setze nirgendwo den state in dem Fall wenn das Reading nicht gefunden wird und trotdem kommt der Event.
Naja vllt. kommt mir später noch eine zündende Idee....
Bleibe jedenfalls dran.

Schönes WE!
Heiko

[betateilchen]

Lass Dir nicht das Wochenende versauen, ich hab das "Problem" ja für mich bereits per Workaround gelöst.

Wenn es mal wieder regnet, schau ich auch mal in das Modul, vielleicht fällt mir was auf. Aber heute ist definitiv Eiscafe-Wetter hier in Heidelberg.

Achja: meine bevorzugte Lösung wäre tatsächlich, das reading mit dem angegebenen Wert zu loggen, selbst wenn es im device nicht exisitiert.

[DS_Starter]

Wenn es mal wieder regnet, schau ich auch mal in das Modul, vielleicht fällt mir was auf. Aber heute ist definitiv Eiscafe-Wetter hier in Heidelberg.

Habs gefunden Udo.  Hab ewig viel gesucht und probiert. Letztlich stand der Lösungsansatz sogar in der DevelopmentModuleIntro im Wiki, nämlich:

Standardmäßig wird jeder Set-Befehl, welcher erfolgreich ausgeführt wurde ($error ist undef), als Event getriggert um dies bspw. in einem FileLog festzuhalten. Dieses Verhalten kann optional unterbunden werden indem der zweite Rückgabewert $skip_trigger auf 1 gesetzt wird. Damit wird das Generieren eines Events für das erfolgreich ausgeführte Set-Kommando unterbunden. Falls nicht gesetzt, wird ein Event erzeugt ($cmd mit sämtlichen @args).

Wer lesen kann ....  Man kann auch einfach innerhalb der addLog-sub einen beliebigen Event setzen, zum Beipiel

Code Auswählen Erweitern

readingsSingleUpdate($hash, 'CacheUsage', $memcount, x);

um das Gleiche zu erreichen. Das passiert auch wenn Device/readings gefunden werden, deswegen wird dieser Event nur erzeugt wenn es keine Findung gibt.
Naja, das hat mich jetzt einige graue Haare gekostet. 

Achja: meine bevorzugte Lösung wäre tatsächlich, das reading mit dem angegebenen Wert zu loggen, selbst wenn es im device nicht exisitiert.

Mal schauen. Man kann eben auch "devspec:regex" angeben, also zum Beispiel "USV:battery.*".  Dann müsste man vorher prüfen ob das Reading nicht als Regex angegeben ist um es dann "durchzudrücken". Bei Vorliegen von Regex natürlich nicht.

Aber jetzt checke ich erstmal die Version ein damit der Event nicht mehr generiert wird.

Grüße,
Heiko

[betateilchen]

Danke für Deine Bemühungen

Mal schauen. Man kann eben auch "devspec:regex" angeben, also zum Beispiel "USV:battery.*".  Dann müsste man vorher prüfen ob das Reading nicht als Regex angegeben ist um es dann "durchzudrücken". Bei Vorliegen von Regex natürlich nicht.

Dass ein Reading in einem device ggf. zu einem Zeitpunkt X "nicht mehr" oder "noch nicht" vorhanden ist, ist ja nichts Aussergewöhnliches. Deshalb kann es trotzdem (insbesondere historische) Einträge im Log geben, die man z.B. per plot auswerten möchte.

In meinem speziellen Fall geht es um einen Blitz-Zähler, für den ich natürlich ein reading anlegen könnte. Aber ausser der Information, wann der letzte Blitz erkannt wurde, hätte das reading keinerlei Aussagekraft. Deshalb war meine Idee, den Blitz direkt als Zahlenwert in das Log zu schreiben.

[DS_Starter]

Ich mache mir mal ein paar Gedanken dazu wie man es in das vorhandene Konstrukt einbauen könnte. Wie gesagt, eigentlich nur schauen ob das Reading als Regex vorliegt oder nicht. Wenn nicht kann das addLog problemlos durchgeführt werden.... so meine Idee.
Ich bleibe dran 

Grüße,
Heiko

[betateilchen]

Hallo Heiko,

vielleicht hilft Dir das irgendwie weiter...

Code Auswählen Erweitern


list mqtt_Wetter

Internals:
... uninteressant ...

   READINGS:
     2018-04-17 08:16:25   Rain_heating    off
     2018-04-17 08:16:25   Rain_lastRain   2018-04-17 07:59:22
     2018-04-17 08:16:25   Rain_rain       000

... Rest auch uninteressant ...


dazu in meiner 99_myUtils.pm mal eben eingebaut:

Code Auswählen Erweitern


sub rr($) {
  my ($readingspec) = @_;
  my $dev = 'mqtt_Wetter';
  return ( grep { /$readingspec/ } keys %{$defs{$dev}{READINGS}} )
}


Wenn ich {rr 'Rain_blub'} ausführe, bekomme ich als Rückgabewert eine 0, weil es kein passendes reading gibt.
Wenn ich {rr 'Rain_rain'} ausführe, bekomme ich als Rückgabewert eine 1, weil es ein reading gibt, das passt.
Wenn ich {rr 'Rain_.*'} ausführe, bekomme ich als Rückgabewert eine 3, weil es drei readings gibt.

[DS_Starter]

Hallo Udo,

danke für deinen Hinweis !

Ich komme erst wieder Freitag dazu mich dem Thema nochmal zu widmen. Dann schaue ich es mir im Kontext genauer an und stöbere auch in der fhem.pl ob Rudi eventuell schon eine sub bereitstellt wie IsRegex ähnlich dem IsDisabled. Also return 1 wenn der zu untersuchende String ein regulärer Ausdruck ist oder so etwas.

Melde mich wieder wenn ich was gebaut und getestet habe .....

Bis dahin,
Heiko

[betateilchen]

und stöbere auch in der fhem.pl ob Rudi eventuell schon

schau mal in die Funktion devspec2array, da siehst Du, wie Rudi auf regexp prüft

Und mach Dir keinen allzu großen Streß, ich hab das Problem ja im Griff, man muss es eben nur mal als Problem erkannt haben

[DS_Starter]

Nun habe ich nach längerem hin und her sowie diversen Tests auf Rudis Funktion "goodReadingName" zurückgegriffen.
Dadurch wird gleich geprüft ob das angegebene (neue) Reading im Sinne von FHEM auch valide ist.   Sollte der angegebene Ausdruck ein Regexp sein, würde dieser dadurch ebenfalls nicht als valider Readingname anerkannt werden. (Zumindest kann ich es mir keine Situation vorstellen wo es so wäre)

D.h. wird jetzt ein nicht vorhandenes Reading eines Devices mit einem Wert angegeben (macht ja sonst keinen Sinn), wird dieses Reading in die DB eingefügt wenn es den Regularien entspricht. Werden die Namensregeln verletzt gibt es einen Logeintrag damit man darauf hingewiesen wird.

Ich habe die neue Version mal hier angehängt und werde über das WE auch noch ein paar Szenarien testen. Aber bis jetzt fügt sich die Neuerung nahtlos in die vorhandene Syntax ein und macht was sie soll.

wünsche ein sonniges WE und LG !
Heiko

[betateilchen]

klingt gut, danke. Werde mir das kurzfristig mal anschauen.