Not all child things on bridge initialized after bridge initialization.

[mherwege]

I have this issue with my own developed binding: nikohomecontrol. I am in doubt where to post, here or in the addons2 repository. This could be an issue in my binding, but I do think it might actually be in the framework code. Please have a look at it and if the problem is in the nikohomecontrol code, could you please give an indication what the issue could be? I will close it here in that case.

I noticed a few times when starting openHABon my RPi, not all my nikohomecontrol child things got initialized. This only appeared in the 2.1 release version. All child things are defined the same way and which ones got initialized was variable. I expect this points to a multi-threading timing issue. I was now able to reproduce it in the Eclipse development environment on my PC.

The full startup log when running in Eclipse with just the nikohomecontrol binding is this:

2017-07-17 16:45:03.183 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.core.thing.ManagedThingProvider' has been added.
2017-07-17 16:45:03.190 [DEBUG] [o.e.s.storage.json.JsonStorage:113  ] - Opened Json storage file at 'C:\Users\MHERWEGE\openhab2-master\git\openhab-distro\launch\home\userdata\jsondb\org.eclipse.smarthome.config.discovery.DiscoveryResult.json'.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.192
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.config.discovery.inbox.Inbox. The reference is: Reference[name = EventPublisher, interface = org.eclipse.smarthome.core.events.EventPublisher, policy = dynamic, cardinality = 0..1, target = null, bind = setEventPublisher, unbind = unsetEventPublisher]
2017-07-17 16:45:03.250 [DEBUG] [s.c.d.internal.PersistentInbox:198  ] - Discovery result with thing 'nikohomecontrol:bridge:440e003a24e6' not added as inbox entry. It is already present as thing in the ThingRegistry.
2017-07-17 16:45:03.324 [DEBUG] [.s.core.internal.CoreActivator:30   ] - Core bundle has been started.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.368
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.binding.BindingInfoRegistry. The reference is: Reference[name = BindingInfoProvider, interface = org.eclipse.smarthome.core.binding.BindingInfoProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addBindingInfoProvider, unbind = removeBindingInfoProvider]
2017-07-17 16:45:03.374 [DEBUG] [core.internal.I18nProviderImpl:94   ] - No language set, fallback to default system locale
2017-07-17 16:45:03.688 [DEBUG] [c.x.o.XmlDocumentBundleTracker:126  ] - Reading the XML document '/ESH-INF/binding/binding.xml' in module 'org.openhab.binding.nikohomecontrol'...
2017-07-17 16:45:03.707 [DEBUG] [c.x.o.XmlDocumentBundleTracker:177  ] - Create an empty XmlDocumentProvider for the module 'org.openhab.binding.nikohomecontrol'.
2017-07-17 16:45:03.731 [DEBUG] [c.x.o.XmlDocumentBundleTracker:126  ] - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.eclipse.smarthome.core.persistence'...
2017-07-17 16:45:03.737 [DEBUG] [c.x.o.XmlDocumentBundleTracker:177  ] - Create an empty XmlDocumentProvider for the module 'org.eclipse.smarthome.core.persistence'.
2017-07-17 16:45:03.748 [DEBUG] [c.x.o.XmlDocumentBundleTracker:126  ] - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.eclipse.smarthome.core.audio'...
2017-07-17 16:45:03.751 [DEBUG] [c.x.o.XmlDocumentBundleTracker:177  ] - Create an empty XmlDocumentProvider for the module 'org.eclipse.smarthome.core.audio'.
2017-07-17 16:45:03.752 [DEBUG] [c.x.o.XmlDocumentBundleTracker:126  ] - Reading the XML document '/ESH-INF/config/config.xml' in module 'org.eclipse.smarthome.ui.classic'...
2017-07-17 16:45:03.755 [DEBUG] [c.x.o.XmlDocumentBundleTracker:177  ] - Create an empty XmlDocumentProvider for the module 'org.eclipse.smarthome.ui.classic'.
2017-07-17 16:45:03.766 [DEBUG] [.core.common.ThreadPoolManager:144  ] - Created thread pool 'ConfigStatusService' with size 5

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.769
!MESSAGE Could not bind a reference of component ConfigStatusService. The reference is: Reference[name = ConfigStatusProvider, interface = org.eclipse.smarthome.config.core.status.ConfigStatusProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addConfigStatusProvider, unbind = removeConfigStatusProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.774
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.thing.firmware.FirmwareRegistry. The reference is: Reference[name = FirmwareProvider, interface = org.eclipse.smarthome.core.thing.firmware.FirmwareProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addFirmwareProvider, unbind = removeFirmwareProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.784
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.thing.firmware.FirmwareUpdateService. The reference is: Reference[name = FirmwareUpdateHandler, interface = org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler, policy = dynamic, cardinality = 0..n, target = null, bind = addFirmwareUpdateHandler, unbind = removeFirmwareUpdateHandler]
2017-07-17 16:45:03.785 [DEBUG] [.s.c.t.f.FirmwareUpdateService:120  ] - Modifying the configuration of the firmware update service.
2017-07-17 16:45:03.785 [DEBUG] [.s.c.t.f.FirmwareUpdateService:444  ] - Given time unit null is not supported. Will keep current configuration.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.790
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.thing.internal.console.FirmwareUpdateConsoleCommandExtension. The reference is: Reference[name = FirmwareUpdateHandler, interface = org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler, policy = dynamic, cardinality = 0..n, target = null, bind = addFirmwareUpdateHandler, unbind = removeFirmwareUpdateHandler]
2017-07-17 16:45:03.815 [DEBUG] [c.x.o.XmlDocumentBundleTracker:126  ] - Reading the XML document '/ESH-INF/thing/thing-types.xml' in module 'org.openhab.binding.nikohomecontrol'...
2017-07-17 16:45:03.829 [DEBUG] [c.x.o.XmlDocumentBundleTracker:177  ] - Create an empty XmlDocumentProvider for the module 'org.openhab.binding.nikohomecontrol'.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.849
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.voice. The reference is: Reference[name = KSService, interface = org.eclipse.smarthome.core.voice.KSService, policy = dynamic, cardinality = 0..n, target = null, bind = addKSService, unbind = removeKSService]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.851
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.voice. The reference is: Reference[name = STTService, interface = org.eclipse.smarthome.core.voice.STTService, policy = dynamic, cardinality = 0..n, target = null, bind = addSTTService, unbind = removeSTTService]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.854
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.voice. The reference is: Reference[name = TTSService, interface = org.eclipse.smarthome.core.voice.TTSService, policy = dynamic, cardinality = 0..n, target = null, bind = addTTSService, unbind = removeTTSService]
2017-07-17 16:45:03.865 [DEBUG] [e.s.a.core.internal.RuleEngine:257  ] - ModuleHandlerFactory added.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.875
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.itemregistry. The reference is: Reference[name = ManagedItemProvider, interface = org.eclipse.smarthome.core.items.ManagedItemProvider, policy = dynamic, cardinality = 0..1, target = null, bind = setManagedProvider, unbind = removeManagedProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.879
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.core.itemregistry. The reference is: Reference[name = StateDescriptionProvider, interface = org.eclipse.smarthome.core.types.StateDescriptionProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addStateDescriptionProvider, unbind = removeStateDescriptionProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.916
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.ui. The reference is: Reference[name = ItemUIProvider, interface = org.eclipse.smarthome.ui.items.ItemUIProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addItemUIProvider, unbind = removeItemUIProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:03.922
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.ui.chart. The reference is: Reference[name = ChartProvider, interface = org.eclipse.smarthome.ui.chart.ChartProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addChartProvider, unbind = removeChartProvider]
2017-07-17 16:45:03.923 [DEBUG] [ui.internal.chart.ChartServlet:121  ] - Starting up chart servlet at /chart

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.094
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.ui.chart.defaultprovider. The reference is: Reference[name = PersistenceService, interface = org.eclipse.smarthome.core.persistence.PersistenceService, policy = dynamic, cardinality = 0..n, target = null, bind = addPersistenceService, unbind = removePersistenceService]
2017-07-17 16:45:04.095 [DEBUG] [u.i.chart.DefaultChartProvider:101  ] - Starting up default chart provider.

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.107
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.ui.classic.pagerenderer. The reference is: Reference[name = WidgetRenderer, interface = org.eclipse.smarthome.ui.classic.render.WidgetRenderer, policy = dynamic, cardinality = 0..n, target = null, bind = addWidgetRenderer, unbind = removeWidgetRenderer]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.177
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.io.rest.sitemapsubscription. The reference is: Reference[name = SitemapProvider, interface = org.eclipse.smarthome.model.sitemap.SitemapProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addSitemapProvider, unbind = removeSitemapProvider]

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.179
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.io.rest.sitemapsubscription. The reference is: Reference[name = ModelRepository, interface = org.eclipse.smarthome.model.core.ModelRepository, policy = dynamic, cardinality = 0..1, target = null, bind = addModelRepository, unbind = removeModelRepository]
2017-07-17 16:45:04.198 [DEBUG] [o.e.s.u.c.i.servlet.CmdServlet:56   ] - Starting up CMD servlet at /classicui/CMD
2017-07-17 16:45:04.204 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.model.thing.internal.GenericItemChannelLinkProvider' has been added.
2017-07-17 16:45:04.213 [DEBUG] [.core.common.ThreadPoolManager:144  ] - Created thread pool 'safeCall' with size 5
2017-07-17 16:45:04.216 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider' has been added.
2017-07-17 16:45:04.234 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.core.thing.internal.ChannelItemProvider' has been added.
2017-07-17 16:45:04.249 [DEBUG] [.core.common.ThreadPoolManager:114  ] - Created scheduled thread pool 'thingManager' of size 5
2017-07-17 16:45:04.261 [DEBUG] [.c.thing.internal.ThingManager:999  ] - Thing handler factory 'NikoHomeControlHandlerFactory' added
2017-07-17 16:45:04.262 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:22' is tracked by ThingManager.
2017-07-17 16:45:04.266 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:21' is tracked by ThingManager.
2017-07-17 16:45:04.267 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:dimmer:440e003a24e6:29' is tracked by ThingManager.
2017-07-17 16:45:04.269 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:17' is tracked by ThingManager.
2017-07-17 16:45:04.271 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:16' is tracked by ThingManager.
2017-07-17 16:45:04.273 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:19' is tracked by ThingManager.
2017-07-17 16:45:04.274 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:18' is tracked by ThingManager.
2017-07-17 16:45:04.276 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:13' is tracked by ThingManager.
2017-07-17 16:45:04.278 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:12' is tracked by ThingManager.
2017-07-17 16:45:04.279 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:15' is tracked by ThingManager.
2017-07-17 16:45:04.281 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:11' is tracked by ThingManager.
2017-07-17 16:45:04.282 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:10' is tracked by ThingManager.
2017-07-17 16:45:04.284 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:7' is tracked by ThingManager.
2017-07-17 16:45:04.286 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:9' is tracked by ThingManager.
2017-07-17 16:45:04.287 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:dimmer:440e003a24e6:36' is tracked by ThingManager.
2017-07-17 16:45:04.289 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:dimmer:440e003a24e6:35' is tracked by ThingManager.
2017-07-17 16:45:04.290 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:dimmer:440e003a24e6:30' is tracked by ThingManager.
2017-07-17 16:45:04.292 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:4' is tracked by ThingManager.
2017-07-17 16:45:04.293 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:6' is tracked by ThingManager.
2017-07-17 16:45:04.294 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:5' is tracked by ThingManager.
2017-07-17 16:45:04.294 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_6_switch-nikohomecontrol:onOff:440e003a24e6:6:switch' has been added.
2017-07-17 16:45:04.296 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:42' is tracked by ThingManager.
2017-07-17 16:45:04.297 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:41' is tracked by ThingManager.
2017-07-17 16:45:04.298 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:44' is tracked by ThingManager.
2017-07-17 16:45:04.300 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:43' is tracked by ThingManager.
2017-07-17 16:45:04.301 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:bridge:440e003a24e6' is tracked by ThingManager.
2017-07-17 16:45:04.303 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.306 [DEBUG] [.core.common.ThreadPoolManager:114  ] - Created scheduled thread pool 'thingHandler' of size 5
2017-07-17 16:45:04.311 [DEBUG] [ikoHomeControlDiscoveryService:45   ] - Niko Home Control: discovery service org.openhab.binding.nikohomecontrol.handler.NikoHomeControlBridgeHandler@3826cfd9
2017-07-17 16:45:04.350 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_42_switch-nikohomecontrol:onOff:440e003a24e6:42:switch' has been added.
2017-07-17 16:45:04.350 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:bridge:440e003a24e6 needs [addr], has [refresh, addr, port].
2017-07-17 16:45:04.351 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:bridge:440e003a24e6' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlBridgeHandler@3826cfd9'.
2017-07-17 16:45:04.353 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_12_switch-nikohomecontrol:onOff:440e003a24e6:12:switch' has been added.
2017-07-17 16:45:04.356 [DEBUG] [h.NikoHomeControlBridgeHandler:60   ] - Niko Home Control: initializing bridge handler
2017-07-17 16:45:04.357 [DEBUG] [h.NikoHomeControlBridgeHandler:66   ] - Niko Home Control: bridge handler host /192.168.0.121, port 8000
2017-07-17 16:45:04.360 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:31' is tracked by ThingManager.
2017-07-17 16:45:04.362 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:33' is tracked by ThingManager.
2017-07-17 16:45:04.363 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:28' is tracked by ThingManager.
2017-07-17 16:45:04.365 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_24_switch-nikohomecontrol:onOff:440e003a24e6:24:switch' has been added.
2017-07-17 16:45:04.365 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:27' is tracked by ThingManager.
2017-07-17 16:45:04.366 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_21_switch-nikohomecontrol:onOff:440e003a24e6:21:switch' has been added.
2017-07-17 16:45:04.366 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_33_switch-nikohomecontrol:onOff:440e003a24e6:33:switch' has been added.
2017-07-17 16:45:04.366 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:24' is tracked by ThingManager.
2017-07-17 16:45:04.368 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:23' is tracked by ThingManager.
2017-07-17 16:45:04.369 [DEBUG] [.c.thing.internal.ThingManager:461  ] - Thing 'nikohomecontrol:onOff:440e003a24e6:25' is tracked by ThingManager.
2017-07-17 16:45:04.373 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_dimmer_440e003a24e6_29_brightness-nikohomecontrol:dimmer:440e003a24e6:29:brightness' has been added.
2017-07-17 16:45:04.373 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_18_switch-nikohomecontrol:onOff:440e003a24e6:18:switch' has been added.
2017-07-17 16:45:04.373 [DEBUG] [o.e.s.u.b.i.servlet.CmdServlet:56   ] - Starting up CMD servlet at /basicui/CMD
2017-07-17 16:45:04.374 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_15_switch-nikohomecontrol:onOff:440e003a24e6:15:switch' has been added.
2017-07-17 16:45:04.374 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_25_switch-nikohomecontrol:onOff:440e003a24e6:25:switch' has been added.
2017-07-17 16:45:04.375 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_43_switch-nikohomecontrol:onOff:440e003a24e6:43:switch' has been added.
2017-07-17 16:45:04.375 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_5_switch-nikohomecontrol:onOff:440e003a24e6:5:switch' has been added.
2017-07-17 16:45:04.376 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_19_switch-nikohomecontrol:onOff:440e003a24e6:19:switch' has been added.
2017-07-17 16:45:04.377 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_28_switch-nikohomecontrol:onOff:440e003a24e6:28:switch' has been added.
2017-07-17 16:45:04.379 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_31_switch-nikohomecontrol:onOff:440e003a24e6:31:switch' has been added.
2017-07-17 16:45:04.382 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_13_switch-nikohomecontrol:onOff:440e003a24e6:13:switch' has been added.
2017-07-17 16:45:04.383 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_10_switch-nikohomecontrol:onOff:440e003a24e6:10:switch' has been added.
2017-07-17 16:45:04.384 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_22_switch-nikohomecontrol:onOff:440e003a24e6:22:switch' has been added.
2017-07-17 16:45:04.384 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_16_switch-nikohomecontrol:onOff:440e003a24e6:16:switch' has been added.
2017-07-17 16:45:04.385 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_9_switch-nikohomecontrol:onOff:440e003a24e6:9:switch' has been added.
2017-07-17 16:45:04.385 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_17_switch-nikohomecontrol:onOff:440e003a24e6:17:switch' has been added.
2017-07-17 16:45:04.386 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_bridge_440e003a24e6_alarm-nikohomecontrol:bridge:440e003a24e6:alarm' has been added.
2017-07-17 16:45:04.386 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_dimmer_440e003a24e6_36_brightness-nikohomecontrol:dimmer:440e003a24e6:36:brightness' has been added.
2017-07-17 16:45:04.386 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_23_switch-nikohomecontrol:onOff:440e003a24e6:23:switch' has been added.
2017-07-17 16:45:04.387 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_41_switch-nikohomecontrol:onOff:440e003a24e6:41:switch' has been added.
2017-07-17 16:45:04.387 [DEBUG] [o.e.s.storage.json.JsonStorage:94   ] - Json storage file at 'C:\Users\MHERWEGE\openhab2-master\git\openhab-distro\launch\home\userdata\jsondb\org.eclipse.smarthome.core.items.Item.json' does not exist - checking for a backup.
2017-07-17 16:45:04.388 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_44_switch-nikohomecontrol:onOff:440e003a24e6:44:switch' has been added.
2017-07-17 16:45:04.388 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_dimmer_440e003a24e6_35_brightness-nikohomecontrol:dimmer:440e003a24e6:35:brightness' has been added.
2017-07-17 16:45:04.389 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_bridge_440e003a24e6_notice-nikohomecontrol:bridge:440e003a24e6:notice' has been added.
2017-07-17 16:45:04.390 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.core.items.ManagedItemProvider' has been added.
2017-07-17 16:45:04.390 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_dimmer_440e003a24e6_30_brightness-nikohomecontrol:dimmer:440e003a24e6:30:brightness' has been added.
2017-07-17 16:45:04.391 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_11_switch-nikohomecontrol:onOff:440e003a24e6:11:switch' has been added.
2017-07-17 16:45:04.391 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_27_switch-nikohomecontrol:onOff:440e003a24e6:27:switch' has been added.
2017-07-17 16:45:04.392 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_4_switch-nikohomecontrol:onOff:440e003a24e6:4:switch' has been added.
2017-07-17 16:45:04.393 [INFO ] [vent.ItemChannelLinkAddedEvent:43   ] - Link 'nikohomecontrol_onOff_440e003a24e6_7_switch-nikohomecontrol:onOff:440e003a24e6:7:switch' has been added.
2017-07-17 16:45:04.394 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:22' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.394 [DEBUG] [.core.common.ThreadPoolManager:79   ] - Updated scheduled thread pool 'discovery' to size 3
2017-07-17 16:45:04.395 [DEBUG] [.core.common.ThreadPoolManager:79   ] - Updated scheduled thread pool 'thingHandler' to size 3
2017-07-17 16:45:04.395 [WARN ] [.core.common.ThreadPoolManager:87   ] - Ignoring invalid configuration for pool 'safeCall': 3,10 - value must be an integer
2017-07-17 16:45:04.395 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:22' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.396 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:21' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.396 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:21' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.397 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:29' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.397 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:29' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.398 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.399 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.400 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.400 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.401 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.401 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.402 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.402 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.403 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.404 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.404 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.405 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.407 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.407 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.408 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.409 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.410 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.411 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.412 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.415 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.415 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.416 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.416 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.417 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.417 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.418 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.419 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:30' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.420 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:30' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.421 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.421 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.422 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.422 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.423 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:5' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.423 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:5' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.448 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:42' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.450 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:42' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.465 [DEBUG] [p.NikoHomeControlCommunication:105  ] - Niko Home Control: connected via local port 51118 from thread 125
2017-07-17 16:45:04.465 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:41' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.469 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"systeminfo"} from thread 125
2017-07-17 16:45:04.469 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:41' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.472 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"systeminfo","data":{"swversion":"1.10.0.34209","api":"1.19","time":"20170717165403","language":"NL","currency":"EUR","units":0,"DST":3600,"TZ":3600,"lastenergyerase":"","lastconfig":"20170429201629"}} on thread 125
2017-07-17 16:45:04.473 [DEBUG] [p.NikoHomeControlCommunication:264  ] - Niko Home Control: systeminfo
2017-07-17 16:45:04.473 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"startevents"} from thread 125
2017-07-17 16:45:04.475 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"startevents", "data":{"error":0}} on thread 125
2017-07-17 16:45:04.476 [DEBUG] [p.NikoHomeControlCommunication:302  ] - Niko Home Control: start events success
2017-07-17 16:45:04.476 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"listlocations"} from thread 125
2017-07-17 16:45:04.479 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"listlocations","data":[ {"id":0,"name":""},{"id":1,"name":"Beneden"},{"id":2,"name":"Boven"},{"id":3,"name":"Kelder"},{"id":4,"name":"Huis"},{"id":5,"name":"Buiten"}]} on thread 125
2017-07-17 16:45:04.480 [DEBUG] [p.NikoHomeControlCommunication:309  ] - Niko Home Control: list locations
2017-07-17 16:45:04.485 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"listactions"} from thread 125
2017-07-17 16:45:04.507 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:44' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.508 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:44' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.508 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:43' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.509 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:43' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.510 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:440e003a24e6' updated: INITIALIZING
2017-07-17 16:45:04.510 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:440e003a24e6' changed from UNINITIALIZED to INITIALIZING
2017-07-17 16:45:04.510 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:31' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.511 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:31' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.511 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:33' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.512 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:33' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.513 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:28' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.514 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:28' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.516 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:27' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.517 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:27' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.518 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:24' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.519 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:24' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.520 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:23' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.520 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:23' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.521 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:25' updated: UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.522 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:25' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2017-07-17 16:45:04.547 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"listactions","data":[ {"id":4,"name":"Garage","type":1,"location":1,"value1":0},{"id":5,"name":"Voordeur","type":1,"location":5,"value1":0},{"id":6,"name":"Trap","type":1,"location":2,"value1":0},{"id":7,"name":"Inkom","type":1,"location":1,"value1":0},{"id":9,"name":"Bureau","type":1,"location":1,"value1":0},{"id":10,"name":"Achtergevel","type":1,"location":5,"value1":0},{"id":11,"name":"Zijterras huis","type":1,"location":5,"value1":0},{"id":12,"name":"Keuken werkblad","type":1,"location":1,"value1":0},{"id":13,"name":"Keuken","type":1,"location":1,"value1":0},{"id":15,"name":"Kelderhal","type":1,"location":3,"value1":0},{"id":16,"name":"Slaapkamer Sander","type":1,"location":2,"value1":0},{"id":17,"name":"Nachthal","type":1,"location":2,"value1":0},{"id":18,"name":"Badkamer lavabos","type":1,"location":2,"value1":0},{"id":19,"name":"Badkamer","type":1,"location":2,"value1":0},{"id":21,"name":"Alles uit","type":1,"location":4,"value1":0},{"id":22,"name":"Boven alles uit","type":1,"location":2,"value1":0},{"id":23,"name":"Buiten alles uit","type":1,"location":5,"value1":0},{"id":24,"name":"Paniek","type":1,"location":4,"value1":100},{"id":25,"name":"Zolder","type":1,"location":2,"value1":0},{"id":27,"name":"Zithoek staanlampen","type":1,"location":1,"value1":0},{"id":28,"name":"Tuinhuis buiten","type":1,"location":5,"value1":0},{"id":29,"name":"Eetkamer","type":2,"location":1,"value1":0},{"id":30,"name":"Ontbijthoek","type":2,"location":1,"value1":0},{"id":31,"name":"Aanwezigheidssimulatie","type":1,"location":4,"value1":0},{"id":33,"name":"Inkom woonkamer","type":1,"location":1,"value1":0},{"id":35,"name":"Zithoek","type":2,"location":1,"value1":0},{"id":36,"name":"Slaapkamer ouders","type":2,"location":2,"value1":0},{"id":41,"name":"Berging","type":1,"location":1,"value1":0},{"id":42,"name":"Buitenkeuken spots","type":1,"location":5,"value1":0},{"id":43,"name":"Buitenkeuken luchters","type":1,"location":5,"value1":0},{"id":44,"name":"Duister","type":1,"location":0,"value1":0}]} on thread 125
2017-07-17 16:45:04.548 [DEBUG] [p.NikoHomeControlCommunication:322  ] - Niko Home Control: list actions
2017-07-17 16:45:04.552 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"listthermostat"} from thread 125
2017-07-17 16:45:04.555 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"listthermostat","data":[]} on thread 125
2017-07-17 16:45:04.555 [DEBUG] [p.NikoHomeControlCommunication:231  ] - Niko Home Control: not acted on json {"cmd":"listthermostat","data":[]}
2017-07-17 16:45:04.556 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"listthermostatHVAC"} from thread 125
2017-07-17 16:45:04.558 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"listthermostatHVAC","data":[]} on thread 125
2017-07-17 16:45:04.559 [DEBUG] [p.NikoHomeControlCommunication:231  ] - Niko Home Control: not acted on json {"cmd":"listthermostatHVAC","data":[]}
2017-07-17 16:45:04.559 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"readtariffdata"} from thread 125
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
2017-07-17 16:45:04.562 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"readtariffdata","data":[]} on thread 125
2017-07-17 16:45:04.563 [DEBUG] [p.NikoHomeControlCommunication:231  ] - Niko Home Control: not acted on json {"cmd":"readtariffdata","data":[]}
2017-07-17 16:45:04.563 [DEBUG] [p.NikoHomeControlCommunication:397  ] - Niko Home Control: send json {"cmd":"getalarms"} from thread 125
2017-07-17 16:45:04.566 [DEBUG] [p.NikoHomeControlCommunication:208  ] - Niko Home Control: received json {"cmd":"getalarms","data":[ {"id":3,"type":0,"date":"20170710130402","text":"Er is paniek thuis ! Iemand steekt alle lichten aan.","confirmed":1},{"id":4,"type":0,"date":"20170625202618","text":"Het alarm gaat af ! Alle lichten gaan aan.","confirmed":1},{"id":3,"type":0,"date":"20170619224848","text":"Er is paniek thuis ! Iemand steekt alle lichten aan.","confirmed":1}]} on thread 125
2017-07-17 16:45:04.567 [DEBUG] [p.NikoHomeControlCommunication:231  ] - Niko Home Control: not acted on json {"cmd":"getalarms","data":[ {"id":3,"type":0,"date":"20170710130402","text":"Er is paniek thuis ! Iemand steekt alle lichten aan.","confirmed":1},{"id":4,"type":0,"date":"20170625202618","text":"Het alarm gaat af ! Alle lichten gaan aan.","confirmed":1},{"id":3,"type":0,"date":"20170619224848","text":"Er is paniek thuis ! Iemand steekt alle lichten aan.","confirmed":1}]}
2017-07-17 16:45:04.575 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:22' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.576 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:21' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.577 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:dimmer:440e003a24e6:29' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.578 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:17' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.578 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:16' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.579 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:19' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.579 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:18' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.579 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:13' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.579 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:12' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.580 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:15' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.580 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:11' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.580 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:10' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.580 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:7' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.580 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:9' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.581 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:dimmer:440e003a24e6:36' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.581 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:dimmer:440e003a24e6:35' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.581 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:dimmer:440e003a24e6:30' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.581 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:4' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.581 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:6' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:5' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:42' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:41' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:44' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:43' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.582 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:31' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.583 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:33' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.583 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:28' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.583 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:27' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.583 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:24' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.584 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:23' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.584 [DEBUG] [.c.thing.internal.ThingManager:623  ] - Register and initialize child 'nikohomecontrol:onOff:440e003a24e6:25' of bridge 'nikohomecontrol:bridge:440e003a24e6'.
2017-07-17 16:45:04.584 [DEBUG] [h.NikoHomeControlBridgeHandler:141  ] - Niko Home Control: restart bridge connection every 300 min
2017-07-17 16:45:04.587 [DEBUG] [ikoHomeControlDiscoveryService:71   ] - Niko Home Control: getting devices on 440e003a24e6
2017-07-17 16:45:04.596 [DEBUG] [s.c.d.internal.PersistentInbox:198  ] - Discovery result with thing 'nikohomecontrol:onOff:440e003a24e6:4' not added as inbox entry. It is already present as thing in the ThingRegistry.
2017-07-17 16:45:04.601 [DEBUG] [s.c.d.internal.PersistentInbox:205  ] - The configuration for thing 'nikohomecontrol:onOff:440e003a24e6:4' is updated...
2017-07-17 16:45:04.605 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:4'.
2017-07-17 16:45:04.619 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:4 needs [actionId], has [actionId].
2017-07-17 16:45:04.620 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:4' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@525649a0'.
2017-07-17 16:45:04.606 [DEBUG] [p.NikoHomeControlCommunication:176  ] - Niko Home Control: listening for events on thread 127
2017-07-17 16:45:04.652 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:440e003a24e6' updated: ONLINE
2017-07-17 16:45:04.653 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:440e003a24e6' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.654 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' updated: INITIALIZING
2017-07-17 16:45:04.655 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.655 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' updated: ONLINE
2017-07-17 16:45:04.656 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.676 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 4
2017-07-17 16:45:04.697 [DEBUG] [.c.c.r.AbstractManagedProvider:134  ] - Updated element nikohomecontrol:onOff:440e003a24e6:4 in ManagedThingProvider.
2017-07-17 16:45:04.698 [DEBUG] [s.c.d.internal.PersistentInbox:198  ] - Discovery result with thing 'nikohomecontrol:onOff:440e003a24e6:5' not added as inbox entry. It is already present as thing in the ThingRegistry.
2017-07-17 16:45:04.699 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:16'.
2017-07-17 16:45:04.718 [DEBUG] [s.c.d.internal.PersistentInbox:205  ] - The configuration for thing 'nikohomecontrol:onOff:440e003a24e6:5' is updated...
2017-07-17 16:45:04.720 [INFO ] [rthome.event.ThingUpdatedEvent:43   ] - Thing 'nikohomecontrol:onOff:440e003a24e6:4' has been updated.
2017-07-17 16:45:04.723 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:16 needs [actionId], has [actionId].
2017-07-17 16:45:04.725 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:16' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@4b370088'.
2017-07-17 16:45:04.729 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 16

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.747
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.io.rest.core.binding.BindingResource. The reference is: Reference[name = ConfigurationService, interface = org.eclipse.smarthome.io.rest.core.config.ConfigurationService, policy = dynamic, cardinality = 0..1, target = null, bind = setConfigurationService, unbind = unsetConfigurationService]
2017-07-17 16:45:04.743 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' updated: INITIALIZING

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.760
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.io.rest.core.service.ConfigurableServiceResource. The reference is: Reference[name = ConfigurationService, interface = org.eclipse.smarthome.io.rest.core.config.ConfigurationService, policy = dynamic, cardinality = 0..1, target = null, bind = setConfigurationService, unbind = unsetConfigurationService]
2017-07-17 16:45:04.760 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:19'.
2017-07-17 16:45:04.762 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:19 needs [actionId], has [actionId].
2017-07-17 16:45:04.764 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:19' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@45f0f79e'.
2017-07-17 16:45:04.765 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.766 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 19
2017-07-17 16:45:04.767 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:18'.
2017-07-17 16:45:04.773 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:18 needs [actionId], has [actionId].

