Rules stop processing

[steve1]

@bbubbat

So why do I get the TRACE output of the persistence cron schedule but not from the other cron scheduler?

Have you turned org.eclipse.smarthome.automation.module.timer down to TRACE?

[bbubbat (Björn Bubbat)]

@steve1 I just set it to trace, but there is nothing in the log. This is my current logger setting:

Logger                                                           | Level
------------------------------------------------------------------------
ROOT                                                             | WARN
com.beowulfe.hap                                                 | ERROR
javax.jmdns                                                      | ERROR
org.apache.aries.spifly                                          | ERROR
org.apache.karaf.kar.internal.KarServiceImpl                     | ERROR
org.eclipse.smarthome                                            | INFO
org.eclipse.smarthome.automation.module.timer                    | TRACE
org.eclipse.smarthome.core.scheduler                             | TRACE
org.eclipse.smarthome.core.scheduler.*                           | TRACE
org.eclipse.smarthome.core.scheduler.ExpressionThreadPoolManager | TRACE
org.eclipse.smarthome.model.rule.runtime                         | TRACE
org.eclipse.smarthome.model.rule.runtime.internal.engine         | TRACE
org.jupnp                                                        | ERROR
org.openhab                                                      | INFO
org.openhab.io.net.http.HttpUtil                                 | WARN
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper      | ERROR
smarthome.event                                                  | INFO
smarthome.event.InboxUpdatedEvent                                | ERROR
smarthome.event.ItemAddedEvent                                   | ERROR
smarthome.event.ItemRemovedEvent                                 | ERROR
smarthome.event.ItemStateEvent                                   | ERROR
smarthome.event.ThingStatusInfoEvent                             | ERROR

[kgoderis (Karel Goderis)]

@bbubbat

19:06:00.405 [TRACE] [cheduler.ExpressionThreadPoolManager] - Expression’s ‘0 * * * * ?’ next execution time is 2017-03-15 19:07:00.000

In short, lines like the one above should match what you expect the cron schedule to be. And it does seemingly. at 19:06 the next execution of that “0 * * * * ?” is effectively 19:07

[bbubbat (Björn Bubbat)]

Yes, but I only get lines from the org.eclipse.smarthome.core.persistence scheduler in the log file. So I can’t see what the other cron schedulers are doing.

[kgoderis (Karel Goderis)]

If you refer to

19:06:00.402 [TRACE] [rthome.core.scheduler.CronExpression] …

lines you posted before, these are from the o.e.s.c.scheduler class, not o.e.s.c.persistence. In your log settings you posted, nothing of o.e.s.c.persistence will show up with the TRACE level.

[steve1]

@kgoderis

lines you posted before, these are from the o.e.s.c.scheduler class, not o.e.s.c.persistence. In your log settings you posted, nothing of o.e.s.c.persistence will show up with the TRACE level.

There are TRACE level messages from internal PersistItemsJob classes in his log output. Doesn’t that code also use the ExpressionThreadPoolManager and the CronExpression class (e.g., PersistenceManagerImpl.java)? If so how do you know if the CronExpression log messages are from the Persistence service or rule triggers?

[bbubbat (Björn Bubbat)]

To get back to the topic: As @Moxified stated, the problem seems to be more global and not only cron related. I as well have the problem that other rules stop working. So maybe focusing only on cron related things (also we can’t get the trace working right now) might get us on the wrong path.

[Moxified]

Exactly. Even if cron has a problem, it’s (or something else is) causing the entire rules processing portion of OH to stop with what appears to be zero warning.

I still have not seen a single trace log entry after setting trace on core.scheduler. As of right now my rules are still running.

Here’s my logging. Perhaps there is something else I can increase logging on…

openhab> log:list
Logger | Level

ROOT | WARN
esh-model-rule | DEBUG
esh-model-rule-runtime | DEBUG
esh-model-script | DEBUG
esh-model-script-runtime | DEBUG
javax.jmdns | WARN
openhab-runtime-base | TRACE
org.apache.aries.spifly | WARN
org.apache.karaf.kar.internal.KarServiceImpl | ERROR
org.apache.karaf.kar.internal.karserviceimp1 | WARN
org.eclipse.smarthome | DEBUG
org.eclipse.smarthome.core.scheduler | TRACE
org.eclipse.smarthome.model.rule.runtime | DEBUG
org.jupnp | WARN
org.openhab | INFO
org.openhab.binding.dscalarm | INFO
org.openhab.persistence.mapdb | INFO
org.openhab.persistence.mysql | INFO
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event | DEBUG
smarthome.event.InboxUpdatedEvent | ERROR
smarthome.event.ItemStateEvent | ERROR
smarthome.event.ThingStatusInfoEvent | ERROR

