Sometimes rules don't get executed?

rkrisi · September 10, 2018, 4:31pm

Dear Community!

I have found that sometimes my rules won’t get executed. For example right now, I’m using @rlkoshak method to calculate the time of the day. It worked for weeks now without a problem, but today morning it stopped executing. Now the time of day should be evening, but it stuck at Morning. However this was not the first time when I experienced this.

For example I have a rule which turns the LEDs on at night when motion is detected.

rule "Night Light in Kitchen and Living Room"
when
	Item Zone4 changed
then
	logInfo("wifiled.rules", "Night Light rule started!")
	if(Zone4.state.toString == "ON" && (vTimeOfDay.state == "BED" || vTimeOfDay.state == "NIGHT") && CurrentActivityHub.state.toString == "PowerOff" && (Sonoff.state.toString == "OFF" || Sonoff.state.toString == "UNDEF" || Sonoff.state.toString == "NULL")) {
		
		// LED on -- Reset timer or start it, if it was turned on before...
		if(gKitchenLedLight.state.toString == "ON") {
			Turn_Off_Leds.sendCommand(ON)
			logInfo("wifiled.rules", "Reset timer")
		}

		// Turn everything on
		else {
			wifiled_presets.sendCommand(3)
			wifiled_livingroom.sendCommand(ON)
			Turn_Off_Leds.sendCommand(ON)
			logInfo("wifiled.rules", "Turning on the LEDs...")
		}
	}
end

As you can see I have a logInfo at the beginning which should get executed every time this rule fires. However I logged this at one night when it stopped working… I was able to see in the log that my Item Zone4 changed from OFF to ON, but the rule don’t even wrote that logInfo into the logs…

Anyone experienced something similar? Which might be the cause of this? I can’t narrow down the problem, because it happens very randomly and after a little time it starts working again (without restart or anything)

rlkoshak · September 10, 2018, 4:34pm

It could be related to Why have my Rules stopped running? Why Thread::sleep is a bad idea.

The time of day may be a problem with the Astro binding. I’ve been helping one other person with an issue where Astro is not rescheduling the sunrize/sunset events every day. What are you triggering the Rule with?

mstormi · September 10, 2018, 4:37pm

Use karaf console to enable debug debugging level for
org.eclipse.smarthome.script
org.eclipse.smarthome.script.model.wifiled.rules

The first one should get you a debug line in openhab.log whenever your rule is called, the 2nd will ensure your logInfo(…) lines will result in log lines. Add some more logInfo() or logDebug() lines to output the triggering item (Zone4) and find out how far into the rule it’s working.
If that does not show anything, it’s likely related to the triggering item (Zone4) not changing.

rkrisi · September 10, 2018, 4:38pm

I don’t really use Thread::sleep, only 1-2 times in all my rules and only for 1-2 seconds and these rules are only run a few times a day. Or this can also cause this?

I can’t really understand your question (sorry ) but I’ll try to provide some info…
I almost copied your solution. The rule is triggered by astro events, just seen in your solution. Then the calculated time of day is written to a String item

rlkoshak · September 10, 2018, 4:41pm

Any sendHttp*Request calls or executeCommandLine calls? Do you have any feedback loops that may have been unnoticed until now?

The Rule triggers are defined between the when and then.

Is the Rule ONLY failing to trigger for the Thing channel triggers or cron Time triggers too?

rkrisi · September 10, 2018, 4:45pm

Sorry this is what I thought… I’ll log when it fails, because since morning there was no cron trigger (it triggers 1min after midnight, 6am, and 23am).

I have only one sendHttpGetRequest (a rule which uses Google API to get postal address from geocode), and the timeout is defined to 20s, which is really big, but I had problems with this rule as well and I left it like that. Should I decrease this? (That rule is working right now…)

rlkoshak · September 10, 2018, 4:51pm

As long as that Rule never gets executed faster than every 20 seconds it should be OK.

rkrisi · September 10, 2018, 4:52pm

This is triggered by multiple Location (more phones), and the iCloud binding refreshes periodically, so I think it might be sometimes triggered within 20 secs… what happens if it is triggered multiple times in 20 sec?

rlkoshak · September 10, 2018, 4:56pm

See my link posted above about Why have my Rules Stopped running?

rkrisi · September 10, 2018, 5:01pm

