[gelöst] Bug? Status wird mit fremden Logeinträgen überschrieben

[Damian]

Es wurden von Usern Probleme mit dem Status im DOIF-Modul gemeldet, die ich bei mir auch zufällig nachvollziehen konnte.

Es handelt sich um Logeinträge von anderen Modulen. Da es sich um fremde Informationen handelt, die es im eigenen Modul so nicht gibt, vermute ich, dass etwas an einer zentralen Stelle schief läuft evtl. in fhem.pl.

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

In meinem System kann ich so etwas sehen:

Internals:
   DEF        ([TH_WZ_HM:measured-temp] > 23 and [Sonne_w] eq "on" and [15:30-21:00])
(set R_W_W1 40, set R_W_W2 25, set R_W_W3 25)

   MODEL      FHEM
   NAME       di_Wohnzimmer_w_b
   NR         220
   NTFY_ORDER 50-di_Wohnzimmer_w_b
  STATE      2019.04.04 23:29:45.072 5 : CUL_HM Tuer protEvent:CMDs_processing... pending:0
   TYPE       DOIF
   VERSION    18890 2019-03-13 18:56:41
   READINGS:
     2019-04-15 08:26:52   Device          TH_WZ_HM
     2018-10-15 16:45:49   cmd             2
     2018-10-15 16:45:49   cmd_event       Sonne_w
     2018-10-15 16:45:49   cmd_nr          2
     2019-04-14 17:59:56   e_Sonne_w_STATE off
     2019-04-15 08:26:52   e_TH_WZ_HM_measured-temp 21.0
     2018-06-01 17:40:23   mode            enabled
     2019-04-04 23:29:45   state           2019.04.04 23:29:45.072 5 : CUL_HM Tuer protEvent:CMDs_processing... pending:0
     2018-09-23 21:15:45   test1           bla1
     2018-09-23 21:15:45   test2           bla2
     2019-04-14 21:00:00   timer_01_c01    15.04.2019 15:30:00
     2019-04-14 21:00:00   timer_02_c01    15.04.2019 21:00:00
     2019-02-23 20:16:43   version         18557 2019-02-10 16:58:11
     2018-10-15 16:45:49   wait_timer      no timer

Die Meldung kommt aus der HM-Abteilung und hat nichts dem DOIF-Modul zu tun. Auch das Device Tuer wird in dieser Definition nicht benutzt.

Wurde ggf. im Logmechanismus etwas geändert?

Der Zeitpunkt des Überschreibens stimmt mit dem Zeitpunkt des Loggens überein.

[rudolfkoenig]

Mir ist keine Aenderung bekannt, was in diesem Bereich Schaden anrichten koennte.

[CoolTux]

Der Zeitpunkt des Überschreibens stimmt mit dem Zeitpunkt des Loggens überein.

Loggen eines HM Gerätes oder Loggen eines DOIF Gerätes?

[Damian]

Von wem der Logeintrag kommt, kannst du doch am Logeintrag selbst sehen:

2019.04.04 23:29:45.072 5 : CUL_HM Tuer protEvent:CMDs_processing... pending:0

DOIF hat regulär seinen Status am 2018-10-15 16:45:49 gesetzt, der wird immer mit anderen Readings z. B. cmd gesetzt.

[CoolTux]

Eine Lösung für das Problem habe ich nicht.
Einzug einen sehr wagen Ansatz.

Es gibt ja die Möglichkeit das globale Logausgaben ein Event generieren. Ist das einzige was mir ein fällt dazu.

[Damian]

Eine Lösung für das Problem habe ich nicht.
Einzug einen sehr wagen Ansatz.

Es gibt ja die Möglichkeit das globale Logausgaben ein Event generieren. Ist das einzige was mir ein fällt dazu.

ja, aber in diesem Fall werden keine Events vom Device "Tuer" ausgewertet und schon gar nicht im Status abgelegt. Wenn man sich etwas im Speicher zerschießen würde, dann nicht so, dass ein kompletter Log-Eintrag sauber im Status landet.

[CoolTux]

