Items not found when displaying sitemap or executing rules #865

mhilbush · 2019-06-10T18:20:09Z

I just installed build 1607 on a system that had been running 1502 for quite a while.

After an openHAB restart, sometimes, when displaying a sitemap, I see errors in my log indicating that items cannot be found, even though the items exist.

I've found each of the following things will clear the issue:

sometimes a restart will clear the issue
modifying an items file will clear the issue for the items defined in that file
stopping/starting org.openhab.core.model.item also resolves the issue

Could there be a timing issue where a dependent bundle might not be available at the right time during startup?

Example of errors.

2019-06-10 13:44:57.912 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:44:57.914 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve visibility item OH_Status for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:44:57.915 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'OH_Status' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:44:57.916 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'OH_Status' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:44:57.917 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'OH_Status' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.191 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.193 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Mark_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.194 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Mark_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.196 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Mark_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.198 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.199 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Cathy_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.200 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Cathy_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text
2019-06-10 13:45:50.201 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Uptime_Cathy_Formatted' for widget org.eclipse.smarthome.model.sitemap.Text

The text was updated successfully, but these errors were encountered:

pavel-gololobov · 2019-06-14T11:45:32Z

I confirm the issue. Build #1603 (x86_64, Debian 9, Docker)

mhilbush · 2019-06-19T16:06:36Z

I saw one other bit of weirdness, which I think might be related to this.

I have an .items file containing some item and group definitions. After starting openHAB, the group is empty. But, if I then save a small change to the .items file (such as adding a blank line), the group now contains the items.

5iver · 2019-06-19T18:46:28Z

I see this often after clearing the cache. After upgrading OH, I do wait a bit and then do another OH restart to get passed this. The scope of this issue is larger than sitemaps... rules fail due to missing Items. I have also not seen this happen to managed Items.

mhilbush · 2019-06-19T18:54:17Z

I see this often after clearing the cache. After upgrading OH, I do wait a bit and then do another OH restart to get passed this.

In recent snapshots I'm seeing this after almost every restart (with or without clearing cache).

The scope of this issue is larger than sitemaps... rules fail due to missing Items.

Agreed.

kaikreuzer · 2019-06-19T20:12:58Z

Sounds to me as if either something has changed wrt to start levels or by having a different startup behavior by recent refactorings wrt service activation (constructor injection, "immediate=true" removals, etc. That'll be very tricky to figure out...

5iver · 2019-06-19T22:29:30Z

Sounds to me as if either something has changed wrt to start levels or by having a different startup behavior by recent refactorings wrt service activation

I've seen this since before the constructor injection PRs. I don't specifically remember, so could be mistaken, but I want to say that it's been happening since S1566. If needed, it wouldn't be hard to test.

In my setup, I've only seen this after clearing the cache.

mhilbush · 2019-06-20T11:54:26Z

I installed build 1618 (the one with the fix for #829) on two systems (one test system and one production system) where I was seeing this issue consistently on startup. After several restarts on each of those systems, I'm no longer seeing the issue. 😕

I'll monitor for a while. If it no longer occurs, I'll close this.

5iver · 2019-06-20T21:07:38Z

I did not see the error with S1618, but several rules failed to load due to Items not being present...

2019-06-20 16:27:11.764 [ERROR] [jsr223.jython.core.triggers] - when: Exception [when: "Item Mode changed" could not be parsed because Item "Mode" is not in the ItemRegistry]: [Traceback (most recent call last):
  File "/opt/openhab2/conf/automation/lib/python/core/triggers.py", line 510, in when
    raise ValueError("when: \"{}\" could not be parsed because Item \"{}\" is not in the ItemRegistry".format(target, trigger_target))
ValueError: when: "Item Mode changed" could not be parsed because Item "Mode" is not in the ItemRegistry
]

Other rules started properly. I suppose this is just a timing issue with the rule engine starting before the Items are available, but I have a script to delay the loading of other scripts to prevent this. And I also found these errors...

2019-06-20 16:24:49.615 [ERROR] [org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler] - An error occurred while calling method 'QueryablePersistenceService.query()' on 'org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate@464fdcc6': java.lang.String cannot be cast to java.lang.Integer
java.lang.ClassCastException: java.lang.String cannot be cast to java.lang.Integer
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.objectAsInteger(JdbcBaseDAO.java:538) ~[?:?]
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.getState(JdbcBaseDAO.java:491) ~[?:?]
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:348) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:158) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:205) ~[?:?]
        at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:51) ~[?:?]
        at sun.reflect.GeneratedMethodAccessor53.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [137:org.openhab.core:2.5.0.201906200301]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [137:org.openhab.core:2.5.0.201906200301]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-06-20 16:24:49.631 [ERROR] [org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl] - Exception occurred while querying persistence service 'jdbc': java.lang.String cannot be cast to java.lang.Integer
