Timer does not execute

I’am trying to use a timer to set an item state delayed, but the code never gets executed. Here is my code:

var Timer rollershutterTimer = null
....
logError("Test1", "Test1")
rollershutterTimer = createTimerWithArgument(now.plusMinutes(5), rollershutterPosition,
[ x |
    logError("Test2", "Test2")
    ROLLERSHUTTER.sendCommand(x as int)
    rollershutterTimer = null
])

In the log I can see that “Test1” is logged, but “Test2” isn’t. What am I doing wrong?

Is the command executed ? are you just missing the log entry ?
I believe the first argument to the logError call must be different. Try “Test1” there.
I don’t recall the whole story out of the top of my head, but IIRC, you need to define logging channels via logback.xml and where to log them. There’s no default where your channel “Test2” can be put. As Test1 works, you likely have made an entry for that already.

The command is not executed and the logging should work. I have a lot of logs in my rules and work without adding them to the logback file. They appear as script.Test1 in the log, so this should not be the problem.

I’ve now added the following line to debug the job creation in OpenHAB:
<logger name=“org.openhab.model.script.action.ScriptExecution” level=“DEBUG” />
But this config doesn’t seam to work because nothing is logged. (Job creation should be logged: https://github.com/openhab/openhab/blob/0ca751504d050b1059988f47280dc89e832e3e54/bundles/model/org.openhab.model.script/src/org/openhab/model/script/actions/ScriptExecution.java)

What could be the problem here?

Some ideas
move the command in front of the logError (to find out if the timer code is executed).
Display current time/copy it to a variable (I’ve once seen this where “now” did not point to “now”.)
To get a log entry, you need to debug “… .rules”:
<logger name="org.openhab.model.script.rules" level="DEBUG" />
That won’t be as good as a debugger, but it’ll give you a hint about the line where processing stops.

I’ve added the logger to my config and I’ve also logged the exection time that is generated by now.plusMinutes(5) and that is e.g. 2016-01-07T17:45:34.109+01:00. The timer in this example was created at 17.40, so everything seams ok, but no logs on 17:45. I’ve already tried to set the command without logging, but that also doesn’t work.

Some time ago I’ve edited the quartz.properties and set the org.quartz.threadPool.threadCount = 10. Could this cause this problem? (I’am also using the caldav plugin that is using quartz to execute events)

I now also added trace logging for Quartz: <logger name=“org.quartz.core” level=“TRACE” />

After that I found the following log entry:

2016-01-08 15:24:00.282 [DEBUG] [org.quartz.core.JobRunShell   ] - Calling execute on job DEFAULT.2016-01-08T15:24:00.232+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure1: org.eclipse.xtext.xbase.impl.XClosureImplCustom@16630f (explicitSyntax: true)

It seams that Quartz is triggering the job, but then nothing happens. No log out of the job and no item commands are sent.

There used to be a thread concurrency problem in versions before 1.7.0, but I assume you’re using recent software?
I wouldn’t mess with quartz.properties, but then again, I never had a need to.

Oh, and just a silly question: you don’t use the timer variable elsewhere, so it cannot happen that some other rule kills the running timer ?

I’am using OpenHAB 1.7.0. I use the variable elsewhere, but there I also write a log and I didn’t found this log entry in my log, but I will create a Test rule with a different Timer to be sure nothing stops the timer.

Try creating a timer without an argument. I’ve never used that action but I’ve never had issue creating a timer without arguments. By default the Timer gets the full context (i.e. variables) that exist when it was created so if your “rollershutterPosition” variable is defined the Timer will have access to it.

rollershutterTimer = createTimer(now.plusMinutes(5), [|
    logError("Test2", "Test2")
    ROLLERSHUTTER.sendCommand(rollershutterPosition as int)
    rollershutterTimer = null
])

I’ve now changed my timer to a timer without parameters and I convert my rollershutter var to a val so I can use it in the timer. This solution seams to work, but logging is still not possible inside the timer.

That is very odd. I don’t have a timer where I don’t log, Though I think I mainly use logInfo. But that shouldn’t make a difference.

Also, you shouldn’t have to make a variable a val to use it in a timer. Is your createTimer inside another lambda such as a forEach? That would explain why you need to use val and can’t log.

When I try to use a var variable inside my timer I get the following error in openHAB Designer: Cannot refer to a non-final variable test from within a closure

My test timer is now executing, but I don’t find the log entry in my log:

rule "Test timer"
when
    Item SW_Test changed
then
	var DateTime executionDateTime = now.plusSeconds(5)
	val test = 90
	logError("Test timer", String::format("executionDateTime: %s", executionDateTime))
	var Timer testTimer = createTimer(executionDateTime, 
	[|
		logError("Test timer executed", String::format("Parameter: %", test))
	])
end

Do I maybe have to declare an additional logger to get these logs? What logger namespace is used in your timer logs?

This is weird.

Here is one of my working timers. I did nothing special to get the logging statements to work:

presenceTimer = createTimer(now.plusMinutes(5), [|
    logInfo("Presence", "No one is home after five minutes")
    if(Present.state != OFF) Present.sendCommand(OFF)
])

Here is another one that I create from with a lambda and I do nothing special to pass in the argument to the lambda to the timer.

val Functions$Function5 procChange = [ GroupItem gr, String name, Map<String, Timer> timers, SwitchItem reset, Map<String, Boolean notified |
    ...
    timers.put(gr.name, createTimer(now.plusMinutes(1), [|
        if(gr.state == OFF) {
            logInfo("Network", name + " is still offline after one minute")
            ...
        }
        ...
    ])

I’m not sure why yours is showing problems. You should not have to do anything special to call logging actions.