Modbus - Timeout2 in ReadAnswer

[Lars]

Hallo zusammen,

basierend auf 98_Modbus.pm baue ich gerade an meinem Modul für eine Nilan KWL. Ich kann sämtliche Register aus Input und Holding auslesen und auch Holding setzen.
Das von 98_Modbus.pm durchgeführte Lesen nach dem Schreiben scheitert dann allerdings mit Timeout2.
Das führt zu Fehlermeldungen im Log und auch im Web-Interface.

Den Parameter commDelay habe ich bereits probehalber auf 1.5 hochgesetzt, führte aber zu keiner Verbesserung.

Auszug aus deviceInfo zum Timing:

Code Auswählen Erweitern

    "timing"    => {
            timeout     =>  2,     
            commDelay   =>  0.7,   
            sendDelay   =>  0.7,     
            },

Und hier das Log wenn ich "Stufe" auf 1 setze:

Code Auswählen Erweitern


2017.04.09 00:48:27 5: Nilan: Set called with Stufe (h1003), setVal = 1
2017.04.09 00:48:27 5: Nilan: Set: checking value 1 against min 1
2017.04.09 00:48:27 5: Nilan: Set: checking value 1 against max 4
2017.04.09 00:48:27 5: Nilan: Set: converted Value 1 to 1 using expr $val
2017.04.09 00:48:27 5: Nilan: set packed hex 31 with n to hex 0001
2017.04.09 00:48:27 4: Nilan: Send called with h1003, len 1 / span - to id 30, op write, qlen 0, value hex 0001
2017.04.09 00:48:27 4: Nilan: Send queues fc 16 to 30, for h1003 (Stufe), len/span 1, force, value hex 0001
2017.04.09 00:48:27 5: Nilan: ReadAnswer called and remaining timeout is 1.99989986419678 requested reading is Stufe
2017.04.09 00:48:28 5: Nilan: ReadAnswer got: 1e10
2017.04.09 00:48:28 5: Nilan: ReadAnswer got: 1e1003eb
2017.04.09 00:48:28 5: Nilan: ReadAnswer got: 1e1003eb00
2017.04.09 00:48:28 5: Nilan: ReadAnswer got: 1e1003eb000173
2017.04.09 00:48:28 5: Nilan: ReadAnswer got: 1e1003eb000173d6
2017.04.09 00:48:28 5: Nilan: ReadAnswer done, reading is Stufe
2017.04.09 00:48:28 5: Nilan: Set: sending read after write
2017.04.09 00:48:28 4: Nilan: Send called with h1003, len 1 / span - to id 30, op read, qlen 0, value hex 30
2017.04.09 00:48:28 4: Nilan: Send queues fc 3 to 30, for h1003 (Stufe), len/span 1, force, value hex 30
2017.04.09 00:48:28 5: Nilan: ReadAnswer called for Stufe
2017.04.09 00:48:30 3: Nilan: Timeout2 in ReadAnswer for Stufe


[StefanStrobel]

Hallo Lars,

im Log sieht es nicht so aus, als ob ein Delay zwischen Schreiben und Lesen stattfinden würde.
Allerdings fehlt auch das Log der physischen Seite. Du scheinst nur für das logische Gerät verbose auf 5 gesetzt zu haben.
Probier das doch noch mal mit einem detaillierteren Log. Zum Testen kannst Du auch die Delays per Attribut setzen. Alle Attribute von ModbusAttr sollten auch in Deinem Modul funktionieren.

Gruss
    Stefan

[Lars]

Hallo Stefan,

danke für Deine schnelle Antwort. Ich war ein paar Tage unterwegs, daher erst heute meine Antwort. Ich habe nun herausgefunden, dass es auch die Timeouts beim "Read" über ein manuelles get (über WebInterface) gibt. Mal geht es, mal nicht. Schwer zu reproduzieren, manchmal klappen 5 Reads hintereinander, manchmal timen 2 hintereinander aus.
Ich habe noch einmal ein Log mit Verbose 5 (Auf den Stick und das Modul) gemacht und hier angehängt.

In Zeile 231 habe ich das get manuell gedrückt. Danach: "Get: Queue is stil busy - taking over the read with ReadAnswer"
In Zeile 288 ist dann das Timeout2 des manuellen get.

