IllegalStateException and no clue where it might come from

I’m running the following rule since quite some time already and it occasionaly throws the following exception:

20:45:29.182 [ERROR] [.eclipse.smarthome.model.script.Error] - Some bad stuff happened in my Buffer rule: java.lang.IllegalStateException

The rule itself is this

rule "Buffer Energy"
when
	Item Energy_Buf received update
then
	for (buffer :  Energy_Buf?.members) {
		try {
			val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.substring(0, buffer.name.lastIndexOf("_")))]
			if(buffer.state != NULL && energyItem != NULL) {
				if(energyItem.state == NULL) {
					//logError(energyItem.name, "Updating to " + buffer.state)
					postUpdate(energyItem, buffer.state)
				} else if((energyItem.state as DecimalType).floatValue < (buffer.state as DecimalType).floatValue && ((buffer.state as DecimalType).floatValue - (energyItem.state as DecimalType).floatValue) < 15.0) {
					//logError(energyItem.name, "Updating to " + buffer.state)
					postUpdate(energyItem, buffer.state)
				} else {
					if(energyItem.state != buffer.state)
						logError(energyItem.name, "Bad value " + buffer.state + ", current is " + energyItem.state)
				}
			}
		} catch(Throwable t) {
			logError("Error", "Some bad stuff happened in my Buffer rule: " + t.toString)
		}
	}
end

The rule is responsible for filtering values that shouldn’t be in there. Did I miss anything that could cause this exception? I checked for null values there so I can’t think about where the issue might come from.

This should do the same:

val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.split("_").get(0))]

