openHAB2 - new issue with the startup process (MiOS binding)

Installing a new openHAB2 distro yesterday, I encountered one time again a new problem at startup. The MiOS binding is apparently started a little too early while all items are not yet loaded. Here is one of all the erros I got:

2016-03-04 23:05:31.677 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'maison.items'
2016-03-04 23:05:32.277 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Disabling weather locationId 'home', no binding available
2016-03-04 23:05:33.784 [INFO ] [ome.event.GroupItemStateChangedEvent] - All changed from NULL to UNDEF through GPersist
2016-03-04 23:05:33.789 [INFO ] [ome.event.GroupItemStateChangedEvent] - GPersist changed from NULL to UNDEF through GVirtualData
2016-03-04 23:05:33.794 [INFO ] [ome.event.GroupItemStateChangedEvent] - GVirtualData changed from NULL to 0 through TempChart1Periode
2016-03-04 23:05:33.803 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart1Periode changed from NULL to 0
2016-03-04 23:05:33.818 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart2Periode changed from NULL to 0
2016-03-04 23:05:33.827 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart3Periode changed from NULL to 0
2016-03-04 23:05:33.840 [INFO ] [marthome.event.ItemStateChangedEvent] - HumChart1Periode changed from NULL to 0
2016-03-04 23:05:33.861 [INFO ] [marthome.event.ItemStateChangedEvent] - HumChart2Periode changed from NULL to 0
2016-03-04 23:05:33.935 [INFO ] [marthome.event.ItemStateChangedEvent] - Date changed from NULL to 2016-03-04T23:05:33.843+0100
2016-03-04 23:05:34.106 [ERROR] [ding.mios.internal.MiosUnitConnector] - Exception 'Item 'SpotsCinema' could not be found in the item registry' raised pushing property 'unit:house,device:7/service/urn:upnp-org:serviceId:Dimming1/LoadLevelStatus' value '0' into openHAB
org.openhab.core.items.ItemNotFoundException: Item 'SpotsCinema' could not be found in the item registry
        at org.openhab.core.items.internal.ItemUIRegistryDelegate.getItem(ItemUIRegistryDelegate.java:49)[155:org.openhab.core.compat1x:2.0.0.201603021555]
        at org.openhab.binding.mios.internal.MiosBinding.internalPropertyUpdate(MiosBinding.java:493)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at org.openhab.binding.mios.internal.MiosBinding.postPropertyUpdate(MiosBinding.java:430)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.publish(MiosUnitConnector.java:471)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processDevices(MiosUnitConnector.java:595)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processResponse(MiosUnitConnector.java:706)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.run(MiosUnitConnector.java:782)[170:org.openhab.binding.mios:1.9.0.201603040213]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]

I get the error for a lot of my items linked to the MiOS binding but not all. So I assume that when the binding is getting the item from the registry, some are already loaded, others are not yet.
I can confirm that I get the same errors at each restart.

I know that in a next distro version, maybe the MiOS binding will be started a little later and I will not see these problems.

I know that noone care about the startup processus and the order of things to be started. It is considered as a kind of feature to have anything started in a random order in openHAB, but in my opinion it is the major problem in openHAB, a problem I already encountered in several different situations. If at statup bindings could be started after the full loading of items, it could solve a lot of problems.

That would be my dream if someone could finally consider this problem as a real problem.

@guessed: if not, I think it will require to implement a complex system in your binding to retry later your stuff when you don’t find the item in registry.
As a workaround, with the MiOS binding and this distro, I can reload the Vera after OH startup to force a full refresh of my items.

I’d be interested to know what changed from OH 1.x to OH 2.x (Compat mode) that triggered it. There has to be something predictable that indicates “we done loading config” that can be used to trigger any downstream (binding) startup events.

In the case of the MiOS Binding data above, IIUC, it looks like Item change events (or Persistence restore?) are coming in for Items that aren’t yet fully described yet to the underlying Binding. That def won’t be a good outcome. :frowning:

I can confirm that my persist file is loaded just before my item files.
I have only few items persisted and the logs just before the exception are relative to persistence restore.
I have no MiOS items persisted.

Here are the new logs with the last distro (same problem):