In Zeile 289 habe ich dann erneut manuell get gedrückt. Keine Meldung wie "Queue is stil(l) busy"
In Zeile 313 wird der Read mit value "on" bestätigt.

In Zeile 484 habe ich dann ein SET gemacht und es wird auch von der Anlage übernommen.
In Zeile 494 kommt dann das Timeout2, zuvor steht in Zeile 492 "CheckDelay commDelay for Nilan not over, sleep 0.315400123596191 forced"

Wäre super, wenn Du Dir das mal anschauen könntest.

Gruß
Lars

[StefanStrobel]

Ich würde den commDelay mal deutlich höher setzen und im Log prüfen, dass er auch wirklich greift ...
Im Log sieht es so aus, als ob er nicht deutlich höher als auf 0,5 sec steht.

Gruß
    Stefan

[StefanStrobel]

Hallo Lars,

Ich habe Dein Log nochmal genauer angesehen. Es sieht fast so aus, als ob der Schreib-Request gar nicht gesendet wird. Das ist schon seltsam. Was für ein Perl und was für eine Plattform verwendest Du denn?

Gruß
    Stefan

[Lars]

Hallo Stefan,

das CommDelay hatte ich beim Trace auf 0.7 stehen. Habe schon Werte zwischen 0.2 und 1.7 ausprobiert, das hat aber keine Auswirkungen. Was genau machen denn die Parameter commDelay und sendDelay?
Hier die Infos zu meinem System:
This is perl 5, version 22, subversion 1 (v5.22.1) built for x86_64-linux-gnu-thread-multi
(with 58 registered patches, see perl -V for more detail)
Aktuelles Ubuntu LTS auf einer ESXi VM.

Kann das vielleicht mit dem RS485 Adapter zusammenhängen? Ich habe diesen Adapter von in-circuit.de und derzeit alle DIPs auf off. Mit DIPs auf ON könnte ich folgendes machen:
R = 390Ω between Signal A and VCC
R = 220Ω between Signal A and B
R = 390Ω between Signal B and GND

Update: Die DIPs für 220 Ohm an A und B und 390 Ohm an B und GND Widerstand habe ich zur Termination gesetzt (google bildet), macht leider auch keinen Unterschied.

Gruß
Lars

[StefanStrobel]

Hallo Lars,

könntest Du mal die angehängte neue Version einspielen und wieder ein Log mit Level 5 erzeugen?
Ich habe ein paar zusätzliche Log-Meldungen eingebaut.
Für mich sieht es wie ein Software-Fehler aus, den ich bei mir nicht nachvollziehen kann ...

Gruss / Thanx
   Stefan

[Lars]

Hallo Stefan,

hast Du nur zusätzliche Logs eingebaut? Jetzt funktioniert nämlich alles und ich kann die Timeouts nicht mehr provozieren! 
Zuvor hatte ich die Datei mit 105.637 Byte mit letztem Changelogeintrag vom 2017-01-06 drin.
Wenn Du noch das Log benötigst, kann ich das natürlich noch gerne ziehen!

Addendum: Habe gerade die Änderungshistorie in dem von dir angehängten File gesehen. Hast du die Änderungen nicht eingecheckt oder hat mein FHEM die Datei beim Update nicht berücksichtigt? Mein letztes Update war Ende März.

Gruß
Lars

[StefanStrobel]

Hallo Lars,

dann war es wohl doch ein Bug, den ich mit einem expliziten return 0 nebenbei beseitigt habe
eigentlich dachte ich dass ich im März eine neue Version eingecheckt habe.
In jedem Fall werde ich die neue Version mit dem Bugfix auch in den nächsten Tagen einchecken.

commDelay sollte eigentlich eine Verzögerung zwischen dem letzen Lesen oder Schreiben auf dem Bus und dem nächsten Request erzwingen.
sendDelay macht das ähnlich, allerdings nur zwischen Requests. Das letzte Lesen wird dabei nicht berücksichtig.

Der Bug hat aber beides vereitelt. Seltsam dass das bisher nicht aufgefallen ist ...

Gruss
    Stefan