Rules stop executing after a while

Dave_D · February 10, 2018, 9:31pm

Hello,

i have an openHab 2.2 installation an my Raspberry 3.
Since a few weeks i have the abnormality that my Rules stops working after a few minutes/hours/days (sometime it stops after a few minutes sometime after 4 days).
After an restart of OH2, OH works again.

A few days ago i installed (fresh installation, i copied only my items/rules) OH2 on an ubuntu PC and the are the same Problems.
The log does not show any error but OH2 stops executing Rules (really all of them, Item changed base, Time base, really all Rules does not work). In the events log i can see that the Items change the state properly.

My OH2 Installation does not have a lot of addons only:
MySQL peristence
MQTT Action/Binding
Telegram Action
Weather Binding

I think it must be something with my Rules which cause this Problem.
How can i debug the Ruleengine from OH2?

Hast someone any idea what it could be?

greets, Dave

StefanMUC · February 10, 2018, 9:39pm

Hi Dave,

do you use Thread:sleep in your rules?
That’s a bad idea because OpenHAB can (per default) only execute five rules in parallel.
If that’s the case, rewrite your rules to use Timers, they don’t block other rules from executing. Se a simple example here: Restart my router on error (with manual trigger and inhibit)

Also see if this topic might help you: Rule execution delayed

StefanMUC

Dave_D · February 10, 2018, 9:42pm

Hey,

no i don’t use the sleep function.
Today the Rules execution died, with nearly no workload on OH, no items changed in this time.
But i have some Cron Rules.
This is are my Rule Files:

var String redpwmstring
var String greenpwmstring
var String bluepwmstring
var HSBType hsbvalue
var Timer startedtimer = null
/*
rule "sende eine Nachricht alle 10sec"
when
    Time cron "/10 * * * * ?"//
then
    logInfo("Cron every 10s", "Test")
    sendTelegram("SmartHomeError", "Test")
end
*/

rule "System Started"
when
    System started
then
    SystemStarting.sendCommand(ON)
    startedtimer = createTimer(now.plusMinutes(1), [| SystemStarting.sendCommand(OFF)])
    Boost_Thermostate_AutoTemp.sendCommand(5)
end

rule "Heartbeat"
when
     Time cron "0 0/30 * * * ?"
then
     logInfo("Heartbeat", "i'm alive")
     sendTelegram("SmartHomeError", "i'm alive")
end


rule "WZ Schiebetuer LED"
when
	Item WZ_Led_Schiebetuer_Picker received update
then
    if(SystemStarting.state == OFF) {
        logInfo("Rules", "WZ Schiebetuer LED")
        //WZ_Led_Schiebetuer_String.postUpdate("1023:0:1023")
        hsbvalue = WZ_Led_Schiebetuer_Picker.state as HSBType // sets hsbvalue to some kind of variable (int/float?) 
        
        logInfo("Testing", hsbvalue.toString)
        
        redpwmstring = (10*hsbvalue.red.intValue).toString// grabs just the red value out of hsbvalue and multiplies it time 10 so that it has a scale of 0-1000 for the PWM
	    greenpwmstring = (10*hsbvalue.green.intValue).toString//same as in red
	    bluepwmstring = (10*hsbvalue.blue.intValue).toString //same as in red
	    WZ_Led_Schiebetuer_String.postUpdate(redpwmstring + ":" + greenpwmstring + ":" + bluepwmstring)
    }
end

rule "WZ Schiebetür LED 2"
when
       Item WZ_Led_Schiebetuer_Selection received update
then
    if(SystemStarting.state == OFF) {
       logInfo("WZ_Schiebetür LED 2", WZ_Led_Schiebetuer_Selection.state.toString)
       switch WZ_Led_Schiebetuer_Selection.state.toString {
          case "0": WZ_Led_Schiebetuer_String.postUpdate("0:0:0")         //Aus
          case "1": WZ_Led_Schiebetuer_String.postUpdate("1024:0:0")      //Rot
          case "2": WZ_Led_Schiebetuer_String.postUpdate("0:1024:0")      //Grün
          case "3": WZ_Led_Schiebetuer_String.postUpdate("0:0:1024")      //Blau
          case "4": WZ_Led_Schiebetuer_String.postUpdate("1024:0:0")      //Rot
          case "5": WZ_Led_Schiebetuer_String.postUpdate("1024:0:0")      //Rot
          default:  WZ_Led_Schiebetuer_String.postUpdate("0:0:0")         //Aus
       }
    }
end

rule "Waschmaschine is an"
when
     Item WR_Strom_Waschmaschine changed 
then
    if(SystemStarting.state == OFF) {
        // logInfo("Rules", "Waschmaschine ist an")
        if (WR_Status_Waschmaschine.state == OFF) { 
            WR_Status_Waschmaschine.postUpdate(ON)
            logInfo("Waschmaschine ist an", WR_Strom_Waschmaschine.state.toString)
        } 
        //WR_Letzte_Verbrauch_Waschmaschine.postUpdate((WR_Strom_Waschmaschine.state as DecimalType))
    }
end

rule "Trockner is an"
when
     Item WR_Strom_Trockner changed
