OH3 Timer reschedule failed

Marcin_J · January 4, 2021, 6:37pm

Platform information:
- Java Runtime Environment: openjdk 11.0.9.1 2020-11-06 LTS
- openHAB version: openHAB 3.0.0

This code executed second time cause Warn message and not reschedule:

var Timer corridorLightsOffTimer //out of the rule definition

...

if (corridorLightsOffTimer !== null)
{
    logInfo("Light", "Corridor: timer state: " + corridorLightsOffTimer.hasTerminated + corridorLightsOffTimer.isRunning + corridorLightsOffTimer.isActive)

    corridorLightsOffTimer.reschedule(now.plusSeconds(3))
}
else
    corridorLightsOffTimer = createTimer(now.plusSeconds(3), [|
        Corridor_LightsState.sendCommand(OFF)])

2021-01-04 19:18:42.491 [INFO ] [org.openhab.core.model.script.Light ] - Corridor: timer state: truefalsefalse
2021-01-04 19:18:42.497 [WARN ] [el.script.internal.actions.TimerImpl] - Rescheduling failed as execution has already started!

Related source code:

github.com

openhab/openhab-core/blob/774b9d607b8277f809c2b2b1d94da1be9c23156d/bundles/org.openhab.core.model.script/src/org/openhab/core/model/script/internal/actions/TimerImpl.java#L55


      
              future = scheduler.schedule(runnable, startTime.toInstant());
          }
          
          @Override
          public boolean cancel() {
              cancelled = true;
              return future.cancel(true);
          }
          
          @Override
          public boolean reschedule(ZonedDateTime newTime) {
              if (future.cancel(false)) {
                  cancelled = false;
                  future = scheduler.schedule(runnable, newTime.toInstant());
                  return true;
              } else {
                  logger.warn("Rescheduling failed as execution has already started!");
                  return false;
              }
          }

Documentation says it should work:

This can also be called after a timer has terminated, which will result in another execution of the same code.

Source:

Edit: Can anyone confirm that reschedule works in OH3 (after execute its code one time)?

cirrusce · January 8, 2021, 6:23am

I’m also seeing this same warning. Here’s my code:

‘’‘rule “Forest Room Occupied OFF”
when
Item SAC_Zone9_ForestRoomMotion changed to CLOSED
then
if (tmr_ForestRoom === null) {
tmr_ForestRoom = createTimer(now.plusSeconds(60),[SAC_ForestRoom_Occupied.sendCommand(OFF)])
} else {
tmr_ForestRoom.reschedule(now.plusSeconds(60))
}
end’’’

Petrows · January 8, 2021, 8:24am

I have the same issue, yesterday rule was failed, but today it is fine.

Yesterday error:

2021-01-07 05:00:00.124 [WARN ] [org.openhab.core.model.script.light ] - Sunrise emulation started
2021-01-07 05:00:00.129 [WARN ] [org.openhab.core.model.script.light ] - Sunrise item snf_eg_fl_spiegel_brightness -> 0
2021-01-07 05:00:00.131 [WARN ] [el.script.internal.actions.TimerImpl] - Rescheduling failed as execution has already started!

github.com

petrows/smarthome-openhab/blob/master/rules/sunrise.rules#L112


            logWarn("light", "Sunrise item " + s + " -> " + setBright)
            sendCommand(s, setBright.toString())
        ]
        // All items 100% ?
        if (sunriseBrightness > (lightGroupItems.size * 100)) {
            logWarn("light", "Sunrise emulation done")
        } else {
            // New timer loop
            sunriseBrightness = sunriseBrightness + sunriseBrightPeriodStep
            sunriseTimer.reschedule(ZonedDateTime.now.plus(brightTimerMs, ChronoUnit.MILLIS))
        }
    ])
end

HomeAutomation · January 8, 2021, 1:23pm

Not sure, but in all available examples at the end of the timer loop the timer variable is set to null again.

else
    corridorLightsOffTimer = createTimer(now.plusSeconds(3), [|
        Corridor_LightsState.sendCommand(OFF)
         corridorLightsOffTimer.cancel
         corridorLightsOffTime = null
         ])

cirrusce · January 8, 2021, 3:50pm

I added the .cancel and = null lines as you show, and that appeared to work. No warning in the log any more, and the code functions as expected.

rossko57 · January 8, 2021, 4:05pm

Comment; that avoids the attempt to reschedule a timer that has already executed once (by recreating a new timer each time).
The docs still suggest it should be possible to reschedule a completed timer, but I have an idea that is wrong. Will have to dig further.

rossko57 · January 9, 2021, 8:02pm

Alright, confirmed behaviour with OH2.5 using rule that can be run ad-hoc

(global var Timer testTimer = null)

if (testTimer === null) {
    logInfo("test", "Creating new timer 20s")
    testTimer = createTimer(now.plusSeconds(20), [ |
        logInfo("test", "Timer has executed")
    ])
} else {
    logInfo("test", "Timer already exists")
    if (testTimer.hasTerminated) {
        logInfo("test", "Timer has terminated")
    } else {
        logInfo("test", "Timer is pending")
    }
    logInfo("test", "Going to reschedule 20s")
    testTimer.reschedule(now.plusSeconds(20))
}

