Timer rescheduling exception: Unable to store job XXX because one already exists with this identification

Setup, Configuration and Use Scripts & Rules
, ,
1

I’m currently running OH2.5 snapshot #1601.

In using the buienradar binding, I use a rule for setting some item values to circumvent the absence of an update timestamp channel. I’m grouping the rain forecasts in quarters and in hours, hence the group totals change several times as the forecast data are released from the buienradar binding to OH.

I use a timer to wait at least 5 seconds after an update of the group item representing the total amount of rainfall. Due to the several changes, I have to reset the timer in the rule several times as well.

I am somehow surprised that I run into “object already existing” exceptions when rescheduling the timer:

==> /var/log/openhab2/openhab.log <==
2019-06-15 09:21:05.961 [WARN ] [el.script.internal.actions.TimerImpl] - An error occurred while rescheduling the job 'DEFAULT.2019-06-15T09:21:10.915+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  val ruleTitle
  logDebug(<XFeatureCallImplCustom>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@78fc9c
  <null>.buienRadarTimer = <XNullLiteralImplCustom>
} ]': Unable to store Job : 'DEFAULT.2019-06-15T09:21:10.915+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  val ruleTitle
  logDebug(<XFeatureCallImplCustom>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@78fc9c
  <null>.buienRadarTimer = <XNullLiteralImplCustom>
} ]', because one already exists with this identification.

Here’s the buienradar.rules file:

var Timer buienRadarTimer = null

rule "It will rain"
when
    Item gBuienRadarForecastRain changed
then
    val String ruleTitle = "It will rain"
    // Wait until all group state updates have been propagated
    if (buienRadarTimer !== null  && !buienRadarTimer.hasTerminated) {
        // Reschedule the timer if it already exists
        logDebug(ruleTitle, "Rescheduling the timer")
        buienRadarTimer.reschedule(now.plusSeconds(5))
    } else {
        logDebug(ruleTitle, "Creating the timer")
        buienRadarTimer = createTimer(now.plusSeconds(5), [ |

            val String ruleTitle = "It will rain (inside timer)"
            logDebug(ruleTitle, "Timer has terminated - code execution started")
            if (gBuienRadarForecastRain.state instanceof DecimalType) {
                val Number rain = gBuienRadarForecastRain.state as Number
                if (rain > 0) {
                    logDebug(ruleTitle, "It will rain: {} mm expected in the coming 120 minutes", rain)
                    val int earliest_time = gBuienRadarForecastRain.allMembers.filter[ i | i.state as Number > 0 ].map[ i |
                        Integer::parseInt( i.name.substring(i.name.length() - 7).substring(0, 3) )
                    ].reduce[ min, v |
                        if (v < min)
                            v
                        else
                            min
                    ] // Lambda return type is: Number
                    postUpdate(Wx_buienradar_rain_time, earliest_time)
                }
                logDebug(ruleTitle, "Timer has terminated - code execution terminated")
            } else {
                // gBuienRadarForecastRain.state is not set
                logWarn(ruleTitle, "gBuienRadarForecastRain.state is not a numeric value: '{}'", gBuienRadarForecastRain.state)
            }

            buienRadarTimer = null
		])
    }

end

So I suppose this is due to the timer granularity (hence the name collision exceptions) and to the burst of item updates triggering the rule (hence the higher chances of occurring).

Is there something I could to to avoid the exceptions (unless asking for the update timestamp to be made available from the binding)?

FWIW I linked this post to the following feature request on GitHub:

2

It appears that the same rule also fires other timer exceptions (java.lang.IllegalStateException: null)…

2019-06-15 10:03:26.933 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-06-15T10:03:26.849+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  val ruleTitle
  logDebug(<XFeatureCallImplCustom>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1550d16
  <null>.buienRadarTimer = <XNullLiteralImplCustom>
} ] threw an unhandled Exception: 
java.lang.IllegalStateException: null
3

There is a case where the Timer is not null and it has not terminated. In fact, that would be the usual case when the Timer is waiting for it’s appointed time.
EDIT - ohh, I messed up here and missed the ! “not”. It’s not like this.

But somehow, your rule will try to create a new Timer and run into the “already exists” error. I can’t work out how it is getting there without throwing an error in the preceding if()

Maybe there’s a misunderstanding of Timer status.
isRunning means the code block is currently executing.
hasTerminated means the code block has run and is finished.
Neither of those get used very often in practice.

Note that when you have the Timer set itself to null on completion … those methods go away anyway.

There is not a “isWaiting” status, which is why most of us use the null / not null trick for that purpose.

I’d get rid of that status check and simplify
if (buienRadarTimer !== null) {

4

I keep learning every day :slight_smile:

If I understand correctly, the code block can exist for as long as the Timer object exists. Since the code block is immutable, I could keep rescheduling it when needed and only create it once.

If this is the case, then I can get rid of setting the timer object to null at the end of the code block. Otherwise, I suppose or expect the Timer object destroys itself upon completion of the code block.

I edited the if() check to only check for null now.

That is indeed a pity, but I suppose it has to do with concurrency and avoiding race conditions. You could check whether the timer is waiting, and when you got the result, the timer (which might be running in another trhead) would expire even before you want to reschedule it. This would mean that the code block would run twice (unless a reschedule aborts the execution of the code block).
But in my limited experience with timers so far, it appears that code blocks can run in parallel when rescheduling a timer.