Ubiquiti Unifi Binding Feature Discussion

ubiquiti
unifi
Tags: #<Tag:0x00007f51dee2b530> #<Tag:0x00007f51dee2b378>

(Matthew) #646

Looks like you’re right, restart kills it.

I’m thinking it’s because fresh snapshot doesn’t have any circular references because unifi isn’t yet loaded.

Installing and starting the bundle works as expected (all the other components are already loaded).

Restart and poof

Digging deeper :thinking:


(Kim Andersen) #647

Could it be related?:


(Angelos) #648

no, I think it’s more complex: The maintainers requested to re-use an existing ESH functionality (HttpClientFactory) and this impacts the way that Matthew had already implemented TLS within the binding so he has to figure out a new method

see here: https://github.com/openhab/openhab2-addons/pull/3387#discussion_r239528242


(Martin van Wingerden) #649

I think this is timing problem which is corrected by the runtime in the end.

And I opened an issue for it: https://github.com/eclipse/smarthome/issues/6641


(Matthew) #650

What’s the difference here vs the iCloud binding?

iCloud uses TlsCertificateProvider where UniFi uses TlsTrustManagerProvider. I would think it would be functionally the same - it’s just different interface implementations.

Edit: I know iCloud uses the HttpRequestBuilder (which I could as well), but even if I remove the references to HttpClientFactory and use my own, it still throws throw the circular reference.


(Martin van Wingerden) #651

I fear that there is no difference and the iCloud binding also has this behaviour (some times ) after a restart.


(Rory Donnelly) #652

@mgbowman Okay, so I shutdown my cloud key and installed a controller on a windows machine (until I get to the bottom of the cert issue). Binding is working fine now :slight_smile:


(Matthew) #653

@martinvw considering there are inconsistent results with using TlsTrustManagerProvider, would it not be ok to revert back to using my own HttpClient instance until we can manage to figure this out?

This way maybe there’s a chance we can still squeeze this into 2.4


(Alexander) #654

Hey folks,

I’ve walked into this error today. Does anyone have an idea?

07-Dec-2018 16:01:01.366 [smarthome.event.ThingStatusInfoChangedEvent ] - ‘unifi:controller:home’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): java.io.EOFException: HttpConnectionOverHTTP@16a41ff(l:/192.168.1.60:48560 <-> r:/192.168.1.7:8443,closed=false)[HttpChannelOverHTTP@372aef(exchange=HttpExchange@4cf134 req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@1c24ae7(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@b88519{s=START}],recv=HttpReceiverOverHTTP@199a7f3(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]]

Kind regards,
Alex


(Angelos) #655

Which version of the binding are you running, on which OH2 release?

this looks like a simple disconnection between the binding running on your OH2 host and the Unifi Controller Software running on the remote host. It could be due to several reasons …(Controller down, link down, etc)

Does it happen often? Does the Thing go back to Online after some time?


(Kai Kreuzer) #656

Ok for me, let’s go the safe route - but please put the current solution back as soon as we are on 2.5.0-SNAPSHOT, so we can investigate further. Our TLS http client has to work reliably and this seems to be a good case to find out potential problems it might still have :slight_smile:


(Matthew) #657

@Dim can you try the latest version?

openhab> bundle:list | grep -i unifi
190 │ Active   │  80 │ 2.4.0.201812080707     │ UniFi Binding

I added some basic SSL exception handling and want to see if maybe you’re having an issue unrelated to the circular dependency warning (which I don’t think is causing your problems).

Edit: Fixed the version number (was using a local build vs. the jenkins build)


(Angelos) #658

There you go Matthew (same status unfortunately)

OH 2.4.0.S1454
Unifi Controller: 5.6.40
binding.unifi: 2.4.0.201812080707

2018-12-08 09:18:17.136 [ERROR] [org.apache.felix.scr                ] - bundle org.apache.felix.scr:2.1.2 (39)Circular reference detected trying to get service {org.eclipse.smarthome.io.net.http.TlsTrustManagerProvider}={service.id=118, service.bundleid=191, service.scope=bundle, component.name=org.openhab.binding.unifi.internal.ssl.UniFiTrustManagerProvider, component.id=17}
 stack of references: ServiceReference: {org.eclipse.smarthome.io.net.http.TlsTrustManagerProvider}={service.id=118, service.bundleid=191, service.scope=bundle, component.name=org.openhab.binding.unifi.internal.ssl.UniFiTrustManagerProvider, component.id=17}
ServiceReference: {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=131, service.bundleid=118, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, component.id=35}

java.lang.Exception: stack trace
	at org.apache.felix.scr.impl.ComponentRegistry.enterCreate(ComponentRegistry.java:481) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.enterCreate(BundleComponentActivator.java:735) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:845) [39:org.apache.felix.scr:2.1.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) [?:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:73) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:662) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2304) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.prebind(DependencyManager.java:419) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1576) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1014) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:899) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:863) [39:org.apache.felix.scr:2.1.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) [?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) [?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:891) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:877) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:944) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:727) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:661) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:427) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [?:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:468) [?:?]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:103) [?:?]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:529) [?:?]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:328) [?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:368) [?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:446) [?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:395) [?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:387) [?:?]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:150) [?:?]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:564) [?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:984) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1011) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:899) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:863) [39:org.apache.felix.scr:2.1.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) [?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) [?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) [?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]
	at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) [?:?]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318) [?:?]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) [?:?]
	at com.eclipsesource.jaxrs.publisher.internal.Activator.openAllServiceTracker(Activator.java:91) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at com.eclipsesource.jaxrs.publisher.internal.Activator.start(Activator.java:55) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) [?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) [?:?]
	at org.eclipse.osgi.container.Module.doStart(Module.java:581) [?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:449) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
