Zwave random delays

MrBov · May 25, 2021, 7:08pm

After struggling with log file issues and other stuff, I’m now trying to get my zwave network working reliably… done a bunch of searching but still not finding some answers… any pointers and assistance from the experts would be very much welcome…

I’m on the latest stable OpenHABian and OH3 build running on a Pi4 with a Aeotec z-stick, via USB hub (I’m learning )

My setup has not changed for some time now, but after the last update I’m finding things really unreliable… I have had days with nothing working, then it starts for a bit. Rebooting the Pi sometimes solves it. Sometimes it works but with 5-10 second delay. Trying to fit in a bit of debug…

So, to the logs… I have turned on full logging… but cannot see any clear errors… but I am now seeing some warnings and a few strange messages…

openhab.log has the following warnings…

2021-05-25 17:51:37.600 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'amazonechocontrol.things'
2021-05-25 17:51:37.658 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'amazonechocontrol.things' has errors, therefore ignoring it: [3,5]: missing '}' at 'Thing'
[10,1]: extraneous input '}' expecting EOF

and…

2021-05-25 17:51:57.589 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://192.168.1.222:80/description.xml}WebClient has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67) ~[bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.AbstractClient.doRunInterceptorChain(AbstractClient.java:705) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doChainedInvocation(WebClient.java:1081) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:927) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:896) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.invoke(WebClient.java:461) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:135) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:130) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.get(SyncInvokerImpl.java:50) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.spec.InvocationBuilderImpl.get(InvocationBuilderImpl.java:88) [bundleFile:1.0.9]
        at org.openhab.io.hueemulation.internal.upnp.UpnpServer.performAddressTest(UpnpServer.java:252) [bundleFile:?]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) [?:?]
        at java.util.concurrent.CompletableFuture$Completion.exec(CompletableFuture.java:479) [?:?]
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) [?:?]
        at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) [?:?]
        at java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) [?:?]
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) [?:?]
        at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) [?:?]
Caused by: java.net.ConnectException: ConnectException invoking http://192.168.1.222:80/description.xml: Connection refused (Connection refused)
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:1402) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1386) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[?:?]
        at java.net.Socket.connect(Socket.java:609) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:177) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:474) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:569) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:341) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:362) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1253) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1232) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1081) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:1015) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1592) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1520) ~[?:?]
        at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:377) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.getResponseCode(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.doProcessResponseCode(HTTPConduit.java:1599) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1627) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1572) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1373) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more
2021-05-25 17:51:57.640 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2021-05-25 17:51:57.871 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://192.168.1.222/description.xml}WebClient has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67) ~[bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.AbstractClient.doRunInterceptorChain(AbstractClient.java:705) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doChainedInvocation(WebClient.java:1081) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:927) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:896) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.invoke(WebClient.java:461) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:135) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:130) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.get(SyncInvokerImpl.java:50) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.spec.InvocationBuilderImpl.get(InvocationBuilderImpl.java:88) [bundleFile:1.0.9]
        at org.openhab.io.hueemulation.internal.upnp.UpnpServer.performAddressTest(UpnpServer.java:280) [bundleFile:?]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) [?:?]
        at java.util.concurrent.CompletableFuture$Completion.exec(CompletableFuture.java:479) [?:?]
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) [?:?]
        at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) [?:?]
        at java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) [?:?]
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) [?:?]
        at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) [?:?]
Caused by: java.net.ConnectException: ConnectException invoking http://192.168.1.222/description.xml: Connection refused (Connection refused)
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:1402) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1386) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[?:?]
        at java.net.Socket.connect(Socket.java:609) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:177) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:474) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:569) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:341) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:362) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1253) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1232) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1081) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:1015) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1592) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1520) ~[?:?]
        at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:377) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.getResponseCode(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.doProcessResponseCode(HTTPConduit.java:1599) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1627) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1572) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1373) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more
2021-05-25 17:51:58.105 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://[fe80:0:0:0:60e9:31a8:3a0d:a63c]/description.xml}WebClient has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67) ~[bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.AbstractClient.doRunInterceptorChain(AbstractClient.java:705) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doChainedInvocation(WebClient.java:1081) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:927) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:896) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.WebClient.invoke(WebClient.java:461) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:135) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.method(SyncInvokerImpl.java:130) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.SyncInvokerImpl.get(SyncInvokerImpl.java:50) [bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.client.spec.InvocationBuilderImpl.get(InvocationBuilderImpl.java:88) [bundleFile:1.0.9]
        at org.openhab.io.hueemulation.internal.upnp.UpnpServer.performAddressTest(UpnpServer.java:280) [bundleFile:?]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) [?:?]
        at java.util.concurrent.CompletableFuture$Completion.exec(CompletableFuture.java:479) [?:?]
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) [?:?]
        at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) [?:?]
        at java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) [?:?]
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) [?:?]
        at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) [?:?]
Caused by: java.net.ConnectException: ConnectException invoking http://[fe80:0:0:0:60e9:31a8:3a0d:a63c]/description.xml: Connection refused (Connection refused)
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:1402) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1386) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[?:?]
        at java.net.Socket.connect(Socket.java:609) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:177) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:474) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:569) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:341) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:362) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1253) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1232) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1081) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:1015) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1592) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1520) ~[?:?]
        at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:377) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.getResponseCode(URLConnectionHTTPConduit.java:373) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.doProcessResponseCode(HTTPConduit.java:1599) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1627) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1572) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1373) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.close(AbstractWrappedOutputStream.java:77) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56) ~[bundleFile:1.0.9]
        at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:673) ~[bundleFile:1.0.9]
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63) ~[bundleFile:1.0.9]
        ... 18 more

