[gelöst] Untersuchung potentielles Speicherleck in ModbusAttr Relay

[FhemPiUser]

Weiterführung des Thema aus https://forum.fhem.de/index.php/topic,83909.390.html.

[FhemPiUser]

Hallo Stefan,

ich habe ein Log erstellt mit verbose 5 und erstmal nur kurz laufen lassen.

Wie lange soll ich es laufen lassen?

Das Speicherleck ist nicht sehr groß, vielleicht ca. 1Mbyte pro Stunde.

Wenn ich das 24h laufen lasse, ist das ein riesiges Logfile.

[code]


2022.09.09 17:26:05 5: SH10rt_1_1: UpdateSetList: setList=reconnect:noArg saveAsModule createAttrsFromParseInfo interval reread:noArg stop:noArg start:noArg close:noArg scanStop:noArg scanModbusObjects inactive active
2022.09.09 17:26:05 5: SH10rt_1_1: UpdateSetList: getList=
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i5016, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i5016, len 2, tid 216, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 9.462 secs ago, required delay is 0
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 9.462 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 9.468 secs ago, required delay is 0.1
2022.09.09 17:26:05 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 00d800000006010413980002 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i5016, len 2, tid 216, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.01 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:05 5: DevIo_SimpleWrite SH10rt_1_1: 00d800000006010413980002
2022.09.09 17:26:05 5: SH10rt_1_1: readFn buffer: 00d800000007010404032a0000
2022.09.09 17:26:05 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:05 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 216, dlen 7 and potential data 04032a0000
2022.09.09 17:26:05 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:05 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:05 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 032a0000, type i, adr 5016
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 032a0000, type i, adr 5016, valuesLen 2
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i5016
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i5017
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:05 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 00d800000007010404032a0000, id 1, fCode 4, tid 216,
request: id 1 fc 4 i5016, len 2, tid 216, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.02 secs ago, sent 0.02 secs ago,
response: id 11, fc 4, i5016, len 2, values 032a0000, tid 52459
2022.09.09 17:26:05 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 00d800000007010404032a0000, id 1, fCode 4, tid 216,
request: id 1 fc 4 i5016, len 2, tid 216, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.02 secs ago, sent 0.02 secs ago,
response: id 11, fc 4, i5016, len 2, values 032a0000, tid 52459
2022.09.09 17:26:05 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:05 5: SH10rt_1_1: DropFrame called from ReadFn - drop 00d800000007010404032a0000
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13021, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13021, len 1, tid 148, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.052 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.046 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.046 secs ago, required delay is 0
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.054 forced
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:05 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 009400000006010432dd0001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13021, len 1, tid 148, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.06 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:05 5: DevIo_SimpleWrite SH10rt_1_1: 009400000006010432dd0001
2022.09.09 17:26:05 5: SH10rt_1_1: readFn buffer: 009400000005010402066b
2022.09.09 17:26:05 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:05 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 148, dlen 5 and potential data 02066b
2022.09.09 17:26:05 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:05 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:05 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 066b, type i, adr 13021
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 066b, type i, adr 13021, valuesLen 1
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i13021
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:05 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 009400000005010402066b, id 1, fCode 4, tid 148,
request: id 1 fc 4 i13021, len 1, tid 148, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.08 secs ago, sent 0.08 secs ago,
response: id 11, fc 4, i13021, len 1, values 066b, tid 52460
2022.09.09 17:26:05 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 009400000005010402066b, id 1, fCode 4, tid 148,
request: id 1 fc 4 i13021, len 1, tid 148, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.08 secs ago, sent 0.08 secs ago,
response: id 11, fc 4, i13021, len 1, values 066b, tid 52460
2022.09.09 17:26:05 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:05 5: SH10rt_1_1: DropFrame called from ReadFn - drop 009400000005010402066b
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13000, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13000, len 1, tid 170, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.028 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.015 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.015 secs ago, required delay is 0
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.085 forced
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:05 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 00aa00000006010432c80001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13000, len 1, tid 170, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.09 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:05 5: DevIo_SimpleWrite SH10rt_1_1: 00aa00000006010432c80001
2022.09.09 17:26:05 5: SH10rt_1_1: readFn buffer: 00aa000000050104020000
2022.09.09 17:26:05 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:05 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 170, dlen 5 and potential data 020000
2022.09.09 17:26:05 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:05 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:05 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i13000
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:05 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 00aa000000050104020000, id 1, fCode 4, tid 170,
request: id 1 fc 4 i13000, len 1, tid 170, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52461
2022.09.09 17:26:05 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 00aa000000050104020000, id 1, fCode 4, tid 170,
request: id 1 fc 4 i13000, len 1, tid 170, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52461
2022.09.09 17:26:05 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:05 5: SH10rt_1_1: DropFrame called from ReadFn - drop 00aa000000050104020000
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13000, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13000, len 1, tid 157, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.013 secs ago, required delay is 0
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.013 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.024 secs ago, required delay is 0.1
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.087 forced
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:05 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 009d00000006010432c80001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13000, len 1, tid 157, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.09 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:05 5: DevIo_SimpleWrite SH10rt_1_1: 009d00000006010432c80001
2022.09.09 17:26:05 5: SH10rt_1_1: readFn buffer: 009d000000050104020000
2022.09.09 17:26:05 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:05 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 157, dlen 5 and potential data 020000
2022.09.09 17:26:05 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:05 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:05 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i13000
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:05 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 009d000000050104020000, id 1, fCode 4, tid 157,
request: id 1 fc 4 i13000, len 1, tid 157, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52462
2022.09.09 17:26:05 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 009d000000050104020000, id 1, fCode 4, tid 157,
request: id 1 fc 4 i13000, len 1, tid 157, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52462
2022.09.09 17:26:05 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:05 5: SH10rt_1_1: DropFrame called from ReadFn - drop 009d000000050104020000
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13009, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13009, len 2, tid 55, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.014 secs ago, required delay is 0
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.014 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.020 secs ago, required delay is 0.1
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.086 forced
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:05 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 003700000006010432d10002 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13009, len 2, tid 55, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.09 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:05 5: DevIo_SimpleWrite SH10rt_1_1: 003700000006010432d10002
2022.09.09 17:26:05 5: SH10rt_1_1: readFn buffer: 003700000007010404ffd7ffff
2022.09.09 17:26:05 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:05 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 55, dlen 7 and potential data 04ffd7ffff
2022.09.09 17:26:05 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:05 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:05 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex ffd7ffff, type i, adr 13009
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex ffd7ffff, type i, adr 13009, valuesLen 2
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i13009
2022.09.09 17:26:05 5: SH10rt_1_1: SplitDataString has no information about handling i13010
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:05 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:05 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:05 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 003700000007010404ffd7ffff, id 1, fCode 4, tid 55,
request: id 1 fc 4 i13009, len 2, tid 55, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13009, len 2, values ffd7ffff, tid 52463
2022.09.09 17:26:05 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 003700000007010404ffd7ffff, id 1, fCode 4, tid 55,
request: id 1 fc 4 i13009, len 2, tid 55, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13009, len 2, values ffd7ffff, tid 52463
2022.09.09 17:26:05 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:05 5: SH10rt_1_1: DropFrame called from ReadFn - drop 003700000007010404ffd7ffff
2022.09.09 17:26:05 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13022, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54846 through io device SH10rt_1_1
2022.09.09 17:26:05 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13022, len 1, tid 154, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.00 secs ago
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.012 secs ago, required delay is 0.1
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.012 secs ago, required delay is 0
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:05 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.016 secs ago, required delay is 0.1
2022.09.09 17:26:05 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.088 forced
2022.09.09 17:26:06 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:06 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 009a00000006010432de0001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13022, len 1, tid 154, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.09 secs ago
2022.09.09 17:26:06 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:06 5: DevIo_SimpleWrite SH10rt_1_1: 009a00000006010432de0001
2022.09.09 17:26:06 5: SH10rt_1_1: readFn buffer: 009a0000000501040203c4
2022.09.09 17:26:06 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:06 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 154, dlen 5 and potential data 0203c4
2022.09.09 17:26:06 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:06 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:06 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:06 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 03c4, type i, adr 13022
2022.09.09 17:26:06 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 03c4, type i, adr 13022, valuesLen 1
2022.09.09 17:26:06 5: SH10rt_1_1: SplitDataString has no information about handling i13022
2022.09.09 17:26:06 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:06 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:06 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:06 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54846, ioDev SH10rt_1_relay_192.168.x.x_54846, current frame / read buffer: 009a0000000501040203c4, id 1, fCode 4, tid 154,
request: id 1 fc 4 i13022, len 1, tid 154, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13022, len 1, values 03c4, tid 52464
2022.09.09 17:26:06 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 009a0000000501040203c4, id 1, fCode 4, tid 154,
request: id 1 fc 4 i13022, len 1, tid 154, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54846 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13022, len 1, values 03c4, tid 52464
2022.09.09 17:26:06 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:06 5: SH10rt_1_1: DropFrame called from ReadFn - drop 009a0000000501040203c4
2022.09.09 17:26:10 3: SH10rt_2_relay_192.168.x.x_44692: read from TCP server connection got null -> closing
2022.09.09 17:26:10 3: SH10rt_2_relay_192.168.x.x_44692: _UnDef is closing SH10rt_2_relay_192.168.x.x_44692
2022.09.09 17:26:10 3: SH10rt_1_relay_192.168.x.x_54846: read from TCP server connection got null -> closing
2022.09.09 17:26:10 3: SH10rt_1_relay_192.168.x.x_54846: _UnDef is closing SH10rt_1_relay_192.168.x.x_54846
2022.09.09 17:26:13 5: SH10rt_1_relay: UpdateSetList: setList=reconnect:noArg saveAsModule createAttrsFromParseInfo inactive active
2022.09.09 17:26:13 5: SH10rt_1_relay: UpdateSetList: getList=
2022.09.09 17:26:15 4: Connection accepted from SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 4: SH10rt_1_relay: HandleServerConnection accepted new TCP connection as device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ResetExpect for HandleServerConnection from undefined to request
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf1000000060b0413980002
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52465, dlen 6 and potential data 13980002
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf1000000060b0413980002, id 11, fCode 4, tid 52465,
request: id 11 fc 4 i5016, len 2, tid 52465
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:15 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf1000000060b0413980002, id 11, fCode 4, tid 52465,
request: id 11 fc 4 i5016, len 2, tid 52465, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_1: QueueRequest called from RelayRequest with i5016, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:15 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i5016, len 2, tid 36, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 9.413 secs ago, required delay is 0.1
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 9.413 secs ago, required delay is 0
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 9.419 secs ago, required delay is 0.1
2022.09.09 17:26:15 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 002400000006010413980002 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i5016, len 2, tid 36, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:15 5: DevIo_SimpleWrite SH10rt_1_1: 002400000006010413980002
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf1000000060b0413980002, id 11, fCode 4, tid 52465,
request: id 11 fc 4 i5016, len 2, tid 52465, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf1000000060b0413980002
2022.09.09 17:26:15 5: SH10rt_1_1: readFn buffer: 00240000000701040403740000
2022.09.09 17:26:15 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:15 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 36, dlen 7 and potential data 0403740000
2022.09.09 17:26:15 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:15 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 03740000, type i, adr 5016
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 03740000, type i, adr 5016, valuesLen 2
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i5016
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i5017
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex 03740000, type i, adr 5016
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex 03740000, type i, adr 5016, valuesLen 2
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString has no information about handling i5016
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString has no information about handling i5017
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:15 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 00240000000701040403740000, id 1, fCode 4, tid 36,
request: id 1 fc 4 i5016, len 2, tid 36, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.02 secs ago, sent 0.02 secs ago,
response: id 11, fc 4, i5016, len 2, values 03740000, tid 52465
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf1000000070b040403740000
2022.09.09 17:26:15 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 00240000000701040403740000, id 1, fCode 4, tid 36,
request: id 1 fc 4 i5016, len 2, tid 36, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.02 secs ago, sent 0.02 secs ago,
response: id 11, fc 4, i5016, len 2, values 03740000, tid 52465
2022.09.09 17:26:15 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:15 5: SH10rt_1_1: DropFrame called from ReadFn - drop 00240000000701040403740000
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf2000000060b0432dd0001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn protocol TCP expecting id 11
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52466, dlen 6 and potential data 32dd0001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf2000000060b0432dd0001, id 11, fCode 4, tid 52466,
request: id 11 fc 4 i13021, len 1, tid 52466
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:15 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf2000000060b0432dd0001, id 11, fCode 4, tid 52466,
request: id 11 fc 4 i13021, len 1, tid 52466, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13021, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:15 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13021, len 1, tid 31, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.054 secs ago, required delay is 0
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.054 secs ago, required delay is 0.1
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.059 secs ago, required delay is 0.1
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.046 forced
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:15 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 001f00000006010432dd0001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13021, len 1, tid 31, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.05 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:15 5: DevIo_SimpleWrite SH10rt_1_1: 001f00000006010432dd0001
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf2000000060b0432dd0001, id 11, fCode 4, tid 52466,
request: id 11 fc 4 i13021, len 1, tid 52466, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf2000000060b0432dd0001
2022.09.09 17:26:15 5: SH10rt_1_1: readFn buffer: 001f00000005010402071d
2022.09.09 17:26:15 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:15 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 31, dlen 5 and potential data 02071d
2022.09.09 17:26:15 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:15 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 071d, type i, adr 13021
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 071d, type i, adr 13021, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i13021
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex 071d, type i, adr 13021
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex 071d, type i, adr 13021, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString has no information about handling i13021
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:15 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 001f00000005010402071d, id 1, fCode 4, tid 31,
request: id 1 fc 4 i13021, len 1, tid 31, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.09 secs ago, sent 0.09 secs ago,
response: id 11, fc 4, i13021, len 1, values 071d, tid 52466
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf2000000050b0402071d
2022.09.09 17:26:15 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 001f00000005010402071d, id 1, fCode 4, tid 31,
request: id 1 fc 4 i13021, len 1, tid 31, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.09 secs ago, sent 0.09 secs ago,
response: id 11, fc 4, i13021, len 1, values 071d, tid 52466
2022.09.09 17:26:15 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:15 5: SH10rt_1_1: DropFrame called from ReadFn - drop 001f00000005010402071d
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf3000000060b0432c80001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn protocol TCP expecting id 11
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52467, dlen 6 and potential data 32c80001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf3000000060b0432c80001, id 11, fCode 4, tid 52467,
request: id 11 fc 4 i13000, len 1, tid 52467
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:15 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf3000000060b0432c80001, id 11, fCode 4, tid 52467,
request: id 11 fc 4 i13000, len 1, tid 52467, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13000, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:15 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13000, len 1, tid 52, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.031 secs ago, required delay is 0.1
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.031 secs ago, required delay is 0
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.058 secs ago, required delay is 0.1
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.069 forced
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:15 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 003400000006010432c80001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13000, len 1, tid 52, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.07 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:15 5: DevIo_SimpleWrite SH10rt_1_1: 003400000006010432c80001
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf3000000060b0432c80001, id 11, fCode 4, tid 52467,
request: id 11 fc 4 i13000, len 1, tid 52467, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf3000000060b0432c80001
2022.09.09 17:26:15 5: SH10rt_1_1: readFn buffer: 0034000000050104020000
2022.09.09 17:26:15 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:15 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 52, dlen 5 and potential data 020000
2022.09.09 17:26:15 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:15 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i13000
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString has no information about handling i13000
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:15 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 0034000000050104020000, id 1, fCode 4, tid 52,
request: id 1 fc 4 i13000, len 1, tid 52, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52467
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf3000000050b04020000
2022.09.09 17:26:15 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 0034000000050104020000, id 1, fCode 4, tid 52,
request: id 1 fc 4 i13000, len 1, tid 52, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.11 secs ago, sent 0.11 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52467
2022.09.09 17:26:15 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:15 5: SH10rt_1_1: DropFrame called from ReadFn - drop 0034000000050104020000
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf4000000060b0432c80001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn protocol TCP expecting id 11
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52468, dlen 6 and potential data 32c80001
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf4000000060b0432c80001, id 11, fCode 4, tid 52468,
request: id 11 fc 4 i13000, len 1, tid 52468
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:15 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf4000000060b0432c80001, id 11, fCode 4, tid 52468,
request: id 11 fc 4 i13000, len 1, tid 52468, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13000, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:15 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13000, len 1, tid 127, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.039 secs ago, required delay is 0.1
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.017 secs ago, required delay is 0
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.017 secs ago, required delay is 0.1
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.083 forced
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:15 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 007f00000006010432c80001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13000, len 1, tid 127, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.09 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:15 5: DevIo_SimpleWrite SH10rt_1_1: 007f00000006010432c80001
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf4000000060b0432c80001, id 11, fCode 4, tid 52468,
request: id 11 fc 4 i13000, len 1, tid 52468, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf4000000060b0432c80001
2022.09.09 17:26:15 5: SH10rt_1_1: readFn buffer: 007f000000050104020000
2022.09.09 17:26:15 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:15 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 127, dlen 5 and potential data 020000
2022.09.09 17:26:15 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:15 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i13000
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex 0000, type i, adr 13000
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex 0000, type i, adr 13000, valuesLen 1
2022.09.09 17:26:15 5: SH10rt_1_relay: SplitDataString has no information about handling i13000
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:15 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 007f000000050104020000, id 1, fCode 4, tid 127,
request: id 1 fc 4 i13000, len 1, tid 127, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52468
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf4000000050b04020000
2022.09.09 17:26:15 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 007f000000050104020000, id 1, fCode 4, tid 127,
request: id 1 fc 4 i13000, len 1, tid 127, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13000, len 1, values 0000, tid 52468
2022.09.09 17:26:15 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:15 5: SH10rt_1_1: DropFrame called from ReadFn - drop 007f000000050104020000
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf5000000060b0432d10002
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn protocol TCP expecting id 11
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52469, dlen 6 and potential data 32d10002
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf5000000060b0432d10002, id 11, fCode 4, tid 52469,
request: id 11 fc 4 i13009, len 2, tid 52469
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:15 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf5000000060b0432d10002, id 11, fCode 4, tid 52469,
request: id 11 fc 4 i13009, len 2, tid 52469, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13009, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:15 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13009, len 2, tid 99, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.018 secs ago, required delay is 0
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.018 secs ago, required delay is 0.1
2022.09.09 17:26:15 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.023 secs ago, required delay is 0.1
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.082 forced
2022.09.09 17:26:15 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:15 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 006300000006010432d10002 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13009, len 2, tid 99, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.09 secs ago
2022.09.09 17:26:15 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:15 5: DevIo_SimpleWrite SH10rt_1_1: 006300000006010432d10002
2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf5000000060b0432d10002, id 11, fCode 4, tid 52469,
request: id 11 fc 4 i13009, len 2, tid 52469, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:15 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf5000000060b0432d10002
2022.09.09 17:26:15 5: SH10rt_1_1: readFn buffer: 006300000007010404ffdfffff
2022.09.09 17:26:15 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:15 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 99, dlen 7 and potential data 04ffdfffff
2022.09.09 17:26:15 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:15 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:15 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex ffdfffff, type i, adr 13009
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex ffdfffff, type i, adr 13009, valuesLen 2
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i13009
2022.09.09 17:26:15 5: SH10rt_1_1: SplitDataString has no information about handling i13010
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:15 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:15 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:15 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex ffdfffff, type i, adr 13009
2022.09.09 17:26:16 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex ffdfffff, type i, adr 13009, valuesLen 2
2022.09.09 17:26:16 5: SH10rt_1_relay: SplitDataString has no information about handling i13009
2022.09.09 17:26:16 5: SH10rt_1_relay: SplitDataString has no information about handling i13010
2022.09.09 17:26:16 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:16 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:16 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:16 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 006300000007010404ffdfffff, id 1, fCode 4, tid 99,
request: id 1 fc 4 i13009, len 2, tid 99, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13009, len 2, values ffdfffff, tid 52469
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf5000000070b0404ffdfffff
2022.09.09 17:26:16 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 006300000007010404ffdfffff, id 1, fCode 4, tid 99,
request: id 1 fc 4 i13009, len 2, tid 99, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13009, len 2, values ffdfffff, tid 52469
2022.09.09 17:26:16 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:16 5: SH10rt_1_1: DropFrame called from ReadFn - drop 006300000007010404ffdfffff
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: readFn buffer: ccf6000000060b0432de0001
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart called from ReadFn protocol TCP expecting id 11
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52470, dlen 6 and potential data 32de0001
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: HandleRequest called from ReadFn
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: ParseRequest called from HandleRequest
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest, current frame / read buffer: ccf6000000060b0432de0001, id 11, fCode 4, tid 52470,
request: id 11 fc 4 i13022, len 1, tid 52470
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest called from HandleRequest
2022.09.09 17:26:16 5: SH10rt_1_relay: GetRelayIO found SH10rt_1_1 as Modbus relay forward io device for SH10rt_1_1 with id 1
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1, current frame / read buffer: ccf6000000060b0432de0001, id 11, fCode 4, tid 52470,
request: id 11 fc 4 i13022, len 1, tid 52470, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:16 5: SH10rt_1_1: QueueRequest called from RelayRequest with i13022, qlen 0 from master SH10rt_1_1 for relay SH10rt_1_relay_192.168.x.x_54926 through io device SH10rt_1_1
2022.09.09 17:26:16 5: SH10rt_1_1: ProcessRequestQueue called from QueueRequest as direct:SH10rt_1_1, qlen 1, force, request: request: id 1 fc 4 i13022, len 1, tid 76, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.00 secs ago
2022.09.09 17:26:16 5: SH10rt_1_1: checkDelays sendDelay, last send to same device was 0.025 secs ago, required delay is 0.1
2022.09.09 17:26:16 5: SH10rt_1_1: checkDelays busDelayRead, last activity on bus was 0.018 secs ago, required delay is 0
2022.09.09 17:26:16 5: SH10rt_1_1: checkDelays clientSwitchDelay is not relevant
2022.09.09 17:26:16 5: SH10rt_1_1: checkDelays commDelay, last communication with same device was 0.018 secs ago, required delay is 0.1
2022.09.09 17:26:16 4: SH10rt_1_1: checkDelays found commDelay not over, sleep for 0.082 forced
2022.09.09 17:26:16 4: SH10rt_1_1: checkDelays sleep done, go on with sending
2022.09.09 17:26:16 4: SH10rt_1_1: ProcessRequestQueue (V4.4.04 - 17.7.2021) qlen 1, sending 004c00000006010432de0001 via 192.168.x.x:502, read buffer empty,
request: id 1 fc 4 i13022, len 1, tid 76, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.09 secs ago
2022.09.09 17:26:16 5: SH10rt_1_1: Send called from ProcessRequestQueue
2022.09.09 17:26:16 5: DevIo_SimpleWrite SH10rt_1_1: 004c00000006010432de0001
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: HandleRequest Done, current frame / read buffer: ccf6000000060b0432de0001, id 11, fCode 4, tid 52470,
request: id 11 fc 4 i13022, len 1, tid 52470, for relay device SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: DropFrame called from ReadFn - drop ccf6000000060b0432de0001
2022.09.09 17:26:16 5: SH10rt_1_1: readFn buffer: 004c0000000501040203c4
2022.09.09 17:26:16 5: SH10rt_1_1: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2022.09.09 17:26:16 4: SH10rt_1_1: ParseFrameStart (TCP, master) extracted id 1, fCode 4, tid 76, dlen 5 and potential data 0203c4
2022.09.09 17:26:16 5: SH10rt_1_1: HandleResponse called from ReadFn
2022.09.09 17:26:16 5: SH10rt_1_1: ParseResponse called from HandleResponse
2022.09.09 17:26:16 5: SH10rt_1_1: now parsing response data objects, master is SH10rt_1_1 relay is SH10rt_1_relay
2022.09.09 17:26:16 5: SH10rt_1_1: ParseDataString called from HandleResponse with data hex 03c4, type i, adr 13022
2022.09.09 17:26:16 5: SH10rt_1_1: SplitDataString called from ParseDataString with data hex 03c4, type i, adr 13022, valuesLen 1
2022.09.09 17:26:16 5: SH10rt_1_1: SplitDataString has no information about handling i13022
2022.09.09 17:26:16 5: SH10rt_1_1: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:16 5: SH10rt_1_1: CreateDataObjects sortedList
2022.09.09 17:26:16 5: SH10rt_1_1: ParseDataString created 0 readings
2022.09.09 17:26:16 5: SH10rt_1_relay: ParseDataString called from HandleResponse with data hex 03c4, type i, adr 13022
2022.09.09 17:26:16 5: SH10rt_1_relay: SplitDataString called from ParseDataString with data hex 03c4, type i, adr 13022, valuesLen 1
2022.09.09 17:26:16 5: SH10rt_1_relay: SplitDataString has no information about handling i13022
2022.09.09 17:26:16 5: SH10rt_1_relay: CreateDataObjects called from ParseDataString with objList
2022.09.09 17:26:16 5: SH10rt_1_relay: CreateDataObjects sortedList
2022.09.09 17:26:16 5: SH10rt_1_relay: ParseDataString created 0 readings
2022.09.09 17:26:16 4: SH10rt_1_1: RelayResponse via SH10rt_1_relay_192.168.x.x_54926, ioDev SH10rt_1_relay_192.168.x.x_54926, current frame / read buffer: 004c0000000501040203c4, id 1, fCode 4, tid 76,
request: id 1 fc 4 i13022, len 1, tid 76, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13022, len 1, values 03c4, tid 52470
2022.09.09 17:26:16 5: SH10rt_1_relay_192.168.x.x_54926: Send called from RelayResponse
2022.09.09 17:26:16 4: SH10rt_1_relay_192.168.x.x_54926: Send ccf6000000050b040203c4
2022.09.09 17:26:16 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 004c0000000501040203c4, id 1, fCode 4, tid 76,
request: id 1 fc 4 i13022, len 1, tid 76, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13022, len 1, values 03c4, tid 52470
2022.09.09 17:26:16 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:16 5: SH10rt_1_1: DropFrame called from ReadFn - drop 004c0000000501040203c4
2022.09.09 17:26:20 3: SH10rt_2_relay_192.168.x.x_44770: read from TCP server connection got null -> closing
2022.09.09 17:26:20 3: SH10rt_2_relay_192.168.x.x_44770: _UnDef is closing SH10rt_2_relay_192.168.x.x_44770
2022.09.09 17:26:21 3: SH10rt_1_relay_192.168.x.x_54926: read from TCP server connection got null -> closing
2022.09.09 17:26:21 3: SH10rt_1_relay_192.168.x.x_54926: _UnDef is closing SH10rt_1_relay_192.168.x.x_54926
2022.09.09 17:26:21 5: SH10rt_1_relay_192.168.x.x_54926: Close called from UndefLDFn with noState and noDelete
2022.09.09 17:26:21 4: SH10rt_1_relay_192.168.x.x_54926: Close TCP server listening connection and delete hash
2022.09.09 17:26:21 5: SH10rt_1_relay_192.168.x.x_54926: Close is removing lastconn from parent device SH10rt_1_relay
2022.09.09 17:26:21 5: SH10rt_2_1: UpdateSetList: setList=reconnect:noArg saveAsModule createAttrsFromParseInfo interval reread:noArg stop:noArg start:noArg close:noArg scanStop:noArg scanModbusObjects inactive active
2022.09.09 17:26:21 5: SH10rt_2_1: UpdateSetList: getList=
2022.09.09 17:26:25 4: Connection accepted from SH10rt_1_relay_192.168.x.x_54932
2022.09.09 17:26:25 4: SH10rt_1_relay: HandleServerConnection accepted new TCP connection as device SH10rt_1_relay_192.168.x.x_54932
2022.09.09 17:26:25 5: SH10rt_1_relay_192.168.x.x_54932: ResetExpect for HandleServerConnection from undefined to request
2022.09.09 17:26:25 5: SH10rt_1_relay_192.168.x.x_54932: readFn buffer: ccf7000000060b0413980002
2022.09.09 17:26:25 5: SH10rt_1_relay_192.168.x.x_54932: ParseFrameStart called from ReadFn
2022.09.09 17:26:25 4: SH10rt_1_relay_192.168.x.x_54932: ParseFrameStart (TCP, relay) extracted id 11, fCode 4, tid 52471, dlen 6 and potential data 13980002
2022.09.09 17:26:25 5: SH10rt_1_relay_192.168.x.x_54932: HandleRequest called from ReadFn
2022.09.09 17:26:25 5: SH10rt_1_relay_192.168.x.x_54932: ParseRequest called from HandleRequest
2022.09.09 17:26:25 4: SH10rt_1_relay_192.168.x.x_54932: HandleRequest, current frame / read buffer: ccf7000000060b0413980002, id 11, fCode 4, tid 52471,
request: id 11 fc 4 i5016, len 2, tid 52471
2022.09.09 17:26:25 4: SH10rt_1_relay_192.168.x.x_54932: RelayRequest called from HandleRequest
2022.09.09 17:26:25 5: SH10rt_1_relay: GetRelay

