Modbus Binding not working on OH3

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.

zacofunny · January 16, 2021, 11:17pm

For some reason, after restart the previously uninstalled original modules were loaded again causing conflict. Why is that?

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

splatch · January 17, 2021, 12:49am

There are few reasons for that. You might modbus/serial binding embedded as part of “boot” features or boot addons. The functionality in openHAB core works in a way which is rather simple - if you specify a modbus as an required binding it will bring it back.

Most reliable way to test “snapshots” is simply to update existing bundle with a JAR available in local filesystem or directly form repository location:

update 192 https://github.com/fwolter/openhab-core/releases/download/modbus-flush/org.openhab.core.io.transport.modbus-3.1.0-SNAPSHOT.jar

Dropping new JAR into addons will work for shipping new things and standard java code. Updating existing binding will require de installation of old module. As you probably know same way doesn’t work for extensions with native libraries. These are loaded just once and can’t be unloaded by JVM.

zacofunny · January 17, 2021, 8:49am

Works perfectly, thanks for the hint Łukasz.

fwolter · January 17, 2021, 10:49am

My serial connection stopped last night again and showed the following in the kernel log:

Jan 17 04:28:05 serial-raspi kernel: usb 1-1.1: short control message received (0 < 2)
Jan 17 04:28:05 serial-raspi kernel: usb 1-1.1: failed to receive control message: -5
Jan 17 04:28:05 serial-raspi kernel: ch341-uart ttyUSB2: failed to read modem status: -5
Jan 17 04:39:29 serial-raspi kernel: usb 1-1.1: short control message received (0 < 2)
Jan 17 04:39:29 serial-raspi kernel: usb 1-1.1: failed to receive control message: -5
Jan 17 04:39:29 serial-raspi kernel: ch341-uart ttyUSB2: failed to read modem status: -5
Jan 17 04:40:23 serial-raspi kernel: usb 1-1.1: short control message received (0 < 2)
Jan 17 04:40:23 serial-raspi kernel: usb 1-1.1: failed to receive control message: -5
Jan 17 04:40:23 serial-raspi kernel: ch341-uart ttyUSB2: failed to read modem status: -5
Jan 17 04:42:55 serial-raspi kernel: usb 1-1.1: short control message received (0 < 2)
Jan 17 04:42:55 serial-raspi kernel: usb 1-1.1: failed to receive control message: -5
Jan 17 04:42:55 serial-raspi kernel: ch341-uart ttyUSB2: failed to read modem status: -5

This seems to be a different sympthom, at least. The binding didn’t hang and continued to re-connect. But no data is transferred.

The OH log:

2021-01-17 04:23:09.390 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 1 failed when executing request (ModbusReadRequestBlueprint@903806[slaveId=12,functionCode=READ_MULTIPLE_REGISTERS,start=27,length=13,maxTries=1]). Abortin
g. 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 d91155c8-fca9-48df-8261-e16cb6d38619]
2021-01-17 04:23:09.397 [DEBUG] [gnu.io.RXTXPort                     ] - Closing port: /dev/rs485-stick-upper
2021-01-17 04:23:09.410 [DEBUG] [gnu.io.CommPortIdentifier           ] - Opened /dev/victron-mk3 (9600 8N1) by victronenergymk3:mk3:a44809e889
2021-01-17 04:23:09.470 [DEBUG] [gnu.io.RXTXPort                     ] - Closed port: /dev/rs485-stick-upper
2021-01-17 04:23:11.388 [DEBUG] [gnu.io.RXTXPort                     ] - Closing port: /dev/victron-mk3
2021-01-17 04:23:11.499 [DEBUG] [gnu.io.RXTXPort                     ] - Closed port: /dev/victron-mk3
2021-01-17 04:23:14.501 [DEBUG] [gnu.io.CommPortIdentifier           ] - Opened /dev/rs485-stick-upper (9600 8N1) by Modbus Serial Master
2021-01-17 04:23:14.509 [DEBUG] [gnu.io.RXTXPort                     ] - tcsetattr returns nonzero value!
2021-01-17 04:23:14.511 [DEBUG] [gnu.io.RXTXPort                     ] - set_port_params failed
2021-01-17 04:23:14.512 [DEBUG] [gnu.io.RXTXPort                     ] - Closing port: /dev/rs485-stick-upper
2021-01-17 04:23:14.530 [DEBUG] [gnu.io.CommPortIdentifier           ] - Opened /dev/victron-mk3 (9600 8N1) by victronenergymk3:mk3:a44809e889
2021-01-17 04:23:14.621 [DEBUG] [gnu.io.RXTXPort                     ] - Closed port: /dev/rs485-stick-upper
2021-01-17 04:23:14.625 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: Unsupported parameter. Connection SerialConnection@81af81[portName=/dev/rs485-stick-upper,port=9600 8N1]. Endpoint ModbusSerialSlaveEndpoint@
17fd87[portName=/dev/rs485-stick-upper]
2021-01-17 04:23:14.626 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: Unsupported parameter. Connection SerialConnection@81af81[portName=/dev/rs485-stick-upper,port=9600 8N1]. Endpo
int ModbusSerialSlaveEndpoint@17fd87[portName=/dev/rs485-stick-upper]
2021-01-17 04:23:14.628 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection SerialConnection@81af81[portName=/dev/rs485-stick-upper,port=9600 8N1] for endpoint ModbusSerialSlaveEndpoint@17fd87[portName=/dev/rs485
-stick-upper]: Unsupported parameter
2021-01-17 04:23:14.629 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@17fd87[portName=/dev/rs485-stick-upper] -- aborting request ModbusReadRequestBlueprint@903806[slaveId=12,fun
ctionCode=READ_MULTIPLE_REGISTERS,start=27,length=13,maxTries=1] [operation ID da326506-7de6-40f4-862e-ce4e0f1f015f]
2021-01-17 04:23:16.506 [DEBUG] [gnu.io.RXTXPort                     ] - Closing port: /dev/victron-mk3
2021-01-17 04:23:16.612 [DEBUG] [gnu.io.RXTXPort                     ] - Closed port: /dev/victron-mk3

There seems to be a delay of 5 min from the first OH error to the kernel log messages.