Cron triggered rules are executed twice

Tags: #<Tag:0x00007f2fb0c32d00> #<Tag:0x00007f2fb0c32b70>

Hi,

I am using Jython rules with cron triggers. After upgrading from 2.4 to 2.5M2 and the latest JSR232 library I noticed, that these sometimes are triggered twice. A few seconds before the actual time and at the correct time.

A few examples:

@when("Time cron 41 7 0/2 * * ?") 
2019-08-18 18:07:37.720 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-18 18:07:42.450 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!
2019-08-19 20:07:41.034 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-19 22:07:42.054 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!
2019-08-20 18:07:36.879 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 18:07:42.688 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!
@when("Time cron 15 55 08 * * ?")   
2019-08-14 08:55:11.773 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-14 08:55:15.773 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-15 08:55:10.729 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-15 08:55:15.729 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-16 08:55:11.689 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-16 08:55:15.689 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-17 08:55:11.629 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-17 08:55:15.629 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-18 08:55:10.579 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-18 08:55:15.579 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-19 08:55:11.520 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
2019-08-19 08:55:15.520 [INFO ] [.smarthome.automation.timer_lamps.py] - Checking lamps in the morning
@when("Time cron 15 15 0 * * ?")
2019-08-14 00:15:11.002 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-14 00:15:15.003 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-15 00:15:09.958 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-15 00:15:15.959 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-16 00:15:11.919 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-16 00:15:15.919 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-17 00:15:11.859 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-17 00:15:15.861 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-18 00:15:10.811 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-18 00:15:15.811 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-19 00:15:11.750 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off
2019-08-19 00:15:15.751 [INFO ] [.smarthome.automation.timer_lamps.py] - It is late, switching lamps off

The first one is interesting, as the error only occurs at 18:07, not at any other time the rule is triggered:

2019-08-20 02:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 04:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 06:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 08:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 10:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 12:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 14:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 16:07:41.939 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 18:07:36.879 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 18:07:42.688 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!

I checked the old log files and this behavior started after the upgrade, but I do not know if it is caused by the 2.5M2 or the JSR232 libraries.

I am surprised, that nobody else reported this (or I have not found it), so maybe there is something wrong with my setup? I am using the packet installation an Debian 10 (but the error also occurred on Debian 9) with Zulu Java 8.

Juelicher

Actually, I swear I just read a thread in the last week or so, same thing Jython rues, cron triggering twice. If I have time I will try to search but anyhow, hit the search button up there

I think this may be the topic that @Andrew_Rowe remembers:

1 Like

bingo!

Thanks for the links, but I am not sure if the behavior from the other thread is the same as I observe, as the rule in measurement_rules.py is triggerd twice only at 18:07 and not at the other times:

2019-08-20 02:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 04:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 06:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 08:07:41.937 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 10:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 12:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 14:07:41.938 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 16:07:41.939 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 18:07:36.879 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-20 18:07:42.688 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!

I will try the "bundle:restart “openHAB Core :: Bundles :: Automation Script RuleSupport” and see, what happens.

Could you please post or PM the entire script file containing one of these rules? Have you updated this script and had errors loading it? Keep an eye on org.openhab.core.automation for errors when loading scripts.

I don’t think these could be related, since that topic was discussing orphaned timers.

It may be better to restart OH, rather than just the NGRE, to make sure everything gets cleaned out.

Hi Scott,

I just send one of the files as PM.

Yesterday I restarted the bundle and in a quick check I could find no rule, that was triggered twice. I wait until after 18:07, to check if the behavior of the rule, that is triggered every two hours and always showed the bug only at 18:07 has changed. If it still shows the bug, I will restart openHAB.

The last time I restarted openHAB was on Monday, after I updated my server to Debian 10. After that I changed the file with the “18:07” trigger, but not the others.

Here is the log output while reloading the files after restarting the bundle, there is some debug output from initializing functions in between, but nor errors:

2019-08-20 19:33:22.111 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/000_startup_delay.py'
2019-08-20 19:33:52.162 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/01_system_rules.py'
2019-08-20 19:33:52.245 [INFO ] [smarthome.automation.system_rules.py] - System seems to be initialized, skipping timers
2019-08-20 19:33:52.453 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/100_DirectoryTrigger.py'
2019-08-20 19:33:52.672 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/100_OsgiEventTrigger.py'
2019-08-20 19:33:52.810 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/100_StartupTrigger.py'
2019-08-20 19:33:52.898 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonBindingInfoProvider.py'
2019-08-20 19:33:53.035 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonExtensionProvider.py'
2019-08-20 19:33:53.143 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonItemChannelLinkProvider.py'
2019-08-20 19:33:53.311 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonItemProvider.py'
2019-08-20 19:33:53.414 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonThingProvider.py'
2019-08-20 19:33:53.567 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonThingTypeProvider.py'
2019-08-20 19:33:53.708 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/core/components/200_JythonTransform.py'
2019-08-20 19:33:53.785 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/appliance.py'
2019-08-20 19:33:53.948 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/astro_rules.py'
2019-08-20 19:33:54.101 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/blinds_rules.py'
2019-08-20 19:33:55.067 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/debug_rules.py'
2019-08-20 19:33:55.194 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/fritzbox_rules.py'
2019-08-20 19:33:55.408 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/garage_rules.py'
2019-08-20 19:33:55.900 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/gate_rules.py'
2019-08-20 19:33:56.410 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/grafana_rules.py'
2019-08-20 19:33:56.499 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/heating_rules.py'
2019-08-20 19:33:56.915 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/holiday_rules.py'
2019-08-20 19:33:57.209 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/lamps_garden_rules.py'
2019-08-20 19:33:57.609 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/lamps_house_rules.py'
2019-08-20 19:33:58.570 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/lamps_terrace_rules.py'
2019-08-20 19:33:58.875 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/laundry.py'
2019-08-20 19:33:59.084 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/lights_drive_rules.py'
2019-08-20 19:33:59.405 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/measurement_rules.py'
2019-08-20 19:34:00.124 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/media_rules.py'
2019-08-20 19:34:00.250 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/network_rules.py'
2019-08-20 19:34:01.806 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/notification_rules.py'
2019-08-20 19:34:02.829 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/outlets_garden_rules.py'
2019-08-20 19:34:03.095 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/scenes_rules.py'
2019-08-20 19:34:03.287 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/shadowing_rules.py'
2019-08-20 19:34:03.752 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Schlafen_hinten_Fenster
2019-08-20 19:34:03.756 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Gaeste_links
2019-08-20 19:34:03.760 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Gaeste_rechts
2019-08-20 19:34:03.763 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Bibliothek_links
2019-08-20 19:34:03.767 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Bibliothek_rechts
2019-08-20 19:34:03.770 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Arbeiten_EG
2019-08-20 19:34:03.774 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Schlafen_vorne_Tuer
2019-08-20 19:34:03.777 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Schlafen_vorne_Fenster
2019-08-20 19:34:03.781 [INFO ] [smarthome.automation.shadowinglib.py] - Sun protection is already active: Rolladen_Schlafen_hinten_Tuer
2019-08-20 19:34:03.783 [INFO ] [smarthome.automation.shadowinglib.py] - Filled blinds data structures
2019-08-20 19:34:05.120 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/smartmeter_rules.py'
2019-08-20 19:34:05.474 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/test_push_rules.py'
2019-08-20 19:34:05.513 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'python/personal/test_rules.py'

Juelicher

Short update: The rule in question was again triggered twice at 18:07, the other rules seem to be OK. I restarted openhab and will monitor, what happens tomorrow.

I have no idea, what is so special with the time 18:07…

Hi,