[StefanStrobel]

Hallo FhemPiUser,

vielen Dank für die Logs.
Am Anfang fehlen noch die Einträge des Relays, aber ab 2022.09.09 17:26:10 ist dann sowohl das Relay als auch der Master drin.
evcc scheint alle 10 Sekunden 6 Requests ohne delays direkt nacheinander zu schicken.

Code: [Auswählen]

2022.09.09 17:26:15 4: Connection accepted from SH10rt_1_relay_192.168.x.x_54926
Der erste Request, der dann weitergeleitet wird:

Code: [Auswählen]

2022.09.09 17:26:15 4: SH10rt_1_relay_192.168.x.x_54926: RelayRequest via SH10rt_1_1, Proto TCP with id 1,
current frame / read buffer: ccf1000000060b0413980002, id 11, fCode 4, tid 52465,
request: id 11 fc 4 i5016, len 2, tid 52465, for relay device SH10rt_1_relay_192.168.x.x_54926

Danach kommen:

Code: [Auswählen]

request: id 11 fc 4 i13021, len 1, tid 52466, for relay device SH10rt_1_relay_192.168.x.x_54926
request: id 11 fc 4 i13000, len 1, tid 52467, for relay device SH10rt_1_relay_192.168.x.x_54926
request: id 11 fc 4 i13000, len 1, tid 52468, for relay device SH10rt_1_relay_192.168.x.x_54926
request: id 11 fc 4 i13009, len 2, tid 52469, for relay device SH10rt_1_relay_192.168.x.x_54926
request: id 11 fc 4 i13022, len 1, tid 52470, for relay device SH10rt_1_relay_192.168.x.x_54926

