Empfang von CUL_EM Geräten mit mehreren CUL

[pantau]

Ich habe einige Stromzähler, die als CUL_EM Gerät definiert sind.
Außerdem habe ich wegen schlechten Empfang im ganzen Haus 3 CUL verteilt:
- cul direkt am Server per USB angeschlossen
- rcul ist ein CUN0 per LAN angeschlossen
- MyRFR ist ein CUL im CUL_RFR Betrieb das mit cul gepaart ist.

FHEM läuft auf dem aktuellen SVN Stand.

Je nach Empfangssituation finde ich nun in meinen Filelogs bis zu 3x den (fast) gleichen Logeintrag:

2013-04-14_21:56:06 EM_WaKe CNT: 106 CUM: 634.005  5MIN: 0.000  TOP: 0.000
2013-04-14_21:56:06 EM_WaKe tsecs: 1365969366
2013-04-14_21:56:06 EM_WaKe seqno: 106
2013-04-14_21:56:06 EM_WaKe peak: 0
2013-04-14_21:56:06 EM_WaKe total: 634.005
2013-04-14_21:56:06 EM_WaKe current_cnt: 0
2013-04-14_21:56:06 EM_WaKe current: 0
2013-04-14_21:56:06 EM_WaKe total_cnt: 10
2013-04-14_21:56:06 EM_WaKe peak_cnt: 0
2013-04-14_21:56:06 EM_WaKe RAW: CNT: 106 CUM: 10  5MIN: 0  TOP: 0
2013-04-14_21:56:16 EM_WaKe CNT: 106 CUM: 634.005  5MIN: 0.000  TOP: 0.000
2013-04-14_21:56:16 EM_WaKe tsecs: 1365969376
2013-04-14_21:56:16 EM_WaKe seqno: 106
2013-04-14_21:56:16 EM_WaKe peak: 0
2013-04-14_21:56:16 EM_WaKe total: 634.005
2013-04-14_21:56:16 EM_WaKe current_cnt: 0
2013-04-14_21:56:16 EM_WaKe current: 0
2013-04-14_21:56:16 EM_WaKe total_cnt: 10
2013-04-14_21:56:16 EM_WaKe peak_cnt: 0
2013-04-14_21:56:16 EM_WaKe RAW: CNT: 106 CUM: 10  5MIN: 0  TOP: 0
2013-04-14_21:56:26 EM_WaKe CNT: 106 CUM: 634.005  5MIN: 0.000  TOP: 0.000
2013-04-14_21:56:26 EM_WaKe tsecs: 1365969386
2013-04-14_21:56:26 EM_WaKe seqno: 106
2013-04-14_21:56:26 EM_WaKe peak: 0
2013-04-14_21:56:26 EM_WaKe total: 634.005
2013-04-14_21:56:26 EM_WaKe current_cnt: 0
2013-04-14_21:56:26 EM_WaKe current: 0
2013-04-14_21:56:26 EM_WaKe total_cnt: 10
2013-04-14_21:56:26 EM_WaKe peak_cnt: 0
2013-04-14_21:56:26 EM_WaKe RAW: CNT: 106 CUM: 10  5MIN: 0  TOP: 0

tsecs ist als einziges unterschiedlich. Auffällig ist auch, das die Logeinträge immer genau 10sec auseinanderliegen, obwohl sie ja von den 3 Empfängern gleichzeitig empfangen wurden.
Ein list EM_Wake ergibt:

