HM-SEC-SCo wiederholt Messages bis zu sechs mal, Ack oder Timingproblem?

RalfRog · 23 Juli 2016, 19:11:34

Hallo
Ich habe ein Problem dessen Ursache ich nicht verstehe.
Ziel war mit den Fensterkontakt HM-SEC-SCo bei Öffen/Schließen eine Nachricht per Mail oder Pushbullet auf das Smartphone zu schicken.

1) HM-SEC-SCo mit VCCU FHEM gepairt / IO ist ein MAX!Cube mit CUL-FW bzw. alternativ nanoCUL (je per USB angeschlossen)
2) Peering "set TuerTerasse peerChan 0 VCCU_Btn2 single set"
Bin irgenwo im Forum mal auf einen Beitrag gestoßen wo ein Peering mit virtullem Button angeregt wurde
3) Notify für VCCU_Btn1 auf trig_VCCU_Btn1 (fand den Trigger besser als die Statusmeldung) für Mail/Pushbullet

Das Ergebins war, dass ich die Nachrichten mehrfach (6mal) erhielt und im Ev.Monitor die Message (6mal) mehrfach auftraten.
Das gleiche Verhalten ergibt sich beim peeren mit einem physikalischem Device hier HM-LC-Sw1PBU-FM
Auch ohne Peering mit einem Notify direkt auf den Status von HM-SEC-SCo das gleiche Verhalten der mehrfachen Messages.

Nach vielen Versuchen und Testen habe ich festegestellt, dass die erwartete Anzahl an Messages (1 oder 2 mit Peer) kommt wenn:
a) für den HM-SEC-SCo das Attr. event-on-change-reading .* gestzt wird (ok schon wegen dem LOG sinnvoll)
oder
b) oder der Notify disabled wird (nicht sinnvoll dann bekomme ich keine Nachricht)
oder natürlich Beides

Also der Workaroud a) ist da, aber mit ist nicht klar warum mit Notify und ohne event-on-change-reading der HM-SEC-SCo die Message wiederholt.
Kommt evtl. das ACK des IO zu spät?

Der Ev.Monitor mit event-on-change-reading .* ; Kontakt sendet korrekt 2 Meldungen eine an Peer und eine an VCCU

Code Auswählen


TürKontakt auf Flurlampe geepert; Licht schaltet
2016-07-23 11:41:37 CUL_HM LampeFlur trigLast: TuerTerasse:open
2016-07-23 11:41:37 CUL_HM LampeFlur trig_TuerTerasse: open
2016-07-23 11:41:38 CUL_HM TuerTerasse contact: open (to LampeFlur)
2016-07-23 11:41:38 CUL_HM TuerTerasse open
2016-07-23 11:41:38 CUL_HM TuerTerasse trigger_cnt: 120
2016-07-23 11:41:38 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-23 11:41:38 CUL_HM LampeFlur level: 0
2016-07-23 11:41:38 CUL_HM LampeFlur pct: 0
2016-07-23 11:41:38 CUL_HM LampeFlur off
2016-07-23 11:41:38 CUL_HM LampeFlur timedOn: off
2016-07-23 11:41:39 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:41:40 CUL_HM LampeFlur deviceMsg: off (to VCCU)
2016-07-23 11:41:40 CUL_HM LampeFlur level: 0
2016-07-23 11:41:40 CUL_HM LampeFlur pct: 0
2016-07-23 11:41:40 CUL_HM LampeFlur off
2016-07-23 11:41:40 CUL_HM LampeFlur timedOn: off

Der Ev.Monitor ohne event-on-change-reading; Kontakt sendet korrekt 1 Meldung an Peer und sechs an VCCU

Code Auswählen


TürKontakt auf Flurlampe geepert; Licht schaltet
2016-07-23 11:45:55 CUL_HM LampeFlur trigLast: TuerTerasse:open
2016-07-23 11:45:55 CUL_HM LampeFlur trig_TuerTerasse: open
2016-07-23 11:45:56 CUL_HM TuerTerasse battery: ok
2016-07-23 11:45:56 CUL_HM TuerTerasse contact: open (to LampeFlur)
2016-07-23 11:45:56 CUL_HM TuerTerasse open
2016-07-23 11:45:56 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:45:56 CUL_HM LampeFlur deviceMsg: on (to TuerTerasse)
2016-07-23 11:45:56 CUL_HM LampeFlur level: 100
2016-07-23 11:45:56 CUL_HM LampeFlur pct: 100
2016-07-23 11:45:56 CUL_HM LampeFlur on
2016-07-23 11:45:56 CUL_HM LampeFlur timedOn: off
2016-07-23 11:45:57 CUL_HM TuerTerasse battery: ok
2016-07-23 11:45:57 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:45:57 CUL_HM TuerTerasse open
2016-07-23 11:45:57 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:45:57 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:45:57 CUL_HM TuerTerasse battery: ok
2016-07-23 11:45:57 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:45:57 CUL_HM TuerTerasse open
2016-07-23 11:45:57 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:45:57 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:45:58 CUL_HM TuerTerasse battery: ok
2016-07-23 11:45:58 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:45:58 CUL_HM TuerTerasse open
2016-07-23 11:45:58 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:45:58 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:45:59 CUL_HM TuerTerasse battery: ok
2016-07-23 11:45:59 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:45:59 CUL_HM TuerTerasse open
2016-07-23 11:45:59 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:45:59 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:45:59 CUL_HM LampeFlur deviceMsg: on (to VCCU)
2016-07-23 11:45:59 CUL_HM LampeFlur level: 100
2016-07-23 11:45:59 CUL_HM LampeFlur pct: 100
2016-07-23 11:45:59 CUL_HM LampeFlur on
2016-07-23 11:45:59 CUL_HM LampeFlur timedOn: off
2016-07-23 11:46:00 CUL_HM TuerTerasse battery: ok
2016-07-23 11:46:00 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:46:00 CUL_HM TuerTerasse open
2016-07-23 11:46:00 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:46:00 CUL_HM TuerTerasse trigger_cnt: 122
2016-07-23 11:46:02 CUL_HM TuerTerasse battery: ok
2016-07-23 11:46:02 CUL_HM TuerTerasse contact: open (to VCCU)
2016-07-23 11:46:02 CUL_HM TuerTerasse open
2016-07-23 11:46:02 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-23 11:46:02 CUL_HM TuerTerasse trigger_cnt: 122

