Item model not loading correctly on RaspberryPi

[openhab-bot]

From yannick....@gmail.com on November 15, 2013 23:31:30

What steps will reproduce the problem? 1. Configured item model in Windows, works fine
2. copied whole OpenHAB runtime folder to RaspberryPi, started in debug mode, creates error "Couldn't find ItemFactory for item '{}' of type '{}'" for all items. What is the expected output? What do you see instead? - What version of the product are you using? On what operating system? - tried 2013-05-25-wheezy-raspbian with java 8 and 2013-09-25-wheezy-raspbian with java 7 and 8, OH1.3.1 Please provide any additional information below. - most interesting log entry is the difference in the logging between windows and raspi startup:

First the windows start:
23:11:40.743 INFO o.o.c.internal.CoreActivator[:92] - openHAB runtime has been started (v1.3.1).
23:11:40.760 DEBUG o.o.c.a.i.AutoUpdateActivator[:51] - AutoUpdate binding has been started.
23:11:41.231 DEBUG o.o.m.p.i.PersistenceModelActivator[:43] - Registered 'persistence' configuration parser
23:11:41.242 DEBUG o.o.c.t.i.TransformationActivator[:58] - Transformation Service has been started.
23:11:41.369 DEBUG o.o.i.g.internal.GCalActivator[:54] - Google Calendar IO has been started.
23:11:41.386 DEBUG o.o.i.m.i.MultimediaActivator[:54] - Multimedia I/O bundle has been started.
23:11:41.401 DEBUG o.o.i.s.i.DiscoveryServiceActivator[:47] - Discovery service has been started.
23:11:41.412 DEBUG o.o.i.t.mqtt.MqttService[:138] - Starting MQTT Service...
23:11:41.484 DEBUG o.o.m.i.i.ItemModelActivator[:44] - Registered 'item' configuration parser
23:11:41.549 DEBUG o.o.c.i.items.ItemRegistryImpl[:157] - Item provider 'GenericItemProvider' has been added.
23:11:41.962 DEBUG o.o.m.s.i.SitemapModelActivator[:43] - Registered 'sitemap' configuration parser
23:11:42.052 INFO o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 'homematic.items'
23:11:42.102 DEBUG o.o.m.i.i.GenericItemProvider[:154] - Read items from model 'homematic.items'
23:11:42.110 DEBUG o.o.i.r.internal.RESTActivator[:53] - REST API has been started.
23:11:42.192 INFO o.o.i.s.i.DiscoveryServiceImpl[:92] - mDNS service has been started

And here the Raspi start:

22:15:54.734 INFO o.o.c.internal.CoreActivator[:92] - openHAB runtime has been started (v1.3.1).
22:15:57.474 DEBUG o.o.c.a.i.AutoUpdateActivator[:51] - AutoUpdate binding has been started.
22:16:43.068 DEBUG o.o.m.p.i.PersistenceModelActivator[:43] - Registered 'persistence' configuration parser
22:16:43.668 DEBUG o.o.c.t.i.TransformationActivator[:58] - Transformation Service has been started.
22:16:46.389 DEBUG o.o.i.g.internal.GCalActivator[:54] - Google Calendar IO has been started.
22:16:47.960 DEBUG o.o.i.m.i.MultimediaActivator[:54] - Multimedia I/O bundle has been started.
22:16:51.405 DEBUG o.o.i.s.i.DiscoveryServiceActivator[:47] - Discovery service has been started.
22:16:53.491 DEBUG o.o.i.t.mqtt.MqttService[:138] - Starting MQTT Service...
22:17:02.385 INFO o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 'rrd4j.persist'
22:17:10.237 DEBUG o.o.m.i.i.ItemModelActivator[:44] - Registered 'item' configuration parser
22:17:14.642 INFO o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 'homematic.items'
22:17:22.564 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Anwesenheit' of type 'Number'
22:17:22.581 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Wohnmodus' of type 'Number'
22:17:22.601 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Eltern' of type 'Rollershutter'
22:17:22.619 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Bad' of type 'Rollershutter'
22:17:22.636 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Arbeit_Window' of type 'Rollershutter'
22:17:22.652 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Arbeit_Door' of type 'Rollershutter'
22:17:22.670 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Wandtaster_FL_PB4_1' of type 'Switch'
22:17:22.688 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing binding configuration of Item 'null' with 'AutoUpdateGenericBindingProvider' reader.
22:17:25.360 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Anwesenheit' of type 'Number'
22:17:25.377 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Wohnmodus' of type 'Number'
22:17:25.395 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Eltern' of type 'Rollershutter'
22:17:25.415 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Bad' of type 'Rollershutter'
22:17:25.432 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Arbeit_Window' of type 'Rollershutter'
22:17:25.449 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Shutter_OG_Arbeit_Door' of type 'Rollershutter'
22:17:25.466 DEBUG o.o.m.i.i.GenericItemProvider[:382] - Couldn't find ItemFactory for item 'Wandtaster_FL_PB4_1' of type 'Switch'
22:17:26.238 DEBUG o.o.m.i.i.GenericItemProvider[:154] - Read items from model 'homematic.items'
22:18:16.843 DEBUG o.o.m.s.i.SitemapModelActivator[:43] - Registered 'sitemap' configuration parser
22:18:20.938 DEBUG o.o.i.r.internal.RESTActivator[:53] - REST API has been started.
22:18:23.004 INFO o.o.i.s.i.DiscoveryServiceImpl[:92] - mDNS service has been started

