Strange behavior with SW Timer @ oh4

[olili]

I migrated my rule for automatic staircase lights from oh3 to oh4
In case of detected motion the following blockly script will be triggered

It’s working as expected as it already did for a couple of years with oh3,

BUT:
after some hours (6 …12h) the timer is not working any more.
The script is switching on the light and the timer is immediately switching off after less then 1sec.

Reloading the script by opening and saving it is healing this strange behavior.

There is no difference by using a shared or private timer.
I get no error failure reported in the logs.

I use 20 other scripts (without retriggerable timers) which are working fine.

Any hints? O.

[Matze0211 (Matthias)]

There is a known issue with rescheduling timers, but this issues is about that a tinder will not reschedule at all and not that a timer will run at a wrong / earlier time.

Can you add logging into the timer, so that we are 100% sure the command is not triggered by any other rule, but it’s really the timer running wrong?

Is this your full rule or only parts of it?

Maybe also share the code that’s generated by blockly.

[olili]

ok, please see the complete rule (including trigger).

configuration: {}
triggers:
  - id: "1"
    configuration:
      itemName: i_PIR_EG_Occupancy
      state: OPEN
    type: core.ItemStateUpdateTrigger
conditions:
  - inputs: {}
    id: "2"
    configuration:
      itemName: v_DayLight
      state: OFF
      operator: =
    type: core.ItemStateCondition
actions:
  - inputs: {}
    id: "3"
    configuration:
      type: application/javascript
      script: >
        items.getItem('i_SwBtn_Hallway_EG').sendCommand('ON');

        if (cache.private.exists('HallwayTimer10') === false || cache.private.get('HallwayTimer10').hasTerminated()) {
          cache.private.put('HallwayTimer10', actions.ScriptExecution.createTimer('HallwayTimer10', time.ZonedDateTime.now().plusSeconds(30), function () {
            items.getItem('i_SwBtn_Hallway_EG').sendCommand('OFF');
            cache.private.remove('HallwayTimer10');
          }));
        } else {
          cache.private.get('HallwayTimer10').reschedule(time.ZonedDateTime.now().plusSeconds(30));
        };
    type: script.ScriptAction

As I have now reloaded the script I have to wait some hours until the failure will occur.
I’ll update.

[olili]

one further hint to

“There is a known issue with rescheduling timers, but this issues is about that a tinder will not reschedule at all and not that a timer will run at a wrong / earlier time”

I read the respective thread and already tried the proposed workaround to isolate the timer to an function. Result: no change, failure still there

O.

[o.s (Oli)]

please find attached the log excerpt/file for the working state.
2 cycles: 1 trigger by PIR, 2…3 switch on (why!?), wait 30sec, switch off.

2023-09-15 12:52:04.977 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-15 12:52:10.688 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:10.698 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:10.700 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-15 12:52:10.722 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:10.750 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:10.756 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:10.762 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:10.784 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:10.790 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:10.815 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:10.820 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:19.617 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_OG' received command OFF
2023-09-15 12:52:19.621 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_OG' predicted to become OFF
2023-09-15 12:52:19.625 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_OG' changed from ON to OFF
2023-09-15 12:52:19.976 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-15 12:52:40.817 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-15 12:52:40.821 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-15 12:52:40.824 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

2023-09-15 12:52:59.578 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-15 12:52:59.584 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:59.589 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:52:59.595 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-15 12:52:59.616 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:52:59.621 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:53:14.582 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-15 12:53:50.205 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:53:50.211 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:53:50.217 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-15 12:53:50.237 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-15 12:53:50.242 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-15 12:54:05.209 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-15 12:54:20.239 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-15 12:54:20.243 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-15 12:54:20.246 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-15 12:54:22.736 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_OG' received command OFF
2023-09-15 12:54:22.741 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_OG' predicted to become OFF
2023-09-15 12:54:22.745 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_OG' changed from ON to OFF

As soon as this rule will not work anymore I post an updated log.

O

[rlkoshak (Rich Koshak)]

@olili

As I have now reloaded the script I have to wait some hours until the failure will occur.
I’ll update.

There is nothing wrong with this code. The problem lies elsewhere.

The problem @Matze0211 refers to was with the looping timer block, not the blocks you are using I think.

@o.s

please find attached the log excerpt/file for the working state.

Did you change accounts or something? This post looks like it’s coming from a different user.

