Incorrect value used when pass Command to Modbus binding (possible race condition?)

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="", 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:

  1. When i move slider, Habpanel POSTs request to OpenHAB with selected value for the item.
  2. In openhab.log I 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=, 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

 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.

Perhaps you are facing issue with MainUI? With browser devtools you can monitor what commands UI sends out

Nope, i’m not using MainUI, i’m sending commands via Habpanel (also tried using REST API directly - got the same results).

I’ve monitored (with browser’s devtools) commands which are POSTed by habpanel to API to make sure they’re correct:


with correct (NEW) value in POST body.
That was discussed in my previous post on this issue (just omitted those here to preserve focus).

Can you produce logs which have

  1. event for the command sent to item
  2. modbus binding logging the received command

If I understand you correctly, these 2 differ and are not matchinh?

Yep, sure, will generate them a bit later.

For now what i see:

  1. REST API posts correct value (e.g. 19).
  2. Modbus binding when logging command logs old item’s value (e.g. 20).

So what is posting the 20 command in the first place? Are you having some rules or other scripts running?

Well, my bad. I’ve added more logging and discovered, that in “buggy” case it’s the habpanel who sends wrong value in request to server.

Added more logging to browser console and it seems that something is going wrong in the slider itself, i suppose something like that:

  1. Slider’s value (as well as item’s value) is 20.
  2. I click on point “19” on the slider.
  3. Before onEnd event is raised (where request is sent to the server), the updateValue function is called (because slider just received from server item’s value of 20)
  4. Slider is updated to “20” despite my click.
  5. Server gets “20” in POST data.

I’ve tried to change slider to knob and it works normally. Justifying by source code that’s because knob receives it’s final value in onEnd, but slider doesn’t.

1 Like