Internals:
   BasicFeePerMonth 0
   CFGFN      /home/FHZ/fhem/em.cfg
   CODE       6
   CostPerUnit 0
   DEF        6 0.01 0.001
   IODev      cul
   LASTInputDev rcul
   MSGCNT     27
   MyRFR_MSGCNT 6
   MyRFR_RAWMSG E02066A0A0000000000EB
   MyRFR_RSSI -84.5
   MyRFR_TIME 2013-04-14 21:56:16
   NAME       EM_WaKe
   NR         75
   NTFY_TRIGGERTIME 2013-04-14 21:56:26
   STATE      CNT: 106 CUM: 634.005  5MIN: 0.000  TOP: 0.000
   TYPE       CUL_EM
   corr1      0.01
   corr2      0.001
   cul_MSGCNT 10
   cul_RAWMSG E02066A0A0000000000DF
   cul_RSSI   -90.5
   cul_TIME   2013-04-14 21:56:06
   rcul_MSGCNT 11
   rcul_RAWMSG E02066A0A000000000003
   rcul_RSSI  -72.5
   rcul_TIME  2013-04-14 21:56:26
   CHANGETIME:
   Readings:
     2013-04-14 21:56:26   RAW             CNT: 106 CUM: 10  5MIN: 0  TOP: 0
     2013-04-14 13:11:05   basis           633995
     2013-04-14 00:03:14   cum_day         CUM_DAY: 0.027 CUM: 633.980 COST: 0.00
     2013-04-01 00:05:05   cum_month       CUM_MONTH: 14.386 CUM: 622.704 COST: 0.00
     2013-04-14 21:56:26   current         0
     2013-04-14 21:56:26   current_cnt     0
     2013-04-14 21:56:26   peak            0
     2013-04-14 21:56:26   peak_cnt        0
     2013-04-14 21:56:26   seqno           106
     2013-04-14 21:56:26   state           CNT: 106 CUM: 634.005  5MIN: 0.000  TOP: 0.000
     2013-04-14 21:56:26   total           634.005
     2013-04-14 21:56:26   total_cnt       10
     2013-04-14 21:56:26   tsecs           1365969386
Attributes:
   room       Strom

Dadurch das Fhem glaubt, das die 3 Logeinträge/Events 10sec auseinnaderliegen, kann ich das auch nicht mit dupTimeout abfangen.

Weiß jemand Rat, warum die Empfangszeiten soweit auseinander liegen und wie man trotz mehrerer an Fhem angeschlossener CUL Empfänger nur 1x ein Event getriggert bekommt?

[rudolfkoenig]

Die Verspaetung der RFR koennte daran liegen, dass ein RFR vor dem weitersenden der empfangenen Daten solange wartet, bis Funkstille herrscht. Das CUNO Problem kann ich nicht erklaeren, da stecke ich nicht (mehr) tief genug drin.

Es gibt ein globales Attribut dupTimeout (default 0.5 Sekunden), um Duplikate, d.h. gleiche RAW Meldungen von unterschiedlichen IO-Geraeten zu filtern.

[pantau]

Ich gehe davon aus, daß die Zeitstempel vom FHEM Server vergeben werden und nicht die einzelnen CULs eine (synchonisierte?) Zeitbasis haben.
Damit wäre es blanker Zufall, wenn ein RFR und ein CUNO _immer_ genau gleich viel Verzögerung und dann auch noch 10 sec haben....
So sieht es nämlich momentan in meinen Logs aus, immer genau 10 (+1)sec
Ich vermute das Problem in der Abarbeitung des FHEM.
Wie schon geschrieben benutze ich dubTimeout, aber ich kann das schlecht auf >10 sec setzen ....

Außerdem unterscheiden sich die Raw Msgs in den letzten 2 byte:
MyRFR_RAWMSG E02066A0A0000000000EB
cul_RAWMSG   E02066A0A0000000000DF
rcul_RAWMSG  E02066A0A000000000003
Ist das zu erwarten, oder führt das zur Erkennung als verschiedene Ereignisse?
Laut CUL_EM bestehen die Nutzdaten nur aus 18byte, also sind die hinterne bytes vermutlich was anderes....

[rudolfkoenig]

> So sieht es nämlich momentan in meinen Logs aus, immer genau 10 (+1)sec
> Ich vermute das Problem in der Abarbeitung des FHEM.

Und ich bei irgendeinem der ausgeloesten notifies.
Ich habe emem/emwz mit mehreren CULs seit Jahren in Betrieb ohne solche Probleme.

>  Außerdem unterscheiden sich die Raw Msgs in den letzten 2 byte:

RSSI ist fuer dupTimeout unerheblich.

[pantau]