Hier der LOG mit Verbose5 vom IO

Code Auswählen


2016.07.23 11:45:00 5: CUL/RAW: /A0C6CA64143BA6231B20201790010

2016.07.23 11:45:00 4: CUL_Parse: cubeCUL2U A 0C 6C A641 43BA62 31B202 01790010 -66
2016.07.23 11:45:00 5: cubeCUL2U dispatch A0C6CA64143BA6231B202017900::-66:cubeCUL2U
2016.07.23 11:45:00 5: CUL/RAW: /A0E6C800231B20243BA62010100003826
A0C6DA64143BA6288515101790012

2016.07.23 11:45:00 4: CUL_Parse: cubeCUL2U A 0E 6C 8002 31B202 43BA62 010100003826 -55
2016.07.23 11:45:00 5: cubeCUL2U dispatch A0E6C800231B20243BA620101000038::-55:cubeCUL2U
2016.07.23 11:45:00 4: CUL_Parse: cubeCUL2U A 0C 6D A641 43BA62 885151 01790012 -65
2016.07.23 11:45:00 5: cubeCUL2U dispatch A0C6DA64143BA62885151017900::-65:cubeCUL2U
2016.07.23 11:45:00 5: cubeCUL2U sending As0D6D800288515143BA620101C800
2016.07.23 11:45:00 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:01 4: CUL_send:  cubeCUL2UAs 0D 6D 8002 885151 43BA62 0101C800
2016.07.23 11:45:01 5: CUL/RAW: /A0C6EA64143BA6288515101790011

2016.07.23 11:45:01 4: CUL_Parse: cubeCUL2U A 0C 6E A641 43BA62 885151 01790011 -65.5
2016.07.23 11:45:01 5: cubeCUL2U dispatch A0C6EA64143BA62885151017900::-65.5:cubeCUL2U
2016.07.23 11:45:01 5: cubeCUL2U sending As0D6E800288515143BA620101C800
2016.07.23 11:45:01 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:01 4: CUL_send:  cubeCUL2UAs 0D 6E 8002 885151 43BA62 0101C800
2016.07.23 11:45:02 5: CUL/RAW: /A0C6FA64143BA6288515101790010

2016.07.23 11:45:02 4: CUL_Parse: cubeCUL2U A 0C 6F A641 43BA62 885151 01790010 -66
2016.07.23 11:45:02 5: cubeCUL2U dispatch A0C6FA64143BA62885151017900::-66:cubeCUL2U
2016.07.23 11:45:02 5: cubeCUL2U sending As0D6F800288515143BA620101C800
2016.07.23 11:45:02 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:02 4: CUL_send:  cubeCUL2UAs 0D 6F 8002 885151 43BA62 0101C800
2016.07.23 11:45:03 5: CUL/RAW: /A0C70A64143BA628851510179000F

2016.07.23 11:45:03 4: CUL_Parse: cubeCUL2U A 0C 70 A641 43BA62 885151 0179000F -66.5
2016.07.23 11:45:03 5: cubeCUL2U dispatch A0C70A64143BA62885151017900::-66.5:cubeCUL2U
2016.07.23 11:45:03 5: cubeCUL2U sending As0D70800288515143BA620101C800
2016.07.23 11:45:03 5: CUL 43BA62 dly:81ms
2016.07.23 11:45:03 4: CUL_send:  cubeCUL2UAs 0D 70 8002 885151 43BA62 0101C800
2016.07.23 11:45:04 5: CUL/RAW: /A0C71A64143BA6288515101790010

2016.07.23 11:45:04 4: CUL_Parse: cubeCUL2U A 0C 71 A641 43BA62 885151 01790010 -66
2016.07.23 11:45:04 5: cubeCUL2U dispatch A0C71A64143BA62885151017900::-66:cubeCUL2U
2016.07.23 11:45:04 5: cubeCUL2U sending As0D71800288515143BA620101C800
2016.07.23 11:45:04 5: CUL 43BA62 dly:81ms
2016.07.23 11:45:04 4: CUL_send:  cubeCUL2UAs 0D 71 8002 885151 43BA62 0101C800
2016.07.23 11:45:55 5: CUL/RAW: /A0C72A64143BA6231B202017AC80D

2016.07.23 11:45:55 4: CUL_Parse: cubeCUL2U A 0C 72 A641 43BA62 31B202 017AC80D -67.5
2016.07.23 11:45:55 5: cubeCUL2U dispatch A0C72A64143BA6231B202017AC8::-67.5:cubeCUL2U
2016.07.23 11:45:56 5: CUL/RAW: /A0E72800231B20243BA620101C8003926
A0C73A64143BA62885151017AC80D

