Cron rules seeming fire but do nothing

Setup, Configuration and Use Scripts & Rules
1

Hi folks,

Quick info -
RPI 3b+
Only has openHAB 2.4 running on it
load-average: 0.13, 0.2, 0.19
Been running for nearly a year without (much) hassle (but I do keep expanding functionality daily / weekly :smiley: )

I have a number of cron rules which have never (knowingly) missed missed a beat.
Recently I they’re not firing any more.
I’ve read a number of posts about cron and, while enabling the quartz debug, I cannot find anything that gells.

18:59:44.680 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[802]
18:59:52.520 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
18:59:54.206 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
18:59:59.676 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:00:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:00:00.005 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.cron.heartbeat.rules#heartbeat#0 0/31 * 1/1 * ? *
19:00:00.009 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:00:00.035 [WARN ] [ipse.smarthome.model.script.Heartbeat] - ping
19:00:00.052 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:00:00.060 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.blinds.http.rules#Check Blind - Check Position#0 0/15 * 1/1 * ? *
19:00:00.180 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:00:00.187 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.blinds.http.rules#Check Blind - Check battery#0 0/16 * 1/1 * ? *
19:00:02.542 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:00:02.547 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.utility.electrical.rules#Utility.Electrical.Pulse.Count - Clear Hour#0 0 0/1 1/1 * ? *
19:00:02.564 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:00:09.297 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:00:14.673 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:00:24.392 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:00:29.668 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:00:30.862 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:00:39.484 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:00:44.662 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[816]
19:00:54.575 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:00:59.659 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:01:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:01:00.003 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:01:09.667 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:01:14.656 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[805]
19:01:24.759 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:01:26.960 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:01:29.649 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:01:39.849 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:01:44.647 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:01:54.940 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:01:55.660 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:01:59.643 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[802]
19:02:00.004 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:02:00.009 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:02:10.032 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:02:14.637 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:02:25.125 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:02:25.977 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:02:29.635 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[811]
19:02:40.216 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:02:44.626 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[816]
19:02:49.714 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:02:55.311 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:02:59.622 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[814]
19:03:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:03:00.006 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:03:10.396 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:03:14.620 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[816]
19:03:23.461 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:03:25.491 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:03:29.616 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[816]
19:03:40.584 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:03:44.609 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[809]
19:03:53.009 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:03:55.673 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:03:59.606 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
19:04:00.005 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:04:00.019 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers

The part I think is wrong is this:

19:08:49.134 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
19:08:57.509 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:08:59.518 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[821]
19:09:00.003 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
19:09:00.003 [DEBUG] [org.quartz.core.JobRunShell          ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
19:09:12.597 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
19:09:14.511 [INFO ] [ghtwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[802]
19:09:23.420 [DEBUG] [org.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers

Does that say it wants to fire but for some reason did not?

Then I have this -

2018-12-27 18:59:54.206 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[69]
2018-12-27 18:59:59.676 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[807]
2018-12-27 19:00:00.003 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2018-12-27 19:00:00.005 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.cron.heartbeat.rules#heartbeat#0 0/31 * 1/1 * ? *
2018-12-27 19:00:00.009 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago 2#0 0/1 * 1/1 * ? *
2018-12-27 19:00:00.035 [WARN ] [pse.smarthome.model.script.Heartbeat] - ping
2018-12-27 19:00:00.052 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2018-12-27 19:00:00.060 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.blinds.http.rules#Check Blind - Check Position#0 0/15 * 1/1 * ? *
2018-12-27 19:00:00.180 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2018-12-27 19:00:00.187 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.blinds.http.rules#Check Blind - Check battery#0 0/16 * 1/1 * ? *
2018-12-27 19:00:02.542 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2018-12-27 19:00:02.547 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.utility.electrical.rules#Utility.Electrical.Pulse.Count - Clear Hour#0 0 0/1 1/1 * ? *
2018-12-27 19:00:02.564 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers

I have a rule, heartbeat, which does fire ok. You can see that it says “acquisition of 1 triggers”.
Why does that one work? You can see a bit later than there is a Warn - Ping.

I have one rules file with the following:

rule "Utility.Electrical.Pulse.Count"
when Item UtilityElectricPulse changed to ON
then 
    //logWarn("KKK", "Pulse")
    var Number pCount = 0;
    if (UtilityElectricPulseCount.state != NULL)
        pCount = ((UtilityElectricPulseCount.state as Number) + 1)

//logWarn("loggerName", pCount.toString)

    if (pCount == 1000){
        pCount = 0;
        UtilityElectricUnitsH.postUpdate(UtilityElectricUnitsH.state as Number + 1)
        UtilityElectricUnitsD.postUpdate(UtilityElectricUnitsD.state as Number + 1)
        UtilityElectricUnitsW.postUpdate(UtilityElectricUnitsW.state as Number + 1)
        UtilityElectricUnitsM.postUpdate(UtilityElectricUnitsM.state as Number + 1)
        UtilityElectricUnitsY.postUpdate(UtilityElectricUnitsY.state as Number + 1)
        UtilityElectricUnitsTotal.postUpdate(UtilityElectricUnitsTotal.state as Number + 1)
    }

    UtilityElectricPulseCount.postUpdate(pCount)
    UtilityElectricPulse.sendCommand(OFF)
end 


rule "Utility.Electrical.Pulse.Count - Reset switch"
    when //Time cron "1/30 * * * * ? *"
    System started
then 
    //if (UtilityElectricPulse.state == OFF)  return;
    UtilityElectricPulse.sendCommand(OFF)
end 

rule "Utility.Electrical.Pulse.Count - Clear Hour"
    when Time cron "0 0 0/1 1/1 * ? *"
then
    UtilityElectricUnitsH.postUpdate(0)
end 

rule "Utility.Electrical.Pulse.Count - Clear Day"
    when Time cron "0 0 12 1/1 * ? *"
then 
    UtilityElectricUnitsD.postUpdate(0)
end 

rule "Utility.Electrical.Pulse.Count - Clear Weekly"
    when Time cron "0 0 12 ? * SUN *"
then 
    UtilityElectricUnitsW.postUpdate(0)
end 

rule "Utility.Electrical.Pulse.Count - Clear Monthly"
    when Time cron "0 0 12 1 1/1 ? *"
then 
    UtilityElectricUnitsM.postUpdate(0)
end 

rule "Utility.Electrical.Pulse.Count - Clear Yearly"
    when Time cron "0 0 12 1 1 ? *"
then 
    UtilityElectricUnitsY.postUpdate(0)
end

If I comment out half of the cron rules the system behaves for a day or so. Does not matter which half, top of bottom, it’s ok. Put all of them back in and the oddness starts. Coupled with this oddness, some binding stop working too. All very random as to when it will stop working.

Question: How can I further debug the cron issue? Am I reach the limits of what I can do on the RPi?

htop:

image
image.png1314×829 77.5 KB

TIA
C

2

I run OH on a larger system and don’t use a Pi, so it’s just a guess, but could it be related to memory (leaks)? Perhaps you can monitor memory usage from a fresh reboot until things go wrong.

3

Not sure. Will monitor now. I have just restarted it all.

The memory usage is high on this because I upped the settings in Java to 450/600.

Having just restarted it I expect it to work to tomorrow sometime.

4

There seem to a few others with issues with cron rules which stop firing. OH 2.4 is the first version where I’ve ever had any issues like this. I’m running OH on a VM, with plenty of RAM/DISK, but I’ll look at memory usage next time it crashes.

5

I’ve managed to recreate the problem in a number of ways. Seems that an exception within a cron rule causes the cron thread to die.
See my other post for an example.

6

Any idea on a fix or a way to autorestart openhab when cron dies?