search

eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
862 stars 786 forks source link

Rules using a CRON statement are triggered more then once #2545

Closed JueBag closed 7 years ago

JueBag commented 7 years ago

Starting with nigthly online build #611, and continued on #617 I'm observing that my cron triggered rules are executed twice or sometimes even more often. This behaviour started after the update for #611, stopped out off unknown reasons for 2-3 days and then reappeared again. The update to #617 didn't change that.

My cron-statement Time cron "50 7,17,27,37,47,57 * * * ?"

A typical log entry looks like:

14:17:50.007 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Benzinpreise'
14:17:50.019 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Benzinpreise'

During startup I observed that the RuleTriggerManager logged the registration of the cron more then once with entries like:

22:44:47.472 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Benzinpreise' with cron expression '50 7,17,27,37,47,57 * * * ?'

Other side information Each time I do update my rules files, I get a double log-entry about that, is that correct? (Rules-file is "price.rules", containing two rules using different cron statements)

14:32:54.246 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'price.rules'
14:32:54.908 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Benzinpreise#50 7,17,27,37,47,57 * * * ?'
14:32:54.913 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Tankstellendaten#50 3 0 * * ?'
14:32:54.927 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Benzinpreise' with cron expression '50 7,17,27,37,47,57 * * * ?'
14:32:54.938 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Tankstellendaten' with cron expression '50 3 0 * * ?'
14:32:55.056 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'price.rules'
14:32:55.460 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Benzinpreise#50 7,17,27,37,47,57 * * * ?'
14:32:55.463 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Tankstellendaten#50 3 0 * * ?'
14:32:55.477 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Benzinpreise' with cron expression '50 7,17,27,37,47,57 * * * ?'
14:32:55.487 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Tankstellendaten' with cron expression '50 3 0 * * ?'
kaikreuzer commented 7 years ago

It would be great (and especially helpful) if you could post a simple rule file with a single cron triggered rule that triggers very often and can be used to reproduce it.

Here is my example (using build 614 on a RasPi3):

pi@raspberrypi:/etc/openhab2/rules $ more test.rules 
rule Test
when
    Time cron "0/5 * * * * ?"
then
    logInfo("Test", "Test")
end

Log at startup:

2016-11-27 14:07:01.688 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
2016-11-27 14:07:02.915 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Started rule engine
2016-11-27 14:07:03.722 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 * * * * ?'
2016-11-27 14:07:04.732 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2016-11-27 14:07:08.855 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:13.280 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:13.314 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:13.314 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:15.014 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:15.081 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:20.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:20.012 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:25.003 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:25.010 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:30.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:30.016 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
2016-11-27 14:07:35.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
2016-11-27 14:07:35.011 [INFO ] [.eclipse.smarthome.model.script.Test] - Test

Looks all good to me.

JueBag commented 7 years ago

Your rule is working correctly, I figure you have entered into a running OH2 instance! When starting OH2 with already saved rule-file (I'm using your example inside the file "price.rules") the log looks like (I omitted parts of the log to shorten the list):

16:33:50.300 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Haus.items'
....
16:33:51.108 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'myopenhab.persist'
16:33:51.124 [DEBUG] [org.eclipse.smarthome.model.rule    ] - BundleEvent STARTING - org.eclipse.smarthome.model.rule
16:33:51.339 [DEBUG] [org.eclipse.smarthome.model.rule    ] - BundleEvent STARTED - org.eclipse.smarthome.model.rule
16:33:51.347 [DEBUG] [eclipse.smarthome.model.rule.runtime] - BundleEvent STARTING - org.eclipse.smarthome.model.rule.runtime
16:33:56.376 [DEBUG] [untime.internal.RuleRuntimeActivator] - Registered 'rule' configuration parser
16:33:57.228 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'price.rules'
16:33:57.881 [DEBUG] [eclipse.smarthome.model.rule.runtime] - ServiceEvent REGISTERED - {org.eclipse.smarthome.model.core.ModelParser}={component.name=org.eclipse.smarthome.model.rule.runtime, component.id=109, service.id=215, service.bundleid=126, service.scope=bundle} - org.eclipse.smarthome.model.rule.runtime
16:33:57.895 [DEBUG] [eclipse.smarthome.model.rule.runtime] - BundleEvent STARTED - org.eclipse.smarthome.model.rule.runtime
16:33:58.799 [DEBUG] [eclipse.smarthome.model.rule.runtime] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber, org.eclipse.smarthome.model.rule.runtime.RuleEngine}={component.name=org.eclipse.smarthome.model.ruleengine, component.id=108, service.id=217, service.bundleid=126, service.scope=bundle} - org.eclipse.smarthome.model.rule.runtime
16:33:58.843 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Started rule engine
**16:33:59.685 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 * * * * ?'**
16:34:00.429 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Haus.sitemap'
...

