Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Log Viewer to MainUI #2884

Merged
merged 21 commits into from
Dec 8, 2024
Merged

Add Log Viewer to MainUI #2884

merged 21 commits into from
Dec 8, 2024

Conversation

cdjackson
Copy link
Contributor

@cdjackson cdjackson commented Nov 25, 2024

Closes #2883.
This adds a basic log viewer into the Main UI, and displays the logs from openHAB log file using a websocket connection.

This is probably a bit rough still, but it's functional so I welcome feedback. There are a few issues that need to be worked through -:

  • The websocket address is currently hard coded - I couldn't work out how to get the dev proxy to proxy the websocket data (it always wants to default to http).
  • This looks a bit messy in dark mode - probably someone with a better understanding of the UI CSS could easily change some of this to make it work properly with the themes
  • Performance may be improved? The system can become swamped with very heave debug logging. Possibly active highlights could be moved into a separate array (might help if there are a lot of inactive highlights if a user creates a large list).

Overview

This adds the log viewer to the Developer Tools -:

image

The main logger window is reasonably simple, and a little busy. Log entries are styled with a background color (again, dark mode may not work so well) - red=error, yellow=warn, greed=info, grey text = trace, no change = debug. The window scrolls horizontally - the time column remains fixed, but the log level, class and message scroll left/right. This allows the user to effectively remove these columns if they desire by simply setting the horizontal scroll point accordingly.

image

Across the top in the navbar are a bunch of status and configuration data/buttons. These are (from left to right) -:

  • Time of the oldest and latest log entries held in the local buffer.
  • Number of log entries currently displayed. This is less than the number of logs available due to the filtering.
  • Number of log entries currently in the buffer.
  • Total number of entries before old logs are removed. This is currently hard coded at 5000 - this seemed to work ok in my testing, but possibly a larger number might also be fine.
  • Filter input box - this filters the display to display only text in either the logger name or message containing the filter text (case insensitive).
  • Play button: Continues receiving/processing logs if paused / stopped.
  • Pause: Continues to receive logs from openHAB, but doesn't add them to the display, so the display is static. When Play is pressed, the filter is updated, so any recent entries will be added.
  • Stop: Stops receiving data from the server. The websocket connection is disconnected - this ensures there is no change to the local buffer.
  • Down: Scrolls to the latest entry and keeps the bottom / latest entry visible - scrolling the screen up. Scrolling down to the bottom should also do this.
  • Download: Downloads a CSV of the filtered log file for further processing.
  • Copy: Copies the log as HTML to the clipboard. This allows pasting of the filtered log complete with highlighting.
  • Delete: Clears the log buffer.
  • Exclamation: Shows ERROR logs even if they would otherwise be filtered out.
  • Pen: Configures highlighting (more on this below).
  • Cog: Configured logging (more on this below).

Highlighting

The UI allows the user to add any number of text elements that will be highlighted. The user can specify a colour, and enable and disable if the highlighting is active or not. The list of highlights is saved locally.

image image

Log Settings

The user can directly manipulate log levels. This allows the user to simply change the log level for existing packages, or delete the log entry (restoring it to default) or adding a new logger for a custom package. If adding a custom package, this gets added as WARN level (it uses the log level provided in the ROOT logger), which can then be changed in the dropdown.

image

@mherwege
Copy link
Contributor

I absolutely love this. Looking at the screenshots, I have a few suggestions for UI improvements:

  • Currently the log viewer is full screen and cannot be used easily together with other functions on the screen. For larger screens (desktop), it might be useful to not have it full screen, but at the bottom of the screen. That allows changing things in the UI and seeing the immediate impact in the log. Just like for the developer sidebar, it could be a switch if the screen is large enough, while being like it is now on smaller screens.
  • In my view, the logging class takes up too much space, hiding the log message. It could potentially be shortened with ... at the start.
  • An extra option to wrap the log messages can also be useful. That can avoid horizontal scrolling (I don't know if it is even possible at this time).

Anyway, even without this, this would be a great addition and we can come back on this later.

@cdjackson
Copy link
Contributor Author

cdjackson commented Nov 25, 2024

Thanks for the feedback @mherwege

For larger screens (desktop), it might be useful to not have it full screen, but at the bottom of the screen

While I understand the idea, I might leave this one for another day (or someone who knows the UI and how to do this a bit more than me :) ).