@o.s

As soon as this rule will not work anymore I post an updated log.

Given this really isn’t a Blockly problem directly, to solve this I might need you to convert this to a JS Scripting script so we can add some logging statements for further investigations.

[Matze0211 (Matthias)]

Within a few milliseconds you send multiple commands for ON.

This looks like you have another rule running, that is triggered … maybe check your other rules if there is a dependency

[olili]

grrr.
I loggedin from another PC so I changed the github account, unattended. Sorry.

JS is no problem, any hint where to add the logs?

       items.getItem('i_SwBtn_Hallway_EG').sendCommand('ON');

        if (cache.private.exists('HallwayTimer10') === false || cache.private.get('HallwayTimer10').hasTerminated()) {
          cache.private.put('HallwayTimer10', actions.ScriptExecution.createTimer('HallwayTimer10', time.ZonedDateTime.now().plusSeconds(30), function () {
            items.getItem('i_SwBtn_Hallway_EG').sendCommand('OFF');
            cache.private.remove('HallwayTimer10');
          }));
        } else {
          cache.private.get('HallwayTimer10').reschedule(time.ZonedDateTime.now().plusSeconds(30));
        };

[rlkoshak (Rich Koshak)]

       items.getItem('i_SwBtn_Hallway_EG').sendCommand('ON');
       console.log("Commanded item");
        if (cache.private.exists('HallwayTimer10') === false || cache.private.get('HallwayTimer10').hasTerminated()) {
          console.log("Creating timer");
          cache.private.put('HallwayTimer10', actions.ScriptExecution.createTimer('HallwayTimer10', time.ZonedDateTime.now().plusSeconds(30), function () {
            console.log("In timer, turning off the light");
            items.getItem('i_SwBtn_Hallway_EG').sendCommand('OFF');
            cache.private.remove('HallwayTimer10');
          }));
        } else {
          console.log('Rescheduling the timer");
          cache.private.get('HallwayTimer10').reschedule(time.ZonedDateTime.now().plusSeconds(30));
        };

Something like that. You want to trace all the logic in the rule.

[olili]

This morning 10h were over and the 30sec-timer is not working correctly anymore - imeditate switch-off:

2023-09-16 04:20:26.240 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-16 04:20:26.245 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 04:20:26.249 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 04:20:26.253 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-16 04:20:26.283 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 04:20:26.286 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 04:20:26.406 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-16 04:20:26.410 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-16 04:20:26.413 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-16 04:20:26.515 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON

2023-09-16 04:20:41.251 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-16 04:20:26.283 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 04:20:26.286 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 04:20:26.406 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-16 04:20:26.410 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-16 04:20:26.413 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-16 04:20:26.515 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-16 04:20:27.550 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

After reloading the script it is working correcly again:

2023-09-16 05:05:09.711 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-16 05:05:09.715 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-16 05:05:10.251 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-16 05:05:10.270 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 05:05:10.297 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 05:05:10.306 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 05:05:10.312 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-16 05:05:10.316 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 05:05:25.203 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-16 05:05:40.307 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-16 05:05:40.310 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-16 05:05:40.315 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

I also checked my rules: there is no other rule that is ascessing the switch.

Additionally I found out that sending a command to the switch will cause 2 mqtt commands.
Zigbee2mqtt logs this

Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/PIR_EG', payload '{"battery":97,"device_temperature":30,"illuminance":0,"illuminance_lux":0,"linkquality":87,"occupancy":true,"power_outage_count":20,"voltage":2995}'
Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/PIR_EG', payload '{"battery":97,"device_temperature":30,"illuminance":0,"illuminance_lux":0,"linkquality":91,"occupancy":true,"power_outage_count":20,"voltage":2995}'
Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":47,"state":"ON"}'
Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":47,"state":"ON"}'
Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":36,"state":"ON"}'
Info 2023-09-16 04:28:16MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":32,"state":"ON"}'
Info 2023-09-16 04:28:17MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":32,"state":"OFF"}'
Info 2023-09-16 04:28:17MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":32,"state":"OFF"}'
Info 2023-09-16 04:28:31MQTT publish: topic 'zigbee2mqtt/PIR_EG', payload '{"battery":97,"device_temperature":30,"illuminance":0,"illuminance_lux":0,"linkquality":91,"occupancy":false,"power_outage_count":20,"voltage":2995}'

The respective thing definiton is like tihs

  - id: SwBtn_Hallway_EG
    channelTypeUID: mqtt:switch
    label: SwBtn Hallway EG Channel
    description: null
    configuration:
      commandTopic: zigbee2mqtt/SwBtn_EG/set
      stateTopic: zigbee2mqtt/SwBtn_EG
      transformationPattern: JSONPATH:$.state
      off: OFF
      on: ON

This is at least explainingg the higher amount of commands and state changes.
I checked it with my oh3 setup. The double mqqt commands are there as well.
But no issue with timer.

The next step I will do the instrumentation of the code as Rrlkoshak proposed.

Any further idea?

O.

[olili]

intstrumentation avtive now:

2023-09-16 05:47:28.804 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-16 05:47:28.815 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 05:47:28.825 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 05:47:28.832 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-16 05:47:28.852 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-16 05:47:28.862 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-16 05:47:43.819 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-16 05:47:58.862 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-16 05:47:58.865 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-16 05:47:58.869 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

2023-09-16 05:47:28.809 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-16 05:47:28.812 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer
2023-09-16 05:47:28.849 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-16 05:47:28.853 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Rescheduling the timer
2023-09-16 05:47:58.858 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light

[Matze0211 (Matthias)]

There is a debounce option in z2m for cases when a device sends multiple messages for the same event. as your pir sensor sends multiple messages, your rule is running multiple times and you issue multiple ON commands.

Also for sending the command, as per my knowledge, the commandtopic within the thing should be

zigbee2mqtt/SwBtn_EG/set/state

Maybe z2m is still accepting this without “state”, not sure if this will cause any issues

[olili]

I’ll try.
But I think the timer behavior is not a matter of the zigbee-communication.

But nevertheless, thing description reworked:

  - id: SwBtn_Hallway_EG
    channelTypeUID: mqtt:switch
    label: SwBtn Hallway EG Channel
    description: null
    configuration:
      commandTopic: zigbee2mqtt/SwBtn_EG/set
      formatBeforePublish: '{ "state" : "%s" }'
      stateTopic: zigbee2mqtt/SwBtn_EG
      transformationPattern: JSONPATH:$.state
      off: OFF
      on: ON

The set command is still sent 2 times even by manual switching on the oh4 gui:

Info 2023-09-16 11:06:56MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":43,"state":"ON"}'
Info 2023-09-16 11:06:56MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":43,"state":"ON"}'
Info 2023-09-16 11:06:57MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":47,"state":"OFF"}'
Info 2023-09-16 11:06:57MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":47,"state":"OFF"}'

[Matze0211 (Matthias)]

The log for mqtt is not from openhab, but directly listening to the mqtt server or?

Try to subscribe “zigbee2mqtt/SwBtn_EG/set” to test if OH is really sending 2 messages, or if your device is sending duplicated messages as a respond to your command

[olili]

as writen - I still see 2 messages. Independent from my timer issue.
This script or switching by GUI

delivers in z2m log file

Info 2023-09-16 21:15:13MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":54,"state":"ON"}'
Info 2023-09-16 21:15:13MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":54,"state":"ON"}'
Info 2023-09-16 21:15:14MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":58,"state":"OFF"}'
Info 2023-09-16 21:15:14MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":58,"state":"OFF"}'

Looking to mqtt-explorer shows me the same, also doubled commands. 

I see this behavious with almost all my switches. 

O.

[Matze0211 (Matthias)]

OH is publishing a message to channel “zigbee2mqtt/SwBtn_EG/set”, but your log shows “zigbee2mqtt/SwBtn_EG”. It’s about the same device, but two different topics.

My understanding is the following:

1. OH sends a command via mqtt to the device
2. The device will acknowledge the command with a reporting current status

You still do not know if A) you are sending two commands and therefore you receive two confirmation message or B) you are sending one command, but your device is confirming this twice