2018-12-08 09:18:17.192 [WARN ] [org.openhab.binding.unifi           ] - FrameworkEvent WARNING - org.openhab.binding.unifi
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:73) ~[?:?]
	at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:662) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2304) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.prebind(DependencyManager.java:419) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1576) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1014) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:899) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:863) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:920) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:469) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:891) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:877) ~[?:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:944) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:727) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:661) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:427) ~[?:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:665) ~[?:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339) ~[?:?]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:381) ~[?:?]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) ~[?:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) ~[?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) ~[?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) ~[?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) ~[?:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) ~[?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:467) ~[?:?]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:468) ~[?:?]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:103) ~[?:?]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:529) ~[?:?]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:328) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:368) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:446) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:395) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:387) ~[?:?]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:150) ~[?:?]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:564) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:984) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1011) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:899) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:863) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:508) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:624) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318) ~[?:?]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.Activator.openAllServiceTracker(Activator.java:91) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.Activator.start(Activator.java:55) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) ~[?:?]
	at org.eclipse.osgi.container.Module.doStart(Module.java:581) ~[?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:449) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]

(Matthew) #659

@martinvw I think I might of discovered what’s going on here…

This is from a freshly unzipped 2.4.0-SNAPSHOT #1451 (no extra packages / no UIs installed - didn’t even open the web UI).

openhab> bundle:install https://jenkins.otr.mx/job/openhab2-unifi-binding/83/artifact/addons/binding/org.openhab.binding.unifi/target/org.openhab.binding.unifi-2.4.0-SNAPSHOT.jar
Bundle ID: 190
openhab> bundle:start 190

Here’s the error

2018-12-08 09:20:10.991 [DEBUG] [.handler.UniFiControllerThingHandler] - Initializing the UniFi Controller Handler with config = UniFiControllerConfig{host = unifi, port = 8443, username = [redacted], password = *****, refresh = 10}
2018-12-08 09:20:11.096 [ERROR] [.handler.UniFiControllerThingHandler] - Unknown error while configuring the UniFi Controller
org.openhab.binding.unifi.internal.api.UniFiException: java.lang.RuntimeException: Delegated task threw Exception/Error
	at org.openhab.binding.unifi.internal.api.UniFiControllerRequest.getContentResponse(UniFiControllerRequest.java:161) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.api.UniFiControllerRequest.getContent(UniFiControllerRequest.java:119) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.api.UniFiControllerRequest.execute(UniFiControllerRequest.java:104) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.api.UniFiController.executeRequest(UniFiController.java:113) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.api.UniFiController.login(UniFiController.java:70) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.api.UniFiController.start(UniFiController.java:56) ~[190:org.openhab.binding.unifi:2.4.0.201812080707]
	at org.openhab.binding.unifi.internal.handler.UniFiControllerThingHandler.initialize(UniFiControllerThingHandler.java:120) [190:org.openhab.binding.unifi:2.4.0.201812080707]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.201812032218]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.201812032218]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.RuntimeException: Delegated task threw Exception/Error
	at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1519) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:528) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:802) ~[?:?]
	at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:766) ~[?:?]
	at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:681) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:128) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:155) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:291) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:151) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) ~[?:?]
	... 1 more