!ENTRY org.eclipse.equinox.ds 1 0 2017-07-17 16:45:04.773
!MESSAGE Could not bind a reference of component org.eclipse.smarthome.io.rest.core.binding.ExtensionResource. The reference is: Reference[name = ExtensionService, interface = org.eclipse.smarthome.core.extension.ExtensionService, policy = dynamic, cardinality = 0..n, target = null, bind = addExtensionService, unbind = removeExtensionService]
2017-07-17 16:45:04.774 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:18' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@41cf6bf8'.
2017-07-17 16:45:04.780 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 18
2017-07-17 16:45:04.783 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' updated: ONLINE
2017-07-17 16:45:04.785 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:13'.
2017-07-17 16:45:04.786 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.789 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:13 needs [actionId], has [actionId].
2017-07-17 16:45:04.790 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:13' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@4cdfda5'.
2017-07-17 16:45:04.792 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 13
2017-07-17 16:45:04.794 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:12'.
2017-07-17 16:45:04.796 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' updated: INITIALIZING
2017-07-17 16:45:04.796 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:12 needs [actionId], has [actionId].
2017-07-17 16:45:04.797 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:12' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@770d9ef4'.
2017-07-17 16:45:04.799 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 12
2017-07-17 16:45:04.801 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.802 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:15'.
2017-07-17 16:45:04.804 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:15 needs [actionId], has [actionId].
2017-07-17 16:45:04.804 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:15' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@3503db8c'.
2017-07-17 16:45:04.806 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 15
2017-07-17 16:45:04.807 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:11'.
2017-07-17 16:45:04.809 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:11 needs [actionId], has [actionId].
2017-07-17 16:45:04.810 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:11' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@f29e67f'.
2017-07-17 16:45:04.811 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' updated: ONLINE
2017-07-17 16:45:04.812 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 11
2017-07-17 16:45:04.819 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:10'.
2017-07-17 16:45:04.820 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:10 needs [actionId], has [actionId].
2017-07-17 16:45:04.820 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.821 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:10' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@64e202ea'.
2017-07-17 16:45:04.823 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 10
2017-07-17 16:45:04.825 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:7'.
2017-07-17 16:45:04.826 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:7 needs [actionId], has [actionId].
2017-07-17 16:45:04.827 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:7' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@7f03cabc'.
2017-07-17 16:45:04.827 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' updated: INITIALIZING
2017-07-17 16:45:04.829 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 7
2017-07-17 16:45:04.831 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.833 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:9'.
2017-07-17 16:45:04.835 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:9 needs [actionId], has [actionId].
2017-07-17 16:45:04.836 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:9' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@54f7a16b'.
2017-07-17 16:45:04.837 [DEBUG] [e.s.i.t.upnp.UpnpIOServiceImpl:186  ] - Starting UPnP IO service...
2017-07-17 16:45:04.837 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 9
2017-07-17 16:45:04.838 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' updated: ONLINE
2017-07-17 16:45:04.840 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:dimmer:440e003a24e6:36'.
2017-07-17 16:45:04.844 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.846 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:dimmer:440e003a24e6:36 needs [actionId, step], has [actionId, step].
2017-07-17 16:45:04.847 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:dimmer:440e003a24e6:36' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@142daf94'.
2017-07-17 16:45:04.861 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 36
2017-07-17 16:45:04.866 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:dimmer:440e003a24e6:35'.
2017-07-17 16:45:04.869 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:dimmer:440e003a24e6:35 needs [actionId, step], has [actionId, step].
2017-07-17 16:45:04.870 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:dimmer:440e003a24e6:35' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@60ac1aa9'.
2017-07-17 16:45:04.877 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.automation.internal.commands.CommandlineModuleTypeProvider' has been added.
2017-07-17 16:45:04.935 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 35
2017-07-17 16:45:04.874 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' updated: INITIALIZING
2017-07-17 16:45:04.936 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.937 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' updated: ONLINE
2017-07-17 16:45:04.938 [DEBUG] [.c.c.registry.AbstractRegistry:267  ] - Provider 'org.eclipse.smarthome.automation.internal.commands.CommandlineTemplateProvider' has been added.
2017-07-17 16:45:04.937 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.942 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' updated: INITIALIZING
2017-07-17 16:45:04.942 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.943 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' updated: ONLINE
2017-07-17 16:45:04.944 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.947 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' updated: INITIALIZING
2017-07-17 16:45:04.955 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.960 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' updated: ONLINE
2017-07-17 16:45:04.962 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.964 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' updated: INITIALIZING
2017-07-17 16:45:04.964 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.965 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' updated: ONLINE
2017-07-17 16:45:04.965 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.966 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' updated: INITIALIZING
2017-07-17 16:45:04.967 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:04.968 [INFO ] [.s.u.c.i.servlet.WebAppServlet:87   ] - Started Classic UI at /classicui/app
2017-07-17 16:45:04.973 [INFO ] [.s.u.b.i.servlet.WebAppServlet:84   ] - Started Basic UI at /basicui/app
2017-07-17 16:45:04.975 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' updated: ONLINE
2017-07-17 16:45:04.990 [DEBUG] [e.s.m.t.i.GenericThingProvider:931  ] - ThingHandlerFactory added org.openhab.binding.nikohomecontrol.internal.NikoHomeControlHandlerFactory@e657f06
2017-07-17 16:45:04.990 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' changed from INITIALIZING to ONLINE
2017-07-17 16:45:04.991 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:17'.
2017-07-17 16:45:04.991 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' updated: INITIALIZING
2017-07-17 16:45:05.055 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:17 needs [actionId], has [actionId].
2017-07-17 16:45:05.055 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:17' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@7b2d0bf6'.
2017-07-17 16:45:05.056 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 17
2017-07-17 16:45:05.061 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.062 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' updated: ONLINE
2017-07-17 16:45:05.062 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' changed from INITIALIZING to ONLINE
2017-07-17 16:45:05.064 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' updated: INITIALIZING
2017-07-17 16:45:05.065 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.065 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' updated: ONLINE
2017-07-17 16:45:05.065 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' changed from INITIALIZING to ONLINE
2017-07-17 16:45:05.066 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' updated: INITIALIZING
2017-07-17 16:45:05.066 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.067 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' updated: ONLINE
2017-07-17 16:45:05.067 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' changed from INITIALIZING to ONLINE
2017-07-17 16:45:05.068 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' updated: INITIALIZING
2017-07-17 16:45:05.069 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.069 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' updated: ONLINE
2017-07-17 16:45:05.069 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' changed from INITIALIZING to ONLINE
2017-07-17 16:45:05.071 [DEBUG] [.c.thing.internal.ThingManager:594  ] - Attempt to register a handler twice for thing nikohomecontrol:onOff:440e003a24e6:4 at the same time will be ignored.
2017-07-17 16:45:05.071 [DEBUG] [.c.thing.internal.ThingManager:647  ] - Attempt to initialize the already initialized thing 'nikohomecontrol:onOff:440e003a24e6:4' will be ignored.
2017-07-17 16:45:05.072 [DEBUG] [.c.thing.internal.ThingManager:603  ] - Calling 'NikoHomeControlHandlerFactory.registerHandler()' for thing 'nikohomecontrol:onOff:440e003a24e6:6'.
2017-07-17 16:45:05.074 [DEBUG] [.c.thing.internal.ThingManager:709  ] - Configuration of thing nikohomecontrol:onOff:440e003a24e6:6 needs [actionId], has [actionId].
2017-07-17 16:45:05.074 [DEBUG] [.c.thing.internal.ThingManager:735  ] - Calling initialize handler for thing 'nikohomecontrol:onOff:440e003a24e6:6' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@75eafae3'.
2017-07-17 16:45:05.093 [DEBUG] [o.b.n.h.NikoHomeControlHandler:210  ] - Niko Home Control: action intialized 6
2017-07-17 16:45:05.103 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' updated: INITIALIZING
2017-07-17 16:45:05.107 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.112 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' updated: ONLINE
2017-07-17 16:45:05.116 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' changed from INITIALIZING to ONLINE
2017-07-17 16:45:05.118 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' updated: INITIALIZING
2017-07-17 16:45:05.119 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2017-07-17 16:45:05.120 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' updated: ONLINE
2017-07-17 16:45:05.120 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' changed from INITIALIZING to ONLINE
2017-07-17 16:45:06.233 [DEBUG] [.e.s.c.t.i.ChannelItemProvider:181  ] - Enabling channel item provider.
2017-07-17 16:45:06.243 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:6:switch
2017-07-17 16:45:06.244 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:6' updated: ONLINE
2017-07-17 16:45:06.246 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:12:switch
2017-07-17 16:45:06.248 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_6_switch' has been added.
2017-07-17 16:45:06.248 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_42_switch' has been added.
2017-07-17 16:45:06.249 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:12' updated: ONLINE
2017-07-17 16:45:06.249 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_12_switch' has been added.
2017-07-17 16:45:06.250 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:18:switch
2017-07-17 16:45:06.250 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_24_switch' has been added.
2017-07-17 16:45:06.251 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:15:switch
2017-07-17 16:45:06.251 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_21_switch' has been added.
2017-07-17 16:45:06.252 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_33_switch' has been added.
2017-07-17 16:45:06.253 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:19:switch
2017-07-17 16:45:06.253 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_dimmer_440e003a24e6_29_brightness' has been added.
2017-07-17 16:45:06.254 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:18' updated: ONLINE
2017-07-17 16:45:06.255 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:13:switch
2017-07-17 16:45:06.255 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_18_switch' has been added.
2017-07-17 16:45:06.256 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:15' updated: ONLINE
2017-07-17 16:45:06.256 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:10:switch
2017-07-17 16:45:06.256 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_15_switch' has been added.
2017-07-17 16:45:06.256 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_25_switch' has been added.
2017-07-17 16:45:06.257 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_43_switch' has been added.
2017-07-17 16:45:06.257 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:16:switch
2017-07-17 16:45:06.258 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:9:switch
2017-07-17 16:45:06.258 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_5_switch' has been added.
2017-07-17 16:45:06.258 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:19' updated: ONLINE
2017-07-17 16:45:06.258 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:17:switch
2017-07-17 16:45:06.259 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_19_switch' has been added.
2017-07-17 16:45:06.259 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:dimmer:440e003a24e6:36:brightness
2017-07-17 16:45:06.261 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_28_switch' has been added.
2017-07-17 16:45:06.261 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:dimmer:440e003a24e6:35:brightness
2017-07-17 16:45:06.261 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_31_switch' has been added.
2017-07-17 16:45:06.262 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:13' updated: ONLINE
2017-07-17 16:45:06.262 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:11:switch
2017-07-17 16:45:06.263 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:4:switch
2017-07-17 16:45:06.264 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_13_switch' has been added.
2017-07-17 16:45:06.264 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:10' updated: ONLINE
2017-07-17 16:45:06.264 [DEBUG] [o.b.n.h.NikoHomeControlHandler:93   ] - Niko Home Control: handle command REFRESH for nikohomecontrol:onOff:440e003a24e6:7:switch
2017-07-17 16:45:06.265 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_10_switch' has been added.
2017-07-17 16:45:06.265 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_22_switch' has been added.
2017-07-17 16:45:06.266 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:16' updated: ONLINE
2017-07-17 16:45:06.266 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_16_switch' has been added.
2017-07-17 16:45:06.266 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:9' updated: ONLINE
2017-07-17 16:45:06.266 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_9_switch' has been added.
2017-07-17 16:45:06.267 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:17' updated: ONLINE
2017-07-17 16:45:06.267 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_17_switch' has been added.
2017-07-17 16:45:06.267 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:36' updated: ONLINE
2017-07-17 16:45:06.267 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_dimmer_440e003a24e6_36_brightness' has been added.
2017-07-17 16:45:06.268 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_23_switch' has been added.
2017-07-17 16:45:06.268 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_41_switch' has been added.
2017-07-17 16:45:06.269 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_44_switch' has been added.
2017-07-17 16:45:06.269 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:440e003a24e6:35' updated: ONLINE
2017-07-17 16:45:06.269 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_dimmer_440e003a24e6_35_brightness' has been added.
2017-07-17 16:45:06.269 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_dimmer_440e003a24e6_30_brightness' has been added.
2017-07-17 16:45:06.270 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:11' updated: ONLINE
2017-07-17 16:45:06.270 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_11_switch' has been added.
2017-07-17 16:45:06.271 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_27_switch' has been added.
2017-07-17 16:45:06.271 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:4' updated: ONLINE
2017-07-17 16:45:06.271 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_4_switch' has been added.
2017-07-17 16:45:06.271 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:440e003a24e6:7' updated: ONLINE
2017-07-17 16:45:06.272 [INFO ] [smarthome.event.ItemAddedEvent:43   ] - Item 'nikohomecontrol_onOff_440e003a24e6_7_switch' has been added.

