Cron triggering too late (NRE, Jython rules, OH in docker)

bastian · October 4, 2020, 11:13am

Hi all,
my rules triggered by cron (acutally also rules triggered by astro phase change channels) are executed too late.
Unfortunately I was not observant enought to see when this started happening - could have been with my update to 2.5.7.
My current setup is OH 2.5.9 running in a docker container on a Linux machine, all rules are using NRE Jython.

I set up the following (NRE Jython) rules, in order to pin down the problem:


@rule("debug")
@when("Time cron 0 /5 * * * ? *")
def cron_test(event):
    my_log = Logger(cron_test, event)
    my_log.message("cron every 5th minute started")

@rule("debug 2")
@when("Time cron 0 0 /2 * * ? *")
def cron_test_2(event):
    my_log = Logger(cron_test_2, event)
    my_log.message("cron every 2nd hour started")

@rule("debug 3")
@when("Time cron 0 0 8 * * ? *")
def cron_test_3(event):
    my_log = Logger(cron_test_3, event)
    my_log.message("cron on 8 AM started")

The Logger class used above is a wrapper for logging, I can see in other places where it is used, that it creates immediate log entries - so no delay coming from this.
When I tail the log, I can see that the timestamp for log entries is matching the current time, so system clock and openhab time seem to be fine (what I want to say is: log time = time on linux server = time on my desktop machine = actual time here in my TZ).

All the entries I see in my log are later than what the cron dictates.
The every 5 minutes have a ca. 20s lag (just showing some examples from the log):

2020-10-04 12:05:21.950 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:10:22.825 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:15:19.876 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:20:21.862 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:25:22.467 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:30:19.280 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:35:20.990 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:40:23.794 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:45:19.087 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:50:21.763 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 12:55:23.251 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started
2020-10-04 13:00:18.304 [INFO ] [jsr223.jython.debug                 ] - cron_test message // cron every 5th minute started

The every 2h are up to 8 minutes late ?!

2020-10-03 20:05:55.916 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-03 22:08:24.183 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 00:08:10.729 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 02:08:13.206 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 04:08:11.867 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 06:08:14.209 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 08:08:11.166 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 10:08:14.407 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 12:08:16.437 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started

And the 8 am one is a whopping 58 minutes late:

2020-10-04 08:58:46.922 [INFO ] [jsr223.jython.debug 3               ] - cron_test_3 message // cron on 8 AM started

I’d be really happy to get some pointers no what could be going wrong here.
If more log-data is needed, I’ll provide it.

Cheers & have a great Sunday!
Bastian

rossko57 · October 4, 2020, 11:41am

bastian:

2020-10-03 20:05:55.916 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-03 22:08:24.183 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 00:08:10.729 [INFO ] ...

That’s interesting. I guess it’s made a cock of the initial setup, then compounded the error at first reschedule.

rlkoshak · October 5, 2020, 3:17pm

What is the CPU doing on this machine? If it’s pegged I could see how it has to wait around, perhaps for minutes even, for it’s chance to run on the CPU. The same could occur if you are out of RAM and have to wait for SWAP. But the delays between the runs is rather consistent with no real pattern I can see (sometimes more, sometimes less time between runs).

Outside of that I can’t imagine what would cause this.

bastian · October 5, 2020, 5:29pm

Thank you for coming back on this - highly appreciated.

CPU is mostly idle (or do I misinterpret something here? Hope you find your way around the German):

Execution of the and 8am morning and every 2h cron are consistently bad:

2020-10-04 08:58:46.922 [INFO ] [jsr223.jython.debug 3               ] - cron_test_3 message // cron on 8 AM started
2020-10-05 09:41:54.555 [INFO ] [jsr223.jython.debug 3               ] - cron_test_3 message // cron on 8 AM started

2020-10-03 20:05:55.916 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-03 22:08:24.183 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 00:08:10.729 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 02:08:13.206 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 04:08:11.867 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 06:08:14.209 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 08:08:11.166 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 10:08:14.407 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 12:08:16.437 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 14:08:14.122 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 16:08:16.557 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 18:08:14.274 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 20:08:14.798 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-04 22:08:15.831 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 00:08:13.557 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 02:08:16.095 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 04:08:10.675 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 06:08:17.396 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 08:08:12.877 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 10:08:17.794 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 12:08:19.555 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 14:08:16.963 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 16:08:17.814 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started
2020-10-05 18:08:18.835 [INFO ] [jsr223.jython.debug 2               ] - cron_test_2 message // cron every 2nd hour started

