Modbus stops without any errors

This makes sense… I can see from thread dump that the connection handling is somehow buggy and it basically gets stuck waiting for a “free” connection

My trouble is that so far I am not able to reproduce this, making troubleshooting and fixes very slow. Do you have easy means to get the erratic behavior?

Does anyone have a possibly for keeping the logging on for longer periods of time? I might have a means for a more extensive diagnostics but that will generate a lot logs

I will setup seperate logging for this when I have had some dinner. (in an hour or two). Then I´ll let it run in debug mode (or do you want trace mode)?
I guess I should log the io.transport? Or do you want me to log the binding? (or both perhaps) ?

My fear is the logfiles will grow pretty quickly. Hopefully it will show some issue before it gets overwritten. I normally log 10 files at 10MB each.

1 Like

Trace level logging of transport would be most useful and hopefully reveal the issue… Unfortunately it is quite a lot of log lines, so not sure if defaults are enough to keep all the logs. They do compress well if you are concerned of disk space.

If you give me some instruction how to set it up without the logs overwriting I will of course do more tests / logs.

thanks @jomojomo95. You can find log configuration in org.ops4j.pax.logging.cfg located in userdata folder (see here).

This post seems to have relevant details Again: Rotating Log

Thanks, I’ve started the TRACE logging of the modbus transport.

2020-09-02 21:23:38.076 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@ff7be7

2020-09-02 21:23:38.078 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] -> true

2020-09-02 21:23:38.079 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]...

2020-09-02 21:23:38.081 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 227ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074617854) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:38.088 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:38.090 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:38.092 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 14 ms

2020-09-02 21:23:38.093 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID f70e3137-9747-477e-94ab-2134323a0d84]

2020-09-02 21:23:38.094 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 254 ms, connection: 32, transaction=18, callback=177} [operation ID f70e3137-9747-477e-94ab-2134323a0d84]

2020-09-02 21:23:38.096 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] finished at 1599074618096. Was started at millis: 1599074617839 (=duration of 257 millis)

2020-09-02 21:23:40.279 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (evict) Connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 2424ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074617854) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:40.282 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - destroyObject for connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] and endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] -> closing the connection

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:43.473 [vent.ItemStateChangedEvent] - dndFunction changed from OFF to ON

2020-09-02 21:23:43.645 [vent.ItemStateChangedEvent] - historyTime changed from 20 to 3206

2020-09-02 21:23:43.651 [vent.ItemStateChangedEvent] - historyArea changed from 22.845 to 3183.075

2020-09-02 21:23:43.653 [vent.ItemStateChangedEvent] - historyArea changed from 3183.075 to 22.845

2020-09-02 21:23:43.656 [vent.ItemStateChangedEvent] - historyTime changed from 3206 to 20

2020-09-02 21:23:43.658 [vent.ItemStateChangedEvent] - dndFunction changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.098 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Current millis: 1599074624097

2020-09-02 21:23:44.100 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Trying to get connection [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.102 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 0 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.103 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Created connection TCPMasterConnection@958429[socket=<null>] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.107 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502], to ensure delay between transactions.

2020-09-02 21:23:44.109 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]]]) for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 5 ms

2020-09-02 21:23:44.111 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] (oneOff=false)! Connection received in 7 ms [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.112 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Got a connection successfully [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.114 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.115 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.117 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.118 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 00 00 68  [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.127 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=55588): d9 24 00 00 00 d3 01 03 d0 e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00  [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.129 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@73eb7c

2020-09-02 21:23:44.131 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:e3dc:polling received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3], registers = ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00)))

