search

seaside1 / unifiprotect

openHAB UniFi Protect Addon
Eclipse Public License 2.0
23 stars 6 forks source link

G5 Bullet - Binding stops working properly after roughly two hours #23

Closed ErikDB87 closed 2 days ago

ErikDB87 commented 3 months ago

I started the issue because an item linked to the channel is-dark of my G5 Bullet remained NULL, even though it's been night and day several times since creating the item. This is inconvenient, since I want a lamp lit when there's motion when it's dark, but not during the day, obviously.

I later found out that it looks like the binding runs into an issue somewhat two hours after openHAB restart (see below - post of 29/7).

I'm on: Protect version 4.0.33 Unifi OS version 4.0.6 G5 Bullet firmware version 4.71.133 openHAB version 4.2.0

ErikDB87 commented 3 months ago

Coincidentally, I noticed this while starting up openHAB:

15:18:01.605 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: Cannot invoke "org.openhab.binding.unifiprotect.internal.types.UniFiProtectCpuInfo.getAverageLoad()" because the return value of "org.openhab.binding.unifiprotect.internal.types.UniFiProtectSystemInfo.getCpu()" is null
        at org.openhab.binding.unifiprotect.internal.types.UniFiProtectNvrDevice.getCpuAverageLoad(UniFiProtectNvrDevice.java:372) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshChannel(UniFiProtectNvrThingHandler.java:329) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshNvrChannels(UniFiProtectNvrThingHandler.java:234) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refresh(UniFiProtectNvrThingHandler.java:212) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:170) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
        at java.lang.Thread.run(Thread.java:840) [?:?]
ErikDB87 commented 3 months ago

However, is-dark now reports OFF. Is that maybe because of this "californium package" I just installed?

(I coincidentally installed it for another binding; see here and succeeding messages: https://community.openhab.org/t/shelly-binding/56862/3916?u=erikdb.)

I'll check what happens tonight!

ErikDB87 commented 3 months ago

It stays OFF, although it's dark outside. :( The camera also detected movement a few minutes ago, when it was also already dark.

So the problem persists: the channel doesn't do what it's supposed to...

ErikDB87 commented 3 months ago

Maybe the issue is that I chose 'Auto'?

Screenshot_20240714-230846.png

ErikDB87 commented 3 months ago

I'm beginning to assume it now reads OFF because I restarted openHAB and this is the first restart since I made the item. I then also assume that if I restart openHAB NOW, the item will remain ON until a new restart.

ErikDB87 commented 3 months ago

I was wrong, the item was still OFF when I restarted openHAB while it was dark... I'll try to get a full log of the next restart.

ErikDB87 commented 3 months ago

Screenshot_20240715-074701.png

The item is still OFF, so the 'Auto' feature is probably not the culprit...

ErikDB87 commented 3 months ago

This is what logged when restarting openHAB earlier today, with keywoard protect:

2024-07-15 10:42:41.963 [INFO ] [otect.internal.model.UniFiProtectNvr] - Initializing the binding, with config: UniFiProtectNvrThingConfig [host=192.168.1.1, username=openhab,  password=*************, refresh=60, eventsTimePeriodLength=30, thumbnailWidth=640.0, imageFolder=/var/lib/openhab/tmp, g4SnapshotWidth=3840, g4SnapshotHeight=2160, defaultSnapshotWidth=1920, defaultSnapshotHeight=1080, watchDog=true, g4SnapshotWidthAsString=3840, g4SnapshotHeightAsString=2160, defaultSnapshotWidthAsString=1920, defaultSnapshotHeightAsString=1080]  
2024-07-15 10:42:42.986 [ERROR] [al.model.json.UniFiProtectJsonParser] - Failed to parse bootstrap json 
2024-07-15 10:42:42.993 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler UniFiProtectG5CameraThingHandler of thing unifiprotect:g5camera:X1X1X111:X1X1X11111X tried accessing its bridge although the handler was already disposed. 
java.lang.NullPointerException: Cannot invoke "org.openhab.binding.unifiprotect.internal.types.UniFiProtectCpuInfo.getAverageLoad()" because the return value of "org.openhab.binding.unifiprotect.internal.types.UniFiProtectSystemInfo.getCpu()" is null  
    at org.openhab.binding.unifiprotect.internal.types.UniFiProtectNvrDevice.getCpuAverageLoad(UniFiProtectNvrDevice.java:372) ~[?:?]
    at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshChannel(UniFiProtectNvrThingHandler.java:329) ~[?:?]
    at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshNvrChannels(UniFiProtectNvrThingHandler.java:234) ~[?:?]
    at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refresh(UniFiProtectNvrThingHandler.java:212) ~[?:?]
    at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:170) ~[?:?]
