Unerklärlicher watchdog Trigger

FhemPiUser · 10 Juli 2017, 13:36:28

Ich habe einen weiteren für mich unerklärlichen watchdog-Trigger identifiziert:

Trigger war um 10:29 Uhr laut DeviceOverview:

Code Auswählen

Triggered triggered 2017-06-24 10:29:55

Der sollte getriggert werden, wenn >15min das Wasser läuft:

Code Auswählen

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:

Code Auswählen

 	
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).

Code Auswählen

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?

amenomade · 10 Juli 2017, 15:28:14

Poste mal ein "list" vom watchdog und vom CUL_EM_10 Device.

Was sind die Events, die CUL_EM_10 im Eventmonitor generiert?

FhemPiUser · 10 Juli 2017, 16:16:43

list ist:

Code Auswählen

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:

Code Auswählen

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

amenomade · 10 Juli 2017, 21:12:17

Das ist aber inkohärent:

Code Auswählen

     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?

FhemPiUser · 10 Juli 2017, 21:27:38

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?

amenomade · 10 Juli 2017, 22:21:04

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"

amenomade · 10 Juli 2017, 22:28:07

Ü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.

amenomade · 10 Juli 2017, 22:46:38

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.

FhemPiUser · 11 Juli 2017, 23:05:03

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...

amenomade · 11 Juli 2017, 23:42:59

Zitataber das sollte nicht dazu führen, dass der watchdog fälschlicherweise getriggert wird.

Stimmt. Aber... fälschlicherweise? sicher?

FhemPiUser · 12 Juli 2017, 21:25:34

ok, sagen wir für mich unerklärlich, warum er getriggert wurde...

rudolfkoenig · 16 Juli 2017, 19:05:36

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.

FhemPiUser · 16 Juli 2017, 19:37:45

gerne, anbei ein list:

Code Auswählen

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") }

rudolfkoenig · 16 Juli 2017, 20:00:21

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.

FhemPiUser · 16 Juli 2017, 20:35:34

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?

Code Auswählen

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...