Would it help to set up a cron outside the OH (and outside docker) and see how that goes?

I also have not yet rebooted the complete server (though I did restart the docker container). It’s not a big deal, so I definitely would give this a try, just wanted to wait if it might be better to gather any more data before trying this.

rossko57 · October 5, 2020, 5:43pm

As an intermediate step, try an old fashioned DSL cron rule alongside.

rlkoshak · October 5, 2020, 6:45pm

Correct, the CPU and overall system load is almost nothing.

Indeed but not consistent when you look at the details.

First we start 5 minutes 55 seconds late.
The next run is 8 minutes 24 seconds late.
Then we improve a little with 8 minutes 10 seconds late.
Then a little worse at 8 minutes 13 seconds.

And so on.

A second is a long time to the CPU and a minute is a near eternity. So that 14 seconds improvement and followed by a 3 second worse are significant changes. That’s what I mean by no pattern. It’s always arounf 8 minutes (except for that first one) but it’s not steadily growing worse nor is it steadily improving.

The values in swap are somewhat concerning though. Ideally you don’t want swap to be used at all. But it’s showing it in KiB instead of MB so it’s not really using all that much of it either.

I don’t really have any ideas on this one. It’s pretty bizar.

Setting up a test with the system cron I’m not sure will tell you that much. If both of them end up being roughly off of what is expected it would point at a general problem with the machine overall. If not I’m not sure it tells us much as the cron rules in openHAB are implemented completely separately from how the system cron works.

A more informative test might be to create some Timers and see if Timers similarly go off with a delay like the cron triggered rules do, as both Timers and Cron triggered rules are handled by the same library.

Do you use Astro? When does the nightly update of the Astro Items occur? Around ten seconds after midnight or five to eight minutes after midnight?

rossko57 · October 5, 2020, 7:05pm

I don’t think that’s entirely valid syntax for Quartz
0 0/5 * * * ? *

but I doubt it helps here.

5iver · October 5, 2020, 7:14pm

What is in your class? I suggest using the logger that I append to the rule callback function…

cron_test.log.info(event)

BTW, event will be None for cron and System started triggers. Do you see rule events in your events.log? I am curious if they reflect the time delay. You are only logging inside the rule action. The timestamp used is the time that the log was written, which could mean a delay in the logging mechanism, but the rule may be executing at the correct time. Looking in the events.log will help, but you could also try switching on/off a light in the rule and watching a clock.

What does your host look like?

The OP is using the Jython helper libraries, where I use…

from org.quartz.CronExpression import isValidExpression

… to confirm that the cron expressions used are valid…

github.com

openhab-scripters/openhab-helper-libraries/blob/master/Core/automation/lib/python/core/triggers.py#L228


      
                  target_type = " ".join(input_list[0:2])
                  input_list = input_list[2:]
              else:
                  target_type = input_list.pop(0)
          elif trigger_target is None:
              if target_type == "System" and len(input_list) > 1:
                  raise ValueError(u"when: \"{}\" could not be parsed. trigger_type '{}' is invalid for target_type 'System'. The only valid trigger_type is 'started'.".format(target, target_type))
                  # if " ".join(input_list[0:2]) == "shuts down":
                  #     trigger_target = "shuts down"
              else:
                  trigger_target = input_list.pop(0)
          elif trigger_type is None:
              if "received" in " ".join(input_list[0:2]):
                  if " ".join(input_list[0:2]) == "received update":
                      if target_type in ["Item", "Thing", "Member of", "Descendent of"]:
                          input_list = input_list[2:]
                          trigger_type = "received update"
                      else:
                          raise ValueError(u"when: \"{}\" could not be parsed. 'received update' is invalid for target_type '{}'. The valid options are 'Item', 'Thing', 'Member of', or 'Descendent of'.".format(target, target_type))
                  elif " ".join(input_list[0:2]) == "received command":
                      if target_type in ["Item", "Member of", "Descendent of"]:

I’m with you though… when I first read the post I scratched my head, since this did not look valid to me .

rossko57 · October 5, 2020, 7:26pm

0 /5 * * * ? *
does blow up in this validator

but that is not gospel either

This certainly would not affect the 8am cron

bastian · October 5, 2020, 8:43pm

