Rules errors while system startup in 2.5.2-SNAPSHOT build 32: "cannot be resolved to an item or type" and [SOLVED] Max binding spamming logfile

Celaeno1 · January 28, 2020, 7:23pm

Hello folks,

I’ve updated from 2.5.0-SNAPSHOT, build 1762 to 2.5.2-SNAPSHOT build 32.

I’m on Windows 10, 64 bit.

Now, three of my rules getting errors during system startup. They were running for nearly 3 years now.
.
.
And my logfile get spamed with smarthome.event.ItemStateChangedEvent

ITEMS:

DateTime WindowsEG_LastUpdate   "Offene Fenster EG: letzte Akt. [%1$ta %1$tR]" <time>
DateTime WindowsUG_LastUpdate   "Offene Fenster UG: letzte Akt. [%1$ta %1$tR]" <time>
DateTime Weather_LastUpdate     "Letzte Aktualisierung [%1$ta %1$tR]"	<time>

.

RULES:

// Creates an item that stores the last update time of this item

rule "Records last windows EG update time"
	when
		Item WindowsEG received update
	then
		postUpdate(WindowsEG_LastUpdate, new DateTimeType())
end

rule "Records last windows UG update time"
	when
		Item WindowsUG received update
	then
		postUpdate(WindowsUG_LastUpdate, new DateTimeType())
end

rule "Records last Motion1 update time"
	when
		Item Motion1 received update
	then
		postUpdate(Motion1_LastUpdate, new DateTimeType())
end

// Creates an item that stores the last update time of this item
rule "Records last weather update time"
when
  Item Weather_Temperature received update
then
  postUpdate(Weather_LastUpdate, new DateTimeType())
end

.
.

ERRORS:

19:48:27.953 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'WindowsEG_LastUpdate' cannot be resolved to an item or type; line 395, column 14, length 20
19:48:27.955 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows UG update time': The name 'WindowsUG_LastUpdate' cannot be resolved to an item or type; line 402, column 14, length 20
19:48:18.569 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last weather update time': The name 'Weather_LastUpdate' cannot be resolved to an item or type; line 417, column 14, length 18

19:48:28.175 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'postUpdate' cannot be resolved to an item or type; line 395, column 3, length 52
19:48:28.174 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'postUpdate' cannot be resolved to an item or type; line 395, column 3, length 52
19:48:28.174 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'postUpdate' cannot be resolved to an item or type; line 395, column 3, length 52
19:48:28.174 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'postUpdate' cannot be resolved to an item or type; line 395, column 3, length 52

LOGS:

20:01:22.549 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.527+0100 to 2020-01-28T20:01:22.546+0100
20:01:22.621 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.546+0100 to 2020-01-28T20:01:22.610+0100
20:01:22.651 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.610+0100 to 2020-01-28T20:01:22.616+0100
20:01:22.673 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.616+0100 to 2020-01-28T20:01:22.629+0100
20:01:22.674 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.629+0100 to 2020-01-28T20:01:22.630+0100
20:01:22.678 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.630+0100 to 2020-01-28T20:01:22.637+0100
20:01:22.679 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.637+0100 to 2020-01-28T20:01:22.638+0100
20:01:22.680 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsUG_LastUpdate changed from 2020-01-28T20:01:02.493+0100 to 2020-01-28T20:01:22.647+0100
20:01:22.681 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.638+0100 to 2020-01-28T20:01:22.648+0100
20:01:22.682 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.648+0100 to 2020-01-28T20:01:22.649+0100
20:01:22.683 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsUG_LastUpdate changed from 2020-01-28T20:01:22.647+0100 to 2020-01-28T20:01:22.650+0100
20:01:22.684 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.649+0100 to 2020-01-28T20:01:22.648+0100
20:01:22.686 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.648+0100 to 2020-01-28T20:01:22.649+0100
20:01:22.687 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.649+0100 to 2020-01-28T20:01:22.650+0100

Bruce_Osborne · January 28, 2020, 7:25pm

Did you try clearing the cache or restarting after the update? It looks like your file based Items files may not have been read in properly.

That is assuming there are no errors in the snapshot. Snapshot errors should always be reported as issues on GitHub. That is part of the implicit testing agreement when running snapshots.

Celaeno1 · January 28, 2020, 7:39pm

Im on Windows. The cache was cleared before update from update.ps1.

Celaeno1 · January 28, 2020, 8:23pm

I’ve cleared Cache again.

Same results.

I found out that SPAMING my logs comes from max binding.

When I stop the Max binding, SPAMING is over.

I seems to be a similar problem to this topic. But it is only a guess.

Bruce_Osborne · January 28, 2020, 8:28pm

Might be worth opening a GitHub issue for that.
You might try to determine which Thing or Item is causing you grief.

Celaeno1 · January 28, 2020, 8:34pm

Yes, I’m going to do this. Have to analyze all the logs or deactivate one max shutter thing at a time.

Bruce_Osborne · January 28, 2020, 8:37pm

If that is a change in behaviour from 2.5.1 I think the developer needs to know through GitHub too.

Celaeno1 · January 28, 2020, 8:40pm

If I find out that it is a problem with max, I will create an issue on Github.

vzorglub · January 28, 2020, 8:41pm

Have you tried

Weather_LastUpdate.postUpdate(new DateTimeType())

instead of

postUpdate(Weather_LastUpdate, new DateTimeType())

As recommended there: https://www.openhab.org/docs/configuration/rules-dsl.html#myitem-sendcommand-new-state-versus-sendcommand-myitem-new-state

Celaeno1 · January 28, 2020, 8:48pm

Thanks for the hint.

I’m going to try this asap.

