Strange behavior with SW Timer @ oh4

olili · September 16, 2023, 7:28pm

as writen - I still see 2 messages. Independent from my timer issue.
This script or switching by GUI
Zwischenablage01
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 · September 16, 2023, 8:22pm

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:

OH sends a command via mqtt to the device
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 · September 17, 2023, 6:27am

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 · September 17, 2023, 6:35am

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 · September 17, 2023, 7:13am

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

As a next step I would

store the

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

log now() & the result now()+30 sec from the varisble
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 · September 17, 2023, 7:46am

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.

olili · September 17, 2023, 8:03am

@ubeaut, thx- I know the expiration timer. As a Workaround a good proposal.

Nevertheless I would like to understand my problem - maybe it is not only my incapability and eventually a severe bug, eg. in memory management or garbage collection.

For that I follow the proposal for extended instrumentation:

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

After reload working as expected:

2023-09-17 10:12:33.109 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-17 10:12:33.114 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-17 10:12:33.116 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-17 10:12:33.123 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-17 10:12:33.130 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-17 10:12:33.151 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer 2023-09-17T10:12:33.140+02:00[SYSTEM] 2023-09-17T10:13:03.119+02:00[SYSTEM]
2023-09-17 10:12:47.094 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-17 10:12:47.096 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-17 10:12:47.101 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-17 10:12:47.124 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Rescheduling the timer 2023-09-17T10:13:17.098+02:00[SYSTEM]
2023-09-17 10:13:02.077 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED
2023-09-17 10:13:02.896 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_OG' changed from CLOSED to OPEN
2023-09-17 10:13:17.110 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light 2023-09-17T10:13:17.099+02:00[SYSTEM]
2023-09-17 10:13:17.116 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-17 10:13:17.120 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-17 10:13:17.125 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF

It will take now another 6…20 hours untill the failure is activated.
I’ll keep you updated

olili · September 18, 2023, 5:29am

after 15h the failure came back, see attached log.

And … the problem seems to be reasoned in a difference between date of now() and date of system. Crazy …

Any explanation?

2023-09-18 07:18:48.544 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from CLOSED to OPEN
2023-09-18 07:18:48.548 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item
2023-09-18 07:18:48.550 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command ON
2023-09-18 07:18:48.555 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become ON
2023-09-18 07:18:48.561 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-18 07:18:48.582 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer 2023-09-18T07:18:05.470+02:00[SYSTEM] 2023-09-18T07:18:35.448+02:00[SYSTEM]
2023-09-18 07:18:48.695 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light 2023-09-18T07:18:05.585+02:00[SYSTEM]
2023-09-18 07:18:48.700 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'i_SwBtn_Hallway_EG' received command OFF
2023-09-18 07:18:48.706 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'i_SwBtn_Hallway_EG' predicted to become OFF
2023-09-18 07:18:48.710 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-18 07:18:48.802 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from OFF to ON
2023-09-18 07:18:49.082 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_SwBtn_Hallway_EG' changed from ON to OFF
2023-09-18 07:19:03.539 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'i_PIR_EG_Occupancy' changed from OPEN to CLOSED

When I activated the PIR I asked for date in console: Mon Sep 18 07:18:48 CEST 2023

Matze0211 · September 18, 2023, 6:26am

What device and OS is your installation running on?
In the past there were a few topics about wrong system time, especially in devices without hw clock. Maybe have a look how this is configured in your environment.

olili · September 18, 2023, 6:57am

I’m running DietPI as OS. Details see attached.
I use exactly the same OS version on my OH3.4 setup without any problems…
System time (date) is equal to timestamps of the log entries.

PRETTY_NAME=“Debian GNU/Linux 11 (bullseye)”
NAME=“Debian GNU/Linux”
VERSION_ID=“11”
VERSION=“11 (bullseye)”
VERSION_CODENAME=bullseye
ID=debian
HOME_URL=“https://www.debian.org/”
SUPPORT_URL=“Debian -- User Support”
BUG_REPORT_URL=“https://bugs.debian.org/”
RASPI2b,
OH4.04