2016.07.23 11:45:56 4: CUL_Parse: cubeCUL2U A 0E 72 8002 31B202 43BA62 0101C8003926 -55
2016.07.23 11:45:56 5: cubeCUL2U dispatch A0E72800231B20243BA620101C80039::-55:cubeCUL2U
2016.07.23 11:45:56 4: CUL_Parse: cubeCUL2U A 0C 73 A641 43BA62 885151 017AC80D -67.5
2016.07.23 11:45:56 5: cubeCUL2U dispatch A0C73A64143BA62885151017AC8::-67.5:cubeCUL2U
2016.07.23 11:45:56 5: cubeCUL2U sending As0D73800288515143BA620101C800
2016.07.23 11:45:56 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:56 4: CUL_send:  cubeCUL2UAs 0D 73 8002 885151 43BA62 0101C800
2016.07.23 11:45:57 5: CUL/RAW: /A0C74A64143BA62885151017AC80A
A0C75A64143BA62885151017AC80E

2016.07.23 11:45:57 4: CUL_Parse: cubeCUL2U A 0C 74 A641 43BA62 885151 017AC80A -69
2016.07.23 11:45:57 5: cubeCUL2U dispatch A0C74A64143BA62885151017AC8::-69:cubeCUL2U
2016.07.23 11:45:57 5: cubeCUL2U sending As0D74800288515143BA620101C800
2016.07.23 11:45:57 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:57 4: CUL_send:  cubeCUL2UAs 0D 74 8002 885151 43BA62 0101C800
2016.07.23 11:45:57 4: CUL_Parse: cubeCUL2U A 0C 75 A641 43BA62 885151 017AC80E -67
2016.07.23 11:45:57 5: cubeCUL2U dispatch A0C75A64143BA62885151017AC8::-67:cubeCUL2U
2016.07.23 11:45:57 5: cubeCUL2U sending As0D75800288515143BA620101C800
2016.07.23 11:45:57 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:57 4: CUL_send:  cubeCUL2UAs 0D 75 8002 885151 43BA62 0101C800
2016.07.23 11:45:58 5: CUL/RAW: /A0C76A64143BA62885151017AC80D
A0D73A41031B2028851510601C80025

2016.07.23 11:45:58 4: CUL_Parse: cubeCUL2U A 0C 76 A641 43BA62 885151 017AC80D -67.5
2016.07.23 11:45:58 5: cubeCUL2U dispatch A0C76A64143BA62885151017AC8::-67.5:cubeCUL2U
2016.07.23 11:45:58 5: cubeCUL2U sending As0D76800288515143BA620101C800
2016.07.23 11:45:58 5: CUL 43BA62 dly:81ms
2016.07.23 11:45:58 4: CUL_send:  cubeCUL2UAs 0D 76 8002 885151 43BA62 0101C800
2016.07.23 11:45:59 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80025 -55.5
2016.07.23 11:45:59 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-55.5:cubeCUL2U
2016.07.23 11:45:59 5: cubeCUL2U sending As0A73800288515131B20200
2016.07.23 11:45:59 5: CUL 31B202 dly:78ms
2016.07.23 11:45:59 4: CUL_send:  cubeCUL2UAs 0A 73 8002 885151 31B202 00
2016.07.23 11:45:59 5: CUL/RAW: /A0C77A64143BA62885151017AC80C

2016.07.23 11:45:59 4: CUL_Parse: cubeCUL2U A 0C 77 A641 43BA62 885151 017AC80C -68
2016.07.23 11:45:59 5: cubeCUL2U dispatch A0C77A64143BA62885151017AC8::-68:cubeCUL2U
2016.07.23 11:45:59 5: cubeCUL2U sending As0D77800288515143BA620101C800
2016.07.23 11:45:59 5: CUL 43BA62 dly:81ms
2016.07.23 11:45:59 4: CUL_send:  cubeCUL2UAs 0D 77 8002 885151 43BA62 0101C800
2016.07.23 11:46:01 5: CUL/RAW: /A0C78A64143BA62885151017AC808

2016.07.23 11:46:01 4: CUL_Parse: cubeCUL2U A 0C 78 A641 43BA62 885151 017AC808 -70
2016.07.23 11:46:01 5: cubeCUL2U dispatch A0C78A64143BA62885151017AC8::-70:cubeCUL2U
2016.07.23 11:46:01 5: cubeCUL2U sending As0D78800288515143BA620101C800
2016.07.23 11:46:01 5: CUL 43BA62 dly:80ms
2016.07.23 11:46:01 4: CUL_send:  cubeCUL2UAs 0D 78 8002 885151 43BA62 0101C800
2016.07.23 11:46:02 5: CUL/RAW: /A0D73A41031B2028851510601C80028

2016.07.23 11:46:02 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80028 -54
2016.07.23 11:46:02 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-54:cubeCUL2U
2016.07.23 11:46:05 5: CUL/RAW: /A0D73A41031B2028851510601C80027

2016.07.23 11:46:05 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80027 -54.5
2016.07.23 11:46:05 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-54.5:cubeCUL2U
2016.07.23 11:46:09 5: CUL/RAW: /A0D73A41031B2028851510601C80024

2016.07.23 11:46:09 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80024 -56
2016.07.23 11:46:09 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-56:cubeCUL2U
2016.07.23 11:46:16 5: CUL/RAW: /A0D73A41031B2028851510601C80025

2016.07.23 11:46:16 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80025 -55.5
2016.07.23 11:46:16 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-55.5:cubeCUL2U
2016.07.23 11:46:26 5: CUL/RAW: /A0D73A41031B2028851510601C80025