ErikDB87 commented 3 months ago

I now noticed is-motion-detected and smart-detect-motion don't work properly either...

ErikDB87 commented 3 months ago

(Copied from the openHAB discussion board: https://community.openhab.org/t/unifi-protect-binding-cloudkey-gen2-dream-machine-pro-nvr/107692/400?u=erikdb)

I restarted openHAB yesterday at 2024-07-27 12:21:27.486.

The Protect binding worked for a while, but at one point (just over two hours later) stopped working. This is what was logged at that moment:

2024-07-27 14:24:47.985 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Request failed reason: EXECUTION_FAULT message: Execution fault when sending request to UniFi Protect
java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
    at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:732) ~[bundleFile:9.4.54.v20240208]
    at org.openhab.binding.unifiprotect.internal.model.request.UniFiProtectRequest.sendRequestGetResponse(UniFiProtectRequest.java:170) ~[bundleFile:?]
    at org.openhab.binding.unifiprotect.internal.model.request.UniFiProtectRequest.sendRequest(UniFiProtectRequest.java:121) ~[bundleFile:?]
    at org.openhab.binding.unifiprotect.internal.model.UniFiProtectNvr.refreshEvents(UniFiProtectNvr.java:190) [bundleFile:?]
    at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.propertyChange(UniFiProtectNvrThingHandler.java:512) [bundleFile:?]
    at java.beans.PropertyChangeSupport.fire(PropertyChangeSupport.java:343) [?:?]
    at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:335) [?:?]
    at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:268) [?:?]
    at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.actionEventDetected(UniFiProtectEventManager.java:97) [bundleFile:?]
    at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.propertyChange(UniFiProtectEventManager.java:70) [bundleFile:?]
    at java.beans.PropertyChangeSupport.fire(PropertyChangeSupport.java:343) [?:?]
    at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:335) [?:?]
    at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:268) [?:?]
    at org.openhab.binding.unifiprotect.websocket.UniFiProtectEventWebSocket.onFrame(UniFiProtectEventWebSocket.java:126) [bundleFile:?]
    at jdk.internal.reflect.GeneratedMethodAccessor49.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
    at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:70) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onFrame(JettyAnnotatedEventDriver.java:210) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:99) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:326) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:202) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:225) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.Parser.parseSingleFrame(Parser.java:259) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:459) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:440) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.54.v20240208]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.54.v20240208]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
    at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:164) ~[?:?]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) ~[?:?]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) ~[?:?]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) ~[?:?]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) ~[?:?]
    at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) ~[?:?]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:374) ~[?:?]
    at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:596) ~[?:?]
    at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1723) ~[?:?]
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1552) ~[?:?]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:208) ~[?:?]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:148) ~[?:?]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
    at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
    at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
    ... 15 more

I then searched the log for WWW-Authenticate, and this was the first time this substring was logged.

There's a lot of logging after that moment (and still going on), but no motion events for example.

I hope this helps? :slight_smile:

By the way, this also turns up in the regular openHAB log after openHAB startup:

13:57:20.226 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: Cannot invoke "org.openhab.binding.unifiprotect.internal.types.UniFiProtectCpuInfo.getAverageLoad()" because the return value of "org.openhab.binding.unifiprotect.internal.types.UniFiProtectSystemInfo.getCpu()" is null
        at org.openhab.binding.unifiprotect.internal.types.UniFiProtectNvrDevice.getCpuAverageLoad(UniFiProtectNvrDevice.java:372) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshChannel(UniFiProtectNvrThingHandler.java:329) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refreshNvrChannels(UniFiProtectNvrThingHandler.java:234) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refresh(UniFiProtectNvrThingHandler.java:212) ~[?:?]
        at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:170) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
        at java.lang.Thread.run(Thread.java:840) [?:?]
seaside1 commented 2 weeks ago

Possible fix: https://github.com/seaside1/unifiprotect/releases/tag/unifiprotect-pre-4.0.0-v1.5

ErikDB87 commented 2 weeks ago

Unfortunately, no success yet, see https://community.openhab.org/t/unifi-protect-binding-cloudkey-gen2-dream-machine-pro-nvr/107692/441?u=erikdb (and private message on the openHAB community forum).

ErikDB87 commented 2 days ago

The binding seems to continue working now. So this matter seems resolved.