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…
Unfortunately I’m back again with this problem. However it is now clear that this rule is not only not executed triggered by astro events, but by cron events also. Sometimes it works as it should sometimes not. Now I’m on 2.4 M4 (the latest Milestone build) and I have experienced not only this, but (which was always there in my setup):
- Randomly one or more rules don’t get executed. Moreover not only don’t get executed but the event won’t trigger my rule. I have some rule which has a logInfo in the beginning of the rule and when an event should trigger the rule I can only see in the events.log that the corresponding trigger Item state changed, but not the log which the rule should produce
- I have increased the execution threads to 7 so now I always have at least 3-4 thread which is available.
- When these ‘rules don’t get executed’ errors happen I can’t see any change on hardware side (CPU load is around 5-10%, memory is not full, everything works as before).
- Moreover I even don’t have to restart openHab or RPi, just wait a couple of hours and everything is back to normal. The logs also don’t produce any significant error or any unfamiliar thing for me.
Both Astro and cron triggered Rules are triggered from a separate thread pool.
Do you know for sure this is the case? See the post I replied with above, particularly post 12. Look at the quartz thread pool to see if you are using those up. You cannot have more than two cron triggered Rules run at the same time.
Also, do you see “Scheduled Astro event-jobs for thing astro:sun:home” for each of your Astro Things? If not then the events are not even being scheduled which points to a problem with the Astro binding.
Look to see if all your RuleEngine threads are running too.
That might be one problem. I have another rule which is triggered by cron exactly at 11pm. I will change that and see if it helps
Dear @rlkoshak!
I have tried simplyfing my rules and removing any unnecessary cron triggers from rules. Now my system mostly depends on the Time Of Day rule if the rule is based on day-states.
However I still have the original problem. My rule which turns on and off the LEDs (I have the same rule as in the original post), sometimes don’t get executed. I have made sure that there is enough rule execution thread is available all-time, so it might be some other problem. Funny though that I can see the log produced by the rule along all day, but not at night… (where this rule really works…)