2016.07.23 11:46:26 4: CUL_Parse: cubeCUL2U A 0D 73 A410 31B202 885151 0601C80025 -55.5
2016.07.23 11:46:26 5: cubeCUL2U dispatch A0D73A41031B2028851510601C800::-55.5:cubeCUL2U

martinp876 · 23 Juli 2016, 19:22:47

Der Sender schickt an alle peers. Da er ein ack sehen will muss er an jeden einzeln schicken. Somit wiederholt sich die message.
Fhem wertet jede mesage aus sofern es kein 100% Duplikat ist.
Dass eventonchangereading zu setzen ist ist kein workaround sondern Standard zumindest bei fhem hm. Ich wiederhole das regelmässig.
Die Alternative dass fhem dies intern filtert ist nicht im Sinne der Implementierung. Ggf. Kann man es abschalten um sonderaktionen zu starten. Dafür gibt es den Filter schliesslich.
Es geht nicht nur um logs!!!

RalfRog · 23 Juli 2016, 19:45:42

Danke
Auf das Thema event-on-change-reading bin ich erst kürzlich aufmerksam geworden, da ich bis letzten Monat nur IT Steckdosenschalter und zwei 230V HM-Schaltaktoren im Einsatz hatte bin ich nicht darüber gestoplert.

Das an jeden Peer (hier) gesendet wird hatte ich in einem Beitrag schon gelesen und ist ja irgewie logisch.

Mich wudert halt nur wie oben im zweiten Beispiel des EventMonitor, dass an den Peer korrekt einmal gesendet wird und dann 6mal an die VCCU.
Ich nehme an dann schlägt der transmitTryMax des HM-SEC-SCo zu.

Gruß Ralf

martinp876 · 23 Juli 2016, 21:07:57

Da hast du recht. Und damit ist wohl klar, dass die vccu nicht antwortet. Ist die den gepeert?
Die Implementierung ist analog zu allen devices: geantwortet wird nur, wenn man gepeert ist. Auch wenn die Adresse stimmt. Die vccu braucht also einen Kanal mit dem der Sender gepeert ist.

Aber halt, es ist die status message. Die sollte eigentlich beantwortet werden. Muss ich nachsehen.

p.s.: bitte loggen wie in Sniffen beschrieben - macht das log viel uebersichtlicher.

RalfRog · 23 Juli 2016, 23:12:49

Ok mach ich.
Muss nur erst wieder alles so einstellen.

Was mich nur stuzig macht, ist dass die Kommunikation (und Message Wiederholugen) zwischen HM-SEC-SCo und der VCCU davon abhängen ob ein Notify aktiv ist oder nicht.

Vermutlich kommt das raus was oben schon unter "Hier der LOG mit Verbose5 vom IO" steht. Dokumentiert ist der Schlechtfall mit Message zum Peer Unterputzschalter und Wiederholungen zur VCCU sowie die Statusmeldungen des Unterputzschalter.
Die VCCU quittiert immer brav mit 8002
2016.07.23 11:45:02 5: cubeCUL2U sending As0D6F800288515143BA620101C800
2016.07.23 11:45:02 5: CUL 43BA62 dly:80ms
2016.07.23 11:45:02 4: CUL_send: cubeCUL2UAs 0D 6F 8002 885151 43BA62 0101C800

RalfRog · 24 Juli 2016, 01:38:13

Hat mir keine Ruhe gelassen

VCCU = 885151 / HM-SEC-SCo = 43BA62 (TuerTerasse) / HM-SEC-SCo = 31B202 (LampeFlur)
VCCU mit beiden gepaired
HM-SEC-SCo Chan0 mit HM-SEC-SCo gepeert (zur zum Testen satt VCCU_Btn1)

Notify TuerTerasse:contact:.* set PuBu message $NAME Aenderung! $EVENT

Alle vier Fälle duchgespielt. Vermutlich reichen die beiden ersten zur Analyse

1. & 2. Tür wurde geschlossen und das Attr. event-on-change-reading .* ist für HM-SEC-SCo gesetzt
Fall mit und ohne Notify enthalten

Code Auswählen


Tür zu mit Notify und Attr. On_Change auf .*
***** LOG-File *****
2016.07.24 00:39:13.495 4: CUL_Parse: cubeCUL2U A 0C CA A641 43BA62 31B202 0185000C -68
2016.07.24 00:39:14.240 4: CUL_Parse: cubeCUL2U A 0E CA 8002 31B202 43BA62 010100003626 -55
2016.07.24 00:39:14.302 4: CUL_Parse: cubeCUL2U A 0C CB A641 43BA62 885151 0185000A -69
2016.07.24 00:39:14.405 4: CUL_send:  cubeCUL2UAs 0D CB 8002 885151 43BA62 0101C800
2016.07.24 00:39:15.252 4: CUL_Parse: cubeCUL2U A 0C CC A641 43BA62 885151 0185000D -67.5
2016.07.24 00:39:15.355 4: CUL_send:  cubeCUL2UAs 0D CC 8002 885151 43BA62 0101C800
2016.07.24 00:39:15.381 4: CUL_Parse: cubeCUL2U A 0C CD A641 43BA62 885151 0185000D -67.5
2016.07.24 00:39:15.485 4: CUL_send:  cubeCUL2UAs 0D CD 8002 885151 43BA62 0101C800
2016.07.24 00:39:16.209 4: CUL_Parse: cubeCUL2U A 0C CE A641 43BA62 885151 0185000C -68
2016.07.24 00:39:16.312 4: CUL_send:  cubeCUL2UAs 0D CE 8002 885151 43BA62 0101C800