Dann scheint es erst mal zufrieden zu sein.

Code: [Auswählen]

2022.09.09 17:26:16 4: SH10rt_1_1: HandleResponse done, current frame / read buffer: 004c0000000501040203c4, id 1, fCode 4, tid 76,
request: id 1 fc 4 i13022, len 1, tid 76, master device SH10rt_1_1, for relay device SH10rt_1_relay_192.168.x.x_54926 (relayed), queued 0.10 secs ago, sent 0.10 secs ago,
response: id 11, fc 4, i13022, len 1, values 03c4, tid 52470
2022.09.09 17:26:16 5: SH10rt_1_1: ResetExpect for HandleResponse from response to idle
2022.09.09 17:26:16 5: SH10rt_1_1: DropFrame called from ReadFn - drop 004c0000000501040203c4
Da ist dann mal eine Pause und dann macht evcc die Verbindung zu:

Code: [Auswählen]

2022.09.09 17:26:20 3: SH10rt_2_relay_192.168.x.x_44770: read from TCP server connection got null -> closing

und öffnet sie dann wieder neu wenn 10 Sekunden vergangen sind:

Code: [Auswählen]

2022.09.09 17:26:25 4: Connection accepted from SH10rt_1_relay_192.168.x.x_54932
2022.09.09 17:26:25 4: SH10rt_1_relay: HandleServerConnection accepted new TCP connection as device SH10rt_1_relay_192.168.x.x_54932