then
    if(SystemStarting.state == OFF) {
        //logInfo("Rules", "WR_Strom_Trockner changed"+WR_Status_Trockner.state.toString)
        if (WR_Status_Trockner.state == OFF) {
            WR_Status_Trockner.postUpdate("ON")
        }
        //WR_Letzte_Verbrauch_Waschmaschine.postUpdate((WR_Strom_Waschmaschine.state as DecimalType))
    }
end

rule "Waschmaschine/Trockner ist aus"
when
     Time cron "0 0/1 * * * ?"
then 
    if(SystemStarting.state == OFF) {
        //logInfo("Trovkner ist aus", WR_Strom_Trockner.lastUpdate("mysql").toString)
        if (WR_Status_Waschmaschine.state == ON) {
            //var DateTime dtWaschmaschine  = parse(WR_Strom_Waschmaschine.lastUpdate("mysql").toString)
            if (!WR_Strom_Waschmaschine.changedSince(now.minusMinutes(5), "mysql") && WR_Strom_Waschmaschine.state < 20) {
            //if (now.minusMinutes(5).compereTo(dtWaschmaschine) > 0) {
                WR_Status_Waschmaschine.postUpdate("OFF")
                logInfo("Waschmaschine ist aus", WR_Strom_Waschmaschine.lastUpdate("mysql").toString)
                logInfo("Waschmaschine ist aus", WR_Strom_Waschmaschine.changedSince(now.minusMinutes(5), "mysql").toString)
                logInfo("Waschmaschine ist aus", WR_Strom_Waschmaschine.changedSince(now.minusSeconds(1), "mysql").toString)
            }
        }
        
        if (WR_Status_Trockner.state == ON) {
            //var DateTime dtTrocknere = parse(WR_Strom_Trockner.lastUpdate("mysql").toString)
            if (!WR_Strom_Trockner.changedSince(now.minusMinutes(5), "mysql") && WR_Strom_Trockner.state < 4) {
            //if (now.minusMinutes(5).compereTo(dtTrockner) > 0) {
                WR_Status_Trockner.postUpdate("OFF")
                logInfo("Trockner ist aus", WR_Strom_Trockner.lastUpdate("mysql").toString)
                logInfo("Trockner ist aus", WR_Strom_Trockner.changedSince(now.minusMinutes(5), "mysql").toString)
                logInfo("Trockner ist aus", WR_Strom_Trockner.changedSince(now.minusSeconds(1), "mysql").toString)
            }
        }
    }
end

rule "Waschmaschine Nachricht"
when
     Item WR_Status_Waschmaschine changed
then
    if(SystemStarting.state == OFF) {
        logInfo("Rules", "Waschmaschine Nachricht")
        if (WR_Status_Waschmaschine.state == ON) {
            sendTelegram("SmartHomeError", "Waschmaschine ist angelaufen.")  
        } else {
            sendTelegram("SmartHomeError", "Waschmaschine ist fertig.")
        }
    }
end

rule "Trockner Nachricht"
when
     Item WR_Status_Trockner changed
then
    if(SystemStarting.state == OFF) {
        logInfo("Rules", "Trockner Nachricht")
        if (WR_Status_Trockner.state == ON) {
            sendTelegram("SmartHomeError", "Trockner ist angelaufen.")
        } else {
            sendTelegram("SmartHomeError", "Trockner ist fertig.")
        }
    }
end

rule "Handy Anwesenheit"
when
        Item Handy_David_BT_Ping changed or
        Item Handy_Miriam_BT_Ping changed or
        Item Handy_David_Wifi_Ping changed /*or
        Item Handy_Miriam_Wifi_Ping changed */
then
        logInfo("Handy Anwesenheit", "juhu es läuft")
        if(SystemStarting.state == OFF) {
                if (Handy_David_BT_Ping.state == "ON" || Handy_Miriam_BT_Ping.state == "ON") {
                        // Alarme ausschalten
                        Handy_Online_Status.postUpdate(ON)
                } else {
                        // Alarme einschlaten
                        Handy_Online_Status.postUpdate(OFF)
                }
        }
end

rule "Jemand zuhause"
when 
     Item Handy_Online_Status changed
then
     if(SystemStarting.state == OFF) {
        if (Handy_Online_Status.state == ON) {
                // Alarme ausschalten
                // wz
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_off?module=HttpSwitcher.29")
                // ez
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_off?module=HttpSwitcher.31")
                // gz
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_off?module=HttpSwitcher.33")

                logInfo("Keiner zuhause Meldungen", "Hausalarm ist deaktiviert.")
                sendTelegram("SmartHomeError", "Hausalarm ist deaktiviert.")
        } else {
                // Alarme starten
                // wz
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_on?module=HttpSwitcher.29")
                // ez
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_on?module=HttpSwitcher.31")
                // gz
                sendHttpGetRequest("http://192.168.1.188:10090/http_switcher_on?module=HttpSwitcher.33")

                logInfo("Keiner zuhause Meldungen", "Hausalarm ist aktiviert.")
                sendTelegram("SmartHomeError", "Hausalarm ist aktiviert.")
        }
     }
end

/*
rule "sende eine Nachricht alle 120sec"
when
    Time cron "0 * * * * ?"
then
    logInfo("Cron every 120s", "Test")
    sendTelegram("SmartHomeError", "Test")
end
*/

rule "Kameras Fehler"
when
        Item CAM_Error received update