Thank you for your thoughts and explanations.
First thing I did, is set up some test rules in the OH DSL as proposed by @rossko57 , and voilá - these rules are very much on time:

2020-10-05 20:40:02.711 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
2020-10-05 20:45:00.002 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
...
2020-10-05 21:55:00.002 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
2020-10-05 22:00:00.001 [home.model.script.bb-rules] - cron every 2nd hour started - old school rule
2020-10-05 22:00:00.001 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
2020-10-05 22:05:00.001 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
2020-10-05 22:10:00.001 [home.model.script.bb-rules] - cron every 5th minute started - old school rule

At the same time, the log entries for the NRE rules are still as before.
So next thing I changed the logging in the NRE rules, to not use my logger class:

from core.rules import rule
from core.triggers import when

@rule("debug")
@when("Time cron 0 /5 * * * ? *")
def cron_test(event):
    cron_test.log.info("cron every 5th minute started - NRE")

@rule("debug 2")
@when("Time cron 0 0 /2 * * ? *")
def cron_test_2(event):
    cron_test_2.log.info("cron every 2nd hour started - NRE")

@rule("debug 3")
@when("Time cron 0 0 8 * * ? *")
def cron_test_3(event):
    cron_test_3.log.info("cron on 8 AM started - NRE")

Which does not make the problem go away:

==> openhab.log <==
2020-10-05 22:30:22.275 [INFO ] [jsr223.jython.debug                 ] - cron every 5th minute started - NRE
==> events.log <==
2020-10-05 22:30:22.275 [.event.RuleStatusInfoEvent] - 136250c0-5e71-4426-a299-98398bbc8a98 updated: RUNNING
2020-10-05 22:30:22.296 [.event.RuleStatusInfoEvent] - 136250c0-5e71-4426-a299-98398bbc8a98 updated: IDLE

Now to check @rossko57 suggestions about actual rule execution time, vs. logging time, I made Alexa talk to me, in the every 5 minute rule before the logging happens:

@rule("debug")
@when("Time cron 0 /5 * * * ? *")
def cron_test(event):
    events.sendCommand("TTTS_Azi", "another 5 minutes have passed") 
        # Talk To Speach for my Alexa in the Arbeitszimmer. 
    cron_test.log.info("cron every 5th minute started - NRE")

But Alexa does not start to speak, before I can see the log-entries appear.
Therefore I would conclude, that the triggering of the rule via the cron is actually delayed:

2020-10-05 22:40:12.761 [.event.RuleStatusInfoEvent] - b5fb40d0-1fdf-451e-bb92-9d8e6e3d3271 updated: RUNNING

==> /home10/services/openhab/userdata/logs/openhab.log <==
2020-10-05 22:40:12.764 [INFO ] [jsr223.jython.debug                 ] - cron every 5th minute started - NRE

==> /home10/services/openhab/userdata/logs/events.log <==
2020-10-05 22:40:12.764 [ome.event.ItemCommandEvent] - Item 'TTTS_Azi' received command another 5 minutes have passed
2020-10-05 22:40:12.765 [nt.ItemStatePredictedEvent] - TTTS_Azi predicted to become another 5 minutes have passed
2020-10-05 22:40:12.766 [.event.RuleStatusInfoEvent] - b5fb40d0-1fdf-451e-bb92-9d8e6e3d3271 updated: IDLE
2020-10-05 22:40:12.767 [vent.ItemStateChangedEvent] - TTTS_Azi changed from  to another 5 minutes have passed
2020-10-05 22:40:16.467 [vent.ItemStateChangedEvent] - TTTS_Azi changed from another 5 minutes have passed to

5iver · October 5, 2020, 8:54pm

The event.log is showing this too. The new and old rule engines use different schedulers. There have been some fixes to the new scheduler that are only available in OH3., but I don’t recall if they were related to what you are experiencing. I use lots of cron triggered rules with Jython and do not experience the same, nor have I heard of anyone else experiencing this. Hence, I suspect it is a configuration or hardware issue.

Pinging @hilbrand in case this is a new bug.

bastian · October 5, 2020, 8:56pm

Some more things.

Astro

Do you use Astro? When does the nightly update of the Astro Items occur? Around ten seconds after midnight or five to eight minutes after midnight?

I do use Astro, but I could not find any astro-related entries at 00:00 or shortly after. Neither in openhab.log nor in events.log. What should I be looking for - and where?