Use Numbers instead and double check the ():

		} else if ( ((energyItem.state as Number) < (buffer.state as Number)) && (((buffer.state as Number)  - (energyItem.state as Number)) < 15.0) ) {

Uncomment your logError and cange them to logInfo and add some more in the rule to find out where it is failing

I made them LogError on purpose as I have about 10-20 values updated per second, not marking this red makes it very difficult to find the appropriate lines in log:tail

I have added a few more debug outputs so it looks like this now:

rule "Buffer Energy"
when
	Item Energy_Buf received update
then
	for (buffer :  Energy_Buf?.members) {
		try {
			//val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.split("_").get(0))]
			val energyItem = Energy_Log.members.findFirst[name.equals(buffer.name.substring(0, buffer.name.lastIndexOf("_")))]
			logError(energyItem.name, "Got item!")
			if(buffer.state !== null && energyItem !== null) {
				logError(energyItem.name, "Item is not null!")
				if(energyItem.state === null) {
					logError(energyItem.name, "Updating to " + buffer.state)
					postUpdate(energyItem, buffer.state)
				} else if ( ((energyItem.state as Number) < (buffer.state as Number)) && (((buffer.state as Number)  - (energyItem.state as Number)) < 15.0) ) {
					logError(energyItem.name, "Updating to " + buffer.state)
					postUpdate(energyItem, buffer.state)
				} else {
					if(energyItem.state != buffer.state)
						logError(energyItem.name, "Bad value " + buffer.state + ", current is " + energyItem.state)
				}
			} else {
				logError("EnergyRule", "Either buffer is null or no destination found!")
			}
		} catch(Throwable t) {
			logError("Error", "Some bad stuff happened in my Buffer rule: " + t.toString)
		}
	}
end

And I am getting this now:

21:34:18.959 [ERROR] [home.model.script.Energy_Office_Total] - Got item!
21:34:18.962 [ERROR] [home.model.script.Energy_Office_Total] - Item is not null!
21:34:18.967 [ERROR] [.eclipse.smarthome.model.script.Error] - Some bad stuff happened in my Buffer rule: java.lang.IllegalStateException
21:34:18.980 [ERROR] [smarthome.model.script.Energy_Heating] - Got item! 

I think the issue is caused by the comparison? But why would that cause an IlegalStateException?

That looks wrong

			if(energyItem.state === null) {

Do this instead:

			if(energyItem.state == NULL) {

1 Like

log:tail /var/log/openahb2/openhab.log | grep “Error”

If this Rule is getting run so frequently that you have more than one instance of it running at the same time there can sometimes be strange interactions between the various instances. I usually see the problem most frequently when the two are working on members of a Group or the like, Certain parts of Rules DSL are not terrible thread safe.

If the fix Vincent makes doesn’t solve things then tell us some more about how this Rule gets triggered.

I added a Lock for now and it looks like this fixed it, seems like there was an issue that reading and writing on the same variable at the same time caused. Shouldn’t the structure under this (OpenHAB itself) take care of this to prevent issues like this (lock item before writing/reading and unlock after writing/reading)?

One can argue either way for whether it should or shouldn’t but the fact is it doesn’t.

Be careful with locks. See Why have my Rules stopped running? Why Thread::sleep is a bad idea.

If this rule is being called that frequently, you might be better off using JSR223 Rules which support this sort of rule better. However, you should consider only triggering the rule on charges if that is possible. If not, try the rule using Member of trigger. When you use received update with a Group item the rule gets triggered N-1 times where N in the number of members for every update.

In short, this rule is spending a while lot of time running when it didn’t need to. I see nothing in the logic that would make Member of changed inappropriate. Though Member of received update would still probably fix the original problem without the need for locks. If you have 5 members, the rule triggers and runs 4 times every time any one of the 5 members updates.

Similar error and no idea why?

Debug version of my rule:

rule "heartbeat_rule"
when
  Member of gHeartbeat changed
then
  var ddd = ""
  try {
    var int logLevel = 6
    ddd += "a"
    if (HH_DebugLevel_Heartbeat.state !== NULL) {
      logLevel = (HH_DebugLevel_Heartbeat.state as Number).intValue
    }
    ddd += "b"
    if (logLevel >= 6) {
      logError("Heartbeat", "Heartbeat change detected {} {}", triggeringItem.name, triggeringItem.state)
    }
    ddd += "c"
    var lastupdate_item = gLastUpdate.members.findFirst[name.equals(triggeringItem.name + "_LastUpdate")]
    ddd += "d"

    if (logLevel >= 6) {
      logError("Heartbeat", "lastupdate_item {}", lastupdate_item)
    }
    ddd += "e"
    if (lastupdate_item !== null) {
      lastupdate_item.postUpdate(now.toString())
      if (logLevel >= 6) {
        logError("Heartbeat", "Last update item {} {}", lastupdate_item.name, lastupdate_item.state)
      }
    }
    ddd += "f"
  } catch (Throwable t) {
    logError("Error", "Error in heartbeat_rule {} {} {} {}", ddd, triggeringItem.name, triggeringItem.state, t.toString)
  } finally {
  }
end

and an error:

2019-04-14 17:37:23.354 [ERROR] [eclipse.smarthome.model.script.Error] - Error in heartbeat_rule abc myItem 847438848.00 java.lang.IllegalStateException

Error occurs “sometimes” on (sometimes means: once per dozens of rule execuitions).

var lastupdate_item = gLastUpdate.members.findFirst[name.equals(triggeringItem.name + "_LastUpdate")]

It looks like findFirst function returns exception when it iterates through group of items and finds during iteration non-initialized item in the group.

It occurs on stable 2.4.0 and trunc 2.5.0 versions (as I’ve checked).

How frequently does this Rule run? Does it every run more than once at the same time?

There are some threading issues that look a whole lot like the error you report when you are iterating over a Group’s members and the state of one of those members changes while the Rule is running.

That’s may be a point. But in fact this is an error. I am not interested in changes of other members. For this specific rule I just want to organize Items in collection easy to maintain in rules and UI.

Can you consider to i.e. add ability to find item with i.e. flag dirtyread to ignore potential changes in items? Otherwise I’ll have to organize some synchronized procedure to make access to this group sequential.

As I see this is known issue and that’s can be the compromise between overall data coherency and specific usage.

I can’t do anything. I’m not a developer on OH. But you can file an issue and perhaps one of them will be able to address the issue.

Those isn’t something that you will be able to fix with a lock because the changes are taking place outside if the roles and therefore outside of your control.

It might be the case that this error doesn’t occur in JSR223 Rules but I can’t guarantee it. The last time I saw something like this, I used a different approach (for this and other reasons) which side street the issue.

I have the same error with some of my rules.
These rules based on the iCloud binding, so multiple devices gets updated together and a rule runs for each device (and also there is other item queries from other groups like above). So I think this causes the error, but not every time, only a few times per day, however this rule runs every 5 min. But it might happen that at that time one rule finishes earlier than another is finished with quering the members…