In my view, the logging class takes up too much space, hiding the log message. It could potentially be shortened with ... at the start.

I should have said above - the window scrolls horizontally. The time column remains fixed, but you can scroll to the right and cut off the log level and class if you want. Arguably neither of these are "important" - the level is already denoted by background colour, and I agree that the class is secondary as well. That said, it might be useful to reduce the size of the class, but I'm also mindful of not doing too much processing on incoming logs as performance will become an issue for heavy logging applications...

Image below showing the horizontally scrolled window set to not show the level and class -:

image

An extra option to wrap the log messages can also be useful. That can avoid horizontal scrolling (I don't know if it is even possible at this time).

I'll have a look at this. For me, having a single line (unwrapped) makes it easier to view when "stuff" is scrolling past quite quickly since everything is much more uniform. As above, horizontal scrolling is already implemented.

@rkoshak
Copy link

rkoshak commented Nov 25, 2024

I second the assessment. This is fantastic! Thanks for taking this on, it's been much needed for some time and with Frontail basically becomming abandonware this could not have come soon enough.

  • I agree with @mherwege's idea to have the log open at the bottom of MainUI but also agree that's not required for an initial release.

  • I really love the ability to adjust the logging level of things right from the viewer. That's going to be super useful.

  • The Human Factors Engineering side of me is raising concerns about the color coding. If you are red/green color blind the default colors could be a problem. Maybe you can address that and the dark mode concerns by letting the user set the colors they want. I understand the color choices but I wonder if choosing "no color" for INFO might lead to a better experience. Unless users have modified the logging levels, INFO is going to be the most commonly seen log entry. It feels like that should be the "default" (i.e. no color highlighting). But that raises the question, what color should DEBUG. Is green a good color for that? 🤷‍♂️ Maybe a less bright shade of green for debug? Using symbols and other clues like bolding or italicising can be useful as well (e.g. DEBUG and TRACE are both gray but TRACE is italisized). I'm just thinking out loud.

  • In some web based log viewers I've seen, one can choose a refresh rate when "playing" the log statements. In these cases one can choose, for example every 5 seconds. Then when playing the logs, they cache the log statements and refresh the view every five seconds. This might be an option to deal with performance problems if the logs are comming too fast. I think you have all the necessary features in place to implement something like this.

  • Another perhaps future feature is to make the logs available from the developer sidebar. Even if it just launches the logger screen (similar to how the -Scratchpad- is accessed from the developer sidebar).

I look forward to seeing this merged!

@digitaldan
Copy link
Contributor

Very excited as well! This should really help with troubleshooting, thanks @cdjackson !

@cdjackson
Copy link
Contributor Author

Thanks for the comments @rkoshak

The Human Factors Engineering side of me is raising concerns about the color coding.

Agreed - the colours I went for were a) a bit random (I quickly chose something to give me the functionality) and b) definitely need to be considered better within the overall styling.

I'm certainly happy to make this configurable though. I have in mind that we should be able to store some of this configuration (like the highlighted text etc) in the server, but for now it's done locally in the browser.

In some web based log viewers I've seen, one can choose a refresh rate when "playing" the log statements.

I'm not sure if this will help or not. Maybe these systems are downloading data from the server in blocks, but in our case, the websocket server in core is sending the logs as they come in. I will take some time to look more at this - for sure if I put some of the zigbee lower level comms in debug, it will swamp the system, but that's very heavy. I need to look at where the time is being taken to work out how best to manage this, but I think this is a refinement - for most of the stuff I've been doing recently the system works pretty nicely so I see this as a refinement once we get an initial MVP merged.

@florian-h05
Copy link
Contributor

This looks like a great addition! 🚀
Many thanks @cdjackson, please let me know once you think this is ready for review.

@ghys
Copy link
Member

ghys commented Nov 26, 2024

Even without testing I can feel you've put some thought into this and it looks great!

The "Highlight" feature is brilliant.

