Items not found when displaying sitemap or executing rules

mhilbush commented 5 years ago

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

pavel-gololobov commented 5 years ago

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

mhilbush commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

mhilbush commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

t2000 commented 4 years ago

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 commented 3 years ago

@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 commented 3 years ago

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

openhab / openhab-core

Items not found when displaying sitemap or executing rules #865