Neue Versionen und Support zum Modbus-Modul

[StefanStrobel]

Halo Jörg,

um Objekte seltener, nur täglich oder sogar nur einmal nach einem Neustart zu lesen, kann man pollDelay setzen.

Die Erläuterungen zu solchen Dingen sollten immer bei ModbusAttr stehen:

obj-[cdih][1-9][0-9]*-polldelay
this applies only to master mode. It allows to poll objects at a lower rate than the interval specified in the define command. You can either specify a time in seconds or number prefixed by "x" which means a multiple of the interval of the define command.
If you specify a normal numer then it is interpreted as minimal time between the last read and another automatic read.
Please note that this does not create an additional interval timer. Instead the normal interval timer defined by the interval of the define command will check if this reading is due or not yet. So the effective interval will always be a multiple of the interval of the define.

was in der Doku aber fehlt (shame on me) ist dass man pollDelay auch auf once stellen kann.
Dann wird das Objekt nur einmal nach dem Start abgefragt.
Ich habe es gerade in der Doku ergänzt. Beim nächsten Einchecken ist es dann drin ...

Gruss
   Stefan

[wthiess]

Hallo Stefan!

Hier der logauszug

Code Auswählen Erweitern

2019.01.30 21:14:26 5: VR400Mod: HandleResponse got 1 readings from ParseObj for Soll_WZ
2019.01.30 21:14:26 4: VR400Mod: ResponseDone, request: id 2, fCode 3, type h, adr 523, len 1 for device Soll_WZ reading Sollof, Current read buffer: 020302ff6a3d9b, Id 2, fCode 3, response: id 2, fCode 3, type h, adr 523, len 1, value ff6a
2019.01.30 21:14:26 5: VR400Mod: DropFrame - drop 020302ff6a3d9b
2019.01.30 21:14:26 5: VR400Mod: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate called from HandleTimeout
2019.01.30 21:14:26 5: Wolfgang_Soll: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-01-30 21:14:31, interval 5
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate objects from attributes: h9
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate full object list: h9
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate check h9 => temperature, poll = 1, last = 1548879263.65399
2019.01.30 21:14:26 4: Wolfgang_Soll: GetUpdate will request temperature
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate tries to combine read commands
2019.01.30 21:14:26 5: Wolfgang_Soll: GetUpdate doesn't sort objList before sending requests
2019.01.30 21:14:26 4: Wolfgang_Soll: DoRequest called from ModbusLD_GetUpdate created, request: id 18, fCode 3, type h, adr 9, len 1 for device Wolfgang_Soll reading temperature, read buffer empty
2019.01.30 21:14:26 5: Zaehler: QueueRequest called from ModbusLD_DoRequest with h9, qlen 17
2019.01.30 21:14:26 5: Zaehler: StartQueueTimer called form QueueRequest has already set internal timer to call Modbus_ProcessRequestQueue in 0.537 seconds
2019.01.30 21:14:26 5: VR400Mod: ProcessRequestQueue called from HandleTimeout as queue:VR400Mod
2019.01.30 21:14:26 4: VR400Mod: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 21:14:26.589) for Soll_WZ, rest 0.080, set timer to try again later
2019.01.30 21:14:26 5: VR400Mod: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.080 seconds
2019.01.30 21:14:26 4: Connection accepted from WEB_192.168.26.200_54961
2019.01.30 21:14:26 4: WEB_192.168.26.200_54961 POST /fhem?cmd=set%20Birgit_Aktiv%20Aktiv%20Ein&XHR=1&fwcsrf=csrf_448301314370321&fw_id=907; BUFLEN:0
2019.01.30 21:14:26 5: Cmd: >set Birgit_Aktiv Aktiv Ein<
2019.01.30 21:14:26 5: Birgit_Aktiv: set called with Aktiv (h0) setVal = Ein
2019.01.30 21:14:26 5: Birgit_Aktiv: MapConvert called from ModbusLD_Set converted Ein to 165 with reversed map Aus:90, Ein:165,
2019.01.30 21:14:26 5: Birgit_Aktiv: set converted Ein to 165 using map 90:Aus,165:Ein
2019.01.30 21:14:26 5: Birgit_Aktiv: set packed hex 313635 with n to hex 00a5
2019.01.30 21:14:26 4: Birgit_Aktiv: DoRequest called from ModbusLD_Set created, request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv, read buffer empty
2019.01.30 21:14:26 5: Zaehler: QueueRequest called from ModbusLD_DoRequest with h0, qlen 18
2019.01.30 21:14:26 5: Zaehler: ProcessRequestQueue called from QueueRequest as direct:Zaehler, force
2019.01.30 21:14:26 5: Zaehler: ProcessRequestQueue called from QueueRequest returns, Fhem is still waiting for response, qlen 19, try again in 1 seconds
2019.01.30 21:14:26 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.01.30 21:14:26 5: Zaehler: ReadAnswer called from ModbusLD_Set
2019.01.30 21:14:26 5: Zaehler: ReadAnswer called and remaining timeout is 0.467666149139404
2019.01.30 21:14:27 3: Zaehler: Timeout waiting for a modbus response in ReadAnswer, request: id 3, fCode 1, type c, adr 2, len 1 for device R2 reading Relais2, read buffer empty
2019.01.30 21:14:27 5: Zaehler: DropFrame - drop
2019.01.30 21:14:27 5: Zaehler: StartQueueTimer called form ReadAnswerTimeout sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.01.30 21:14:27 4: WEB: /fhem?cmd=set%20Birgit_Aktiv%20Aktiv%20Ein&XHR=1&fwcsrf=csrf_448301314370321&fw_id=907 / RL:72 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.01.30 21:14:27 5: VR400Mod: ProcessRequestQueue called from HandleTimeout as queue:VR400Mod
2019.01.30 21:14:27 5: VR400Mod: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 21:14:26.589) for Soll_WZ, delay over
2019.01.30 21:14:27 5: VR400Mod: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 21:14:26.553) for Soll_WZ, delay over
2019.01.30 21:14:27 5: VR400Mod: PackRequest called from ProcessRequestQueue
2019.01.30 21:14:27 4: VR400Mod: ProcessRequestQueue got pdu from PackRequest: 0301040001
2019.01.30 21:14:27 5: VR400Mod: PackFrame called from ProcessRequestQueue id 2, pdu 0301040001
2019.01.30 21:14:27 4: VR400Mod: ProcessRequestQueue (V4.0.20 - 29.1.2019) sending, request: id 2, fCode 3, type h, adr 260, len 1 for device Soll_WZ reading TemperaturSoll, read buffer empty
2019.01.30 21:14:27 5: SW: 020301040001c404
2019.01.30 21:14:27 5: VR400Mod: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.01.30 21:14:27 5: Zaehler: ProcessRequestQueue called from HandleTimeout as queue:Zaehler
2019.01.30 21:14:27 5: Zaehler: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 21:14:23.727) for Birgit_Aktiv, delay over
2019.01.30 21:14:27 5: Zaehler: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 21:14:23.702) for Birgit_Aktiv, delay over
2019.01.30 21:14:27 5: Zaehler: PackRequest called from ProcessRequestQueue
2019.01.30 21:14:27 4: Zaehler: ProcessRequestQueue got pdu from PackRequest: 06000000a5
2019.01.30 21:14:27 5: Zaehler: PackFrame called from ProcessRequestQueue id 16, pdu 06000000a5
2019.01.30 21:14:27 4: Zaehler: ProcessRequestQueue (V4.0.20 - 29.1.2019) sending, request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv, read buffer empty
2019.01.30 21:14:27 5: SW: 1006000000a54af0
2019.01.30 21:14:27 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.01.30 21:14:27 5: Zaehler: read buffer: 1006000000a54af0
2019.01.30 21:14:27 5: Zaehler: ParseFrameStart (RTU) extracted id 16, fCode 6 and data 000000a5
2019.01.30 21:14:27 5: Zaehler: HandleResponse called from Read
2019.01.30 21:14:27 5: Zaehler: ParseResponse called from HandleResponse
2019.01.30 21:14:27 5: Zaehler: CheckChecksum (called from HandleResponse): 4af0 is valid
2019.01.30 21:14:27 5: Zaehler: HandleResponse now passing to logical device Birgit_Aktiv for parsing data
2019.01.30 21:14:27 5: Birgit_Aktiv: ParseObj called with data 00a5, type h, adr 0, valuesLen 1, op write
2019.01.30 21:14:27 5: Birgit_Aktiv: ParseObj ObjInfo for h0: reading=Aktiv, unpack=n, expr=, format=, map=90:Aus,165:Ein
2019.01.30 21:14:27 5: Birgit_Aktiv: ParseObj unpacked 00a5 with n to 165 hex 313635
2019.01.30 21:14:27 5: Birgit_Aktiv: MapConvert called from ModbusLD_ParseObj converted 165 to Ein with map 90:Aus,165:Ein
2019.01.30 21:14:27 5: Birgit_Aktiv: ParseObj for Aktiv maps value 165 to Ein with 90:Aus,165:Ein
2019.01.30 21:14:27 4: Birgit_Aktiv: ParseObj assigns value Ein to Aktiv
2019.01.30 21:14:27 5: Starting notify loop for Birgit_Aktiv, 1 event(s), first is Aktiv: Ein
2019.01.30 21:14:27 4: dewpoint_notify: cmd_type=dewpoint devname=Birgit_Aktiv dewname=Taupunkt1, dev=Birgit_Aktiv, dev_regex=.* temp_name=temperature hum_name=humidity
2019.01.30 21:14:27 5: dewpoint_notify: s='Aktiv: Ein'
2019.01.30 21:14:27 5: dewpoint_notify: evName='Aktiv:' val=Ein'
2019.01.30 21:14:27 5: dewpoint max_timediff=1
2019.01.30 21:14:27 4: dewpoint_notify: cmd_type=dewpoint devname=Birgit_Aktiv dewname=Taupunkt2, dev=Birgit_Aktiv, dev_regex=.* temp_name=T hum_name=H
2019.01.30 21:14:27 5: dewpoint_notify: s='Aktiv: Ein'
2019.01.30 21:14:27 5: dewpoint_notify: evName='Aktiv:' val=Ein'
2019.01.30 21:14:27 5: dewpoint max_timediff=1
2019.01.30 21:14:27 5: End notify loop for Birgit_Aktiv
2019.01.30 21:14:27 5: Zaehler: HandleResponse got 1 readings from ParseObj for Birgit_Aktiv
2019.01.30 21:14:27 4: Zaehler: ResponseDone, request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv, Current read buffer: 1006000000a54af0, Id 16, fCode 6, response: id 16, fCode 6, type h, adr 0, len 1, value 00a5
2019.01.30 21:14:27 5: Zaehler: DropFrame - drop 1006000000a54af0
2019.01.30 21:14:27 5: Zaehler: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.01.30 21:14:27 5: Zaehler: ProcessRequestQueue called from HandleTimeout as queue:Zaehler
2019.01.30 21:14:27 5: Zaehler: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 21:13:54.937) for Kueche_01, delay over
2019.01.30 21:14:27 5: Zaehler: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 21:13:54.900) for Kueche_01, delay over
2019.01.30 21:14:27 5: Zaehler: PackRequest called from ProcessRequestQueue
2019.01.30 21:14:27 4: Zaehler: ProcessRequestQueue got pdu from PackRequest: 0300030001
2019.01.30 21:14:27 5: Zaehler: PackFrame called from ProcessRequestQueue id 17, pdu 0300030001
2019.01.30 21:14:27 4: Zaehler: ProcessRequestQueue (V4.0.20 - 29.1.2019) sending, request: id 17, fCode 3, type h, adr 3, len 1 for device Kueche_01 reading EinAus, read buffer empty
2019.01.30 21:14:27 5: SW: 110300030001769a
2019.01.30 21:14:27 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds

Zaehler ist mein Stik für Thermostate und Stromzähler und Relais.
VR400Mod ist mein Stik für die Lüftung und ein Thermostat.

lg
Wolfgang

[StefanStrobel]

Hallo Wolfgang,

beim Durchsehen Deiner Logs ist mir ein Bug aufgefallen. Ich bin nicht sicher, ob es Deine Timeouts behebt, aber zumindest das Logging wird dadurch klarer.
Könntest Du mit der angehängten neuen Version nochmal Logs erzeugen und posten?

Gruss / vielen Dank
   Stefan

[wthiess]

Hallo Stefan!
keine Änderung

Code Auswählen Erweitern

2019.01.31 19:55:40 5: Kueche_Aktiv: set called with Aktiv (h0) setVal = Ein
2019.01.31 19:55:40 5: Kueche_Aktiv: MapConvert called from ModbusLD_Set converted Ein to 165 with reversed map Aus:90, Ein:165,
2019.01.31 19:55:40 5: Kueche_Aktiv: set converted Ein to 165 using map 90:Aus,165:Ein
2019.01.31 19:55:40 5: Kueche_Aktiv: set packed hex 313635 with n to hex 00a5
2019.01.31 19:55:40 4: Kueche_Aktiv: DoRequest called from ModbusLD_Set created, request: id 17, fCode 6, type h, adr 0, len 1, value 00a5 for device Kueche_Aktiv reading Aktiv, read buffer empty
2019.01.31 19:55:40 5: Zaehler: QueueRequest called from ModbusLD_DoRequest with h0, qlen 21
2019.01.31 19:55:40 5: Zaehler: ProcessRequestQueue called from QueueRequest as direct:Zaehler, force
2019.01.31 19:55:40 5: Zaehler: ProcessRequestQueue called from QueueRequest returns, Fhem is still waiting for response, qlen 22, try again in 1 seconds
2019.01.31 19:55:40 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.01.31 19:55:40 5: Zaehler: ReadAnswer called from ModbusLD_Set
2019.01.31 19:55:40 5: Zaehler: ReadAnswer called and remaining timeout is 0.838778972625732
2019.01.31 19:55:40 3: Zaehler: Timeout waiting for a modbus response in ReadAnswer, request: id 3, fCode 1, type c, adr 1, len 1 for device R1 reading Relais1, read buffer empty
2019.01.31 19:55:40 5: Zaehler: DropFrame - drop
2019.01.31 19:55:40 5: Zaehler: StartQueueTimer called form ReadAnswerTimeout sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.01.31 19:55:40 4: WEB: /fhem?cmd=set%20Kueche_Aktiv%20Aktiv%20Ein&XHR=1&fwcsrf=csrf_416846969762650&fw_id=910 / RL:72 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.01.31 19:55:40 5: Zaehler: ProcessRequestQueue called from HandleTimeout as queue:Zaehler
2019.01.31 19:55:40 5: Zaehler: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 19:55:38.852) for Kueche_Aktiv, delay over
2019.01.31 19:55:40 5: Zaehler: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 19:55:38.828) for Kueche_Aktiv, delay over
2019.01.31 19:55:40 5: Zaehler: PackRequest called from ProcessRequestQueue
2019.01.31 19:55:40 4: Zaehler: ProcessRequestQueue got pdu from PackRequest: 06000000a5
2019.01.31 19:55:40 5: Zaehler: PackFrame called from ProcessRequestQueue id 17, pdu 06000000a5
2019.01.31 19:55:40 4: Zaehler: ProcessRequestQueue (V4.0.20 - 29.1.2019) sending, request: id 17, fCode 6, type h, adr 0, len 1, value 00a5 for device Kueche_Aktiv reading Aktiv, read buffer empty
2019.01.31 19:55:40 5: SW: 1106000000a54b21
2019.01.31 19:55:40 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.01.31 19:55:40 5: Zaehler: read buffer: 1106000000a54b21
2019.01.31 19:55:40 5: Zaehler: ParseFrameStart (RTU) extracted id 17, fCode 6 and data 000000a5
2019.01.31 19:55:40 5: Zaehler: HandleResponse called from Read
2019.01.31 19:55:40 5: Zaehler: ParseResponse called from HandleResponse
2019.01.31 19:55:40 5: Zaehler: CheckChecksum (called from HandleResponse): 4b21 is valid
2019.01.31 19:55:40 5: Zaehler: HandleResponse now passing to logical device Kueche_Aktiv for parsing data
2019.01.31 19:55:40 5: Kueche_Aktiv: ParseObj called with data 00a5, type h, adr 0, valuesLen 1, op write
2019.01.31 19:55:40 5: Kueche_Aktiv: ParseObj ObjInfo for h0: reading=Aktiv, unpack=n, expr=, format=, map=90:Aus,165:Ein
2019.01.31 19:55:40 5: Kueche_Aktiv: ParseObj unpacked 00a5 with n to 165 hex 313635
2019.01.31 19:55:40 5: Kueche_Aktiv: MapConvert called from ModbusLD_ParseObj converted 165 to Ein with map 90:Aus,165:Ein
2019.01.31 19:55:40 5: Kueche_Aktiv: ParseObj for Aktiv maps value 165 to Ein with 90:Aus,165:Ein
2019.01.31 19:55:40 4: Kueche_Aktiv: ParseObj assigns value Ein to Aktiv