I also wish this could be a tool that you could invoke at any time when you need it - like the Developer Sidebar with Shift-Alt-D.

Shift-Alt-L could work, maybe? (it's actually a pain to find a convenient keyboard shortcut that doesn't conflict with the browser's or whatever else). But it's just wishful thinking, the fullscreen page will definitely do for now.

I'll be sure to test it soon.

First remark: I suspect this busy navigation bar at the top is designed for desktops only and won't fare well on mobile... I'm normally (very) picky about this but that's (relatively) OK because the Developer Tools aren't on the same "it-has-to-work-on-mobile" standard as the rest.

image

Side note - can we drop the checks for the webpack-stats one day, these errors reported twice are annoying now.

image

Why hasn't the RelativeCI bot commented...? 🤔

@cdjackson
Copy link
Contributor Author

Even without testing I can feel you've put some thought into this and it looks great!

Yep - it's come together from a server development mindset - ie I plan to use this myself :) On the other side, you might find some of the coding is a little less optimal ;) - it's been a while since I've done too much in js/vue...

I also wish this could be a tool that you could invoke at any time when you need it

I agree - I might need to leave that to you :). I'd suggest to get this merged and then do that?

First remark: I suspect this busy navigation bar at the top is designed for desktops only and won't fare well on mobile...

I'm sure that's right - and I've never tested it. I would say that in reality, viewing logs in a meaningful way on a mobile device is likely to be problematic at best, but if we wanted to support that a bit better, we should be able to hide some of the buttons and status info on different screen sizes (things like the number of logs, and buttons like download are certainly contenders for removal on small devices). I did try that, but couldn't find classes that worked!

Performance may be an issue - certainly with heavy logging this currently can't keep up. I think in the longer term we might want to think more about server side filtering/processing. I had a look at a few open source loggers (eg frontail) and as far as I can tell (from a quick look/read of their repos), they all seem to do a chunk of this on the server side, where-as at the moment the OH server just sends all logs straight out the socket as they are logged. I think some buffering and filtering might be useful, but again, I think that's a discussion for another day unless you have any thoughts on this...

@cdjackson
Copy link
Contributor Author

I've improved dark mode so that it's at least usable. I accept the comments above by @rkoshak about colours in general, but at least this is now usable in dark mode -:

image

I've added a toggle filter with the exclamation mark in the navbar. If enabled, this will show ERROR level logs even if they would otherwise have been filtered out. I found this super useful where I've got a filter for a script - this filter would otherwise not display any errors from the script due to the way I'm filtering it, so this ensures errors are always displayed.

I reduced the number of log entries to 2000 - maybe we can make this configurable but I read on another OS logger that it's what they found as a good compromise. It's clearly a trade here with performance versus visibility and as mentioned above, in the slightly longer term we might want to add some more functionality to the core to better support logging. I'm not against doing this myself, but I suggest we do this in a second phase as this logger is perfectly usable, with some performance limits, as it is...

I'll do a rebase shortly and a bit of final testing then @ghys you can tear it apart :)

Signed-off-by: Chris Jackson <[email protected]>
Copy link

relativeci bot commented Nov 29, 2024

#2532 Bundle Size — 10.89MiB (+0.17%).

6707d06(current) vs 1a208e7 main#2531(baseline)

Warning

Bundle contains 2 duplicate packages – View duplicate packages

Bundle metrics  Change 3 changes Regression 1 regression
                 Current
#2532
     Baseline
#2531
Regression  Initial JS 1.91MiB(+0.03%) 1.91MiB
No change  Initial CSS 577.48KiB 577.48KiB
Change  Cache Invalidation 22.86% 17.69%
No change  Chunks 226 226
No change  Assets 249 249
Change  Modules 2946(+0.14%) 2942
No change  Duplicate Modules 152 152
No change  Duplicate Code 1.8% 1.8%
No change  Packages 96 96
No change  Duplicate Packages 2 2
Bundle size by type  Change 2 changes Regression 2 regressions
                 Current
#2532
     Baseline
