search

openhab / openhab-js

openHAB JavaScript Library for JavaScript Scripting Automation
https://www.openhab.org/addons/automation/jsscripting/
Eclipse Public License 2.0
38 stars 31 forks source link

Java.type("java.time.ZonedDateTime").now() and time.ZonedDateTime.now() getting different by 43sec #299

Closed olili closed 5 months ago

olili commented 9 months ago

see https://community.openhab.org/t/strange-behavior-with-sw-timer-oh4/149629/22

Time provided by openhab-js "time.ZonedDateTime.now()" and the regular java time Java.type("java.time.ZonedDateTime").now() are getting different after time.

Reloading the script is healing this behavior.

Expected Behavior

times are congruent

Current Behavior

Java.type("java.time.ZonedDateTime").now() is getting delayed by 43sec to Java.type("java.time.ZonedDateTime").now()

Possible Solution

sync times

Steps to Reproduce (for Bugs)

see https://community.openhab.org/t/strange-behavior-with-sw-timer-oh4/149629/22

or add following rule and watch the log file after 24h:

configuration: {}
triggers:
  - id: "1"
    configuration:
      cronExpression: 0 0 * * * ? *
    type: timer.GenericCronTrigger
conditions: []
actions:
  - inputs: {}
    id: "3"
    configuration:
      type: application/javascript
      script: >
        var JZonedDateTime = Java.type("java.time.ZonedDateTime");

        var tmp;

        var d;

        function x1_writeFile(file, data, append) { const FileWriter = Java.type('java.io.FileWriter'); try { const output = new FileWriter(file,append);
              output.write(data);
              output.close(); }
        catch (e) { console.error(e); }}

        d = new Date( JZonedDateTime.now() );

        tmp = (['Java ZonedDateTime: ', d ,' --- OH JS ZDT: ',time.ZonedDateTime.now()].join(''));

        tmp += '\r\n';

        x1_writeFile( '/tmp/SW_Timertmp.txt', tmp, 'TRUE' === 'TRUE' ); 
    type: script.ScriptAction

Logs: Java ZonedDateTime: Tue Sep 19 2023 20:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-19T20:00:00.067+02:00[SYSTEM] Java ZonedDateTime: Tue Sep 19 2023 21:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-19T21:00:00.070+02:00[SYSTEM] Java ZonedDateTime: Tue Sep 19 2023 22:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-19T22:00:00.065+02:00[SYSTEM] Java ZonedDateTime: Tue Sep 19 2023 23:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-19T23:00:00.066+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 00:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T00:00:00.068+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 01:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T01:00:00.066+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 02:00:43 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T02:00:00.066+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 03:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T02:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 04:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T03:59:16.984+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 05:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T04:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 06:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T05:59:16.984+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 07:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T06:59:16.984+02:00[SYSTEM] Update: delay of 43sec are logged per night! Java ZonedDateTime: Wed Sep 20 2023 22:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T21:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Wed Sep 20 2023 23:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T22:59:16.984+02:00[SYSTEM] Java ZonedDateTime: Thu Sep 21 2023 00:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-20T23:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Thu Sep 21 2023 01:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-21T00:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Thu Sep 21 2023 02:00:43 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-21T01:59:16.983+02:00[SYSTEM] Java ZonedDateTime: Thu Sep 21 2023 03:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-21T02:58:33.908+02:00[SYSTEM] Java ZonedDateTime: Thu Sep 21 2023 04:00:00 GMT+0200 (CEST) --- OH JS ZDT: 2023-09-21T03:58:33.910+02:00[SYSTEM]

Context

PRETTY_NAME="Debian GNU/Linux 11 (bullseye)" NAME="Debian GNU/Linux" VERSION_ID="11" VERSION="11 (bullseye)" VERSION_CODENAME=bullseye ID=debian

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"

florian-h05 commented 9 months ago

Can you please improve the issue description? It’s nice that you have linked a community thread, however the important information should still be written down in the issue.

This is also in the wrong repo …

@kaikreuzer Can you please transfer this to openhab-js?