Ich habe die Ursache gefunden, nicht aber die endgültige Erklärung:
"Schuld" ist das Modul 93_DBLog.pm....
Wenn ich das Datenbankloggen abschalte geht alles problemlos: Nur noch ein Filelogeintrag und alle CULs zeigen auch sekundengenau die gleiche Empfangszeit.
Habe gestern im Code versucht das nachzuvollziehen, ist mir aber nicht gelungen:
Erwartet hätte ich, das der CheckDuplicates _vor_ der Abarbeitung der "notify"/trigger/events erfolgt, damit sollte aber das Modul DBLog nicht so einen Unterschied machen.
Also Signale/Events werden Empfangen, von FHEM auf Duplikate geprüft und dann erst die Events für die einzelnen Module generiert?
Meine Interpretation meiner Logs deutet darauf hin das jede Nachricht der einzelnen CULs ein event im DBLog triggert, da dauert dann die Abarbeitung 10 sec (?) und dann kommt der nächste CUL dran. Und in der Zwischezeit ist der ganze FHEM blockiert, da auch keine normalen FS20 Kommandos zwischendrin abgearbeitet werden. Sondern erst danach.
Wie ist es denn von der Struktur her implementiert?

[rudolfkoenig]

> Erwartet hätte ich, das der CheckDuplicates _vor_ der Abarbeitung der "notify"/trigger/events erfolgt,

Wenn man etwas nachdenkt, dann sieht man dass das nicht wirklich eine Alternative ist:
- fhem muesste immer erst X Sekunden warten, bevor sie die notifies losschicken kann
- es wuerde nicht mal in deinem Fall wirklich helfen: die 10-Sekunden-Blockade besteht weiterhin.

Ich schlage vor ein neues Thread mit besseren Titel anzulegen.

[pantau]

Ok, danke für die Antworten, ich werde einen neuen Thread bzgl. der Vermeidung von "duplicates" erstellen.

Apropos Threads:
Ich weiß dazu gab es schon Diskussionen, die ich nicht im Detail verfolgt habe...
aber prinzipiell wäre es wünschenswert, wenn eine nicht zeitkritische Sache (Daten loggen) nicht unbedingt ein notify "Tastendruck führt Aktion aus" endlos lang (10 sec) blockieren kann.
Ich hatte das Problem schon einmal. Ursache war damals das Filelog. Meine Logfiles waren einfach zu groß geworden, was auch zu etlichen Sekunden "delay" geführt hat.
Gut logrotate geht auch...:-)

Danke

Peter

[rudolfkoenig]

>  ... endlos lang (10 sec) blockieren kann.

Das "Problem" ist bekannt, und der ModulAutor kann es (wenn es wirklich notwendig ist) durch komplizierte Konstrukte vermeiden. Ich bin der Ansicht, dass sowas nur in sehr wenigen Faellen notwendig ist, ind deinem Fall ist das ein Bug, was durch Nebenlaeufigkeit auch nicht wirklich geloest ist.

>  Meine Logfiles waren einfach zu groß geworden, was auch zu etlichen Sekunden "delay" geführt hat.

Was auch immer mit "delay" hier gemeint ist. Beim Schreiben/Plots anzeigen macht die Dateigroesse keinen Unterschied, die Anzeige der Daten im Browser sollte inzwischen gefixed sein.

[pantau]

>Was auch immer mit "delay" hier gemeint ist. Beim Schreiben/Plots anzeigen macht die Dateigroesse keinen Unterschied, die Anzeige der Daten im Browser sollte inzwischen gefixed sein.

Mit "delay" war gemeint, das wie bei dem dblog Problem fhem mit den filelog schreiben beschäftigt war und in der (langen= mehrere Sekunden) Zeit keine Aktionen ausgeführt hat.
Wobei ich nicht genau sagen kann ob beim Empfangen, Verarbeiten von notifys oder beim Senden.
Verkleinern der Logfiles hat definitiv geholfen (sie waren aber auch >50MB...), aber das ist länger her, ich kann die damalige Rev. von fhem nicht mehr nachvollziehen, somit bringt das wohl momentan nichts.