wie vor Notify disabled
2016.07.24 01:04:21.140 4: CUL_Parse: cubeCUL2U A 0C D7 A641 43BA62 31B202 0189000F -66.5
2016.07.24 01:04:21.271 4: CUL_Parse: cubeCUL2U A 0E D7 8002 31B202 43BA62 010100003527 -54.5
2016.07.24 01:04:21.412 4: CUL_Parse: cubeCUL2U A 0C D8 A641 43BA62 885151 0189000E -67
2016.07.24 01:04:21.516 4: CUL_send:  cubeCUL2UAs 0D D8 8002 885151 43BA62 0101C800



***** Monitor *****
2016.07.24 00:39:13.495 4 : CUL_Parse: cubeCUL2U A 0C CA A641 43BA62 31B202 0185000C -68
2016-07-24 00:39:13.570 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 00:39:13.570 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 00:39:14.202 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to LampeFlur)
2016-07-24 00:39:14.209 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 00:39:14.209 CUL_HM TuerTerasse closed
2016-07-24 00:39:14.209 CUL_HM TuerTerasse trigger_cnt: 133
2016.07.24 00:39:14.240 4 : CUL_Parse: cubeCUL2U A 0E CA 8002 31B202 43BA62 010100003626 -55
2016-07-24 00:39:14.299 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 00:39:14.299 CUL_HM LampeFlur level: 0
2016-07-24 00:39:14.299 CUL_HM LampeFlur pct: 0
2016-07-24 00:39:14.299 CUL_HM LampeFlur off
2016-07-24 00:39:14.299 CUL_HM LampeFlur timedOn: off
2016.07.24 00:39:14.302 4 : CUL_Parse: cubeCUL2U A 0C CB A641 43BA62 885151 0185000A -69
2016.07.24 00:39:14.405 4 : CUL_send: cubeCUL2UAs 0D CB 8002 885151 43BA62 0101C800
2016-07-24 00:39:15.215 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 00:39:15.221 CUL_HM TuerTerasse contact: closed (to VCCU)
2016.07.24 00:39:15.252 4 : CUL_Parse: cubeCUL2U A 0C CC A641 43BA62 885151 0185000D -67.5
2016.07.24 00:39:15.355 4 : CUL_send: cubeCUL2UAs 0D CC 8002 885151 43BA62 0101C800
2016.07.24 00:39:15.381 4 : CUL_Parse: cubeCUL2U A 0C CD A641 43BA62 885151 0185000D -67.5
2016.07.24 00:39:15.485 4 : CUL_send: cubeCUL2UAs 0D CD 8002 885151 43BA62 0101C800
2016.07.24 00:39:16.209 4 : CUL_Parse: cubeCUL2U A 0C CE A641 43BA62 885151 0185000C -68
2016.07.24 00:39:16.312 4 : CUL_send: cubeCUL2UAs 0D CE 8002 885151 43BA62 0101C800

wie vor Notify disabled
2016.07.24 01:04:21.140 4 : CUL_Parse: cubeCUL2U A 0C D7 A641 43BA62 31B202 0189000F -66.5
2016-07-24 01:04:21.213 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 01:04:21.213 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 01:04:21.240 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 01:04:21.240 CUL_HM TuerTerasse closed
2016-07-24 01:04:21.240 CUL_HM TuerTerasse trigger_cnt: 137
2016.07.24 01:04:21.271 4 : CUL_Parse: cubeCUL2U A 0E D7 8002 31B202 43BA62 010100003527 -54.5
2016-07-24 01:04:21.329 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 01:04:21.329 CUL_HM LampeFlur level: 0
2016-07-24 01:04:21.329 CUL_HM LampeFlur pct: 0
2016-07-24 01:04:21.329 CUL_HM LampeFlur off
2016-07-24 01:04:21.329 CUL_HM LampeFlur timedOn: off
2016.07.24 01:04:21.412 4 : CUL_Parse: cubeCUL2U A 0C D8 A641 43BA62 885151 0189000E -67
2016.07.24 01:04:21.516 4 : CUL_send: cubeCUL2UAs 0D D8 8002 885151 43BA62 0101C800
2016-07-24 01:04:21.560 CUL_HM TuerTerasse contact: closed (to VCCU)

3. & 4. Tür wurde geschlossen und das Attr. event-on-change-reading .* ist für HM-SEC-SCo ist gelöscht
Fall mit und ohne Notify enthalten
nicht so übersichtlich wie vor da viel mehr Einträge

Code Auswählen


Tür zu mit Notify und Attr. On_Change gelöscht
***** LOG *****
2016.07.24 01:11:43.265 4: CUL_Parse: cubeCUL2U A 0C DE A641 43BA62 31B202 018B0008 -70
2016.07.24 01:11:44.018 4: CUL_Parse: cubeCUL2U A 0E DE 8002 31B202 43BA62 010100003926 -55
2016.07.24 01:11:44.079 4: CUL_Parse: cubeCUL2U A 0C DF A641 43BA62 885151 018B0008 -70
2016.07.24 01:11:44.184 4: CUL_send:  cubeCUL2UAs 0D DF 8002 885151 43BA62 0101C800
2016.07.24 01:11:44.898 4: CUL_Parse: cubeCUL2U A 0C E0 A641 43BA62 885151 018B000C -68
2016.07.24 01:11:45.002 4: CUL_send:  cubeCUL2UAs 0D E0 8002 885151 43BA62 0101C800
2016.07.24 01:11:45.726 4: CUL_Parse: cubeCUL2U A 0C E1 A641 43BA62 885151 018B000B -68.5
2016.07.24 01:11:45.830 4: CUL_send:  cubeCUL2UAs 0D E1 8002 885151 43BA62 0101C800
2016.07.24 01:11:46.522 4: CUL_Parse: cubeCUL2U A 0C E2 A641 43BA62 885151 018B000B -68.5
2016.07.24 01:11:46.626 4: CUL_send:  cubeCUL2UAs 0D E2 8002 885151 43BA62 0101C800
2016.07.24 01:11:47.381 4: CUL_Parse: cubeCUL2U A 0C E3 A641 43BA62 885151 018B000C -68
2016.07.24 01:11:47.485 4: CUL_send:  cubeCUL2UAs 0D E3 8002 885151 43BA62 0101C800

