Command 'OFF' isn't registered, but the item is turned off anyway

[ErikDB (Erik)]

Sorry for the double post, but maybe this is not necessarily an ESPHome binding issue, but a general ‘strange behavior’ issue.

Since yesterday, strange things happen…

This:

esphome:
  name: haard-eetkamer
[...]
switch:
  - platform: template
    name: winter_OFF
    id: winter_OFF
    turn_on_action:
      - then:
        - switch.turn_on: IN3
        - delay: 8s
        - switch.turn_off: IN3
        - switch.template.publish:
            id: winter_OFF
            state: OFF

… used to declare OFF. But now it doesn’t anymore:

openhab> log:display | grep -i haard_eetkamer_winter_OFF
21:56:13.458 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'haard_eetkamer_winter_OFF' received command ON

However! The item is turned off…:

var status = items.getItem("haard_eetkamer_winter_OFF").state
console.log("haard_eetkamer_winter_OFF = "+status)

Results in:

22:04:41.776 [INFO ] [enhab.automation.script.ui.scratchpad] - haard_eetkamer_winter_OFF = OFF

Strange, but not too harmful, you would think. However, a rule triggered by said item being turned OFF now doesn’t get triggered. Which is inconvenient

Does anyone have any idea what the cause of this strange behavior might be?

[rlkoshak (Rich Koshak)]

@ErikDB

However! The item is turned off…:

Is autoupdate enabled on this Item? That’s the default but if you’ve gone in and disabled autoupdate then the Item will not change in response to a command.

In truth, the Item never changes in response to a command. The Item only changes state in response to an update. The update will come from one of two sources:

1. the binding will post and update to the Item when the device reports that it’s changed state
2. autoupdate does it’s best to predict what state the Item should become in response to the command and posts the update accordingly. But this is just a guess and does not reflect the actual state of the device.

@ErikDB

Strange, but not too harmful, you would think. However, a rule triggered by said item being turned OFF now doesn’t get triggered. Which is inconvenient

It depends on the trigger.

• received command: will definitely trigger but it will trigger before the update to the Item is processed so MyItem.state is likely to still be in the old state
• received update: will not trigger on the command and will only trigger on an update which is a separate event from the binding or autoupdate

[ErikDB (Erik)]

Another strang non-event:

openhab> log:display | grep -i zomer
17:12:14.955 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'haard_eetkamer_zomer_ON' received command ON

openhab> log:display | grep -i relais
openhab> 

The group item didn’t change. Also, a rule that triggers when one of the members of this group changes, wasn’t triggered. (This happened until yesterday afternoon.) (This is the aforementioned rule.)

[ErikDB (Erik)]

@rlkoshak

Is autoupdate enabled on this Item? That’s the default but if you’ve gone in and disabled autoupdate then the Item will not change in response to a command.

I didn’t change anything, and it used to log the status changes. Also:

@rlkoshak

the binding will post and update to the Item when the device reports that it’s changed state

I suppose that is a more accurate wording of what I meant. But regardless, should this update not appear in the logs?

@rlkoshak

It depends on the trigger.

Also here, I didn’t change anything, and it used to work. The rule triggers when a member (of haard_eetkamer_relais_in_werking) is changed.

[rlkoshak (Rich Koshak)]

@ErikDB

But regardless, should this update not appear in the logs?

Only changes to the same state appear in the logs.

When autoupdate is enabled (note that some bingings can turn autupdate off at the time the channel is first linked to the Item) you will see the following in events.log:

• Item received command
• Autoupdate predicts new state to become
• Item changed to

The “Item changed to” event only appears in events.log if the Item actually changes state. Updates to the same state events are suppressed (though they can be enabled by changing the logging level for that event to INFO.

If you don’t see the “predicted” log entry after the command, that means either you or the binding have turned that off. For technologies that support reporting changes from the device, autoupdate should be turned off and usually the binding will do so.

If you don’t see the “changed” log entry after a command that means the Item didn’t change state in response to the command. Either it was updated to the same state or it was never updated.

You can see the update events too either in the developer sidebar or by changing the openhab.event.ItemStateUpdatedEvent logger to INFO which will make them appear in events.log.

Don’t forget to check openhab.log for errors also which might cause changes or events to not occur.

[ErikDB (Erik)]

@rlkoshak

If you don’t see the “changed” log entry after a command that means the Item didn’t change state in response to the command. Either it was updated to the same state or it was never updated.

I now see what you mean… The Item gets the command (I see the switch change to ON in the UI) and it sends a command to the ESP32. But according to the logs, it never actually changes to ON, therefore it doesn’t register the later ‘change’ to OFF. Correct?

var status = items.getItem("haard_salon_winter_ON").state
console.log("haard_salon_winter_ON = "+status)

openhab> log:display | grep -i haard_salon_winter_ON
18:21:43.998 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'haard_salon_winter_ON' received command ON
18:22:30.153 [INFO ] [enhab.automation.script.ui.scratchpad] - haard_salon_winter_ON = OFF

openhab> log:display | grep -i relais
openhab>

@rlkoshak

Don’t forget to check openhab.log for errors also which might cause changes or events to not occur.

There are none…

@rlkoshak

note that some bingings can turn autupdate off at the time the channel is first linked to the Item

I’ll recreate the items, and see what that does.

[rlkoshak (Rich Koshak)]

@ErikDB

But according to the logs, it never actually changes to ON, therefore it doesn’t register the later ‘change’ to OFF. Correct?

Correct. The Item’s state was OFF all along.

The UI will toggle to OH when you click it, but that change is just local to the browser. It waits to receive an event from the server indicating that the Item changed before it will attempt to update the toggle UI element. Since the Item never changed, there was no event to cause the UI to change the UI element back to OFF so the Item remained OFF and the UI element showed it as ON.

[ErikDB (Erik)]

I recreated the thing and the items. No luck…

I also put “auto-update” on. That resulted in the item being turned ON, but not again OFF, as expected by the ESP32. So I assume the problem is with the binding somewhere.

But I didn’t change anything to the jar file, and everything worked before… I’ll start TRACE logging the binding…

[ErikDB (Erik)]

@rlkoshak

You can see the update events too either in the developer sidebar

How does that “topic filter” work exactly?

[ErikDB (Erik)]

I figured it out. Apparently, it weren’t items like haard_eetkamer_winter_OFF which changed the status of haard_eetkamer_relais_in_werking. That was only done by these items:

Switch haard_salon_IN1 "Haard salon - IN1" <switch> (haard_salon_groep, haard_salon_relais_in_werking) { channel="esphome:device:haard-salon:in1" }
Switch haard_salon_IN2 "Haard salon - IN2" <switch> (haard_salon_groep, haard_salon_relais_in_werking) { channel="esphome:device:haard-salon:in2" }
Switch haard_salon_IN3 "Haard salon - IN3" <switch> (haard_salon_groep, haard_salon_relais_in_werking) { channel="esphome:device:haard-salon:in3" }

… which were linked to this in the ESPHome yaml:

  - platform: gpio
    pin: GPIO13   #D7
    name: IN1 
    id: IN1
    inverted: true

I deleted these items, as documented in the last sentence of this post. I now recreated the items, and all is well again.

Thanks for your help once more, @rlkoshak!