[SOLVED] Random Timer Error - Unable to store Job

I’m getting a random timer error from 2.5M4 running in a ESXI VM. Should I actually start naming my timers?

Code (about 80% sure that this code is causing the random error):

createTimer(now.plusMillis(50), [ |   // Set to 50 ms in case Homemode changes concurrently turns the overrides off



	if(HomeMode.state == "HOME")
	{
		// Turn on both lamps in the living room
					
		if(LivingRoomLamp.state != ON && OverrideLivingRoomLampChange.state != ON)
		{
			postUpdate(IgnoreLivingRoomLampChange,ON)  // for ignoring changes on living room lamp
			sendCommand(LivingRoomLamp,ON)    // Turn on living room lamp
			//logInfo("rules", "Turning on Living Room Lamp now")
		}
		
		if(LivingRoomFloorLamp.state != ON && OverrideLivingRoomFloorLampChange.state != ON)
		{					
			createTimer(now.plusSeconds(2), [ |
					postUpdate(IgnoreLivingRoomFloorLampChange,ON)  // for ignoring changes on living room floor lamp
					sendCommand(LivingRoomFloorLamp,ON)    // Turn on living room floor lamp
			])  
		}					
])

Error:

2019-10-26 22:59:05.416 [WARN ] [el.script.internal.actions.TimerImpl] - An error occurred while rescheduling the job 'DEFAULT.Timer 1 2019-10-26T08:41:20.251-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@55ebd025
} ]': Unable to store Job : 'DEFAULT.Timer 1 2019-10-26T08:41:20.251-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@55ebd025
} ]', because one already exists with this identification.

There was a fairly recent fix to createTimer, where multiple timers stored with same target time could silently fail (except last one). I think the fix was a proper fix, though, not just adding a complaint message.

I do not think the given code snippet is the source of your error.
Logged at 22:59:05.416 is a complaint about the timer with target 08:41:20.251 - rather more than a few seconds duration.

EDIT -think the mention of rescheduling may mean what it says too - not a create, but a reschedule.

Does that overnight timeframe on that day happen to span a daylight savings time change for you? (it would for me, this may be relevant)

1 Like

Thank you for your response! Here is the chunk of code where I am doing the reschedule, but I didn’t think it was triggering at this error. Maybe it needs a second set of eyes. I’m trying to turn the lights off after there hasn’t been motion for at least x amount of minutes. And yes, we are in daylight savings time. Here is a timer with a rescheduled event, that happens in that same code block. I really appreciate your help.

