OH4.3.2 runtime hangs/crashes up on modbus poll

Setup, Configuration and Use Runtime
1

Hi all I have here a bug, that stops OH4 from working on this CLEAN new system with minimal amount of bindings.

  • Platform information:

    • Hardware: x86 Celeron 4105/8GB ram NVME drive
    • OS: Ubuntu 24.04.1 LTS
    • Java Runtime Environment: _OpenJDK Runtime Environment (build 21.0.5+11-Ubuntu-1ubuntu124.04)
    • openHAB version: 4.3.2 but the problem also existed in 4.3.0 as I upgraded as a part of troubleshooting. Installed with OpenHabian script , pesistence is running to local influxDB v2.x

  • Issue of the topic: at some 2-3 days intervals the core system stops working and polling the items or recieving updates to the items, event log is not populating any more. I have one modbus TCP poller that is polling a TCP/RTU converter ever 5-10 seconds for some data from the solar inverter. I see that this poler sometimes times out and resets and and I do not know if that is bec
    My one suspicion is that this problem showed up after installing MQTT binding for some 5 temp sensors data pickup. The system now has only 3 bindings Modbus, MQTT and Shelly (but it was crashing before with just modbus and MQTT) Things/Items files are fairly minimal. I include them below the log.

I would greatly appreciate help in debugging this crash, do not know where to start.
Tried adding timeBetweenTransactionsMillis=200to the poller with no change it still crashed 4 days later.

openhab.log: (event log does not have an special entry)

Here is the whole tail.

2025-01-17 13:28:54.158 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33049, length=20, maxTries=3]). Will try again soon. Error was I/O error, so resetting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: EOFException null [operation ID 54cc39c9-0ad6-46ce-938d-ec75f25a0713]
2025-01-17 13:28:54.362 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33049, length=20, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37679) does not equal response (0). Slave response is invalid. [operation ID 54cc39c9-0ad6-46ce-938d-ec75f25a0713]
2025-01-17 13:28:54.574 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33049, length=20, maxTries=3]). Aborting. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37680) does not equal response (37679). Slave response is invalid. [operation ID 54cc39c9-0ad6-46ce-938d-ec75f25a0713]
2025-01-17 13:28:56.524 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33134, length=18, maxTries=3]). Will try again soon. Error was I/O error, so resetting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: EOFException null [operation ID 0b689c2d-edea-4252-9303-59786ab545a0]
2025-01-17 13:28:56.728 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33148, length=10, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37682) does not equal response (0). Slave response is invalid. [operation ID 39cf841a-438d-439d-b343-19fb3e73b0c5]
2025-01-17 13:28:56.940 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=34291, length=2, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37683) does not equal response (37682). Slave response is invalid. [operation ID 6151baac-59d5-4437-bf68-e5e7c4c6ca06]
2025-01-17 13:28:57.152 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33134, length=18, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37684) does not equal response (37683). Slave response is invalid. [operation ID 0b689c2d-edea-4252-9303-59786ab545a0]
2025-01-17 13:28:57.364 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33148, length=10, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37685) does not equal response (37684). Slave response is invalid. [operation ID 39cf841a-438d-439d-b343-19fb3e73b0c5]
2025-01-17 13:28:57.576 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=34291, length=2, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37686) does not equal response (37685). Slave response is invalid. [operation ID 6151baac-59d5-4437-bf68-e5e7c4c6ca06]
2025-01-17 13:28:57.788 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33134, length=18, maxTries=3]). Aborting. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37687) does not equal response (37686). Slave response is invalid. [operation ID 0b689c2d-edea-4252-9303-59786ab545a0]
2025-01-17 13:28:57.999 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33148, length=10, maxTries=3]). Aborting. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37688) does not equal response (37687). Slave response is invalid. [operation ID 39cf841a-438d-439d-b343-19fb3e73b0c5]
2025-01-17 13:28:58.211 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=33029, length=24, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37689) does not equal response (37688). Slave response is invalid. [operation ID bc69d585-25eb-4ee5-8a60-16b84d8f9ea1]
2025-01-17 13:28:58.423 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=34291, length=2, maxTries=3]). Aborting. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37690) does not equal response (37689). Slave response is invalid. [operation ID 6151baac-59d5-4437-bf68-e5e7c4c6ca06]
2025-01-17 13:28:58.635 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusReadRequestBlueprint [slaveId=1, functionCode=READ_INPUT_REGISTERS, start=34275, length=8, maxTries=3]). Will try again soon. The response did not match the request. Resetting the connection. Error details: org.openhab.core.io.transport.modbus.exception.ModbusUnexpectedTransactionIdException Transaction id of request (37691) does not equal response (37690). Slave response is invalid. [operation ID 6153884f-1d32-44a3-b303-d4829453ee6e]

