GlobalCache Binding Error - Upgrade from openhab 3.2 to 3.4.2

irulewellswood · March 13, 2023, 2:57pm

I’ve upgraded to openhab 3.4.2 from 3.2 (using openhabian). However none of my GlobalCache device ‘things’ will now initialise. I get a ‘HANDLER INITIALIZING ERROR’ message and the following in my log file. Unfortunately it now means that I can’t control the various devices. Does anyone know if this a known problem with the binding (I searched but couldn’t find any) or any pointers as to where I can look further to investigate?

2023-03-13 14:32:56.801 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'globalcache:itachIR:iTach-IRA': null
java.lang.NullPointerException: null
	at org.openhab.binding.globalcache.internal.handler.GlobalCacheHandler.initialize(GlobalCacheHandler.java:109) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2023-03-13 14:36:28.758 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.globalcache.internal.handler.GlobalCacheHandler@1631788': null
java.lang.NullPointerException: null
	at org.openhab.binding.globalcache.internal.handler.GlobalCacheHandler.initialize(GlobalCacheHandler.java:109) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

Thanks
Martin

morph166955 · March 13, 2023, 3:31pm

You may want to clear your cache and try a restart. I use GC on 3.4 and 4.0 with no issues.

irulewellswood · March 13, 2023, 3:35pm

Thanks. It has me perplexed - I tried the clear cache and restart but to not avail… If you have it working at least there’s hope for me!

mhilbush · March 13, 2023, 3:37pm

It must be dying (NPE) when it tries to get the name of the network interface to which the GC device’s IP address is associated. That’s very odd because I’ve never heard of that happening.

I’m not sure what, if anything, changed between 3.4.0 and 3.4.2 that would cause this.

github.com

openhab/openhab-addons/blob/3.4.x/bundles/org.openhab.binding.globalcache/src/main/java/org/openhab/binding/globalcache/internal/handler/GlobalCacheHandler.java#L109


      
              this.ipv4Address = ipv4Address;
              this.bundleContext = FrameworkUtil.getBundle(GlobalCacheHandler.class).getBundleContext();
          }
          
          