openjdk version “17.0.7” 2023-04-18
OpenJDK Runtime Environment Zulu17.42+19-CA (build 17.0.7+7)
OpenJDK Server VM Zulu17.42+19-CA (build 17.0.7+7, mixed mode)

EXTRA_JAVA_OPTS=“-Xms256m -Xmx678m -XX:+ExitOnOutOfMemoryError”

rlkoshak · September 18, 2023, 4:18pm

I see that the rule is triggered, the Item is commanded ON, a Timer is created. Then the Timer goes off almost immediately.

08:07:41.110 timer is created
08:07:41.243 timer goes off

Assuming the timer that went off is the same Timer that was created, that’s not right.

One of the following is happening:

there’s an orphaned Timer still running in the background
the time calculated for the Timer is in the past somehow (please do what @Matze0211 described to see if this is the case)
there is something wrong with Timers in general (unlikely or I think more people would be experiencing this)

I’m not sure what I’m seeing here. Can you show the current rule with all these log statements. I see date times but am not sure what they are.

olili · September 18, 2023, 5:04pm

Dear rikoshak,

thx.

In my opinion the logs are also showing that the time of the javascript is behind system time.
Eg, system time 07:18:48, now() for creating timer 07:18:05.
That’s the reason that the timer is immediately terminating

Do you have an explanation for this time drift?

rlkoshak · September 18, 2023, 5:08pm

Well, the time comes from the system clock. There’s only one clock on the whole system. If your machine is behind then OH will be behind.

But it’s also all relative. If OH is behind then it’s uniformly behind. It shouldn’t impact the timers. They should still be scheduled 30 seconds into the future, based on that system clock.

Only if you system clock is jumping around somehow would this cause a problem.

olili · September 18, 2023, 5:21pm

Sorry, this I do not understand.

At the same point of time “time.ZonedDateTime.now()” and “date” (=timestamp of log) have a difference of 43sec.

If I reload JS they are in sync again.

How can this happen?

rlkoshak · September 18, 2023, 5:56pm

That’s kind of why I asked you to show the rule as it exists now.

I don’t know where those timestamps are coming from.

The logger and OH rules use the same clock so that shouldn’t be possible.

olili · September 18, 2023, 6:08pm

okay, here is the complete rule

configuration: {}
triggers:
  - id: "1"
    configuration:
      itemName: i_PIR_EG_Occupancy
      state: OPEN
    type: core.ItemStateUpdateTrigger
conditions:
  - inputs: {}
    id: "3"
    configuration:
      itemName: v_DayLight
      state: OFF
      operator: =
    type: core.ItemStateCondition
actions:
  - inputs: {}
    id: "2"
    configuration:
      type: application/javascript
      script: >-2
               items.getItem('i_SwBtn_Hallway_EG').sendCommand('ON');
               console.log("Commanded item");
                if (cache.private.exists('HallwayTimer11') === false || cache.private.get('HallwayTimer11').hasTerminated()) {
                  var eot = time.ZonedDateTime.now().plusSeconds(30);
                  console.log("Creating timer", time.ZonedDateTime.now(), eot);
                  cache.private.put('HallwayTimer11', actions.ScriptExecution.createTimer('HallwayTimer11', eot, function () {
                    console.log("In timer, turning off the light", time.ZonedDateTime.now());
                    items.getItem('i_SwBtn_Hallway_EG').sendCommand('OFF');
                    cache.private.remove('HallwayTimer11');
                  }));
                } else {
                  var eot = time.ZonedDateTime.now().plusSeconds(30);
                  console.log("Rescheduling the timer", eot);
                  cache.private.get('HallwayTimer11').reschedule(eot);
                };
    type: script.ScriptAction

rlkoshak · September 18, 2023, 6:41pm

This doesn’t make sense based on what I know.

How do the timestamps of the log statements compare to the system time?

Add the following and log out the Java time in addition to the joda-js time.

