Fehlende ACKs nach Update 00_CUL.pm 4389 --> 4467

[Andre]

Hallo,

ich habe seit einigen Tagen Probleme mit dem Empfang der ACKs (grüne LED) meiner Fenstersensoren (HM-SEC-SC) und meiner Fernbedienung (HM-RC-SEC3). Bislang lief alles tadellos, doch seit einem Update Ende Dezember kommen die ACKs nur noch selten an. Bei meinen Fenstersensoren kommt hauptsächlich der ACK für das Öffnen des Kontakts an, meine Fernbedienung empfängt gar keine ACKs mehr. Für mich sieht das derzeit ein wenig sporadisch aus. Beim Zurückspielen meiner Backups habe ich irgendwann festgestellt, das es an einem Update in der Datei 00_CUL.pm liegen könnte, und zwar die Änderung von

# $Id: 00_CUL.pm 4389 2013-12-16 06:47:56Z rudolfkoenig $ --> # $Id: 00_CUL.pm 4467 2013-12-26 17:11:11Z rudolfkoenig $

Ich habe das Öffnen und Schließen eines Fenstersensors vor der Änderung und nach der Änderung aufgezeichnet:

Vor der Änderung (Funktioniert einwandfrei)

Schließen:

Code Auswählen Erweitern


2014.01.02 01:21:21.840 5: CUL/RAW: /A0CB2A4411CFF4CF1103401E3000D

2014.01.02 01:21:21.842 5: myCUL: A0CB2A4411CFF4CF1103401E300 -67.5
2014.01.02 01:21:21.845 5: myCUL dispatch A0CB2A4411CFF4CF1103401E300::-67.5:myCUL
2014.01.02 01:21:21.856 5: myCUL sending As0DB28002F110341CFF4C0101C800
2014.01.02 01:21:21.939 5: SW: As0DB28002F110341CFF4C0101C800


Öffnen:

Code Auswählen Erweitern


2014.01.02 01:21:25.839 5: CUL/RAW: /A0CB3A4411CFF4CF1103401E4C80A

2014.01.02 01:21:25.842 5: myCUL: A0CB3A4411CFF4CF1103401E4C8 -69
2014.01.02 01:21:25.845 5: myCUL dispatch A0CB3A4411CFF4CF1103401E4C8::-69:myCUL
2014.01.02 01:21:25.856 5: myCUL sending As0DB38002F110341CFF4C0101C800
2014.01.02 01:21:25.938 5: SW: As0DB38002F110341CFF4C0101C800


Nach der Änderung (Funktioniert sporadisch):

Schließen (klappt nicht im Beispiel):

Code Auswählen Erweitern


2014.01.02 01:24:45.351 5: CUL/RAW: /A0CB4A4411CFF4CF1103401E50012

2014.01.02 01:24:45.353 4: CUL_Parse: myCUL A 0C B4 A441 1CFF4C F11034 01E50012 -65
2014.01.02 01:24:45.357 5: myCUL dispatch A0CB4A4411CFF4CF1103401E500::-65:myCUL
2014.01.02 01:24:45.367 5: myCUL sending As0DB48002F110341CFF4C0101C800
2014.01.02 01:24:45.370 5: CUL 1CFF4C dly:86ms
2014.01.02 01:24:45.578 4: CUL_send:  myCULAs 0D B4 8002 F11034 1CFF4C 0101C800
2014.01.02 01:24:46.080 5: CUL/RAW: /A0CB4A0411CFF4CF1103401E50013

2014.01.02 01:24:46.083 4: CUL_Parse: myCUL A 0C B4 A041 1CFF4C F11034 01E50013 -64.5
2014.01.02 01:24:46.085 5: myCUL dispatch A0CB4A0411CFF4CF1103401E500::-64.5:myCUL
2014.01.02 01:24:47.053 5: CUL/RAW: /A0CB4A0411CFF4CF1103401E50013

2014.01.02 01:24:47.056 4: CUL_Parse: myCUL A 0C B4 A041 1CFF4C F11034 01E50013 -64.5
2014.01.02 01:24:47.071 5: myCUL dispatch A0CB4A0411CFF4CF1103401E500::-64.5:myCUL
2014.01.02 01:24:48.997 5: CUL/RAW: /A0CB4A0411CFF4CF1103401E50012