then
    if(SystemStarting.state == OFF) {
   //     itemValue = CAM_Error.state
    //    logInfo("Testing","This is a log entry of type Info!")
        switch CAM_Error.state {
            case "1":
                 sendTelegram("SmartHomeError", "Kamerafehler im Garten.")
        }
    }
end

/*
rule "Gartenbesuch CAM"
when
        Item CAM_Garten_Besuch received update
then
   //     itemValue = CAM_Error.state
    //    logInfo("Testing","This is a log entry of type Info!")
        switch CAM_Garten_Besuch.state {
            case "1": { //?resolution=1920x1080
                 //sendTelegram("SmartHomeMessages", "Ein Beuscher oder Post ist da.")
                 sendTelegramPhoto("SmartHomeMessages", "http://192.168.1.188:10090/image20.jpg?resolution=1920x1080", "Ein Besucher oder Post ist da.")
            }
            default:
                continue
        }
end*/

rule "Cam Bewegungen"
when 
        Item CAM_Bewegung received update 
then
    if(SystemStarting.state == OFF) {
        if(CAM_Bewegung.state !="clear") {
                switch CAM_Bewegung.state {
                        case "futter": {
                                logInfo("CAM_Bewegung", "futter")
                                sendTelegramPhoto("SmartHomeMessages", "http://192.168.1.188:10090/image19.jpg?resolution=1280x720", "Katzen sind am Naschen")
                        }
                        case "garten": {
                                logInfo("CAM_Bewegung", "garten")
                                sendTelegramPhoto("SmartHomeMessages", "http://192.168.1.188:10090/image20.jpg?resolution=1920x1080", "Ein Besucher oder Post ist da.")
                        }
                        case "alarm_wz": {
                                logInfo("CAM_Bewegung", "alarm_wz")
                                sendTelegramPhoto("SmartHomeError", "http://192.168.1.188:10090/image17.jpg?resolution=1920x1080", "Hausalarm: Bewegung im Wohnzimmer erkannt.")
                        }
                        case "alarm_gz": {
                                logInfo("CAM_Bewegung", "alarm_gz")
                                sendTelegramPhoto("SmartHomeError", "http://192.168.1.188:10090/image18.jpg?resolution=1920x1080", "Hausalarm: Bewegung im Gästezimmer erkannt.")
                        }
                        case "alarm_ez": {
                                logInfo("CAM_Bewegung", "alarm_ez")
                                sendTelegramPhoto("SmartHomeError", "http://192.168.1.188:10090/image16.jpg?resolution=1920x1080", "Hausalarm: Bewegung im Esszimmer erkannt.")
                        }
                        default: {
                                logInfo("CAM_Bewegung", "Unbekannter Status: " + CAM_Bewegung.state.toString)
                        }
                }  
                CAM_Bewegung.postUpdate("clear");
        }
    }
end

var	Timer	boost_timer = null 
var 	DateTime boost_started 

rule "Heizungsboost Automatik"
when
        Item Boost_Thermostate_AutoTemp changed
then
    if(SystemStarting.state.toString == "OFF") {
        if(Boost_Thermostate_AutoTemp.state > 5) {
            logInfo("Heizungsboost Automatik", "Wurde auf "+Boost_Thermostate_AutoTemp.state.toString+"°C eingeschaltet")
            boost_started = now
            Thermostate.members.forEach[xItem|
			    xItem.sendCommand(Boost_Thermostate_AutoTemp.state.toString)
	    ]
            boost_timer = createTimer(now.plusMinutes(120)) [|
                logInfo("Heizungsboost Automatik", "Wurde ausgeschaltet, und Thermostate werden auf den Ursprungswert zurückgesetzt.")
                Thermostate.members.forEach[xItem|
                        xItem.sendCommand(xItem.historicState(boost_started).state.toString)
                ]
                Boost_Thermostate_AutoTemp.sendCommand(5)
            ]
        }
    }
end

rule "Heizung Nachtmodus"
when 
        Time cron "0 0 22 * * ?" // at 22 o'clock
        //Time cron "*/50 * * * * ?"
then
    if(SystemStarting.state.toString == "OFF") {
        if (Wetter_heute_Temp_Min.state < 12) {
                logInfo("Heizung Nachtmodus", Thermostate.state.toString)
                sendCommand(Thermostate, "18")
                sendTelegram("SmartHomeMessages", "Die Heizung war noch an und wurde in den Nachtmodus versetzt (18°C).")
        } else {
                logInfo("Heizung Nachtmodus", Thermostate.state.toString)
                sendCommand(Thermostate, "5")
                sendTelegram("SmartHomeMessages", "Die Heizung war noch an und wurde ausgemacht.")
        }
        if(boost_timer !== null) {
             boost_timer.cancel()
        }
    }
end

rule "Heizung Tagesmodus"
when 
        Time cron "0 0 9 * * ?" // at 22 o'clock
        //Time cron "*/50 * * * * ?"
then
    if(SystemStarting.state.toString == "OFF") {
        logInfo("Heizung Tagmodus", "heute temp: "+Wetter_heute_Temp_Max.state.toString)
        if (Wetter_heute_Temp_Max.state < 15) {
                logInfo("Heizung Tagmodus", "21")
                sendCommand(Thermostate, "21")
        } else {
                logInfo("Heizung Tagmodus", "5")
                sendCommand(Thermostate, "5")
        }
    }
end

