Modbus Binding not working on OH3

lampy · January 5, 2021, 11:41am

@JamesC This morning the modbus stopped working again, here below the logs:

2021-01-05 04:53:41.917 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ApparentPower channels updated: {}. readValueType=float32, readIndex=Optional[18], readSubIndex(or 0)=0, extractIndex=18 -> numeric value 377.86651611328125 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.920 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ReactivePower channels updated: {}. readValueType=float32, readIndex=Optional[24], readSubIndex(or 0)=0, extractIndex=24 -> numeric value -365.1000061035156 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.923 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PowerFactor channels updated: {modbus:data:endpointSDM120:inputRegisters:PowerFactor:number=0.25716885924339294}. readValueType=float32, readIndex=Optional[30], readSubIndex(or 0)=0, extractIndex=30 -> numeric value 0.25716885924339294 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.926 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PhaseAngle channels updated: {}. readValueType=float32, readIndex=Optional[36], readSubIndex(or 0)=0, extractIndex=36 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.930 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Frequency channels updated: {modbus:data:endpointSDM120:inputRegisters:Frequency:number=50.0}. readValueType=float32, readIndex=Optional[70], readSubIndex(or 0)=0, extractIndex=70 -> numeric value 50.0 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.933 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=72 -> numeric value 1718.68505859375 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.935 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=74 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.938 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=17.885000228881836}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 17.885000228881836 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:41.940 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2361.3798828125 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB020C000000000000000042C23333000000000000000043BCEEEA0000000000000000C3B68CCD00000000000000003E83ABA3000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.811 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614)))
2021-01-05 04:53:43.813 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=227.10000610351562}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 227.10000610351562 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.815 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=1.7139999866485596}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 1.7139999866485596 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.820 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ActivePower channels updated: {modbus:data:endpointSDM120:inputRegisters:ActivePower:number=98.69999694824219}. readValueType=float32, readIndex=Optional[12], readSubIndex(or 0)=0, extractIndex=12 -> numeric value 98.69999694824219 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.822 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ApparentPower channels updated: {}. readValueType=float32, readIndex=Optional[18], readSubIndex(or 0)=0, extractIndex=18 -> numeric value 378.81805419921875 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.825 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ReactivePower channels updated: {}. readValueType=float32, readIndex=Optional[24], readSubIndex(or 0)=0, extractIndex=24 -> numeric value -365.70001220703125 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.829 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PowerFactor channels updated: {modbus:data:endpointSDM120:inputRegisters:PowerFactor:number=0.260623574256897}. readValueType=float32, readIndex=Optional[30], readSubIndex(or 0)=0, extractIndex=30 -> numeric value 0.260623574256897 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.830 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PhaseAngle channels updated: {}. readValueType=float32, readIndex=Optional[36], readSubIndex(or 0)=0, extractIndex=36 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.834 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Frequency channels updated: {modbus:data:endpointSDM120:inputRegisters:Frequency:number=50.0}. readValueType=float32, readIndex=Optional[70], readSubIndex(or 0)=0, extractIndex=70 -> numeric value 50.0 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.837 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=72 -> numeric value 1718.68505859375 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.839 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=74 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.842 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=17.885000228881836}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 17.885000228881836 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:43.845 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2361.3798828125 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDB645A000000000000000042C56666000000000000000043BD68B60000000000000000C3B6D99A00000000000000003E857074000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D5EC00000000418F147B45139614) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:53:46.850 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID c0d86404-44f2-411a-aff4-f5eaa0849f95]
2021-01-05 05:04:29.310 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = xxxxxxxx, base URL = http://localhost:8080)
2021-01-05 05:05:20.354 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = xxxxxxx, base URL = http://localhost:8080)

The WARN message comes back more often:

2021-01-05 04:35:37.814 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=17.885000228881836}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 17.885000228881836 and boolValue=true. Registers ModbusRegisterArray(4363333300000000000000003FDB4396000000000000000042C2999A000000000000000043BD3B080000000000000000C3B6D99A00000000000000003E83C3D2000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D4FE00000000418F147B45139452) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:35:37.817 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2361.27001953125 and boolValue=true. Registers ModbusRegisterArray(4363333300000000000000003FDB4396000000000000000042C2999A000000000000000043BD3B080000000000000000C3B6D99A00000000000000003E83C3D2000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044D6D4FE00000000418F147B45139452) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:35:40.821 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID fea1fcfa-218f-404d-a431-fd9bdae62a8a]
2021-01-05 04:35:41.307 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(4363333300000000000000003FDB4396000000000000000042C4999A000000000000000043BD3B0F0000000000000000C3B6B33300000000000000003E8512DF000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D4FE00000000418F147B45139456)))
2021-01-05 04:35:41.310 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=227.1999969482422}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 227.1999969482422 and boolValue=true. Registers ModbusRegisterArray(4363333300000000000000003FDB4396000000000000000042C4999A000000000000000043BD3B0F0000000000000000C3B6B33300000000000000003E8512DF000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D4FE00000000418F147B45139456) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:35:41.314 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=1.7130000591278076}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 1.7130000591278076 and boolValue=true. Registers ModbusRegisterArray(4363333300000000000000003FDB4396000000000000000042C4999A000000000000000043BD3B0F0000000000000000C3B6B33300000000000000003E8512DF000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D4FE00000000418F147B45139456) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]

2021-01-05 04:51:53.421 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=17.885000228881836}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 17.885000228881836 and boolValue=true. Registers ModbusRegisterArray(4363000000000000000000003FDB4396000000000000000042C43333000000000000000043BCD0540000000000000000C3B64CCD00000000000000003E852261000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D5D300000000418F147B451395E7) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:51:53.426 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2361.368896484375 and boolValue=true. Registers ModbusRegisterArray(4363000000000000000000003FDB4396000000000000000042C43333000000000000000043BCD0540000000000000000C3B64CCD00000000000000003E852261000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D5D300000000418F147B451395E7) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:51:56.430 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID 5b9b51f3-2094-43e1-b718-89f2df624f67]
2021-01-05 04:51:56.859 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(4363199A00000000000000003FDAE148000000000000000042C20000000000000000000043BCD05B0000000000000000C3B6733300000000000000003E839EC1000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D5DB00000000418F147B451395E7)))
2021-01-05 04:51:56.862 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=227.10000610351562}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 227.10000610351562 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDAE148000000000000000042C20000000000000000000043BCD05B0000000000000000C3B6733300000000000000003E839EC1000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D5DB00000000418F147B451395E7) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-05 04:51:56.865 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=1.7100000381469727}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 1.7100000381469727 and boolValue=true. Registers ModbusRegisterArray(4363199A00000000000000003FDAE148000000000000000042C20000000000000000000043BCD05B0000000000000000C3B6733300000000000000003E839EC1000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44D6D5DB00000000418F147B451395E7) for request ModbusReadRequestBlueprint@1aa1c08[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]

I had updated to the new .jar from @fwolter already earlier.

Screenshot of symlinks:

Screenshot of openhab file:

Output of command lsusb

[12:35:56] openhabian@openHAB3:~$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 007: ID 1cf1:0030 Dresden Elektronik
Bus 001 Device 006: ID 0658:0200 Sigma Designs, Inc. Aeotec Z-Stick Gen5 (ZW090) - UZB
Bus 001 Device 005: ID 1a86:7523 QinHeng Electronics HL-340 USB-Serial adapter
Bus 001 Device 004: ID 1a40:0101 Terminus Technology Inc. Hub
Bus 001 Device 003: ID 14cd:1212 Super Top microSD card reader (SY-T18)
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

To make it all complete, here my .things file:

Bridge modbus:serial:endpointSDM120 [port="/dev/ttyUSBMODBUS",baud=9600,id=1,dataBits=8,parity="none",stopBits="1.0",encoding="rtu"] {
    Bridge poller inputRegisters [ start=0, length=80, refresh=1500, type="input" ] {
        Thing data Voltage                       "Voltage" @ "Mains"                            [ readStart="0", readValueType="float32" ]
        Thing data Current                       "Current" @ "Mains"                             [ readStart="6", readValueType="float32" ]
        Thing data ActivePower                   "Active Power" @ "Mains"                        [ readStart="12", readValueType="float32" ]
        Thing data ApparentPower                 "Apparent Power" @ "Mains"                      [ readStart="18", readValueType="float32" ]
        Thing data ReactivePower                 "Reactive Power" @ "Mains"                      [ readStart="24", readValueType="float32" ]
        Thing data PowerFactor                   "Power Factor" @ "Mains"                        [ readStart="30", readValueType="float32" ]
        Thing data PhaseAngle                    "Phase Angle" @ "Mains"                          [ readStart="36", readValueType="float32" ]
        Thing data Frequency                     "Frequency" @ "Mains"                            [ readStart="70", readValueType="float32" ]
        Thing data ImportActiveEnergy            "Import Active Energy" @ "Mains"                 [ readStart="72", readValueType="float32" ]
        Thing data ExportActiveEnergy            "Export Active Energy" @ "Mains"                [ readStart="74", readValueType="float32" ]
        Thing data ImportReactiveEnergy          "Import Reactive Energy" @ "Mains"              [ readStart="76", readValueType="float32" ]
        Thing data ExportReactiveEnergy          "Export Reactive Energy" @ "Mains"             [ readStart="78", readValueType="float32" ]
        
	}}

JamesC · January 6, 2021, 7:46pm

I also had the modus stop working with the new JAR installed. It held up for about two days.
The readings flatline:

The modus things remain online:

The logfile shows:

2021-01-06 11:44:45.213 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:afad3afb channels updated: {modbus:data:afad3afb:number=5.0, modbus:data:afad3afb:datetime=1970-01-01T00:00:05.000+0000, modbus:data:afad3afb:contact=OPEN, modbus:data:afad3afb:string=5.0, modbus:data:afad3afb:lastReadSuccess=2021-01-06T11:44:45.213639+1000, modbus:data:afad3afb:dimmer=ON, modbus:data:afad3afb:rollershutter=5.0, modbus:data:afad3afb:switch=ON}. readValueType=float32, readIndex=Optional[2], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 5.0 and boolValue=true. Registers ModbusRegisterArray(40A00000) for request ModbusReadRequestBlueprint@67a36a15[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=2,maxTries=3]
2021-01-06 11:44:46.036 [DEBUG] [t.wimpi.modbus.io.ModbusRTUTransport] - Sent: 01 04 00 48 00 0c 70 19 
2021-01-06 11:44:46.154 [TRACE] [t.wimpi.modbus.io.ModbusRTUTransport] - Managed to read at least one byte
2021-01-06 11:44:46.155 [DEBUG] [t.wimpi.modbus.io.ModbusRTUTransport] - Response: 01 04 18 46 b9 3c 05 46 b3 3d dc 44 12 da 9e 46 43 a0 1e 47 3d 4b 47 48 04 d2 df c5 43 
2021-01-06 11:44:46.156 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:29600f78 received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@60b1042b[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=72,length=12,maxTries=3], registers = ModbusRegisterArray(46B93C0546B33DDC4412DA9E4643A01E473D4B474804D2DF)))
2021-01-06 11:44:46.156 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel number will be updated to '22942.9296875' (type DecimalType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.157 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel datetime will be updated to '1970-01-01T06:22:22.000+0000' (type DateTimeType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.157 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel string will be updated to '22942.9296875' (type StringType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.157 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'OPEN' (type OpenClosedType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.157 [WARN ] [ernal.handler.ModbusDataThingHandler] - Channel rollershutter will not be updated since transformation was unsuccessful. Channel is expecting the following data types [PercentType, UpDownType, UnDefType]. Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.158 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel dimmer will be updated to 'ON' (type OnOffType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.158 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel switch will be updated to 'ON' (type OnOffType). Input data: number value 22942.9296875 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.158 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:2b4a8a03 channels updated: {modbus:data:2b4a8a03:string=22942.9296875, modbus:data:2b4a8a03:datetime=1970-01-01T06:22:22.000+0000, modbus:data:2b4a8a03:dimmer=ON, modbus:data:2b4a8a03:number=22942.9296875, modbus:data:2b4a8a03:lastReadSuccess=2021-01-06T11:44:46.158427+1000, modbus:data:2b4a8a03:switch=ON, modbus:data:2b4a8a03:contact=OPEN}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=2 -> numeric value 22942.9296875 and boolValue=true. Registers ModbusRegisterArray(46B93C0546B33DDC4412DA9E4643A01E473D4B474804D2DF) for request ModbusReadRequestBlueprint@60b1042b[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=72,length=12,maxTries=3]
2021-01-06 11:44:46.159 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel number will be updated to '23710.009765625' (type DecimalType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.159 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel datetime will be updated to '1970-01-01T06:35:10.000+0000' (type DateTimeType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.159 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel string will be updated to '23710.009765625' (type StringType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.159 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'OPEN' (type OpenClosedType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.160 [WARN ] [ernal.handler.ModbusDataThingHandler] - Channel rollershutter will not be updated since transformation was unsuccessful. Channel is expecting the following data types [PercentType, UpDownType, UnDefType]. Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.160 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel dimmer will be updated to 'ON' (type OnOffType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.160 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel switch will be updated to 'ON' (type OnOffType). Input data: number value 23710.009765625 (value type 'float32' taken into account) and bool value true. Transformation: <identity>
2021-01-06 11:44:46.160 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:dcc865e8 channels updated: {modbus:data:dcc865e8:contact=OPEN, modbus:data:dcc865e8:switch=ON, modbus:data:dcc865e8:string=23710.009765625, modbus:data:dcc865e8:dimmer=ON, modbus:data:dcc865e8:number=23710.009765625, modbus:data:dcc865e8:datetime=1970-01-01T06:35:10.000+0000, modbus:data:dcc865e8:lastReadSuccess=2021-01-06T11:44:46.160549+1000}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 23710.009765625 and boolValue=true. Registers ModbusRegisterArray(46B93C0546B33DDC4412DA9E4643A01E473D4B474804D2DF) for request ModbusReadRequestBlueprint@60b1042b[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=72,length=12,maxTries=3]
2021-01-06 11:44:50.665 [DEBUG] [t.wimpi.modbus.io.ModbusRTUTransport] - Sent: 03 04 00 00 00 1a 70 23 
2021-01-06 11:44:52.167 [TRACE] [t.wimpi.modbus.io.ModbusRTUTransport] - Managed to read at least one byte
2021-01-06 11:44:52.167 [DEBUG] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 03 04 00 00 00 1a 70 23
2021-01-06 11:44:52.168 [DEBUG] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2021-01-06 11:44:52.168 [DEBUG] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/1 error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadInputRegistersRequest@7d832fa1 (unit id 3 & transaction 32803). Serial parameters: SerialParameters@29c14505[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2021-01-06 11:44:52.168 [DEBUG] [pi.modbus.io.ModbusSerialTransaction] - execute reached max tries 1, throwing last error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadInputRegistersRequest@7d832fa1 (unit id 3 & transaction 32803). Serial parameters: SerialParameters@29c14505[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2021-01-06 11:44:52.169 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@6c4ff397[slaveId=3,functionCode=READ_INPUT_REGISTERS,start=0,length=26,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID 284c3879-8e30-407c-817e-f24255cfe433]
2021-01-06 11:44:52.228 [TRACE] [et.wimpi.modbus.net.SerialConnection] - Got Port Identifier

@fwolter please see the log files from the patched JAR.

fwolter · January 6, 2021, 8:02pm

Which OH version are you using? The patched JAR was built for a milestone release. Maybe it doesn’t have an effect anymore.

rossko57 · January 6, 2021, 11:24pm

This is ordinary enough, Modbus is robust enough to retry failed transfers.
So, there should afterwards be a “try 2 out of 3” warn - or - an ordinary working update.
Do you have any more Modbus log entries after this point? If not, it suggests the binding is messing up somewhere in setting up the retry.

lampy · January 7, 2021, 7:33am

After this error no more modbus related logs are shown. Not from the debug level nor the item updates.
Should we file an issue somewhere?

ssalonen · January 7, 2021, 8:15am

Well… Issue or not we need to have more information to actually fix the issue.

Since there are no messages at all after some point I wonder if the system gets somehow stuck.

Can you please follow the troubleshooting steps from Modbus stops without any errors - #19 by ssalonen

Especially the thread command are of interest

JamesC · January 7, 2021, 9:55am

I’m using openHAB 3.0.0 Release Build.

I will need to wait for the modbus to stop again and then run the thread debug commands. Will post once I have it.

lampy · January 7, 2021, 11:36am

Actually I didn’t restarted openhab to be able to provide additional information if required. I’ve executed the two commands and the logs are below.
It stopped working already a couple of days ago, so I am not sure if it is still containing the required information.

threads --locks --monitors.txt (198.4 KB) threads.txt (188.6 KB)

I am also on OH3.0.0 release build.

ssalonen · January 7, 2021, 5:17pm

@lampy Thank you, this was very useful.

It seems that it is stuck opening the serial port… This gives further indication where the problem is and how to resolve it

“OH-modbusManagerPollerThreadPool-3” Id=223 in TIMED_WAITING

at java.base@11.0.9/java.lang.Thread.sleep(Native Method)

at gnu.io.RXTXPort.waitForTheNativeCodeSilly(RXTXPort.java:958)

at gnu.io.RXTXPort.<init>(RXTXPort.java:180)

at gnu.io.RXTXCommDriver.getCommPort(RXTXCommDriver.java:983)

Looking at the relevant code (assuming openhab uses fresh version)

github.com

NeuronRobotics/nrjavaserial/blob/master/src/main/java/gnu/io/RXTXPort.java

/*-------------------------------------------------------------------------
|   RXTX License v 2.1 - LGPL v 2.1 + Linking Over Controlled Interface.
|   RXTX is a native interface to serial ports in java.
|   Copyright 1997-2008 by Trent Jarvi tjarvi@qbang.org and others who
|   actually wrote it.  See individual source files for more information.
|
|   A copy of the LGPL v 2.1 may be found at
|   http://www.gnu.org/licenses/lgpl.txt on March 4th 2007.  A copy is
|   here for your convenience.
|
|   This library is free software; you can redistribute it and/or
|   modify it under the terms of the GNU Lesser General Public
|   License as published by the Free Software Foundation; either
|   version 2.1 of the License, or (at your option) any later version.
|
|   This library is distributed in the hope that it will be useful,
|   but WITHOUT ANY WARRANTY; without even the implied warranty of
|   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
|   Lesser General Public License for more details.
|

This file has been truncated. show original

/**
 *	Give the native code a chance to start listening to the hardware
 *	or should we say give the native code control of the issue.
 *
 *	This is important for applications that flicker the Monitor
 *	thread while keeping the port open.
 *	In worst case test cases this loops once or twice every time.
 */

protected void waitForTheNativeCodeSilly()
{
	while( MonitorThreadLock )
	{
		try {
			Thread.sleep(5);
		} catch( Exception e ) {}
	}
}

This seems to indicate that locking is somehow buggy with the serial library (nrjavaserial) used by the openHAB.

Potential up stream issue initialise_event_info_struct: initialise failed! · Issue #111 · NeuronRobotics/nrjavaserial · GitHub (I guess @fwolter found this already)

@fwolter does this look familiar?

fwolter · January 7, 2021, 6:03pm

That doesn’t look familiar. But that doesn’t mean anything. Seems like we need to find the other monitor, which holds MonitorThreadLock. The blocking in waitForTheNativeCodeSilly() seems only a symptom.

Funnily enough, my Modbus binding stopped working today, too, after several weeks of flawlessly running. At first sight it looks different. threads.txt (134.6 KB) threads locks monitors.txt (143.8 KB)

zacofunny · January 8, 2021, 9:04pm

I believe that I have the same or similar issue and my MODBUS serial connection stops work almost immediately. So I can’t now control lights and sockets or read any registers from my PLC
How can I separate MODBUS logs to have full TRACE log?
I have found description for SONY binding https://community.openhab.org/t/sony-devices-binding/14052, but don’t know how to set it up for MODBUS.

JamesC · January 8, 2021, 9:11pm

The modbus stopped working again at around 01:19 this morning. Here is the threads locks monitors.txt (210.1 KB), threads.txt (198.9 KB) and openhab.log (726.2 KB).

All the modbus things remain online but havn’t updated since 01:19, about 7 hours ago. Please let me know if there is any other information you need.

fwolter · January 12, 2021, 11:36am

In the stack traces which don’t show waitForTheNativeCodeSilly() as the blocker, it blocks at nativeDrain(), which is called by flush(). I assume tcdrain() is blocking there. That calls TCSBRK via ioctl(). So, this might be a kernel/usb-driver issue.

I made a JAR which doesn’t call flush() to test if the error vanishes. It can be dropped into the addons folder. With this removal the RS485 echo mode (advanced settings) won’t work reliably anymore, probably. There might be other caveat. In my environment it works for now.

lampy · January 12, 2021, 4:45pm

Tried to use the new jar, but not sure if I did it well.
Just put the file in the addons folder where you also drop in bindings which are not yet available from within openHAB?

Did put it in there, and normally one should remove the installed binding via the UI first. But then no binding is found anymore.
After reinstalling the binding obiously it starts working again, but not sure if the new JAR is being used now?

zacofunny · January 12, 2021, 10:36pm

Me also. I’ve put it into addons and nothing happened.

fwolter · January 14, 2021, 10:59am

The JAR is a core bundle, which cannot be uninstalled via the UI. You can log into the OH console and list the bundles with bundle:list | grep -i modbus. Then, you can uninstall a specific bundle with bundle:uninstall <id>. It should be re-downloded if necessary, i.e. if you remove the patched JAR again.

My modbus binding doesn’t hang with the patches JAR anymore in nativeDrain(), but in waitForTheNativeCodeSilly(). There is a PR for nrjavaserial which allows logging via openHAB’s logging system, also in native code.

This version of nrjavaserial is now running on my RPI. I hope this gives us more information when the hang occurs again. Normally this happens over night with a specific modbus bus. Surprisingly, another modbus bus at the same RPI with the same type of RS485 adapter runs without blocking for months. The stable bus has a poll interval of 100ms. The unstable has 5 sec.

Just for the fun of it, you could try to lower the poll interval to see if that has any influence.

zacofunny · January 14, 2021, 4:24pm

So you need:

log in into the openhab console by

ssh -p 8101 openhab@localhost

default password is: habopen

uninstall original version of org.openhab.core.io.transport.modbus by command:

bundle:uninstall org.openhab.core.io.transport.modbus

exit console (CTRL+D) and stop openhab

service openhab stop

download JAR file as posted by @fwolter into Addons folder

cd /usr/share/openhab/addons
wget https://github.com/fwolter/openhab-core/releases/download/modbus-flush/org.openhab.core.io.transport.modbus-3.1.0-SNAPSHOT.jar

start openhab and wait for loading new JAR.

service openhab start

You can check the loaded version by logging into openhab console and use command as @fwolter provided

bundle:list | grep -i modbus

Cheers

lampy · January 15, 2021, 5:12pm

Today the modbus stopped after approx 12 hours of functioning, with the new JAR installed. Polling time is 1500ms, changed now to 600ms.

Below the logs, here the two other commands:threads --locks --monitors.txt (195.7 KB) threads.txt (185.7 KB)

2021-01-15 09:38:11.987 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2454.751953125 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407C39580000000000000000443C06660000000000000000445B35B40000000000000000C3E1599A00000000000000003F5B9667000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616000000000419170A445196C08) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.851 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C)))
2021-01-15 09:38:13.853 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=228.3000030517578}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 228.3000030517578 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.857 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=3.933000087738037}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 3.933000087738037 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.859 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ActivePower channels updated: {modbus:data:endpointSDM120:inputRegisters:ActivePower:number=751.5}. readValueType=float32, readIndex=Optional[12], readSubIndex(or 0)=0, extractIndex=12 -> numeric value 751.5 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.862 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ApparentPower channels updated: {}. readValueType=float32, readIndex=Optional[18], readSubIndex(or 0)=0, extractIndex=18 -> numeric value 876.2821044921875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.866 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ReactivePower channels updated: {}. readValueType=float32, readIndex=Optional[24], readSubIndex(or 0)=0, extractIndex=24 -> numeric value -450.5 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.870 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PowerFactor channels updated: {modbus:data:endpointSDM120:inputRegisters:PowerFactor:number=0.8577157855033875}. readValueType=float32, readIndex=Optional[30], readSubIndex(or 0)=0, extractIndex=30 -> numeric value 0.8577157855033875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.872 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PhaseAngle channels updated: {}. readValueType=float32, readIndex=Optional[36], readSubIndex(or 0)=0, extractIndex=36 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.876 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Frequency channels updated: {modbus:data:endpointSDM120:inputRegisters:Frequency:number=49.95000076293945}. readValueType=float32, readIndex=Optional[70], readSubIndex(or 0)=0, extractIndex=70 -> numeric value 49.95000076293945 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.879 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=72 -> numeric value 1795.04296875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.882 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=74 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.886 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=18.18000030517578}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 18.18000030517578 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:13.888 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2454.7529296875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407BB6460000000000000000443BE0000000000000000000445B120E0000000000000000C3E1400000000000000000003F5B9343000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004247CCCD44E0616000000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.756 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C)))
2021-01-15 09:38:15.759 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=228.3000030517578}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 228.3000030517578 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.764 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=3.927000045776367}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 3.927000045776367 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.768 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ActivePower channels updated: {modbus:data:endpointSDM120:inputRegisters:ActivePower:number=749.9000244140625}. readValueType=float32, readIndex=Optional[12], readSubIndex(or 0)=0, extractIndex=12 -> numeric value 749.9000244140625 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.772 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ApparentPower channels updated: {}. readValueType=float32, readIndex=Optional[18], readSubIndex(or 0)=0, extractIndex=18 -> numeric value 874.8155517578125 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.774 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ReactivePower channels updated: {}. readValueType=float32, readIndex=Optional[24], readSubIndex(or 0)=0, extractIndex=24 -> numeric value -450.29998779296875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.780 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PowerFactor channels updated: {modbus:data:endpointSDM120:inputRegisters:PowerFactor:number=0.857283890247345}. readValueType=float32, readIndex=Optional[30], readSubIndex(or 0)=0, extractIndex=30 -> numeric value 0.857283890247345 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.782 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PhaseAngle channels updated: {}. readValueType=float32, readIndex=Optional[36], readSubIndex(or 0)=0, extractIndex=36 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.786 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Frequency channels updated: {modbus:data:endpointSDM120:inputRegisters:Frequency:number=50.0}. readValueType=float32, readIndex=Optional[70], readSubIndex(or 0)=0, extractIndex=70 -> numeric value 50.0 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.788 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=72 -> numeric value 1795.0439453125 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.790 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=74 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.794 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=18.18000030517578}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 18.18000030517578 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:15.797 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2454.7529296875 and boolValue=true. Registers ModbusRegisterArray(43644CCD0000000000000000407B53F80000000000000000443B799A0000000000000000445AB4320000000000000000C3E1266600000000000000003F5B76F5000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.668 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:endpointSDM120:inputRegisters received response PollResult(result=AsyncModbusReadResult(request = ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3], registers = ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C)))
2021-01-15 09:38:17.671 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Voltage channels updated: {modbus:data:endpointSDM120:inputRegisters:Voltage:number=228.1999969482422}. readValueType=float32, readIndex=Optional[0], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 228.1999969482422 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.674 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Current channels updated: {modbus:data:endpointSDM120:inputRegisters:Current:number=3.930999994277954}. readValueType=float32, readIndex=Optional[6], readSubIndex(or 0)=0, extractIndex=6 -> numeric value 3.930999994277954 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.678 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ActivePower channels updated: {modbus:data:endpointSDM120:inputRegisters:ActivePower:number=749.7999877929688}. readValueType=float32, readIndex=Optional[12], readSubIndex(or 0)=0, extractIndex=12 -> numeric value 749.7999877929688 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.682 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ApparentPower channels updated: {}. readValueType=float32, readIndex=Optional[18], readSubIndex(or 0)=0, extractIndex=18 -> numeric value 874.3463745117188 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.687 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ReactivePower channels updated: {}. readValueType=float32, readIndex=Optional[24], readSubIndex(or 0)=0, extractIndex=24 -> numeric value -449.6000061035156 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.692 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PowerFactor channels updated: {modbus:data:endpointSDM120:inputRegisters:PowerFactor:number=0.8576387763023376}. readValueType=float32, readIndex=Optional[30], readSubIndex(or 0)=0, extractIndex=30 -> numeric value 0.8576387763023376 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.695 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:PhaseAngle channels updated: {}. readValueType=float32, readIndex=Optional[36], readSubIndex(or 0)=0, extractIndex=36 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.699 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:Frequency channels updated: {modbus:data:endpointSDM120:inputRegisters:Frequency:number=50.0}. readValueType=float32, readIndex=Optional[70], readSubIndex(or 0)=0, extractIndex=70 -> numeric value 50.0 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.702 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[72], readSubIndex(or 0)=0, extractIndex=72 -> numeric value 1795.0439453125 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.704 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportActiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[74], readSubIndex(or 0)=0, extractIndex=74 -> numeric value 0.0 and boolValue=false. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.707 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy channels updated: {modbus:data:endpointSDM120:inputRegisters:ImportReactiveEnergy:number=18.18000030517578}. readValueType=float32, readIndex=Optional[76], readSubIndex(or 0)=0, extractIndex=76 -> numeric value 18.18000030517578 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:17.711 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:endpointSDM120:inputRegisters:ExportReactiveEnergy channels updated: {}. readValueType=float32, readIndex=Optional[78], readSubIndex(or 0)=0, extractIndex=78 -> numeric value 2454.7529296875 and boolValue=true. Registers ModbusRegisterArray(436433330000000000000000407B95810000000000000000443B73330000000000000000445A962B0000000000000000C3E0CCCD00000000000000003F5B8E37000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004248000044E0616800000000419170A445196C0C) for request ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]
2021-01-15 09:38:20.716 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@6695d6[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=80,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID 0be31ef1-59d5-47b6-93d2-a39ac19bb390]