!ENTRY org.eclipse.equinox.ds 2 0 2017-07-17 16:45:34.953
!MESSAGE [SCR - WorkThread] Timeout occurred! Thread was blocked on processing [QueuedJob] WorkPerformer: org.eclipse.equinox.internal.ds.SCRManager@1a255d; actionType 1

!ENTRY org.eclipse.equinox.ds 2 0 2017-07-17 16:45:34.968
!MESSAGE [SCR] Enabling components of bundle org.eclipse.smarthome.model.core did not complete in 30000 ms 
2017-07-17 16:45:58.441 [DEBUG] [.n.i.p.NikoHomeControlDiscover:54   ] - Niko Home Control: IP address is /192.168.0.121, unique ID is 440e003a24e6
2017-07-17 16:45:58.441 [DEBUG] [eControlBridgeDiscoveryService:67   ] - Niko Home Control: bridge found at /192.168.0.121

A few observations:

• The ThingManager is properly tracking the bridge and all child things.
• registerHandler is called for the bridge.
• thingHandler thread pool is created, size 5. Each thread seems to be running for a very long time. I suspect it is blocked for some reason, waiting for some configuration to finish.
• all child things status change to BRIDGE_UNINTIALIZED
• register and initialize child called for all child things, but run method in thread pool not executed for all (ThingManager registerChildHandlers method)
• for each child thing for which initialize is called, status updated to ONLINE correctly.
• NikoHomeControlBridgeDiscoveryService is called after 60s. This is intended as there could be changes in configuration. In this case there is no update to the bridge configuration, but still, it seems to stop the proper initialization of the remaining child things that did not get initialized within 60s after startup of the discovery service. The run methods from the thingHandler thread pool are not executed anymore.