/*
rule "WZ Command Abfangen"
when 
        Item WZ_Thermostat_AutoTemp received command
then
        //sendCommand(WZ_Thermostat_AutoTemp, WZ_Thermostat_AutoTemp.state.toString + 5)
        logInfo("Testing", "WZ received Command")
end
*/

Sascha_Billian · February 10, 2018, 10:13pm

I’ve had a similar issue when all of my cron rules stopped working:

I still do not know exactly what was the root cause, but since i have moved my variables so that they are declared inside of the rule this error is gone now.

So you could also test and move the following variable declarations to be inside of a rule:

var String redpwmstring
var String greenpwmstring
var String bluepwmstring
var HSBType hsbvalue
var Timer startedtimer = null

Dave_D · February 10, 2018, 10:37pm

ok thanks, i try this.

But in the second rules file i need "var DateTime boost_started " as a global variable.

Edit:
Ok i merged my two rules and now i don’t have any global variables.
We will see if it run stable now.

Dave_D · February 11, 2018, 4:37pm

ok it crushes again between 13:15 and 13:30.
I have an Heartbeat Rule which say “i’m alive” every 30 minutes.

2018-02-11 12:00:00.001 [INFO ] [pse.smarthome.model.script.Heartbeat] - i'm alive
2018-02-11 12:22:06.243 [INFO ] [.smarthome.model.script.CAM_Bewegung] - futter
2018-02-11 12:30:00.003 [INFO ] [pse.smarthome.model.script.Heartbeat] - i'm alive
2018-02-11 13:00:00.002 [INFO ] [pse.smarthome.model.script.Heartbeat] - i'm alive
2018-02-11 13:15:30.051 [INFO ] [me.model.script.Waschmaschine ist an] - 78.07
2018-02-11 13:15:30.509 [INFO ] [eclipse.smarthome.model.script.Rules] - Waschmaschine Nachricht

i try to delete the Caches and restart OH2.

Have someone other idea?

Sascha_Billian · February 11, 2018, 8:02pm

Phew, sorry that my first guess didn’t work out.

Try to narrow down which rules are causing the problem.

Disable all cron based rules except your test rule.
Enable debugging of the scheduler in the karaf console

log:set DEBUG org.quartz.core

Do you still have this problem then?
For me it dissappeared, so that gave me a hint that something in my rules went terribly wrong.
After enabling / disabling rules, i’ve realized that the only rule with a bit of more advanced programming caused this.

In my case I still think that inside my lambda expression a there was some kind of mistake. After making sure that the items/states which are accessed inside of the lambda expression are initialized, it is gone now.

But still the root cause is unknown…

Dave_D · February 12, 2018, 8:08am

Ok, thanks, i will try it if it crashed again.

I have merged my Cron rules, so i have only 2 now, every 5 Minutes and every Hour and no global variables.
I also deleted all Caches and restarted OH2.

If it crashes again i will deactivate all cron Rules and try to locate the “broken” rule.

Dave_D · February 25, 2018, 9:14am

In the last two weeks i have testet my rules.

The result ist, every cron based rule produce after a while my problem. Without any cron rule, all rules run now a week without any problems.

Is something wrong with my cron rule declaration??

Dave_D · March 17, 2018, 3:52pm

no one has any other idea?

vzorglub · March 17, 2018, 4:09pm

Maybe create a cron job in the cron tab
Google it
And check if that fires. If it stops, you have a problem with cron not openHAB
if it doesn’t raise an issue on github

Dave_D · March 17, 2018, 7:15pm

i have already crons in crontab on my pc and they works fine.

i will open an issue on github

StefanMUC · March 24, 2018, 6:52am

Here’s the issue: Rules stops executing after a while #660

Nicholas_Waterton · May 14, 2018, 12:19pm

I’m adding to this thread here, because I have been seeing similar problems over the last few weeks. I’m running OH 2.2 release, and after a few days rules simply stop triggering. My cron rules still work, and events are coming in, but all rules that are being triggered by events stop.

No error, or anything. It mostly happens at about 3:30 am (don’t know why), but I have had it happen at other times.

I’m running on a quad core proliant gen 8 server, with thread pool set to 50.

I can’t pinpoint any one cause - but I have set up a cron rule, that detects when rules stops triggering, and logs it (it only runs every 5 minutes though, so it takes a little while to detect that rules have stopped).

Here is my rules log output when this happens:

14-May-2018 03:34:14.568 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Parse Json Data from MCT 111BC Module'
14-May-2018 03:34:14.569 [INFO ] [pse.smarthome.model.script.JSON Data] - Received from module: MCThings111BC : {"time":"1526268850473","Uptime":13251347,"UptimeString":"153:8:55:47","BatteryVoltage":3596,"Temperature":24.250000,"LowBattery":false}
14-May-2018 03:34:14.570 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 0 : "time"->"1526268850473"
14-May-2018 03:34:14.570 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 1 : "Uptime"->13251347
14-May-2018 03:34:14.570 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 2 : "UptimeString"->"153:8:55:47"
14-May-2018 03:34:14.571 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 3 : "BatteryVoltage"->3596
14-May-2018 03:34:14.571 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 4 : "Temperature"->24.250000
14-May-2018 03:34:14.571 [INFO ] [pse.smarthome.model.script.JSON Data] - item: 5 : "LowBattery"->false
14-May-2018 03:34:14.572 [INFO ] [pse.smarthome.model.script.JSON Data] - Converted to JSON List: ["time":"1526268850473", "Uptime":13251347, "UptimeString":"153:8:55:47", "BatteryVoltage":3596, "Temperature":24.250000, "LowBattery":false] of size: 6
14-May-2018 03:34:14.572 [INFO ] [pse.smarthome.model.script.JSON Data] - Converted to HashMAP: {Temperature=24.250000, time=1526268850473, UptimeString=153:8:55:47, Uptime=13251347, LowBattery=false, BatteryVoltage=3596}
14-May-2018 03:34:14.572 [INFO ] [pse.smarthome.model.script.JSON Data] - Posting: 24.250000 to: MCThings111BCTemperature
14-May-2018 03:34:14.573 [INFO ] [pse.smarthome.model.script.JSON Data] - Received time_string: 1526268850473
14-May-2018 03:34:14.573 [INFO ] [pse.smarthome.model.script.JSON Data] - Received time, milliseconds: 1526268850473
14-May-2018 03:34:14.573 [INFO ] [pse.smarthome.model.script.JSON Data] - posting json timestamp: 2018-05-13T23:34:10.473-04:00 to: MCThings111BCJsonTimestamp
14-May-2018 03:34:14.575 [INFO ] [pse.smarthome.model.script.JSON Data] - Posting: 153:8:55:47 to: MCThings111BCUptimeString
14-May-2018 03:34:14.575 [INFO ] [pse.smarthome.model.script.JSON Data] - Posting: 13251347 to: MCThings111BCUptime
14-May-2018 03:34:14.576 [INFO ] [pse.smarthome.model.script.JSON Data] - Posting: CLOSED to: MCThings111BCLowBattery
14-May-2018 03:34:14.576 [INFO ] [pse.smarthome.model.script.JSON Data] - Posting: 3596 to: MCThings111BCBatteryVoltage
14-May-2018 03:34:14.577 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Temperature'
14-May-2018 03:34:14.577 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Last Updated'
14-May-2018 03:34:14.578 [INFO ] [e.smarthome.model.script.Last Update] - MCThings111BCLastUpdate DateTimeItem updated at: Mon 03:34:14
14-May-2018 03:34:14.578 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Status'
14-May-2018 03:34:14.578 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Status'
14-May-2018 03:34:14.579 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Battery Monitor (111BC) Status'
14-May-2018 03:34:15.615 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Monitor LED Current'
14-May-2018 03:34:19.299 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Compute garden humidex'
14-May-2018 03:34:19.301 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Compute garden humidex'
14-May-2018 03:34:20.724 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Glass Break Received Update'
14-May-2018 03:34:20.725 [INFO ] [e.smarthome.model.script.Last Update] - GlassBreakDetectorLastUpdate DateTimeItem updated at: Mon 03:34:20
14-May-2018 03:34:20.725 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Glass Break Detected'
14-May-2018 03:34:20.725 [INFO ] [e.smarthome.model.script.Glass Break] - Glass break Detector changed to: NULL
14-May-2018 03:34:20.725 [INFO ] [e.smarthome.model.script.Glass Break] - Glass break Sensor changed to: NULL
14-May-2018 03:34:20.725 [INFO ] [e.smarthome.model.script.Glass Break] - Glass break Alarm General changed to: OFF
14-May-2018 03:34:20.836 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Glass Break Received Update'
14-May-2018 03:34:20.837 [INFO ] [e.smarthome.model.script.Last Update] - GlassBreakDetectorLastUpdate DateTimeItem updated at: Mon 03:34:20
14-May-2018 03:34:21.454 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Update In Use Light Sensor Back Garden'
14-May-2018 03:34:25.512 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Monitor LED Current'
14-May-2018 03:34:26.117 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Status'
14-May-2018 03:34:26.118 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'MCThings 111BC Basement Entry Battery Monitor Status'
14-May-2018 03:34:28.146 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Real Item Changed'
14-May-2018 03:35:00.000 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Reset homekit lock'
14-May-2018 03:35:00.000 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test Rules operation'
14-May-2018 03:35:00.001 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: True
14-May-2018 03:35:00.001 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule 'Reset homekit lock': null
14-May-2018 03:36:00.001 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test Rules operation'
14-May-2018 03:36:00.002 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: False
14-May-2018 03:36:00.002 [INFO ] [eclipse.smarthome.model.script.Rules] - Rules have stopped triggering
14-May-2018 03:36:00.176 [DEBUG] [model.script.actions.ScriptExecution] - Scheduled code for execution at 2018-05-14T15:36:00.176-04:00
14-May-2018 03:37:00.001 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test Rules operation'
14-May-2018 03:37:00.002 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: False

This is the full openhab.log for that time:

2018-05-14 03:34:28.080 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'dining_room_humidity' with state '35' in rrd4j database
2018-05-14 03:34:28.099 [DEBUG] [nternal.rest.NestStreamingRestClient] - Received 'put' event, data: {"path":"/","data":{"devices":{"thermostats":{"1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X":{"humidity":35,"locale":"en-GB","temperature_scale":"C","is_using_emergency_heat":false,"has_fan":true,"software_version":"5.8-8","has_leaf":false,"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0_n4GuwLjLAw","device_id":"1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X","name":"Dining Room","can_heat":true,"can_cool":true,"target_temperature_c":23.0,"target_temperature_f":73,"target_temperature_high_c":24.0,"target_temperature_high_f":75,"target_temperature_low_c":22.0,"target_temperature_low_f":72,"ambient_temperature_c":22.0,"ambient_temperature_f":72,"away_temperature_high_c":28.0,"away_temperature_high_f":83,"away_temperature_low_c":18.0,"away_temperature_low_f":65,"eco_temperature_high_c":28.0,"eco_temperature_high_f":83,"eco_temperature_low_c":18.0,"eco_temperature_low_f":65,"is_locked":false,"locked_temp_min_c":20.0,"locked_temp_min_f":68,"locked_temp_max_c":22.0,"locked_temp_max_f":72,"sunlight_correction_active":false,"sunlight_correction_enabled":true,"structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","fan_timer_active":true,"fan_timer_timeout":"1970-01-01T00:00:00.000Z","fan_timer_duration":15,"previous_hvac_mode":"","hvac_mode":"heat-cool","time_to_target":"~0","time_to_target_training":"ready","where_name":"Dining Room","label":"","name_long":"Dining Room Thermostat","is_online":true,"last_connection":"2018-05-14T07:34:24.620Z","hvac_state":"off"}},"smoke_co_alarms":{"8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X":{"locale":"en-US","structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","software_version":"3.1.4rc3","where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0odBTxTsbLKg","device_id":"8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X","where_name":"Upstairs","name":"Upstairs","name_long":"Upstairs Nest Protect","is_online":true,"last_connection":"2018-05-14T07:12:50.007Z","battery_health":"ok","co_alarm_state":"ok","smoke_alarm_state":"ok","ui_color_state":"green","is_manual_test_active":false,"last_manual_test_time":"2018-04-11T20:57:38.000Z"},"8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X":{"name":"Basement","locale":"en-US","structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","software_version":"3.1.4rc3","where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3FLJ8DEciPxQ","device_id":"8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X","where_name":"Basement","name_long":"Basement Nest Protect","is_online":true,"last_connection":"2018-05-14T07:28:03.901Z","battery_health":"ok","co_alarm_state":"ok","smoke_alarm_state":"ok","ui_color_state":"green","is_manual_test_active":false,"last_manual_test_time":"2018-04-11T20:58:08.000Z"},"8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X":{"name":"Master Bedroom","locale":"en-US","structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","software_version":"3.1.4rc3","where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0zdeHTwYOSzQ","device_id":"8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X","where_name":"Master Bedroom","name_long":"Master Bedroom Nest Protect","is_online":true,"last_connection":"2018-05-13T09:54:50.262Z","battery_health":"ok","co_alarm_state":"ok","smoke_alarm_state":"ok","ui_color_state":"green","is_manual_test_active":false,"last_manual_test_time":"2018-04-11T20:58:08.000Z"},"8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X":{"name":"Hallway","locale":"en-US","structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","software_version":"3.1.4rc3","where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Qaq6Lx4pdGw","device_id":"8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X","where_name":"Hallway","name_long":"Hallway Nest Protect","is_online":true,"last_connection":"2018-05-14T07:27:49.094Z","battery_health":"ok","co_alarm_state":"ok","smoke_alarm_state":"ok","ui_color_state":"green","is_manual_test_active":false,"last_manual_test_time":"2018-04-11T20:58:08.000Z"}}},"structures":{"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA":{"smoke_co_alarms":["8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X","8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X","8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X","8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X"],"name":"Home","country_code":"CA","time_zone":"America/Toronto","away":"home","thermostats":["1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X"],"structure_id":"9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA","co_alarm_state":"ok","smoke_alarm_state":"ok","wheres":{"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0mM4BlNe1TRQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0mM4BlNe1TRQ","name":"Attic"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3ccPkgs1sspw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3ccPkgs1sspw","name":"Back Door"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3onmDw4TT6ZQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3onmDw4TT6ZQ","name":"Backyard"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3FLJ8DEciPxQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3FLJ8DEciPxQ","name":"Basement"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3o5HrFfpd2Nw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3o5HrFfpd2Nw","name":"Bathroom"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2QL5v41HS1fQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2QL5v41HS1fQ","name":"Bedroom"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT1dV32SltYJWQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT1dV32SltYJWQ","name":"Deck"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2n5_KbWdE6rg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2n5_KbWdE6rg","name":"Den"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0_n4GuwLjLAw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0_n4GuwLjLAw","name":"Dining Room"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT1oVWjd8Ex4dg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT1oVWjd8Ex4dg","name":"Downstairs"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2hru6sFEYjUw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2hru6sFEYjUw","name":"Driveway"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0xRpYZ4QMpIg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0xRpYZ4QMpIg","name":"Entryway"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2CBVUk5u3D7g":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2CBVUk5u3D7g","name":"Family Room"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT05MeEeCndvkg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT05MeEeCndvkg","name":"Front Door"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3h3SOh2QjejQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3h3SOh2QjejQ","name":"Front Yard"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2a4T1M8ouMXg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2a4T1M8ouMXg","name":"Garage"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Wgt1j-K8PiQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Wgt1j-K8PiQ","name":"Guest House"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2V0p3nUzlJVA":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2V0p3nUzlJVA","name":"Guest Room"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Qaq6Lx4pdGw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Qaq6Lx4pdGw","name":"Hallway"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0dH2sJBC_QjQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0dH2sJBC_QjQ","name":"Kids Room"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2AQ3L4Dq52Fw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2AQ3L4Dq52Fw","name":"Kitchen"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3fRrIw-7lgrQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3fRrIw-7lgrQ","name":"Living Room"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0zdeHTwYOSzQ":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0zdeHTwYOSzQ","name":"Master Bedroom"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Xyjrff4wqdA":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3Xyjrff4wqdA","name":"Office"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0SWS-x8CrA7A":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0SWS-x8CrA7A","name":"Outside"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3-utsyfoWVdA":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT3-utsyfoWVdA","name":"Patio"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0ujcN9WMedww":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0ujcN9WMedww","name":"Shed"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2A4vW6hL16qw":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT2A4vW6hL16qw","name":"Side Door"},"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0odBTxTsbLKg":{"where_id":"S0hMrb9lbmOOY87fdBLOoB-tZaXq9zh64cUs0gTUgT0odBTxTsbLKg","name":"Upstairs"}}}},"metadata":{"access_token":"c.yK9vahY7O6Lq4QMBKyHMJRLFyOcbbY0fOapNCqQT0r73UJIXUPeJYnIqvmHoYnZUYn5g0JTRT2PCHrlUt9yF1f2ygfxkul48ikxSQSp2Ku36yagfdzKJAGwo4jh7TZPC5No6xFj4ZMGHc8Yd","client_version":1,"user_id":"z.1.1.lwQVaC7IEn51rvBZPQrH59GldiS3necyiEwI3VKSbuw="}}}
2018-05-14 03:34:28.099 [DEBUG] [nternal.rest.NestStreamingRestClient] - Data has changed (or initial data sent)
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:thermostat:2e8429ee:1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X, properties={firmwareVersion=5.8-8, deviceId=1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Dining Room Thermostat, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268099]
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:thermostat:2e8429ee:1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X, properties={firmwareVersion=5.8-8, deviceId=1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Dining Room Thermostat, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268099]
2018-05-14 03:34:28.100 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for thermostat
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Upstairs Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Upstairs Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for smoke detector
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Basement Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Basement Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for smoke detector
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Master Bedroom Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Master Bedroom Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.100 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for smoke detector
2018-05-14 03:34:28.101 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Hallway Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.101 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:smoke_detector:2e8429ee:8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X, properties={firmwareVersion=3.1.4rc3, deviceId=8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X}, representationProperty=deviceId, flag=NEW, label=Hallway Nest Protect, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268100]
2018-05-14 03:34:28.101 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for smoke detector
2018-05-14 03:34:28.101 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X is not handling update for 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X
2018-05-14 03:34:28.101 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X is not handling update for 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X
2018-05-14 03:34:28.101 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Updating smoke detector 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X
2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X is not handling update for 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X
2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X is not handling update for 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X
2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X is not handling update for 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X
2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X is not handling update for 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X
2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Updating smoke detector 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X
2018-05-14 03:34:28.103 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X is not handling update for 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X
2018-05-14 03:34:28.103 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Updating smoke detector 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X
2018-05-14 03:34:28.103 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X is not handling update for 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X is not handling update for 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Updating smoke detector 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X is not handling update for 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X is not handling update for 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X is not handling update for 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_C-7YHfxZDciriEqXFuKc3X is not handling update for 8DPl0FPVZ_D5iDYvVC6mobiEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_C-7YHfxZDciriEqXFuKc3X is not handling update for 8DPl0FPVZ_Bo3v0uQN7fDriEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_C-7YHfxZDciriEqXFuKc3X is not handling update for 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_C-7YHfxZDciriEqXFuKc3X is not handling update for 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X
2018-05-14 03:34:28.104 [DEBUG] [g.nest.handler.NestThermostatHandler] - Updating thermostat 1jI-LvQvFyOH19V0pvhvs7iEqXFuKc3X
2018-05-14 03:34:28.108 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'dining_room_ambient_temperature_c' with state '22.0' in rrd4j database
2018-05-14 03:34:28.108 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:structure:2e8429ee:9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA, properties={structureId=9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA}, representationProperty=structureId, flag=NEW, label=Home, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268107]
2018-05-14 03:34:28.108 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - thingDiscovered: DiscoveryResult [thingUID=nest:structure:2e8429ee:9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA, properties={structureId=9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA}, representationProperty=structureId, flag=NEW, label=Home, bridgeUID=nest:account:2e8429ee, ttl=-1, timestamp=1526283268107]
2018-05-14 03:34:28.108 [DEBUG] [ernal.discovery.NestDiscoveryService] - thingDiscovered called for structure
2018-05-14 03:34:28.108 [DEBUG] [ng.nest.handler.NestStructureHandler] - Updating structure 9AY0QSwA9NI6NBmBKWwpk6v8xIwHbh7zqN5wtLN1Bu63Tk5oOFPDrA
2018-05-14 03:34:28.146 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Real Item Changed'
2018-05-14 03:34:28.199 [DEBUG] [nternal.rest.NestStreamingRestClient] - Received 'keep-alive' event, data: null
2018-05-14 03:34:28.199 [DEBUG] [nternal.rest.NestStreamingRestClient] - Received message to keep connection alive
2018-05-14 03:34:29.142 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'dining_room_ambient_temperature_c' with state '22.0' in rrd4j database
2018-05-14 03:34:29.179 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'dining_room_humidity' with state '35' in rrd4j database
2018-05-14 03:34:29.616 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'Driveway_camera_motiondetect_status' is about to be refreshed now
...
2018-05-14 03:35:00.000 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Test Rules operation'
2018-05-14 03:35:00.000 [DEBUG] [ntime.internal.engine.ExecuteRuleJob] - Executing scheduled rule 'Reset homekit lock'
2018-05-14 03:35:00.001 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: True
2018-05-14 03:35:00.001 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule 'Reset homekit lock': null
2018-05-14 03:35:00.002 [DEBUG] [inding.expire.internal.ExpireBinding] - Item rules_operating received update 'False'; stopping any future expiration.
2018-05-14 03:35:04.465 [DEBUG] [nternal.rest.NestStreamingRestClient] - Check: Receiving streaming events, millisSinceLastEvent=6263
2018-05-14 03:35:08.189 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'basementLeakDetector' with state 'OPEN' in rrd4j database (again)
2018-05-14 03:35:08.190 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'basementLeakDetector' with state '1' in rrd4j database
2018-05-14 03:35:21.475 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job

ignore the ‘Reset homekit lock’ error, I just added that yesterday to try to figure out what is happening.

Nothing except cron rules are triggered after 2018-05-14 03:34:28.146 and the last rule triggered is almost always ‘Real Item Changed’ - but I have had this rule for years, and it has always worked just fine (it is being triggered by the nest thermostat update). I also don’t know the significance of the 3:30am time.

Is there any log which will tell me why rules just stop triggering? it seems silent. I’m also not sure how to start them again (I can detect this happening, and a restart of OH fixes it for a day or two, or three - but I don’t want to continually restart OH because of this).

I have 7000 lines of rules, so going through them is not really an option, Visual Studio says that the rules are OK, and this only just started happening in the last few weeks. I was suspecting the last java update, but that doesn’t explain the 3;30am (ish) problem.

Any suggestions on where to look to find out why the rules stop triggering?

vzorglub · May 14, 2018, 12:30pm

It could be that your nest is restarting/booting at 3:30am and OH needs to reconnect and somehow it freezes the eventbus???
Have you tried to uninstall and re-install the nest binding?

Nicholas_Waterton · May 14, 2018, 12:32pm

Anything is possible. I did replace a nest smoke detector a few weeks ago - it’s possible there are some remnants of that still lying around, and the nest binding is the experimental 2.2 version…

I don’t know what:

2018-05-14 03:34:28.102 [DEBUG] [est.handler.NestSmokeDetectorHandler] - Smoke detector 8DPl0FPVZ_APWnZpNnOVQ7iEqXFuKc3X is not handling update for 8DPl0FPVZ_A8AHtgt3zcNLiEqXFuKc3X

means.

vzorglub · May 14, 2018, 12:37pm

Remove the nest binding
Stop OH
Clear the cache
Start OH
Install Nest

rlkoshak · May 14, 2018, 3:02pm

Are the events still occuring? Look in events.log to see that your Items are still changing state and receiving the commands that would trigger your rules.

Do you have any Thread::sleeps, while(true) (or the like), or other long running commands like executeCommandLine or sendHttp*Request in your Rules?

Do you see any spike in memory or CPU usage when the Rules top working?

Nicholas_Waterton · May 14, 2018, 3:18pm

Yes the events are still occurring, I can see them being logged - just the rules stop triggering on them. They get recorded in the persistence files as well. Cron based rules still fire, and timers work, (just new ones do not get created because the rules that create them never fire).

I do have rules with Thread::sleeps, but they are all to do with remote control commands, none of them are automatic, and don’t seem to be anything to do with this (which only started a few weeks ago). There are a couple of executeCommandLine but they don’t seem to be associated with the issue, I have a few sendHttp requests, but they are all manually triggered (ie click a control, and it sends an http request to home a camera).

No spike in memory or CPU that I can see, but this is always at about 3:30am.

It’s frustrating, as if i could find what is causing it, I could fix it, but the rules just silently stop triggering. No messages, errors or anything, and I can’t find a way to restart rule triggers without stopping and restarting OH as a whole.

If the theory is that I’m running out of threads, or a rule is getting into a deadlock, how can I find the culprit? is there a way to tell how many rule threads are in use at any one time, so I could see when it starts to rise?

I changed the number of rule threads from 5 to 50, but it doesn’t really seem to make a difference.

Thanks,

rlkoshak · May 14, 2018, 3:40pm

Just to eliminate them as being a problem (this is the number 1 cause of this behavior) I’d add some logging at the ends of your Rules that have these commands, even the manually triggered ones, just to verify that these Rules are exiting and doing so in a timely manner.

I do think it is unlikely to be the cause but it is the usual cause and I’m hesitant to eliminate it as a possibility without some more confirmation.

There may be some tools (profilers) that can be hooked up to OH while it is running to see the thread counts and such but it has been so long since I’ve done anything like that I don’t know what modern Java programs use. There may be some commands that you can run in the Karaf console to get the thead counts.

But before spending too much time researching and testing on this, I would recommend backing up (always backup), and upgrading to 2.3 to verify that it is still a problem there. This may be something that has been previously identified and fixed. 2.3 is nearing release so it shouldn’t be too unstable. Note: it will require some changes to your Rules, mainly you need to put a space after all [ and before all ].