Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Binding in "NOT_YET_READY" state after recent core changes #3394

Closed
digitaldan opened this issue Feb 22, 2023 · 27 comments · Fixed by #3407
Closed

Binding in "NOT_YET_READY" state after recent core changes #3394

digitaldan opened this issue Feb 22, 2023 · 27 comments · Fixed by #3407
Labels
bug An unexpected problem or unintended behavior of the Core

Comments

@digitaldan
Copy link
Contributor

Hi, i'm not sure if this is an error with the Harmony Binding that is only now surfacing with recent core changes, or if recent core changes are affecting certain existing bindings negatively by accident, so i'll start with opening the issue here.

After upgrading yesterday to the latest nightly build (with core 4.0.0.202302191628) , my harmonyhub things come up in a new state i have never seen before "NOT_YET_READY", which looks like was added to indicate binding dependencies or configs have not yet been satisfied ? In any case, the handler never activates, and i'm not sure what to do to fix this in the binding.

Here's a screenshot of the things in the UI (we probably need to add this state in the Main UI @ghys )
image

Here's a shot of a thing in this state:
image

Here's a dump of logs if i restart the Harmony Binding. Let me know what else i can do to help, thanks!

07:11:20.120 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Querying state active
07:11:20.122 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Deactivating component
07:11:20.123 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : registration change queue [unregistered]
07:11:20.125 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Querying state active
07:11:20.127 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : getting deactivate: deactivate
07:11:20.128 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Locating method deactivate in class org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory
07:11:20.129 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Declared Method org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory.deactivate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.130 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Locating method deactivate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
07:11:20.131 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Found deactivate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.deactivate(org.osgi.service.component.ComponentContext)
07:11:20.132 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : invoking deactivate: deactivate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
07:11:20.133 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : invoked deactivate: deactivate
07:11:20.133 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : DependencyManager: $000 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@7e4d7e8f at tracking count 1 refpairs: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=244, maxThreadsShared=80, service.bundleid=176, service.scope=bundle, maxThreadsCustom=25, minThreadsCustom=10, minThreadsShared=20, service.pid=org.openhab.webclient, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=185}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@37479e0b]]]
07:11:20.135 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
07:11:20.136 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Changed state from active to satisfied
07:11:20.140 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Deactivating dependency managers
07:11:20.145 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Disabling dependency managers
07:11:20.147 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : unregistering service listener for dependency $000
07:11:20.150 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Querying state satisfied
07:11:20.151 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Changed state from satisfied to disposed
07:11:20.151 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(434)] : Disposing component (reason: 6)
07:11:20.152 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Querying state active
07:11:20.152 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Deactivating component
07:11:20.153 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : registration change queue [unregistered]
07:11:20.154 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Querying state active
07:11:20.154 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : getting deactivate: deactivate
07:11:20.155 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Locating method deactivate in class org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService
07:11:20.157 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Declared Method org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService.deactivate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.158 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Locating method deactivate in class org.openhab.core.config.discovery.AbstractDiscoveryService
07:11:20.158 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Declared Method org.openhab.core.config.discovery.AbstractDiscoveryService.deactivate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.159 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Found deactivate method: protected void org.openhab.core.config.discovery.AbstractDiscoveryService.deactivate()
07:11:20.159 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : invoking deactivate: deactivate: parameters []
07:11:20.159 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - Stop HarmonyHub background discovery
07:11:20.160 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : invoked deactivate: deactivate
07:11:20.160 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
07:11:20.160 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Changed state from active to satisfied
07:11:20.161 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Deactivating dependency managers
07:11:20.162 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Disabling dependency managers
07:11:20.162 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Querying state satisfied
07:11:20.162 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Changed state from satisfied to disposed
07:11:20.163 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(435)] : Disposing component (reason: 6)
07:11:20.178 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : BundleComponentActivator : ComponentHolder created.
07:11:20.179 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : BundleComponentActivator : ComponentHolder created.
07:11:20.180 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.io.net.http.HttpClientFactory, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
07:11:20.180 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.harmonyhub]
07:11:20.181 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory, org.openhab.core.thing.type.ChannelTypeProvider, org.openhab.core.thing.type.ChannelGroupTypeProvider]
07:11:20.181 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Component Properties: {}
07:11:20.182 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Querying state disabled
07:11:20.182 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Querying state disabled
07:11:20.182 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Component can not be activated since it is in state disabled
07:11:20.183 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory] : Querying state disabled
07:11:20.184 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Updating target filters
07:11:20.184 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : No change in target property for dependency $000: currently registered: false
07:11:20.184 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] :  No existing service listener to unregister for dependency $000
07:11:20.185 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Setting target property for dependency $000 to null
07:11:20.185 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.net.http.HttpClientFactory), initialReferenceFilter (objectClass=org.openhab.core.io.net.http.HttpClientFactory)
07:11:20.185 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : dm $000 tracker reset (closed)
07:11:20.189 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=244, maxThreadsShared=80, service.bundleid=176, service.scope=bundle, maxThreadsCustom=25, minThreadsCustom=10, minThreadsShared=20, service.pid=org.openhab.webclient, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=185} (enter)
07:11:20.189 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
07:11:20.190 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=244, maxThreadsShared=80, service.bundleid=176, service.scope=bundle, maxThreadsCustom=25, minThreadsCustom=10, minThreadsShared=20, service.pid=org.openhab.webclient, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=185} (exit)
07:11:20.191 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : dm $000 tracker opened
07:11:20.191 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : registering service listener for dependency $000
07:11:20.191 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Changed state from disabled to unsatisfiedReference
07:11:20.192 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Component enabled
07:11:20.192 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : ActivateInternal
07:11:20.192 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state unsatisfiedReference
07:11:20.192 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state unsatisfiedReference
07:11:20.193 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Activating component from state unsatisfiedReference
07:11:20.193 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state unsatisfiedReference
07:11:20.193 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state unsatisfiedReference
07:11:20.194 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Changed state from unsatisfiedReference to satisfied
07:11:20.194 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : registration change queue [registered]
07:11:20.195 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Checking constructor public org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory)
07:11:20.196 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : getReferenceClass: Looking for interface class org.openhab.core.io.net.http.HttpClientFactory through loader of org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory
07:11:20.196 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : getParameterClass: Found class org.openhab.core.io.net.http.HttpClientFactory
07:11:20.196 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Found constructor with 1 arguments : public org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory)
07:11:20.197 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : This thread collected dependencies
07:11:20.197 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : getService (single component manager) dependencies collected.
07:11:20.197 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state satisfied
07:11:20.198 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Querying state satisfied
07:11:20.198 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=244, maxThreadsShared=80, service.bundleid=176, service.scope=bundle, maxThreadsCustom=25, minThreadsCustom=10, minThreadsShared=20, service.pid=org.openhab.webclient, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=185}] service: [null]]]
07:11:20.199 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : getting activate: activate
07:11:20.199 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Locating method activate in class org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory
07:11:20.199 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Declared Method org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.200 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
07:11:20.200 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
07:11:20.201 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
07:11:20.201 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : invoked activate: activate
07:11:20.202 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Set implementation object for component
07:11:20.202 [DEBUG] [hub.internal.HarmonyHubHandlerFactory] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.HarmonyHubHandlerFactory(436)] : Changed state from satisfied to active
07:11:20.211 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Component created: DS=DS13, implementation=org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[discovery.harmonyhub]
07:11:20.211 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Component Services: scope=singleton, services=[org.openhab.core.config.discovery.DiscoveryService]
07:11:20.212 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Component Properties: {}
07:11:20.212 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Querying state disabled
07:11:20.212 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Querying state disabled
07:11:20.212 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Component can not be activated since it is in state disabled
07:11:20.213 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService] : Querying state disabled
07:11:20.213 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Updating target filters
07:11:20.214 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Changed state from disabled to unsatisfiedReference
07:11:20.214 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Component enabled
07:11:20.214 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : ActivateInternal
07:11:20.214 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state unsatisfiedReference
07:11:20.215 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state unsatisfiedReference
07:11:20.215 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Activating component from state unsatisfiedReference
07:11:20.215 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state unsatisfiedReference
07:11:20.215 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state unsatisfiedReference
07:11:20.216 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Changed state from unsatisfiedReference to satisfied
07:11:20.216 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : registration change queue [registered]
07:11:20.217 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Checking constructor public org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService()
07:11:20.217 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Found constructor with 0 arguments : public org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService()
07:11:20.217 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : This thread collected dependencies
07:11:20.217 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : getService (single component manager) dependencies collected.
07:11:20.218 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state satisfied
07:11:20.218 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Querying state satisfied
07:11:20.218 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : getting activate: activate
07:11:20.219 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Locating method activate in class org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService
07:11:20.219 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Declared Method org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService.activate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.219 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Locating method activate in class org.openhab.core.config.discovery.AbstractDiscoveryService
07:11:20.219 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Declared Method org.openhab.core.config.discovery.AbstractDiscoveryService.activate([interface org.osgi.service.component.ComponentContext]) not found
07:11:20.220 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Found activate method: protected void org.openhab.core.config.discovery.AbstractDiscoveryService.activate(java.util.Map)
07:11:20.220 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.helper.ReadOnlyDictionary]
07:11:20.221 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - Start Harmony Hub background discovery
07:11:20.221 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - Start Scan
07:11:20.221 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - StartScan called
07:11:20.221 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - Creating Harmony server on port 40343
07:11:20.222 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : invoked activate: activate
07:11:20.222 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Set implementation object for component
07:11:20.222 [DEBUG] [.discovery.HarmonyHubDiscoveryService] - bundle org.openhab.binding.harmonyhub:4.0.0.202302200340 (270)[org.openhab.binding.harmonyhub.internal.discovery.HarmonyHubDiscoveryService(437)] : Changed state from satisfied to active
@J-N-K
Copy link
Member