if (LivingRoomLightsOffSleepTimer === null)  // If you make changes here, also change the MorningMotionOffSleepTimer timer
{
	LivingRoomLightsOffSleepTimer = createTimer(now.plusMillis(50)) [|  // Wait 50 ms, so if the first reschedule happens, it won't reschedule a null and error out
	
		if (now.isAfter((new DateTime((NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)).plusMinutes((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)))
			
		{
			if (WorkoutMode.state != ON)
			{
			
				//logInfo("rules","Turning off lights now")
				
				if(LivingRoomLamp.state != OFF && OverrideLivingRoomLampChange.state != ON)  // OverrideLivingRoomLampChange should be off since homemode just changed
				{
					postUpdate(IgnoreLivingRoomLampChange,ON)  // for ignoring changes on living room lamp
					sendCommand(LivingRoomLamp,OFF)    // Turn off living room lamp
				}
				
			
				if(LivingRoomFloorLamp.state != OFF && OverrideLivingRoomFloorLampChange.state != ON)  // OverrideLivingRoomFloorLampChange should be off since homemode just changed
				{
					postUpdate(IgnoreLivingRoomFloorLampChange,ON)  // for ignoring changes on living room floor lamp
					sendCommand(LivingRoomFloorLamp,OFF)    // Turn off living room floor lamp
				}									
					
				LivingRoomLightsOffSleepTimer.cancel
				LivingRoomLightsOffSleepTimer = null
		
				
			} else
			{
				//logInfo("rules","Workout mode is on.  Restarting to wait the default time")
				LivingRoomLightsOffSleepTimer.reschedule(now.plusMinutes((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue))
			}
		
			
		} else
		{

			//logInfo("rules","Rescheduling the living room lights off timer because there has been motion in the last " + String.format("%.0f", Math::ceil((now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)/60000) )  + " minutes.")
			//logInfo("rules","Seconds since last movement " + ((now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)/1000).toString)
			//logInfo("rules","Timer is rescheduled to " +  ( ((((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)*60000) - (now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)	+ 1000) ).toString + " ms.")
			LivingRoomLightsOffSleepTimer.reschedule(now.plusMillis( ((((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)*60000) - (now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)	+ 100).intValue ))  // +100 is a 100 ms buffer

		}
	
	]
	


}

This line is redundant within the timer’s own code block - the time has triggered, the code is running, there is no future time to to cancel.
I do not think that is related.

So, there’s useful logInfo in your code but commented out. Might at least determine if you are looking at right area.

1 Like

Sir,

Many thanks. I just added debug statements to several timer blocks, I turned on quartz debugging, and I removed the .cancel’s throughout all my rules. I really appreciate your help and I’ll let you know what comes out of this.

Best Regards.

Well, you need to look at each case. Sometimes you do want to cancel a timer that hasn’t “gone off” yet. But you cannot do that from inside the block of code that runs only when the timer has already gone off.

1 Like

Understood. To clarify, I removed all of the .cancel’s inside my timer blocks. I did not have any .cancel’s outside of my timer blocks.

I really appreciate your help.

I still can’t figure out why I’m getting the timer errors. This is not the “unable to store job” error, but a similar error. I haven’t seen the “unable to store job” error since I removed the .cancel but I am getting this new error.

The timer name is from when the system booted. I don’t see that timer created at boot.
My rules seem to run great and the error doesn’t seem to cause any issues. The error occurs about 25% of the time when I enter this block of code.

Error:

2019-10-30 22:46:25.698 [WARN ] [el.script.internal.actions.TimerImpl] - An error occurred while rescheduling the job 'DEFAULT.Timer 1 2019-10-30T08:13:30.038-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@5a2b8264
} ]': Unable to store Job : 'DEFAULT.Timer 1 2019-10-30T08:13:30.038-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@5a2b8264
} ]', because one already exists with this identification.

The code:

if (LivingRoomLightsOffSleepTimer === null)
{
	logInfo("rules", "Hit this place in the code - message 6")

	LivingRoomLightsOffSleepTimer = createTimer(now.plusMillis(50)) [|  // Wait 50 ms, so if the first reschedule happens, it won't reschedule a null and error out
	
		logInfo("rules", "Hit this place in the code - message 7")
		
		if (now.isAfter((new DateTime((NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)).plusMinutes((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)))
			
		{
			if (WorkoutMode.state != ON)
			{
			
				logInfo("rules","Turning off lights now")
				
				if(LivingRoomLamp.state != OFF && OverrideLivingRoomLampChange.state != ON)  // OverrideLivingRoomLampChange should be off since homemode just changed
				{
					postUpdate(IgnoreLivingRoomLampChange,ON)  // for ignoring changes on living room lamp
					sendCommand(LivingRoomLamp,OFF)    // Turn off living room lamp
					//logInfo("rules", "Turning on Living Room Lamp now")
				}
				
			
				if(LivingRoomFloorLamp.state != OFF && OverrideLivingRoomFloorLampChange.state != ON)  // OverrideLivingRoomFloorLampChange should be off since homemode just changed
				{
					postUpdate(IgnoreLivingRoomFloorLampChange,ON)  // for ignoring changes on living room floor lamp
					sendCommand(LivingRoomFloorLamp,OFF)    // Turn off living room floor lamp
				}									
				
				//postUpdate(MorningMotion,OFF)
				
				//LivingRoomLightsOffSleepTimer.cancel
				LivingRoomLightsOffSleepTimer = null
		
				
			} else
			{
				logInfo("rules","Workout mode is on.  Restarting to wait the default time")
				logInfo("rules", "Hit this place in the code - message 8")
				LivingRoomLightsOffSleepTimer.reschedule(now.plusMinutes((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue))
			}
		
			
		} else
		{

			logInfo("rules","Rescheduling the living room lights off timer because there has been motion in the last " + String.format("%.0f", Math::ceil((now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)/60000) )  + " minutes.")
			logInfo("rules","Seconds since last movement " + ((now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)/1000).toString)
			logInfo("rules","Timer is rescheduled to " +  ( ((((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)*60000) - (now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)	+ 1000) ).toString + " ms.")
			logInfo("rules", "Hit this place in the code - message 9")
			LivingRoomLightsOffSleepTimer.reschedule(now.plusMillis( ((((Living_Room_Lights_Off_Sleep_Mode_Motion_Timer.state as Number).intValue)*60000) - (now.millis-(NightIndoorMotionLastTrigger.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)	+ 100).intValue ))  // +100 is a 100 ms buffer

		}
	
	]
	


}

The log:

2019-10-30 22:46:25.672 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 2
2019-10-30 22:46:25.672 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 6
2019-10-30 22:46:25.723 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 7
2019-10-30 22:46:25.726 [INFO ] [eclipse.smarthome.model.script.rules] - Rescheduling the living room lights off timer because there has been motion in the last 0 minutes.
2019-10-30 22:46:25.727 [INFO ] [eclipse.smarthome.model.script.rules] - Seconds since last movement 17
2019-10-30 22:46:25.728 [INFO ] [eclipse.smarthome.model.script.rules] - Timer is rescheduled to 283496 ms.
2019-10-30 22:46:25.728 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 9
2019-10-30 22:51:08.322 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 7
2019-10-30 22:51:08.323 [INFO ] [eclipse.smarthome.model.script.rules] - Rescheduling the living room lights off timer because there has been motion in the last 1 minutes.
2019-10-30 22:51:08.324 [INFO ] [eclipse.smarthome.model.script.rules] - Seconds since last movement 90
2019-10-30 22:51:08.324 [INFO ] [eclipse.smarthome.model.script.rules] - Timer is rescheduled to 210321 ms.
2019-10-30 22:51:08.324 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 9
2019-10-30 22:54:37.745 [INFO ] [eclipse.smarthome.model.script.rules] - Hit this place in the code - message 7
2019-10-30 22:54:37.746 [INFO ] [eclipse.smarthome.model.script.rules] - Turning off lights now

The Quartz Log at the time of the error

2019-10-30 22:46:25.671 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.Timer 2467 2019-10-30T22:46:25.671-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@4994f9c5
} ]
2019-10-30 22:46:25.671 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 22:46:25.672 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.Timer 2468 2019-10-30T22:46:25.672-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@64a1ca1b
} ]
2019-10-30 22:46:25.673 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 22:46:25.673 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.Timer 2469 2019-10-30T22:46:25.674-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <null>.Living_Room_Lights_Concurrency_Guard = <XBooleanLiteralImpl>
} ]
2019-10-30 22:46:25.723 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 22:46:25.723 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.Timer 2470 2019-10-30T22:46:25.722-05:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1e9a3867
} ]

The Quartz log at near startup

2019-10-30 08:13:22.067 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-10-30 08:13:22.089 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:27.067 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:27.067 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-10-30 08:13:27.067 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:32.068 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:32.068 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-10-30 08:13:32.068 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:35.001 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-10-30 08:13:35.001 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.main.rules#Palm Grow Lights control#    35 0/1 * 1/1 * ? *

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 LivingRoomLightsOffSleepTimer

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.

1 Like

Sir,

Thank you so much for your help. Yes, I misread the error. With your encouragement, I started checking out unrelated areas of code with a reschedule and I found the issue.