Validity of the Quarty Cron expressions
I changed the cron expressions to be valid with the Cron Expression Generator & Explainer - Quartz:
0 /5 * * * ? * into 0 0/5 * * * ? *
0 0 /2 * * ? * into 0 0 0/2 * * ? *
no changes in the execution delay of the 5min rule.

5iver · October 5, 2020, 8:59pm

Could you try this format to see if it changes anything?

Time cron 0 0/5 * * * ?"

bastian · October 5, 2020, 9:11pm

@5iver, I tried these three different crons now, but all don’t change the timing of the 5min rule - it is still >10s late.

"Time cron 0 /5 * * * ? *" #initially
"Time cron 0 0/5 * * * ? *" #added the starting point to the 5min step
"Time cron 0 0/5 * * * ?" #removed the year

bastian · October 5, 2020, 9:27pm

I now tried the following:

stop OH
move away all
– item files
– things files (but most of my things are already in PaperUI - so that won’t change)
– rules files - except the one with the three debug cron rules
– Jython personal scripts - except the one with the three debug cron rules
– Jython personal libs
start OH back up

Not any better

2020-10-05 23:25:01.446 [home.model.script.bb-rules] - cron every 5th minute started - old school rule
2020-10-05 23:25:22.054 [.event.RuleStatusInfoEvent] - 15b1dc4a-90ab-4453-b794-3c5d18239c17 updated: RUNNING

==> /home10/services/openhab/userdata/logs/openhab.log <==
2020-10-05 23:25:22.059 [INFO ] [jsr223.jython.debug                 ] - cron every 5th minute started - NRE

==> /home10/services/openhab/userdata/logs/events.log <==
2020-10-05 23:25:22.063 [.event.RuleStatusInfoEvent] - 15b1dc4a-90ab-4453-b794-3c5d18239c17 updated: IDLE

How would I go about it, if I want to disable installed bindings (etc.) and try if that changes anything?
I know I can stop the bundles via the OH console, but would this have any effect on the scheduling without restarting OH?

rlkoshak · October 5, 2020, 9:31pm

There should be, or at least used to be a log statement from the Astro binding saying it’s recalculating the times for the new day. But I think it only does so when you have Items linked to Channels. If you’re only using the event Channels than I don’t know if it logs that.

You should also see the Astro linked Items being updated around a midnight as well.

But it doesn’t sound like this would tell us anything so it’s no biggie.

rossko57 · October 5, 2020, 9:32pm

Astro binding uses the Quartz scheduler, same as DSL rules, so I would think that is a redundant path to follow now.
You normally see something in your openhab.log like

2020-10-05 00:00:30.468 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:fosscross
2020-10-05 00:00:30.728 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:fossmoon

That running at 00:00:30 is itself a result of a (Quartz) scheduled job, which goes on to set up scheduled jobs for the day ahead with dawn etc.

Slow down, you’ve confined the problem to NGRE scheduler.

bastian · October 5, 2020, 9:42pm

Thanks again for your help!

Slow down, you’ve confined the problem to NGRE scheduler.

I’ll happily take that advise and call it a day for now

bastian · October 12, 2020, 4:57pm

Ping.

Has anyone any idea what I could do to fix this problem or get it being fixed (in case it is not due to my wrongdoing)?

Especially the cron schedule for full hours is really really off, and that limits the usefulness of OH somehwat for me.

2020-10-06 08:38:09.122 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-07 09:45:05.185 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-08 09:40:29.503 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-09 09:41:10.607 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-10 09:41:38.006 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-11 09:42:07.498 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE
2020-10-12 09:42:33.260 [INFO ] [jsr223.jython.debug 3               ] - cron on 8 AM started - NRE

5iver · October 12, 2020, 7:34pm

Since this does not seem to be affecting anyone else, it is unlikely that it is a bug. So, you would need to determine if the source of the problem is your OH configuration, docker, host configuration, or hardware. What hardware, OS, docker version, and Java version are you using? How did you create your container?

I suggest testing the hello_world.py script and a similar rules DSL cron rule simultaneously in a new clean container with just Jython and the helper libraries, while tailing the log file to see in real time if the logs are out of sync with the docker and/or host system clocks. If you still see the issue, use “docker export” to create a tar of the container and try it on different hardware.

I’m curious to see the same test using a manual installation of OH running on your host system ourside fo docker.