16:34:04.889 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:05.261 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
16:34:08.605 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
16:34:20.701 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:20.752 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:20.753 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:20.765 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:20.772 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:20.853 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
...

16:34:29.911 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:29.935 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:30.006 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:30.014 [INFO ] [.eclipse.smarthome.model.script.Test] - Test

....
16:34:42.386 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:42.386 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:42.394 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:42.394 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
...
...
16:34:45.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:45.014 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
...
16:34:46.595 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 * * * * ?'
16:34:50.006 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:50.011 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:55.748 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:55.755 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:55.772 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:55.780 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:34:55.781 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:34:55.789 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:00.006 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:00.016 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:00.027 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:00.038 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:05.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:05.013 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:05.014 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:05.022 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:10.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:10.011 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:10.022 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:10.022 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:15.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:15.011 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:35:15.015 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:35:15.024 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
...
Saving the price.rules file
...
16:38:17.696 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'price.rules'
16:38:17.977 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Test#0/5 * * * * ?'
16:38:17.999 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 * * * * ?'
16:38:18.130 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'price.rules'
16:38:18.453 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'price.rules#Test#0/5 * * * * ?'
16:38:18.482 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 * * * * ?'
16:38:20.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:26.800 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:26.822 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:38:26.822 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:38:30.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:30.012 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:38:35.003 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:35.010 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:38:40.003 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:40.014 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:38:45.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:38:45.013 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
...
Changing the rule to every minute
...
16:50:28.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:50:28.015 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:50:29.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:50:29.014 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:50:30.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:50:30.015 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:50:31.005 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'
16:50:31.017 [INFO ] [.eclipse.smarthome.model.script.Test] - Test
16:50:32.004 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test'

So it looks to me as if the problem only occurs when using the rules file unchanged since system started, a "touch" of the file (saving is enough) stops it.

[Edit:] Not only does the problem occur if the system is started, it reappears also on a running system if any change is made online, which is causing OH to stop parts (like BasicUI, HabPanel etc).

kaikreuzer commented 7 years ago

I figure you have entered into a running OH2 instance!

No, I didn't - my log was directly after a runtime restart. We should try to find out what is different on your system in comparison to mine. Is your prices.rules the ONLY rule file you have in it? Does it only contain this one rule that I posted?

JueBag commented 7 years ago

No, my price.rules file contains my two other rules that use cron statements. Both show the same faulty behaviour. Additionally I have other rules files, all without cron statements and all without the above posted problems. My compleye setup contains the UIs: Basic, Classic, Paper and HABPanel Bindings Sonos, Intertechno, Network Transformations JSONPath,Map, RegEx Persistence MapDB, RRD4J VoiceRSS, MyOpenHAB, Rest Documentation

kaikreuzer commented 7 years ago

So you confirm that my setup from above works as expected? What is the minimal change to it to make the problem appear then?

JueBag commented 7 years ago

Did I say something in that direction, not in my understanding. I see that on your system the problem does not show up. Besides the workaround of "touching" the rules file, I have so far not been able to find a reduced setup that doesn't show the problem. Will continue to search and will report findings asap.

JueBag commented 7 years ago

