Modbus binding creates lots of log entries once gateway disconnected

Add-ons Bindings
1

Hello,

I’m using the Modbus binding with a RS485-Ethernet Gateway. My problem is, once the gateway is disconnected as I don’t need the meters all time the modbus binding creates a lot of log entries.
Every 3s there are three new warnings. The strange thing is, that the Modbus TCP Bridge even stays online. I rather would expect that it goes to ERR:COMM and does not produce further log entries.

2023-11-11 21:25:54.246 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Connect reached max tries 1, throwing last error: No route to host. Connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true]. Endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]

2023-11-11 21:25:54.249 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-11 21:25:54.251 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502] -- aborting request ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=0, length=80, maxTries=3] [operation ID 0000000-0000-0000-0000-00000000f46]

@ssalonen Do you know how I can prevent this warning?
Once the bridge can not connect to the gateway there should be no repeated log entries. A new reconnect try 1 minute later would be ok, can this be configured?

2

Warning is normal, but you can filter logs the same way as other logs. Community forums here have threads about this

To change reconnection interval, try timeBetweenReconnectMillis. It is by design attempting retry forever.

The poller and data things do go offline when this happens. It’s true that tcp thing remains online

3

I changed Time Between Reconnections in UI to 10000ms, but still the log entries every 3s. I guess it it is the “m_Timeout=3000”, can I change this?

2023-11-11 21:53:05.048 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.120, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-11 21:53:08.168 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.120, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

4

I changed the Time Between Reconnections in UI to 7000ms, but it is nowhere taken over?

5

Hard to confirm the logs since you only give few lines, it does not show the repeated retrys

Do you have a poller, what is the interval with that one? Every poll will try to reconnect

6

There are always these three entries every 3 seconds. At the moment I have 4 pollers, in the future there will be 12 pollers with 3 slaves (three TCP bridges, same IP but different ID). All pollers with 3s. I think this even makes it worse. Is this too much for the Modbus binding?

2023-11-12 07:51:49.526 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Connect reached max tries 1, throwing last error: No route to host. Connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true]. Endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]

2023-11-12 07:51:49.528 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-12 07:51:49.530 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502] – aborting request ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=342, length=4, maxTries=3] [operation ID 0000000-0000-0000-0000-000000000000]

2023-11-12 07:51:52.647 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Connect reached max tries 1, throwing last error: No route to host. Connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true]. Endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]

2023-11-12 07:51:52.649 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-12 07:51:52.650 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502] – aborting request ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=0, length=80, maxTries=3] [operation ID 0000000-0000-0000-0000-000000000000]

2023-11-12 07:51:55.767 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Connect reached max tries 1, throwing last error: No route to host. Connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true]. Endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]

2023-11-12 07:51:55.768 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-12 07:51:55.770 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502] – aborting request ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=84, length=12, maxTries=3] [operation ID 0000000-0000-0000-0000-000000000000]

2023-11-12 07:51:58.886 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Connect reached max tries 1, throwing last error: No route to host. Connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true]. Endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]

2023-11-12 07:51:58.888 [WARN ] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection [m_Socket=Socket[unconnected], m_Timeout=3000, m_Connected=false, m_Address=/192.168.178.10, m_Port=502, m_ModbusTransport=null, m_ConnectTimeoutMillis=10000, rtuEncoded=true] for endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502]: No route to host

2023-11-12 07:51:58.889 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusIPSlaveEndpoint [address=192.168.178.10, port=502] – aborting request ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=342, length=4, maxTries=3] [operation ID 0000000-0000-0000-0000-000000000000]

7

Modbus binding can handle it easily, no problem. Some people here have hundred pollers, some poll data multiple times per second

8

As said you can filter out logs if that is your concern. What is the primary issue here?

9

Way to many warnings in the log. Of course I can disable them, but I would prefer them only once. Can I configure a retry after 1 minute?

10

To what logging level should I set it? I tried to set the level by navigating to Settings → Bindings → Binding Name and click the little gear icon in the upper right, but it was already set to ERROR?

11

You can for example filter all those things using log4j2.xml configuration: Log filtering in OH 3 - #3 by markus7017

Then you would be notified of connection issues via thing status updates. As said, the data and poller things should go offline when there are connection issues.

Can I configure a retry after 1 minute?

I think I might have said things a bit wrong previously. The pollers you have run every x seconds (I assume). On each poll attempt, the binding tries to re-establish the broken connection (as it should!). It is therefore natural to see frequent connection log statements with WARN level when you have connection issues.

What is the poll interval you have configured?

It’s been a while but I think “Time Between Reconnections in UI” still should do the trick. Would be easier that you share the whole thing config, and all modbus logs from 10s interval.

12

3s for every poll.

This has no effect at all. I can set whatevery I want.


UID: modbus:tcp:7ed000000
label: Modbus Zähler Slave 1
thingTypeUID: modbus:tcp
configuration:
  rtuEncoded: true
  connectMaxTries: 1
  reconnectAfterMillis: 0
  timeBetweenTransactionsMillis: 60
  port: 502
  timeBetweenReconnectMillis: 7000
  connectTimeoutMillis: 10000
  host: 192.168.178.10
  afterConnectionDelayMillis: 0
  id: 1
  enableDiscovery: false

First Modbus poller, but the other ones are identical only different start address.

UID: modbus:poller:7ed000000:10000000
label: Modbus Zähler Poll 0_80
thingTypeUID: modbus:poller
configuration:
  length: 80
  start: 0
  refresh: 3000
  maxTries: 3
  cacheMillis: 50
  type: input
bridgeUID: modbus:tcp:7ed000000

I have only three warnings every 3s shown above.

13

Ok checked the code a bit: Time Between Reconnections in UI (timeBetweenReconnectMillis) - this only has an effect when you have had at least one successful connection. I suppose that is not the case here? Enabling verbose logs confirms this…in a very verbose way.