wie vor Notify disabled
2016.07.24 01:16:25.529 4: CUL_Parse: cubeCUL2U A 0C EB A641 43BA62 31B202 018D000D -67.5
2016.07.24 01:16:25.655 4: CUL_Parse: cubeCUL2U A 0E EB 8002 31B202 43BA62 010100003626 -55
2016.07.24 01:16:25.800 4: CUL_Parse: cubeCUL2U A 0C EC A641 43BA62 885151 018D000E -67
2016.07.24 01:16:25.904 4: CUL_send:  cubeCUL2UAs 0D EC 8002 885151 43BA62 0101C800



**** Monitor *****
2016.07.24 01:11:43.265 4 : CUL_Parse: cubeCUL2U A 0C DE A641 43BA62 31B202 018B0008 -70
2016-07-24 01:11:43.317 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 01:11:43.317 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 01:11:43.954 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to LampeFlur)
2016-07-24 01:11:43.962 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:43.962 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 01:11:43.962 CUL_HM TuerTerasse closed
2016-07-24 01:11:43.962 CUL_HM TuerTerasse trigger_cnt: 139
2016.07.24 01:11:44.018 4 : CUL_Parse: cubeCUL2U A 0E DE 8002 31B202 43BA62 010100003926 -55
2016-07-24 01:11:44.076 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 01:11:44.076 CUL_HM LampeFlur level: 0
2016-07-24 01:11:44.076 CUL_HM LampeFlur pct: 0
2016-07-24 01:11:44.076 CUL_HM LampeFlur off
2016-07-24 01:11:44.076 CUL_HM LampeFlur timedOn: off
2016.07.24 01:11:44.079 4 : CUL_Parse: cubeCUL2U A 0C DF A641 43BA62 885151 018B0008 -70
2016.07.24 01:11:44.184 4 : CUL_send: cubeCUL2UAs 0D DF 8002 885151 43BA62 0101C800
2016-07-24 01:11:44.831 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 01:11:44.840 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:44.840 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:11:44.840 CUL_HM TuerTerasse closed
2016-07-24 01:11:44.840 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:11:44.840 CUL_HM TuerTerasse trigger_cnt: 139
2016.07.24 01:11:44.898 4 : CUL_Parse: cubeCUL2U A 0C E0 A641 43BA62 885151 018B000C -68
2016.07.24 01:11:45.002 4 : CUL_send: cubeCUL2UAs 0D E0 8002 885151 43BA62 0101C800
2016-07-24 01:11:45.662 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 01:11:45.670 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:45.670 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:11:45.670 CUL_HM TuerTerasse closed
2016-07-24 01:11:45.670 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:11:45.670 CUL_HM TuerTerasse trigger_cnt: 139
2016.07.24 01:11:45.726 4 : CUL_Parse: cubeCUL2U A 0C E1 A641 43BA62 885151 018B000B -68.5
2016.07.24 01:11:45.830 4 : CUL_send: cubeCUL2UAs 0D E1 8002 885151 43BA62 0101C800
2016-07-24 01:11:46.455 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 01:11:46.464 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:46.464 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:11:46.464 CUL_HM TuerTerasse closed
2016-07-24 01:11:46.464 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:11:46.464 CUL_HM TuerTerasse trigger_cnt: 139
2016.07.24 01:11:46.522 4 : CUL_Parse: cubeCUL2U A 0C E2 A641 43BA62 885151 018B000B -68.5
2016.07.24 01:11:46.626 4 : CUL_send: cubeCUL2UAs 0D E2 8002 885151 43BA62 0101C800
2016-07-24 01:11:47.315 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 01:11:47.324 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:47.324 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:11:47.324 CUL_HM TuerTerasse closed
2016-07-24 01:11:47.324 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:11:47.324 CUL_HM TuerTerasse trigger_cnt: 139
2016.07.24 01:11:47.381 4 : CUL_Parse: cubeCUL2U A 0C E3 A641 43BA62 885151 018B000C -68
2016.07.24 01:11:47.485 4 : CUL_send: cubeCUL2UAs 0D E3 8002 885151 43BA62 0101C800
2016-07-24 01:11:48.172 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 01:11:48.180 CUL_HM TuerTerasse battery: ok
2016-07-24 01:11:48.180 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:11:48.180 CUL_HM TuerTerasse closed
2016-07-24 01:11:48.180 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:11:48.180 CUL_HM TuerTerasse trigger_cnt: 139