and…

> 2021-05-25 19:38:13.666 [WARN ] [apache.cxf.jaxrs.utils.ResourceUtils] - No resource methods have been found for resource class javax.ws.rs.core.Response

And my events.log has a few things I don’t recognize from previous debugging… lots of “changed from ONLINE” with “Node initializing: REQUEST_NIF to ONLINE” and “Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF”.

2021-05-25 18:54:19.304 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Livingroomtable_DimmerSwitch1' changed from 0 to 100
2021-05-25 18:54:30.340 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node82' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:31.422 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node65' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:32.186 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node2' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:32.439 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node46' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:32.994 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Livingroomedge_DimmerSwitch1' changed from 0 to 100
2021-05-25 18:54:33.278 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node38' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:33.411 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'zwave_sensor_3_b' changed from OFF to ON
2021-05-25 18:54:33.414 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Sensor3_BinarySensor2' changed from OFF to ON
2021-05-25 18:54:33.431 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node46' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:33.559 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node64' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:33.782 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node41' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:41.341 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node64' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:42.057 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node70' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:42.463 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BreakfastTable_DimmerSwitch1' changed from 100 to 0
2021-05-25 18:54:43.429 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node41' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:43.939 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node37' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:48.359 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Livingroomsofaspot_DimmerSwitch1' changed from 0 to 100
2021-05-25 18:54:48.700 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node70' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:48.824 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node37' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:54:48.898 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node80' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:48.923 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node7' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:54:55.938 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CurrentTime' changed from 2021-05-25T18:53:55.934+0100 to 2021-05-25T18:54:55.936+0100
2021-05-25 18:55:12.814 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node47' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:55:13.623 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node7' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:13.785 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node47' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:19.035 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node8' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:55:19.067 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node22' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:55:27.166 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'zwave_lights_sunroom_lamp' changed from 0 to 40
2021-05-25 18:55:27.169 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'gAllSunroomLights' changed from 0 to UNDEF through zwave_lights_sunroom_lamp
2021-05-25 18:55:27.502 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node8' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:27.653 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node12' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:55:27.727 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node22' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:28.141 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node28' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:55:40.592 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node12' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:45.713 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node28' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:55:55.939 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CurrentTime' changed from 2021-05-25T18:54:55.936+0100 to 2021-05-25T18:55:55.937+0100
2021-05-25 18:55:59.167 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node57' changed from ONLINE: Node initialising: PING to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-05-25 18:55:59.492 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node71' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:56:00.236 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node80' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:56:00.315 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node71' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:56:00.336 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node68' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:56:00.384 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node10' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:56:03.579 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node68' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:56:03.698 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node10' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:56:03.761 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node75' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:56:16.268 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node75' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:56:25.135 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node67' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2021-05-25 18:56:55.941 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CurrentTime' changed from 2021-05-25T18:55:55.937+0100 to 2021-05-25T18:56:55.939+0100
2021-05-25 18:57:16.031 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node67' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2021-05-25 18:57:55.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CurrentTime' changed from 2021-05-25T18:56:55.939+0100 to 2021-05-25T18:57:55.940+0100
2021-05-25 18:58:55.944 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CurrentTime' changed from 2021-05-25T18:57:55.940+0100 to 2021-05-25T18:58:55.942+0100
2021-05-25 18:59:12.737 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node43' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE: Node initialising: REQUEST_NIF

Pointers most welcome… Thanks.

apella12 · May 25, 2021, 8:37pm

So not an expert, but it could be that the answer is to fix the problems with the first WARN

amazonechocontrol.things

it’s telling you what it doesn’t like.

Bob

rossko57 · May 25, 2021, 9:15pm

Aside from the Amazon error, zwave has a fair amount going on. But what’s the context here for the log excerpt, soon after bootup, or just during normal activity?

MrBov:

2021-05-25 18:59:12.737 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:9412cbc8:node43' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE: Node initialising: REQUEST_NIF

For this particular entry, you might look back to when this Thing first got into the state (COMMUNICATION_ERROR), see what else was going on.

Andrew_Rowe · May 26, 2021, 12:24am

@stefan.hoehn is your buddy, he just posted a huge thread explaining all how to diagnose zwave issues. Read it, then read it again

anyhow. I’d bet anything you have one (or several) zombie nodes (and I’m not a betting man) always the same… everytime

MrBov · June 1, 2021, 8:04pm

Thanks for the replies all…

Eventually solved the amazonechocontrol.things issue - I was missing the word “Binding” at the front. Adding that and reconnecting my Amazon account seems to have removed all the errors/warnings… fingers crossed see how it goes over the next few days.

I’m still getting a few warnings for:

> 2021-06-01 20:23:24.129 [WARN ] [apache.cxf.jaxrs.utils.ResourceUtils] - No resource methods have been found for resource class javax.ws.rs.core.Response
> 2021-06-01 20:23:24.132 [WARN ] [apache.cxf.jaxrs.utils.ResourceUtils] - No resource methods have been found for resource class javax.ws.rs.core.Response

Any ideas?

Thanks @Andrew_Rowe for that thread I’ll take a look… I agree, I suspect either a zombie or some z-wave comms issues causing blockages…

I did just notice in the openhab log I’m getting

2021-05-31 09:29:22.794 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 25: Not initialized (ie node unknown), ignoring message.

Although that dimmer module shows up fine and seems to work ok now.

I’ll keep working through this… any further ideas or pointers are really most welcome…

Thanks