2014.01.02 01:24:49.000 4: CUL_Parse: myCUL A 0C B4 A041 1CFF4C F11034 01E50012 -65
2014.01.02 01:24:49.003 5: myCUL dispatch A0CB4A0411CFF4CF1103401E500::-65:myCUL


Hier ist scheinbar ein ACK gesendet worden, aber vermutlich zu spät für das Timing im Sensor (?). Der Fenstersensor sendet zwar noch ein paar versuche, es kommt aber kein weiterer ACK aus FHEM (via CUL).

Öffnen (klappt im Beispiel):

Code Auswählen Erweitern


2014.01.02 01:24:57.852 5: CUL/RAW: /A0CB5A4411CFF4CF1103401E6C813

2014.01.02 01:24:57.855 4: CUL_Parse: myCUL A 0C B5 A441 1CFF4C F11034 01E6C813 -64.5
2014.01.02 01:24:57.858 5: myCUL dispatch A0CB5A4411CFF4CF1103401E6C8::-64.5:myCUL
2014.01.02 01:24:57.869 5: myCUL sending As0DB58002F110341CFF4C0101C800
2014.01.02 01:24:57.872 5: CUL 1CFF4C dly:86ms
2014.01.02 01:24:58.118 4: CUL_send:  myCULAs 0D B5 8002 F11034 1CFF4C 0101C800
2014.01.02 01:24:58.132 5: CUL/RAW: /A0CB5A0411CFF4CF1103401E6C813