J-N-K commented Feb 22, 2023

That happens if "something" is missing. You can set org.openhab.core.thing.internal.ThingManagerImpl to DEBUG and disable/enable the thing. You should see a message like Check result is 'not ready': {} where the placeholder shows a list of dependencies that are not found.

@digitaldan
Copy link
Contributor Author

Thanks, here's the relevant log:

09:12:48.919 [DEBUG] [.core.thing.internal.ThingManagerImpl] - Check result is 'not ready': ThingPrerequisites{thingUID=harmonyhub:hub:GameRoom, thingTypeUID=null, channelTypeUIDs=[harmonyhub:hub:GameRoom:currentActivity], configDescriptionUris=[]}

This is also happening to the remoteopenhab binding

09:12:48.917 [DEBUG] [.core.thing.internal.ThingManagerImpl] - Check result is 'not ready': ThingPrerequisites{thingUID=remoteopenhab:server:north, thingTypeUID=null, channelTypeUIDs=[remoteopenhab:itemSwitch1, remoteopenhab:itemDimmer1], configDescriptionUris=[]}

image

Looks like the thing types are not being initialized right ?

@J-N-K
Copy link
Member

J-N-K commented Feb 22, 2023

The result lists the missing entities:

  • thingTypeUID=null means that the ThingType for this thing has been found in the ThingTypeRegistry (otherwise it would be non-null, showing the ThingTypeUID which couldn't be resolved).
  • channelTypeUIDs=[harmonyhub:hub:GameRoom:currentActivity] means that the thing has a channel with the given ChannelTypeUID, but the ChannelTypeRegistry has no entry for that UID. Could it be that the channel-type has been removed in the past and the thing still carries the channel?

@J-N-K
Copy link
Member

J-N-K commented Feb 22, 2023

Probably. The question is how to solve that. We can either introduce a timeout similar to what we have for missing ThingTypes. But that is a bit ugly because it may cause issues in other places.

The reason the check was introduced is that we found that configuration parameters can cause issues if they are not normalized. For the normalization we need the config description of the thing/channel and that is available in the ThingType/ChannelType.

Maybe we should introduce an AbstractPersistingThing(Channel)TypeProvider that uses the StorageService to store all generated Thing(Channel)Types. A binding using dynamic types can implement that and the last version of these types is always available when the bundle is initialized (and then also thing initialization works). If the dynamic type needs to be updated, it is enough to update it in the provider and it's immediately available in the registry and the storage will be updated. If the ThingHandler implements handleRemoval, it can also remove the types related to the thing. WDYT?

I can make the code implementation and one reference implementation in openhab-addons, but I will not adjust all bindings.

@digitaldan
Copy link
Contributor Author

I can make the code implementation and one reference implementation in openhab-addons, but I will not adjust all bindings.

I worry that there a quite a few more bindings then that will be broken in 4.0 ?
/~https://github.com/search?q=repo%3Aopenhab%2Fopenhab-addons%20ChannelTypeBuilder&type=code

I don't mind going through bindings and fixing if our solution is a simple persist call, although would we have to handle removal in that case? Not sure what that lifecycle would look like.

Could we have bindings declare in their service or config that they use dynamic channels, and so are skipped the check that is currently failing ?

@J-N-K
Copy link
Member

J-N-K commented Feb 22, 2023

I think excluding from the check is wrong. We could do both things: Provide a way for easily persisting the types and add the time-out. That will not break systems (because it only delays initialization by IIRC 2 minutes and log w warning) and also show which bindings still need to be fixed.

@ghys
Copy link
Member

ghys commented Feb 22, 2023

Here's a screenshot of the things in the UI (we probably need to add this state in the Main UI @ghys )

Relevant UI code, which could indeed use some improvement: /~https://github.com/openhab/openhab-webui/blob/main/bundles/org.openhab.ui/web/src/components/thing/thing-status-mixin.js

@digitaldan
Copy link
Contributor Author

That will not break systems (because it only delays initialization by IIRC 2 minutes and log w warning) and also show which bindings still need to be fixed.

Gotcha, so the binding would eventually initialize after 2 mins regardless. If the binding is then modified to persist dynamic channels, then when a user upgrades , the first start would be delayed, but subsequent starts would not ( they now have persisted data)?

@lolodomo
Copy link
Contributor

Probably 20 bindings impacted !

Isn't 2 minutes a little too much ?

florian-h05 pushed a commit to openhab/openhab-webui that referenced this issue Feb 23, 2023
See openhab/openhab-core#3394.

Signed-off-by: Jan N. Klug <github@klug.nrw>
@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/openhab-4-0-snapshot-discussion/142322/188

@digitaldan
Copy link
Contributor Author

Could we possibly modify the BaseThingHandler to remove then add and persist channels when updated ? So handle this behind the scenes so bindings don't need to change ?

maybe here?

@J-N-K
Copy link
Member

J-N-K commented Feb 23, 2023

No, there is no way to clean that up after thing deletion in that case. I'm working on a solution that requires only minimal changes to bindings.

@wborn
Copy link
Member

wborn commented Mar 11, 2023

Is this fixed now?

@wborn wborn added the bug An unexpected problem or unintended behavior of the Core label Mar 11, 2023
@J-N-K
Copy link
Member

J-N-K commented Mar 11, 2023

There is a temporary fix, the „permanent“ solution is in the linked PR.

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/espmilighthub-new-binding-for-milight-limitlessled-and-easybulb/39720/556

@lolodomo
Copy link
Contributor

lolodomo commented May 7, 2023

Should we keep this issue opened until bindings are fixed?

@kaikreuzer
Copy link
Member

I'd say it is ok to keep it closed as #3397 anyhow mitigates the issue.

@lolodomo
Copy link
Contributor

@J-N-K : when I install the NTP binding with the last snapshot, I can see these logs:

10:34:42.775 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (NOT_YET_READY)
10:34:43.454 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
10:34:43.580 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from INITIALIZING to ONLINE

Is it normal that the thing is "not yet ready" during less than one second just after I installed the NTP binding ?

@J-N-K
Copy link
Member

J-N-K commented May 14, 2023

Could be. If the handler factory is present before all XMLs (with the thing definitions and config descriptions) are parsed, this can happen.

@kaikreuzer
Copy link
Member

Shouldn't our startup levels make sure that handlers are not initialized before all XMLs are processed?

@J-N-K
Copy link
Member

J-N-K commented May 14, 2023

This works fine if you start the system with installed add-ons, but not if you install add-ons later, because we don't reduce the start-levels.

@kaikreuzer
Copy link
Member

Ok, right.

@lolodomo
Copy link
Contributor

lolodomo commented May 14, 2023

It looks like it happens even when the binding is already installed.
First I stop the bundle:

2023-05-14 12:18:30.074 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from ONLINE to UNINITIALIZED
2023-05-14 12:18:30.079 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

and then I restart it:

2023-05-14 12:18:48.588 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (NOT_YET_READY)
2023-05-14 12:18:49.950 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2023-05-14 12:18:49.991 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'ntp:ntp:local' changed from INITIALIZING to ONLINE

I still have the "NOT_YET_READY".

It is a test OH server with the default install setup + the NTP binding installed.

@J-N-K
Copy link
Member

J-N-K commented May 14, 2023

That's the same as installing/uninstalling.

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/core-thing-internal-thingmanagerimpl-check-result-is-not-ready/149393/2

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/esphome-binding-for-the-native-api/146849/57

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of the Core
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants