Unifi Protect binding - HTTP protocol violation: Authentication challenge without WWW-Authenticate header

ErikDB · May 30, 2025, 9:00am

I would like to try to figure out why @Seaside’s Unifi Protect binding logs these errors regularly:

2025-05-30 06:25:29.761 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap
2025-05-30 06:25:29.761 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[GET /proxy/protect/api/bootstrap HTTP/1.1]@391ebe20
2025-05-30 06:25:29.761 [DEBUG] [al.model.request.UniFiProtectRequest] - >> GET https://192.168.1.1/proxy/protect/api/bootstrap
2025-05-30 06:25:29.768 [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) ~[?:?]
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:732) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.model.request.UniFiProtectRequest.sendRequestGetResponse(UniFiProtectRequest.java:170) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.model.request.UniFiProtectRequest.sendRequest(UniFiProtectRequest.java:121) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.model.UniFiProtectNvr.refreshBootstrap(UniFiProtectNvr.java:166) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.model.UniFiProtectNvr.refreshProtect(UniFiProtectNvr.java:223) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.refresh(UniFiProtectNvrThingHandler.java:206) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:170) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
	at java.lang.Thread.run(Thread.java:1583) [?:?]
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) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
	... 1 more
2025-05-30 06:25:29.781 [DEBUG] [al.model.request.UniFiProtectRequest] - Response is null, it shouldn't be
2025-05-30 06:25:29.781 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Credentials expired, logging in again
2025-05-30 06:25:29.781 [DEBUG] [al.model.request.UniFiProtectRequest] - Set json Body: {"remember":false,"password":"vuayc9gomsAWeNByQc","rememberMe":false,"strict":false,"username":"openhab","token":null}
2025-05-30 06:25:29.781 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /api/auth/login
2025-05-30 06:25:29.781 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[POST /api/auth/login HTTP/1.1]@7823b41b
2025-05-30 06:25:29.781 [DEBUG] [al.model.request.UniFiProtectRequest] - >> POST https://192.168.1.1/api/auth/login

I don’t fully grasp how these error logs are to be read. Is it top to bottom (i.e. “step down” in debugging goes to the line below), or the other way around? Is the actual problem in the Unifi Protect binding, or somewhere else?

Is there a way to find out what exactly is missing?

ErikDB · June 5, 2025, 6:45pm

Any takers?

Nadahar · June 12, 2025, 8:39pm

What you see is a Java Stack Trace. On the very top, you see the error itself (the Exception), usually with a message (like here) that may or may not be very helpful. Below that, you see where the program “was on the stack” at the moment the Exception was thrown. Each line is a method, with the line number in the class listed (so that you can look up the source and see exactly where it was). The stack simply reflects the nesting of the calls at that moment, so all “lines” have called the method in the line above, except the topmost line which indicates where the Exception was thrown.

Exceptions can, but do not always, have a “cause” that usually is another Exception. When this is the case, the “underlying Exception” is listed below after “Caused by:”.

When it comes to how to read them, it’s not always so easy to know. Normally I start by looking up the code on the first line to see what it is doing in that location. But, the “error” doesn’t necessarily stem from there. Often, some other code has done something that “broke some rules” that lead to the situation that the code on the top line can’t handle - which is why it throws and Exception. So, the clue is to figure out where that is.

In this case, the 3 topmost lines are from Jetty. That’s a pretty well-used library, so my first assumption would be to not look there for the error. I would thus start by looking at the 4th line, the call to UniFiProtectRequest.sendRequestGetResponse() and try to figure out what it’s doing:

github.com/seaside1/unifiprotect

src/main/java/org/openhab/binding/unifiprotect/internal/model/request/UniFiProtectRequest.java