2025-01-17 13:29:03.435 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@16a2a48b' takes more than 5000ms.
2025-01-17 13:29:08.218 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: java.util.concurrent.TimeoutException: Idle timeout expired: 10001/10000 ms
2025-01-17 13:32:21.883 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'shelly:shellyplugs:b08184a5ba7c' to inbox.
2025-01-17 13:40:23.311 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: <null>

I also have catched the crash where the events were loged in revese with the Websocket timoute first

2025-01-13 13:54:49.243 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: java.util.concurrent.TimeoutException: Idle timeout expired: 10001/10000 ms
2025-01-13 13:57:11.929 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@31694d6' takes more than 5000ms.
2025-01-13 14:06:52.559 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: <null>

Just in case here is the poller setup in the thing file :slight_smile:

Bridge modbus:tcp:remoteTCP [ host="192.168.1.199", port=502, timeBetweenTransactionsMillis=200, connectTimeoutMillis=3000 ]  {
   Bridge poller Battery1 [ start=33134, length=18, refresh=5000, type="input" ]  {
			 Thing data Battery1_Current		[ readStart="33134", readValueType="int16" ]
			 Thing data Battery1_Direction		[ readStart="33135", readValueType="uint16" ]
			 Thing data Battery1_SOC 			[ readStart="33139", readValueType="uint16" ]
			 Thing data Battery1_Voltage 		[ readStart="33141", readValueType="uint16" ]
			 Thing data Battery1_Current_BMS	[ readStart="33142", readValueType="int16" ]
   }
   
   Bridge poller Load_Total_Power [ start=33148, length=10, refresh=5000, type="input" ]  {
	         Thing data Load_Total_Power [ readStart="33148", readValueType="uint16" ]
			 Thing data Battery_Total_Power [ readStart="33149", readValueType="int32" ]
			 Thing data Grid_Total_Power [ readStart="33151", readValueType="int32" ]
   }
   
   Bridge poller PV_energy [ start=33029, length=24, refresh=5000, type="input" ]  {
	         Thing data PV_Total_energy 			[ readStart="33029", readValueType="int32" ]
			 Thing data PV_Current_Month_energy 	[ readStart="33031", readValueType="int32" ]
			 Thing data PV_Last_Month_energy		[ readStart="33033", readValueType="int32" ]
			 Thing data PV_Today_energy				[ readStart="33035", readValueType="int16" ]
			 Thing data PV_Current_Year_energy		[ readStart="33037", readValueType="int32" ]
			 Thing data PV_Last_Year_energy			[ readStart="33039", readValueType="int32" ]
			 
   }

    Bridge poller PV_data [ start=33049, length=20, refresh=5000, type="input" ]  {
	         Thing data PV_1_Voltage [ readStart="33049", readValueType="uint16" ]
			 Thing data PV_1_Current [ readStart="33050", readValueType="uint16" ]
			 Thing data PV_2_Voltage [ readStart="33051", readValueType="uint16" ]
			 Thing data PV_2_Current [ readStart="33052", readValueType="uint16" ]
	         Thing data PV_3_Voltage [ readStart="33053", readValueType="uint16" ]
			 Thing data PV_3_Current [ readStart="33054", readValueType="uint16" ]
			 Thing data PV_4_Voltage [ readStart="33055", readValueType="uint16" ]
			 Thing data PV_4_Current [ readStart="33056", readValueType="uint16" ]
			 Thing data PV_Total_Power [ readStart="33057", readValueType="uint32"]	
   }
   
       Bridge poller energy_data [ start=33161, length=40, refresh=10000, type="input" ]  {
	         Thing data Grid_Total_energy [ readStart="33169", readValueType="uint32" ]
			 Thing data Grid_Today_energy [ readStart="33171", readValueType="uint16" ]
			 Thing data Load_Total_energy [ readStart="33177", readValueType="uint32" ]
			 Thing data Load_Today_energy [ readStart="33179", readValueType="uint16" ]
	         Thing data Clean_Energy_Ratio [ readStart="33181", readValueType="uint16" ]
			
   }

   
    Bridge poller bat2_data [ start=34275, length=8, refresh=5000, type="input" ]  {
	
			 Thing data Battery2_Voltage [ readStart="34275", readValueType="uint16"  ]
	         Thing data Battery2_Current [ readStart="34276", readValueType="uint16"  ]
			 Thing data Battery2_Temp [ readStart="34277", readValueType="uint16"   ]
			 Thing data Battery2_SOC [ readStart="34278", readValueType="uint16" ]
			 

   }
   
    Bridge poller bat2_data2 [ start=34291, length=2, refresh=5000, type="input" ]  {
	
			 Thing data Battery2_Direction		[ readStart="34291", readValueType="uint16" ]
	         
   }
   
    Bridge poller energy_data2 [ start=33594, length=6, refresh=10000, type="input" ]  {
	         Thing data Load_Current_Month_energy [ readStart="33594", readValueType="uint32" ]
			 Thing data Load_Today_energy2 [ readStart="33596", readValueType="uint16" ]
	         
			
   }
   

}
2