das sieht alles völlig harmlos aus. Keine Fehler, keine Timeouts etc.
Läuft auf diesem Pi noch irgend etwas anderes in Fhem oder ist es wirklich nur das Relay?
Bitte poste doch noch die vollständige Konfiguration (am einfachsten die ganze fhem.cfg)
und die Version vom OS und von Perl.

Ich könnte mal versuchen, das ganze bei mir nachzustellen. Wenn es wirklich nur die 6 Requests sind, kann ich die ja auch per Fhem simulieren.
Leider kann ich nicht absehen, wann ich in den nächsten Tagen / Wochen dazu komme.
Um sicherzugehen, dass da nicht doch noch was anderes passiert wären 2-3 Stunden Logs doch ganz hilfreich. Die kannst Du ja als Datei posten.

Gruss
   Stefan

[FhemPiUser]

Hallo Stefan,

die Log-Datei über 1,5 Std hängt an.

OS-Version ist Raspbian GNU/Linux 10 (buster).
Perl-Version ist perl 5, version 28, subversion 1 (v5.28.1) built for arm-linux-gnueabihf-thread-multi-64int
(with 65 registered patches).

Fhem- und Modbus-Versionen sind:

Code: [Auswählen]

fhem.pl           26115 2022-06-04 09:50:00Z rudolfkoenig
98_Modbus.pm      25963 2022-04-14 16:52:16Z StefanStrobel
98_ModbusAttr.pm  25963 2022-04-14 16:52:16Z StefanStrobel

