search

eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
865 stars 782 forks source link

Issues with corrupted items after reboot #5728

Open ncpe20012003 opened 6 years ago

ncpe20012003 commented 6 years ago

My issues is very similar to: https://github.com/eclipse/smarthome/issues/1550 Before going to OH 2.3, I could change the start level of the Eclipse SH Core Things bundle in Karaf to a higher level for a work around. Since going to stable OH 2.3, this work around doesn't seem to work anymore. In my case, all InBox things are auto approved and item creation is in Simplemode (Auto) or I think also called virtual items. When I reboot, the item category for my dimmable bulbs is missing until I go to, in paperUI, system/JSONDB Storage and change the write delay from 500 to 501 which initiates the back end without restart OH. Do I need to make other bundle start level adjustments in Karaf in order to resolve this?

htreu commented 6 years ago

Hi @ncpe20012003 thanks for the bug report. Please make sure to meat the following criteria:

Please also observe the logfile and search for entries of the ManagedItemProvider complaining about not being able to add its items to the ItemRegistry. Report back if you have those with the corresponding log entries.

ncpe20012003 commented 6 years ago

Thanks for the response. I looked through the log and events file and found nothing for ManagedItemProvider. I believe I need to set my logging levels correctly in Karaf, here is how logging levels are currently set:

openhab> log:get Logger │ Level ───────────────────────────────────────────────────┼────── ROOT │ WARN javax.jmdns │ ERROR org.apache.karaf.jaas.modules.audit │ INFO org.apache.karaf.kar.internal.KarServiceImpl │ ERROR org.apache.karaf.shell.support │ OFF org.apache.sshd │ ERROR org.eclipse.smarthome │ INFO org.jupnp │ ERROR org.openhab │ INFO org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR org.ops4j.pax.web.pax-web-runtime │ OFF smarthome.event │ INFO smarthome.event.InboxUpdatedEvent │ ERROR smarthome.event.ItemAddedEvent │ ERROR smarthome.event.ItemRemovedEvent │ ERROR smarthome.event.ItemStateEvent │ ERROR smarthome.event.ThingAddedEvent │ ERROR smarthome.event.ThingRemovedEvent │ ERROR smarthome.event.ThingStatusInfoEvent │ ERROR

What adjustments should I make to get the logging needed to troubleshoot this?

On Wed, Jun 13, 2018 at 2:53 AM, Henning Treu notifications@github.com wrote:

Hi @ncpe20012003 https://github.com/ncpe20012003 thanks for the bug report. Please make sure to meat the following criteria:

  • only one storage service is configured for your system
  • all bundle start levels are back to defaults

Please also observe the logfile and search for entries of the ManagedItemProvider complaining about not being able to add its items to the ItemRegistry. Report back if you have those with the corresponding log entries.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/eclipse/smarthome/issues/5728#issuecomment-396833492, or mute the thread https://github.com/notifications/unsubscribe-auth/Ag6q4Rvsb0VtHj2Rv8kflOV3Y68DXDR6ks5t8Lb-gaJpZM4Ulcvk .

ncpe20012003 commented 6 years ago

Still need some guidance on setting up my logging correctly. I'm still not seeing anything about ManagedItemProvider in my logs.

ncpe20012003 commented 6 years ago

May have found something...full log is attached. No handler found found for all my Zwave devices. openhab.log

2018-06-18 15:20:25.128 [DEBUG] [ome.core.thing.internal.ThingManager] - Thing 'zwave:device:163f5dd1448:node10' is tracked by ThingManager. 2018-06-18 15:20:25.131 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point since no handler factory for thing 'zwave:device:163f5dd1448:node10' found. 2018-06-18 15:20:25.133 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point. No handler factory for thing 'zwave:device:163f5dd1448:node10' found. 2018-06-18 15:20:25.146 [DEBUG] [ome.core.thing.internal.ThingManager] - Thing 'zwave:device:163f5dd1448:node11' is tracked by ThingManager. 2018-06-18 15:20:25.148 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point since no handler factory for thing 'zwave:device:163f5dd1448:node11' found. 2018-06-18 15:20:25.150 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point. No handler factory for thing 'zwave:device:163f5dd1448:node11' found. 2018-06-18 15:20:25.161 [DEBUG] [ome.core.thing.internal.ThingManager] - Thing 'zwave:device:163f5dd1448:node2' is tracked by ThingManager. 2018-06-18 15:20:25.163 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point since no handler factory for thing 'zwave:device:163f5dd1448:node2' found. 2018-06-18 15:20:25.165 [DEBUG] [ome.core.thing.internal.ThingManager] - Not registering a handler at this point. No handler factory for thing 'zwave:device:163f5dd1448:node2' found.

sjsf commented 6 years ago

That's perfectly fine and expected. Please note that debug messages usually don't indicate an error but merely state a fact. The ThingHandlers will be instantiated later on, once all XMLs are loaded completely and the corresponding ThingHandlerFactory is registered. You can see that in the log as well:

2018-06-18 15:20:39.185 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:serial_zstick:163f5dd1448' at 'org.openhab.binding.zwave.handler.ZWaveSerialHandler@54606a65'.
2018-06-18 15:20:39.529 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node20' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@5ccdf796'.
2018-06-18 15:20:39.550 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node18' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@113ca9d0'.
2018-06-18 15:20:39.631 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node14' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@6ddb09ae'.
2018-06-18 15:20:39.697 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node16' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@5001a3eb'.
2018-06-18 15:20:39.728 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node10' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@7472115f'.
2018-06-18 15:20:39.738 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node2' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@de21e83'.
2018-06-18 15:20:39.771 [DEBUG] [ome.core.thing.internal.ThingManager] - Calling initialize handler for thing 'zwave:device:163f5dd1448:node11' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@43f4ff82'.

Nevertheless, I cannot see anything suspicious in your log file (apart from some warnings and errors which I guess origin from you running it on a dev instance or the like - in any case unrelated).

htreu commented 6 years ago

I added some advanced logging to the ChannelItemProvider which is responsible for creating "virtual" items (see https://github.com/eclipse/smarthome/pull/5758). @ncpe20012003 please update your instance once a new stable is build with these changes and report back with a new log file. Right now I'm out of ideas for your problem.

htreu commented 6 years ago

@ncpe20012003 the latest openHAB-2.4.0 stable includes the changes mentioned above. Please set the logging of org.eclipse.smarthome.core.thing.internal.ChannelItemProvider to TRACE to activate the logging.