I think you poller try to read same values.

Bridge poller Battery1 [ start=33134, length=18

Try to change length to 5 because you have 5 adresses not 18

3

I understood that length is in bytes? so for the int/uint it is 2 bytes per address and you have to account that I want to skip some registers I’m not interested in. So I read 18 bytes and select 5 2byte registers from that.

Since that is working without error most of the time I don’t think that is a reason for a crash.

4

Today it crashed with additional line in log.


2025-01-22 02:29:02.568 [WARN ] [ab.core.internal.events.EventHandler] - The queue for a subscriber of type 'class org.openhab.core.io.monitor.internal.EventLogger' exceeds 5000 elements. System may be unstable.
5

Try to change length from 18 to 9.
You read with 2 pollers same addresses
uint16 and int16 length is 1
uint32 and int32 lenght is 2

1 Like
6

This is how i see how it should work just fine.

1 Like
7

I have changed the lenght by half, as I misunderstood the logic and that did not change amount of the errors the poller generate, it restarts about every 3-6 minutes.

What I did concurrently is doubled amount of heap memory for Java as I found that to be an issue in some other thread.

I’m now on 5th day without a crash. will come back to this thread in a week or so to confirm that this is a solution.
Maciej

8

And it crashed again, so those pooler optimizations did not fix anything.

2025-01-28 02:57:12.711 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@24203be2' takes more than 5000ms.
2025-01-28 02:59:57.711 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: <null>
2025-01-28 03:06:40.484 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'shelly:shellyplugs:b08184a5ba7c' to inbox.
2025-01-28 04:03:59.446 [WARN ] [ab.core.internal.events.EventHandler] - The queue for a subscriber of type 'class org.openhab.core.io.monitor.internal.EventLogger' exceeds 5000 elements. System may be unstable.

indeed it is unstable

9

And it crashed today with similar error WebSocket error: java.util.concurrent.TimeoutException

2025-02-04 03:07:49.185 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: java.util.concurrent.TimeoutException: Idle timeout expired: 10000/10000 ms
2025-02-04 03:17:17.324 [INFO ] [b.core.io.websocket.log.LogWebSocket] - WebSocket error: <null>
2025-02-04 04:12:19.821 [WARN ] [ab.core.internal.events.EventHandler] - The queue for a subscriber of type 'class org.openhab.core.io.monitor.internal.EventLogger' exceeds 5000 elements. System may be unstable.

Anyone can put some light when how to debug that. I use Java 21 could that be a problem?