doppelter Empfang, dupetimeout and so on ...

Begonnen von fhem-challenge, 21 April 2017, 14:57:12

Vorheriges Thema - Nächstes Thema

fhem-challenge

Seit jeher habe ich sporadisch Probleme mit dem doppeltem Empfang über meine IODEV's (i.d.R. slowrf FS20 usw.).
Bei Temperaturwerten stört mich das weniger, da ich im dblog ja ohnehin meist "event-on-change-reading" nutze und dadurch als Nebeneffekt die doppelten Werte nicht geloggt werden.

"Blöd" wird das Ganze eben, wenn ich meine (alten) FS20 6-fachSchalter verwende, die ganze Prozesse auslösen (Beispiel: AllesAusschalten... ), dann wird bei mir der Prozess zweimal oder mehrfach durchlaufen, was eher sehr unnötig ist.

Ich hab das dupetimeout mittlerweile auf 12(s) gestellt. Sehr viel kleinere Werte führen dann sogleich ins "Verderben".

Ich nutze momentan an IODev's:

1 x HMLAN (HM)
1 x cul433-Keller (slowRF, IT)
1 x CUL_868_Garage (slowRF über FHEM2FHEM (RAW))
1 x cul868-Keller (slowRF)
1 x CUN1-868 (slowRF)
1 x CUN2-433 (slowRF, IT)
1 x CUN3-HM (HM)

Auffällig ist aus meiner Sicht auch, mein CUL868_Garage, der über FHEM2FHEM angebunden ist. Den habe ich schon wohlweislich nicht im LOG-Mode, da hier ja die dupe-detection gänzlich nicht funktioniert. Aber warum habe ich dennoch doppelte Events, hier am Beispiel des CUL_WS S300TH Temp_Poolraum der über den lolkalen cul868 empfangen wird, und über CUL_868_Garage  FHEM2FHEM:RAW.

2017.04.21 13:47:09 4: CUL_WS S300TH Temp_Poolraum: T: 17.7  H: 62.2
2017.04.21 13:47:09 4: CUL_Parse: cul868 K117721622C -52
2017.04.21 13:47:09 4: CUL868_Garage: CUL CUL_868_Garage K11772162
...
2017.04.21 13:50:44 4: CUL_WS S300TH Temp_Hobbyraum: T: 17.9  H: 44.1
2017.04.21 13:50:44 4: CUL_Parse: cul868 K3179114404 -72
2017.04.21 13:50:44 4: CUL868_Garage: CUL CUL_868_Garage K31791144


Ich hätte bei beiden obigen Events eigentlich ein "... dupe: dont process" erwartet ? Oder sehe ich das falsch ?

Welche Möglichkeiten stehen mir noch offen, die "dupes" herauszufiltern, ohne mir selbst an jeder Stelle code einzubauen, der das erledigt.


Viele Grüße!


Andreas

rudolfkoenig

Es heisst nicht dupe sondern dup, es kommt von duplicate.

Dein Log-Auszug beweist nur, dass beide CULs die Nachricht empfangen haben, und FHEM2FHEM auch. FHEM2FHEM ruft nach der Logmeldung Dispatch auf, was per CheckDuplicate (hoffentlich) das Duplikat erkennt. En Nachweis waere fuer mich, wenn im Event-Monitor (oder telnet:inform timer) das "verdaute" Event doppelt kommt. Zum debuggen brauche ich dann die zu den Events passende "attr global verbose 5" Logs.

Ich habe gerade ein aehnlches Szenario hier getestet (1. CUL lokal, 2.CUL per FHEM2FHEM), die Duplikat-Erkennung funktioniert mi der Voreinstellung.

fhem-challenge

Zitat von: rudolfkoenig am 23 April 2017, 12:52:21
Es heisst nicht dupe sondern dup, es kommt von duplicate.

Dein Log-Auszug beweist nur, dass beide CULs die Nachricht empfangen haben, und FHEM2FHEM auch. FHEM2FHEM ruft nach der Logmeldung Dispatch auf, was per CheckDuplicate (hoffentlich) das Duplikat erkennt. En Nachweis waere fuer mich, wenn im Event-Monitor (oder telnet:inform timer) das "verdaute" Event doppelt kommt. Zum debuggen brauche ich dann die zu den Events passende "attr global verbose 5" Logs.

Ich habe gerade ein aehnlches Szenario hier getestet (1. CUL lokal, 2.CUL per FHEM2FHEM), die Duplikat-Erkennung funktioniert mi der Voreinstellung.

Ja "dupTimeout" habe ich auch in der config (ich hatte es nur noch so ungefähr syntaktisch im Gedächtnis).

Anbei log mit verbose=5 und nur dispatch und parse:

root@fhem:~# tail -2000  /opt/fhem/log/fhem-2017-04.log | grep -iE "dispatch.K[0-9]{1,10}|CUL_Parse.*K[0-9]{1,10}"
2017.04.24 08:51:32 4: CUL_Parse: mapleCUN1 K1188116114 -64
2017.04.24 08:51:32 5: mapleCUN1: dispatch K11881161
2017.04.24 08:51:32 4: CUL_Parse: cul868 K118811612C -52
2017.04.24 08:51:32 5: cul868: dispatch K11881161
2017.04.24 08:51:32 5: CUL_868_Garage: dispatch K11881161
2017.04.24 08:52:23 4: CUL_Parse: mapleCUN1 K176660170153D0FF -74.5
2017.04.24 08:52:23 4: CUL_Parse: cul868 K176660170153D0E3 -88.5
2017.04.24 08:52:42 4: CUL_Parse: mapleCUN1 K3165014526 -55
2017.04.24 08:52:42 5: mapleCUN1: dispatch K31650145
2017.04.24 08:52:42 5: CUL_868_Garage: dispatch K31650145
2017.04.24 08:52:42 4: CUL_Parse: cul868 K3165014505 -71.5
2017.04.24 08:52:42 5: cul868: dispatch K31650145
2017.04.24 08:53:11 4: CUL_Parse: mapleCUN1 K0162306014 -64
2017.04.24 08:53:11 5: mapleCUN1: dispatch K01623060
2017.04.24 08:53:11 5: CUL_868_Garage: dispatch K01623060
2017.04.24 08:53:27 4: CUL_Parse: mapleCUN1 K4115416223 -56.5
2017.04.24 08:53:27 5: mapleCUN1: dispatch K41154162
2017.04.24 08:53:27 4: CUL_Parse: cul868 K4115416222 -57
2017.04.24 08:53:27 5: cul868: dispatch K41154162
2017.04.24 08:53:27 5: CUL_868_Garage: dispatch K41154162
2017.04.24 08:53:32 4: CUL_Parse: mapleCUN1 K216551451C -60
2017.04.24 08:53:32 5: mapleCUN1: dispatch K21655145
2017.04.24 08:53:32 4: CUL_Parse: cul868 K21655145FC -76
2017.04.24 08:53:32 5: cul868: dispatch K21655145
2017.04.24 08:53:32 5: CUL_868_Garage: dispatch K21655145
2017.04.24 08:53:54 4: CUL_Parse: mapleCUN1 K514721441B -60.5
2017.04.24 08:53:54 5: mapleCUN1: dispatch K51472144
2017.04.24 08:53:54 4: CUL_Parse: cul868 K5147214404 -72
2017.04.24 08:53:54 5: cul868: dispatch K51472144
2017.04.24 08:54:28 4: CUL_Parse: mapleCUN1 K1188116113 -64.5
2017.04.24 08:54:28 5: mapleCUN1: dispatch K11881161
2017.04.24 08:54:28 5: CUL_868_Garage: dispatch K11881161
2017.04.24 08:54:28 4: CUL_Parse: cul868 K118811612A -53
2017.04.24 08:54:28 5: cul868: dispatch K11881161


sowie hier ein paar Impressionen (mit mehr Details) für die S300TH K41154162 & K11901161:

2017.04.24 09:12:02 4: CUL_Parse: mapleCUN1 **A0DAD841019819B6EF4150601E9004E
2017.04.24 09:12:02 5: mapleCUN1: dispatch **A0DAD841019819B6EF4150601E9004E
2017.04.24 09:12:02 4: CUL_Parse: mapleCUN3 A 0D AD 8410 19819B 6EF415 0601E9004E -35
2017.04.24 09:12:02 5: mapleCUN3: dispatch A0DAD841019819B6EF4150601E900::-35:mapleCUN3
2017.04.24 09:12:02 5: Starting notify loop for move.i.HM.Wohnzimmer, 5 event(s), first is battery: ok
2017.04.24 09:12:02 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:12:02 5: End notify loop for move.i.HM.Wohnzimmer
2017.04.24 09:12:02 4: CUL_HM move.i.HM.Wohnzimmer dupe: dont process
2017.04.24 09:12:02 5: Starting notify loop for move.i.HM.Wohnzimmer, 2 event(s), first is RAWMSG: E19819B,0000,0E21445A,FF,FFD8,AD841019819B6EF4150601E900
2017.04.24 09:12:02 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:12:02 5: End notify loop for move.i.HM.Wohnzimmer
2017.04.24 09:12:03 5: Starting notify loop for HMLAN2, 1 event(s), first is loadLvl: low
2017.04.24 09:12:03 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:12:03 5: End notify loop for HMLAN2
2017.04.24 09:12:07 5: CUL/RAW: /K1190116114
2017.04.24 09:12:07 4: CUL_Parse: mapleCUN1 K1190116114 -64
2017.04.24 09:12:07 5: mapleCUN1: dispatch K11901161
2017.04.24 09:12:07 4: CUL_WS S300TH Temp_Poolraum: T: 19.0  H: 61.1
2017.04.24 09:12:07 5: Starting notify loop for Temp_Poolraum, 2 event(s), first is RSSI: -64
2017.04.24 09:12:07 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:12:07 5: End notify loop for Temp_Poolraum
2017.04.24 09:12:07 5: CUL/RAW: /K119011612A
2017.04.24 09:12:07 4: CUL_Parse: cul868 K119011612A -53
2017.04.24 09:12:07 5: cul868: dispatch K11901161
2017.04.24 09:12:07 4: CUL868_Garage: CUL CUL_868_Garage K11901161
2017.04.24 09:12:07 5: CUL_868_Garage: dispatch K11901161
...
2017.04.24 09:13:51 4: CUL_Parse: cul868 K01637060F1 -81.5
2017.04.24 09:13:51 5: cul868: dispatch K01637060
2017.04.24 09:13:52 5: CUL/RAW: /K4115416223
2017.04.24 09:13:52 4: CUL_Parse: mapleCUN1 K4115416223 -56.5
2017.04.24 09:13:52 5: mapleCUN1: dispatch K41154162
2017.04.24 09:13:52 4: CUL_WS S300TH Temp_Toilette: T: 11.5  H: 62.4
2017.04.24 09:13:52 5: Starting notify loop for Temp_Toilette, 2 event(s), first is RSSI: -56.5
2017.04.24 09:13:52 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:13:52 5: End notify loop for Temp_Toilette
2017.04.24 09:13:52 4: CUL868_Garage: CUL CUL_868_Garage K41154162
2017.04.24 09:13:52 5: CUL_868_Garage: dispatch K41154162
2017.04.24 09:13:52 5: CUL/RAW: /K4115416222
2017.04.24 09:13:52 4: CUL_Parse: cul868 K4115416222 -57
2017.04.24 09:13:52 5: cul868: dispatch K41154162
2017.04.24 09:13:54 5: Starting notify loop for analog2.1, 2 event(s), first is reading: 350
2017.04.24 09:13:54 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 09:13:54 5: End notify loop for analog2.1
2017.04.24 09:13:54 5: Starting notify loop for analog2.2, 1 event(s), first is Spannung: 0.352
2017.04.24 09:13:54 5: RG_TempHygro: not on any display, ignoring notify


