POST Item via REST API from Habpanel works unstable (not every time)

[ftc (Denis Denisov)]

Hello!
I’m struggling with a problem that updating my Item via REST API works strange. Sometimes it updates item (and sends modbus write packet to device), sometimes it is ignored.
My setup is as follows:

1. The device is ESP8266 with Modbus TCP library.
2. I’m using OpenHAB 3.2.0
3. Things config for device is as follows:

Bridge modbus:tcp:LivingRoomBigHeater [ host="192.168.0.33", port=15000, id=1 ] {
	Bridge poller H[start = 0, length = 8, type = "holding", refresh = 500] {
		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)"]
	}
}

Transforms (divide100 / multiply100) are simple JS functions which divide and multiply their numeric argument.
4. Items config is as follows:

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"}

So, i’m trying to write item LivingRoomBigHeater_TargetT (via Habpanel if that’s important). According to browser console logs, Habpanel dutifully sends POST request to OpenHAB every time i’m trying to change value. But very often the item is not updated in OpenHAB (and it seems that modbus write request is not generated. And sometimes it works as expected.

Why can this work like that? I’ve tried to think about some race conditions in the device, but it does not write to that modus registed, merely reads from it (so, register code could be only written to by modbus library in reaction to write requests).

[rlkoshak (Rich Koshak)]

@ftc

But very often the item is not updated in OpenHAB (and it seems that modbus write request is not generated. And sometimes it works as expected.

More details on this are needed and be careful with terminology. “Command” and “update” have specific meanings in OH. Do you really mean “item is not commanded” here?

What exactly do you see in events.log and is there anything relevant in openhab.log?

[ftc (Denis Denisov)]

@rlkoshak

More details on this are needed and be careful with terminology. “Command” and “update” have specific meanings in OH. Do you really mean “item is not commanded” here?

What exactly do you see in events.log and is there anything relevant in openhab.log?

Yep, it seems i’ve messed terminology a bit, sorry for that.

So, what I’m doing and what i see.
I have a Habpanel UI with slider, which is connected to the item ( LivingRoomBigHeater_TargetT to be precise).
When I change slider’s value, habpanel sends POST request to OpenHAB, something like that:

POST http://192.168.0.5:8081/rest/items/LivingRoomBigHeater_TargetT

And with value in POST data. Request always returns with code 200, so I consider it processed successfully.

Now i’ve investigated requests more carefully and see that sometimes request’s body data contains new value (e.g, i’m trying change value from 20 to 21 and body data contains 21). And sometimes old value (e.g. 20).

So now i think it is kind of race condition in habpanel itself, so maybe i should open another post.

Yes, events.log on the server contains correct information about command received from Habpanel

2023-03-06 22:18:15.787 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoomBigHeater_TargetT' received command 21
2023-03-06 22:18:15.787 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'LivingRoomBigHeater_TargetT' predicted to become 21
2023-03-06 22:18:15.787 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LivingRoomBigHeater_TargetT' changed from 20.0 to 21

[rlkoshak (Rich Koshak)]

Yes, if HABPanel is failing to send the command of course the OH server isn’t going to get it and process it. That will need specific investigation but I don’t use HABPanel so will be of limited help. It seems weird that it does that though. HABPanel hasn’t really changed in years and this hasn’t been reported before. Maybe the network is flakey?

[rpwong (Russ)]

I suspect that the issue is the slider element, which I recall being finicky in HabPanel. Try using a different element such as selection, which gives you a popup to choose the exact value you want.

[ftc (Denis Denisov)]

@rlkoshak

Yes, if HABPanel is failing to send the command of course the OH server isn’t going to get it and process it. That will need specific investigation but I don’t use HABPanel so will be of limited help. It seems weird that it does that though. HABPanel hasn’t really changed in years and this hasn’t been reported before. Maybe the network is flakey?

Well, Habpanel does send the command every time I change slider’s value, but sometimes it sends correct value (which is selected in slider) and sometimes wrong (old value, which item already has).
I suppose there is a race condition (but that’s just a guess) of such sort:

1. The item has value of 20.
2. I click on the slider to change item to 21. Habpanel begins to construct HTTP query and remembers value of 21.
3. After my click item is updated from server (because OpenHAB just read values from device) to its value of 20.
4. Habpanel takes updated value from server and substitutes it into the newly-constructed request.
5. Habpanel sends request to the server with old value.

As for network - computer with habpanel and OpenHAB server are connected via ethernet, so I don’t think that’s the case (and, btw, no any network problems occur between them).

So you say, habpanel isn’t changed in years. Does it mean it’s not actively supported and I should change my interfaces to something else?

Nevertheless, thanks for your time.

[ftc (Denis Denisov)]

A good idea, thank you.
I’ll try soon and report if that helped.

[rpwong (Russ)]

@ftc

So you say, habpanel isn’t changed in years. Does it mean it’s not actively supported and I should change my interfaces to something else?

It’s not actively supported, but it’s not going anywhere in the neat future.

@ftc

After my click item is updated from server (because OpenHAB just read values from device) to its value of 20.

This suggests to me that the issue is autoupdate, not HabPanel.

Autoupdate - a primer

I’ve found myself having to investigate and/or explain some of the features of autoupdate over time, and thought an in-depth view would be helpful. These notes apply to openHAB version 2.5 Overview Autoupdate is primarily a “speed up” feature for openHAB Items. Mostly we can ignore it, but sometimes you may get an unwanted or unexpected effect, or you may wish to exercise more control. To fully understand autoupdate, we must understand the difference between command and state of Items. If w…

[rlkoshak (Rich Koshak)]

@ftc

So you say, habpanel isn’t changed in years. Does it mean it’s not actively supported and I should change my interfaces to something else?

Like @rpwong says, the main developer of HABPanel is the main developer for MainUI so the bulk of the effort is going towards MainUI and I believe in his mind, MainUI is a replacement for HABPanel. I personally am happier with MainUI than I ever was with HABPanel.

@rpwong

This suggests to me that the issue is autoupdate, not HabPanel.

Agreed.

[ftc (Denis Denisov)]

Hello! @rlkoshak @rpwong, thanks for you help.

I’ve Tried to disable auto-update. Item commands stopped working completely, see logs:

2023-03-07 19:08:18.488 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenHeater_RelayT' changed from 53.54 to 53.51
2023-03-07 19:08:18.498 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'GarageHeater_RelayT' changed from 5.45 to 5.47
2023-03-07 19:08:18.566 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'LivingRoomBigHeater_TargetT' received command 20
2023-03-07 19:08:18.773 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LivingRoomBigHeater_RelayT' changed from 16.64 to 16.69
2023-03-07 19:08:18.805 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 't2' changed from 1.600000023841858 to 1.7000000476837158
2023-03-07 19:08:18.937 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Defrost_T' changed from 4.17 to 4.04

That’s so no matter, am i using REST API directly or moving the slider.

Frankly speaking, that completely perplexes me

[rlkoshak (Rich Koshak)]

Make sure you understand the difference between a command and an update.

A command is asking for a device to do something. Therefore commands go through the binding and out to the device. Commands are not guaranteed to create an update to the Item. If an update to the Item does occur, the update is not guaranteed to be the same as the command (e.g. sending INCREASE to a dimmer might result in an update of 75).

In an ideal world, you would want the state of the Item to always reflect the last state reported by the actual device. So the round trip would be:

command to Item -> binding -> device -> binding -> update to Item.

Autoupdate short circuits that end-to-end because not all devices report their new state in response to a command or can take too long to respond making users think the command didn’t go because the UI won’t change until the Item is updated. In that the round trip would be:

command to Item -> binding -> device -> binding -> update to Item
                |-> AutoUpdate -> update to Item

Notice that it splits into two parallel paths. That’s why Russ and I think AutoUpdate might be the cause of the behavior you describe. That can result in this sort of mixing of new and old states, especially if the device just happens to report an old state from before the command while OH is processing the command.

However, you’ve turned off AutoUpdate so one of the following is not happening:

• the binding isn’t receiving the command
• the device isn’t receiving the command
• the device isn’t reporting it’s new state
• the binding isn’t updating the Item with the new state

So I think some debug level logs from the binding will help see if it gets the command and a message back from the device or not.

[ftc (Denis Denisov)]

Thanks for the explanation, now it seems i’ve understood how that’s working under the hood.

Meanwhile, i’ve turned on debug logging on the binding and on the device and now it looks that:

1. The binding receives command. It can be confirmed by log which occurs every time i move slider in habpanel:

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

2. The device receives the command (i’ve added logging of modbus function, address and value received), logs like that:

slavePDU 6 5 2100 
slavePDU 3 0 8 

Here we see first modbus packet with function code 6 (write register), address 5 (correct) and value 2100 (which is obviously 21 * 10).
And second modbus packet with function 3 (read registers) address 0 and amount of 8. This is also correct.
Everything seems fine except… that value 21*100 is OLD value of item, not NEW.
And sometimes OpenHAB sends correct new value to device.

Now i’m beginning to think about some kind of race condition in modbus binding itself. I’ve tried to increase poll interval in the binding (from 500ms to 5s) and now command works much better (works every second try, or even 2 times from 3 tries) (with 500ms interval it worked once in ten tries or like that).

To be sure, i’ve looked at device logs and it seems that when command (and therefore, write packet to device) appears close in time to read from device (poll), command typically does not work. But when I try to make commands between poll tasks (waiting a second or two after successfull poll), it works almost every time.

So, my theory is that something goes wrong in modbus binding when item updates state during scheduling or processing write task. I’ll investigate further.

[ftc (Denis Denisov)]

And last update for today
Turned on some TRACE logging and poured over Modbus binding source code.
I’m seeing in log:

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'

Which corresponds to this part in ModbusDataThingHandler.java

 public synchronized void handleCommand(ChannelUID channelUID, Command command) {
        logger.trace("Thing {} '{}' received command '{}' to channel '{}'", getThing().getUID(), getThing().getLabel(),
                command, channelUID);

So it seems something happens not in the binding but when constructing Command for it.

Don’t really know how to debug it further, maybe there exists a way to log all item updates and commands in the openhab core?

[rpwong (Russ)]

I think you might want to start a new post so that you can describe your issue without the REST/HabPanel/Autoupdate noise. You could just change the title of this one, but people who know Modbus won’t see it as a new discussion. Also, I find that when I describe an issue a second time I often see it from new perspectives.

[rlkoshak (Rich Koshak)]

@ftc

Don’t really know how to debug it further, maybe there exists a way to log all item updates and commands in the openhab core?

The log4j2.xml file has a bunch of the event loggers configured at ERROR. Change them to INFO and you’ll see all the events in events.log. But be aware, they are not active by default for a reason. There are lots of events happening almost all the time.

[ftc (Denis Denisov)]

Seems reasonable, will do that.

[ftc (Denis Denisov)]

Oh, great. Yep, that’s understandable that there will be so many logs. Hope i’ll manage to analyze them.