#2531
Regression  JS 9.1MiB (+0.18%) 9.08MiB
Regression  CSS 866.2KiB (+0.2%) 864.45KiB
No change  Fonts 526.1KiB 526.1KiB
No change  Media 295.6KiB 295.6KiB
No change  IMG 140.74KiB 140.74KiB
No change  HTML 1.38KiB 1.38KiB
No change  Other 871B 871B

Bundle analysis reportBranch cdjackson:log-viewerProject dashboard


Generated by RelativeCIDocumentationReport issue

@cdjackson
Copy link
Contributor Author

@ghys, @florian-h05 I think this is now ok for review. Note that I've not worked out how to proxy the websocket or get the correct URL automatically, so this is still hard coded. Hopefully this is simple and you can suggest a fix.

@florian-h05
Copy link
Contributor

Thanks for the info 👍

I don't think I will have the time to review this before our feature freeze, and anyway I would propose to not merge such a major addition as short before the 4.3 release, better have more time for testing.
So I have added this to our openHAB 5 feature planning 🚀

@florian-h05
Copy link
Contributor

IIRC does the lot websocket itself support filtering, see openhab/openhab-core#3859.
I guess server-side filtering outperforms the web and also saves bandwidth.

@cdjackson
Copy link
Contributor Author

Yes, the websocket supports filtering, but IMHO this is not super useful. Since there is no local buffering on the server, if you filter using websocket, then you can't change the filter to see something different (which is often the case when debugging). You might as well just change the log level (although of course then it's also not logged to file).

As above, I plan to look at changing the server side - but that's a job for another day ;) I think a combination of server side buffering and filtering is probably a strong combination

I've not looked at the dom filtering mentioned above yet.

@ghys
Copy link
Member

ghys commented Dec 6, 2024

I'm just remembering them now but this would be a textbook case for a so-called "Virtual List":
https://v5.framework7.io/vue/virtual-list
https://v5.framework7.io/docs/virtual-list
Especially since the items' heights are fixed and can be determined in advance.

They're made for this exact purpose of when you have huge amounts of elements (the examples have 10000).

I'm not sure if we can still do the scroll-to-bottom/auto-scroll features easily with these (there's a virtualList.scrollToItem(index); method though) and the filtering would probably need a partial reimplementation.

@cdjackson
Copy link
Contributor Author

Thanks @ghys - I'll take a look at this tonight (your Saturday morning).

@florian-h05 - one other point about the server side filtering that I probably wasn't clear on above - it can only filter on the logger name (ie package). Hence my point that you might as well just use the log levels... A lot of filtering is more useful (again, IMHO) if it's done on the message rather than package... I have started to mod the server side, but it's not for the next release ;)

@ghys
Copy link
Member

ghys commented Dec 6, 2024

@cdjackson this:
cdjackson/openhab-webui@log-viewer...ghys:openhab-webui:log-viewer-virtual-list
(commit ghys@b361d29)
is a very early implementation with a virtual list.

I couldn't reproduce the tabular layout easily unfortunately, and the filtering hasn't been changed so it's broken. Maybe you could give it a spin to check if it's better performance-wise, otherwise we can abandon the idea.

@cdjackson
Copy link
Contributor Author

Thanks @ghys

I did a quick test of your change, and if anything I'd say it has worse performance... I ran with some moderate log levels and by the time it got to 2000 entries, I'd say (a little subjectively) that it was about 5 seconds behind in the logs it was displaying. You could see that the display was scrolling consistently/all the time - ie not in response to the incoming logs which could can have maybe 1/2 a second between incoming entries. However, performance didn't noticeably change when we hit the 2000 limit and it started removing old logs...

With the normal table and the same logging, it seemed to keep up with the incoming logs. As opposed to the above test, the logs were noticeably "jittery" as new entries came in at random intervals, so this seemed more "real-time". However (!!) the big problem here is the issue identified earlier in that as soon as we hit the 2000 limit, and we're removing old entries, performance drops to "zero" - it takes about a second maybe to process a new entry. My guess is that the removal of an entry in the table causes the framework to re-evaluate the whole table.

I have to go out for a while today so won't get the opportunity to look at this further until this evening. I think if we can find a way to avoid the performance hit when the buffer is full, then the original code seems best so far (unless you think there's further optimisation)...

