Modbus Binding not working on OH3

[Kamil_Matuszczak]

Any luck with it?
At mine OH3 I get in logs after few hours of working:

2021-02-01 15:50:16.383 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0]. Error was: java.lang.InterruptedException null
2021-02-01 15:50:16.399 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@1d6c207[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=72,length=2,maxTries=3] [operation ID f4f52785-0c35-44e2-b93d-cb98bb27b5fb]
2021-02-01 15:50:16.425 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0]. Error was: java.lang.InterruptedException null
2021-02-01 15:50:16.428 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@11e0765[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=30,length=2,maxTries=3] [operation ID a4354492-3c0a-40f1-a2f1-1a4a16920cb8]
2021-02-01 15:50:16.512 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0]. Error was: java.lang.InterruptedException null
2021-02-01 15:50:16.513 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@c73cbe[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=0,length=2,maxTries=3] [operation ID 24f57a1c-c5a3-4dd8-8fde-0cdae4353eca]
2021-02-01 15:50:16.563 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0]. Error was: java.lang.InterruptedException null
2021-02-01 15:50:16.564 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@8ad26c[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=6,length=2,maxTries=3] [operation ID 88908998-404c-4c03-9366-ed622697560f]
2021-02-01 15:50:16.745 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0]. Error was: java.lang.InterruptedException null
2021-02-01 15:50:16.758 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@148deba[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@1e162fc[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=70,length=2,maxTries=3] [operation ID a2bd69a8-e075-4db4-a6f8-5858e4d69c02]
2021-02-01 15:50:18.344 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2021-02-01 15:50:18.856 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Could not get port identifier, maybe insufficient permissions. null. Connection SerialConnection@1e8cb5c[portName=/dev/ttyUSB0,port=<null>]. Endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]
2021-02-01 15:50:18.858 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: Could not get port identifier, maybe insufficient permissions. null. Connection SerialConnection@1e8cb5c[portName=/dev/ttyUSB0,port=<null>]. Endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]
2021-02-01 15:50:18.859 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection SerialConnection@1e8cb5c[portName=/dev/ttyUSB0,port=<null>] for endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]: Could not get port identifier, maybe insufficient permissions. null
2021-02-01 15:50:18.861 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0] -- aborting request 

Then from 15:50 till 19:19 every 5 sec it gets same errors:

2021-02-01 18:52:28.185 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Could not get port identifier, maybe insufficient permissions. null. Connection SerialConnection@87e2[portName=/dev/ttyUSB0,port=<null>]. Endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]
2021-02-01 18:52:28.204 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: Could not get port identifier, maybe insufficient permissions. null. Connection SerialConnection@87e2[portName=/dev/ttyUSB0,port=<null>]. Endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]
2021-02-01 18:52:28.208 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection SerialConnection@87e2[portName=/dev/ttyUSB0,port=<null>] for endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]: Could not get port identifier, maybe insufficient permissions. null
2021-02-01 18:52:28.211 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0] -- aborting request ModbusReadRequestBlueprint@14f4517[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=30,length=2,maxTries=3] [operation ID 6ce328ea-cf35-429c-93f3-49aede90658b]
2021-02-01 18:52:28.217 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Could not get port identifier, maybe insufficient permissions. null. Connection SerialConnection@16adad8[portName=/dev/ttyUSB0,port=<null>]. Endpoint ModbusSerialSlaveEndpoint@147cbd8[portName=/dev/ttyUSB0]

And after this time Openhab restarts itself. After restart I see every few minutes WARN like this:

2021-02-01 22:02:27.880 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@c10428[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=30,length=2,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 621bfe54-b70b-492e-b483-7a1ac1200b19]
2021-02-01 22:03:06.313 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@18007fd[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=70,length=2,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 5fcdcb0d-61f0-4da9-ab6a-a4d9471f84aa]
2021-02-01 22:32:37.714 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@7e4c81[slaveId=1,functionCode=READ_INPUT_REGISTERS,start=72,length=2,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 493bb125-127d-45ff-b08f-228cc8a4c44d]

And something like this:

