Yes it happens, because now I was able to see that at least one astro event triggered the rule (in the events.log I saw that astro … triggerend event start). It just seems that not for all events… or maybe it is just what @rlkoshak said and the rules execution thread is full, but it should execute in that case as well, right (just with some latency) ?
It should. Split the rule as I suggested. Enable DEBUG on org.eclipse.smarthome.script to see if the rule is called.
If we are thinking of the same problem, the problem was having more than one cron trigger on the same Rule. And that was fixed in 2.2 I think (maybe as late as 2.3?).
Around midnight do you see lines like the following?
2018-07-05 00:00:30.012 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2018-07-05 00:00:30.021 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2018-07-05 00:00:30.027 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2018-07-05 00:00:30.027 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus150
2018-07-05 00:00:30.042 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus120
2018-07-05 00:00:30.045 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus90
There should be a line for each Astro thing you have defined. If one of your Things are missing, then the event will not occur that day. That was the behavior I was helping someone with on another thread. Some of their Astro events got rescheduled but not for all of their Things. And the Things that didn’t get rescheduled sometimes work. It’s really bizarre and I think an Issue was filed.
Yes, here it is from yesterday:
2018-09-11 00:00:30.218 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:d4cd4cd0
2018-09-11 00:00:30.250 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2018-09-11 00:00:30.465 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2018-09-11 00:01:00.010 [INFO ] [arthome.model.script.day_state.rules] - Calculating time of day...
2018-09-11 00:01:00.076 [INFO ] [arthome.model.script.day_state.rules] - Calculated time of day is BED
As I move forward to recreate or recall this “bug”, it seems more and more random for me. Can’t really tell in which scenarios it won’t work. All other rules just seem fine for me…
Maybe this can help… now it calculated EVENING (at 10:57 pm, weird…) and I always get an error like this:
2018-09-11 22:56:29.065 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'iPhone Home': cannot invoke method public abstract java.lang.String org.eclipse.smarthome.core.items.Item.getName() on null
2018-09-11 22:56:29.065 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'LocationString': cannot invoke method public abstract org.eclipse.smarthome.core.types.State org.eclipse.smarthome.core.items.Item.getState() on null
2018-09-11 22:56:29.069 [INFO ] [arthome.model.script.day_state.rules] - Calculating time of day...
2018-09-11 22:56:29.123 [INFO ] [arthome.model.script.day_state.rules] - Calculated time of day is EVENING
Those errors are most likely caused by a known bug. When OH starts up sometimes the Rules start running before all the Items have been fully loaded and populated. If those errors only exist during startup that is the source of the problem.
Yes. What system do you run on, a slow one like a RPi ?
Check out this workaround (should work on any systemd based Unix).
Yes I’m running on RPi (openHabian). I know this bug, but for me it happens not just at startup, but every execution of the day_state rule.
You mean you get the error messages in your last post every time that rule is executed and not just during startup ?
Then it’s a different issue and unrelated to the startup problem and workaround I posted.
Of course if you for example initialize variable on “when system started” and items aren’t loaded at that point in time, they might never get initialized, leading to followup errors.But we don’t know your code so this is just a guess.
Exactly. I have added to my ‘LocationString’ and ‘iPhone Home’ rule the System started trigger, since then I get the errors. But not just at startup, it always shows this error when the day_state rule runs. I will post my rules here if you might want a look at it, but now I have monitored the usage of RPi and I think I have reached the end of the performance of RPi. The RAM is almost on full and very often the CPU usage is on 100%.
No that is highly unlikely (unless you’re doing a lot more stuff on there beyond openHAB).
RAM usage at ~600MB is perfectly normal (although note the part resident in memory is even less).
100% CPU on a 4-core system means 25%, that’s also ok (I assume you don’t run on a 1-core RPi1, do you ?). You would need to see 400% or close to before you may call the system overloaded.
And most of the time when you see 100% it’s one thread blocked and the others idling. Most often this is due to constant reparsing, see this thread for details and a remedy.
OK, then the problem isn’t the startup timing problem.
Add some logging to your day_state Rule to try and narrow down the error to a specific line of code. Then we need to look at all the Items, States, and variables used on those lines. From there we will hopefully have the clues to figure out why one of those Items or variables doesn’t exist or is not set to what you think it is.
No, I’m running RPi 3B. The problem is that I not only use this RPi for openHab, but this is my media center (Kodi) and runs other little scripts as well. Swap memory is full (100MB/100MB) and yes, openHab only uses one core only (it seems that it can only run on one core?), but other apps uses up the other resources as well. So in average I get around 60% CPU usage. The RAM usage is around 650-700 MB.
Yes I have experienced that when I edit some rules or items much often, it will get slower and slower (and yes I’m using samba, which I read somewhere just makes the things worse). I have also experienced that the LSP server is using too much resource on an RPi.
I will move this setup to a server soon, so we will have a look at how the performance changes.
Read that thread I linked to.
Running Kodi shouldn’t be all that much of a problem as it’s idling most of the time
(although I would put a USB stick in and swap there to have more RAM and more swap space).
If you wanna move to new HW, I’d recommend an Odroid C2 for Kodi (as it can do 4K) and to stick with the Pi for OH.
Thank you! I will have a look at it.
@rlkoshak, here is my rule and items:
.rule
rule "Calculate time of day state"
when
System started or // run at system start in case the time changed when OH was offline
Channel 'astro:sun:home:rise#event' triggered START or
Channel 'astro:sun:home:set#event' triggered START or
Channel 'astro:sun:d4cd4cd0:set#event' triggered START or
Time cron "0 1 0 * * ? *" or // one minute after midnight so give Astro time to calculate the new day's times
Time cron "0 0 6 * * ? *" or
Time cron "0 0 23 * * ? *"
then
logInfo("day_state.rules", "Calculating time of day...")
// Calculate the times for the static tods and populate the associated Items
// Update when changing static times
// Jump to tomorrow and subtract to avoid problems at the change over to/from DST
val morning_start = now.withTimeAtStartOfDay.plusDays(1).minusHours(18)
vMorning_Time.postUpdate(morning_start.toString)
val night_start = now.withTimeAtStartOfDay.plusDays(1).minusHours(1)
vNight_Time.postUpdate(night_start.toString)
val bed_start = now.withTimeAtStartOfDay
vBed_Time.postUpdate(bed_start.toString)
// Convert the Astro Items to Joda DateTime
val day_start = new DateTime((vSunrise_Time.state as DateTimeType).getZonedDateTime.toInstant.toEpochMilli)
val evening_start = new DateTime((vSunset_Time.state as DateTimeType).getZonedDateTime.toInstant.toEpochMilli)
val afternoon_start = new DateTime((vEvening_Time.state as DateTimeType).getZonedDateTime.toInstant.toEpochMilli)
// Calculate the current time of day
var curr = "UNKNOWN"
switch now {
case now.isAfter(morning_start.millis) && now.isBefore(day_start.millis): curr = "MORNING"
case now.isAfter(day_start.millis) && now.isBefore(afternoon_start.millis): curr = "DAY"
case now.isAfter(afternoon_start.millis) && now.isBefore(evening_start.millis): curr = "AFTERNOON"
case now.isAfter(evening_start.millis) && now.isBefore(night_start.millis): curr = "EVENING"
case now.isAfter(night_start.millis): curr = "NIGHT"
case now.isAfter(bed_start.millis) && now.isBefore(morning_start.millis): curr = "BED"
}
// Publish the current state
logInfo("day_state.rules", "Calculated time of day is " + curr)
vTimeOfDay.sendCommand(curr)
end
.items
String vTimeOfDay "Current Time of Day [%s]" <tod>
DateTime vMorning_Time "Morning [%1$tH:%1$tM]" <sunrise>
DateTime vSunrise_Time "Day [%1$tH:%1$tM]" <sun> { channel="astro:sun:local:rise#start" }
DateTime vSunset_Time "Evening [%1$tH:%1$tM]" <sunset> { channel="astro:sun:local:set#start" }
DateTime vNight_Time "Night [%1$tH:%1$tM]" <moon>
DateTime vBed_Time "Bed [%1$tH:%1$tM]" <bedroom_blue>
DateTime vEvening_Time "Afternoon [ %1$tH:%1$tM]" <sunset> { channel="astro:sun:d4cd4cd0:set#start" }
I was able to narrow down the problem a little bit. Usually it won’t change from Morning to Day and the evening trigger seems to be off… It will change to it after 30min-1hour after sunset…
Add logging statements to the rule to narrow down which line specifically is causing the error.
I have tried adding logging statements to the rule, but it seems that it won’t run at all at certain times.
What I have tried so far:
- Checked the astro things, might be some problem with the location - No problem, location is OK
- Added logging statements to the rule - Won’t help, but I knew this, because I wasn’t able to see your loggings (from original post) during calculation. When these logs are seen, the rule is working as normal.
- Tried to recreate the problem, but is really hard. As I wrote it before, it seems that it won’t change to DAY and also changing to EVENING is around + 90min later than the actual sunset, not before.
- Checked the items which is updated by this rule and all seems fine and provide the sufficent info (I have an additional sitemap where this ‘debug’ items can be seen and I haven’t seen any difference between now and before, when it was working as it should.)
Now I have enabled DEBUG logging for org.eclipse.smarthome.script and see if I can grab something there. I don’t know if an error or bug existed before, but it seems that the rule and things are functional, but it won’t trigger a rule…
I recommend focusing on one problem at a time. Either focus on why the Rule isn’t triggering sometimes or focus on why it is generating an error when it does exit.
You can add a simple Switch Item and set it as a trigger to this Rule so you can trigger it to run whenever you want.
Thanks for your help! I was able to get rid of the errors when it runs, by removing the System started trigger from the my other rules, where that error was referring to.
I have added a switch to it, if I trigger it with it, it runs well, without errors and calculates the right time of day. I will see if the removed ‘System started’ trigger makes sense…
With the removed System started trigger, you will have to wait until the next scheduled time trigger for vTimeOfDay to be updated when OH restarts.
If the errors only occur during the System started trigger, then the errors are almost certainly caused by the previously mentioned bug in OH.
It seems that removing the System started trigger did the trick. Now it is working as normal…