lg
Wolfgang

[StefanStrobel]

Hallo Wolfgang,

Das Log sieht auch nicht nach der neuen Version aus.
Die neue ist von Heute, Version 4.0.22.

Gruß
    Stefan

[StefanStrobel]

Hallo Wolfgang,

konntest Du schon einen Test mit der neuen Version machen?
Ich gehe davon aus, dass der bei Dir angezeigte Timeout gar nicht von dem set-Befehl sondern von dem bereits in der Queue vorhandenen Lesen kam.
Durch den Bug, den ich in Version 4.0.22 des Modbus-Moduls hoffentlich behoben habe, wurde der Timout im Kontext des Set-Befehls angezeigt, da sich der Set-Befehl mit höhere Priorität in die Queue "quetscht".
Die Timeouts werden durch den Fix nicht behoben, aber sollten jetzt korrekt im Log erscheinen und dann kann man hoffentlich besser erkennen, welches Delay-Attribut erhöht werden sollte.

Gruss
   Stefan

[wthiess]

Hallo Stefan!

Ich habe die Version von 31.1.
Sicherheitshalber alles neu gestartet.

2019-01-31  fixed bug in GetSetCheck (failed to check for busy)

Code Auswählen Erweitern


2019.02.04 20:58:49 4: Syn1_cam3V - SSCam_refresh - caller: "n.a.", callerroom: "n.a.", detail: "n.a.", pload: 0, forcePageRefresh: 0
2019.02.04 20:58:50 4: WEB_192.168.26.200_51705 POST /fhem?cmd=set%20Birgit_Aktiv%20Aktiv%20Ein&XHR=1&fwcsrf=csrf_414770179673336&fw_id=904; BUFLEN:0
2019.02.04 20:58:50 5: Cmd: >set Birgit_Aktiv Aktiv Ein<
2019.02.04 20:58:50 5: Birgit_Aktiv: set called with Aktiv (h0) setVal = Ein
2019.02.04 20:58:50 5: Birgit_Aktiv: GetSetChecks with force
2019.02.04 20:58:50 4: Birgit_Aktiv: GetSetChecks calls ReadAnswer to take over async read (still waiting for response to request: id 3, fCode 1, type c, adr 1, len 1 for device R1 reading Relais1 (getUpdate), queued 14.68 secs ago, sent 0.90 secs ago, read buffer empty
2019.02.04 20:58:50 5: Zaehler: ReadAnswer called from ModbusLD_GetSetChecks
2019.02.04 20:58:50 5: Zaehler: ReadAnswer called and remaining timeout is 1.09723496437073
2019.02.04 20:58:51 3: Zaehler: Timeout waiting for a modbus response in ReadAnswer request: id 3, fCode 1, type c, adr 1, len 1 for device R1 reading Relais1 (getUpdate), queued 15.78 secs ago, sent 2.00 secs ago, read buffer empty
2019.02.04 20:58:51 5: Zaehler: DropFrame - drop
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form ReadAnswerTimeout sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.02.04 20:58:51 5: Birgit_Aktiv: GetSetChecks returns success
2019.02.04 20:58:51 5: Birgit_Aktiv: MapConvert called from ModbusLD_Set converted Ein to 165 with reversed map Aus:90, Ein:165,
2019.02.04 20:58:51 5: Birgit_Aktiv: set converted Ein to 165 using map 90:Aus,165:Ein
2019.02.04 20:58:51 5: Birgit_Aktiv: set packed hex 313635 with n to hex 00a5
2019.02.04 20:58:51 4: Birgit_Aktiv: DoRequest called from ModbusLD_Set created request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv (set Aktiv), read buffer empty
2019.02.04 20:58:51 5: Zaehler: QueueRequest called from ModbusLD_DoRequest (Birgit_Aktiv) with h0, qlen 15
2019.02.04 20:58:51 5: Zaehler: ProcessRequestQueue called from QueueRequest as direct:Zaehler, force
2019.02.04 20:58:51 5: Zaehler: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 20:58:47.438) for Birgit_Aktiv, delay over
2019.02.04 20:58:51 5: Zaehler: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 20:58:47.414) for Birgit_Aktiv, delay over
2019.02.04 20:58:51 5: Zaehler: PackRequest called from ProcessRequestQueue
2019.02.04 20:58:51 4: Zaehler: ProcessRequestQueue got pdu from PackRequest: 06000000a5
2019.02.04 20:58:51 5: Zaehler: PackFrame called from ProcessRequestQueue id 16, pdu 06000000a5
2019.02.04 20:58:51 4: Zaehler: ProcessRequestQueue (V4.0.22 - 31.1.2019) sending request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv (set Aktiv), queued 0.00 secs ago, read buffer empty
2019.02.04 20:58:51 5: SW: 1006000000a54af0
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.02.04 20:58:51 5: Zaehler: ReadAnswer called from ModbusLD_Set
2019.02.04 20:58:51 5: Zaehler: ReadAnswer called and remaining timeout is 1.99387216567993
2019.02.04 20:58:51 5: Zaehler: ReadAnswer got: 1006000000a54af0
2019.02.04 20:58:51 5: Zaehler: ParseFrameStart (RTU) extracted id 16, fCode 6 and data 000000a5
2019.02.04 20:58:51 5: Zaehler: HandleResponse called from ReadAnswer
2019.02.04 20:58:51 5: Zaehler: ParseResponse called from HandleResponse
2019.02.04 20:58:51 5: Zaehler: CheckChecksum (called from HandleResponse): 4af0 is valid
2019.02.04 20:58:51 5: Zaehler: HandleResponse now passing to logical device Birgit_Aktiv for parsing data
2019.02.04 20:58:51 5: Birgit_Aktiv: ParseObj called with data 00a5, type h, adr 0, valuesLen 1, op write
2019.02.04 20:58:51 5: Birgit_Aktiv: ParseObj ObjInfo for h0: reading=Aktiv, unpack=n, expr=, format=, map=90:Aus,165:Ein
2019.02.04 20:58:51 5: Birgit_Aktiv: ParseObj unpacked 00a5 with n to 165 hex 313635
2019.02.04 20:58:51 5: Birgit_Aktiv: MapConvert called from ModbusLD_ParseObj converted 165 to Ein with map 90:Aus,165:Ein
2019.02.04 20:58:51 5: Birgit_Aktiv: ParseObj for Aktiv maps value 165 to Ein with 90:Aus,165:Ein
2019.02.04 20:58:51 4: Birgit_Aktiv: ParseObj assigns value Ein to Aktiv
2019.02.04 20:58:51 5: Starting notify loop for Birgit_Aktiv, 1 event(s), first is Aktiv: Ein
2019.02.04 20:58:51 4: dewpoint_notify: cmd_type=dewpoint devname=Birgit_Aktiv dewname=Taupunkt1, dev=Birgit_Aktiv, dev_regex=.* temp_name=temperature hum_name=humidity
2019.02.04 20:58:51 5: dewpoint_notify: s='Aktiv: Ein'
2019.02.04 20:58:51 5: dewpoint_notify: evName='Aktiv:' val=Ein'
2019.02.04 20:58:51 5: dewpoint max_timediff=1
2019.02.04 20:58:51 4: dewpoint_notify: cmd_type=dewpoint devname=Birgit_Aktiv dewname=Taupunkt2, dev=Birgit_Aktiv, dev_regex=.* temp_name=T hum_name=H
2019.02.04 20:58:51 5: dewpoint_notify: s='Aktiv: Ein'
2019.02.04 20:58:51 5: dewpoint_notify: evName='Aktiv:' val=Ein'
2019.02.04 20:58:51 5: dewpoint max_timediff=1
2019.02.04 20:58:51 5: End notify loop for Birgit_Aktiv
2019.02.04 20:58:51 5: Zaehler: HandleResponse got 1 readings from ParseObj for Birgit_Aktiv
2019.02.04 20:58:51 4: Zaehler: ResponseDone request: id 16, fCode 6, type h, adr 0, len 1, value 00a5 for device Birgit_Aktiv reading Aktiv (set Aktiv), queued 0.05 secs ago, sent 0.05 secs ago, Current read buffer: 1006000000a54af0, Id 16, fCode 6, response: id 16, fCode 6, type h, adr 0, len 1, value 00a5
2019.02.04 20:58:51 5: Zaehler: DropFrame - drop 1006000000a54af0
2019.02.04 20:58:51 5: Birgit_Aktiv: StartQueueTimer called from ModbusLD_Set removes internal timer because it is not needed now
2019.02.04 20:58:51 4: WEB: /fhem?cmd=set%20Birgit_Aktiv%20Aktiv%20Ein&XHR=1&fwcsrf=csrf_414770179673336&fw_id=904 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate called from HandleTimeout
2019.02.04 20:58:51 5: Birgit_Soll: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-02-04 20:58:56, interval 5
2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate objects from attributes: h9
2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate full object list: h9
2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate check h9 => temperature, poll = 1, last = 1549310329.18303
2019.02.04 20:58:51 4: Birgit_Soll: GetUpdate will request temperature
2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate tries to combine read commands
2019.02.04 20:58:51 5: Birgit_Soll: GetUpdate doesn't sort objList before sending requests
2019.02.04 20:58:51 4: Birgit_Soll: DoRequest called from ModbusLD_GetUpdate created request: id 16, fCode 3, type h, adr 9, len 1 for device Birgit_Soll reading temperature (getUpdate), read buffer empty
2019.02.04 20:58:51 5: Zaehler: QueueRequest called from ModbusLD_DoRequest (Birgit_Soll) with h9, qlen 15
2019.02.04 20:58:51 5: Zaehler: ProcessRequestQueue called from QueueRequest as direct:Zaehler
2019.02.04 20:58:51 5: Zaehler: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 20:58:38.506) for Wolfgang_Soll, delay over
2019.02.04 20:58:51 5: Zaehler: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 20:58:38.482) for Wolfgang_Soll, delay over
2019.02.04 20:58:51 5: Zaehler: PackRequest called from ProcessRequestQueue
2019.02.04 20:58:51 4: Zaehler: ProcessRequestQueue got pdu from PackRequest: 0300090001
2019.02.04 20:58:51 5: Zaehler: PackFrame called from ProcessRequestQueue id 18, pdu 0300090001
2019.02.04 20:58:51 4: Zaehler: ProcessRequestQueue (V4.0.22 - 31.1.2019) sending request: id 18, fCode 3, type h, adr 9, len 1 for device Wolfgang_Soll reading temperature (getUpdate), queued 16.32 secs ago, read buffer empty
2019.02.04 20:58:51 5: SW: 12030009000156ab
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate called from HandleTimeout
2019.02.04 20:58:51 5: Kueche_Soll: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-02-04 20:58:56, interval 5
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate objects from attributes: h9
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate full object list: h9
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate check h9 => temperature, poll = 1, last = 1549310329.21437
2019.02.04 20:58:51 4: Kueche_Soll: GetUpdate will request temperature
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate tries to combine read commands
2019.02.04 20:58:51 5: Kueche_Soll: GetUpdate doesn't sort objList before sending requests
2019.02.04 20:58:51 4: Kueche_Soll: DoRequest called from ModbusLD_GetUpdate created request: id 17, fCode 3, type h, adr 9, len 1 for device Kueche_Soll reading temperature (getUpdate), read buffer empty
2019.02.04 20:58:51 5: Zaehler: QueueRequest called from ModbusLD_DoRequest (Kueche_Soll) with h9, qlen 15
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form QueueRequest has already set internal timer to call Modbus_ProcessRequestQueue in 0.993 seconds
2019.02.04 20:58:51 5: R1: GetUpdate called from HandleTimeout
2019.02.04 20:58:51 5: R1: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-02-04 20:58:56, interval 5
2019.02.04 20:58:51 5: R1: GetUpdate objects from attributes: c1
2019.02.04 20:58:51 5: R1: GetUpdate full object list: c1
2019.02.04 20:58:51 5: R1: GetUpdate check c1 => Relais1, poll = 1, last = 0
2019.02.04 20:58:51 4: R1: GetUpdate will request Relais1
2019.02.04 20:58:51 5: R1: GetUpdate tries to combine read commands
2019.02.04 20:58:51 5: R1: GetUpdate doesn't sort objList before sending requests
2019.02.04 20:58:51 4: R1: DoRequest called from ModbusLD_GetUpdate created request: id 3, fCode 1, type c, adr 1, len 1 for device R1 reading Relais1 (getUpdate), read buffer empty
2019.02.04 20:58:51 5: Zaehler: QueueRequest called from ModbusLD_DoRequest (R1) with c1, qlen 16
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form QueueRequest has already set internal timer to call Modbus_ProcessRequestQueue in 0.986 seconds
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate called from HandleTimeout
2019.02.04 20:58:51 5: Soll_WZ: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-02-04 20:58:56, interval 5
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate objects from attributes: h260 h523
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate full object list: h260 h523
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate check h260 => TemperaturSoll, poll = 1, last = 1549310326.83856
2019.02.04 20:58:51 4: Soll_WZ: GetUpdate will request TemperaturSoll
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate check h523 => Sollof, poll = 1, last = 1549310326.97977
2019.02.04 20:58:51 4: Soll_WZ: GetUpdate will request Sollof
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate tries to combine read commands
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate cant combine request for TemperaturSoll / h260 with Sollof / h523, span 264 > max 5
2019.02.04 20:58:51 5: Soll_WZ: GetUpdate doesn't sort objList before sending requests
2019.02.04 20:58:51 4: Soll_WZ: DoRequest called from ModbusLD_GetUpdate created request: id 2, fCode 3, type h, adr 523, len 1 for device Soll_WZ reading Sollof (getUpdate), read buffer empty
2019.02.04 20:58:51 5: VR400Mod: QueueRequest called from ModbusLD_DoRequest (Soll_WZ) with h523, qlen 0
2019.02.04 20:58:51 5: VR400Mod: ProcessRequestQueue called from QueueRequest as direct:VR400Mod
2019.02.04 20:58:51 5: VR400Mod: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 20:58:46.977) for Soll_WZ, delay over
2019.02.04 20:58:51 5: VR400Mod: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 20:58:46.939) for Soll_WZ, delay over
2019.02.04 20:58:51 5: VR400Mod: PackRequest called from ProcessRequestQueue
2019.02.04 20:58:51 4: VR400Mod: ProcessRequestQueue got pdu from PackRequest: 03020b0001
2019.02.04 20:58:51 5: VR400Mod: PackFrame called from ProcessRequestQueue id 2, pdu 03020b0001
2019.02.04 20:58:51 4: VR400Mod: ProcessRequestQueue (V4.0.22 - 31.1.2019) sending request: id 2, fCode 3, type h, adr 523, len 1 for device Soll_WZ reading Sollof (getUpdate), queued 0.00 secs ago, read buffer empty
2019.02.04 20:58:51 5: SW: 0203020b0001f443
2019.02.04 20:58:51 5: VR400Mod: StartQueueTimer called from ProcessRequestQueue removes internal timer because it is not needed now
2019.02.04 20:58:51 4: Soll_WZ: DoRequest called from ModbusLD_GetUpdate created request: id 2, fCode 3, type h, adr 260, len 1 for device Soll_WZ reading TemperaturSoll (getUpdate), read buffer empty
2019.02.04 20:58:51 5: VR400Mod: QueueRequest called from ModbusLD_DoRequest (Soll_WZ) with h260, qlen 0
2019.02.04 20:58:51 5: VR400Mod: StartQueueTimer called form QueueRequest sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2019.02.04 20:58:51 5: Zaehler: read buffer: 12030200143d88
2019.02.04 20:58:51 5: Zaehler: ParseFrameStart (RTU) extracted id 18, fCode 3 and data 020014
2019.02.04 20:58:51 5: Zaehler: HandleResponse called from Read
2019.02.04 20:58:51 5: Zaehler: ParseResponse called from HandleResponse
2019.02.04 20:58:51 5: Zaehler: CheckChecksum (called from HandleResponse): 3d88 is valid
2019.02.04 20:58:51 5: Zaehler: HandleResponse now passing to logical device Wolfgang_Soll for parsing data
2019.02.04 20:58:51 5: Wolfgang_Soll: ParseObj called with data 0014, type h, adr 9, valuesLen 1, op read
2019.02.04 20:58:51 5: Wolfgang_Soll: ParseObj ObjInfo for h9: reading=temperature, unpack=n, expr=$val/2, format=%.1f, map=
2019.02.04 20:58:51 5: Wolfgang_Soll: ParseObj unpacked 0014 with n to 20 hex 3230
2019.02.04 20:58:51 5: Wolfgang_Soll: CheckEval for ModbusLD_ParseObj evaluates expr for temperature, val=20, expr=$val/2
2019.02.04 20:58:51 5: Wolfgang_Soll: CheckEval for ModbusLD_ParseObj result is 10
2019.02.04 20:58:51 5: Wolfgang_Soll: ParseObj for temperature does sprintf with format %.1f, value is 10
2019.02.04 20:58:51 5: Wolfgang_Soll: ParseObj for temperature sprintf result is 10.0
2019.02.04 20:58:51 4: Wolfgang_Soll: ParseObj assigns value 10.0 to temperature
2019.02.04 20:58:51 5: Zaehler: HandleResponse got 1 readings from ParseObj for Wolfgang_Soll
2019.02.04 20:58:51 4: Zaehler: ResponseDone request: id 18, fCode 3, type h, adr 9, len 1 for device Wolfgang_Soll reading temperature (getUpdate), queued 16.36 secs ago, sent 0.04 secs ago, Current read buffer: 12030200143d88, Id 18, fCode 3, response: id 18, fCode 3, type h, adr 9, len 1, value 0014
2019.02.04 20:58:51 5: Zaehler: DropFrame - drop 12030200143d88
2019.02.04 20:58:51 5: Zaehler: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate called from HandleTimeout
2019.02.04 20:58:51 5: Temp_WZ_S: SetartUpdateTimer called from ModbusLD_GetUpdate updated timer, will call GetUpdate in 5.0 sec at 2019-02-04 20:58:56, interval 5
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate objects from attributes: h260
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate full object list: h260
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate check h260 => TemperaturSoll, poll = 1, last = 1549310327.02843
2019.02.04 20:58:51 4: Temp_WZ_S: GetUpdate will request TemperaturSoll
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate tries to combine read commands
2019.02.04 20:58:51 5: Temp_WZ_S: GetUpdate doesn't sort objList before sending requests
2019.02.04 20:58:51 4: Temp_WZ_S: DoRequest called from ModbusLD_GetUpdate created request: id 2, fCode 3, type h, adr 260, len 1 for device Temp_WZ_S reading TemperaturSoll (getUpdate), read buffer empty