java.lang.ClassCastException: java.lang.String cannot be cast to java.lang.Integer
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.objectAsInteger(JdbcBaseDAO.java:538) ~[?:?]
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.getState(JdbcBaseDAO.java:491) ~[?:?]
        at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:348) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:158) ~[?:?]
        at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:205) ~[?:?]
        at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:51) ~[?:?]
        at sun.reflect.GeneratedMethodAccessor53.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [137:org.openhab.core:2.5.0.201906200301]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [137:org.openhab.core:2.5.0.201906200301]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

I use jdbc-mariadb for persistence. After a restart of OH, everything was OK.

mhilbush · 2019-06-24T16:56:05Z

I now have 1622 running on three systems (one test and two production). I've not seen this issue on any of those systems since installing build 1618 or later. Therefore, I'm closing this issue.

mhilbush · 2019-10-10T14:24:54Z

I'm reopening this issue because similar behavior was reported recently on the forum.

https://community.openhab.org/t/oh2-system-behavior-after-upgrade-some-items-not-resolved/83373

rkoshak · 2019-10-10T14:39:21Z

I don't have a lot to add except that I'm seeing the same as openhab-5iver. When I upgrade or clear the cache the first boot results in lots of missing Item errors from both the sitemap and Python rules (e.g. cannot create Rule triggers). I just need to wait patiently for OH to fully start up and then a restart of OH will work like it should. I can't remember when I first saw this (I should have written that down) but I can confirm that yesterday when I updated to build 1715 I saw the same behavior.

All my Items are defined in .items files.

macdroid53 · 2019-10-10T14:44:24Z

I don't have much to add as well. But, this thread details my experiences and are similar to mhilbush.