At the top of the rule:

var JZonedDateTime = Java.type("java.time.ZonedDateTime");

Then to get the time using the Java class

JZonedDateTime.now()

Where you get the timestamp and log it, also log the Java timestamp.

olili · September 19, 2023, 5:15am

done, and this morning I can show you that joda-js-time got delayed at night by 43sec against JZonedDateTime

Times are logged as followed
var eot = time.ZonedDateTime.now().plusSeconds(30);
console.log(“Creating timer”, JZonedDateTime.now(), time.ZonedDateTime.now(), eot);

2023-09-19 06:59:32.997 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item 2023-09-19T06:59:32.986799485+02:00[Europe/Berlin] 2023-09-19T06:58:49.885+02:00[SYSTEM]
2023-09-19 06:59:33.040 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer 2023-09-19T06:59:33.021763452+02:00[Europe/Berlin] 2023-09-19T06:58:49.919+02:00[SYSTEM] 2023-09-19T06:59:19.898+02:00[SYSTEM]
2023-09-19 06:59:33.155 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light 2023-09-19T06:59:33.146243941+02:00[Europe/Berlin] 2023-09-19T06:58:50.044+02:00[SYSTEM]
2023-09-19 06:59:39.058 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item 2023-09-19T06:59:39.046607386+02:00[Europe/Berlin] 2023-09-19T06:58:55.944+02:00[SYSTEM]
2023-09-19 06:59:39.089 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer 2023-09-19T06:59:39.077371579+02:00[Europe/Berlin] 2023-09-19T06:58:55.975+02:00[SYSTEM] 2023-09-19T06:59:25.958+02:00[SYSTEM]
2023-09-19 06:59:39.204 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light 2023-09-19T06:59:39.194140770+02:00[Europe/Berlin] 2023-09-19T06:58:56.093+02:00[SYSTEM]
2023-09-19 06:59:48.423 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Commanded item 2023-09-19T06:59:48.413158691+02:00[Europe/Berlin] 2023-09-19T06:59:05.310+02:00[SYSTEM]
2023-09-19 06:59:48.453 [INFO ] [nhab.automation.script.ui.bce3eb3097] - Creating timer 2023-09-19T06:59:48.443457857+02:00[Europe/Berlin] 2023-09-19T06:59:05.341+02:00[SYSTEM] 2023-09-19T06:59:35.322+02:00[SYSTEM]
2023-09-19 06:59:48.566 [INFO ] [nhab.automation.script.ui.bce3eb3097] - In timer, turning off the light 2023-09-19T06:59:48.557826841+02:00[Europe/Berlin] 2023-09-19T06:59:05.455+02:00[SYSTEM]

I think this “retarding of joda-time” happened between 2…3AM at once and not continously, because I set up an hourly js which is logging the js-time:

Java LocalDateTime: 2023-09-19T00:00:00.573 --- OH Javascript: 2023-09-19T00:00:00.580+02:00[SYSTEM]
Java LocalDateTime: 2023-09-19T01:00:00.567 --- OH Javascript: 2023-09-19T01:00:00.574+02:00[SYSTEM]
Java LocalDateTime: 2023-09-19T02:00:00.567 --- OH Javascript: 2023-09-19T02:00:00.573+02:00[SYSTEM]
Java LocalDateTime: 2023-09-19T02:59:17.465 --- OH Javascript: 2023-09-19T02:59:17.471+02:00[SYSTEM]
Java LocalDateTime: 2023-09-19T03:59:17.465 --- OH Javascript: 2023-09-19T03:59:17.470+02:00[SYSTEM]
Java LocalDateTime: 2023-09-19T04:59:17.466 --- OH Javascript: 2023-09-19T04:59:17.471+02:00[SYSTEM]

rlkoshak · September 19, 2023, 2:52pm

I have no idea how joda-js gets it’s time. All I can recommend is what you’ve already done in filing the issue.

In the mean time you can work with the java.time.ZonedDateTime classes.

system · October 31, 2023, 6:53am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.