Therefore suggesting that you look for both zigbee2mqtt/SwBtn_EG/set and zigbee2mqtt/SwBtn_EG mqtt topics

[olili]

Matze0211, you are perfectly right.
I wrongly assessed the acknowledge of the switches. These are sent for almost most of my switches 2 times.

oh4 “send command” is correctly sending it only once.

Debug 2023-09-17 08:14:13Received MQTT message on 'zigbee2mqtt/SwBtn_EG/set' with data '{ "state" : "ON" }'
Debug 2023-09-17 08:14:13Publishing 'set' 'state' to 'SwBtn_EG'
Debug 2023-09-17 08:14:13Received Zigbee message from 'SwBtn_EG', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
Info 2023-09-17 08:14:14MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":72,"state":"ON"}'
Info 2023-09-17 08:14:14MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":72,"state":"ON"}'
Debug 2023-09-17 08:14:14Received MQTT message on 'zigbee2mqtt/SwBtn_EG/set' with data '{ "state" : "OFF" }'
Debug 2023-09-17 08:14:14Publishing 'set' 'state' to 'SwBtn_EG'
Debug 2023-09-17 08:14:14Received Zigbee message from 'SwBtn_EG', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Info 2023-09-17 08:14:15MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":72,"state":"OFF"}'
Info 2023-09-17 08:14:15MQTT publish: topic 'zigbee2mqtt/SwBtn_EG', payload '{"linkquality":72,"state":"OFF"}'