[rossko57]

@bbubbat

the problem seems to be more global and not only cron related

But as cron triggers are predictable and you currently have the attention of someone who understands what should happen with cron, it’d be smart to follow through with exploring why that doesn’t work, rather than dismiss it.
When the problem is “everywhere”, looking at a part of it in detail can give results.

[bbubbat (Björn Bubbat)]

@rossko57

When the problem is “everywhere”, looking at a part of it in detail can give results.

That’s true, of course.

Yesterday I installed the latest docker container. I had to restart it several times because (at least) the minutely cron rules where not working. They fired only once and stopped. Unfortunately I still don’t have a clue on how to get the needed trace logs working.

[kgoderis (Karel Goderis)]

@steve1 you don’t in fact, and what I wrote was literal, there are no logs from the class itself (analogue to self cpu time concept). But what was in the post had to do with persistence

[kgoderis (Karel Goderis)]

@Moxified

I still have not seen a single trace log entry after setting trace on core.scheduler.

Also nothing with respect to expression candidates and so forth? That would indicate that the expression is not even evaluated, and could point to a problem with the Rule parser (if you work with rules)

[kgoderis (Karel Goderis)]

@bbubbat

Unfortunately I still don’t have a clue on how to get the needed trace logs working.

Are you able to connect to the console via ssh?

[bbubbat (Björn Bubbat)]

To be honest, I’m not really sure. I use docker and the official docker document says to run docker this way:

docker run --it openhab/openhab:2.1.0-snapshot-amd64 ./start_debug.sh

Then I’m in the console and do a log:tail. Is this what you mean?

[kgoderis (Karel Goderis)]

@bbubbat

Then I’m in the console and do a log:tail. Is this what you mean?

almost. do

log:set TRACE org.eclipse.smarthome.core.scheduler

I am definitely interested to see all the output from the ExpressionThreadPoolManager class. Can you for example tell that you have at exactly one MonitorThread per cron expression?

[kgoderis (Karel Goderis)]

@kgoderis

19:06:00.405 [TRACE] [cheduler.ExpressionThreadPoolManager] - Expression’s ‘0 * * * * ?’ next execution time is 2017-03-15 19:07:00.000

@bbubbat Ok, you have it set to trace level. If you could provide the full logs with respect to the the scheduler classes then I could have a better look at things

[bbubbat (Björn Bubbat)]

@bbubbat Here is my log. I made a “clean” start. I delete all log files and started the docker container with the debug script. As you will see, this time my hourly rules (“ping” and “sunrise-sunset”) are only executed twice.

I don’t know how to attach the log file, but I will try to add the plain text in my next reply.

Okay, you can download it from Dropbox: https://www.dropbox.com/s/5g0ylz59co7mzs8/openhab.log.zip?dl=0

[kgoderis (Karel Goderis)]

@kgoderis

I am definitely interested to see all the output from the ExpressionThreadPoolManager class. Can you for example tell that you have at exactly one MonitorThread per cron expression?

Ok - this I have to take back after revisiting my own code. There should be only one monitor task for all expressions

[kgoderis (Karel Goderis)]

Ok - I have looked at the code.The issue is not with the ExpressionThreadPoolManager or core.scheduler.CronExpression.

The Persistence infrastructure does use the above classes indeed. However, the rules you add from the configuration files do use the RuleTriggerManager, and that class is still using the Quartz job scheduler (see https://github.com/eclipse/smarthome/blob/3ae5d7b1b284f2bde6199bfe8dad950fd38cae39/bundles/model/org.eclipse.smarthome.model.rule.runtime/src/org/eclipse/smarthome/model/rule/runtime/internal/engine/RuleTriggerManager.java#L568). There must thus be something wrong with Quartz (and I am not sure what that could be)

[Kai (Kai Kreuzer)]

@kgoderis

that class is still using the Quartz job scheduler

Interesting, I wasn’t aware of this. Would make sense to soon switch this implementation over to the new scheduler as well.