[https://community.openhab.org/t/oh2-system-behavior-after-upgrade-some-items-not-resolved/83373]

This started for me after the following upgrade:
From:
OH 2 on a raspberry Pi. (openHAB 2.5.0~S1566-1 (Build #1566))

To:
openHAB 2.5.0~S1645-1 (Build #1645)

mstormi · 2019-12-09T14:43:42Z

Hasn't it been like that ever since ? Remember ESH#1892 (IIRC), that no-startlevels thingy.

mhilbush · 2019-12-09T14:57:22Z

Hasn't it been like that ever since ?

Yes, it was not uncommon to see this on the first startup after an upgrade.

However, the behavior I was seeing was occurring consistently on every startup, which from my perspective was new behavior.

mstormi · 2019-12-09T15:21:50Z

I've ever been seeing that. Possibly more visible because my RPi is slower than most of your boxes.
That's why I added that script to delay rules loading to openHABian.

mhilbush · 2019-12-09T16:22:58Z

But it's not just a rules thing. It impacts sitemaps, as well as console smarthome:send commands. Essentially anything that tries to use an item.

mstormi · 2019-12-09T16:27:33Z

Yes but the predominant problem is with rules, in particular when these take long to compile (such as they do on Raspis if you use primitives there - I for instance have got a rules file that takes 90-100 secs. to load. Almost nothing else to work meanwhile).
That's probably why most of you non-RPi users didn't get to see that issue or did but have not realized how much of a problem it is to some users.

mhilbush · 2019-12-09T16:32:37Z

I would disagree. I view it as a problem with rules AND sitemaps (or any UI for that matter) equally. And, for the problem I'm describing in this issue, no amount of delay in loading the rules will resolve the situation.

mstormi · 2019-12-09T17:00:01Z

Oh that's right. I didn't mean to say to delay rules actually solves the problem(s).

t2000 · 2020-06-15T17:14:31Z

I just did an update from one openHAB snapshot to the latest 2.5.6 build #144 and experienced missing items (like on a few updates before).

Then I searched for related bugs and found this issue. I am not sure if its only timing related, which might then be fixed by #1514, because I observed the following:

By comparing the output of "items list" after startup with an "items list" after I had done "touch *.items" in bash, I could see a pattern showing WHICH items were not loaded:

items that are NOT linked to any channel (dummy items used for rules only, for example)
items filled by openhab-1 bindings, like from the caldav or fritz tr64 binding
items that are linked to a channel that belongs to a thing whose binding isn't installed currently

So all these items didn't exist after my update and only appeared once I refreshed the .items files.

ALL items that were linked against openHAB-2 thing channels were correctly loaded!

@kaikreuzer FYI: Since you have just worked on improving the model loading. Maybe my observation rings a bell to you.

weakfl · 2020-09-23T09:39:00Z

@t2000 items that are NOT linked to any channel (dummy items used for rules only, for example)

I can confirm this observation, only items without a channel seem to be affected.

mhilbush · 2020-12-11T22:42:07Z

I'm closing this as it may be fixed as a result of changes for OH3.

* Fixed links in uis.md Multiple dead links fixed * Fix links multiple links to addons page fixed * Delete reference to non-existing doc page Reorg of docs made the referenced chapter obsolete * Fixed multiple links various links fixed * Fixed links links to section addons fixed Deleted reference to yahooweather binding (now obsolete) as example for binding that requires manual thing definition. * link fixed link to addons section fixed * fixed link fixed link to UI selection screen * Fix link Fixed link to addons section * Fix links, update example Signed-off-by: Markus Lipp [email protected] (github: LightIsLife) Links to addon section and others fixed. Old example using the now obsolete Yahooweather binding has been replaced with an example using the network binding * delete link habpanel.md Deleted inexisitng link * Fix links index.md Fixed links * Fix link sitemaps.md (code review) * Update installation/windows.md (Code review) Co-Authored-By: LightIsLife <[email protected]> * Fix typo migration.md (Code review) * Fixed typo migration.md (code review) * Update qnap.md

mhilbush changed the title ~~[sitemap] Items not found when displaying sitemap~~ Items not found when displaying sitemap Jun 19, 2019

mhilbush closed this as completed Jun 24, 2019

mhilbush reopened this Oct 10, 2019

mhilbush changed the title ~~Items not found when displaying sitemap~~ Items not found when displaying sitemap or executing rules Oct 10, 2019

5iver mentioned this issue Oct 21, 2019

cannot be resolved to an item or type #1154

Closed

This was referenced Nov 11, 2019

First start after update: [ERROR] [e.internal.items.GroupFunctionHelper] - Group function 'OR' requires two arguments. Using Equality instead. #974

Closed

Two restarts needed after clearing cache #1205

Closed

mhilbush mentioned this issue Jun 7, 2020

[dsl] Model loading improvements #1514

Merged

mhilbush closed this as completed Dec 11, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Items not found when displaying sitemap or executing rules #865

Items not found when displaying sitemap or executing rules #865

mhilbush commented Jun 10, 2019

pavel-gololobov commented Jun 14, 2019

mhilbush commented Jun 19, 2019 •

edited

Loading

5iver commented Jun 19, 2019

mhilbush commented Jun 19, 2019

kaikreuzer commented Jun 19, 2019

5iver commented Jun 19, 2019 •

edited

Loading

mhilbush commented Jun 20, 2019

5iver commented Jun 20, 2019

mhilbush commented Jun 24, 2019

mhilbush commented Oct 10, 2019

rkoshak commented Oct 10, 2019

macdroid53 commented Oct 10, 2019

mstormi commented Dec 9, 2019 •

edited

Loading

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019 •

edited

Loading

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019 •

edited

Loading

t2000 commented Jun 15, 2020 •

edited

Loading

weakfl commented Sep 23, 2020

mhilbush commented Dec 11, 2020

Items not found when displaying sitemap or executing rules #865

Items not found when displaying sitemap or executing rules #865

Comments

mhilbush commented Jun 10, 2019

pavel-gololobov commented Jun 14, 2019

mhilbush commented Jun 19, 2019 • edited Loading

5iver commented Jun 19, 2019

mhilbush commented Jun 19, 2019

kaikreuzer commented Jun 19, 2019

5iver commented Jun 19, 2019 • edited Loading

mhilbush commented Jun 20, 2019

5iver commented Jun 20, 2019

mhilbush commented Jun 24, 2019

mhilbush commented Oct 10, 2019

rkoshak commented Oct 10, 2019

macdroid53 commented Oct 10, 2019

mstormi commented Dec 9, 2019 • edited Loading

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019 • edited Loading

mhilbush commented Dec 9, 2019

mstormi commented Dec 9, 2019 • edited Loading

t2000 commented Jun 15, 2020 • edited Loading

weakfl commented Sep 23, 2020

mhilbush commented Dec 11, 2020

mhilbush commented Jun 19, 2019 •

edited

Loading

5iver commented Jun 19, 2019 •

edited

Loading

mstormi commented Dec 9, 2019 •

edited

Loading

mstormi commented Dec 9, 2019 •

edited

Loading

mstormi commented Dec 9, 2019 •

edited

Loading

t2000 commented Jun 15, 2020 •

edited

Loading