It is embarrassing for me, but it are the rules in my "price.rules" file. The problem occurs when I use my rules, it disappears when using the rule from @kaikreuzer. I did use those rules for some month without problems! I do need some more time to find the reason why the rules are causing that error, I will continue to search tomorrow and report. Here is the code one of the rules:

val String Tankstelle1_ID="3e563b17-f3fc-4a3d-b486-60d25e5948d5"
val String Tankstelle2_ID="bc01b1b9-b2b9-4f78-98ef-b7ee8d8a66a4"
val String Tankstelle3_ID="a53fff71-133c-48b1-84ba-20a9be6ec538"
val String API_Key="myAPIKey"
var String Status
var Number E10
var Number E5
var Number Diesel
var String TankstellenMarke
var String TankstellenStrasse
var String TankstellenOrt

rule "Benzinpreise"
when 
    Time cron "50 7,17,27,37,47,57 * * * ?"
then
    var String URL= "https://creativecommons.tankerkoenig.de/json/prices.php?ids=" + Tankstelle1_ID + "\," +Tankstelle2_ID + "\," + Tankstelle3_ID + "&apikey=" + API_Key
    logInfo ("Benzinpreise", "URL = {}", URL)
    var String json = sendHttpGetRequest(URL)
    var Number PreisGeschlossen=0
    logInfo("Benzinpreise","JSON-String = {}", json)
    if (json!=null)  {
        var Boolean  OK = transform("JSONPATH", "$.ok", json)
        if (OK=true) {
            Status = transform("JSONPATH", "$.prices." + Tankstelle1_ID + ".status", json)
            //logInfo("Benzinpreise", "Status = {}", Status)
            if (Status=="open") {
                E10 = transform("JSONPATH",  "$.prices." + Tankstelle1_ID + ".e10", json)
                E5  = transform("JSONPATH",  "$.prices." + Tankstelle1_ID + ".e5", json)
                Diesel  = transform("JSONPATH",  "$.prices." + Tankstelle1_ID + ".diesel", json)
                E10_1.postUpdate(E10.toString)
                E5_1.postUpdate(E5.toString)
                Diesel_1.postUpdate(Diesel.toString)
            }
            else {
            }
            Status = transform("JSONPATH", "$.prices." + Tankstelle2_ID + ".status", json)
            if (Status=="open") {
                E10 = transform("JSONPATH", "$.prices." + Tankstelle2_ID + ".e10", json)
                E5  = transform("JSONPATH", "$.prices." + Tankstelle2_ID + ".e5", json)
                Diesel  = transform("JSONPATH", "$.prices." + Tankstelle2_ID + ".diesel", json)
                E10_2.postUpdate(E10.toString)
                E5_2.postUpdate(E5.toString)
                Diesel_2.postUpdate(Diesel.toString)
              }
              else {

            }
            Status = transform("JSONPATH", "$.prices." + Tankstelle3_ID + ".status", json)
            if(Status=="open") {
                E10 = transform("JSONPATH",  "$.prices." + Tankstelle3_ID + ".e10", json)
                E5  = transform("JSONPATH",  "$.prices." + Tankstelle3_ID + ".e5", json)
                Diesel  = transform("JSONPATH",  "$.prices." + Tankstelle3_ID + ".diesel", json)
                E10_3.postUpdate(E10.toString)
                E5_3.postUpdate(E5.toString)
                Diesel_3.postUpdate(Diesel.toString)
            }
            else {
             }
        }
        else {
            logInfo("Benzinpreise", "OK = {}", OK)
            var String HttpError = transform("JSONPATH",  "$.message", json)
            logInfo("Benzinpreise", "HttpError = {}", HttpError)
        }
    }    
    else {
        logInfo("Benzinpreise", "Empty Return from HTTPRequest")        
    }

end
steand commented 7 years ago

@kaikreuzer

Hi Kai,

I have the same behavior. The rule is:

rule "Sun_workaround"
  when
        Time cron "0 */5 * * * ?"
  then
    logInfo("File", "SunW: Hallo")
    if (Sun_elevation.state >= -5.0 && Daylight.state == OFF) {
        logInfo("File", "SunW: Sonne augegangen")
        sendCommand(Daylight, ON)
    }

    if (Sun_elevation.state < -5.0 && Daylight.state == ON) {
        logInfo("File", "SunW: Sonne untergegangen")
        sendCommand(Daylight, OFF)
    }