olili commented 9 months ago

description updated

olili commented 7 months ago

problem gone with openHAB 4.0.4.

florian-h05 commented 7 months ago

Interesting, I’d say let’s close this, and in case the issue re-appears, re-open the issue (even though I have no idea how to fix that).

olili commented 7 months ago

bad news, problem is still there. I was wondering why my timers for light automation are running longer as expexted and enabled the logging rule from my first post. And the root cause seems to be as titeled:

Java.type("java.time.ZonedDateTime").now() and time.ZonedDateTime.now() getting different by 43sec per night:

Java ZonedDateTime: Mon Nov 27 2023 22:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-27T22:00:00.431+01:00[SYSTEM]
Java ZonedDateTime: Mon Nov 27 2023 23:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-27T23:00:00.432+01:00[SYSTEM]
Java ZonedDateTime: Tue Nov 28 2023 00:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T00:00:00.432+01:00[SYSTEM]
Java ZonedDateTime: Tue Nov 28 2023 01:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T01:00:00.434+01:00[SYSTEM]
Java ZonedDateTime: Tue Nov 28 2023 02:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T02:00:43.499+01:00[SYSTEM]
Java ZonedDateTime: Tue Nov 28 2023 03:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T03:00:43.497+01:00[SYSTEM]
Java ZonedDateTime: Tue Nov 28 2023 04:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T04:00:43.501+01:00[SYSTEM]
....
Java ZonedDateTime: Tue Nov 28 2023 23:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-28T23:00:43.500+01:00[SYSTEM]
Java ZonedDateTime: Wed Nov 29 2023 00:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-29T00:00:43.497+01:00[SYSTEM]
Java ZonedDateTime: Wed Nov 29 2023 01:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-29T01:00:43.498+01:00[SYSTEM]
Java ZonedDateTime: Wed Nov 29 2023 02:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-29T02:01:26.561+01:00[SYSTEM]
Java ZonedDateTime: Wed Nov 29 2023 03:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-29T03:01:26.563+01:00[SYSTEM]
Java ZonedDateTime: Wed Nov 29 2023 04:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-29T04:01:26.563+01:00[SYSTEM]
...
Java ZonedDateTime: Thu Nov 30 2023 01:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-30T01:01:26.558+01:00[SYSTEM]
Java ZonedDateTime: Thu Nov 30 2023 02:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-30T02:02:09.631+01:00[SYSTEM]
Java ZonedDateTime: Thu Nov 30 2023 03:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-30T03:02:09.632+01:00[SYSTEM]
Java ZonedDateTime: Thu Nov 30 2023 04:00:00 GMT+0100 (CET) --- OH JS ZDT: 2023-11-30T04:02:09.632+01:00[SYSTEM]
florian-h05 commented 7 months ago

Can you please share your rule code?

BTW: Please use code blocks for your logs, not the code enclosing stuff: https://docs.github.com/en/get-started/writing-on-github/working-with-advanced-formatting/creating-and-highlighting-code-blocks

olili commented 7 months ago

my rule is attached within correct "code blocks" in my intial post of this this thread.

Sorry, for using the wrong meta characters....

florian-h05 commented 6 months ago

Sorry for not seeing the rule code at the top.

I will try to reproduce this on my machine. If I can reproduce this, I guess we can't really fix it, because it is either a problem with JS-Joda and/or GraalJS, but we probably are able to work around it.

olili commented 6 months ago

issue has not gone with oh4.1 - still 43sec per night. Somebody else facing this issue as well? Any idea where it comes from?

O.

olili commented 5 months ago

I finally found the root cause and a solution.

I'm using DietPi for RaspberryPi. System clock was configured to be synced once per day at 01.17AM. During day system clock is drifting by 43sec in my case.

Running scripts/rules in OH4 are excluded from this single update of system clock (why is still not clear for me... ).

Solution: DietPI is offering also a timesync daemon that is continously adjusting system time. Enabling this feature resolved my issue.

Best regards, Oliver

florian-h05 commented 5 months ago

Hmm, okay thanks for the information.