2021-02-02 01:45:26.767 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/3 error: connect timed out. Connection TCPMasterConnection@141adac[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:31.835 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: connect timed out. Connection TCPMasterConnection@141adac[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:36.900 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: connect timed out. Connection TCPMasterConnection@141adac[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:36.902 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: connect timed out. Connection TCPMasterConnection@141adac[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:36.903 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@141adac[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]: connect timed out
2021-02-02 01:45:36.905 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502] -- aborting request ModbusReadRequestBlueprint@dcb5a9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3] [operation ID 71238e03-e60b-409b-8bfd-cfd4fc69c96b]
2021-02-02 01:45:43.031 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@1682a20[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:43.099 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@1682a20[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:43.173 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@1682a20[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:43.174 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@1682a20[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:43.175 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@1682a20[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]: Połączenie odrzucone (Connection refused)
2021-02-02 01:45:43.176 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502] -- aborting request ModbusReadRequestBlueprint@dcb5a9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3] [operation ID 8e5f48f7-e874-420d-8a8e-5c357be063ad]
2021-02-02 01:45:48.188 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@5c5cbe[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:48.257 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@5c5cbe[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:48.326 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@5c5cbe[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:48.327 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: Połączenie odrzucone (Connection refused). Connection TCPMasterConnection@5c5cbe[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]
2021-02-02 01:45:48.328 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@5c5cbe[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502]: Połączenie odrzucone (Connection refused)
2021-02-02 01:45:48.329 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@f9e855[address=192.168.31.47,port=1502] -- aborting request ModbusReadRequestBlueprint@dcb5a9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3] [operation ID 11745924-5b59-4a57-8cd5-8cd9de3fe891]

[rossko57]

You have both serial and TCP connections?

The serial error looks a bit like the falure to recover the serial port. What binding version are you using?

The TCP error looks like external issues - network, slave offline - no response. It’s possible the slave has not yet tidied up the old connection from before the restart. Does this problem go away by itself, or do you do something?

@Kamil_Matuszczak

And after this time Openhab restarts itself.

That’s a bit alarming, sounds like out of memory issue.

[Kamil_Matuszczak]

Im on latest SNAPSHOT 3.1.0.

openhab> list -s | grep modbus
239 │ Active │  80 │ 3.1.0.202102020340      │ org.openhab.binding.modbus
240 │ Active │  80 │ 3.1.0.202102020413      │ org.openhab.binding.modbus.e3dc
241 │ Active │  80 │ 3.1.0.202102020413      │ org.openhab.binding.modbus.helioseasycontrols
242 │ Active │  80 │ 3.1.0.202102020413      │ org.openhab.binding.modbus.stiebeleltron
243 │ Active │  80 │ 3.1.0.202102020413      │ org.openhab.binding.modbus.studer
244 │ Active │  80 │ 3.1.0.202102020413      │ org.openhab.binding.modbus.sunspec
258 │ Active │  80 │ 3.1.0.202101310255      │ org.openhab.core.io.transport.modbus
openhab> list -s | grep nrjavaserial
223 │ Active │  80 │ 5.2.1.TEST1             │ nrjavaserial
openhab>      

Yes, TCP error sometime happens. That is not problem. It goes away by itself.

Problem is SERIAL conenction that disconnects after few hours of working.

Openhab restarts but there is no info in logs about out of memory…

[zacofunny (Bogumil J.)]

Yep, problem still exists. Also, in my case normally switching modbus switches works fast if triggered from openhab, but they are refreshed very slow if triggered from the other side. I’ve changed refresh parameter to 1000(ms) and this doesn’t help in anything.

Bridge modbus:serial:fatekplcusb0 "FatekPLC1" [ baud=115200, timeBetweenTransactionsMillis=60, cacheMillis=50, connectMaxTries=1, stopBits="1.0", parity="none", receiveTimeoutMillis=1500, dataBits=8, echo=false, encoding="rtu", flowContrrolIn="none", port="/dev/ttyFatekPLC1", flowControlOut="none", connectTimeoutMillis=10000, id=1 ] {
    Bridge poller markers_M1200_to_M1263 "FatekPLC_Poller_M1200_to_M1263" [ start=3200, length=64, refresh=1000, type="coil" ] {
        // Note the zero based indexing: first coil is index 0.
       Thing data FatekPLC_Modbus_M1200 "FatekPLC_Modbus_M1200" [ readStart="3200", readValueType="bit", writeStart="3200", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1201 "FatekPLC_Modbus_M1201" [ readStart="3201", readValueType="bit", writeStart="3201", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1204 "FatekPLC_Modbus_M1204" [ readStart="3204", readValueType="bit", writeStart="3204", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1205 "FatekPLC_Modbus_M1205" [ readStart="3205", readValueType="bit", writeStart="3205", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1206 "FatekPLC_Modbus_M1206" [ readStart="3206", readValueType="bit", writeStart="3206", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1207 "FatekPLC_Modbus_M1207" [ readStart="3207", readValueType="bit", writeStart="3207", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1209 "FatekPLC_Modbus_M1209" [ readStart="3209", readValueType="bit", writeStart="3209", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1210 "FatekPLC_Modbus_M1210" [ readStart="3210", readValueType="bit", writeStart="3210", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1211 "FatekPLC_Modbus_M1211" [ readStart="3211", readValueType="bit", writeStart="3211", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1212 "FatekPLC_Modbus_M1212" [ readStart="3212", readValueType="bit", writeStart="3212", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1213 "FatekPLC_Modbus_M1213" [ readStart="3213", readValueType="bit", writeStart="3213", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1214 "FatekPLC_Modbus_M1214" [ readStart="3214", readValueType="bit", writeStart="3214", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1215 "FatekPLC_Modbus_M1215" [ readStart="3215", readValueType="bit", writeStart="3215", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1216 "FatekPLC_Modbus_M1216" [ readStart="3216", readValueType="bit", writeStart="3216", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1217 "FatekPLC_Modbus_M1217" [ readStart="3217", readValueType="bit", writeStart="3217", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1218 "FatekPLC_Modbus_M1218" [ readStart="3218", readValueType="bit", writeStart="3218", writeValueType="bit", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1224 "FatekPLC_Modbus_M1224" [ readStart="3224", readValueType="bit", readTransform="JS(invertstate_read.js)", writeStart="3224", writeValueType="bit", writeTransform="JS(invertstate_write.js)", writeTransform="JS(invertstate_write.js)", writeType="coil" ]
       Thing data FatekPLC_Modbus_M1225 "FatekPLC_Modbus_M1225" [ readStart="3225", readValueType="bit", readTransform="JS(invertstate_read.js)", writeStart="3225", writeValueType="bit", writeTransform="JS(invertstate_write.js)", writeTransform="JS(invertstate_write.js)", writeType="coil" ]
    }
}

[rossko57]

@zacofunny

readStart="3200", readValueType="bit"

That’s an odd combination, whole register address instead of bit address. Surprised it works, but I suppose it defaults to 3200.0

Guessing you are linking to Switches, it might be slightly more efficient to treat whole register as “zero/non-zero” i.e. use int16. Assuming the rest of the register is predictable zeroes.

With many Items, you may want to look at data Thing setting updateUnchangedValuesEveryMillis which can have a significant performance impact on the rest of openHAB - events bus, persistence etc.

[zacofunny (Bogumil J.)]

@rossko57

updateUnchangedValuesEveryMillis

Thanks for the hint.
I thought coils are considered as “bit” type by default? The above part of my modbus config reads only coils.
Anyway it does not work if I replace “bit” to “int16”.
I’m not a Modbus expert and I was wondering if instead of reading/writing coil by coil with “bit” type, It would be possible to read i.e. 16 coils at once and then dispatch it to specific switches in openhab with rule or transform.
I’m using Fatek PLC and it has the following table of memory allocation as here http://www.esea.cz/support/fatek/doc/FBs-Manual_Web_English/FBs-Special-Relay-Register-List-EN.pdf.

[rossko57]

@zacofunny

I thought coils are considered as “bit” type by default?

Oh yes of course, misreading on my part, sorry.

@zacofunny

I was wondering if instead of reading/writing coil by coil with “bit” type, It would be possible to read i.e. 16 coils at once and then dispatch it to specific switches in openhab

There are ways, if your PLC offers a mirror of coils in a 16-bit register.
But if coils are available, use those for efficiency. You only have to set it up once.

[kreutzer_peter (kreutpet)]

hi,
I am running in to same issue with the modbus binding related to the underlying serial jar.
Using the below link ot read out data from my inverter

Reading data from Huawei inverter SUN 2000 (3KTL-10KTL) via modbus TCP and RTU

Hello, I made some configuration to read all the data from the huawei SUN 2000 inverters with the modbus binding.And i want to share it so other people can use it to. With the Huawei Smart Dongle-WLAN-FE you can connect with modbusTCP and Fusion solar app at the same time. With modbus RTU you can not connect to the Fusion solar app and with modbus RTU at the same time. To connect via TCP you need the Smart Dongle-WLAN-FE with the latest software update (SDongle_V100R001C00SPC120_package) and…

2021-04-05 12:57:54.637 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10000ms) poll task BasicPollTask@1cf7a5f9[request=ModbusReadRequestBlueprint@12305817[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32002,length=1,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@1c3a740c[portName=/dev/ttyUSB0],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@478c573f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@478c573f] finished at 1617620274637. Was started at millis: 1617620274357 (=duration of 280 millis)
2021-04-05 12:57:54.664 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10000ms) poll task BasicPollTask@66c98c8d[request=ModbusReadRequestBlueprint@572b709b[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32114,length=2,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@1c3a740c[portName=/dev/ttyUSB0],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@6abf0bb5,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@6abf0bb5]. Current millis: 1617620274664
2021-04-05 12:57:54.749 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint@6baf0db1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32008,length=1,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 CRC Error in received frame: 0 bytes:  [operation ID 473c51d8-07f7-438c-a4bd-a710851bdeee]
2021-04-05 12:57:55.196 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10000ms) poll task BasicPollTask@2ad31c77[request=ModbusReadRequestBlueprint@2414e75d[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32016,length=8,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@1c3a740c[portName=/dev/ttyUSB0],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@21b57a,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@21b57a]. Current millis: 1617620275196
2021-04-05 12:57:57.427 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-04-05 12:57:58.979 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-04-05 12:57:59.492 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10000ms) poll task BasicPollTask@37751fa1[request=ModbusReadRequestBlueprint@39b2f73f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32064,length=31,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@1c3a740c[portName=/dev/ttyUSB0],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@263fad78,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@263fad78]. Current millis: 1617620279492
2021-04-05 12:58:04.261 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10000ms) poll task BasicPollTask@31c0a566[request=ModbusReadRequestBlueprint@799dab92[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32106,length=2,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@1c3a740c[portName=/dev/ttyUSB0],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@4678b36d,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@4678b36d]. Current millis: 1617620284261

The binding reads out continuously, but stops after ‘Try 1 out of 3 failed when executing request’
Is there a solution on the horizon ? Or is it better to go back to OH2?

I am running a binding depending on openhab-transport-serial, but it runs flawlessly .
So i guess it mus be related the underlying serial library that the modbus binding is using.

[fwolter (Fabian Wolter)]

@kreutzer_peter That doesn’t look like the locking problem discussed here. It seems rather a communication problem e.g. wiring, missing terminator…

[ssalonen]

On the other hand, the fact that it does not retry (gets stuck) after IO error is related to locking issue?

But yeah, perhaps the root cause for the error to appear in the first place is bad wiring or similar…

[fwolter (Fabian Wolter)]

You might be right. I came to the conclusion because I didn’t see any Could not get port identifier, but this message is only a subsequent error when the locking issue already happened.

[ssalonen]

FYI here, I’ve introduced a possible workaround for the serial library issues in modbus binding: [modbus] Workaround for nrjavaserial issues: do not disconnect serial by ssalonen · Pull Request #2272 · openhab/openhab-core · GitHub

[kreutzer_peter (kreutpet)]

The only way to get it up and running again is to restart the complete runtime.
I have tried to restart the bundle , without any success.
So the serial interface is locked.

[kreutzer_peter (kreutpet)]

any chance to get an updated jar file , so i check is the problem disappears.
thx

[ssalonen]

@kreutzer_peter absolutely, please find the precompiled jar from the github, just added it.

[kreutzer_peter (kreutpet)]

i guess the update did not succeed completely.

list -s | grep modbus
256 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus
257 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus.e3dc
258 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus.helioseasycontrols
259 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus.stiebeleltron
260 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus.studer
261 │ Active │  80 │ 3.0.1                   │ org.openhab.binding.modbus.sunspec
263 │ Active │  80 │ 3.1.0.202104051358      │ org.openhab.core.io.transport.modbus

list -s | grep nrjavaserial
210 │ Active │  80 │ 5.2.1                   │ nrjavaserial

is it correct that on the org.openhab.core.io.transport.modbus has updated?

16:56:52.279 [WARN ] [ort.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_MULTIPLE_REGISTERS, start=32008, length=1, 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 CRC Error in received frame: 0 bytes:  [operation ID d745e46a-f4fe-455e-bd3d-7d0565a11440]              
16:56:52.282 [DEBUG] [ort.modbus.internal.ModbusManagerImpl] - Skipping invalidation of serial connection to workaround openhab-core#1842.

i see that your fix is applied but after that line the modbus conenction does not bring any new updates

[ssalonen]

Ah I see, thanks for testing! The fix needs a bit of correction, let me get you updated version

[ssalonen]

@kreutzer_peter please try again, I uploaded a new version in github.

[kreutzer_peter (kreutpet)]

many thanks.
modbus interface is much more stable and serial interface is not locked.

[zacofunny (Bogumil J.)]

I’ve introduced this workaround yesterday, so far modbus works with no locks.