In fhem ist außer den ModbusAttr devices nur noch ein dummy und sysmon devices zur Kontrolle der RAM-Nutzung. Die fhem.cfg ist wie folgt:

Code: [Auswählen]

attr global userattr cmdIcon devStateIcon:textField-long devStateStyle icon sortby webCmd webCmdLabel:textField-long widgetOverride
attr global autoload_undefined_devices 1
attr global logfile ./log/fhem-%Y-%m.log
attr global modpath .
attr global statefile ./log/fhem.save
attr global verbose 3

define WEB FHEMWEB 8083 global
setuuid WEB xx
attr WEB menuEntries CodeImport,/fhem?detail=ImporDummyt#

# Fake FileLog entry, to access the fhem log from FHEMWEB
define Logfile FileLog ./log/fhem-%Y-%m.log Logfile
setuuid Logfile xx

define autocreate autocreate
setuuid autocreate xx
attr autocreate filelog ./log/%NAME-%Y.log

define eventTypes eventTypes ./log/eventTypes.txt
setuuid eventTypes xx

# Disable this to avoid looking for new USB devices on startup
define initialUsbCheck notify global:INITIALIZED usb create
setuuid initialUsbCheck xx
define allowed allowed
setuuid allowed xx
attr allowed basicAuth xx
attr allowed validFor WEB
define SH10rt_2_1 ModbusAttr 1 0 192.168.xx.xx:502 TCP
setuuid SH10rt_2_1 xx
attr SH10rt_2_1 verbose 0
define SH10rt_1_1 ModbusAttr 1 0 192.168.xx.xx:502 TCP
setuuid SH10rt_1_1 xx
attr SH10rt_1_1 verbose 0
define SH10rt_1_relay ModbusAttr 11 relay 192.168.x.xx:1502 TCP to SH10rt_1_1
setuuid SH10rt_1_relay xx
attr SH10rt_1_relay verbose 0
define SH10rt_2_relay ModbusAttr 12 relay 192.168.x.xx:1503 TCP to SH10rt_2_1
setuuid SH10rt_2_relay xx
attr SH10rt_2_relay verbose 0
define ImportDummy dummy
setuuid ImportDummy xx
attr ImportDummy room ImportDummy
define sysmon SYSMON 5 5 5 30
setuuid sysmon xx
attr sysmon event-on-update-reading cpu_temp,cpu_temp_avg,cpu_freq,eth0_diff,loadavg,ram,fs_.*,stat_cpu_percent,load_15min,load_5min
attr sysmon filesystems fs_boot:/boot,fs_root:/:Root
attr sysmon group RPi
attr sysmon network-interfaces eth0:eth0:Ethernet
attr sysmon room Sysmon
attr sysmon userReadings load_15min { ((split(" ",ReadingsVal("sysmon","loadavg","0")))[2]) }, load_5min { ((split(" ",ReadingsVal("sysmon","loadavg","0")))[1]) }, fs_boot_percused { ((split(" ",ReadingsVal("sysmon","fs_boot","0")))[6]) },  fs_root_percused { ((split(" ",ReadingsVal("sysmon","fs_root","0")))[6]) }, swap_used_perc { ((split(" ",ReadingsVal("sysmon","swap","0")))[6]) },ram_used_perc { ((split(" ",ReadingsVal("sysmon","ram","0")))[6]) }
define FileLog_sysmon FileLog ./log/sysmon-%Y-%m.log sysmon
setuuid FileLog_sysmon xx
attr FileLog_sysmon group RPi
attr FileLog_sysmon logtype SM_CPUTemp:Plot,text
attr FileLog_sysmon nrarchive 3
attr FileLog_sysmon room Sysmon
define wl_sysmon_temp SVG FileLog_sysmon:SM_CPUTemp:CURRENT
setuuid wl_sysmon_temp xx
attr wl_sysmon_temp group RPi
attr wl_sysmon_temp label "CPU Temperatur: Min $data{min2}, Max $data{max2}, Last $data{currval2}"
attr wl_sysmon_temp room 9.03_Tech
define wl_sysmon_eth0 SVG FileLog_sysmon:SM_Network_eth0:CURRENT
setuuid wl_sysmon_eth0 xx
attr wl_sysmon_eth0 group RPi
attr wl_sysmon_eth0 label "Netzwerk-Traffic eth0: $data{min1}, Max: $data{max1}, Aktuell: $data{currval1}"
attr wl_sysmon_eth0 room 9.03_Tech
define wl_sysmon_wlan0 SVG FileLog_sysmon:SM_Network_wlan0:CURRENT
setuuid wl_sysmon_wlan0 xx
attr wl_sysmon_wlan0 group RPi
attr wl_sysmon_wlan0 label "Netzwerk-Traffic wlan0: $data{min1}, Max: $data{max1}, Aktuell: $data{currval1}"
attr wl_sysmon_wlan0 room 9.03_Tech
define wl_sysmon_load SVG FileLog_sysmon:SM_Load:CURRENT
setuuid wl_sysmon_load xx
attr wl_sysmon_load group RPi
attr wl_sysmon_load label "Load Min: $data{min1}, Max: $data{max1}, Aktuell: $data{currval1}"
attr wl_sysmon_load room 9.03_Tech
define wl_sysmon_ram SVG FileLog_sysmon:SM_RAM:CURRENT
setuuid wl_sysmon_ram xx
attr wl_sysmon_ram group RPi
attr wl_sysmon_ram label "RAM-Nutzung Total: $data{max1}, Min: $data{min2}, Max: $data{max2}, Avg: $data{avg2}, Aktuell: $data{currval2}"
attr wl_sysmon_ram room 9.03_Tech
define wl_sysmon_fs_root SVG FileLog_sysmon:SM_FS_root:CURRENT
setuuid wl_sysmon_fs_root xx
attr wl_sysmon_fs_root group RPi
attr wl_sysmon_fs_root label "Root Partition Total: $data{max1}, Min: $data{min2}, Max: $data{max2}, Aktuell: $data{currval2}"
attr wl_sysmon_fs_root room 9.03_Tech
define wl_sysmon_fs_usb1 SVG FileLog_sysmon:SM_FS_usb1:CURRENT
setuuid wl_sysmon_fs_usb1 xx
attr wl_sysmon_fs_usb1 group RPi
attr wl_sysmon_fs_usb1 label "USB1 Total: $data{max1}, Min: $data{min2}, Max: $data{max2}, Aktuell: $data{currval2}"
attr wl_sysmon_fs_usb1 room 9.03_Tech
define SysValues weblink htmlCode {SYSMON_ShowValuesHTML('sysmon')}
setuuid SysValues xx
attr SysValues group RPi
attr SysValues room 9.03_Tech
define wl_sysmon_cpustat SVG FileLog_sysmon:SM_CPUStat:CURRENT
setuuid wl_sysmon_cpustat xx
attr wl_sysmon_cpustat group RPi
attr wl_sysmon_cpustat label "CPU(min/max): user:$data{min1}/$data{max1} nice:$data{min2}/$data{max2} sys:$data{min3}/$data{max3} idle:$data{min4}/$data{max4} io:$data{min5}/$data{max5} irq:$data{min6}/$data{max6} sirq:$data{min7}/$data{max7}"
attr wl_sysmon_cpustat plotsize 840,420
attr wl_sysmon_cpustat room 9.99_Test
define wl_sysmon_cpustat_s SVG FileLog_sysmon:SM_CPUStatSum:CURRENT
setuuid wl_sysmon_cpustat_s 631a2935-f33f-28ea-d748-4afe56fe92d258fc
attr wl_sysmon_cpustat_s group RPi
attr wl_sysmon_cpustat_s label "CPU(min/max): user:$data{min1}/$data{max1} nice:$data{min2}/$data{max2} sys:$data{min3}/$data{max3} idle:$data{min4}/$data{max4} io:$data{min5}/$data{max5} irq:$data{min6}/$data{max6} sirq:$data{min7}/$data{max7}"
attr wl_sysmon_cpustat_s plotsize 840,420
attr wl_sysmon_cpustat_s room 9.99_Test
define wl_sysmon_cpustatT SVG FileLog_sysmon:SM_CPUStatTotal:CURRENT
setuuid wl_sysmon_cpustatT xx
attr wl_sysmon_cpustatT group RPi
attr wl_sysmon_cpustatT label "CPU-Auslastung"
attr wl_sysmon_cpustatT plotsize 840,420