wie vor Notify disabled
2016.07.24 01:16:25.529 4 : CUL_Parse: cubeCUL2U A 0C EB A641 43BA62 31B202 018D000D -67.5
2016-07-24 01:16:25.581 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 01:16:25.581 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 01:16:25.610 CUL_HM TuerTerasse battery: ok
2016-07-24 01:16:25.610 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 01:16:25.610 CUL_HM TuerTerasse closed
2016-07-24 01:16:25.610 CUL_HM TuerTerasse trigger_cnt: 141
2016.07.24 01:16:25.655 4 : CUL_Parse: cubeCUL2U A 0E EB 8002 31B202 43BA62 010100003626 -55
2016-07-24 01:16:25.714 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 01:16:25.714 CUL_HM LampeFlur level: 0
2016-07-24 01:16:25.714 CUL_HM LampeFlur pct: 0
2016-07-24 01:16:25.714 CUL_HM LampeFlur off
2016-07-24 01:16:25.714 CUL_HM LampeFlur timedOn: off
2016.07.24 01:16:25.800 4 : CUL_Parse: cubeCUL2U A 0C EC A641 43BA62 885151 018D000E -67
2016.07.24 01:16:25.904 4 : CUL_send: cubeCUL2UAs 0D EC 8002 885151 43BA62 0101C800
2016-07-24 01:16:25.957 CUL_HM TuerTerasse battery: ok
2016-07-24 01:16:25.957 CUL_HM TuerTerasse contact: closed (to VCCU)
2016-07-24 01:16:25.957 CUL_HM TuerTerasse closed
2016-07-24 01:16:25.957 CUL_HM TuerTerasse trigDst_VCCU: noConfig
2016-07-24 01:16:25.957 CUL_HM TuerTerasse trigger_cnt: 141

Fazit aus dem Log: nur ohne Notify ist die Anzahl der Messages wie ich erwartet habe. Meldung an Peer und VCCU jeweils eine Quittung. Im Vergleich Fall 1. / 2. sieht man bei 2. drei Parse/Send Päärchen am ende der Sequenz mehr.
Warum?

martinp876 · 24 Juli 2016, 08:30:47

Mal so auf die Schnelle, ohne logs zu lesen: gut möglich.
Der aktor erwartet eine Antwort in strengen zeitlichen Grenzen. HmIos senden ein ack automatisch was ein sauberes timing sicherstellt. CulIos machen das nicht, hier steuert es die zentrale. Zum einen kommen Variable delays durch Ethernet oder USB zum Tragen. Dann kommen noch delays durch fhem selbst hinzu - und Perl ist nun einmal langsam, der Code nicht wirklich Echtzeit.
Aktionen wie notify schlagen einfach unkontrolliert in die Abarbeitung .
Weiter hat die cul nach default Implementierung keinerlei Unterstützung das timing zu kontrolieren( ganz im Gegensatz zu HmIos) . Hier gibt es zumindest eine Ersatz fw welche gute Dienste leistet.

Bottom line : culIos sind kritisch und fuer hm ausschliesslich mit alternativer fw brauchbar.
HmIos sind darüber hinaus besser im Bezug auf timing.
Fhem Code kann immer timing Probleme verursachen. Diese würde ich ggf. Mit apptime untersuchen ( oder Perl timing analysetools, falls du welche hast)

RalfRog · 24 Juli 2016, 12:18:12

Hallo
zunächst eine Frage: trifft das bessere Timingverhalten auf HM-CFG-USB(-2) , HM-CFG-LAN zu?

Hier ging es zwar um den Sensor (Fensterkontakt) macht aber vermutlich hinsichtlich der Aussage keinen Unterschied.
Im Einsatz ist ein MAxCube mit "V 1.20.08 a-culfw Build: 220 (2016-04-11_23-12-16) CUBe (F-Band: 868MHz)"

Da ich bei "apptime" "Perl timing analysetools" momentan nicht wirklich weiss um was es geht bin ich vermutlich überfordert.

Ich habe bisher nur Beleuchtung geschaltet und würde für mich als Fazit ziehen:

wenn der eine Fensterkontakt der Spielphase entwächst und echte Szenarien mit mehr Devices entstehen -> umstellen auf HM-IO
mein Test (Pi1) und Produktivsystem (Pi2) tauschen in der Hoffnung das die 2er mit mehr Performance etwas ausbügelt
Lastreduzierung mit "event-on-change-reading", vorsichtig mit Notify keine Not.Ketten etc.

passen die Erkenntnisse?

Vielen Dank für die Unterstützung

frank · 24 Juli 2016, 13:33:49

fw plus 00_cul.pm => https://forum.fhem.de/index.php/topic,31421.0.html

mgernoth · 24 Juli 2016, 13:57:07

Hi,

die alternative Firmware wird hier nicht helfen.

Das Pushbullet verzoegert den Empfang der Nachricht auf die Fhem innerhalb von 100ms antworten muss um ca. 1s. Das einzige was hier helfen kann ist entweder ein nicht-blockierendes Pushbullet oder ein HM IO, das selbst acked. Aber 1s blockieren geht eigentlich gar nicht...

Viele Gruesse
Michael

RalfRog · 24 Juli 2016, 20:21:46

Hallo Michael und die Anderen

Zitat von: mgernoth am 24 Juli 2016, 13:57:07
Hi,
die alternative Firmware wird hier nicht helfen.

Das Pushbullet verzoegert den Empfang der Nachricht auf die Fhem innerhalb von 100ms antworten muss um ca. 1s. Das einzige was hier helfen kann ist entweder ein nicht-blockierendes Pushbullet oder ein HM IO, das selbst acked. Aber 1s blockieren geht eigentlich gar nicht...

Das hat mich einen neuen Test machen lassen.
Statt Pushbullet nur ein Logeintrag mit notify "TuerTerasse:contact:.* { Log 1, "ExecNotify" }". In der Tat, der weniger aufwändige Notify blockiet den ACK nicht mehr.
Eine Message an die VCCU und ein ACK wie es sein soll.