lg
Wolfgang

[StefanStrobel]

Hallo Wolfgang,

Ja, jetzt ist es die aktuelle Version. Man sieht ganz gut was passiert.

Könntest Du noch das Log für den Zeitraum zwischen 20:58:30 und 20:58:50 posten?
Oder sogar für eine ganze Minute?
In den Log-Ausschnitten, die ich bisher gesehen habe, scheint es immer eine Abfrage eines Relais zu sein, die in den Timeout läuft. Gleichzeitig scheint die Queue auch recht voll zu sein und ich frage mich wie viele Abfragen vor dem Timout erfolgreich sind. Wie oft kommt der Fehler? Wie sind die Fhem-Geräte definiert?
Ein größerer Ausschnitt gibt eventuell ein klareres Bild.

Gruß
    Stefan

[wthiess]

Hallo Stefan!
hier der link zu meinem log
Leider kann ich den log nicht in ein Codefenster einfügen.
www.thiess.at/log/log.zip
lg
Wolfgang

[SandroK]

Hallo Stephan,

wie kann ich Bit's bswp. MX1000.0 von einem WAGO PFC auslesen ?
Laut Modulbeschreibung mit c13289, da kommt aber nichts.
Wenn ich mit h13289 das komplette Register lese, dann kommt auch derkomplette Wert.

