Not sure I understand you here, the error just shown is
If we put the events in timestamp order
22:46:25.672 [INFO ] … - Hit this place in the code - message 6
22:46:25.698 [WARN ] … - An error occurred while rescheduling…
22:46:25.723 [INFO ] … - Hit this place in the code - message 7
22:46:25.726 [INFO ] … - Rescheduling the living room lights…
So, the rule has come along to “message 6” point, and will next create a Timer for 50mS hence, and store a handle to that in
25mS later - so before the timer executes - we get the WARN/error. This is not that timer executing. This may or may not be the same timer being rescheduled - but the error message suggests it’s first line is likely to be some
if() statement - not the
logInfo() of that 50mS timer.
After the appointed 50mS, “our” Timer does appear to fire and execute normally.
Could your rule be re-entering a second time, and trying to create two timers in very rapid succession? No evidence of that (unless there are multiple “message 6” you haven’t shown).
The 25mS delay from “message 6” to error does suggest we may be further along in the same rule, after having completed and scheduled to 50mS job.
I think you need to show us the remainder of this rule.
It is also possible that some other rule altogether is running in parallel here, triggered from similar events; or perhaps immediately after, triggered by changes this rule makes. I’d be looking for a
createTimer with a leading
if(), and then look for places that gets rescheduled.
So, that’s all how I’d look at it
without taking the quartz debug log into account. But of course we should take it into account.
22:46:25.671 [DEBUG] ...- Calling execute on job DEFAULT.Timer ...
Here’s a timer going off, notably before “message 6”
We must be a bit careful about the millisecond accuracy of log timestamps, but I’ll trust this one.
Also notable, it begins with an if() and so it is in the frame for our culprit.
22:46:25.672 [DEBUG] - Calling execute on job DEFAULT.Timer...
Here’s another timer going off, and it’s a different one.
It has the
logInfo() , if() structure of the 50mS one we are creating right about this time - but it is not the same one.
I’m not sure what debug output we should expect for the timer creation that is also going on at this time - I think ‘quartz’ is only involved in execution, not initial set up. This might be the creation, but the key doesn’t match the execution 50mS later.
2019-10-30 22:46:25.673 [DEBUG] - Calling execute on job DEFAULT.Timer...
Another completely different timer going off? Yep,
It is possible that either one of those last two timers is attempting to reschedule the leading culprit timer (and is maybe messing up because it is in execution still), who can say without knowing the code.
22:46:25.723 [DEBUG] - Calling execute on job DEFAULT.Timer ...
Phew, well this one we were expecting - this is the 50ms “message 6” business, all is well here.
There are a lot of timers flying about here at the same time.
I think you may need to plant more
logInfo()s in your timers to trace who is firing when.