Es laufen noch ein paar andere Dinge auf den Pi, u.a. evcc und pi-hole.

Ich hoffe es hilft. Vielen Dank für Deine Arbeit und das hervorragende Modul ModbusAttr!

Update: Die RAM-Nutzung steigt übrigens in 24Std um ca. 60Mbyte zur Abschätzung der Größe des Speicherlecks...

[StefanStrobel]

Hallo FhemPiUser,

ich glaube dass ich etwas gefunden habe.
Dein svcc hat wohl einen sehr kurzen Timeout und schließt die TCP-Verbindung zum Relay während das Relay noch auf die Antwort des Geräts wartet und wenn das Relay dann die Fehlermeldung (dass das Gerät nicht geantwortet hat) an evcc zurück schicken möchte, dann ist der Verbindungs-Hash weg, aber durch die Hash-Referenzen zwischen den internen Strukturen im Modul (Queue->Master und Queue->Relay) ist hier ein Memory-Leak denkbar. Ich habe mal ein paar weaken-Calls für diesen Fall eingebaut.
Bitte probier doch mal ob das etwas ändert.

Gruss
   Stefan

[FhemPiUser]

ok, klasse, vielen Dank! Ich tausche einfach das 98_Modbus.pm aus, starte fhem neu und warte mal ein paar Tage, ob das Speicherleck weg ist.