Code Auswählen


Tür zu mit Notify Pushbullet und Attr. On_Change auf .*
***** LOG-File *****
2016.07.24 19:57:42.208 4: CUL_Parse: cubeCUL2U A 0C 07 A641 43BA62 31B202 018F0003 -72.5
2016.07.24 19:57:42.880 4: CUL_Parse: cubeCUL2U A 0E 07 8002 31B202 43BA62 01010000371F -58.5
2016.07.24 19:57:42.939 4: CUL_Parse: cubeCUL2U A 0C 08 A641 43BA62 885151 018F0004 -72
2016.07.24 19:57:43.042 4: CUL_send:  cubeCUL2UAs 0D 08 8002 885151 43BA62 0101C800
2016.07.24 19:57:43.714 4: CUL_Parse: cubeCUL2U A 0C 09 A641 43BA62 885151 018F0001 -73.5
2016.07.24 19:57:43.817 4: CUL_send:  cubeCUL2UAs 0D 09 8002 885151 43BA62 0101C800
2016.07.24 19:57:43.910 4: CUL_Parse: cubeCUL2U A 0C 0A A641 43BA62 885151 018F0003 -72.5
2016.07.24 19:57:44.013 4: CUL_send:  cubeCUL2UAs 0D 0A 8002 885151 43BA62 0101C800

wie vor aber einfaches Notify 
016.07.24 20:11:11.481 4: CUL_Parse: cubeCUL2U A 0C 13 A641 43BA62 31B202 01930007 -70.5
2016.07.24 20:11:11.580 1: ExecNotify
2016.07.24 20:11:11.608 4: CUL_Parse: cubeCUL2U A 0E 13 8002 31B202 43BA62 01010000371F -58.5
2016.07.24 20:11:11.753 4: CUL_Parse: cubeCUL2U A 0C 14 A641 43BA62 885151 01930005 -71.5
2016.07.24 20:11:11.857 4: CUL_send:  cubeCUL2UAs 0D 14 8002 885151 43BA62 0101C800
2016.07.24 20:11:11.904 1: ExecNotify


***** Monitor *****
2016-07-24 19:57:42.258 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 19:57:42.258 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 19:57:42.866 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to LampeFlur)
2016-07-24 19:57:42.872 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 19:57:42.872 CUL_HM TuerTerasse closed
2016-07-24 19:57:42.872 CUL_HM TuerTerasse trigger_cnt: 143
2016-07-24 19:57:42.936 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 19:57:42.936 CUL_HM LampeFlur level: 0
2016-07-24 19:57:42.936 CUL_HM LampeFlur pct: 0
2016-07-24 19:57:42.936 CUL_HM LampeFlur off
2016-07-24 19:57:42.936 CUL_HM LampeFlur timedOn: off
2016-07-24 19:57:43.701 Pushbullet PuBu message TuerTerasse Aenderung! contact: closed (to VCCU)
2016-07-24 19:57:43.706 CUL_HM TuerTerasse contact: closed (to VCCU)

wie vor aber einfaches Notify 
2016-07-24 20:11:11.551 CUL_HM LampeFlur trigLast: TuerTerasse:closed
2016-07-24 20:11:11.551 CUL_HM LampeFlur trig_TuerTerasse: closed
2016-07-24 20:11:11.587 CUL_HM TuerTerasse contact: closed (to LampeFlur)
2016-07-24 20:11:11.587 CUL_HM TuerTerasse closed
2016-07-24 20:11:11.587 CUL_HM TuerTerasse trigger_cnt: 147
2016-07-24 20:11:11.665 CUL_HM LampeFlur deviceMsg: off (to TuerTerasse)
2016-07-24 20:11:11.665 CUL_HM LampeFlur level: 0
2016-07-24 20:11:11.665 CUL_HM LampeFlur pct: 0
2016-07-24 20:11:11.665 CUL_HM LampeFlur off
2016-07-24 20:11:11.665 CUL_HM LampeFlur timedOn: off
2016-07-24 20:11:11.910 CUL_HM TuerTerasse contact: closed (to VCC

Sollte man sich merken und bei Szenarien mit Fensterkontakten und Feuermelder / Alamtechnik auf HM-IO umrüsten.

frank · 24 Juli 2016, 20:36:46

oder die blockierenden module/aktionen in ein 2. fhem auslagern und mit fhem2fhem verbinden.

RalfRog · 24 Juli 2016, 21:09:22

Auch ne Idee.

Das Projet für die CULFW mit Timestamp beinhaltet aber nur den V3 und der CUbe ist nicht dabei, oder?

RalfRog · 24 Juli 2016, 21:52:21

Vielen Dank an Alle für die Erklärungen.
Nicht alles erschließt sich durch Wiki und Forenbeiträge.

Ich denke die Beobachtungen zeigen, dass es Timing- bzw. Lastprobleme in FHEM sind.
Praktisch hatte es sich nicht ausgwirkt da die Nachrichten verschickt wurden und der Status in FHEM korrekt dargestellt wurde (halt doch: mit AES machte der Türkontakt die rote Lampe an).

Edit: siehe auch hier Anmerkung am Ende von Beitrag #149
https://forum.fhem.de/index.php/topic,24436.msg466261.html#msg466261

Wenn das System wächst Sicherheits- und Alarmanlagenfunktionen dazu kommen steigt man besser auf ein HM-IO um.
Und ich sattle jetzt wieder auf meinen Pi2 um. Der fühlt sich sowie an der Weboberfläche und mit HTTPS besser an.