Ich habe einen weiteren für mich unerklärlichen watchdog-Trigger identifiziert:
Trigger war um 10:29 Uhr laut DeviceOverview:
Triggered triggered 2017-06-24 10:29:55
Der sollte getriggert werden, wenn >15min das Wasser läuft:
define w_WasserLeckage_U watchdog CUL_EM_10:wasserentnahme:.on.* 00:16 CUL_EM_10:wasserentnahme:.off.* { fhem("set Wasser_Stellventil off"); &TriggerAlarmWasser("Wasser läuft seit >15min!"); }
wasserentnahme ist ein CUL_EM_10 device UserReading, welches abhängig vom CUL_EM current Wert gesteuert wird:
wasserentnahme { (ReadingsVal("CUL_EM_10","current",0) > 0 ? "on" : "off"); }
Aber zu der betreffenden Zeit lief nicht 15min lang das Wasser laut Log des CUL_EM. Der 5min-Wert zeigt, dass zwischen 10:13-10:18 das Wasser kurz lief (5min-Wert > 0) und zwischen 10:28-10:33, aber dazwischen nicht (5min-Wert == 0).
2017-06-24_09:58:53 CUL_EM_10 CNT: 229 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:03:54 CUL_EM_10 CNT: 230 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:08:54 CUL_EM_10 CNT: 231 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:13:55 CUL_EM_10 CNT: 232 CUM: 162.220 5MIN: 0.001 TOP: 0.000
2017-06-24_10:18:56 CUL_EM_10 CNT: 233 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:23:57 CUL_EM_10 CNT: 234 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:28:58 CUL_EM_10 CNT: 235 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:33:58 CUL_EM_10 CNT: 236 CUM: 162.222 5MIN: 0.002 TOP: 0.000
Jemand eine Idee?
Poste mal ein "list" vom watchdog und vom CUL_EM_10 Device.
Was sind die Events, die CUL_EM_10 im Eventmonitor generiert?
list ist:
Internals:
CMD { &TriggerAlarmWasser("Wasser läuft seit >15min"); }
DEF CUL_EM_10:wasserentnahme:.on.* 00:16 CUL_EM_10:wasserentnahme:.off.* { &TriggerAlarmWasser("Wasser läuft seit >15min"); }
NAME w_WasserLeckage_U
NOTIFYDEV w_WasserLeckage_U,CUL_EM_10
NR 938
NTFY_ORDER 50-w_WasserLeckage_U
RE1 CUL_EM_10:wasserentnahme:.on.*
RE2 CUL_EM_10:wasserentnahme:.off.*
STATE defined
TO 960
TYPE watchdog
Readings:
2017-07-02 05:03:21 Activated activated
2017-06-24 10:29:55 Triggered triggered
2017-07-09 22:27:07 state inactive
Attributes:
disabledForIntervals 18:55-19:10 06:55-07:10
room Wasser
Events sind:
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 CNT: 36 CUM: 162.773 5MIN: 0.000 TOP: 0.000
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 seqno: 36
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 current: 0
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 current_cnt: 0
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 peak_cnt: 20694
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 peak: 0
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 tsecs: 1499696131
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 total_cnt: 20694
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 RAW: CNT: 36 CUM: 20694 5MIN: 0 TOP: 20694
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 total: 162.773
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 wasserentnahme: off
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 seqnodiff: 1
2017-07-10 16:15:31.268 CUL_EM CUL_EM_10 seqnodiffs: 435
Das ist aber inkohärent:
2017-07-02 05:03:21 Activated activated
2017-06-24 10:29:55 Triggered triggered
Activated wurde er am 2.7 um 5:03 => hat CUL_EM_10:wasserentnahme:.on.* bekommen.
Seitdem wartet er... und ist nicht auf "triggered" gekommen; vielleicht weil Du den inzwischen auf inactive gesetzt hast?
¨
Es ware interessant das "activated" zu sehen, das VOR dem "triggered" vom 24.6 passiert ist. Hast Du es in irgendwelcher Log?
Zwei Fragen dazu?
1) Warum ist das inkohärent? Er war am 24.6. aktiviert, sonst hätte er ja nicht getriggert werden können, oder? Er wurde danach zwischenzeitlich deaktiviert und am 2.7. erneut aktiviert.
2) Inwiefern kann der Status activated/inactivated damit zu tun haben, dass er watchdog fälschlicherweise getriggered wurde?
Dann hätten wir die Zeit zwischen "activated" (Next:?? ) und "trigerred" sehen können. Ob es 16 Minuten genau war. Hier fehlen Informationen, um das Problem zu analysieren. Wurde das Ding früher gestartet, als was du glaubst, oder durch ein anderes Event? Wurde das Ding tatsächlich vor den 16 Minuten getriggert? Ich kann nicht wissen.
Mit inkohärent meinte ich: activated und triggered gehören nicht zum gleichen "Zug"...
EDIT: vielleicht zur Klärung: ich meine NICHT den Status active/inactive. Ich meine das Reading "Activated"
Übrigens: es fehlt m.A. entweder ein "trigger w_WasserLeckage_U ." am Ende der DEF des Watchdogs, oder das Attribute autoRestart damit dein Watchdog mehrmals funktionieren kann.
Ahja, und noch ein Ding, wenn wir dabei sind:
ZitatdisabledForIntervals 18:55-19:10 06:55-07:10
Ist das wirklich, was Du willst, dass das Notify zwischen 18:55 und 19:10, und auch zwischen 06:55 und 07:10 disabled wird? Finde ich merkwürdig.
stimmt, autostart fehlt. aber das sollte nicht dazu führen, dass der watchdog fälschlicherweise getriggert wird.
die disabled intervals sind so gewollt, da zu den zeitpunkten die automatische gartenbewässerung läuft, die dann keinen alarm auslösen soll...
Zitataber das sollte nicht dazu führen, dass der watchdog fälschlicherweise getriggert wird.
Stimmt. Aber... fälschlicherweise? sicher?
ok, sagen wir für mich unerklärlich, warum er getriggert wurde...
Zitatok, sagen wir für mich unerklärlich, warum er getriggert wurde...
Fuer mich erstmal auch. Habs versucht nachzustellen mit einem dummy als CUL_EM_10 und "setreading CUL_EM_10 current 10", usw. ohne Erfolg. Kannst du bitte noch die komplette Definition von CUL_EM_10 (via Raw definition aus der Detailansicht) hier zeigen?
Falls da mit "event-on-.*" rumgespielt wird, dann kann das den Watchdog austricksen.
gerne, anbei ein list:
Internals:
BasicFeePerMonth 14.61
CODE 10
CUL_0_MSGCNT 247
CUL_0_RAWMSG E030A07E0590000E059
CUL_0_RSSI -76.5
CUL_0_TIME 2017-07-16 19:33:46
CostPerUnit 1.77
DEF 10 0.001 0.001 1.77 14.61
IODev CUL_0
LASTInputDev CUL_0
MSGCNT 247
NAME CUL_EM_10
NR 777
STATE CNT: 7 CUM: 165.087 5MIN: 0.000 TOP: 0.000
TYPE CUL_EM
corr1 0.001
corr2 0.001
READINGS:
2017-07-09 19:32:15 Ausfall 0
2017-07-16 19:33:46 RAW CNT: 7 CUM: 23008 5MIN: 0 TOP: 23008
2017-05-28 14:37:35 basis 142079
2017-07-16 00:00:41 cum_day CUM_DAY: 0.365 CUM: 164.783 COST: 0.65
2017-07-01 00:03:47 cum_month CUM_MONTH: 16.992 CUM: 162.268 COST: 44.69
2017-07-16 19:33:46 current 0
2017-07-16 19:33:46 current_cnt 0
2017-07-16 00:35:02 kumLastMonth 23.243
2017-07-16 00:35:02 kumLastMonthE 70.36
2017-07-16 00:35:02 kumLastYear 83
2017-07-16 00:35:02 kumLastYearE 250
2017-07-16 00:35:02 kumThisMonth 5
2017-07-16 00:35:02 kumThisMonthE 23
2016-08-08 20:40:43 kumThisMonthLast 0
2017-07-16 00:35:02 kumThisYear 302
2017-07-16 00:35:02 kumThisYearE 903
2017-07-16 00:35:02 kumlinesStr 83
2017-07-16 00:35:02 kumlinesStrE 249
2017-07-16 00:35:02 kumlineslastStr 23
2017-07-16 00:35:02 kumproz +259
2017-07-16 19:33:46 peak 0
2017-07-16 19:33:46 peak_cnt 23008
2017-07-16 00:35:02 proz -58
2017-07-16 19:33:46 seqno 7
2017-07-16 19:33:46 seqnodiff 1
2017-07-16 19:33:46 seqnodiffs 477
2017-07-16 19:33:46 state CNT: 7 CUM: 165.087 5MIN: 0.000 TOP: 0.000
2017-07-16 19:33:46 total 165.087
2017-07-16 19:33:46 total_cnt 23008
2017-07-16 19:33:46 tsecs 1500226426
2017-07-16 19:33:46 wasserentnahme off
Attributes:
IODev CUL_0
room Wasser,CUL_EM
userReadings wasserentnahme { (ReadingsVal("CUL_EM_10","current",0) > 0 ? "on" : "off"); }, seqnodiff difference { ReadingsVal("CUL_EM_10","seqno","0") }, seqnodiffs { ((ReadingsVal("CUL_EM_10","seqnodiff","0") > 1) and (ReadingsVal("CUL_EM_10","seqnodiff","0") < 200)) ? (ReadingsVal("CUL_EM_10","seqnodiff","0")+ReadingsVal("CUL_EM_10","seqnodiffs","0")-1) : ReadingsVal("CUL_EM_10","seqnodiffs","0") }
Zitat...via Raw definition aus der Detailansicht...
...
Zitatgerne, anbei ein list:
Ich sehe schon, meine Wuensche werden auch nicht immer erfuellt. Wie auch immer, ich kann auch mit diesen Attributen keinen Fehler reproduzieren.
Evtl. funkt noch derjenige dazwischen, der die kum* Readings erzeugt, wahrscheinlich ist das aber nicht. Sorry, habe keine Idee.
wusste nicht, was du mit raw definition meinst, ich dachte die raw def der internals, die auch mit list angezeigt wird
vielleicht meintest du das hier?
defmod CUL_EM_10 CUL_EM 10 0.001 0.001 1.77 14.61
attr CUL_EM_10 IODev CUL_0
attr CUL_EM_10 room Wasser,CUL_EM
attr CUL_EM_10 userReadings wasserentnahme { (ReadingsVal("CUL_EM_10","current",0) > 0 ? "on" : "off");; }, seqnodiff difference { ReadingsVal("CUL_EM_10","seqno","0") }, seqnodiffs { ((ReadingsVal("CUL_EM_10","seqnodiff","0") > 1) and (ReadingsVal("CUL_EM_10","seqnodiff","0") < 200)) ? (ReadingsVal("CUL_EM_10","seqnodiff","0")+ReadingsVal("CUL_EM_10","seqnodiffs","0")-1) : ReadingsVal("CUL_EM_10","seqnodiffs","0") }
setstate CUL_EM_10 CNT: 18 CUM: 165.362 5MIN: 0.001 TOP: 0.000
setstate CUL_EM_10 2017-07-09 19:32:15 Ausfall 0
setstate CUL_EM_10 2017-07-16 20:28:54 RAW CNT: 18 CUM: 23283 5MIN: 1 TOP: 23283
setstate CUL_EM_10 2017-05-28 14:37:35 basis 142079
setstate CUL_EM_10 2017-07-16 00:00:41 cum_day CUM_DAY: 0.365 CUM: 164.783 COST: 0.65
setstate CUL_EM_10 2017-07-01 00:03:47 cum_month CUM_MONTH: 16.992 CUM: 162.268 COST: 44.69
setstate CUL_EM_10 2017-07-16 20:28:54 current 0.001
setstate CUL_EM_10 2017-07-16 20:28:54 current_cnt 1
setstate CUL_EM_10 2017-07-16 00:35:02 kumLastMonth 23.243
setstate CUL_EM_10 2017-07-16 00:35:02 kumLastMonthE 70.36
setstate CUL_EM_10 2017-07-16 00:35:02 kumLastYear 83
setstate CUL_EM_10 2017-07-16 00:35:02 kumLastYearE 250
setstate CUL_EM_10 2017-07-16 00:35:02 kumThisMonth 5
setstate CUL_EM_10 2017-07-16 00:35:02 kumThisMonthE 23
setstate CUL_EM_10 2016-08-08 20:40:43 kumThisMonthLast 0
setstate CUL_EM_10 2017-07-16 00:35:02 kumThisYear 302
setstate CUL_EM_10 2017-07-16 00:35:02 kumThisYearE 903
setstate CUL_EM_10 2017-07-16 00:35:02 kumlinesStr 83
setstate CUL_EM_10 2017-07-16 00:35:02 kumlinesStrE 249
setstate CUL_EM_10 2017-07-16 00:35:02 kumlineslastStr 23
setstate CUL_EM_10 2017-07-16 00:35:02 kumproz +259
setstate CUL_EM_10 2017-07-16 20:28:54 peak 0.000128849375080531
setstate CUL_EM_10 2017-07-16 20:28:54 peak_cnt 23283
setstate CUL_EM_10 2017-07-16 00:35:02 proz -58
setstate CUL_EM_10 2017-07-16 20:28:54 seqno 18
setstate CUL_EM_10 2017-07-16 20:28:54 seqnodiff 1
setstate CUL_EM_10 2017-07-16 20:28:54 seqnodiffs 477
setstate CUL_EM_10 2017-07-16 20:28:54 state CNT: 18 CUM: 165.362 5MIN: 0.001 TOP: 0.000
setstate CUL_EM_10 2017-07-16 20:28:54 total 165.362
setstate CUL_EM_10 2017-07-16 20:28:54 total_cnt 23283
setstate CUL_EM_10 2017-07-16 20:28:54 tsecs 1500229734
setstate CUL_EM_10 2017-07-16 20:28:54 wasserentnahme on
der watchdog ist nicht immer aktiv und wird bei bedarf mit set ... active auf active gesetzt...
Zitatvielleicht meintest du das hier?
Ja, das kann ich naemlich mit Copy&Paste uebernehmen. Ist uebrigens die Ausgabe von "list -r Geraetename"
Aendert aber nichts daran, dass ich keine neue Idee habe.
Meine Idee ist, dass der Watchdog doch richtig funktioniert... nur kann man nicht genau feststellen, was passiert ist, da FhemPiUser kein gutes Beispiel zeigt. (siehe https://forum.fhem.de/index.php/topic,74092.msg658106.html#msg658106 )
Die Activated und Triggered Readings sind mAn in Ordnung: Activated zeigt, wann der Watchdog zuletzt den ersten Regexp bekommen hat. Wenn es danach nicht ausloest, weil Regexp2 eintrifft, dann wird der letzte Triggered nicht ueberschrieben. Wenn Regexp2 nicht eintrifft, dann wird ausgeloest, und Triggered gesetzt.
Triggered ist auf die Sekunde genau 16 Minuten nach dem letzten 5MIN, was nicht 0.000 ist. Das entspricht current, und daraus wird wasserentnahme:on. D.h. der watchdog wurde aktiviert, und nach 16 Minuten ausgeloest, vmtl. weil kein wasserentnahme:off eingetroffen ist. Keine Ahnung wieso, laut Daten haetten 3 wasserentnahme:off's eintreffen muessen.
Ja, aber bisher habe ich nur das gesehen:
Readings:
2017-07-02 05:03:21 Activated activated
2017-06-24 10:29:55 Triggered triggered
Da sieht man nicht das "Activated", das VOR dem "Triggered" war, und kann man dann nicht sagen: das Watchdog funktioniert nicht. Deswegen hatte ich folgendes geschrieben:
ZitatActivated wurde er am 2.7 um 5:03 => hat CUL_EM_10:wasserentnahme:.on.* bekommen.
Seitdem wartet er... und ist nicht auf "triggered" gekommen; vielleicht weil Du den inzwischen auf inactive gesetzt hast?
¨
Es ware interessant das "activated" zu sehen, das VOR dem "triggered" vom 24.6 passiert ist. Hast Du es in irgendwelcher Log?
Nur wenn wir folgendes hätten:
Readings:
2017-06-24 10:27:55 Activated activated
2017-06-24 10:29:55 Triggered triggered
könnte man sagen: das Watchdog spinnt.
Es fehlen Informationen (die Reihenfolge von allen Events), um zu sagen " das Watchdog hat ein Bug".
Watchdog "fälschlicherweise getriggert"? Was beweisst das?
Ausserdem haben wir:
Triggered triggered 2017-06-24 10:29:55
Und
2017-06-24_09:58:53 CUL_EM_10 CNT: 229 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:03:54 CUL_EM_10 CNT: 230 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:08:54 CUL_EM_10 CNT: 231 CUM: 162.219 5MIN: 0.000 TOP: 0.000
2017-06-24_10:13:55 CUL_EM_10 CNT: 232 CUM: 162.220 5MIN: 0.001 TOP: 0.000
2017-06-24_10:18:56 CUL_EM_10 CNT: 233 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:23:57 CUL_EM_10 CNT: 234 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:28:58 CUL_EM_10 CNT: 235 CUM: 162.220 5MIN: 0.000 TOP: 0.000
2017-06-24_10:33:58 CUL_EM_10 CNT: 236 CUM: 162.222 5MIN: 0.002 TOP: 0.000
Naja, ok, anscheinend hat das Watchdog das Wasser um 10:29 ausgeschaltet... aber es war schon seit mind. 10:18 aus. Na und? Was sind die andere Geräte o. Menschen, die das Wasser steuern?