Even after the timer has finished, it should not get garbage-collected because we kept a handle for it. And so we should be able to reschedule.

Results

// initial poke
2021-01-09 19:37:39.473 [INFO ] [.eclipse.smarthome.model.script.test] - Creating new timer 20s
// test reschedule before expiry
2021-01-09 19:37:48.560 [INFO ] [.eclipse.smarthome.model.script.test] - Timer already exists
2021-01-09 19:37:48.561 [INFO ] [.eclipse.smarthome.model.script.test] - Timer is pending
2021-01-09 19:37:48.563 [INFO ] [.eclipse.smarthome.model.script.test] - Going to reschedule 20s
2021-01-09 19:38:08.563 [INFO ] [.eclipse.smarthome.model.script.test] - Timer has executed
// test reschedule after expiry
2021-01-09 19:38:31.758 [INFO ] [.eclipse.smarthome.model.script.test] - Timer already exists
2021-01-09 19:38:31.759 [INFO ] [.eclipse.smarthome.model.script.test] - Timer has terminated
2021-01-09 19:38:31.760 [INFO ] [.eclipse.smarthome.model.script.test] - Going to reschedule 20s
2021-01-09 19:38:51.763 [INFO ] [.eclipse.smarthome.model.script.test] - Timer has executed
// longer term test
2021-01-09 19:57:58.617 [INFO ] [.eclipse.smarthome.model.script.test] - Timer already exists
2021-01-09 19:57:58.620 [INFO ] [.eclipse.smarthome.model.script.test] - Timer has terminated
2021-01-09 19:57:58.621 [INFO ] [.eclipse.smarthome.model.script.test] - Going to reschedule 20s

So, it all seems to work as expected in OH2

I have no viable OH3 install to test, that should be possible using a similar rule. Looks like a bug to me.

deswong · January 13, 2021, 9:36am

I have noticed I am having the same issue as well.

Openhab.log

2021-01-13 18:48:45.660 [INFO ] [nhab.core.model.script.default.rules] - 433MHz Sensor:PIR Kitchen
2021-01-13 18:48:45.661 [WARN ] [el.script.internal.actions.TimerImpl] - Rescheduling failed as execution has already started!
2021-01-13 18:48:45.661 [INFO ] [ore.model.script.global_lights.rules] - Kitchen light timer extended for 5 minutes
2021-01-13 18:52:21.859 [INFO ] [nhab.core.model.script.default.rules] - 433MHz Sensor:PIR Kitchen
2021-01-13 18:52:21.860 [WARN ] [el.script.internal.actions.TimerImpl] - Rescheduling failed as execution has already started!
2021-01-13 18:52:21.860 [INFO ] [ore.model.script.global_lights.rules] - Kitchen light timer extended for 5 minutes

Rule

var Timer tKitchenLight       = null
rule "Turn on kitchen light when motion triggered"
when
 Item PIRKitchen changed from OPEN to CLOSED
 then
 if(LoungeLight_PowerSwitch.state == ON) {
   if (tKitchenLight !== null)
        {
             tKitchenLight.reschedule(now.plusMinutes(5))
             logInfo("global_lights.rules", "Kitchen light timer extended for 5 minutes")
         }
         else
         {
         logInfo("kitchen_light.rules", "Kitchen light turned ON.")
         KitchenDimmerAction.sendCommand("bright")
         tKitchenLight = createTimer(now.plusMinutes(5)) 
         [| 
         logInfo("kitchen_light.rules", "Kitchen timer has reached 5 minutes, exiting.")
         KitchenDimmerAction.sendCommand(KitchenDimmerAction.previousState(true))
         tKitchenLight = null]
         }   
     }
   PIRKitchen.postUpdate(OPEN)
end

This worked fine in OpenHAB 2.5, and moving to OpenHAB 3 I have noticed this in my logs.

In my case here, it seems to break the timer - and the light never turns off as the timer seems to be broken after this happens.

rossko57 · January 13, 2021, 12:20pm

This is a slightly different situation - this one attempts reschedule while timer code is actually executing. Previous demo was attempting reschedule after timer code had finished. Almost certainly same bug though.

Well, is anybody going to create a simple demo and log a github issue for this?

Marcin_J · January 18, 2021, 4:06pm

I made it here

JimT · January 24, 2021, 10:03pm

The problem exists in OH3, not in OH2. It seems that a lot of changes were made on the Timer implementation in OH3.
The problem occurred when a timer that has already executed is being rescheduled.
The problem didn’t occur when a timer that has not already executed, cancelled, and rescheduled.

I’ve submitted a PR to fix this issue.

There’s also a separate bug on hasTerminated(), which may only affect some people, depending on their script logic, which I have filed as a separate issue on github.

JimT · January 29, 2021, 1:47am

PR merged. This should be fixed in 3.1