Log Viewer: Implement keep alive mechanism for WS

[florian-h05]

According to openhab/openhab-core#5165, the log viewer needs some type of keep alive handling for the WebSocket:

What exactly is needed there? What should the UI send?

I can't quite answer that, but usually when you make a heartbeat functionality, you want to use it for something. As it is now, MainUI sends them but never checks if they make it. Core just accepts them without doing anything as well. They might be intended to prevent the socket from timing out, but normally I'd expect that they should have some "meaning" in themselves.

One option I could see is that they could be used to indicate if the log viewer is "connected" - if failed heartbeats were caught, it could be used to set a status that's visible to the user, so that the user knows that the log isn't "online". Another option could be that if a heartbeat fails, an attempt is made to set up a new connection, perhaps on a timer, combined with some kind of online/offline indication.

As they are now, they seem quite pointless, and I also think that it's a problem that you can't really see if the log is "connected" or not - because it certainly has a tendency to "lose connection", and you have no way to know if no new entries arrive because the connection has been lost or because no loggable events have taken place. You can't reload the page "to make sure that you're connected" either, because if you do that, you lose all history except the last 100 entries (which is "nothing"). To me, the fact that you don't know it does receive log entries or not, is one of the things that make the log viewer a very poor replacement for Frontail (the lack of history is the biggest one though).

Originally posted by @Nadahar in openhab/openhab-core#5165 (comment)

[Nadahar]

I just found another reason why the log viewer fails/disconnects: Reauthentication or possibly expired token. I let #3576 run overnight to see how it behaved, and it disconnected after ~ 1 hour with:

POST http://localhost:8081/rest/auth/token net::ERR_CONNECTION_REFUSED - request.js:406
Uncaught (in promise) 0 - auth-mixin.js:90

So, something makes the auth "expire" after a while, which is a big problem for something that you might want to leave running.

[florian-h05]

So, something makes the auth "expire" after a while, which is a big problem for something that you might want to leave running.

This quite common for OAuth access tokens: https://www.oauth.com/oauth2-servers/access-tokens/access-token-lifetime/

[Nadahar]

This quite common for OAuth access tokens

I'm not really into OAuth, but I read that there's such a thing as refresh tokens. They should make sure that this situation doesn't occur. Don't OH use those?

To me, this goes to the core of the log viewer and its somewhat "problematic" role in replacing Frontail. Because, if you just want to see what's happening right now, it's fine, but at least for me, that's rarely the case. When something goes wrong, I want to see what happened in the past. And since the "history" the log viewer can retrieve is just 100 events, that often means less than a minute back, it doesn't make much difference.

So, the only way I can see that it can be used, is to let it stay running in a tab and let the browser cache all the log in memory. Not very memory efficient, but what is the alternative? And, to do that, you must be able to let that tab stay running over time - which is why I've been trying to address the various issues that cause this to fail. I believe that most/all of the reasons in core has been addressed in openhab/openhab-core#5165, and doing the MainUI side that at least let you know if it is connected or not, potentially also that reconnects if the connection is lost, chances should improve even more. But, if the auth expires on a regular basis and there's no solution to this, the whole idea of using the log viewer in this way is moot. I'd say this makes its usefulness marginal, you can use it to test that rules log what you expect etc., but you can't really use it for troubleshooting after the fact.

[florian-h05]

I'm not really into OAuth, but I read that there's such a thing as refresh tokens. They should make sure that this situation doesn't occur. Don't OH use those?

Yes, there are refresh tokens, and Main UI uses them to refresh it's access token. The stacktrace above however indicates that refreshing the access token failed, it would be interesting if you could provide the error that was put into the console and not only "Uncaught in promise [...]".
I am also not sure if a WS connection needs to get reestablished if the access token changes, but I don't think so and expect that the token is only checked upon connection init.

And since the "history" the log viewer can retrieve is just 100 events, that often means less than a minute back, it doesn't make much difference.

Yes, that's indeed an issue. I've set up Alloy -> Loki -> Grafana for log aggregation which allows me to comfortably filter for warnings and errors but that's no real solution, I mainly wanted to get my hands on log aggregation.

[Nadahar]

Yes, there are refresh tokens, and Main UI uses them to refresh it's access token. The stacktrace above however indicates that refreshing the access token failed, it would be interesting if you could provide the error that was put into the console and not only "Uncaught in promise [...]".

Unfortunately, I don't have that console available anymore, and the browser control really suck at copying (I've found no "clean" way to copy a stack trace, it will randomly include other information which I must edit out manually). It doesn't always include an "expand arrow" (for reasons I don't understand), and I don't think this one did, or I would probably have tried to paste more information.

I guess I can spin up another instance and hope to capture it again.

I am also not sure if a WS connection needs to get reestablished if the access token changes, but I don't think so and expect that the token is only checked upon connection init.

My guess is that the connection is invalidated/closed by the server when the token expires, otherwise it wouldn't make any sense why I got this failure logged at the same time that the socket connection died.

[Nadahar]

I set up another test. It disconnected just 7 minutes after I started it, but I hadn't remembered to open the browser console first, so nothing was "captured". I've since opened the console and let it run for 8ish hours, without it disconnecting. So, this doesn't seem to be something that happens on a fixed interval like token expiration.

[Nadahar]

It's still running without a hitch. The initial disconnect I had after 7 minutes could perhaps have been caused by something else, I'll never know since I didn't have the browser console open, and nothing "of interest" was logged in the OH log (except some SSE exceptions, but I wouldn't think they should be related?).

I don't know the expiration time for the tokens, but I assume that it has successfully survived several expirations already in the ~12 hours it's been running now?

My Core build is the latest main, which includes my websocket concurrency fixes. What I'm starting to wonder is if I used a Core with or without those fixes the last time I did this check (I don't remember), and perhaps some of the concurrency issues caused this to happen?

[Nadahar]

I stopped it now, because it was preventing me from doing other things. Still no error.