The main difference (apart from the ages it take for the Raspi to start) is that the line

22:04:35.185 DEBUG o.o.c.i.items.ItemRegistryImpl[:157] - Item provider 'GenericItemProvider' has been added.

is coming before loading of the model in windows and it is missing (once it cames after loading the model) on the Raspi. That doesn't seem to make sense. I took a glance in the code but didn'd dig deep enough.

Original issue: http://code.google.com/p/openhab/issues/detail?id=517

[openhab-bot]

From kai.openhab on November 15, 2013 15:03:27

I assume this is a startlevel problem. I have just committed a fix to start the itemtype factory earlier than the rest: b8d5feb Please test it with tomorrows build and let me know if it solves the problem!

Status: Fixed
Labels: Version-1.4.0

[openhab-bot]

From yannick....@gmail.com on November 16, 2013 01:40:46

Thx for the quick reaction Kai, but that's still open. There are less errors now because I reduced the model to just one item.

I used #527 from today. "GenericItemProvider" is still loading after the model (although reading of the model now appears twice):

09:29:28.618 INFO o.q.impl.StdSchedulerFactory[:1328] - Quartz scheduler version: 2.1.7
09:29:28.641 INFO o.quartz.core.QuartzScheduler[:534] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
09:29:28.766 DEBUG o.o.c.core.ConfigDispatcher[:146] - Processing openHAB default configuration file '/home/pi/distribution-1.4.0-SNAPSHOT-runtime/configurations/openhab_default.cfg'.
09:29:30.820 DEBUG o.o.c.core.ConfigDispatcher[:168] - Processing openHAB main configuration file '/home/pi/distribution-1.4.0-SNAPSHOT-runtime/configurations/openhab.cfg'.
09:29:32.272 DEBUG o.o.c.internal.CoreActivator[:104] - UUID file already exists at '/home/pi/distribution-1.4.0-SNAPSHOT-runtime/webapps/static/uuid' with content '4eec0a46-23fc-4d00-9e41-6de4393ec35d'
09:29:37.113 DEBUG o.o.c.internal.CoreActivator[:170] - You are running 'v1.4.0' a potentially unstable version of openHAB. The current stable version is 'v1.3.1'.
09:29:37.147 DEBUG o.o.c.internal.CoreActivator[:126] - Created file '/home/pi/distribution-1.4.0-SNAPSHOT-runtime/webapps/static/version' with content '1.4.0'
09:29:37.164 INFO o.o.c.internal.CoreActivator[:72] - openHAB runtime has been started (v1.4.0).
09:29:38.661 DEBUG o.o.c.a.i.AutoUpdateActivator[:31] - AutoUpdate binding has been started.
09:30:24.112 DEBUG o.o.m.p.i.PersistenceModelActivator[:23] - Registered 'persistence' configuration parser
09:30:24.819 DEBUG o.o.c.t.i.TransformationActivator[:38] - Transformation Service has been started.
09:30:27.356 DEBUG o.o.i.g.internal.GCalActivator[:34] - Google Calendar IO has been started.
09:30:28.697 DEBUG o.o.i.m.i.MultimediaActivator[:34] - Multimedia I/O bundle has been started.
09:30:31.277 DEBUG o.o.i.s.i.DiscoveryServiceActivator[:27] - Discovery service has been started.
09:30:32.129 DEBUG o.o.i.t.mqtt.MqttService[:118] - Starting MQTT Service...
09:30:42.089 INFO o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'rrd4j.persist'
09:30:49.266 DEBUG o.o.m.i.i.ItemModelActivator[:24] - Registered 'item' configuration parser
09:30:53.184 INFO o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'homematic.items'
09:31:01.309 DEBUG o.o.m.i.i.GenericItemProvider[:408] - Couldn't find ItemFactory for item 'Wandtaster_FL_PB4_1' of type 'Switch'
09:31:01.328 DEBUG o.o.m.i.i.GenericItemProvider[:334] - Start processing binding configuration of Item 'null' with 'AutoUpdateGenericBindingProvider' reader.
09:31:05.201 DEBUG o.o.m.i.i.GenericItemProvider[:133] - Read items from model 'homematic.items'
09:31:05.328 DEBUG o.o.c.i.items.ItemRegistryImpl[:137] - Item provider 'GenericItemProvider' has been added.
09:31:05.352 DEBUG o.o.m.i.i.GenericItemProvider[:133] - Read items from model 'homematic.items'
09:31:54.816 DEBUG o.o.m.s.i.SitemapModelActivator[:23] - Registered 'sitemap' configuration parser
09:31:59.464 DEBUG o.o.i.r.internal.RESTActivator[:33] - REST API has been started.
09:32:01.600 INFO o.o.i.s.i.DiscoveryServiceImpl[:72] - mDNS service has been started
09:32:06.291 INFO o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'default.sitemap'
09:32:10.024 INFO o.a.cpr.AtmosphereFramework[:2154] - Atmosphere is using org.atmosphere.cpr.DefaultAnnotationProcessor for processing annotation
09:32:10.115 INFO o.a.c.DefaultAnnotationProcessor[:131] - AnnotationProcessor class org.atmosphere.cpr.DefaultAnnotationProcessor$BytecodeBasedAnnotationProcessor being used
09:32:13.468 INFO o.a.cpr.AtmosphereFramework[:1491] - Auto detecting atmosphere handlers /WEB-INF/classes/

