Problem with Timer and Cron

Hi all,

I recently switched to openhab 2 and first of all I’d like to say thanks for the good work to all involved.

Unfortunately it seems that in my setup all the rule related stuff that involves times is not working. First I faced this issue with openhab 2.1 and a cron based rule that should be triggered every 5 minutes but is never fired. After reading here that there are some issues with cron in version 2.1 I updated to 2.2 and I’m currently running build #1055 (openhabian on raspberry 2). Unfortunately the rule is still not fired even I can see in the log that it is scheduled.

Additionally another rule that creates a timer is also not working well because timer is created proberly (according to manual log messages) but never triggered.

Both rules worked well in openhab 1 so I guess it is not a problem with my code and I also tried to remove all productive code and only added log messages.

Unfortunately I still have problems understanding the new logging mechanisms using karaf console so I don’t know what exactly to activate to get a prober log that helps solving the issue.

Does anybody have an idea what I’m missing or what to change for logs to get a better information?

Thanks in advance.

Regards,
Olti

Hey Olti,
I don’t know of any issues. There were reports of cron rules triggering more than once but your case is different. I’d suspect an error in the config files.

Please read:

Then test the following example:

rule "Test"
when
    Time cron "0 * * * * ?"
then
    logInfo("crontest.rules", "minutely cron rule seems to be working...")
end

Entering this in the Karaf console will help to monitor when the cron rules are executed too. When your done monitoring, rerun with DEBUG changed to OFF, INFO, or WARN.

log:set DEBUG org.quartz.core

Hi all,

I implemented the suggested rule with some additional logging.

Unfortunately the log output doesn’t help me a lot:

2017-10-06 18:23:42.310 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘default.rules’
2017-10-06 18:23:42.519 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Feiertag’ with cron expression ‘0 0 0 * * ?’
2017-10-06 18:23:42.532 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Wochenende’ with cron expression ‘0 0 0 * * ?’ 2017-10-06 18:23:42.543 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Test’ with cron expression ‘0 * * * * ?’
2017-10-06 18:23:44.463 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model ‘default.rules’
2017-10-06 18:23:44.662 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Feiertag#midnight’
2017-10-06 18:23:44.668 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Wochenende#midnight’ 2017-10-06 18:23:44.675 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Test#0 * * * * ?’
2017-10-06 18:23:44.698 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Feiertag’ with cron expression ‘0 0 0 * * ?’
2017-10-06 18:23:44.710 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Wochenende’ with cron expression ‘0 0 0 * * ?’ 2017-10-06 18:23:44.721 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Test’ with cron expression ‘0 * * * * ?’
2017-10-06 18:23:46.598 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model ‘default.rules’
2017-10-06 18:23:46.795 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Feiertag#midnight’
2017-10-06 18:23:46.801 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Wochenende#midnight’
2017-10-06 18:23:46.809 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job ‘default.rules#Test#0 * * * * ?’
2017-10-06 18:23:46.820 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Feiertag’ with cron expression ‘0 0 0 * * ?’
2017-10-06 18:23:46.832 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Wochenende’ with cron expression ‘0 0 0 * * ?’ 2017-10-06 18:23:46.843 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule ‘Test’ with cron expression ‘0 * * * * ?’
2017-10-06 18:23:51.855 [INFO ] [org.quartz.core.QuartzScheduler ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
2017-10-06 18:23:51.859 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing startup rule ‘Feiertag’
2017-10-06 18:23:51.859 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing startup rule ‘Wochenende’
2017-10-06 18:27:28.966 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule ‘Dimme Stehlampe’

The only thing I don’t get is why the cron job is removed and scheduled multiple times. Is this normal behavior?

Thanks & Regards,
Olti

I can’t validate in my own logs right now, but I believe I have seen this before and my cron triggered rules work.

You should also be seeing things like this in the log:

2017-Oct-06 06:56:00.002 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job DEFAULT.Cron.rules#Cron: Check for weather alert#0 1/5 * * * ?
2017-Oct-06 06:56:28.860 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:56:57.924 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 1 triggers
2017-Oct-06 06:57:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:57:00.004 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job DEFAULT.Cron.rules#Cron: Speaker state refresh#0 2/5 * * * ?
2017-Oct-06 06:57:27.953 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:57:57.163 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:58:25.735 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:58:51.751 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:59:20.564 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 06:59:46.034 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 1 triggers
2017-Oct-06 07:00:00.004 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:00:00.004 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job DEFAULT.Mode.rules#Mode: Morning#0 0 7 * * ?
2017-Oct-06 07:00:23.847 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:00:48.855 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 1 triggers
2017-Oct-06 07:01:00.001 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job DEFAULT.Cron.rules#Cron: Check for weather alert#0 1/5 * * * ?
2017-Oct-06 07:01:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:01:28.198 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:01:54.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 1 triggers
2017-Oct-06 07:02:00.000 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:02:00.001 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job DEFAULT.Cron.rules#Cron: Speaker state refresh#0 2/5 * * * ?
2017-Oct-06 07:02:24.496 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:02:53.754 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:03:18.006 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:03:47.901 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 1 triggers
2017-Oct-06 07:03:57.029 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:03:57.030 [DEBUG] [org.quartz.core.JobRunShell                       ] - Calling execute on job Weather.weatherJob-Hinckley
2017-Oct-06 07:04:21.710 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers
2017-Oct-06 07:04:44.772 [DEBUG] [org.quartz.core.QuartzSchedulerThread             ] - batch acquisition of 0 triggers

There is talk on changing the scheduler, and there has been a couple fixes to the current one recently, but I don’t know if they are in the build you have or if they could be the cause. I’m on 2.2 snapshot 1054 and do not have this issue. Maybe get a newer build?

Could you try changing the rule suggested by @ThomDietrich to trigger on Time cron "0 0/1 * * * ?" and see if that fires the rule every minute? That is the format I use and works for my rules.

PS - Instead of Blockquote, use Preformatted Text for wrapping the logs… makes them much easier to read!

Hi

changing the cron expression didn’t change anything but it seems that your log which mentions QuartzSchedulerThread gave me the right hint. I remembered something related to the quartz thread count when setting up caldav binding for openhab 1. I gave it a try and changed the quartz thread count to 20 and now I can see the cron rule to be triggered.

Thanks for all your help.

BTW: Is there an easy way to reset logging settings to the defaults for everything?

Maybe log:clear? If you try it, let me know! I manually edit the org.ops4j.pax.logging.cfg file.

Where is this configured?

Unfortunately not working.

There is a file called quartz.properties which is located under /usr/share/openhab2/runtime/etc/ or openhab-sys/runtime/etc if using the shares via Samba / Designer

1 Like

Check Github for the org.ops4j.pax.logging.cfg file that comes with the distribution and copy it in. That should put you back to default settings.

Hmm. Unfortunately it stopped working again since the file is overwritten at update (at least on openhabian).

Does anybody know, whether there is another location where I can change that setting persistantly?

I jumped into this topic, because I had a very similar issue.

I had literally this rule:

rule "Test chron"
when
    Time cron "0 * 0 ? * * *"
then
    logWarn("test", "triggered")
end

And it was not being triggered at all.
Eventually, I restarted the system, and it started working again.
I have no Thread::Sleep() in any rule, but I do have quite a lot of timers (made with CreateTimer).

Now, you mentioned that adding threads helped, but up to a certain point.
Is it possible that the two issues are related?

Checked after about 12 hours, and it stopped working again.

As a matter of facts, it seems that all cron rules stopped working: I have another rule, simply resetting an item state every day at 8AM, and I can see that the item state was not reset.

That rule stopped working about at the beginning of November; and I performed update to 2.4 M5 at about that time: maybe that could be the reason?