end

The cron-job start's 2 times sometimes 3 times. After reloading of the rulefile it work normal. After shutdown and restart openhab2 there are two cron-jobs.

Extract (Only rules "SunW") from openhab.log:

####### Reload of rulefile

2016-11-29 11:10:29.854 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:10:30.039 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:10:36.354 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufegangen
2016-11-29 11:15:00.016 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:20:00.015 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:25:00.015 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

#### Switch on DEBUG org.quartz

2016-11-29 11:30:00.005 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:30:00.026 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:30:50.321 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:30:50.488 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:30:56.833 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufgeangen
2016-11-29 11:35:00.005 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:35:00.030 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

#### Restart openhab2 by systemctl 

2016-11-29 11:38:22.800 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SunWorkaround.rules'
2016-11-29 11:40:00.021 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:40:00.032 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:40:00.033 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:40:00.046 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:45:00.007 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:45:00.019 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:45:00.021 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:45:00.029 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:50:00.006 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:50:00.015 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:50:00.023 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:50:00.033 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:50:00.043 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufgeangen
2016-11-29 11:50:00.076 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufgeangen
2016-11-29 11:51:23.445 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SunWorkaround.rules'
2016-11-29 11:55:00.020 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:55:00.032 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 11:55:00.034 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:55:00.058 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 11:55:44.605 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:55:44.751 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 11:55:50.987 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufgeangen
2016-11-29 12:00:00.006 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:00:00.023 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

#### Restart openhab2 by systemctl 

2016-11-29 12:01:15.495 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SunWorkaround.rules'
2016-11-29 12:05:00.018 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:05:00.029 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:05:00.036 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 12:05:00.047 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

#### Reload rulefile

2016-11-29 12:06:00.456 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'SunWorkaround.rules'
2016-11-29 12:06:06.748 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Sonne aufgeangen
2016-11-29 12:10:00.007 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:10:00.020 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

#### Shutdown with console and start with systemctl

2016-11-29 12:13:38.950 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SunWorkaround.rules'
2016-11-29 12:15:00.017 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:15:00.029 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.SunWorkaround.rules#Sun_workaround#0 */5 * * * ?
2016-11-29 12:15:00.031 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo
2016-11-29 12:15:00.044 [INFO ] [.eclipse.smarthome.model.script.File] - SunW: Hallo

Sometimes the scheduler change by self to multiple starts. Furthermore I run my installation with DEBUG org.quartz. Maybe I will found out why.

Installation: RPI2 B: Linux rpi2 4.4.26-v7+ #915 Openhab2 #622

I hope it helps.

Regard Stefan

Edit: 13:35 I have test it on a clear system (VM: ubuntu).

rule TestMeCron
when
    Time cron "*/10 * * * * ?"
then
    logInfo("TestMeCron", "Hello")
end

and it works. I don't know why the problem exist on the RPI installation.

steand commented 7 years ago

@kaikreuzer @JueBag I think I have found the problem. After copy my rule to the clear system i had the same behavior: rule is start twice. In the rulefile was a missing end.


rule "Sun_workaround"
  when
        Time cron "0 */5 * * * ?"
  then
    logInfo("File", "SunW: Hallo")
    if (Sun_elevation.state >= -5.0 && Daylight.state == OFF) {
        logInfo("File", "SunW: Sonne aufgegangen")
        sendCommand(Daylight, ON)
    }

    if (Sun_elevation.state < -5.0 && Daylight.state == ON) {
        logInfo("File", "SunW: Sonne untergegangen")
        sendCommand(Daylight, OFF)
    }
end

rule "Sun_Startup"
  when
   System started 
  then
     if (Sun_elevation.state >= -5.0) {
        logInfo("File", "SunW: Sonne aufgeangen")
        sendCommand(Daylight, ON)
    }

    if (Sun_elevation.state < -5.0) {
        logInfo("File", "SunW: Sonne untergegangen")
        sendCommand(Daylight, OFF)
    }