[openhab-bot]

From kai.openhab on November 16, 2013 02:20:17

Hm, pity that it didn't solve it. :-(
Will have to do testing myself then on a RaspPi to really fix the issue. Hope I will find time for it soon.

Status: Accepted

[openhab-bot]

From kai.openhab on November 16, 2013 02:20:29

Owner: kai.openhab

[openhab-bot]

From teichsta on November 17, 2013 10:43:00

Labels: To-Github

[timove]

I just had the same issues with a similar setup. Once I deleted my .persist files I could start up openhab successfully. The windows and raspi startup-logs above seem to differ at that point as well, look for "Loading model 'rrd4j.persist'". HTH

[timove]

Unfortunately, I was lucky. (Even) without the *.persist files openhab seems to be non-deterministic about the start-up order...

[marcelrv]

Same here. my temp workaround is to do a touch of all the files in the item directory after OH has fully started. Seems that triggers re-loading of all the items.

[marcelrv]

Hi anyone knows why this is closed now. AFAIK there was no code change to fix this?

[DocZoid]

A friend of mine pointed out that this problem only occurs in debug mode. Disable debug mode, and the behaviour is different.

[kusemuckl]

I am the friend mentioned by DocZoid. I could reproduce his problem with my configuration by running in debug mode.
However although my system was running fine for a few days I now encounter similar problems also when not running in debug mode after I moved my configuration to a different folder and created a symlink in the openhab folder.
I am still trying to figure out, whether it is the same problem as in this thread or not.

[kusemuckl]

Just wanted to let you know, that the problem seems to be gone for me, after I switched to snapshot build #566

[kickus]

I'm using a snapshot build from yesterday, and I'm not sure if it's the same problem but I've had a startup issue today which required me to touch some of my item files to get the loaded. Otherwise they were ignored on startup. I was not using debug mode.

[kaikreuzer]

I think this was solved with 1.4 - if anybody still sees it, please provide logs and reopen this issue!

[kickus]

I think I'll have to reopen it.
I'm running 1.4.0 and I do typically need to touch my files to get them all loaded correctly. I has got better since the 1.3 versions, but it is not yet in order. Maybe I have needlessly many configuration files or too heavy configuration? I guess a more light weight setup would start fine regularly.

I'll reopen next time when it occurs.

[kickus]

Apologies for my multiple posts, I'm not used with github issue tracker.