ReadAnswerFn und SendStack

[A.Harrenberg]

Hallo Rudi,

ich beobachte immer wieder ein Problem (vor allem mit SECURITY Befehlen) mit dem Sendstack und dem Aufruf der ReadAnswerFn in ZWave_CMD

Code Auswählen Erweitern

  my $r = ZWave_addToSendStack($baseHash, $data);
  if($r) {
    return (AttrVal($name,"verbose",3) > 2 ? $r : undef);
  }

  my $val;
  if($type eq "get") {
    no strict "refs";
    my $iohash = $hash->{IODev};
    my $fn = $modules{$iohash->{TYPE}}{ReadAnswerFn};
    my $re = $cmdList{$cmd}{regexp};
    my ($err, $data) = &{$fn}($iohash, $cmd, $re ? $re : "^000400${id}..$cmdId")
                        if($fn);
 

Und zwar kommt es relativ häufig vor, das die ReadAnswerFn aufgerufen wird, BEVOR der Befehl durch den Sendstack überhaupt versendet wurde. Dadurch wird dann das eigentliche versenden verhindert und die Übertragung verursacht einen 3 Sekunden Time-Out...
Das Problem tritt verstärkt dann auf, wenn im Dongle noch "delayNeeded" auf 1 steht, da dann das Versenden ja noch mal 0.3 Sekunden verzögert wird.

(Ich konnte das bisher in Ermangelung eines WakeUp Testobjektes noch nicht ausprobieren, aber eigentlich müsste dieser 3 Sekunden Time-Out doch auch dafür sorgen das der Sendstack aktiv wird, oder?)

Auf Anhieb fällt mir da auch leider keine Lösung für ein, hast Du vielleicht eine Idee wie man das verhindern könnte?

Gruß,
Andreas.

[rudolfkoenig]

Versteh das Problem aus deiner Beschreibung nicht.

Der Sendstack wird abgearbeitet, entweder nach Antwort vom Geraet, oder nach Timeout.
Normallfall ist kein Timeout, d.h, die Befehle werden solange ausgesendet/vom Geraet bestaetigt bis der "get" Befehl dran ist, und dessen Antwort wird dann von der Schleife akzeptiert. Haken: waehrend des gets werden alle _anderen_ Geraete von FHEM ignoriert.

get  sollte wg. der "monothreading" Architektur von FHEM nur selten verwendet werden, eigentlich gehoert es komplett abgeschafft, da es ein Hack ist, und FHEM bis auf das abgefragte Geraet blockiert. Mir waere es deutlich lieber, wenn du secNonce und secSupported nicht als get, sondern als set realisieren wuerdest, damit wuerde man sicher Probleme vermeiden.

[A.Harrenberg]

Hallo Rudi,

hab' gerade leider kein Logfile zur Hand um mal ein Beispiel zeigen zu können.

Was ich beobachte ist folgendes:

Get-Befehl wird erzeugt, geparst und mit ZWave_addToSendStack an den Sendstack übergeben.

Dann wird ReadAnswerFn aufgerufen noch bevor der Befehl vom Sendstack per IOWrite gesendet wurde. Jetzt läuft der 3-Sekunden Time-out. Erst nachdem der Time-Out abgelaufen ist und ReadAnswerFn die Fehlermeldung ausgegeben hat wird der Befehl (auf dessen Antwort ja gerade vergeblich gewartet wurde) per IOWrite gesendet. Der Aufruf von ReadAnswerFn blockiert daher anscheinend auch das weitere Versenden per IOWrite auf dem gleichen Device.

Das der GET-Aufruf den Rest von FHEM blockiert war mir bisher auch nicht so klar. Wäre es dann nicht konsequent bei ALLEN Get-Befehlen auch secInProgress zu setzen und so das Versenden von weiteren Nachrichten zu blockieren bis die Antwort eingetroffen ist? Das würde den Rest von FHEM/ZWave nicht blockieren.

Ich denke wir sollten beide noch mal darüber nachdenken was hier möglich ist. Auch bei unverschlüsselten Nachrichten wäre es unschön eine weitere Nachricht an ein Gerät zu senden wenn noch auf die Antwort der letzten Nachricht gewartet wird. Das sollte eigentlich zu einer CAN-Message vom Gerät führen.

Gruß,
Andreas.

[rudolfkoenig]

Dann wird ReadAnswerFn aufgerufen noch bevor der Befehl vom Sendstack per IOWrite gesendet wurde.

Das verstehe ich nicht, bzw. wenn das wiederholbar der Fall ist, dann ist das ein Bug.

Auch bei unverschlüsselten Nachrichten wäre es unschön eine weitere Nachricht an ein Gerät zu senden wenn noch auf die Antwort der letzten Nachricht gewartet wird.

Dieses Problem sehe ich nicht. get blockiert FHEM, es werden keine Befehle gesendet, bevor die Antwort eintrifft, da man nicht in der Lage ist, Befehle nach dem get/waehrend get wartet auf dem SendStack zu legen. Heisst nicht, dass ich meine Meinung zu get geaendert habe.

Das sollte eigentlich zu einer CAN-Message vom Gerät führen.

Das wuerde mich wundern, CAN kommt vom Dongle, und der weiss nicht, ob man auf Antwort wartet, oder nicht.

[A.Harrenberg]

Hi Rudi,

ich versuche das heute abend noch mal nachzustellen (hab leider gestern meine logfiles gelöscht...) und schicke Dir das mal als log.

Im Log steht (aus dem Gedächtnis) dann was von:
ZWave_write <FHEM Befehl>
dann was von ReadAnswer mit der RegEx
dann kommt der Timeout von ReadAnswerFn
erst dann kommt die Meldung von simpleWrite mit SW:<Befehlscode> und die Nachricht wird verschickt

Das ist sicherlich nicht so geplant, wenn ich mir den Ablauf ansehen und dazu dann noch der zusätzliche Delay in ProcessSendStack wundert mich das allerdings nicht wirklich.

Meine Bemerkungen zu get bei unverschlüsselten nachrichten bezogen sich auf den Fall das die Behandlung von GET in ZWave_CMD mittels ReadAnswerFn ausgebaut wird. Momentan funktioniert das noch wie gewollt, auch wenn es FHEM blockiert.

Ich bin bisher davon ausgegangen das CAN vom Gerät als Antwort gesendet wird wenn die aktuelle Nachricht gerade nicht akzeptiert werden kann, z.B. weil noch eine andere Kommunikation läuft. Aus welchem Grund sollte der Dongle denn von sich aus CAN-Msg melden?

Gruß,
Andreas.

[rudolfkoenig]

Aus welchem Grund sollte der Dongle denn von sich aus CAN-Msg melden?

Gute Frage, weiss nicht genau. Vermutlich, wenn irgendwelche Puffer voll sind.

[A.Harrenberg]

Hallo Rudi,

hier mal ein Beispiel aus meinem Log, allerdings finde ich das NUR in Verbindung mit Security und GET-secNonce, ich werde mir meinen Code auch noch mal genauer anschauen, vielleicht liegt es ja an meinen Eingriffen...

Code Auswählen Erweitern

2015.10.12 18:52:34.284 5: ZWDongle_0 dispatch 000400a503980500
2015.10.12 18:52:34.284 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:a5 ARG:03980500
2015.10.12 18:52:34.284 2: ZWave get ZWave_SENSOR_MULTILEVEL_165 secNonce
2015.10.12 18:52:34.284 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a5..98
2015.10.12 18:52:36.544 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400a5032001ff
2015.10.12 18:52:36.544 5: SW: 06
2015.10.12 18:52:36.545 5: ZWDongle_0 dispatch 000400a5032001ff
2015.10.12 18:52:36.546 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:a5 ARG:032001ff
2015.10.12 18:52:36.852 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400a50a7105000000ff07080000
2015.10.12 18:52:36.852 5: SW: 06
2015.10.12 18:52:36.853 5: ZWDongle_0 dispatch 000400a50a7105000000ff07080000
2015.10.12 18:52:36.853 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:a5 ARG:0a7105000000ff07080000
2015.10.12 18:52:39.857 5: ZWDongle_ReadAnswer: select timeout
2015.10.12 18:52:39.857 5: ZWDongle_Write 00 13a502984025a5
2015.10.12 18:52:39.857 5: SW: 01090013a502984025a51a
2015.10.12 18:52:39.890 5: ACK received, removing 01090013a502984025a51a from dongle sendstack
2015.10.12 18:52:39.907 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.10.12 18:52:39.907 5: SW: 06

Hier kommt nach dem "ZWave get ZWave_SENSOR_MULTILEVEL_165 secNonce" direkt das "ZWDongle_ReadAnswer arg:secNonce regexp:^000400a5..98", der Befehl wird aber erst viel später ausgelöst "ZWDongle_Write 00 13a502984025a5" und verschickt "SW: 01090013a502984025a51a"

Unter normalen Bedingungen kann ich das aktuell nicht provozieren.

Wenn ich mehrere (Security)-Befehle abschicke die dann "durcheinander" laufen passiert das auch. Wenn man unter Security mal ein "set ... configRequestAll" absetzt kommt das System irgendwann so durcheinander das für einen Zeitraum >10 gar nichts mehr gesendet wird...

Code Auswählen Erweitern

2015.10.12 20:01:24.707 2: ZWave get ZWave_SENSOR_MULTILEVEL_168 secNonce
2015.10.12 20:01:24.708 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a8..98
2015.10.12 20:01:27.714 5: ZWDongle_ReadAnswer: select timeout
2015.10.12 20:01:27.715 1: configGroup2Reports: Timeout reading answer for get secNonce
2015.10.12 20:01:27.715 2: ZWave set ZWave_SENSOR_MULTILEVEL_168 configGroup3Interval
2015.10.12 20:01:27.715 1: ZWave_SENSOR_MULTILEVEL_168: CONFIGURATION is a secured class!
2015.10.12 20:01:27.715 3: ZWave_SENSOR_MULTILEVEL_168 SECURITY: 700571 stored for encryption
2015.10.12 20:01:27.715 2: ZWave get ZWave_SENSOR_MULTILEVEL_168 secNonce
2015.10.12 20:01:27.715 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a8..98
2015.10.12 20:01:30.715 5: ZWDongle_ReadAnswer: select timeout
2015.10.12 20:01:30.715 1: configGroup3Interval: Timeout reading answer for get secNonce
2015.10.12 20:01:30.716 2: ZWave set ZWave_SENSOR_MULTILEVEL_168 configGroup3Reports
2015.10.12 20:01:30.716 1: ZWave_SENSOR_MULTILEVEL_168: CONFIGURATION is a secured class!
2015.10.12 20:01:30.716 3: ZWave_SENSOR_MULTILEVEL_168 SECURITY: 700567 stored for encryption
2015.10.12 20:01:30.716 2: ZWave get ZWave_SENSOR_MULTILEVEL_168 secNonce
2015.10.12 20:01:30.716 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a8..98
2015.10.12 20:01:33.719 5: ZWDongle_ReadAnswer: select timeout
2015.10.12 20:01:33.719 1: configGroup3Reports: Timeout reading answer for get secNonce
2015.10.12 20:01:33.719 2: ZWave set ZWave_SENSOR_MULTILEVEL_168 configHumidityCalibration
2015.10.12 20:01:33.719 1: ZWave_SENSOR_MULTILEVEL_168: CONFIGURATION is a secured class!
2015.10.12 20:01:33.719 3: ZWave_SENSOR_MULTILEVEL_168 SECURITY: 7005ca stored for encryption
2015.10.12 20:01:33.719 2: ZWave get ZWave_SENSOR_MULTILEVEL_168 secNonce
2015.10.12 20:01:33.720 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a8..98
2015.10.12 20:01:36.722 5: ZWDongle_ReadAnswer: select timeout
2015.10.12 20:01:36.723 1: configHumidityCalibration: Timeout reading answer for get secNonce
2015.10.12 20:01:36.723 2: ZWave set ZWave_SENSOR_MULTILEVEL_168 configHumidityReportingThreshold
2015.10.12 20:01:36.723 1: ZWave_SENSOR_MULTILEVEL_168: CONFIGURATION is a secured class!
2015.10.12 20:01:36.723 3: ZWave_SENSOR_MULTILEVEL_168 SECURITY: 70052a stored for encryption
2015.10.12 20:01:36.723 2: ZWave get ZWave_SENSOR_MULTILEVEL_168 secNonce
2015.10.12 20:01:36.723 2: ERROR: ZWave_SENSOR_MULTILEVEL_168: cleaning commands without ack after 10s
2015.10.12 20:01:36.723 5: ZWDongle_Write 00 13a802984025a8
2015.10.12 20:01:36.723 2: ZWDongle_ProcessSendStack: no ACK, resending message 01090013a802984025a81a
2015.10.12 20:01:36.723 5: SW: 01090013a802984025a81a
2015.10.12 20:01:36.724 4: ZWDongle_ReadAnswer arg:secNonce regexp:^000400a8..98

Ich werde aber das ungute Gefühl nicht los das es etwas mit meinen Änderungen zu tun hat... ,-(

Gruß,
Andreas.

[rudolfkoenig]

Ich schlage vor, du baust alle intern verwendeten ZWave_Get's auf ZWave_Set um, bevor du das etwas verkorkste und prinzipiell kaputte get debugst.

[A.Harrenberg]

Hi,

Ich schlage vor, du baust alle intern verwendeten ZWave_Get's auf ZWave_Set um, bevor du das etwas verkorkste und prinzipiell kaputte get debugst.

ich bin ja immer noch der Meinung das man prinzipiell nach Absetzen eines GET-Befehls keine weiteren Befehle senden darf bis die Antwort empfangen wurde...

Das blockieren mit ReadAnswerFn sollte natürlich anders gelöst werden, aber ich wäre erst einmal dagegen komplett auszubauen.
Ich werde mal versuchen so einen Fall zu erzeugen wo zwischen Get und Response ein weiterer Befehl gesendet wird und dann schaue ich mal ob es dann zu einer CAN-Msg kommt oder nicht.

Gruß,
Andreas.