@Override
          public void initialize() {
              logger.debug("Initializing thing {}", thingID());
              try {
                  ifAddress = InetAddress.getByName(ipv4Address);
                  logger.debug("Handler using address {} on network interface {}", ifAddress.getHostAddress(),
                          NetworkInterface.getByInetAddress(ifAddress).getName());
              } catch (SocketException e) {
                  logger.error("Handler got Socket exception creating multicast socket: {}", e.getMessage());
                  markThingOfflineWithError(ThingStatusDetail.OFFLINE.CONFIGURATION_ERROR, "No suitable network interface");
                  return;
              } catch (UnknownHostException e) {
                  logger.error("Handler got UnknownHostException getting local IPv4 network interface: {}", e.getMessage());
                  markThingOfflineWithError(ThingStatusDetail.OFFLINE.CONFIGURATION_ERROR, "No suitable network interface");
                  return;
              }
              scheduledFuture = scheduledExecutorService.schedule(commandProcessor, 2, TimeUnit.SECONDS);

mhilbush · March 13, 2023, 4:54pm

As there are several bindings that do this, I could submit a fix to check for null, or I could remove it completely. But I’m still confused why this would start happening all of a sudden simply by upgrading from 3.4.0 to 3.4.2.

irulewellswood · March 13, 2023, 10:03pm

Thanks for looking at this - much appreciated. It’s rather perplexing to me: despite clearing the cache and and doing a power down (and up) of the Pi I still had a problem. Taking on Mark’s pointer about the network I’ve eventually got things running - it took a power cycle my router and network switch…(which had been up and running for months). So something network related but no idea what… well beyond my limited knowledge.

mhilbush · March 14, 2023, 11:52am

Glad you got it working. That’s really strange.

I might submit a fix to prevent the error from occurring.

irulewellswood · March 17, 2023, 11:09am

All seems to be fine working these last few days. Although I still get these messages appearing at seemingly random frequency in the log. I don’t recall seeing these with OH 3.2

2023-03-17 10:29:56.634 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachIR:iTach-IRA at 192.168.1.21: Socket closed
2023-03-17 10:29:56.724 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachIR:iTach-IRE at 192.168.1.27: Socket closed
2023-03-17 10:29:56.750 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachSL:iTach-SLB at 192.168.1.26: Socket closed
2023-03-17 10:29:56.751 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachIR:iTach-IRD at 192.168.1.28: Socket closed
2023-03-17 10:29:56.754 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachSL:iTach-SLA at 192.168.1.23: Socket closed
2023-03-17 10:30:56.637 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachIR:iTach-IRA at 192.168.1.21
2023-03-17 10:30:56.725 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachIR:iTach-IRE at 192.168.1.27
2023-03-17 10:30:56.751 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachIR:iTach-IRD at 192.168.1.28
2023-03-17 10:30:56.753 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachSL:iTach-SLB at 192.168.1.26
2023-03-17 10:30:56.756 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachSL:iTach-SLA at 192.168.1.23
2023-03-17 10:30:56.756 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to serial-1 port for thing itachSL:iTach-SLB at 192.168.1.26
2023-03-17 10:30:56.762 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to serial-1 port for thing itachSL:iTach-SLA at 192.168.1.23

It’s not affecting me at the moment, but I offer it to complete the observation.

morph166955 · March 17, 2023, 3:15pm

That’s weird for them all to crash in the same second. Any chance of LAN issues?

mhilbush · March 18, 2023, 11:47am

I agree with @morph166955. It seems like there’s something going on at the networking level that would cause all the connections to drop at the same time. That problem, and the other problem where the binding was unable to get the network interface, suggests to me that something network-related is causing the issue.

The binding uses a 60 second reconnect interval. Hence we see all the connections being restored at the same time one minute later. So whatever happened was temporary.

The network interface issue might suggest something local to the openHAB host, since that call (I think) uses the openHAB host’s IP address to find the network interface to which that IP address is bound.

irulewellswood · March 18, 2023, 11:58am

Thanks all. OH seems to been running a lot more slowly today so I’ve run a reboot of the network router and switches - so we’ll see what that does.

irulewellswood · March 20, 2023, 9:13pm

Well all seemed to be fine for 2 days until this evening,. Then the GC things went off line and steadfastly refuse to start. I restarted openhab - all Ok for a little while and then hit the same issue - bindings started, commands sent OK and then all of a sudden all go off-line again. I’m really at a loss as to where to look next. Everything else on the network is running (or appears to run) just fine. They have static IP addresses, DHC allocates addresses above .100 (been like that for years…) . Nothing has been added to the network recently (as far as I’m aware…)
I turned on DEBUG and restarted the binding. That produces this output:

2023-03-20 20:50:12.548 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:iTach-IRA
2023-03-20 20:50:12.561 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRA is being marked ready to terminate.
2023-03-20 20:50:13.712 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRA created request queue, depth=10
2023-03-20 20:50:13.741 [DEBUG] [.internal.handler.GlobalCacheHandler] - Initializing thing itachIR:iTach-IRA
2023-03-20 20:51:41.016 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Querying state active
2023-03-20 20:51:41.017 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Deactivating component
2023-03-20 20:51:41.019 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : registration change queue [unregistered]
2023-03-20 20:51:41.030 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachSL:iTach-SLA
2023-03-20 20:51:41.031 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachSL:iTach-SLA is being marked ready to terminate.
2023-03-20 20:51:41.043 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:000C1E0381F7
2023-03-20 20:51:41.044 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:000C1E0381F7 is being marked ready to terminate.
2023-03-20 20:51:41.054 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachSL:000C1E02823A
2023-03-20 20:51:41.056 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachSL:000C1E02823A is being marked ready to terminate.
2023-03-20 20:51:41.068 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:000C1E028BBF
2023-03-20 20:51:41.069 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:000C1E028BBF is being marked ready to terminate.
2023-03-20 20:51:41.085 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:iTach-IRD
2023-03-20 20:51:41.086 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRD is being marked ready to terminate.
2023-03-20 20:51:41.097 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachSL:000C1E0355A6
2023-03-20 20:51:41.099 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachSL:000C1E0355A6 is being marked ready to terminate.
2023-03-20 20:51:41.110 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:000C1E04C1B9
2023-03-20 20:51:41.111 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:000C1E04C1B9 is being marked ready to terminate.
2023-03-20 20:51:41.121 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:iTach-IRE
2023-03-20 20:51:41.122 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRE is being marked ready to terminate.
2023-03-20 20:51:41.140 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:iTach-IRC
2023-03-20 20:51:41.142 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRC is being marked ready to terminate.
2023-03-20 20:51:41.158 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:iTach-IRA
2023-03-20 20:51:41.160 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:iTach-IRA is being marked ready to terminate.
2023-03-20 20:51:41.180 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachIR:000C1E031D3E
2023-03-20 20:51:41.181 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:000C1E031D3E is being marked ready to terminate.
2023-03-20 20:51:41.195 [DEBUG] [.internal.handler.GlobalCacheHandler] - Disposing thing itachSL:iTach-SLB
2023-03-20 20:51:41.197 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachSL:iTach-SLB is being marked ready to terminate.
2023-03-20 20:51:41.204 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Querying state active
2023-03-20 20:51:41.206 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : getting deactivate: deactivate
2023-03-20 20:51:41.208 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Locating method deactivate in class org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory
2023-03-20 20:51:41.210 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Declared Method org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-20 20:51:41.212 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Locating method deactivate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2023-03-20 20:51:41.214 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Found deactivate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.deactivate(org.osgi.service.component.ComponentContext)
2023-03-20 20:51:41.216 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : invoking deactivate: deactivate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2023-03-20 20:51:41.244 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : invoked deactivate: deactivate
2023-03-20 20:51:41.248 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : DependencyManager: $000 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@e97401 at tracking count 1 refpairs: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54}] service: [org.openhab.core.net.NetUtil@156817b]]]
2023-03-20 20:51:41.249 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2023-03-20 20:51:41.251 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Changed state from active to satisfied
2023-03-20 20:51:41.253 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Deactivating dependency managers
2023-03-20 20:51:41.255 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Disabling dependency managers
2023-03-20 20:51:41.259 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : unregistering service listener for dependency $000
2023-03-20 20:51:41.261 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Querying state satisfied
2023-03-20 20:51:41.262 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Changed state from satisfied to disposed
2023-03-20 20:51:41.263 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(378)] : Disposing component (reason: 6)
2023-03-20 20:51:41.265 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Querying state active
2023-03-20 20:51:41.267 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Deactivating component
2023-03-20 20:51:41.268 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : registration change queue [unregistered]
2023-03-20 20:51:41.273 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Querying state active
2023-03-20 20:51:41.275 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : getting deactivate: deactivate
2023-03-20 20:51:41.276 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Locating method deactivate in class org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.277 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-20 20:51:41.279 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Found deactivate method: protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.deactivate()
2023-03-20 20:51:41.280 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : invoking deactivate: deactivate: parameters []
2023-03-20 20:51:41.282 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - Globalcache discovery service deactivated
2023-03-20 20:51:41.284 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - Canceling background discovery job
2023-03-20 20:51:41.285 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : invoked deactivate: deactivate
2023-03-20 20:51:41.286 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : DependencyManager: NetworkAddressService close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@90e542 at tracking count 1 refpairs: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54}] service: [org.openhab.core.net.NetUtil@156817b]]]
2023-03-20 20:51:41.288 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : getting unbind: unsetNetworkAddressService
2023-03-20 20:51:41.289 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Locating method unsetNetworkAddressService in class org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.290 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : doFindMethod: Looking for method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.unsetNetworkAddressService
2023-03-20 20:51:41.291 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.unsetNetworkAddressService([interface org.osgi.framework.ServiceReference]) not found
2023-03-20 20:51:41.293 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.unsetNetworkAddressService([interface org.osgi.service.component.ComponentServiceObjects]) not found
2023-03-20 20:51:41.294 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : getReferenceClass: Looking for interface class org.openhab.core.net.NetworkAddressService through loader of org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.295 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : getParameterClass: Found class org.openhab.core.net.NetworkAddressService
2023-03-20 20:51:41.297 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.net.NetworkAddressService
2023-03-20 20:51:41.298 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : doFindMethod: Found Method protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.unsetNetworkAddressService(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.299 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Found unbind method: protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.unsetNetworkAddressService(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.300 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : invoking unbind: unsetNetworkAddressService: parameters [org.openhab.core.net.NetUtil]
2023-03-20 20:51:41.302 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : invoked unbind: unsetNetworkAddressService
2023-03-20 20:51:41.303 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2023-03-20 20:51:41.304 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Changed state from active to satisfied
2023-03-20 20:51:41.306 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Deactivating dependency managers
2023-03-20 20:51:41.307 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Disabling dependency managers
2023-03-20 20:51:41.310 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : unregistering service listener for dependency NetworkAddressService
2023-03-20 20:51:41.311 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Querying state satisfied
2023-03-20 20:51:41.312 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Changed state from satisfied to disposed
2023-03-20 20:51:41.314 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(379)] : Disposing component (reason: 6)
2023-03-20 20:51:41.358 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2023-03-20 20:51:41.364 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : BundleComponentActivator : ComponentHolder created.
2023-03-20 20:51:41.372 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.net.NetworkAddressService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2023-03-20 20:51:41.374 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.globalcache]
2023-03-20 20:51:41.376 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2023-03-20 20:51:41.377 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Component Properties: {}
2023-03-20 20:51:41.379 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Querying state disabled
2023-03-20 20:51:41.380 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Querying state disabled
2023-03-20 20:51:41.382 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Component can not be activated since it is in state disabled
2023-03-20 20:51:41.383 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory] : Querying state disabled
2023-03-20 20:51:41.385 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Updating target filters
2023-03-20 20:51:41.387 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : No change in target property for dependency $000: currently registered: false
2023-03-20 20:51:41.389 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] :  No existing service listener to unregister for dependency $000
2023-03-20 20:51:41.390 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Setting target property for dependency $000 to null
2023-03-20 20:51:41.391 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.net.NetworkAddressService), initialReferenceFilter (objectClass=org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.393 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : dm $000 tracker reset (closed)
2023-03-20 20:51:41.397 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54} (enter)
2023-03-20 20:51:41.399 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2023-03-20 20:51:41.400 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54} (exit)
2023-03-20 20:51:41.402 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : dm $000 tracker opened
2023-03-20 20:51:41.403 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : registering service listener for dependency $000
2023-03-20 20:51:41.404 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Changed state from disabled to unsatisfiedReference
2023-03-20 20:51:41.406 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Component enabled
2023-03-20 20:51:41.407 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : ActivateInternal
2023-03-20 20:51:41.408 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.410 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.411 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Activating component from state unsatisfiedReference
2023-03-20 20:51:41.413 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.414 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.416 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Changed state from unsatisfiedReference to satisfied
2023-03-20 20:51:41.417 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : registration change queue [registered]
2023-03-20 20:51:41.421 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Checking constructor public org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.423 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : getReferenceClass: Looking for interface class org.openhab.core.net.NetworkAddressService through loader of org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory
2023-03-20 20:51:41.424 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : getParameterClass: Found class org.openhab.core.net.NetworkAddressService
2023-03-20 20:51:41.425 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Found constructor with 1 arguments : public org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.427 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : This thread collected dependencies
2023-03-20 20:51:41.428 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : getService (single component manager) dependencies collected.
2023-03-20 20:51:41.429 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state satisfied
2023-03-20 20:51:41.430 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Querying state satisfied
2023-03-20 20:51:41.432 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54}] service: [null]]]
2023-03-20 20:51:41.434 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : getting activate: activate
2023-03-20 20:51:41.436 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Locating method activate in class org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory
2023-03-20 20:51:41.437 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Declared Method org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-20 20:51:41.438 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2023-03-20 20:51:41.440 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2023-03-20 20:51:41.441 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2023-03-20 20:51:41.443 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : invoked activate: activate
2023-03-20 20:51:41.445 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Set implementation object for component
2023-03-20 20:51:41.446 [DEBUG] [e.internal.GlobalCacheHandlerFactory] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.GlobalCacheHandlerFactory(380)] : Changed state from satisfied to active
2023-03-20 20:51:41.450 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Dependency Manager created NetworkAddressServiceinterface=org.openhab.core.net.NetworkAddressService, filter=null, policy=static, cardinality=1..1, bind=setNetworkAddressService, unbind=unsetNetworkAddressService, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2023-03-20 20:51:41.452 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Component created: DS=DS13, implementation=org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=modified configuration-pid=[discovery.globalcache]
2023-03-20 20:51:41.453 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Component Services: scope=singleton, services=[org.openhab.core.config.discovery.DiscoveryService]
2023-03-20 20:51:41.454 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Component Properties: {}
2023-03-20 20:51:41.456 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Querying state disabled
2023-03-20 20:51:41.457 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Querying state disabled
2023-03-20 20:51:41.458 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Component can not be activated since it is in state disabled
2023-03-20 20:51:41.460 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService] : Querying state disabled
2023-03-20 20:51:41.461 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Updating target filters
2023-03-20 20:51:41.463 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : No change in target property for dependency NetworkAddressService: currently registered: false
2023-03-20 20:51:41.464 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] :  No existing service listener to unregister for dependency NetworkAddressService
2023-03-20 20:51:41.465 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Setting target property for dependency NetworkAddressService to null
2023-03-20 20:51:41.467 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : New service tracker for NetworkAddressService, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.net.NetworkAddressService), initialReferenceFilter (objectClass=org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.468 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : dm NetworkAddressService tracker reset (closed)
2023-03-20 20:51:41.472 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : dm NetworkAddressService tracking 1 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54} (enter)
2023-03-20 20:51:41.474 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : dm NetworkAddressService tracking 1 SingleStatic active: false trackerOpened: false optional: false
2023-03-20 20:51:41.475 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : dm NetworkAddressService tracking 1 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54} (exit)
2023-03-20 20:51:41.477 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : dm NetworkAddressService tracker opened
2023-03-20 20:51:41.478 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : registering service listener for dependency NetworkAddressService
2023-03-20 20:51:41.480 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Changed state from disabled to unsatisfiedReference
2023-03-20 20:51:41.481 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Component enabled
2023-03-20 20:51:41.483 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : ActivateInternal
2023-03-20 20:51:41.484 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.485 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.487 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Activating component from state unsatisfiedReference
2023-03-20 20:51:41.488 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.489 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state unsatisfiedReference
2023-03-20 20:51:41.491 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Changed state from unsatisfiedReference to satisfied
2023-03-20 20:51:41.493 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : registration change queue [registered]
2023-03-20 20:51:41.496 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Checking constructor public org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService()
2023-03-20 20:51:41.497 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Found constructor with 0 arguments : public org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService()
2023-03-20 20:51:41.498 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : getting bind: setNetworkAddressService
2023-03-20 20:51:41.499 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Locating method setNetworkAddressService in class org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.501 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : doFindMethod: Looking for method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.setNetworkAddressService
2023-03-20 20:51:41.503 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.setNetworkAddressService([interface org.osgi.framework.ServiceReference]) not found
2023-03-20 20:51:41.505 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.setNetworkAddressService([interface org.osgi.service.component.ComponentServiceObjects]) not found
2023-03-20 20:51:41.506 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : getReferenceClass: Looking for interface class org.openhab.core.net.NetworkAddressService through loader of org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.507 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : getParameterClass: Found class org.openhab.core.net.NetworkAddressService
2023-03-20 20:51:41.508 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.net.NetworkAddressService
2023-03-20 20:51:41.509 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : doFindMethod: Found Method protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.setNetworkAddressService(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.511 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Found bind method: protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.setNetworkAddressService(org.openhab.core.net.NetworkAddressService)
2023-03-20 20:51:41.512 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : This thread collected dependencies
2023-03-20 20:51:41.513 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : getService (single component manager) dependencies collected.
2023-03-20 20:51:41.514 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state satisfied
2023-03-20 20:51:41.516 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Querying state satisfied
2023-03-20 20:51:41.517 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : For dependency NetworkAddressService, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=2029, service.bundleid=149, service.scope=bundle, service.config.category=system, service.pid=org.openhab.network, service.config.label=Network Settings, component.name=org.openhab.core.net.NetUtil, service.config.description.uri=system:network, component.id=54}] service: [org.openhab.core.net.NetUtil@156817b]]]
2023-03-20 20:51:41.519 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : invoking bind: setNetworkAddressService: parameters [org.openhab.core.net.NetUtil]
2023-03-20 20:51:41.521 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : invoked bind: setNetworkAddressService
2023-03-20 20:51:41.522 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : getting activate: activate
2023-03-20 20:51:41.523 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Locating method activate in class org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService
2023-03-20 20:51:41.524 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Declared Method org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.activate([interface org.osgi.service.component.ComponentContext]) not found
2023-03-20 20:51:41.526 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Found activate method: protected void org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService.activate(java.util.Map)
2023-03-20 20:51:41.527 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.helper.ReadOnlyDictionary]
2023-03-20 20:51:41.529 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - Globalcache discovery service activated
2023-03-20 20:51:41.530 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - Starting background discovery job in 10 seconds
2023-03-20 20:51:41.531 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : invoked activate: activate
2023-03-20 20:51:41.533 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Set implementation object for component
2023-03-20 20:51:41.534 [DEBUG] [iscovery.GlobalCacheDiscoveryService] - bundle org.openhab.binding.globalcache:3.4.2 (263)[org.openhab.binding.globalcache.internal.discovery.GlobalCacheDiscoveryService(381)] : Changed state from satisfied to active
2023-03-20 20:51:41.601 [DEBUG] [.GlobalCacheHandler$CommandProcessor] - Processor for thing itachIR:000C1E031D3E created request queue, depth=10
2023-03-20 20:51:41.611 [DEBUG] [.internal.handler.GlobalCacheHandler] - Initializing thing itachIR:000C1E031D3E
2023-03-20 20:51:41.612 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.globalcache.internal.handler.Globa>
java.lang.NullPointerException: null
        at org.openhab.binding.globalcache.internal.handler.GlobalCacheHandler.initialize(GlobalCacheHandler.java:109) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor280.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-03-20 20:51:41.616 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'globalcache:itachIR:000C1E031D3E': null
java.lang.NullPointerException: null
        at org.openhab.binding.globalcache.internal.handler.GlobalCacheHandler.initialize(GlobalCacheHandler.java:109) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor280.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]        at java.lang.Thread.run(Thread.java:829) [?:?]

Unfortunately those logs don’t mean too much to me, other than things aren’t initialising.
So I’d be grateful for any more pointers, if anyone has any.
Thanks

irulewellswood · March 22, 2023, 8:17pm

Progress it seems! As per the advice, it looks like it’s network related. I rebooted, activated the Global Cache Things systematically, one by one, and it all fell over when I activated one of the serial devices. Repeated the process a few times and eventually when I resorted to changing the network cable to the device - it looked successful. Nothing has been changed in that area for the last few years so I guess it’s one of those things…
Thanks you for the pointers. A frustrating few days but seems OK now.