Strange behavior with SW Timer @ oh4

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.