Caused by: java.lang.NullPointerException
	at org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager.getLinkedTrustMananger(ExtensibleTrustManager.java:135) ~[?:?]
	at org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager.checkServerTrusted(ExtensibleTrustManager.java:112) ~[?:?]
	at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1626) ~[?:?]
	at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:223) ~[?:?]
	at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1037) ~[?:?]
	at sun.security.ssl.Handshaker$1.run(Handshaker.java:970) ~[?:?]
	at sun.security.ssl.Handshaker$1.run(Handshaker.java:967) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1459) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:775) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:128) ~[?:?]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
	at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:155) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:291) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:151) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) ~[?:?]
	... 1 more
2018-12-08 09:20:11.112 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Initializing the UniFi Client Handler with config = UniFiClientConfig{cid: '[redacted]', site: 'default', considerHome: 180}
2018-12-08 09:20:11.114 [DEBUG] [org.openhab.binding.unifi           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=313, service.bundleid=190, service.scope=bundle, component.name=org.openhab.binding.unifi.internal.UniFiThingHandlerFactory, component.id=176} - org.openhab.binding.unifi
2018-12-08 09:20:11.118 [DEBUG] [org.openhab.binding.unifi           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.TlsTrustManagerProvider}={service.id=314, service.bundleid=190, service.scope=bundle, component.name=org.openhab.binding.unifi.internal.ssl.UniFiTrustManagerProvider, component.id=177} - org.openhab.binding.unifi

It looks like the UniFiControllerThingHandler is getting started before the TlsTrustManagerProvider is being registered (notice the ServiceEvent REGISTERED lines at the end)


(Martin van Wingerden) #660

But that does not have to be a problem, it should just retry the connection later, would you be able to implement that?

Or is the common client null when injecting?


(Matthew) #661

It’s the ExtendedTrustManager throwing an NPE

Same setup as above with TRACE enabled for org.eclipse.smarthome.io.net

...
2018-12-08 09:41:34.618 [TRACE] [http.internal.ExtensibleTrustManager] - Searching trustManager by Subject Alternative Names: null
...
Caused by: java.lang.NullPointerException
	at org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager.getLinkedTrustMananger(ExtensibleTrustManager.java:135) ~[?:?]

...

You’re calling .stream() on NULL

Edit: looking through the ExtensibleTrustManager code again, I believe it confirms my suspicions of the TlsTrustManagerProvider being registered after because the branch a few lines above the NPE should of been taken:


(Matthew) #662

@Dim try build #84

You should be back in business as I reverted to using an internal HttpClient instance


(Martin van Wingerden) #663

@roryd Could you share the certificate with us (maybe a private message to me or @mgbowman)

@mgbowman indeed, thanks! Because the common name was not supported it started searching for the subject alternative names, I will create a PR to make that more resilient.


(Matthew) #664

So I had a :bulb: moment!

If I make UniFiThingHandlerFactory implement both ThingHandlerFactory and TlsTrustManagerProvider (vs. making it a separate component), I believe it forces the ExtendedTrustManager to be initialized first:

2018-12-08 10:02:27.090 [DEBUG] [org.openhab.binding.unifi           ] - BundleEvent INSTALLED - org.openhab.binding.unifi
2018-12-08 10:02:32.230 [DEBUG] [org.openhab.binding.unifi           ] - BundleEvent RESOLVED - org.openhab.binding.unifi
2018-12-08 10:02:32.232 [DEBUG] [org.openhab.binding.unifi           ] - BundleEvent STARTING - org.openhab.binding.unifi
2018-12-08 10:02:32.243 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
2018-12-08 10:02:32.244 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@23e77111
2018-12-08 10:02:32.248 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared http client created
2018-12-08 10:02:32.249 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating web socket client for consumer common, endpoint null
2018-12-08 10:02:32.253 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@23e77111
2018-12-08 10:02:32.263 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared web socket client created
2018-12-08 10:02:32.264 [DEBUG] [t.http.internal.WebClientFactoryImpl] - shared http client requested
2018-12-08 10:02:32.265 [DEBUG] [org.openhab.binding.unifi           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory, org.eclipse.smarthome.io.net.http.TlsTrustManagerProvider}={service.id=313, service.bundleid=190, service.scope=bundle, component.name=org.openhab.binding.unifi.internal.UniFiThingHandlerFactory, component.id=176} - org.openhab.binding.unifi
2018-12-08 10:02:32.269 [DEBUG] [org.openhab.binding.unifi           ] - BundleEvent STARTED - org.openhab.binding.unifi
2018-12-08 10:02:32.318 [DEBUG] [.handler.UniFiControllerThingHandler] - Initializing the UniFi Controller Handler with config = UniFiControllerConfig{host = unifi, port = 8443, username = operator, password = *****, refresh = 10}
2018-12-08 10:02:32.443 [TRACE] [http.internal.ExtensibleTrustManager] - Found trustManager by common name: UniFi