rlkoshak · January 28, 2020, 8:59pm

This looks a lot like a problem I’ve experienced and @hilbrand has already filed an issue for. There is no fix known yet.

The symptom is after a clear the cache, some to all Items are simply gone as far as OH is concerned. If you open the sitemap you’ll get bombarded with “Item doesn’t exist” errors. Rules that run will bombard you with errors like the above.

The work around is after clearing the cache, let OH fully come up and settle. Then restart OH. Don’t do anything else, just a restart. That seems to clear it. I’ve seen one report that a user needed to restart a couple of times so if it doesn’t work after one restart, try it again.

Celaeno1 · January 28, 2020, 10:45pm

@vzorglub
@rlkoshak

I’ve changed it to:

Weather_LastUpdate.postUpdate(new DateTimeType())

Rules are running, but…

I get above errors only at system startup!

I want to initialize my *_LastUpdate items (see above) during startup with
something like DateTime = now

rule "Startup"
when
    System started
then
    if (Weather_LastUpdate.state == NULL || Weather_LastUpdate.state == "") {
      Weather_LastUpdate.postUpdate(???)
    }
end

What do I have to fill in for (???) ?

rlkoshak · January 28, 2020, 10:54pm

You could try now.toString. That should work.

Celaeno1 · January 28, 2020, 11:33pm

Syntax is correct, but rule did not help.

rule "Startup"
when
    System started
then
    if (Weather_LastUpdate.state == NULL || Weather_LastUpdate.state == "") {
      Weather_LastUpdate.postUpdate(now.toString)
    }
end

Rule gets loaded during reload without any errors.

Still errors during system startup:

19:48:27.953 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows EG update time': The name 'WindowsEG_LastUpdate' cannot be resolved to an item or type; line 395, column 14, length 20
19:48:27.955 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last windows UG update time': The name 'WindowsUG_LastUpdate' cannot be resolved to an item or type; line 402, column 14, length 20 
19:48:18.569 [ERROR] [untime.internal.engine.RuleEngineImpl] - Rule 'Records last weather update time': The name 'Weather_LastUpdate' cannot be resolved to an item or type; line 417, column 14, length 18

rossko57 · January 29, 2020, 12:26am

I’m sure you’ve already checked that you have a xxx.items loaded message in your openhab.log at startup.
How long is that before xxx.rules loaded message?

Celaeno1 · January 29, 2020, 4:43am

Good idea. I’m going to check it asap.

Celaeno1 · January 29, 2020, 5:39am

2020-01-29 00:08:55.206 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.items'
2020-01-29 00:08:56.695 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'logging.persist'
2020-01-29 00:08:56.737 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2020-01-29 00:08:57.362 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2020-01-29 00:08:57.753 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.things'
2020-01-29 00:09:15.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'

About 20 seconds.

Better should use?

createTimer(now.plusSeconds(30)

csi_oh · January 29, 2020, 6:31am

Hi @Celaeno1,

we we’re in contact yesterday - in this topic I was given the advice there to clear the cache, resulting in the very same problems (names can’t be resolved, rules not working).

After restarting twice (as @rlkoshak mentioned here), everything was working fine again.

In addition to that, I’m doing the following for items that aren’t updated by bindings;

proxy.items

[...]
Switch Kueche_Rollo_Override "Küche Rollo Override" (gOverrides)
[...]

startup.rules

when
    System started
then
    [...]
    Kueche_Rollo_Override.postUpdate(OFF)
    [...]
end

KR
Chris

5iver · January 29, 2020, 6:47am

I had created an issue for this, thinking it was a good issue to resolve before the 2.5 release, but that didn’t happen and it was closed…

Here’s another issue that appears to be the same/related and is still open…

If anyone else is experiencing this, it would be helpful if you would comment in the latter issue.

Celaeno1 · January 29, 2020, 8:03am

I’m going to do further investigations, but not before this evening. Reloading the rules is a workarround in the meantime.

I also will investigate the spaming of logfile every few milliseconds:

20:01:22.549 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.527+0100 to 2020-01-28T20:01:22.546+0100
20:01:22.621 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.546+0100 to 2020-01-28T20:01:22.610+0100
20:01:22.651 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.610+0100 to 2020-01-28T20:01:22.616+0100
20:01:22.673 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.616+0100 to 2020-01-28T20:01:22.629+0100
20:01:22.674 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.629+0100 to 2020-01-28T20:01:22.630+0100
20:01:22.678 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.630+0100 to 2020-01-28T20:01:22.637+0100
20:01:22.679 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.637+0100 to 2020-01-28T20:01:22.638+0100
20:01:22.680 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsUG_LastUpdate changed from 2020-01-28T20:01:02.493+0100 to 2020-01-28T20:01:22.647+0100
20:01:22.681 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.638+0100 to 2020-01-28T20:01:22.648+0100
20:01:22.682 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.648+0100 to 2020-01-28T20:01:22.649+0100
20:01:22.683 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsUG_LastUpdate changed from 2020-01-28T20:01:22.647+0100 to 2020-01-28T20:01:22.650+0100
20:01:22.684 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.649+0100 to 2020-01-28T20:01:22.648+0100
20:01:22.686 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.648+0100 to 2020-01-28T20:01:22.649+0100
20:01:22.687 [INFO ] [smarthome.event.ItemStateChangedEvent] - WindowsEG_LastUpdate changed from 2020-01-28T20:01:22.649+0100 to 2020-01-28T20:01:22.650+0100

I suspect that it is caused by one or more window shuttercontacts. They are all provided by the max binding.
Never had this issue before.

EDIT:
Maybe it has to do with this PR 6692?

@marcel_verpaalen Could this be? It’s only a guess…