Cron based rules suddenly stop executing

[CDriver]

@rlkoshak

But the error could be caused by other Timers blocking the cron trigger’s Rule’s ability to run within five seconds of being triggered. The error isn’t very clear that it’s complaining that a Timer or cron triggered rule took more than five seconds to complete or that it took more than five seconds for a thread to free up so it could execute the Rule.

Interesting. I have many every-minute cron rules which fire and don’t cause a problem.
I am certain, but checking again tonight, I did have a rule which used cron to trigger the switch and the switch triggered the motion rule. This also failed. Why would it fail?
While I am sure, I am setting this up again tonight and will let it run overnight.

@rlkoshak

There is nothing in that Rule that should take a long time to run, unless you have thousands of members in g_LastMotionAgo. So perhaps the real problem is the latter of the two described above, it’s taking longer than five seconds for the Rule to start executing because all the threads are currently in use for five seconds.

No, the group has 5 or 6 items in it. It’s not large. To @rossko57 point, none of the items are persisted. They’re datetime if that feeds any thought process.

@rlkoshak

The more I look at it the less I think it’s this Rule that is causing the problem. Somewhere else you have a Timer body or cron/Astro triggered Rule that is taking longer than expected or crashing in a way that doesn’t return the thread to the Quartz thread pool. Then when this Rule tries to run, it takes more than five seconds to start running and OH sees that delay and throws an error.

I have loads of cron rules which work without a problem. I have one which runs every 30 minutes and writes out “ping”. I can certainly make it move frequent to try and exacerbate the problem.
I also have a rule, cron based, which runs every 5 minutes to check the position of the blinds. It does not falter until quartz totally gives up the ghost.

@rlkoshak

That’s an interesting theory. You can see if that’s the case by adding logging statements before and after the sendCommand/postUpdates and checking the timestamps. That will also show that anything going on in the binding is also not blocking the Rule from running.

This “we’ve” spoken about before. When this error happens the log entries are all out of sequence.
See here: Help understanding quartz crashing - "Worker thread was interrupt()'ed."

As a snippet, look at the logs here:

1	2019-01-05 10:48:14.674 [INFO ] [home.model.script.Motion - resetting] - Motion from - Kitchen_MotionSensor - resetting to zero	
2	2019-01-05 10:48:12.596 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1e2e736' takes more than 5000ms.	
3	2019-01-05 10:47:37.641 [INFO ] [home.model.script.Motion - resetting] - Motion from - Hallway_MotionSensor - resetting to zero	
4	2019-01-05 10:47:27.061 [WARN ] [me.model.script.Motion - Auto Lights] - Bathroom_MotionSensor caused auto-lights - state:OFF	
5	2019-01-05 10:47:17.012 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness to 100.	
6	2019-01-05 10:52:12.890 [WARN ] [me.model.script.Motion - Auto Lights] - Room: Bathroom	
7	2019-01-05 10:49:42.950 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers	
8	2019-01-05 10:49:42.949 [ERROR] [org.quartz.simpl.SimpleThreadPool   ] - Worker thread was interrupt()'ed.	
9	java.lang.InterruptedException: null	
10		at java.lang.Object.wait(Native Method) ~[?:?]
11		at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
12	2019-01-05 10:49:12.610 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[726]	
13	2019-01-05 10:49:12.610 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago#0 0/1 * 1/1 * ? *	
14	2019-01-05 10:55:12.954 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[144]	
15	2019-01-05 10:54:42.934 [ERROR] [org.quartz.simpl.SimpleThreadPool   ] - Worker thread was interrupt()'ed.	
16	java.lang.InterruptedException: null	
17		at java.lang.Object.wait(Native Method) ~[?:?]
18		at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
19	

See how out of sequence the log entries are?
That “resetting” entry is the binding triggering a motion. It then set a the motionago item for that room back to zero.
So, actually, you have two rules here: 1) counting the minutes up. When it uses an item with that binding it fails and 2) a rule which fires and then resets the counter back to zero.
Two rules and they both fail, binding in the middle.

Things to try tonight -

1. Set up another minute-based rule in the same rules file to test with.
2. Disable the OS cron and revert to a cron-based rule which toggles the proxy item and check for failures.
3. to do tomorrow - remove the binding from the items. You’re theories will be proved either way if I do that. If it no longer fails then it’s confirmed to be a item+binding issue. If it still fails, then it is a rule / item / threading issue.