Verwende ich aktuelle Sourcen bis auf die 00_CUL.pm (da nehme ich diese: # $Id: 00_CUL.pm 4389 2013-12-16 06:47:56Z rudolfkoenig $) funktioniert alles wie bisher. Neben dem Log-Format hat sich hier etwas an dem "Delay" geändert (mir ist nicht ganz klar was hier gemacht wird, daher zitiere ich delay nur aus dem Quellcodekommentar):

Vorher (Rev 4389):

Code Auswählen Erweitern


    if($hm) {
      CUL_XmitLimitCheckHM($hash,$bstring, $now);
    } else {
      CUL_XmitLimitCheck($hash, $bstring, $now);
    }
    CUL_SimpleWrite($hash, $bstring);


Nachher (Rev 4467):

Code Auswählen Erweitern


    if($hm) {
      CUL_SimpleWrite($hash, $bstring) if(!CUL_XmitDlyHM($hash,$bstring,$now));
      return;
    } else {
      CUL_XmitLimitCheck($hash, $bstring, $now);
      CUL_SimpleWrite($hash, $bstring);
    }


Die bisherige Funktion CUL_XmitLimitCheckHM ist durch CUL_XmitDlyHM ersetzt worden. Kann mein Problem hierher kommen? Oder bin ich auf der falschen Fährte? Hat einer eine Idee dazu oder ähnliche Probleme?

Danke!

Gruß,

André

[martinp876]

Hi André,

ja, dein Problem kann daher kommen.

Hintergrund:
hier die entscheidenden Zeilen
01:24:45.351   CUL/RAW: /A0CB4A4411CFF4CF1103401E50012
# mach 100ms muss das ack gesendet werden
01:24:45.367   myCUL sending As0DB48002F110341CFF4C0101C800
#kalkulierter Delay:86ms
01:24:45.370   CUL 1CFF4C dly:86ms
# fhem delay 210ms - zu spät
01:24:45.578   CUL_send:  myCULAs 0D B4 8002 F11034 1CFF4C 0101C800

Rudi hatte korrekt angemerkt, dass HM aktiv wartet (hier wären es 86ms) und damit das System blockiert. Das ist immer unschön und sollte nach Möglichkeit vermieden werden.
So habe ich die Alternative (SW-technisch korrekter) passiv-warten eingebaut. Jetzt kann FHEM zwischendurch andere Dinge erledigen. Leider gibt es bei dir jobs, die einzeln oder im Block 130 - 210ms dauern.

Wir sind also in einem Dilemma - wir kommen wohl um das Blockieren nicht herum, da FHEM bislang keinen präzisen timer kann, single tasked ist und preemption nicht unterstützt.

Langer Rede kurzer sinn - ich werde es korrigieren und mit Rudi (owner der CUL) diskutieren.

Anbei eine Version in der du es einstellen kannst.
Attribut waitPassiv ist ein attribut der CUL (in dieser Version)
'0' ist activ-warten, also 'wie früher' - ist auch default

Die Version enthält auch verbesserungen bei -multi-io betrieb (falls du mehrere IO devices aktiv für HM nutzt)


Gruss Martin

[Andre]

Hallo Martin,

Danke für die schnelle Antwort. Ich habe das Modul eingespielt und getestet - funktioniert! Kommt das demnächst ins Repo oder soll ich das auf meiner exclude-Liste lassen?

Bei dem fehlgeschlagenen ACK (da zu spät) sendet der Sensor ja erneut, FHEM antwortet aber nicht mit weiteren ACKs (meine Interpretation der Logs). Vom Gefühl her ist das auch so (und war auch früher so), entweder ich bekomme direkt eine positive Rückmeldung (grüne LED), oder der Sensor geht an sein transmitRetry Limit. Ist das ein gewolltes Verhalten?

Habe ich eine Chance herauszufinden wo bei mir die Zeit liegen bleibt? Für das debuggen hatte ich bereits alle notifies deaktiviert.

Gruß,
André

[martinp876]

Hallo André,

Rudi ist owner des 00_CUL - ich kann es bei ihm nur beantragen. In jeden Fall muss es eine Änderung geben - ich werde es mit ihm diskutieren. Ob es steuerbar (attribut) sein wird ist...

Beim ack auf Wiederholungen muss ich noch nachdenken. Die Herausforderung ist, die doppelten Antworten(u.a. bei mehreren IOs) von den Wiederholungen zu differenzieren...

zu deinen Verzögerungen - ich habe ein modul gebastelt (apptime) kannst du vom Link downloaded
http://forum.fhem.de/index.php/topic,16103.msg111482.html#msg111482

das sollte zu mindest helfen Siehe auch
http://forum.fhem.de/index.php/topic,17746.msg117049.html#msg117049

Gruss Martin

[Andre]

Hallo Martin,

vielen Dank dafür. Scheinbar liegt meine Verzögerung am notify loop, da ich die Alarmanlage darüber steuere und einige Checks darauf horchen. Zusätzlich hatte ich einige unsaubere notifies, die doppelt ausgelöst haben. Wirklich aufwendige Sachen werden dabei nicht gemacht, aber ein paar ms sind halt immer weg.

Verwendet man statt des selects den internen Timer, wird der ACK erst gesendet wenn der komplette Notify loop abgearbeitet ist. Vermutlich kompliziert, aber wäre es nicht möglich innerhalb des Loops auch andere Events zu bearbeiten, die vom Timing her eine hohe Prio haben (wie der ACK)?

Im Repo habe ich eine neue 10_CUL.pm Version gesehen, die wieder mit einem select arbeitet, kommt beim update aber noch nicht mit. Dauert vermutlich ein wenig.

Wenn ich bei dem mulit-ACK irgendwie helfen kann, gib mir Bescheid. Ich kann gerne testen, loggen, etc. Ist MultiIO der einzige Grund oder gibt es noch andere?

Grüße,
André

[meldelinie]

Hallo,
meine MAX! Ecotaster meldeten sporadisch seit kurzem fehlende ACKS (3x blinken).

Merkwürdigerweise kam oft nach missing ACK (3x blinken) noch ein OK (1x blinken) hinterher.

Mit der Version von martinp876 und dem neuen Attribut funkt es wieder.

Danke an euch beide !

[martinp876]

Hi,

die neue Version ist drin, das Attribut drausen. Es wird jetzt immer aktiv gewartet (wie früher)

Der Update sollte sein heute Verfügbar sein.

@André
es gibt keine prioritäten in FHEM (leider)
es bringt aber auch nicht wirklich viel - der bringer wäre eine unterbrechbarkeit. Das ist aber nachträglich wirklich komplex.
Wenn etwas kommt, dass das auslagern des sendens incl des Wartens in einen separaten Process.

Meine implementierung der ack für wiederhohl-messages hatte bugs - sollte jetzt (aus SVN) oder morgen per update funktionieren. Falls du testen willst, gerne. Multi-IOs sollten auch funktionieren, wie vorher

Gruss Martin

[Andre]

Hallo Martin,

ich habe die Version aus dem SVN geladen. Funktioniert jetzt wunderbar, auch die weiteren ACKs kommen an. Multi IO kann ich leider nicht testen, da ich nur ein Device habe.

Vielen Dank für Deine Hilfe!

/André