Ich hoffe, das der LogAuszug einigermassen hilfreich ist ?


Viele Grüße!


Andreas

rudolfkoenig

ZitatIch hoffe, das der LogAuszug einigermassen hilfreich ist ?
Wenn es genau zu den noch zu liefernden Event-Monitor / inform-Timer Liste passt, dann ja.
So nicht.

fhem-challenge

Zitat von: rudolfkoenig am 24 April 2017, 09:51:23
Wenn es genau zu den noch zu liefernden Event-Monitor / inform-Timer Liste passt, dann ja.
So nicht.



Anbei mit event-Monitor:


Inform timer:

2017-04-24 10:26:47 CUL_WS Temp_Toilette humidity: 62.4
2017-04-24 10:26:47 CUL_WS Temp_Toilette RAWMSG: K41164162
2017-04-24 10:26:47 CUL_WS Temp_Toilette RSSI: -57.5
2017-04-24 10:26:47 CUL_WS Temp_Toilette dewpoint: 4.7


Die internals:

CUL_868_Garage_TIME
2017-04-24 10:26:47

cul868_RAWMSG
K41164162
cul868_RSSI
-58
cul868_TIME
2017-04-24 10:26:47

mapleCUN1_RAWMSG
K41164162
mapleCUN1_RSSI
-57.5
mapleCUN1_TIME
2017-04-24 10:26:47


log mit verbose=5:

2017.04.24 10:26:47 4: CUL_Parse: mapleCUN1 K4116416221 -57.5
2017.04.24 10:26:47 5: mapleCUN1: dispatch K41164162
2017.04.24 10:26:47 4: CUL_WS S300TH Temp_Toilette: T: 11.6  H: 62.4
2017.04.24 10:26:47 5: Starting notify loop for Temp_Toilette, 3 event(s), first is humidity: 62.4
2017.04.24 10:26:47 5: RG_TempHygro: not on any display, ignoring notify
2017.04.24 10:26:47 5: Triggering alarm_dewpoint
...
2017.04.24 10:26:47 5: CUL/RAW: /K4116416220
...
2017.04.24 10:26:47 4: CUL_Parse: cul868 K4116416220 -58
2017.04.24 10:26:47 5: cul868: dispatch K41164162
2017.04.24 10:26:47 4: CUL868_Garage: CUL CUL_868_Garage K41164162
2017.04.24 10:26:47 5: CUL_868_Garage: dispatch K41164162
2017.04.24 10:26:49 5: CUL/RAW: /**A0C0E84703032B200000000A3292E



Viele Grüße!

Andreas

rudolfkoenig

Ich sehe im Event-Monitor-Log keine doppelten Events.

fhem-challenge

Zitat von: rudolfkoenig am 24 April 2017, 10:57:45
Ich sehe im Event-Monitor-Log keine doppelten Events.

Richtig, ich jetzt für den einen TempSensor auch nicht. Ich bin leider derzeit nicht vor Ort. Ich melde mich, wenn ich die Situation mit dem "6-fach FS20 Schalter" nachgestellt habe und das logging höher gestellt habe.

Viele Dank!

Gruss

Andreas