Have you turned
org.eclipse.smarthome.automation.module.timer down to TRACE?
Have you turned
@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
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
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.
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.
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?
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.
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…
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
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.
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.
@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
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)
Are you able to connect to the console via ssh?
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?
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?
@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 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
Ok - this I have to take back after revisiting my own code. There should be only one monitor task for all expressions
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)
Interesting, I wasn’t aware of this. Would make sense to soon switch this implementation over to the new scheduler as well.