Hi everyone,
I recognized that all my scripts that have a time trigger run with a huge delay. But first some words about my setup:
- Windows 11
- WSL2
- Docker Desktop
- openHAB 4.2.3
OpenHAB runs within a docker container on WSL2; Host system is Windows 11.
The following script shall be executed at 6:00, but according to the logs it was executed at about 7:30
rules.JSRule({
name: "Weihnachtsbeleuchtung morgens anschalten",
triggers: [triggers.TimeOfDayTrigger("6:00"))],
execute: (event) => {
console.info(`Rule 'Weihnachtsbeleuchtung morgens anschalten' triggered at ${time.ZonedDateTime.now()}`);
items.Aussen_Hof_Steckdose.sendCommand("ON")
items.Aussen_Shelly_1PM_Carport_Steckdosen.sendCommand("ON")
items.Aussen_Shelly_1PM_Terrasse_Theke.sendCommand("ON")
}
});
At first I checked the time of the host system (correct), as well as the time within WSL2 (also correct), and within the openHAB docker contain (also correct).
To further investigate this I created multiple scripts in the following way (the first runs at 00:00, the next at 00:05, then 00:10 and so on)
for (let h = 0; h < 24; h++) {
for (let m = 0; m < 60; m += 5) {
const hour = h < 10 ? `0${h}` : `${h}`
const minute = m < 10 ? `0${m}` : `${m}`
const triggerTime = `${hour}:${minute}`
const name = `Time test ${triggerTime}`
rules.JSRule({
name: name,
triggers: [triggers.TimeOfDayTrigger(triggerTime)],
execute: () => {
console.info(`Rule ${name} triggered at ${time.ZonedDateTime.now()}.`);
}
});
}
}
This leads to the following output:
2024-12-12 09:20:08.756 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:20 triggered at 2024-12-12T09:20:00.894+01:00[SYSTEM].
2024-12-12 09:25:24.730 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:25 triggered at 2024-12-12T09:25:00.897+01:00[SYSTEM].
2024-12-12 09:30:40.912 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:30 triggered at 2024-12-12T09:30:00.898+01:00[SYSTEM].
2024-12-12 09:35:57.320 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:35 triggered at 2024-12-12T09:35:00.901+01:00[SYSTEM].
2024-12-12 09:41:13.777 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:40 triggered at 2024-12-12T09:40:00.903+01:00[SYSTEM].
2024-12-12 09:46:30.443 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:45 triggered at 2024-12-12T09:45:00.905+01:00[SYSTEM].
2024-12-12 09:51:47.318 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:50 triggered at 2024-12-12T09:50:00.907+01:00[SYSTEM].
2024-12-12 09:57:04.557 [INFO ] [.automation.script.file.time_test.js] - Rule Time test 09:55 triggered at 2024-12-12T09:55:00.907+01:00[SYSTEM].
As you can see the first trigger (at 9:20) is more or less in sync with the log time (8s delay), the delay increases with each execution. Interestingly the internal “time.ZonedDateTime.now)” also drifts away. This effect can also be seen using this script:
rules.JSRule({
name: "Timer test",
triggers: [triggers.SystemStartlevelTrigger(100)],
execute: () => {
setInterval(() => {
console.log(`Now: ${time.ZonedDateTime.now()}`)
}, 60 * 1000)
}
});
Each time the “now” gets printed it is more and more behind the timestamp in the logs:
2024-12-12 09:20:12.913 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:20:05.051+01:00[SYSTEM]
2024-12-12 09:21:12.926 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:21:01.903+01:00[SYSTEM]
2024-12-12 09:22:12.935 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:21:58.742+01:00[SYSTEM]
2024-12-12 09:23:12.936 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:22:55.572+01:00[SYSTEM]
2024-12-12 09:24:12.938 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:23:52.401+01:00[SYSTEM]
2024-12-12 09:25:13.059 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:24:49.227+01:00[SYSTEM]
2024-12-12 09:26:12.927 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:25:45.931+01:00[SYSTEM]
2024-12-12 09:27:13.097 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:26:42.769+01:00[SYSTEM]
2024-12-12 09:28:12.927 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:27:39.436+01:00[SYSTEM]
2024-12-12 09:29:13.113 [INFO ] [automation.script.file.timer_test.js] - Now: 2024-12-12T09:28:36.274+01:00[SYSTEM]
It seems like openHAB uses its own clock (used for triggering scripts and time constants) that is far behind the actual time (the timestamps in the logs look good to me).
Any ideas on this?
That’s what we are trying to figure out.