today I created the following minimalistic test file (most imports are not needed, but for a first test I wanted to duplicate the imports from the files the error occurred). After that, I restarted openHAB completly:

from core.rules import rule
from core.triggers import when, CronTrigger
from org.eclipse.smarthome.core.types import UnDefType
from org.joda.time import DateTime
from org.slf4j import Logger, LoggerFactory
import math
from time import time

#import personal.mylib
#reload (personal.mylib)
#from personal.mylib import logTestVariable 

from personal.mylib import checkPostUpdate, checkSendCommand, checkSendCommandLog
from personal.mylib import getChangedSince, getHistoricState, getMinimumSince, getMinimumTimeSince, getMaximumSince, getMaximumTimeSince, getAverageSince
from personal.mylib import notifyMe


NULL  = UnDefType.NULL
UNDEF = UnDefType.UNDEF


log = LoggerFactory.getLogger("org.eclipse.smarthome.automation.measurement_rules.py")



@rule("Test cron trigger 1 - Jython")
@when("Time cron 41 7 0/2 * * ?") 
def testCronTrigger1(event):
    log.info("test cron trigger 1 was triggered ")


@rule("Test cron trigger 2 - Jython")
@when("Time cron 25 14 0/2 * * ?") 
def testCronTrigger1(event):
    log.info("test cron trigger 2 was triggered ")


@rule("Test cron trigger 3 - Jython")
@when("Time cron 30 21 0/1 * * ?") 
def testCronTrigger1(event):
    log.info("test cron trigger 3 was triggered ")

This resulted in the following log output:

Trigger 1:

2019-08-22 14:07:41.171 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 
2019-08-22 16:07:41.170 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 
2019-08-22 18:07:36.131 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 
2019-08-22 18:07:41.132 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 
2019-08-22 20:07:41.132 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 

Trigger 2:

2019-08-22 14:14:25.197 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 2 was triggered 
2019-08-22 16:14:25.197 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 2 was triggered 
2019-08-22 18:14:20.157 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 2 was triggered 
2019-08-22 18:14:25.157 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 2 was triggered 
2019-08-22 20:14:25.157 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 2 was triggered 

Trigger 3:

2019-08-22 14:21:30.219 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 15:21:30.219 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 16:21:30.219 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 17:21:25.179 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 17:21:30.180 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 18:21:30.181 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 19:21:30.181 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 
2019-08-22 20:21:30.181 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 3 was triggered 

So, in the time the rules where active until now, each of the rules was triggered twice once.

It’s very hard to imagine what might (mis)fire a consistent five seconds before the appointed time, but it must be a clue.

I’d cut down to one test job and enable quartz debug logging, see if the setup is weird.
I’ll place a bet it’s when the next due time is calculated at execution time, it plants a five-second-short in error, then when that arrives calculates the next due correctly (i.e. 5 secs later)

I did a “log:set DEBUG org.quartz.core”, but no hint regarding an error in the logs… I assume, that is, what you meant by “enable quartz debug logging”?!

Interestingly the error does not occur on every trigger.

I wasn’t really expecting it to announce an error, you’d see that anyway. It doesn’t know it’s messed up.
If those logs show you the rescheduling activity at each execution, then I’d think you have enough to open a github issue.

This is an excerpt from the log at the time the 18:07 cron job was triggered twice (the messages regarding Enocean are from the triggered rule).

2019-08-24 18:07:27.285 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-24 18:07:27.286 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-24 18:07:32.285 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2019-08-24 18:07:32.285 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-24 18:07:32.287 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-24 18:07:33.184 [INFO ] [smarthome.automation.system_rules.py] - Received KNX Watchdog reply
2019-08-24 18:07:37.247 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-24 18:07:37.286 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-24 18:07:37.286 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2019-08-24 18:07:37.318 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-24 18:07:41.433 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 was triggered 
2019-08-24 18:07:42.050 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!
2019-08-24 18:07:42.285 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2019-08-24 18:07:42.285 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-24 18:07:42.319 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-24 18:07:47.286 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2019-08-24 18:07:47.286 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction

Disappointing log really; it doesn’t mention anything about executing your rule or scheduling the next run.
I expected at least to see Calling execute on "some rule" … the lack of that is odd.

TRACE logging level would give us more, but I think perhaps you have a busy system and this extra work might throw more side effects. I note there is some jumbling of order in the log snippet, suggesting a fair bit of traffic from time to time at least.

However, poking around in old similar github issues, quartz may be the wrong place to look. It’s being the “clock” but something else does the scheduling. All terribly complicated, lists of candidates for scheduling, beyond me.

That used to be org.eclipse.smarthome.core.scheduler - but I’m guessing that is renamed in 2.5M2?? Need some proper developer advice here I think.
@kgoderis ?

I will try trace logging, system load should not be a big issue.

Today I created a DSL rules file with a cron trigger (all my other rules are Jython), so far this trigger works as expected, so this might be Jython and not a openHAB core problem. I will monitor this in the next few days.

There’s nothing specific to Jython when it comes to the trigger in your rule, so JavaScript, Groovy, UI based rules, etc. would behave the same. This could be an issue in the NGRE, but I have a lot of cron based rules and have never observed this.

1 Like

I activated the log level “TRACE” for Quartz, but that does not give any additional information.

I expected at least to see Calling execute on "some rule" … the lack of that is odd.

In addition I added the same cron trigger, that shows the problem, as a trigger for a DSL rule. In the following log the message “Calling execute on…” is printed for the DSL rule, but not for the Jython rule.

The DSL rule is executed only once, the Jython rule twice with the usual 5s delay between the function calls (these are the lines with “test cron trigger 1…”):

2019-08-26 18:07:32.285 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-26 18:07:32.285 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-26 18:07:32.319 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-26 18:07:37.149 [INFO ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication OK!
2019-08-26 18:07:37.285 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2019-08-26 18:07:37.285 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-26 18:07:37.318 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-26 18:07:37.568 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 Jython was triggered 
2019-08-26 18:07:41.001 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2019-08-26 18:07:41.002 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.test_cron_dsl.rules#Test cron trigger 1 - DSL#41 7 0/2 * * ?
2019-08-26 18:07:41.006 [INFO ] [smarthome.model.script.test_cron_dsl] - test cron trigger 1 DSL was triggered 
2019-08-26 18:07:41.568 [INFO ] [home.automation.measurement_rules.py] - test cron trigger 1 Jython was triggered 
2019-08-26 18:07:41.923 [WARN ] [home.automation.measurement_rules.py] - Enocean I humidity sensor communication failure!
2019-08-26 18:07:42.286 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2019-08-26 18:07:42.286 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction

Okay, makes sense. Does however suggest that quartz is treating the jobs differently, which is a surprise.

I think you need the debug for org.eclipse.smarthome.core.scheduler - or whatever it might be called now - to see the scheduling activity.

5 seconds early is so damn weird, good job it seems to be repeatable! I’d lay money it is the 16:07:41 event that messes up, but cannot see any magic about that time.

1 Like

Thanks for the hint, I will do some more testing when I am back home!

1 Like

Yesterday I updated to 2.5M3 und initially had the impression, that this solved the issue, as the error did not occur at the first 18:07 trigger after the update. But today the rule in question was again triggered twice at 18:07.

I tried to set the log level to TRACE, but did not succeed in getting more information, probably because I used the wrong names (I tried “org.eclipse.smarthome.core.internal.scheduler”, “org.eclipse.smarthome.core.internal.scheduler”, “org.openhab.core.scheduler”, “org.eclipse.smarthome.core.scheduler” and “org.openhab.core.internal.scheduler”)

For the time being I will implement a workaround, that checks the last time a rule was triggered.