Again, this may very well be an issue in my binding programming. In that case, please give me a hint and close this issue. I do think that it might be an issue in the framework itself though as I suspect the framework should not give up on initializing child things if the discovery service looking for bridges is called.

As this is a timing issue, I typically get my live system to operate without issues after a few restarts. Still I want to solve the issue and avoid the problem in the first place.

[triller-telekom]

I just tried to understand where your problem is but I do not get it. You are saying that your things get only half initialized and then the discovery somehow kicks in and kills the initializing threads?

Also your log file is very long, what is the relevant part? As far as I see in the end all things are initialized...

Could you please point me towards the specific problem?

[sjsf]

@mherwege I see what puzzles you - and I agree, something must have gone terribly wrong. No matter if it's an issue in the binding or not, this must not happen!

Would you mind getting a thread dump the next time you see this? Maybe that gives us a clue what the 5 thing manager threads keep themselves entertained with...

[mherwege]

@sjka I will when I see it happen again. I did try again today in Eclipse, with the latest updates included. I couldn't reproduce it anymore. Could it have anything to do with #3423 that it now works? I noticed another time when it happened a number of messages related to the XML files not being read completely yet. It didn't appear in the log I provided, but there was one logger that did not start properly. That could cause these messages not to appear. From the log:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

With my limited understanding of the code, I tought there was a lock somewhere that had methods waiting for this XML file loading to finish.

[sjsf]

No, that is unrelated I'm pretty sure. The waiting for XML processing delays handler creation but would influence the whole binding.

I'm rather suspecting a dead-lock in the ThingManager. It is using locks internally to ensure that only a single call goes to one ThingHandler at any time in parallel. So I suspect that the niko home control binding somehow discovered a way how to dead-lock the worker threads of the ThingManager. I just want that confirmed before I rework it completely...

[maggu2810]

@mherwege As you are using a Karaf based solution (openHAB), you could be interested in the command dev:dump-create (https://karaf.apache.org/manual/latest/#_dump).

[mherwege]

Just a little update. I was on vacation, so not able to test any further. On my return I upgraded openHAB to the latest unstable version (#1008). I have done a few restarts and not seen the problem since. If I run into it again, I will get you a dump.

[kaikreuzer]

Thanks for the feedback - so let's close the issue. Feel free to re-open it, if you come across it again.