Thanks I’ll read it carefully. Maybe if you have a little time I wanted to ask you something.
Also in this rule (where is a sendHttpGetRequest) sometimes I get a ‘null’ response. I wanted to deal with this, so I compared the the output with “null”. However it seems that doesn’t really matters… I don’t really see that an old location is sent to the item with a ! in the beginning.

    if(formattedAddress !== "null") {
      postUpdate(triggeringiPhoneName, formattedAddress)
    }
    else {
      val locationItem = gPhoneLocationString.members.findFirst[i | i.name == triggeringiPhoneName]
      val String oldFormatAddress = "! " + locationItem.state
      postUpdate(triggeringiPhoneName, oldFormatAddress)
    }

What should be wrong? Tried first with ‘!=’ but then I somewhere read that you should compare it with ‘!==’. However I was right, this doesn’t really compare by content, but by memory address (in Java), am I right? Tried comparing it with equals, no success…

rlkoshak · September 10, 2018, 5:04pm

Are you certain that the sendHttpGetRequest returns null or does it timeout and throw an exception/error in the log?

rkrisi · September 10, 2018, 5:07pm

I’m sure that it returns null, because before this if clause I was able to see sometimes ‘null’ on my sitemap at the regarding item state.
Some week ago I have bundled the sendHttpGetRequest around with a try and catch, but I wasn’t able to grab a TimeoutException.

val geocodeURL = "https://maps.googleapis.com/maps/api/geocode/json?latlng=" + Latitude + "," + Longitude + "&sensor=true&key=" + GoogleAPIKey
    var String gecodeResponse

    // Trying to get the location
    try {
      gecodeResponse = sendHttpGetRequest(geocodeURL, 20000)
    }
    catch(java.util.concurrent.TimeoutException e) {
      logWarn("LocationToString.rules", "Received timeout exception, skipping item update")
    }

rlkoshak · September 10, 2018, 5:11pm

null is not the same thing as NULL. When an Item first comes up or when one attempts to set an Item to an invalid value, that Item’s state becomes NULL.

null is something that only exists in Rules.

TimeoutException may not be the top level Exception that gets thrown .Try just catching Exception. Beyond that add some logging to verify that it is returning null when it does time out.

rkrisi · September 10, 2018, 5:13pm

Thanks for your help! I’ll try to narrow down this problem
This is what it looks like now, I think I should be able to see the json respone when it times out…

    catch(Exception e) {
      logWarn("LocationToString.rules", "Received timeout exception, skipping item update ->" + gecodeResponse)
    }

rkrisi · September 10, 2018, 5:22pm

Just two things to mention:

Now somehow the time of day is updated to represent the current state.

2018-09-10 19:06:00.036 [INFO ] [arthome.model.script.day_state.rules] - Calculating time of day...
2018-09-10 19:06:00.192 [INFO ] [arthome.model.script.day_state.rules] - Calculated time of day is EVENING
2018-09-10 19:06:12.206 [WARN ] [rm.AbstractFileTransformationService] - Could not transform 'UNDEF' with the file 'astro.map' : Target value not found in map for 'UNDEF'

There is an item which is undefined… why?

Also I wanted to mention that when this day_state.rule runs, I sometimes get error like:

2018-09-10 19:13:15.221 [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

Which is the rule we talked about now (handling the postal code conversion). But I only get this kind of error when the day_state rule runs or just after reboot.

rlkoshak · September 10, 2018, 5:53pm

Which Item?

If it is only during reboot it is a known bug that occurs when Rules start running before all the Items are loaded. If it is every time this Rule runs I’d ask if that Item exists or if you may have a typo in the name.

rkrisi · September 10, 2018, 5:56pm

I’ll look into which item is undef. The strange thing that this rule works fine (without errors), just throws this error upon startup (so it surely because what you said) and when the day_state rule runs. It seems like when day_state rule is executed this rule also gets executed (don’t know why) and thatks why it can’t call that function because the triggeringItem is different

Ps: if I can remember right, this happens since I have added System started trigger to the LocationString rule.

rlkoshak · September 10, 2018, 6:41pm

Because the day_state Rule is posting an update or sending a command to an Item that triggers the Rule.

That certainly points to the aforementioned bug.

rkrisi · September 10, 2018, 6:44pm

Thanks!

I have tried to decrease the timeout in the rule to 2000ms, but it is not enough to get a response from Google. Now I’m trying it with 10000ms. And this rule is triggered by 4 Location item which updates (almost) together, so that means I use min. 4 Rule execution thread just by this rule for seconds…

rlkoshak · September 10, 2018, 6:46pm

You can put the sendHttpRequest and everything that follows it into a Timer and that will at least move the problem to a different thread pool.