Mich interessiert die Adressier-/Zählweise von Bit's innerhalb eines Wortes.

Danke für eine kurze Hilfestellung

VG Sandro

[StefanStrobel]

Hallo Wolfgang,

im Log sieht es so aus, als ob die Timeouts regelmäßig dann kommen, wenn id 3 abgefragt wird und zuvor eine andere id abgefragt wurde.
Versuch doch mal ein commDelay für das Gerät mit id 3 auf 0,2 statt 0,1 zu setzen oder ein clientSwitchDelay auf 0,2 zu setzen.

Gruss
   Stefan

[StefanStrobel]

Hallo Sandro,

die Adressen und die Bedeutung der Bits in Registern ist immer geräteabhängig.
Was meinst Du mit "kommt nichts". Kommt ein Fehler / ein Timeout oder ein Wert 0 und Du erwartest eine 1?
Wenn Du die Bits auch über ein holding register abfragen kannst, dann kannst Du ja auch im Register-Wert per Expression und eine Und-Verknüpfung das richtige Bit herausholen. Ich bezweifle aber, dass die Register-Adresse dann der Adresse des Coils entspricht. Vermutlich werden dann immer 16 Coils in ein Register gepackt.
Das müsste aber im Handbuch des Geräts stehen.

Gruss
   Stefan

[wthiess]

Hallo Stefan!

"dev-timing-commDelay" hat nichts gebracht.
"clientSwitchDelay" find ich nicht.

lg
Wolfgang

[StefanStrobel]

Hallo Wolfgang,

Wie hoch bist Du denn mit commDelay gegangen?
Ich würde das durchaus bis auf 1 Sekunde testen ...

clientSwitchDelay wird auf dem physischen Interface angegeben.

Gruß
   Stefan

[wthiess]

Hallo Stefan!

Habe beide Werte nun bis 1 Sek. getestet.
Kein Erfolg.

lg
Wolfgang