<<<<<<<<<<<<<<<<<<<<<<< missing end

After I put in the end it works on both installations. My feeling is, if in the rulefile is a error (what the parser not found) the problem is coming up.

Regards Stefan

kaikreuzer commented 7 years ago

Thanks Stefan, this is a very good observation and can indeed explain the behavior! If a rule cannot be parsed, the whole file is re-parsed whenever new items or actions appear - possibly this re-parsing creates a new job for "correct" rules as well.

Can the others confirm that this is only happening in case of invalid rules?

JueBag commented 7 years ago

The problem on my side is different, it appears when the system is started (by "sudo systemctl start openhab2") and is gone when the rule is saved afterwards. During my tests I observed that the cron statements is scheduled once early during startup and some time after that (items have been restored and the login to myopenhab is performed) the cron statement is either scheduled again or removed and scheduled again. In first case the rule is triggereed twice afterwards, in the second case it is called only once. So far I could not find any trace what is causing that, I have tried removing comments, global variable and/or constant definitions ...... Still searching, will report

ghost commented 7 years ago

I think Stefan is on to something. Using Kai's rule above. When my system starts (same with build 611 and 623) I get:

2016-11-30 08:28:01.812 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 ?'

2016-11-30 08:28:26.469 [DEBUG] [e.internal.engine.RuleTriggerManager] - Removed scheduled cron job 'GeneralSecurity - Copy.rules#Test#0/5 ?' 2016-11-30 08:28:26.473 [DEBUG] [e.internal.engine.RuleTriggerManager] - Scheduled rule 'Test' with cron expression '0/5 ?'

2016-11-30 08:28:41.315 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test' 2016-11-30 08:28:41.417 [INFO ] [.eclipse.smarthome.model.script.Test] - Test 2016-11-30 08:28:50.006 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test' 2016-11-30 08:28:50.025 [INFO ] [.eclipse.smarthome.model.script.Test] - Test

i.e. the cron rule is scheduled then removed, then rescheduled. If the file has an error (e.g. missing end) then possibly the removals don't occur and it runs multiple times?

In addition - I did recently find that the last end had been dropped of some of my rule files and fixed it - just didn't connect this with rules running correctly after restart.

kaikreuzer commented 7 years ago

If the file has an error (e.g. missing end) then possibly the removals don't occur and it runs multiple times?

Yes, this was exactly my thought as well!

ghost commented 7 years ago

I have just confirmed this behaviour on my system. Removing the end from a simple rule file (i.e. only containing the Test rule example given above) makes all of the Cron rules in any of the rule files run multiple times

JueBag commented 7 years ago

Found my problem, it is the adding of "\" to the URL string. If I remove those (there are 2 instances) the rules is triggered only once. That character was added in order to "escape" the "," character.

[Edit:] Since my problem, does not really relate to the one reported by @steand, I think I'll hand over the control over this one to him. My problem was caused by a false (or oblsolete?) usage of an escape character.

maggu2810 commented 7 years ago

@JueBag You started the issue, so I think the issue is yours and you should close it if your problem is solved. If there is an additional problem of @steand that is still present, we should open a separate one.

JueBag commented 7 years ago

Understood. My problem was clearly caused by a changed behaviour of strings. The use of the escape character ("\") in a string caused the rule to be triggered twice. A change or save of the causing .rules file during the runtime of the OH instance stops the misbehaviour. Although this is a behaviour of OH that leaves room for discussion, I think this not worth an issue. So I'd like to close this one. Does anybody complain?

maggu2810 commented 7 years ago

All fine (for me)

kaikreuzer commented 7 years ago

Although this is a behaviour of OH that leaves room for discussion, I think this not worth an issue.

I actually think it is worth an issue (while maybe not a priority for fixing). But I can imagine that the same effect can happen, if rules are fully correct and just item or actions aren't existing when first being parsed.

To keep track of our discussion here, I entered #2580.