I have a python script that converts a TCP STREAM packet to a mqtt message. Sometimes, the TCP STREAM packets come in very fast, so I queue up the messages and resend at 20 millisecond intervals.

It appeared that my python was property spacing the mqtt messages, however OpenHAB was processing them in batches.

Example Python Script MQTT Publish:

Sending: 09EM0020013  at  2019-11-01 22:25:28.619819
Sending: 1EAS1000000031111111000000003BF6  at  2019-11-01 22:25:28.639829

Example Openhab MQTT Receive:

2019-11-01 22:25:28.646 [vent.ItemStateChangedEvent] - Elk_Alarm_Update_MQTT changed from 1CLD1173003122251101000619004E to 09EM0020013
2019-11-01 22:25:28.647 [vent.ItemStateChangedEvent] - Elk_Alarm_Update_MQTT changed from 09EM0020013 to 1EAS1000000031111111000000003BF6

Therefore, I commented this code out

if (AlarmGoodConnectionTimer === null)
{
	AlarmGoodConnectionTimer = createTimer(now.plusSeconds(70)) [|

		if ((now.isBefore((new DateTime((SystemStartupDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)).plusSeconds(80)))  // set to 80 seconds
			&& ((SystemStartupDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli - (SystemStartingFirstTimeDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli) > 5)  // This shows if just the rules are reset
		{

			logInfo("alarmrules","Alarm connection lost, but it was when system rebooted.")		
			logInfo("alarmrules","SystemStartingFirstTimeDateTime (fresh boot):     " + SystemStartingFirstTimeDateTime.state.toString)		
			logInfo("alarmrules","SystemStartupDateTime:                            " + SystemStartupDateTime.state.toString)		
			logInfo("alarmrules","SystemStartupDateTime (fresh boot) - SystemStartingFirstTimeDateTime:     " + ((((SystemStartupDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)-((SystemStartingFirstTimeDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli))/1000).toString + " seconds.")
			
			AlarmGoodConnectionTimer.reschedule(now.plusSeconds(70))										
			
		} else
		{
			
			postUpdate(AlarmMsgLostConnectionCounter,(AlarmMsgLostConnectionCounter.state as Number).intValue + 1)
			logInfo("alarmrules","CONNECTION DROPPED TO THE ALARM")
			logInfo("alarmrules","SystemStartingFirstTimeDateTime (fresh boot):     " + SystemStartingFirstTimeDateTime.state.toString)		
			logInfo("alarmrules","SystemStartupDateTime:                            " + SystemStartupDateTime.state.toString)		
			logInfo("alarmrules","SystemStartupDateTime (fresh boot) - SystemStartingFirstTimeDateTime:     " + ((((SystemStartupDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)-((SystemStartingFirstTimeDateTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli))/1000).toString + " seconds.")
						
			
			if (AlarmConnectionGood.state != OFF)
			{
				postUpdate(AlarmConnectionGood,OFF)
			}

			AlarmGoodConnectionTimer = null
												

		}
	]	
} else
{
	AlarmGoodConnectionTimer.reschedule(now.plusSeconds(70))
	//logInfo("alarmrules","Alarm connection is operating.")
}	

And replaced it with a simple

AlarmLastMessageTime.postUpdate(new DateTimeType())

and a new rule:

rule "Alarm Connection Watch"
when
	Time cron "	30 0/1 * 1/1 * ? *"
then


	if (now.isAfter((new DateTime((AlarmLastMessageTime.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli)).plusSeconds(70))
		&& AlarmConnectionGood.state != OFF)
	{

		postUpdate(AlarmConnectionGood,OFF)
		
		logInfo("alarmrules","CONNECTION DROPPED TO THE ALARM")
						
		
	}
	
end

Thank you so much for all of your help!

Glad you have made progress. Timer issues are arses, cloak themselves in obscurity.

Quite ambitious, depending on openHABs involvement - it’s not really a real time system.

I don’t really like cron based rules, but I see your point here. Only occasionally checking data packet frequency instead of manipulating timers for every packet.