OK, es legt also die Vermutung nahe das in der Tat in das state Reading einer DOIF Instanz geschrieben wird.
Hast Du mal geschaut ob es im CUL_HM Modul seltsamen Code zum Logging gibt oder einfach wie üblich Log3() genommen wurde? Hab da schon die Verrücktesten Umbiegungen gesehen.

[Damian]

OK, es legt also die Vermutung nahe das in der Tat in das state Reading einer DOIF Instanz geschrieben wird.
Hast Du mal geschaut ob es im CUL_HM Modul seltsamen Code zum Logging gibt oder einfach wie üblich Log3() genommen wurde? Hab da schon die Verrücktesten Umbiegungen gesehen.

Ich habe auch schon CUL_HM im Verdacht gehabt, da alle drei überschriebene DOIF-Status von da kamen, leider wird meine Vermutung mit dieser Meldung widerlegt:

https://forum.fhem.de/index.php/topic,99511.msg929066.html#msg929066

Diese Eintrag kommt wohl nicht von HM:

2019-04-10 10:38:58   state           2019.04.10 10:38:58 1 : Timeout for XiaomiBTLESens::ExecGatttool_Run reached, terminated process 23663

Auf jeden Fall ist der Auslöser der Loggende selbst, denn mit dem Logeintrag wird der Status geändert, das sieht man am Zeitstempel.

[rudolfkoenig]

Ich kriege sowas mit folgendem Konstrukt hin:

Code Auswählen Erweitern

define d dummy
defmod n notify .*test.* setreading d state $EVENT
attr n readLog
{ Log 1, "test me" }
l d
Internals:
   FUUID      5cb428ae-f33f-c296-6e60-412432a99570eb7f
   NAME       d
   NR         7
   STATE      2019.04.15 09:50:18 1 : test me
   TYPE       dummy
   READINGS:
     2019-04-15 09:50:18   state           2019.04.15 09:50:18 1 : test me
Vielleicht steht sowas in der Art in einem der Wiki/Blog/Forum Beispiele.

[CoolTux]

Ich habe auch schon CUL_HM im Verdacht gehabt, da alle drei überschriebene DOIF-Status von da kamen, leider wird meine Vermutung mit dieser Meldung widerlegt:

https://forum.fhem.de/index.php/topic,99511.msg929066.html#msg929066

Diese Eintrag kommt wohl nicht von HM:

2019-04-10 10:38:58   state           2019.04.10 10:38:58 1 : Timeout for XiaomiBTLESens::ExecGatttool_Run reached, terminated process 23663

Auf jeden Fall ist der Auslöser der Loggende selbst, denn mit dem Logeintrag wird der Status geändert, das sieht man am Zeitstempel.

Interessant und gutes Beispiel 
Bin erstmal unterwegs. Werde aber weiter drüber nach denken.

[Damian]

Ich habe gerade meine cfg nach readLog durchsucht - kein Treffer.

[rudolfkoenig]

Ich habe gerade meine cfg nach readLog durchsucht - kein Treffer.

logInform wird von den Modulen FHEMWEB (wg. EventMonitor), telnet, notify, Log2Syslog und MSwitch verwendet.
FHEMWEB und telnet kommen nicht in Betracht, sie setzen keine Werte in fremden devicehash.

[betateilchen]

Anmerkung:
Das beschriebene Phänomen hatte ich identisch vor langer Zeit (mindestens zwei Jahre) auch schonmal in meinen FHEM Installationen (in denen es keine DOIF gibt).
Nach ein paar Tagen war der Spuk dann wieder vorbei, deshalb hatte ich der Sache damals keine weitere Beachtung geschenkt.

[Damian]

Bevor man weiter sucht. Ich habe eine verdächtige Definition bei mir ausfindig gemacht, die ich auf Nachfrage formuliert habe, die vermutlich das Problem verursacht, siehe: https://forum.fhem.de/index.php/topic,99203.msg926068.html#msg926068

Edit: Problem erkannt und behoben: https://forum.fhem.de/index.php/topic,99511.msg930350.html#msg930350