@ghys
Copy link
Member

ghys commented Dec 7, 2024

@cdjackson thanks for trying, too bad - I agree optimizing the original implementation should be best.

I tried reaching the max log size and you're right, removing the top row of the table seems to be the reason.

It's pretty clear in this performance recording when the 2001st element is added. Most of the time seems to be spent or rendering/recalculating styles.

image

One obvious solution I think would be to display the logs in reverse order i.e. adding recent entries at the top, also there would be nothing to do to "stay at the top", but it's less intuitive.

Signed-off-by: Yannick Schaus <[email protected]>
@ghys
Copy link
Member

ghys commented Dec 7, 2024

I think I had a marginal performance improvement by not using Vue to render the table, but the bottleneck seems to be elsewhere (in the Dom7 module).

image

More about this forced reflow:
https://web.dev/articles/avoid-large-complex-layouts-and-layout-thrashing
https://yonatankra.com/layout-reflow/

Despite this I think if there isn't any further objections we can merge this before the feature freeze.

ghys and others added 2 commits December 7, 2024 17:42
Signed-off-by: Yannick Schaus <[email protected]>
Signed-off-by: Chris Jackson <[email protected]>
@cdjackson
Copy link
Contributor Author

@ghys I somehow missed your message above, but saw that you'd pushed the direct dom manipulation. I found a reference to batched processing and manipulating the data within the requestAnimationFrame method. This seems to help further - it still can't keep up with really heavy logging, but it does seem to improve on your earlier improvement.

@cdjackson
Copy link
Contributor Author

note that I left your debug that adds 1980 logs on startup enabled...

@cdjackson
Copy link
Contributor Author

I just noticed that the clear log doesn't work now. I can look at it tomorrow, but since the badge with the number of logs is cleared, I suspect that it's just that the dom needs clearing.

Copy link
Member

@ghys ghys left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I made the last fixes and we'll have to leave it at that.
Any further fixes can still be made before the release.
Also the help text for the developer tools will have to be amended:

image

Thanks!

@ghys ghys merged commit 92dd646 into openhab:main Dec 8, 2024
8 checks passed
@ghys ghys added enhancement New feature or request main ui Main UI labels Dec 8, 2024
@ghys ghys added this to the 4.3 milestone Dec 8, 2024
@florian-h05
Copy link
Contributor

Also the help text for the developer tools will have to be amended:

That text can be found in the docs repo:
https://github.com/openhab/openhab-docs/blob/main/mainui/developer/index.md

@florian-h05
Copy link
Contributor

@cdjackson Thousand thanks for work, and @ghys many thanks for the review and the fixes on this!

@cdjackson cdjackson deleted the log-viewer branch December 8, 2024 17:57
@cdjackson
Copy link
Contributor Author

Awesome - thanks @ghys for your help with getting this over the line.

I think there's still some work to do as I'd like to improve the performance for heavy logging (probably with some core changes) but I think as it stands this is a great start and will hopefully cover most user needs.

@mherwege
Copy link
Contributor

I think there's still some work to do as I'd like to improve the performance for heavy logging (probably with some core changes) but I think as it stands this is a great start and will hopefully cover most user needs.

Great we finally have an integrated log viewer.

One thing that immediately struck me when I started testing this, is that the server sends over all logs, also what has been explicitely excluded in the log4j configuration file. I have the systeminfo binding running and it creats some heavy event logging on things like CPU usage. I normally don't want to see this in the log, so explicitely excluded things like this from the logger configuration.

When you start looking at doing something server side, it would probably be good to have filters you can configure very upstream in the logging pipeline, so it never hits the websocket connection. It would definitely also make the usage in the logger view easier.

florian-h05 added a commit that referenced this pull request Dec 31, 2024
…h header (#2907)

Depens on openhab/openhab-core#4515.

This refactors the WebSocket connection code from #2884 to the `$oh`
namespace, same as it is for the SSE logic.
It also passes the access token as WebSocket subprotocol so it is sent
with the `Sec-WebSocket-Protocol` header.

---------

Signed-off-by: Florian Hotze <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request main ui Main UI
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add log viewer directly to the main UI
8 participants