[SOLVED] Simple timer

skaestle · March 21, 2019, 8:12pm

Platform information:
- Hardware: x86 64 Bit, 16GB, SSD
- OS: Ubuntu 18.04.2 LTS
- Java Runtime Environment: java version “1.8.0_201”
- openHAB version: 2.4

Hello everybody.
It seems I cannot get the most basic timer working, here is the code I have in my rules file (I temporarily removed everything else).

rule "Test timers"
when
    Item Test received command
then
    logInfo("timer", "hello")
    createTimer(now.plusSeconds(5)) [|
        logInfo("timer", "world")
    ]
end

Here is what I tried:

Restarting OpenHab (in addition to simply overwriting the rules file)
Spacing (as suggested by some posts)
[ | instead of [|
now.plusSeconds(5, [| … ]) instead of now.plusSeconds(5) [| ]

I trigger the rule from the shell:

openhab> smarthome:send Test ON

Here is the output:

2019-03-21 21:01:57.679 [INFO ] [eclipse.smarthome.model.script.timer] - hello
2019-03-21 21:02:48.874 [INFO ] [eclipse.smarthome.model.script.timer] - hello

No matter what I’m doing, the timer is never triggered.
I don’t see anything suspicious on the log either. I have no idea how to debug this. It appears to simply do nothing, without any indication as of why.

I also tried other, more complex triggers, where I use cancel, and define a global variable to store the timer.
I already spent hours trying to debug this, but couldn’t find any solution to the problem.

Any ideas?

cbaxter · March 21, 2019, 8:25pm

Change this to
myTimer = createTimer(now.plusSeconds(5)) [|

skaestle · March 21, 2019, 8:28pm

Nope
That didn’t work either, even when adding

 var Timer myTimer

MDAR · March 21, 2019, 8:41pm

Did you declare the variable at the top of the file?

var Timer myTimer = null

skaestle · March 21, 2019, 9:01pm

Thanks. Tried that already, also didn’t work.
This is what I have now.

var Timer myTimer = null

rule "Test timers"
when
    Item Test received command
then
    logInfo("timer", "hello")
    myTimer = createTimer(now.plusSeconds(5)) [|
        logInfo("timer", "world")
    ]
end

rlkoshak · March 21, 2019, 9:11pm

Are there any errors in the logs at all? Even if they don’t seem relevant they could be.

There is nothing apparent wrong with the lambda. I prefer to define the lambda inside the parens since it really is an argument passed to createTimer, but what you have should be fine.

I have timers like that all over the place and they work fine and I’ve seen no other reports of Timers not working, particularly with a months old version like the 2.4 release.

You only need to assign the Timer to a variable like myTimer if you want to interact with it later (e.g. cancel it). It is not required for the Timer to run.

I really don’t know what else to try to figure out why this isn’t working. You do have an alternative though with Design Pattern: Expire Binding Based Timers. But the fact that this doesn’t work is concerning.

rossko57 · March 21, 2019, 9:13pm

Particularly look for any errors about “quartz”, the timer’s engine.

skaestle · March 21, 2019, 10:20pm

Thanks!
I checked the log files. There is nothing suspicious in there. That’s the log output from around a minuter after the “hello” part of my rule got logged.

23:12:41.860 [INFO ] [.eclipse.smarthome.model.script.timer] - hello
23:12:43.529 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_noise' received command 48.014707380971316
23:12:43.530 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_noise changed from 77.63732812878308 to 48.014707380971316
23:12:43.868 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 809 to 810
23:12:46.679 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_AmbientLight changed from 2.07 to 3.14
23:12:47.379 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_Humidity' received command 33.375
23:12:47.380 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Humidity changed from 33.31 to 33.375
23:12:49.927 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 810 to 811
23:12:50.937 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'hue:0106:001788281884:11' has been updated.
23:12:50.987 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_10' received command 9.0
23:12:50.988 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_pm_10 changed from 8.0 to 9.0
23:12:50.991 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_25' received command 9.0
23:12:50.994 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_100' received command 9.0
23:13:01.329 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_Humidity' received command 33.435
23:13:01.329 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Humidity changed from 33.375 to 33.435
23:13:02.047 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 811 to 812
23:13:04.067 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 812 to 813
23:13:10.128 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 813 to 814
23:13:12.243 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 814 to 815
23:13:21.000 [INFO ] [smarthome.event.ItemStateChangedEvent] - Computer_Sensor_CPUTemp changed from 36.0 to 33.0
23:13:21.829 [INFO ] [smarthome.event.ItemStateChangedEvent] - Network_DataSent changed from 735405 to 735429
23:13:21.830 [INFO ] [smarthome.event.ItemStateChangedEvent] - Computer_CPU_Uptime changed from 24654.6 to 24655.6
23:13:25.058 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_Humidity' received command 33.535
23:13:25.059 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Humidity changed from 33.435 to 33.535
23:13:27.216 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_AmbientLight changed from 3.14 to 3.41
23:13:27.223 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Barometer changed from 977.664 to 977.651
23:13:27.886 [INFO ] [smarthome.event.ItemStateChangedEvent] - fboxWanTotalGbReceived changed from 828070968193 to 828076469062
23:13:27.887 [INFO ] [smarthome.event.ItemStateChangedEvent] - fboxWanTotalGbSent changed from 58975942816 to 58976360485
23:13:28.441 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 815 to 816
23:13:30.382 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_Humidity' received command 33.614999999999995
23:13:30.383 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Humidity changed from 33.535 to 33.614999999999995
23:13:40.562 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 816 to 817
23:13:40.988 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_10' received command 9.0
23:13:40.991 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_25' received command 10.0
23:13:40.992 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_pm_25 changed from 9.0 to 10.0
23:13:40.995 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_pm_100' received command 10.0
23:13:40.996 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_pm_100 changed from 9.0 to 10.0
23:13:43.527 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_noise' received command 52.00285609777402
23:13:43.527 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_noise changed from 48.014707380971316 to 52.00285609777402
23:13:51.001 [INFO ] [smarthome.event.ItemStateChangedEvent] - Computer_Sensor_CPUTemp changed from 33.0 to 36.0
23:13:51.059 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TF_Humidity' received command 33.695
23:13:51.060 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_Humidity changed from 33.614999999999995 to 33.695
23:13:56.723 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 817 to 818
23:13:58.742 [INFO ] [smarthome.event.ItemStateChangedEvent] - TF_CO2 changed from 818 to 819

Do I need to enable debug mode output somewhere? Or will there not be any extra information there?
Could this be related to other bindings? Would it help if I tried to disable some of them to figure out if they cause any issues?

@rlkoshak - The link you send is very useful, thank you very much! I can try to use that as a workaround. However, please let me know if there is anything else I can try to help debug the cause of the Timer issue.

@rossko57 - I do have a bunch of stack traces with quartz in the log, but they are likely older:

2019-03-21 20:56:27.244 [WARN ] [caldav.internal.job.EventReloaderJob] - Parser exception parsing ics file: b0709309-47bf-44d5-a38f-425423727602
net.fortuna.ical4j.data.ParserException: Error at line 14:Cannot set timezone for UTC properties
    at net.fortuna.ical4j.data.CalendarParserImpl.parse(CalendarParserImpl.java:143) ~[235:org.openhab.io.caldav:1.13.0]
    at net.fortuna.ical4j.data.CalendarBuilder.build(CalendarBuilder.java:198) ~[235:org.openhab.io.caldav:1.13.0]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:339) ~[235:org.openhab.io.caldav:1.13.0]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.loadEvents(EventReloaderJob.java:320) [235:org.openhab.io.caldav:1.13.0]
    at org.openhab.io.caldav.internal.job.EventReloaderJob.execute(EventReloaderJob.java:137) [235:org.openhab.io.caldav:1.13.0]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
Caused by: java.lang.UnsupportedOperationException: Cannot set timezone for UTC properties
    at net.fortuna.ical4j.model.property.UtcProperty.setTimeZone(UtcProperty.java:94) ~[?:?]
    at net.fortuna.ical4j.data.CalendarBuilder.updateTimeZone(CalendarBuilder.java:353) ~[?:?]
    at net.fortuna.ical4j.data.CalendarBuilder.access$300(CalendarBuilder.java:68) ~[?:?]
    at net.fortuna.ical4j.data.CalendarBuilder$ContentHandlerImpl.parameter(CalendarBuilder.java:278) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$ParameterParser.parse(CalendarParserImpl.java:328) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$ParameterParser.access$1700(CalendarParserImpl.java:283) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$ParameterListParser.parse(CalendarParserImpl.java:271) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.parse(CalendarParserImpl.java:208) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$PropertyParser.access$1100(CalendarParserImpl.java:190) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$PropertyListParser.parse(CalendarParserImpl.java:173) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$ComponentParser.parse(CalendarParserImpl.java:383) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$ComponentParser.access$900(CalendarParserImpl.java:367) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl$PropertyListParser.parse(CalendarParserImpl.java:171) ~[?:?]
    at net.fortuna.ical4j.data.CalendarParserImpl.parse(CalendarParserImpl.java:122) ~[?:?]
    ... 6 more

They seem to be related to the " CalDAV Binding (personal)" binding I’m using.

Note that the stacktrace I posted is the latest one I received, and it’s from a couple of hours ago, but it happened after the last restart I did.

Since I had problems with that binding before, I actually tried uninstalling it for a while, but the problem didn’t go away.

Perhaps it’s worth trying that again? Would that help?

skaestle · March 21, 2019, 10:32pm

Oh wow, I disabled that binding and restarted OpenHAB, it appears to be working now? I will check a bit more, but this looks promising.

Oh yes, even the more complex timers with cancel etc work now!

So that’s it, thanks for the tip with quartz, would never have found this without your help!

So I guess the question now is what’s wrong with the calendar binding!

rossko57 · March 22, 2019, 12:09am

Unexpectedly spiteful knock-on effect, somehow the caldav is messing with scheduling? I wonder if the timers will eventually go off in a different timezone - maybe now() has got wrong.

It’s muttering about timezone and parsing, so I’d guess its a parameter error of some kind.

skaestle · March 22, 2019, 7:20am

I printed now() as well as now().plus.... yesterday in the logs, and it seemed correct:

2019-03-21 20:41:49.460 [INFO ] [eclipse.smarthome.model.script.timer] - disabling timer: null
2019-03-21 20:41:55.515 [INFO ] [eclipse.smarthome.model.script.timer] - kitchen motion changed - now: OFF at time 2019-03-21T20:41:55.515+01:00
2019-03-21 20:41:55.516 [INFO ] [eclipse.smarthome.model.script.timer] - kitchen motion - programming timer: 2019-03-21T20:42:55.516+01:00
2019-03-21 20:41:55.517 [INFO ] [eclipse.smarthome.model.script.timer] - kitchen timer is: org.eclipse.smarthome.model.script.internal.actions.TimerImpl@16338146

+01:00 should be correct (I’m in Zurich).
The last line of output is on the timer object after createTimer.

I always assumed that the caldav errors are related to corrupt events from my calendar, but I didn’t verify that further.