[OH 2.4.0 M6] Cannot add "Metadata" with key "channel:aLivingFloorLeftBulbs_switch". It exists already from provider "GenericMetadataProvider"

[Hilbrand]

Problem description:

User ptweety made the following observation in when testing OH 2.4.0 M6:

there seems to be some kind of issue (just a warning though) with my item definition. I have 2 or 3 channels linked to a single item. Is this use case deprecated?

Dimmer aLivingCeilingBulb "Deckenlampe" <wallswitch> (gLivingCeilingBulb) { channel="hue:0220:00178840cd07:5:brightness", channel="hue:0220:00178840cd07:6:brightness", channel="hue:0220:00178840cd07:7:brightness" }
Dimmer aLivingFloorLeftBulbs "Stehlampe Links" <wallswitch> (gLivingFloorLeftBulbs) { channel="hue:0220:00178840cd07:12:brightness", channel="hue:0220:00178840cd07:13:brightness" }
Dimmer aLivingFloorRightBulbs "Stehlampe Rechts" <wallswitch> (gLivingFloorRightBulbs) { channel="hue:0220:00178840cd07:14:brightness", channel="hue:0220:00178840cd07:15:brightness" }

Logs:

2018-11-22 19:51:01.838 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingCeilingBulb". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!
2018-11-22 19:51:01.839 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingCeilingBulb". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!
2018-11-22 19:51:01.844 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingFloorRightBulbs". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!
2018-11-22 19:51:01.845 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingFloorRightBulbs_switch". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!
2018-11-22 19:51:01.846 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingFloorLeftBulbs". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!
2018-11-22 19:51:01.847 [WARN ] [ore.common.registry.AbstractRegistry] - Cannot add "Metadata" with key "channel:aLivingFloorLeftBulbs_switch". It exists already from provider "GenericMetadataProvider"! Failed to add a second with the same UID from provider "GenericMetadataProvider"!

Analysis:

• At first it was thought this was related to pr #6438. Because that change modified the lines that were changed. However up on better looking at it the warning was already present and should have been given without the change.
• The provider mentioned in the warning GenericMetadataProvider triggers this warning from the method addMetadata and that method is only called from GenericItemProvider.
• The that call to addMetaData was added in pr #4390 related to adding meta data.
• To get to this call the BindingConfigReader must be null in method internalDispatchBindings
• That will only happen if parameter reader is null and bindingConfigReaders.get(bindingType) also returns null.
• bindingConfigReaders.get(bindingType) is null if bindingType isn't in bindingConfigReaders. And that only seems to be possible if addBindingConfigReader is not called before a call to internalDispatchBindings with a null reader is done.

Questions

• Because these 2 calls seem to be triggered by service availability this looks like a timing issue. Where one call becomes before the other. It could even be due to the initial mentioned pr because that improved performance and it can be this changes the order because some services are now faster. Or was it intended design that it always was called in that order?
• Looking at the warning message it tries to add channel:aLivingFloorLeftBulbs_switch as a meta data tag. That seems strange because channel should not be added as a meta tag. So why is is added as a meta tag?
• The use of method internalDispatchBindings looks somewhat complex. There are several methods calling this method from different starting points. Maybe it needs some improvement here, like calling with a null reader to trigger a specific path seems somewhat hacky.
• The question is if this is a problem. At first sight it looks like it might not be a problem it just tries to add a channel as a second meta tag. tags in an item must be unique, but channels are an exception. So it's ok to add multiple channels to an item and when added all these as meta tags the warning is logical because then. So the questions remain why is it adding channel as a tag? and what (change) could trigger this?

[kaikreuzer]

this looks like a timing issue.

Sounds likely, I agree.

That seems strange because channel should not be added as a meta tag. So why is is added as a meta tag?

My assumption is that the GenericItemChannelLinkProvider (which implements BindingConfigReader) is not started at that moment and hence "channel" is considered to be some "random" meta-data.

At first sight it looks like it might not be a problem it

If the expected meta-data is available, it probably is not a problem that will break anything. Having "channel" metadata added is a bit ugly, but it shouldn't harm. Doing changes to internalDispatchBindings sounds pretty risky to me, so I'd rather go with reducing the log level for now.

[cweitkamp]

I submitted https://github.com/openhab/openhab-core/pull/755 to reduce the logging level.