Hello!
Sometimes when an Item receives Command (e.g. by POSTing via API), Modbus binding uses not commanded value, but current value received from device. It mostly happens when command and update occur close to each other in time. Could it be a kind of race condition and what can i do to fix it?
So, details and what is known so far:
I’ve set up a testing device (which is an ESP8266 with Modbus library) and patched the library to output all received modbus requests to serial port. And i’ve made things and items for it, like that:
Bridge modbus:tcp:LivingRoomBigHeater [ host="192.168.0.34", port=15000, id=1 ] {
Bridge poller H[start = 0, length = 8, type = "holding", refresh = 5000] {
Thing data LivingRoomBigHeater_Mode[readStart = "0", readValueType = "int16", writeStart="0", writeValueType="int16", writeType="holding"]
Thing data LivingRoomBigHeater_State[readStart = "1", readValueType = "int16"]
Thing data LivingRoomBigHeater_RelayT[readStart = "2", readValueType = "int16", readTransform="JS(divide100.js)"]
Thing data LivingRoomBigHeater_Overheat[readStart = "3", readValueType = "int16"]
Thing data LivingRoomBigHeater_OverrideState[readStart = "4", readValueType = "int16", writeStart="4", writeValueType="int16", writeType="holding"]
Thing data LivingRoomBigHeater_TargetT[readStart = "5", readValueType = "int16", readTransform="JS(divide100.js)", writeStart="5", writeValueType="int16", writeType="holding", writeTransform="JS(multiply100.js)"]
Thing data LivingRoomBigHeater_InternalT[readStart = "6", readValueType = "int16", readTransform="JS(divide100.js)"]
Thing data LivingRoomBigHeater_ExternalT[readStart = "7", readValueType = "int16", readTransform="JS(divide100.js)"]
}
}
Number LivingRoomBigHeater_Mode "LivingRoomBigHeater mode" <switch> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_Mode:number"}
Switch LivingRoomBigHeater_State "LivingRoomBigHeater state" <switch> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_State:switch"}
Number LivingRoomBigHeater_RelayT "LivingRoomBigHeater relay temperature [%.1f °C]" <temperature> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_RelayT:number"}
Number LivingRoomBigHeater_Overheat "LivingRoomBigHeater relay overheated" <switch> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_Overheat:number"}
Switch LivingRoomBigHeater_OverrideState "LivingRoomBigHeater override state" <switch> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_OverrideState:switch"}
Number LivingRoomBigHeater_TargetT "LivingRoomBigHeater desired temperature [%.1f °C]" <temperature> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_TargetT:number"}
Number LivingRoomBigHeater_InternalT "LivingRoomBigHeater internal temperature [%.1f °C]" <temperature> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_InternalT:number"}
Number LivingRoomBigHeater_ExternalT "LivingRoomBigHeater external temperature [%.1f °C]" <temperature> {channel="modbus:data:LivingRoomBigHeater:H:LivingRoomBigHeater_ExternalT:number"}
Also, i’ve made a simple panel in Habpanel with a slider connected to LivingRoomBigHeater_TargetT (to make sending test requests simpler). And i’ve enabled debug logs for modbus binding.
So, what we see:
- When i move slider, Habpanel POSTs request to OpenHAB with selected value for the item.
- In
openhab.logI can see
2023-03-07 22:09:56.809 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask [endpoint=ModbusIPSlaveEndpoint [address=192.168.0.34, port=15000], request=ModbusWriteRegisterRequestBlueprint [slaveId=1, reference=5, registers=ModbusRegisterArray(0834), maxTries=3, getFunctionCode()=WRITE_SINGLE_REGISTER], resultCallback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler$Lambda$1283/0x00000007c1442c40@21c6a37b, failureCallback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler$Lambda$1284/0x00000007c1440840@79664e17], waited in thread pool for 0
And also i see logs like that in device’s serial port:
slavePDU 6 5 2100
slavePDU 3 0 8
Which confirms that device really receives modbus function 6 request (to write single register).
3. And here are differences:
a) When i move slider just before or after device receiving slavePDU 3 0 8 (read registers), device receives for writing not value from slider (NEW value), but value that Item already have (OLD value).
b) When i wait a second or two after successful read (justifying by device’s logs), write request contains NEW value (as expected).
4. I’ve tried to enable TRACE logs for modbus binding to see, what it receives from core and see something like that:
2023-03-07 23:05:57.595 [TRACE] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:TestHeater:H:TestHeater_TargetT 'Modbus Data' received command '22' to channel 'modbus:data:TestHeater:H:TestHeater_TargetT:number'
Here 22 is OLD value.
According to binding’s source this log is produced at ModbusDataThingHandler.java:
public synchronized void handleCommand(ChannelUID channelUID, Command command) {
logger.trace("Thing {} '{}' received command '{}' to channel '{}'", getThing().getUID(), getThing().getLabel(),
command, channelUID);
So i’m beginning to think that some race condition occurs when constructing Command for the binding.
Could anyone help with debugging it further?
Thanks in advance.