2020-09-02 21:23:44.137 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Consumption channels updated: {modbus:data:e3dc:polling:Consumption:number=629}. readValueType=int32_swap, readIndex=Optional[71], readSubIndex(or 0)=0, extractIndex=71 -> numeric value 629 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.139 [vent.ItemStateChangedEvent] - E3DC_Haus changed from 634 to 629

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.144 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:PV_Inverter channels updated: {modbus:data:e3dc:polling:PV_Inverter:number=0}. readValueType=int32_swap, readIndex=Optional[67], readSubIndex(or 0)=0, extractIndex=67 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.163 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Battery channels updated: {modbus:data:e3dc:polling:Battery:number=630.0}. readValueType=int32_swap, readIndex=Optional[69], readSubIndex(or 0)=0, extractIndex=69 -> numeric value -630 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.168 [vent.ItemStateChangedEvent] - E3DC_Battery changed from 636.0 to 630.0

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.169 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Grid channels updated: {modbus:data:e3dc:polling:Grid:number=-1}. readValueType=int32_swap, readIndex=Optional[73], readSubIndex(or 0)=0, extractIndex=73 -> numeric value -1 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.180 [vent.ItemStateChangedEvent] - E3DC_Netz changed from -2 to -1

2020-09-02 21:23:44.188 [vent.ItemStateChangedEvent] - E3DC_Battery_charge changed from 636.0 to 630.0

2020-09-02 21:23:44.191 [vent.ItemStateChangedEvent] - E3DC_Netz_provide changed from -2 to -1

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.196 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:External channels updated: {modbus:data:e3dc:polling:External:number=0.0}. readValueType=int32_swap, readIndex=Optional[75], readSubIndex(or 0)=0, extractIndex=75 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.202 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SelfConsumption channels updated: {modbus:data:e3dc:polling:SelfConsumption:number=99}. readValueType=uint8, readIndex=Optional[81], readSubIndex(or 0)=0, extractIndex=162 -> numeric value 99 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.208 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Autarky channels updated: {modbus:data:e3dc:polling:Autarky:number=99}. readValueType=uint8, readIndex=Optional[81], readSubIndex(or 0)=1, extractIndex=163 -> numeric value 99 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.214 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SoC channels updated: {modbus:data:e3dc:polling:SoC:number=80}. readValueType=uint16, readIndex=Optional[82], readSubIndex(or 0)=0, extractIndex=82 -> numeric value 80 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.220 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Emergency_Power_Status channels updated: {modbus:data:e3dc:polling:Emergency_Power_Status:number=2}. readValueType=uint16, readIndex=Optional[83], readSubIndex(or 0)=0, extractIndex=83 -> numeric value 2 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.226 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock channels updated: {modbus:data:e3dc:polling:EMS_Charge_Lock:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=0, extractIndex=1344 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.231 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock channels updated: {modbus:data:e3dc:polling:EMS_DisCharge_Lock:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=1, extractIndex=1345 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.237 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Emergency_Power channels updated: {modbus:data:e3dc:polling:EMS_Emergency_Power:number=1}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=2, extractIndex=1346 -> numeric value 1 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.242 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Wather_Based channels updated: {modbus:data:e3dc:polling:EMS_Wather_Based:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=3, extractIndex=1347 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.251 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Output_Cut channels updated: {modbus:data:e3dc:polling:EMS_Output_Cut:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=4, extractIndex=1348 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.260 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock_Time channels updated: {modbus:data:e3dc:polling:EMS_Charge_Lock_Time:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=5, extractIndex=1349 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.269 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock_Time channels updated: {modbus:data:e3dc:polling:EMS_DisCharge_Lock_Time:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=6, extractIndex=1350 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.277 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Voltage channels updated: {modbus:data:e3dc:polling:String1_Voltage:number=58}. readValueType=uint16, readIndex=Optional[95], readSubIndex(or 0)=0, extractIndex=95 -> numeric value 58 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.286 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Voltage channels updated: {modbus:data:e3dc:polling:String2_Voltage:number=65}. readValueType=uint16, readIndex=Optional[96], readSubIndex(or 0)=0, extractIndex=96 -> numeric value 65 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.294 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Voltage channels updated: {modbus:data:e3dc:polling:String3_Voltage:number=0}. readValueType=uint16, readIndex=Optional[97], readSubIndex(or 0)=0, extractIndex=97 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.303 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Current channels updated: {modbus:data:e3dc:polling:String1_Current:number=0}. readValueType=uint16, readIndex=Optional[98], readSubIndex(or 0)=0, extractIndex=98 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.312 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Current channels updated: {modbus:data:e3dc:polling:String2_Current:number=0}. readValueType=uint16, readIndex=Optional[99], readSubIndex(or 0)=0, extractIndex=99 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.320 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Current channels updated: {modbus:data:e3dc:polling:String3_Current:number=0}. readValueType=uint16, readIndex=Optional[100], readSubIndex(or 0)=0, extractIndex=100 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.329 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Power channels updated: {modbus:data:e3dc:polling:String1_Power:number=0}. readValueType=uint16, readIndex=Optional[101], readSubIndex(or 0)=0, extractIndex=101 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.337 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Power channels updated: {modbus:data:e3dc:polling:String2_Power:number=0}. readValueType=uint16, readIndex=Optional[102], readSubIndex(or 0)=0, extractIndex=102 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.345 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Power channels updated: {modbus:data:e3dc:polling:String3_Power:number=0}. readValueType=uint16, readIndex=Optional[103], readSubIndex(or 0)=0, extractIndex=103 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.347 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@73eb7c

2020-09-02 21:23:44.349 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] -> true

2020-09-02 21:23:44.352 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]...

2020-09-02 21:23:44.354 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 246ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074624107) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:44.361 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.363 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.365 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 16 ms

2020-09-02 21:23:44.367 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.368 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 269 ms, connection: 24, transaction=8, callback=220} [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.370 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] finished at 1599074624370. Was started at millis: 1599074624097 (=duration of 273 millis)

2020-09-02 21:23:46.387 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-02 21:23:46.391 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: 3981. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-02 21:23:46.394 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 1, remaining space 2147483647. Active threads 1

2020-09-02 21:23:46.396 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

I´m not worried about disk space. I´m worried that the error will appear and dissapear from the logfil, before I get the chance to grap it. But lets see how it goes.

EDIT - Logging runs now.

EDit again…
I kept an eye on the logfiles… Seems like it takes about 20MB in file size every 7 minutes. Thats HUGE!
In order to catch the issue when it happens it requires at least 12 hours of logfiles. Thats aprox 2GB of data…

I wonder if there is a way to stop the logging (save the existing logfiles from beeing overwritten) when the issue happens?

Well… I guess logging will reduce drastically when polling stops :sweat_smile:

Hopefully :slight_smile:
Atm I have set the logging to 20 files and 50MB each. Thats aprox 1GB and aprox 6 hours of logging. I Hope to catch it with this.

1 Like

After 2 days without any stops (idk why) I had a stop today again but sadly I could not log it with trace as I did the karaf trace setting first and afterwards changed the logs settings, this must have stop the trace logging I guess. :frowning:
I changed the logging to trace again and see the traces coming in.

FYI this are the traces of the stopped behavior, it still tries to poll but without any Item changes:

2020-09-05 13:10:33.134 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:33.137 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9650810. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:33.140 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:33.143 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:43.146 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:43.150 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9660822. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:43.154 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:43.159 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:53.163 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:53.168 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9670840. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:53.171 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:53.174 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

I’ll restart the binding and will report as I have a stop again.

@jomojomo95, no it’s not polling. The regular poll monitor log messages are actually just diagnostics information for troubelshooting.

@Kim_Andersen I assume no log with the trace logging? Based on user reports it seems the issue is less likely when there is verbose logging enabled…indicating a timing issue.

@jomojomo95 @Kim_Andersen ,

I would like to try one more thing, replacing one of the libraries used by the binding (pool2) to latest version with bug fixes.

  1. Uninstall modbus binding, using Paper UI
  2. Confirm uninstallation using bundle:list -s |grep modbus, no bundles should be installed
  3. Download modbus258.zip.pdf (309.9 KB) and rename modbus258.zip.pdfas modbus258.zip
  4. Unzip
  5. Find 2.5.8 jar files and copy them under addons
  6. Check the logs, you will probably have error there
SNIP
         Unresolved requirement: Import-Package: gnu.io; version="[3.12.0,6.0.0)"
SNIP
  1. gnu.io dependency is missing. Install it by feature:install openhab-transport-serial, and restart the bundles using bundle:restart
openhab> feature:install openhab-transport-serial
openhab> bundle:list -s |grep modbus
203 │ Installed │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Installed │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> bundle:restart 203 205  # Find correct IDs above
  1. Check the logs (log:tail), you will probably have error there, slightly different this time:
	Unable to start bundle 203: Could not resolve module: org.openhab.io.transport.modbus [203]
  Unresolved requirement: Import-Package: org.apache.commons.pool2; version="[2.4.0,3.0.0)"
...
  1. org.apache.commons.pool2 dependency is missing. Install it by bundle:install, and restart the bundles using bundle:restart. This time we install the latest version available, 2.8.1. This is newer than the version provided by default openHAB 2.5.8 installation

NOTE If you do not see the error regarding org.apache.commons.pool2, do not continue

openhab>bundle:install https://repo1.maven.org/maven2/org/apache/commons/commons-pool2/2.8.1/commons-pool2-2.8.1.jar
openhab> bundle:list -s |grep modbus
203 │ Installed │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Installed │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> bundle:restart 203 205  # Find correct IDs above
  1. Bundles should be now active, with no errors in logs
openhab> bundle:list -s |grep modbus
203 │ Active   │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Active   │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> log:tail
...
08:16:58.685 [INFO ] [ort.modbus.internal.ModbusManagerImpl] - Modbus manager activated
08:16:58.946 [INFO ] [ort.modbus.internal.ModbusManagerImpl] - Modbus manager activated
  1. Finally confirm the apache pool2 is the correct version, 2.8.1
openhab> bundle:tree-show 203 |grep pool # replace 203 with id of transport bundle (see above)
+- org.apache.commons.commons-pool2 [278]
openhab> bundle:list -s|grep pool
278 │ Resolved │  80 │ 2.8.1                   │ org.apache.commons.commons-pool2

Check that you have the same number (278) above outputted by both commands above. This means that modbus binding is using really the version 2.8.1 of pool2 library.

  1. Installation successfull

Ok, did as described step by step.
Now have the modbus jars active and pool2 resolved.
I hadn’t had to install gnu.io but I guess that’s ok.

@ssalonen should I stop the trace logging to force it faster or just let it run?

1 Like

Sounds good. Remove the trace logging please, hopefully it is more likely to get the issue then

You´re right. everything is working fine since I´d enabled the trace log…
I will not have time to give your suggest a try untill late tonight or tomorrow. But I will give it a try for sure.

1 Like

I got two stops since the change.
First one was just after 1 hour second around 11 hours.
So it seems no fix with the new pool2 version.

Ok that’s a shame to hear :grimacing:

Would you please run the threads commands when it is stuck?

Yet another possible fix

Install the binding manually, with pool 2.8.1, per the instructions in this post. Use the jar files from this zip:
modbus-fix-hang-reupload.zip.pdf (309.0 KB)

Successful installation should look like (check the date part after 2.5.9....)

openhab> bundle:list -s|grep '(modbus|pool)'; bundle:tree-show org.openhab.io.transport.modbus|grep pool2
256 │ Active   │  80 │ 2.5.9.202009100355      │ org.openhab.io.transport.modbus
257 │ Active   │  80 │ 2.5.9.202009100357      │ org.openhab.binding.modbus
266 │ Resolved │  80 │ 2.8.1                   │ org.apache.commons.commons-pool2
+- org.apache.commons.commons-pool2 [266]

2 Likes

Can you upload modbus-fix-hang.zip again? jar files contain only text of .jar file locations…
I have the same issue since I configured my inverter (SE4K) - it works for a few hours then suddenly stops - no matching errors in log files.

After about two days without any interupts I just got an stop again.
Here is the threads output: threads.txt (77.0 KB)

I will try the new possible fix tomorrow.
As said by @pewu78 the .jar Files you uploaded are only 1kb, I guess the compile failed.

1 Like