(Angelos) #665

Logs are clean but I need to double check why my Items are not getting updates…

OH 2.4.0.S1454
Unifi Controller: 5.6.40
binding.unifi: 2.4.0.201812080737

2018-12-08 09:59:25.492 [DEBUG] [.handler.UniFiControllerThingHandler] - Found client 'mac:04:d6:aa:87:4c:25' = UniFiClient{mac: '04:d6:aa:87:4c:25', ip: '172.16.13.75', hostname: 'galaxy-s8', alias: 'galaxy-s8', wired: false, device: UniFiDevice{mac: '44:d9:e7:fc:d5:9f', name: 'AP-AC-LR 1', model: 'U7LR', site: UniFiSite{name: 'default', desc: 'Default'}}}
2018-12-08 09:59:25.492 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:online
2018-12-08 09:59:25.492 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:site
2018-12-08 09:59:25.493 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:macAddress
2018-12-08 09:59:25.493 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:ipAddress
2018-12-08 09:59:25.493 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:uptime
2018-12-08 09:59:25.494 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:lastSeen
2018-12-08 09:59:25.494 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:ap
2018-12-08 09:59:25.494 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:essid
2018-12-08 09:59:25.494 [DEBUG] [rnal.handler.UniFiClientThingHandler] - Refreshing channel = unifi:wirelessClient:Unifi_HomeR:Angelos_S8:rssi
openhab> items list |grep Angelos
Angelos_S8_PRES (Type=SwitchItem, State=ON, Label=Angelos S8 Presence, Category=switch, Groups=[gUnifi])
Angelos_S8_UPTF (Type=StringItem, State=106266, Label=Angelos S8 Uptime F, Category=time, Groups=[gUnifi])
Angelos_S8_RSSI (Type=NumberItem, State=28, Label=Angelos S8 RSSI, Category=qualityofservice, Groups=[gUnifi])
Angelos_S8_UPTM (Type=NumberItem, State=106266, Label=Angelos S8 Uptime, Category=time, Groups=[gUnifi])
Angelos_S8_TIME (Type=DateTimeItem, State=2018-12-06T21:12:53.000+0200, Label=Angelos S8 Last Seen, Category=time, Groups=[gUnifi])
Angelos_S8_AP (Type=StringItem, State=AP-AC-LR 2, Label=Angelos S8 AP, Category=qualityofservice, Groups=[gUnifi])

For example: AP Association is currently at AP-AC-LR 1 but my Angelos_S8_AP Item state stays at AP-AC-LR 2 even though logs show:

2018-12-08 09:59:25.492 [DEBUG] [.handler.UniFiControllerThingHandler] - Found client 'mac:04:d6:aa:87:4c:25' = UniFiClient{mac: '04:d6:aa:87:4c:25', ip: '172.16.13.75', hostname: 'galaxy-s8', alias: 'galaxy-s8', wired: false, device: UniFiDevice{mac: '44:d9:e7:fc:d5:9f', name: 'AP-AC-LR 1', model: 'U7LR', site: UniFiSite{name: 'default', desc: 'Default'}}}
String		Angelos_S8_AP	"Angelos S8 AP [%s]"				<qualityofservice>	(gUnifi)	{channel="unifi:client:Unifi_HomeR:Angelos_S8:ap"}
Thing	wirelessClient	Angelos_S8	"Angelos_S8" @ "Unifi"	[ cid="04:d6:aa:87:4c:25", site="default", considerHome=180 ]