2016-03-05 15:00:53.440 [INFO ] [b.core.service.AbstractActiveService] - Freebox Refresh Service has been started
2016-03-05 15:00:53.452 [INFO ] [ding.freebox.internal.FreeboxBinding] - Freebox binding properly configured
2016-03-05 15:00:53.483 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2016-03-05 15:00:53.486 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2016-03-05 15:00:54.673 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-03-05 15:00:54.798 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-03-05 15:00:54.938 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:temperaturehumidity:3ac86e19:8196' changed from OFFLINE to ONLINE
2016-03-05 15:00:55.289 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=WUNDERGROUND,apiKey=e75f7f109ae6fd98]
2016-03-05 15:00:55.291 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=WUNDERGROUND,language=FR,updateInterval=30,latitude=49.001122,longitude=2.230609,woeid=<null>,locationId=home,name=Maison]
2016-03-05 15:00:55.632 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'maisonOH2.sitemap'
2016-03-05 15:00:57.361 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2016-03-05 15:00:57.688 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'maison.items'
2016-03-05 15:00:58.304 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Disabling weather locationId 'home', no binding available
2016-03-05 15:00:59.188 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'LampeTeleviseurSw2-hue:LLC011:0017881108fc:1:color' has been added.
2016-03-05 15:00:59.820 [INFO ] [ome.event.GroupItemStateChangedEvent] - All changed from NULL to UNDEF through GPersist
2016-03-05 15:00:59.826 [INFO ] [ome.event.GroupItemStateChangedEvent] - GPersist changed from NULL to UNDEF through GVirtualData
2016-03-05 15:00:59.833 [INFO ] [ome.event.GroupItemStateChangedEvent] - GVirtualData changed from NULL to 0 through TempChart1Periode
2016-03-05 15:00:59.840 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart1Periode changed from NULL to 0
2016-03-05 15:00:59.862 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart2Periode changed from NULL to 0
2016-03-05 15:00:59.896 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart3Periode changed from NULL to 0
2016-03-05 15:00:59.900 [ERROR] [ding.mios.internal.MiosUnitConnector] - Exception 'Item 'LampeSalon' could not be found in the item registry' raised pushing property 'unit:house,device:4/service/urn:upnp-org:serviceId:SwitchPower1/Status' value '0' into openHAB
org.openhab.core.items.ItemNotFoundException: Item 'LampeSalon' could not be found in the item registry

Note that in my OH1 config (same machine RPI 2), I can see that my rrd4j.persist file is loaded before my maison.items file too.

PS: The MiOS binding is logging no message at all at INFO level at startup in OH 1.

No, there isn’t something like that. Items can come at at any time, not only during startup.
Isn’t that the same discussion as the one we had?

@guessed even if it is not the full solution, you should probably catch the not found exception at line 493.
Then the question is: what to do next when it happens ? Probably no simple solution. You would have to store the value and try later when bindingChanged is called for this item ?
That is a difficulty for most of bindings and I would not be surprised that only few of them handled that properly.

This is a little different.

When I get a data changing event, I lookup the Item in the registry (using its name) to get its typing information. This is needed so the appropriate data mapping/conversions can be done (etc).

Here, I appear to be presented with the name of an Item, and its value, that doesn’t exist in the Item registry.

This seems out of sequence, and is what I’m referring to by a predictable ordering.

Ie. item defined in Registry prior to restoring values from persistence, or receiving events at the Binding level.

Perhaps I’m reading the stacks incorrectly, but this wasn’t possible in OH1, so handling the ‘not found’ case wasn’t needed.

I wouldn’t be surprised either :slight_smile:

Receiving the value before having the typing information in hand will cause more than a little acid reflux … In a strongly typed system.

The exception had the desired effect in this case, alerting us to an unexpected data input.

I could convert it to an assert, but the effect would be the same. Buffering in this case isn’t the answer, as other things would end up delivered out of order to the user/rule engine.

In OH1 I’ll re-pull the data when the Items file changes (eg additions of Binding defs) but the Item registry entry was always present prior to this trigger event, so everything aligned as expected.

I don’t think it’s reasonable, nor expected, for a Binding to ever see these out of order…

Probably only @Kai can explain this difference between OH1 and OH2 and confirm if current behaviour is expected or not. But reading your explanations, I would say it is not…

As a temporary fix, you could delay the connection to the Vera by few seconds with a simple sleep ?

@lolodomo,
The code already defers the event-loop creation until one of the following occurs:

  • a) allBindingsChanged event.
  • b) bindingChanged event.
  • c) a Rule calls sendCommand() on an Item from the MiOS Binding.
  • d) a Rule calls a MiOS Action Binding Scene or Action. (aka sendMios...())
  • e) After the configuration is setup, or changed, via updated()

For (e), I’m only doing it when OSGi is passing in a valid/non-null context. This’ll happen on the 2nd pass call to updated(), after OSGi startup, under OH2.

It’s possible that if the mios.cfg object is changed, and a named MiOS Unit is removed, that I’m not closing down it’s event-loop… I don’t think that’s what you’re running into here, as that’s a fairly specific case.

Deferring it further will not fix the problem, it’ll just hide it.

I have a parameter in the settings that’ll trigger the Binding to perform a full load again, after a certain # of calls. I originally put this in to handle cases where the Binding might get out of sync with MiOS, but I ended up making it more automatic. I don’t recall the parameter name atm, but it defaults to disabled.

Using this option has side-effects, since every Item will get Item-update events when the data hasn’t changed. Rules (etc) would need to be coded to avoid unexpected behaviors :wink:

I’ll double check the code when I get time, but I’m not clear how I (correctly) resolve the case where I get data, for a named-Item that I’m bound to, and the ItemRegistry doesn’t know about it the named-Item.

I’ll also fix the code in the error handler to get the full exception (4 parameters, only 3x printed, oops!) and potentially stop running the event-loop at the end of updated() just in case that’s causing headaches in OH2-Compat… I’ll have to look at the event sequence for OH1 and 2 to ensure it doesn’t cause other problems.

Here is my starting sequence after enabling DEBUG logs for MiOS binding:

2016-03-06 19:23:58.649 [DEBUG] [org.openhab.binding.mios            ] - BundleEvent STARTING - org.openhab.binding.mios
2016-03-06 19:23:58.658 [DEBUG] [.binding.mios.internal.MiosActivator] - MiOS binding has been started
2016-03-06 19:23:58.719 [DEBUG] [org.openhab.binding.mios            ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mios.MiosBindingProvider}={component.name=org.openhab.binding.mios.genericbindingprovider, component.id=162, service.id=270, service.bundleid=155, service.scope=bundle} - org.openhab.binding.mios
2016-03-06 19:23:58.739 [DEBUG] [ios.internal.MiosBindingProviderImpl] - setItemRegistry: called
2016-03-06 19:23:58.821 [DEBUG] [org.openhab.binding.mios            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService, org.openhab.binding.mios.MiosActionProvider}={event.topics=openhab/*, service.pid=org.openhab.mios, component.name=org.openhab.binding.mios.activebinding, component.id=161, service.id=272, service.bundleid=155, service.scope=bundle} - org.openhab.binding.mios
2016-03-06 19:23:58.853 [DEBUG] [ab.binding.mios.internal.MiosBinding] - allBindingsChanged: start provider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd'
2016-03-06 19:23:58.858 [DEBUG] [ab.binding.mios.internal.MiosBinding] - MiosBinding activate()
2016-03-06 19:23:58.897 [DEBUG] [org.openhab.binding.mios            ] - BundleEvent STARTED - org.openhab.binding.mios



2016-03-06 19:24:01.586 [DEBUG] [ab.binding.mios.internal.MiosBinding] - updated: Created Unit 'house'
2016-03-06 19:24:01.588 [DEBUG] [ab.binding.mios.internal.MiosBinding] - registerAllWatches: start
2016-03-06 19:24:01.590 [DEBUG] [ab.binding.mios.internal.MiosBinding] - registerAllWatches: provider 'class org.openhab.binding.mios.internal.MiosBindingProviderImpl'



2016-03-06 19:24:04.999 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'maisonOH2.sitemap'
2016-03-06 19:24:06.233 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2016-03-06 19:24:06.505 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'maison.items'
2016-03-06 19:24:06.866 [DEBUG] [os.internal.config.MiosBindingConfig] - Successfully loaded UPnP Service Aliases from 'org/openhab/binding/mios/internal/config/ServiceAliases.properties', entries '133'
2016-03-06 19:24:06.873 [DEBUG] [os.internal.config.MiosBindingConfig] - Successfully loaded Device Parameter defaults from 'org/openhab/binding/mios/internal/config/DeviceDefaults.properties', entries '23'
2016-03-06 19:24:06.884 [DEBUG] [ios.internal.MiosBindingProviderImpl] - processBindingConfiguration: Adding Item 'MiniMoteSceneActivated' Binding 'unit:house,device:6/service/urn:micasaverde-com:serviceId:SceneController1/sl_SceneActivated', from 'maison.items'
2016-03-06 19:24:06.887 [DEBUG] [ab.binding.mios.internal.MiosBinding] - bindingChanged: start provider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'MiniMoteSceneActivated'
2016-03-06 19:24:06.890 [DEBUG] [ab.binding.mios.internal.MiosBinding] - registerWatch: start miosProvider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'MiniMoteSceneActivated'
2016-03-06 19:24:06.892 [DEBUG] [ab.binding.mios.internal.MiosBinding] - Creating new MiosConnector for 'house' on 192.168.1.19
2016-03-06 19:24:06.902 [DEBUG] [ding.mios.internal.MiosUnitConnector] - Constructor: unit 'org.openhab.binding.mios.internal.MiosUnit@fec825', binding 'org.openhab.binding.mios.internal.MiosBinding@1158818'
2016-03-06 19:24:07.286 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Disabling weather locationId 'home', no binding available
2016-03-06 19:24:07.696 [DEBUG] [ios.internal.MiosBindingProviderImpl] - processBindingConfiguration: Adding Item 'MiniMoteSceneDeactivated' Binding 'unit:house,device:6/service/urn:micasaverde-com:serviceId:SceneController1/sl_SceneDeactivated', from 'maison.items'
2016-03-06 19:24:07.696 [DEBUG] [ding.mios.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.1.19:3480/data_request?id=status2' loop '0'
2016-03-06 19:24:07.698 [DEBUG] [ab.binding.mios.internal.MiosBinding] - bindingChanged: start provider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'MiniMoteSceneDeactivated'
2016-03-06 19:24:07.704 [DEBUG] [ab.binding.mios.internal.MiosBinding] - registerWatch: start miosProvider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'MiniMoteSceneDeactivated'

Then you have all calls to bindingChanged including the call for item LampeSalon:


2016-03-06 19:24:07.781 [DEBUG] [ios.internal.MiosBindingProviderImpl] - processBindingConfiguration: Adding Item 'LampeSalon' Binding 'unit:house,device:4/service/urn:upnp-org:serviceId:SwitchPower1/Status,command:ON|OFF,in:MAP(miosSwitchIn.map),out:MAP(miosSwitchOut.map)', from 'maison.items'
2016-03-06 19:24:07.782 [DEBUG] [ab.binding.mios.internal.MiosBinding] - bindingChanged: start provider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'LampeSalon'
2016-03-06 19:24:07.784 [DEBUG] [ab.binding.mios.internal.MiosBinding] - registerWatch: start miosProvider 'org.openhab.binding.mios.internal.MiosBindingProviderImpl@f078bd', itemName 'LampeSalon'

And then just after:


2016-03-06 19:24:08.560 [DEBUG] [ding.mios.internal.MiosUnitConnector] - processResponse: success! loadTime=1457206105, dataVersion=206114798 devices(29) scenes(1) rooms(0) sections(0)
2016-03-06 19:24:08.560 [INFO ] [ome.event.GroupItemStateChangedEvent] - All changed from NULL to UNDEF through GPersist
2016-03-06 19:24:08.566 [INFO ] [ome.event.GroupItemStateChangedEvent] - GPersist changed from NULL to UNDEF through GVirtualData
2016-03-06 19:24:08.571 [INFO ] [ome.event.GroupItemStateChangedEvent] - GVirtualData changed from NULL to 0 through TempChart1Periode
2016-03-06 19:24:08.576 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart1Periode changed from NULL to 0
2016-03-06 19:24:08.581 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart2Periode changed from NULL to 0
2016-03-06 19:24:08.585 [INFO ] [marthome.event.ItemStateChangedEvent] - TempChart3Periode changed from NULL to 0
2016-03-06 19:24:08.589 [INFO ] [marthome.event.ItemStateChangedEvent] - HumChart1Periode changed from NULL to 0
2016-03-06 19:24:08.597 [INFO ] [marthome.event.ItemStateChangedEvent] - HumChart2Periode changed from NULL to 0
2016-03-06 19:24:08.635 [INFO ] [marthome.event.ItemStateChangedEvent] - Date changed from NULL to 2016-03-06T19:24:08.599+0100
2016-03-06 19:24:08.674 [ERROR] [ding.mios.internal.MiosUnitConnector] - Exception 'Item 'LampeSalon' could not be found in the item registry' raised pushing property 'unit:house,device:4/service/urn:upnp-org:serviceId:SwitchPower1/Status' value '1' into openHAB
org.openhab.core.items.ItemNotFoundException: Item 'LampeSalon' could not be found in the item registry
        at org.openhab.core.items.internal.ItemUIRegistryDelegate.getItem(ItemUIRegistryDelegate.java:49)[154:org.openhab.core.compat1x:2.0.0.201603021555]
        at org.openhab.binding.mios.internal.MiosBinding.internalPropertyUpdate(MiosBinding.java:493)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosBinding.postPropertyUpdate(MiosBinding.java:430)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.publish(MiosUnitConnector.java:471)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processDevices(MiosUnitConnector.java:595)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processResponse(MiosUnitConnector.java:706)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.run(MiosUnitConnector.java:782)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]
2016-03-06 19:24:08.707 [DEBUG] [ab.binding.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Full) Updating 'MiniMoteSceneActivated {mios="unit:house,device:6/service/urn:micasaverde-com:serviceId:SceneController1/sl_SceneActivated"}' to '2', was 'Uninitialized'
2016-03-06 19:24:08.716 [DEBUG] [ab.binding.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Full) Updating 'MiniMoteSceneDeactivated {mios="unit:house,device:6/service/urn:micasaverde-com:serviceId:SceneController1/sl_SceneDeactivated"}' to '3', was 'Uninitialized'
2016-03-06 19:24:08.730 [INFO ] [marthome.event.ItemStateChangedEvent] - MiniMoteSceneActivated changed from NULL to 2
2016-03-06 19:24:08.734 [ERROR] [ding.mios.internal.MiosUnitConnector] - Exception 'Item 'SpotsCinema' could not be found in the item registry' raised pushing property 'unit:house,device:7/service/urn:upnp-org:serviceId:Dimming1/LoadLevelStatus' value '0' into openHAB
org.openhab.core.items.ItemNotFoundException: Item 'SpotsCinema' could not be found in the item registry
        at org.openhab.core.items.internal.ItemUIRegistryDelegate.getItem(ItemUIRegistryDelegate.java:49)[154:org.openhab.core.compat1x:2.0.0.201603021555]
        at org.openhab.binding.mios.internal.MiosBinding.internalPropertyUpdate(MiosBinding.java:493)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosBinding.postPropertyUpdate(MiosBinding.java:430)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.publish(MiosUnitConnector.java:471)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processDevices(MiosUnitConnector.java:595)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.processResponse(MiosUnitConnector.java:706)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at org.openhab.binding.mios.internal.MiosUnitConnector$LongPoll.run(MiosUnitConnector.java:782)[155:org.openhab.binding.mios:1.9.0.201603050212]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]
2016-03-06 19:24:08.738 [INFO ] [marthome.event.ItemStateChangedEvent] - MiniMoteSceneDeactivated changed from NULL to 3

So it first fails for LampeSalon and then immediately works for MiniMoteSceneActivated
and MiniMoteSceneDeactivated, then fails for SpotsCinema…

That is really weird !!!

It is at least interesting to mention that items MiniMoteSceneActivated
and MiniMoteSceneDeactivated are the first to be called with bindingChanged() and they works.
LampeSalon is the 8th and it fails.
SpotsCinema is the 62th and it fails.
That would mean you’re right, even if bindingChanged() is first called for an item, the item is not immediately available through the registry… and a delay is required !

A solution could be to catch the “not found” exception and when occurs then wait 1 or 2 seconds before retrying.
It should fix the current issue even if the real issue is probably elsewhere…

The logs show me that the first response from the Vera is handled after all calls to bindingChanged.
Are logs timing reliable ?

@guessed: When I consult your code, I can see that you establish the connection to the Vera and send a request “status2” to the the Vera (confirmed by my logs) as soon as the first call to bindingChanged occurs, meaning that potentially postPropertyUpdate could be called for an item before bindingChanged is called for this item ?

We can see that other bindings have similar problems:

I think here lies the problem. It was never (officially) allowed to use the ItemRegistry within a binding. The type information is passed with the processBindingConfiguration call.
I vaguely remember you had some reason why this wasn’t good enough for MIOS and why you nonetheless wanted to use the ItemRegistry. But this is then an exceptional case that we will have to see how we can get it working in OH2.

I personaly think it would be a good improvement to call the bridge intialization AFTER all things assigned to the bridge are up and running (only related indirectly to this problem)

@s.simma We are talking about OH1 bindings here, so there are no bridges involved :wink:

Any progress or solution for this problem ?