Edit: after approx 6 hours communication stopped

fwolter · January 16, 2021, 11:12am

Your binding hangs at the well-known location.

Since I added the debug messages to the serial library, my modbus didn’t stop again. Maybe you have more luck. I uploaded the JAR I test with. You need to set the log level of gnu.io to DEBUG. For example via the OH console: log:set DEBUG gnu.io The JAR can be dropped into the addons folder. To check if it is loaded correctly, execute:

openhab> bundle:list | grep nrj
242 x Resolved x  80 x 5.2.1.TEST1             x nrjavaserial

When the binding is started, something like this should appear in the logs:

2021-01-16 12:10:52.053 [DEBUG] [gnu.io.CommPortIdentifier           ] - Opened /dev/rs485-stick-upper (9600 8N1) by Modbus Serial Master

zacofunny · January 16, 2021, 12:04pm

Ok I’ve set it all app together with nrjavaserial so we will see the result soon.

openhab> list -s | grep modbus
208 x Active x  80 x 3.1.0.202101121114      x org.openhab.core.io.transport.modbus
240 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus
241 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus.e3dc
242 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus.helioseasycontrols
243 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus.stiebeleltron
244 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus.studer
245 x Active x  80 x 3.0.0                   x org.openhab.binding.modbus.sunspec
openhab> list -s | grep nrjavaserial
209 x Active x  80 x 5.2.1.TEST1             x nrjavaserial

openhab> log:get org.openhab.core.io.transport.modbus
DEBUG
openhab> log:get org.openhab.binding.modbus
DEBUG
openhab> log:get nrjavaserial
WARN
openhab> log:get gnu.io
DEBUG

Do you maybe have configuration of log4j2 in order to redirect all these logs into separate file?
I’ve tried to do it myself but nothing works.