Oder soll ich direkt Logs senden?

[StefanStrobel]

Nein, ich würde auch erst mal 2 Tage beobachten.

Gruss / Thanx
   Stefan

[FhemPiUser]

Hallo Stefan,

leider ist das Speicherleck weiterhin vorhanden auch mit der neuen 98_modbus.pm.

Seit dem Neustart mit der neuen 98_modbus.pm gestern 12 Uhr ist der Speicherbedarf stetig leicht gestiegen. Ich habe um 17 Uhr fhem neu gestartet und der Speicherbedarf ist von ca. 180MB auf ca. 130MB gesunken (siehe Screenshots). Also Größe des Speicherlecks ist ca. 50MB in 29 Std bzw. 1,7MB pro Stunde.

"version" zeigt, dass auch wirklich die neue Version benutzt wurde:

Code: [Auswählen]

# $Id: 98_Modbus.pm unreleased development version StefanStrobel $
Auf der fhem-Instanz läuft außer dem modbusattr relay sonst praktisch nichts wie oben geschrieben.

Hast Du noch eine Idee?

[StefanStrobel]

Hallo FhemPiUser,

da muss ich weiter suchen.
Ich bin aber optimistisch.
Nur komme aber wohl nicht drum herum das Verhalten Deiner Geräte irgendwie bei mir zu simulieren.

Gruß
    Stefan

[StefanStrobel]

Hallo FhemPiUser,

kurzer Zwischenstand:
Ich habe Deine Konfiguration inzwischen nachstellen können und auch ein Speicherleck im Zusammenhang mit vom Slave geschlossenen TCP-Verbindungen gefunden.
Jetzt teste ich gerade ob der Fix auch wirklich funktioniert. Dann kommt eine neue Version :-)

Gruss
   Stefan

[FhemPiUser]

klasse, vielen Dank für die Zwischeninfo. Bin gespannt, ob es das dann war

[StefanStrobel]

Hallo FhemPiUser,

bei mir ist jetzt kein Speicherleck im Relay-Modus mehr feststellbar.
Probier doch mal das angehängte Modul.

Gruss
   Stefan

[FhemPiUser]

Hallo Stefan,

ja, das Speicherleck ist auch bei mir mit der neuen Version weg (s.u.). Klasse, vielen Dank!

[rudolfkoenig]

@Stefan: kannst Du uns sagen, wo das Problem lag?

[FhemPiUser]

ist der Fix inzwischen in der offiziellen mit fhem gelieferten Version enthalten?