And you were also absolutly right with the assumption that the PIR sensor is reporting a changed state twice within a short time.

Debug 2023-09-17 08:03:27Received Zigbee message from 'PIR_EG', type 'attributeReport', cluster 'msIlluminanceMeasurement', data '{"measuredValue":15}' from endpoint 1 with groupID 0
Info 2023-09-17 08:03:27MQTT publish: topic 'zigbee2mqtt/PIR_EG', payload '{"battery":90,"device_temperature":32,"illuminance":15,"illuminance_lux":15,"linkquality":91,"occupancy":true,"power_outage_count":20,"voltage":2985}'
Debug 2023-09-17 08:03:27Received Zigbee message from 'PIR_EG', type 'attributeReport', cluster 'msOccupancySensing', data '{"occupancy":1}' from endpoint 1 with groupID 0
Info 2023-09-17 08:03:27MQTT publish: topic 'zigbee2mqtt/PIR_EG', payload '{"battery":90,"device_temperature":32,"illuminance":15,"illuminance_lux":15,"linkquality":91,"occupancy":true,"power_outage_count":20,"voltage":2985}'

That’s the reason why the rule is triggered 2 times. (as it already happened in oh3 as well) .

Now I understand the zigbee communication behavior. Thx!!!

But my timer problem is still not explained to me. See my next post.

[olili]

I’m using a debounce filter of 1sec now for the PIR reporting and instrumented the code as rikoshak proposed.

This mornig the strange behavior is back again - only 1sec instead of 30sec:

2023-09-17 08:07:41.104 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-17 08:07:41.108 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-17 08:07:41.110 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer
2023-09-17 08:07:41.111 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-17 08:07:41.118 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-17 08:07:41.122 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-17 08:07:41.243 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light
2023-09-17 08:07:41.248 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-17 08:07:41.252 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-17 08:07:41.255 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-17 08:07:41.456 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-17 08:07:41.779 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

I’m quite sure.
If I reload the script I will see the 30sec untill tonight.

Any hints?

[Matze0211 (Matthias)]

My hope was, that the wrong timer was a side effect of the duplicated messages… obviously not.

As a next step I would

1. store the

time.ZonedDateTime.now().plusSeconds(30)
Calculation into a variable

2. log now() & the result now()+30 sec from the varisble
3. schedule the timer based on the variable

By this you can verify if the time calculation is correct and the timer is running to early (= timer scheduled for 30 seconds, but already running after 1 second) or if the time calculation is wrong and the timer working correct (e.g. something with your clock not correct and +30 seconds will only add +1 second & therefore timer is “correctly” executing after 1 second)

[ubeaut (Greg)]

I have PIR and I just use the metadata expire on the switch item or virtual switch if you want to use that as well.
I have a rule that if there is movement then turn on the light with the expire metadata.
If the movement happens again before the timer expires it is reset.
Yes I know some will say that’s not what the expire is supposed to be used for but it works for me.

[SOLVED] Rules with timers or virtual/dummy switches

If you are not a programmer and just want to point and click then virtual dummy switch should work. The issue you are having with z-wave is the metadata timer is reset every time z-wave updates. To get around that problem you use a virtual switch which will not be affected by the z-wave updates. You would need a rule to turn the virtual switch on when the z-wave was set to on. The another rule to turn turn the z-wave off when the virtual switch was turned off. The metadata timer is set in th…