565efd50a


      
          public synchronized String getJsonContent() {
              final ContentResponse response = getResponse();
              return response != null ? response.getContentAsString() : null;
          }
          
          private synchronized UniFiProtectStatus sendRequestGetResponse() {
              Request request = newRequest();
              logger.debug("New request: {}", request);
              try {
                  logger.debug(">> {} {}", request.getMethod(), request.getURI());
                  response = request.send();
              } catch (TimeoutException e) {
                  return new UniFiProtectStatus(SendStatus.TIMEOUT, e);
              } catch (InterruptedException e) {
                  return new UniFiProtectStatus(SendStatus.INTERRUPTED, e);
              } catch (ExecutionException e) {
                  return new UniFiProtectStatus(SendStatus.EXECUTION_FAULT, e);
              } catch (Exception x) {
                  logger.debug("Unexpected exception: {}", x.getMessage(), x);
              }
              return RESPONSE_STATUS_OK;

You can immediately see that the request isn’t created there, but at line 166, so I’d look into the newRequest method:

github.com/seaside1/unifiprotect

src/main/java/org/openhab/binding/unifiprotect/internal/model/request/UniFiProtectRequest.java

565efd50a


      
          private synchronized Request newRequest() {
              HttpURI uri = new HttpURI(getHttpScheme().concat(SCHEME_SEPARATOR).concat(host).concat(path));
              final Request request = httpClient.newRequest(uri.toString()).timeout(TIMEOUT_SECONDS, TimeUnit.SECONDS);
              request.method(getHttpMethod());
              for (Entry<String, List<String>> entry : queryParameters.entrySet()) {
                  for (String value : entry.getValue()) {
                      request.param(entry.getKey(), value);
                  }
              }
              if (!bodyParameters.isEmpty()) {
                  String jsonBody = getRequestBodyAsJson();
                  ContentProvider content = new StringContentProvider(CONTENT_TYPE_APPLICATION_JSON, jsonBody,
                          StandardCharsets.UTF_8);
                  request.content(content);
                  logger.debug("Set json Body: {}", jsonBody);
              }
          
              if (getJsonRaw() != null && !getJsonRaw().isEmpty()) {
                  ContentProvider content = new StringContentProvider(CONTENT_TYPE_APPLICATION_JSON, getJsonRaw(),
                          StandardCharsets.UTF_8);

This file has been truncated. show original

When it comes to what actually goes wrong here, is probably a bit more complicated to figure out. Authentication challenge without WWW-Authenticate header mae it seem like there’s a breach of the HTTP standard that Jetty doesn’t like, but it’s not immediately obvious if the “offender” is the addon or the device it’s communicating with.

Since the Exception is thrown in FutureResponseListener, it interpret it as if what Jetty is throwing a tantrum over is in the response - that is, what is sent from the other device in response to the request just sent by the binding.

Without digging deeper, it’s hard to know exactly what’s going on, but it looks to me like the device might respond with HTTP status 401 without including the authenticate header, which isn’t OK for Jetty. More information on the subject can be found here, with references to HTTP specs etc.:

github.com/jetty-project/jetty-reactive-httpclient

Reopen Previous issue: java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header

opened 04:28PM - 11 Feb 21 UTC

closed 08:34PM - 11 Feb 21 UTC

majones713

Hi, I opened an issue here: https://github.com/jetty-project/jetty-reactiv…e-httpclient/issues/28 https://github.com/eclipse/jetty.project/issues/5829 I reported this to Okta in which they replied with teh following: ----------------------------------------------------------------------------- After investigating this internally I can now provide an answer, Okta does not reply with the www-authenticate header because it does not perform basic authentication, the header tells the client that the user must authenticate but Okta provides that information in the response body: https://developer.okta.com/docs/reference/api/authn/#response-parameters. In this case, I would recommend submitting this as a New Feature Request, under our Support Portal's Ideas section https://support.okta.com/help/s/ideas. Features suggested in our community are reviewed and can be voted and commented on by other members of the community, therefore making it much easier for our Product Management Team to prioritize our customers’ needs. For reference: https://www.okta.com/blog/tag/authentication-methods. ----------------------------------------------------------------------------- From what got from Okta is that this header is only required when using basic authentication. Most corporate companies are using Okta today, hence, this header restriction/enforcement shouldn't be there unless this restriction doesn't only apply to basic authentication but all methods? If what Okta is saying is true Is there a way this can be turned off when not using basic authentication?

If you read the above issue, you can see that there’s a way to disable this behavior, so that Jetty doesn’t throw a tantrum. But, that’s not necessarily the solution here, the real solution is probably to figure out why 401 is returned in the first place. It indicates that the username/password sent in the request is rejected by the device, or maybe it’s missing altogether.

What I would do is to add logging to the request and response (if possible, it seems that Jetty might throw the Exception before you can log it). Alternatively, if this communication is HTTP, not HTTPS, I’d simply capture it using WireShark or similar. Sadly, these days, a lot of things force HTTPS, which makes such approaches difficult or impossible.

I can’t do any of this though, since I don’t have a device to communicate with. But, the “solution” here is to figure out why this happens, and then how to deal with it. The “why” can only be answered by studying the communication that takes place.

edit: I found this in the binding code:

            case HttpStatus.UNAUTHORIZED_401:
                return "Expired Credentials";

…which suggests that maybe the device respond with 401 when credentials have expired (they are probably only valid for a certain duration). If that is what Ubiquiti have chosen to do, without including a valid authentication header that indicates to the client how to authenticate, Jetty isn’t really suitable to use since they have taken such a hard stance on the HTTP spec. Maybe the solution is to disable automatic authentication handling and just handle it manually, which might be what’s actually happening anyway.

Nadahar · June 12, 2025, 9:43pm

Even without a device to test with, I think I have a pretty good idea about what’s happening now. The device implements a “custom” (as in not HTTP spec supported) authentication mechanism, but does what Jetty considers the moral sin of using the official 401 - Not Authorized status code whenever the credentials are rejected.

This is the login request:

github.com/seaside1/unifiprotect

src/main/java/org/openhab/binding/unifiprotect/internal/model/request/UniFiProtectLoginRequest.java

565efd50a


      
          public UniFiProtectLoginRequest(String token, HttpClient httpClient, UniFiProtectNvrThingConfig config) {
              super(httpClient, config);
              setPath(AUTH_PATH_UNIFI_OS);
              setBodyParameter(USERNAME, config.getUserName());
              setBodyParameter(PASSWORD, config.getPassword());
              setBodyParameter(STRICT, false);
              setBodyParameter(REMEMBER, false);
              setBodyParameter(REMEMBER_ME, false);
              setBodyParameter(TOKEN, UniFiProtectBindingConstants.EMPTY_STRING);
          }

Successful login results in a return token that must then be sent as HTTP header x-csrf-token with all subsequent requests. After some timeout, the token is invalidated and a new login, producing a new token, is required. It is when the token has expired that you see the above Exception logged - it should be logged fairly regularly, and you can probably deduce the token expiration duration by looking at the timestamps in your log.

This might not actually matter, the binding probably simply does a new login and continues on working - but it does log this “ugly error” that isn’t nice. The correct thing to do here is probably just to disable Jetty’s automatic authentication handling, since it’s not used anyway. That way, the 401 should be accepted by Jetty and things should work as intended, without logging the Exception.

ErikDB · June 15, 2025, 11:39am

Thanks for your thorough investigation!

I assume you mean what’s suggested in this post?

And if so, would you mind guiding me on how to implement that fix? I thought changing lines 96-99 of org.openhab.binding.unifiprotect.internal.model.request.UniFiProtectRequest.java to:

public UniFiProtectRequest(HttpClient httpClient, UniFiProtectNvrThingConfig config) {
        this.httpClient = httpClient;
        this.httpClient.start();
        this.httpClient.getProtocolHandlers().remove(WWWAuthenticationProtocolHandler.NAME);
        this.setHost(config.getHost());
    }

Eclipse then suggested I add import org.eclipse.jetty.client.WWWAuthenticationProtocolHandler; on line 28, but still complains about the line this.httpClient.start();: “Unhandled exception type Exception”:

I also wouldn’t know what to do with the last three lines of the fix suggestion:

baseClientConfiguration = new ClientConfig();
baseClientConfiguration.connectorProvider(new JettyConnectorProvider());
baseClientConfiguration.register(new JettyHttpClientSupplier(httpClient));

Helpless regards

Nadahar · June 15, 2025, 12:36pm

I’m afraid that you can’t simply copy code found online

The clue is that you need to deactivate said protocol, and the logical place to do it is where the HttpClient is created, in my opinion. The HttpClient instance is passed around a lot, but I think I found where it originates from (UniFiProtectNvr).

Also, you shouldn’t try to start the client more than once. The important part of the referenced post is that you must remove the protocol after the client has been started, so why not put it directly after it has been started?

This is my suggested change:

 .../openhab/binding/unifiprotect/internal/model/UniFiProtectNvr.java    | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/main/java/org/openhab/binding/unifiprotect/internal/model/UniFiProtectNvr.java b/src/main/java/org/openhab/binding/unifiprotect/internal/model/UniFiProtectNvr.java
index bbc7c41..fcddcdd 100644
--- a/src/main/java/org/openhab/binding/unifiprotect/internal/model/UniFiProtectNvr.java
+++ b/src/main/java/org/openhab/binding/unifiprotect/internal/model/UniFiProtectNvr.java
@@ -22,6 +22,7 @@ import java.util.Optional;
 import org.eclipse.jdt.annotation.NonNullByDefault;
 import org.eclipse.jdt.annotation.Nullable;
 import org.eclipse.jetty.client.HttpClient;
+import org.eclipse.jetty.client.WWWAuthenticationProtocolHandler;
 import org.eclipse.jetty.util.ssl.SslContextFactory;
 import org.openhab.binding.unifiprotect.internal.UniFiProtectIrMode;
 import org.openhab.binding.unifiprotect.internal.UniFiProtectLcdMessage;
@@ -93,6 +94,7 @@ public class UniFiProtectNvr {
         try {
             httpClient.start();
             logger.info("Initializing the binding, with config: {}", getConfig());
+            httpClient.getProtocolHandlers().remove(WWWAuthenticationProtocolHandler.NAME);
         } catch (Exception e) {
             logger.error("Failed to start binding: ", e);
             return false;

ErikDB · June 15, 2025, 3:47pm

I should have searched for httpClient.start(), in the entire project, of course…

I’ll give it a go tomorrow!

Nadahar · June 15, 2025, 4:19pm

I really wish there was a “thumbs up” button on the forum. The heart/like doesn’t always fit, but it’s nice to indicate that you have read and agree without having to write a one-word reply.

Nadahar · June 15, 2025, 4:30pm

There is a Discourse plugin for that:

That would be super-useful in my opinion. Who makes such decisions around here?

hmerk · June 15, 2025, 4:57pm

You need to ping the admin group.

ErikDB · June 15, 2025, 5:15pm

Ironically, I need to write that I agree.

Nadahar · June 15, 2025, 5:30pm

Nothing obvious comes up when I write @admin or similar. Does anybody here know the “tag” of the admin group?

ErikDB · June 16, 2025, 6:42pm

Mmm, after running fine for almost two hours, this all of a sudden happened:

2025-06-16 17:47:45.317 [DEBUG] [websocket.UniFiProtectEventWebSocket] - Connection closed: 1006 - Disconnected
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Executing refresh job
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing Protect: 128839533
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing the UniFi Protect Controller unifiprotect:nvr:f4b3b5f657
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - Key: x-csrf-token, value: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[GET /proxy/protect/api/bootstrap HTTP/1.1]@7a5e45d5
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - >> GET https://192.168.1.1/proxy/protect/api/bootstrap
2025-06-16 17:48:45.355 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Successfullt sent request
2025-06-16 17:48:45.355 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Request is ok, parsing cameras
2025-06-16 17:48:45.357 [DEBUG] [ifiprotect.internal.UniFiProtectUtil] - Wrote file: /var/lib/openhab/tmp/bootstrap15937554689022137452.json
2025-06-16 17:48:45.357 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Wrote bootstrap to temp file: /var/lib/openhab/tmp/bootstrap15937554689022137452.json
2025-06-16 17:48:45.357 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Put all size: 0
2025-06-16 17:48:45.358 [DEBUG] [otect.internal.model.UniFiProtectNvr] - UniFiProtectNvrDevice: null
2025-06-16 17:48:45.358 [DEBUG] [ernal.event.UniFiProtectEventManager] - Failed to stop manager
java.lang.NullPointerException: Cannot invoke "org.openhab.binding.unifiprotect.websocket.UniFiProtectEventWebSocket.removePropertyChangeListener(java.beans.PropertyChangeListener)" because "this.socket" is null
	at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.stop(UniFiProtectEventManager.java:110) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.dispose(UniFiProtectEventManager.java:122) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:180) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
	at java.lang.Thread.run(Thread.java:1583) [?:?]

In the log of 39.000+ lines, there’s only one instance of Connection closed: 1006 - Disconnected. The java.lang.NullPointerException first appeared at 17:49:45, and has repeated itself every minute since then. (All the lines between Connection closed: 1006 - Disconnected and java.lang.NullPointerException have 100+ identical copies) The NVR thing is since then OFFLINE. The event.log shows this:

2025-06-16 17:47:45.318 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'unifiprotect:nvr:f4b3b5f657' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Execution fault when sending request to UniFi Protect
2025-06-16 17:47:45.318 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'unifiprotect:g5camera:f4b3b5f657:F4E2C676310A' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

Since that error wasn’t there with my previous jar, I deduce that it’s somehow related to httpClient.getProtocolHandlers().remove(WWWAuthenticationProtocolHandler.NAME);…?

Although… The thing going offline seems to predate the error, so the error is probably the consequence of the thing being offline. The mystery is thus: why did it go offline… The logs of the Unifi system don’t mention anything out of the ordinary.

I’ve now disabled and re-enabled the NVR thing. We’ll see how long it lasts now. Although trying the same and hoping for a different result is known not to be the wisest approach.

Nadahar · June 16, 2025, 7:35pm

I’m not sure that I would trust that deduction… it might be that “fixing” one error simply reveals another. Can it be that the token timeout is as long as 2 hours, and that it’s at this point that the original Exception was thrown? The program flow is altered when the 401 response status no longer triggers an exception, so code that previously would never run might come into play now.

That said, I don’t quite understand how this problem “could have arisen” if the binding used to work, unless UniFi has changed the token timeout to be much shorter through software updates, so that the issue is more visible now.

There seems to be multiple things going on here, the NPE itself is the result of somewhat “sloppy” code:

    public synchronized void stop() {
        try {
            socket.removePropertyChangeListener(this);
            socket.dispose();
            wsClient.stop();
            cancelReinitFuture();
            socket = null;
        } catch (Exception e) {
            logger.debug("Failed to stop manager", e);
        }
    }

    public synchronized void dispose() {
        try {
            stop();
        } catch (Exception e) {
            logger.debug("Failed to stop websocket client on dispose", e);
        }
    }

The logic in UniFiProtectEventManager is that socket is non-null if it is “started” and null if it is “stopped”. But, dispose(), which is called before the event manager is terminated, doesn’t take that into account - it basically assumes that the event manager is always started when dispose() is called. This is because, as you can see, dispose() calls stop() which then doesn’t check if socket is null or not before trying to stop it. In short, calling stop() when it’s already stopped will produce an NPE. That however doesn’t seem to be the cause of why it’s failing, the NPE is catched and the even manager should still be terminated. The only caveat that I can see is that the timer, reInitializationFuture, isn’t cancelled in such a case, so that it might live on trying to do stuff. But, I can’t find any evidence that reInitializationFuture is ever created or serves any purpose at all. The whole thing looks unfinished to me. Preventing the NPE is easy, but wouldn’t necessarily make things work. I also see that there are some synchronization issues in the code, where instances aren’t consistently protected. I don’t think it has anything to do with what happens here, but it’s still a bug.

My guess is that the connection is closed because the token has expired, or for some other reason. The binding then attempts to set up a new connection, called “refreshing”, and it does get a new token. But, something goes wrong, because the parsing of the “bootstrap” file results in 0 cameras. This all happens in UniFiProtectNvr:

    protected synchronized UniFiProtectStatus refreshBootstrap(String bootstrapJsonContent) {
        boolean bootstrapParseSuccess = getUniFiProtectJsonParser().parseBootstrap(bootstrapJsonContent);
        if (logger.isDebugEnabled()) {
            try {
                final File tmpFile = File.createTempFile("bootstrap", ".json");
                UniFiProtectUtil.writeFile(tmpFile, bootstrapJsonContent.getBytes());
                logger.debug("Wrote bootstrap to temp file: {}", tmpFile.getAbsolutePath());
            } catch (IOException e) {
                logger.debug("Failed to write bootstrap", e);
            }
        }
        if (!bootstrapParseSuccess) {
            return UniFiProtectStatus.STATUS_EXECUTION_FAULT;
        }
        UniFiProtectCamera[] allCameras = getUniFiProtectJsonParser().getCamerasFromBootstrap();
        if (allCameras == null) {
            return UniFiProtectStatus.STATUS_EXECUTION_FAULT;
        }
        getCameraInsightCache().clear();
        getCameraInsightCache().putAll(Arrays.asList(allCameras));
        logger.debug("Put all size: {}", getCameraInsightCache().getCameras().size());
        nvrDevice = getUniFiProtectJsonParser().getNvrDeviceFromBootstrap();
        logger.debug("UniFiProtectNvrDevice: {}", nvrDevice);
        if (nvrDevice == null) {
            return UniFiProtectStatus.STATUS_EXECUTION_FAULT;
        }

As you can see, all existing “cameras” are cleared from the cache and replaced by the the “new ones”, which are none. Probably for the same reason, nvrDevice is null (nothing meaningful is parsed from the “bootstrap file”), and this fact is what leads the binding to go into “execution fault” mode, which again is why the Thing goes offline.

It’s almost impossible to debug this without a device, but a good start would be to inspect the “bootstrap file” which is written to a temp file location (the name/location is logged). It probably doesn’t contain what the binding expects.

Has this binding ever been “fully functioning”/completed?

ErikDB · June 16, 2025, 8:29pm

I’m in awe of your analytical powers!

Digging some more, with a focus on the bootstraps:

2025-06-16 17:46:45.156 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Executing refresh job
2025-06-16 17:46:45.156 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing Protect: 128839533
2025-06-16 17:46:45.156 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing the UniFi Protect Controller unifiprotect:nvr:f4b3b5f657
2025-06-16 17:46:45.156 [DEBUG] [al.model.request.UniFiProtectRequest] - Key: x-csrf-token, value: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:46:45.156 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap
2025-06-16 17:46:45.157 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[GET /proxy/protect/api/bootstrap HTTP/1.1]@2c3c28c0
2025-06-16 17:46:45.157 [DEBUG] [al.model.request.UniFiProtectRequest] - >> GET https://192.168.1.1/proxy/protect/api/bootstrap
2025-06-16 17:46:45.273 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Successfullt sent request
2025-06-16 17:46:45.273 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Request is ok, parsing cameras
2025-06-16 17:46:45.277 [DEBUG] [ifiprotect.internal.UniFiProtectUtil] - Wrote file: /var/lib/openhab/tmp/bootstrap14850285846207178418.json
2025-06-16 17:46:45.277 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Wrote bootstrap to temp file: /var/lib/openhab/tmp/bootstrap14850285846207178418.json
2025-06-16 17:46:45.278 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Put all size: 1
2025-06-16 17:46:45.278 [DEBUG] [otect.internal.model.UniFiProtectNvr] - UniFiProtectNvrDevice: UniFiProtectNvrDevice [mac=D8B370550AB9, host=192.168.1.1, name=Droomsorteerder, canAutoUpdate=false, isStatsGatheringEnabled=false, timezone=Europe/Brussels, version=5.3.48, firmwareVersion=4.2.12, hardwarePlatform=, ports={ump=7449, http=7080, https=7443, rtsp=7447, rtsps=7441, rtmp=1935, devicesWss=7442, cameraHttps=7444, liveWs=7445, liveWss=7446, tcpStreams=7451, playback=7450, emsCLI=7440, emsJsonCLI=1112, emsLiveFLV=7550, emsLiveFLVs=7552, cameraEvents=7551, stacking=7600, tcpBridge=7888, aiFeatureConsole=7086, ucore=11081, discoveryClient=0, accessHttp=12080}, uptime=267396280, lastSeen=1750088799689, isUpdating=false, lastUpdateAt=null, isConnectedToCloud=false, isStation=false, enableAutomaticBackups=true, enableStatsReporting=false, isSshEnabled=false, releaseChannel=release, hosts=[192.168.1.1, 192.168.3.1], hardwareId=3cfebf0e-42ef-5d7b-9a79-a437b2b11457, hardwareRevision=113-00786-32, hostType=60620, hostShortname=UDR, isHardware=false, timeFormat=24h, recordingRetentionDurationMs=null, enableCrashReporting=true, disableAudio=false, storageInfo=UniFiProtectSystemInfo [cpu=null, memory=UniFiProtectMemoryInfo [available=366292, free=262340, total=1981936], storage=UniFiProtectStorageInfo [devices=[], available=0, isRecycling=true, size=0, type=sdcard, used=0]]]
2025-06-16 17:46:45.278 [DEBUG] [otect.internal.model.UniFiProtectNvr] - UniFiProtectNvrUser: UniFiProtectNvrUser [enableNotifications=false, localUsername=openhab, firstName=openhab, id=6689908a0211e403e4000537]
2025-06-16 17:46:45.278 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Login Token Success: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:46:45.278 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Successfully refreshed bootstrap
[... a lot of other stuff ...]
2025-06-16 17:47:45.289 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Executing refresh job
2025-06-16 17:47:45.289 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing Protect: 128839533
2025-06-16 17:47:45.289 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing the UniFi Protect Controller unifiprotect:nvr:f4b3b5f657
2025-06-16 17:47:45.290 [DEBUG] [al.model.request.UniFiProtectRequest] - Key: x-csrf-token, value: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:47:45.290 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap
2025-06-16 17:47:45.290 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[GET /proxy/protect/api/bootstrap HTTP/1.1]@3b04c5c0
2025-06-16 17:47:45.290 [DEBUG] [al.model.request.UniFiProtectRequest] - >> GET https://192.168.1.1/proxy/protect/api/bootstrap
2025-06-16 17:47:45.315 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Successfullt sent request
2025-06-16 17:47:45.315 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Request is ok, parsing cameras
2025-06-16 17:47:45.315 [DEBUG] [ifiprotect.internal.UniFiProtectUtil] - Wrote file: /var/lib/openhab/tmp/bootstrap14195585535038475261.json
2025-06-16 17:47:45.315 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Wrote bootstrap to temp file: /var/lib/openhab/tmp/bootstrap14195585535038475261.json
2025-06-16 17:47:45.315 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Put all size: 0
2025-06-16 17:47:45.315 [DEBUG] [otect.internal.model.UniFiProtectNvr] - UniFiProtectNvrDevice: null
2025-06-16 17:47:45.317 [DEBUG] [websocket.UniFiProtectEventWebSocket] - Connection closed: 1006 - Disconnected
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Executing refresh job
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing Protect: 128839533
2025-06-16 17:48:45.318 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing the UniFi Protect Controller unifiprotect:nvr:f4b3b5f657
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - Key: x-csrf-token, value: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - New request: HttpRequest[GET /proxy/protect/api/bootstrap HTTP/1.1]@7a5e45d5
2025-06-16 17:48:45.318 [DEBUG] [al.model.request.UniFiProtectRequest] - >> GET https://192.168.1.1/proxy/protect/api/bootstrap
2025-06-16 17:48:45.355 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Successfullt sent request
2025-06-16 17:48:45.355 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Request is ok, parsing cameras
2025-06-16 17:48:45.357 [DEBUG] [ifiprotect.internal.UniFiProtectUtil] - Wrote file: /var/lib/openhab/tmp/bootstrap15937554689022137452.json
2025-06-16 17:48:45.357 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Wrote bootstrap to temp file: /var/lib/openhab/tmp/bootstrap15937554689022137452.json
2025-06-16 17:48:45.357 [DEBUG] [otect.internal.model.UniFiProtectNvr] - Put all size: 0
2025-06-16 17:48:45.358 [DEBUG] [otect.internal.model.UniFiProtectNvr] - UniFiProtectNvrDevice: null
2025-06-16 17:48:45.358 [DEBUG] [ernal.event.UniFiProtectEventManager] - Failed to stop manager
java.lang.NullPointerException: Cannot invoke "org.openhab.binding.unifiprotect.websocket.UniFiProtectEventWebSocket.removePropertyChangeListener(java.beans.PropertyChangeListener)" because "this.socket" is null
	at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.stop(UniFiProtectEventManager.java:110) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.event.UniFiProtectEventManager.dispose(UniFiProtectEventManager.java:122) ~[?:?]
	at org.openhab.binding.unifiprotect.internal.thing.UniFiProtectNvrThingHandler.run(UniFiProtectNvrThingHandler.java:180) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
	at java.lang.Thread.run(Thread.java:1583) [?:?]
2025-06-16 17:49:45.369 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Executing refresh job
2025-06-16 17:49:45.370 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing Protect: 128839533
2025-06-16 17:49:45.370 [DEBUG] [al.thing.UniFiProtectNvrThingHandler] - Refreshing the UniFi Protect Controller unifiprotect:nvr:f4b3b5f657
2025-06-16 17:49:45.370 [DEBUG] [al.model.request.UniFiProtectRequest] - Key: x-csrf-token, value: fe4159b8-d27d-4bad-b60a-e00c46b42f46
2025-06-16 17:49:45.370 [DEBUG] [al.model.request.UniFiProtectRequest] - Created new request host: 192.168.1.1, scheme: https, path: /proxy/protect/api/bootstrap

The last ones indeed only contain {"error":{"code":401,"message":"Unauthorized"}}. So here is our 401 again, spoiling the fun. (I’ll send you the last ‘real’ one in a private message; I’m not sure it doesn’t contain “sensitive” data.)

I’m not sure. I also don’t want to be ungrateful to the author of the code: I would be nowhere without him.

Nadahar · June 16, 2025, 8:43pm

It’s not about being ungrateful, it’s just that I’ve assumed that it was once complete and then for some reason hasn’t been maintained. If that assumption is incorrect, the code should probably be seen from a different perspective.

ErikDB · June 16, 2025, 8:50pm

The feeling I get from reading the discussion about the binding, is that it’s a work in progress. (But the progress is maybe a bit stalled; I assume life gets in the way :)). Bug the binding did/does function for the large part, and maybe for others without that HTTP error, since the binding author didn’t seem to recognize it when I mentioned the last time I had contact with him.

This makes sense, of course. The snowball keeps on rolling now.

Nadahar · June 16, 2025, 9:35pm

Yeah, it seems like it’s a work in progress, but that it has gotten “quite far” so that it mostly works. At least the author has been active this year, so it might not be “permanently stalled”.

I’m actually trying to work on implementing version support for the community marketplace, I’m meeting some obstacles, but if I ever manage to navigate past all the obstacles, I think it would greatly benefit bindings like this. As it is now, the only way to “upgrade” a marketplace add-on is to uninstall and install it - and there’s no notification that there’s an updated version available.

From your latest log, it seems that there’s a problem with request.creditialsExpired(), since the credentials seems to actually be expired but goes undetected.

    protected synchronized UniFiProtectStatus refreshBootstrap() {
        UniFiProtectBootstrapRequest request = new UniFiProtectBootstrapRequest(httpClient, getConfig(), token);
        UniFiProtectStatus bootStrapRequestStatus = request.sendRequest();
        if (!requestSuccessFullySent(bootStrapRequestStatus)) {
            if (request.creditialsExpired()) {
                logger.debug("Credentials expired, logging in again");
                UniFiProtectStatus status = login();
                if (status.getStatus() == SendStatus.SUCCESS) {
                    request = new UniFiProtectBootstrapRequest(httpClient, getConfig(), token);
                    bootStrapRequestStatus = request.sendRequest();
                } else {
                    return bootStrapRequestStatus;
                }
            }
        }
        logger.debug("Request is ok, parsing cameras");
        final String bootstrapJsonContent = request.getJsonContent();
        if (bootstrapJsonContent == null) {
            logger.error("Got null response when refreshing bootstrap");
            return UniFiProtectStatus.STATUS_EXECUTION_FAULT;
        }
        return refreshBootstrap(bootstrapJsonContent);
    }

The reason for this is that the HTTP status code is used to detect expiry (with the 401 status), but the expiry is signalled with a JSON payload instead ({"error":{"code":401,"message":"Unauthorized"}}). Without proper request/response logging, we don’t know if the response was sent with 200 or some other status. It’s thus very hard to figure out how this should work.

From the binding thread, I saw that the API used is undocumented. This not only makes it hard to figure out how to communicate with the devices, it also means that it can change at any time. When something isn’t documented, there’s no assumption that it will be used, so the developers don’t feel “bound” but what’s already there So, maybe they have changed some of the behavior since this part of the binding was written.

It can also be that the device responds using the HTTP status code for some requests, and by using a JSON payload for others. If so, the binding must be made to handle both cases.

I’m afraid there’s no “easy fix” for this, there are too many unknowns, too many guesses. It might be that the binding actually works better when an exception is thrown when the token expires, because that somehow leads to “the problem being detected” and a new token acquired, while we now have a situation where the expiration basically goes on undetected and a new token is never acquired.

It’s far from ideal to have such “scary” exceptions logged, but somebody will have to do the actual work of analyzing how this communication currently works, and how it’s supposed to work, and then make the binding do that. Lacking that, the best option might actually be to “live with” the Exception in the log every couple of hours or so.

ErikDB · June 17, 2025, 2:22pm

I’m willing, but as established, my Java (or programming language as a whole) knowledge is very limited. And I can’t expect you to “run” me through it all, as you’ve already done so kindly. I wish I understood more about it, but it’s complex.

So I’ll live with this.

Thanks for giving it a go!

AndrewFG · June 17, 2025, 2:47pm

These are DEBUG logs right? Most bindings have to catch exceptions from time to time (particularly if there is an Internet connection involved). If such exceptions are “normal” frequently occuring expected events then the convention is to log to DEBUG (just so you know about it) and reset the connection; whereas if it is a non frequent unexpected exception it would be logged to WARN.

And the convention for users is to log:set DEFAULT which generally does not display DEBUG or TRACE logs.