Add a custom log handler and GUI viewer with filters

[brisvag]

References and relevant issues

Followup on #6849 (comment)

Description

The idea is to have our own custom handler for log messages so we can then expose the logs as we prefer from the GUI. This will make it easier for users to copy-paste logs even if they didn't manually open from the console, and also easier for developers to quickly check things.

I never really worked with the logging module, so I have a feeling that this is garbage... but oh well, let's see how bad :P

To test, open napari and do some stuff. Then, from the terminal or console run:

napari._LOG_STREAM.logs_at_level(10)

EDIT: Added a very quick-and-dirty GUI for the logger based on the implementation of the About widget. For how bad it is, it's actually ok xD You can open it from the menu `Help -> Show log".

cc @Czaki

[Czaki]

I think that custom log handler should be initialized in napari.qt.qt_event_loop, same as notification manager.

[brisvag]

But the logger should work regardless of qt right? Also headless it would be useful.

[Czaki]

As I understand, it is log handler, not logger. The current code means, that each time one import napari it starts storing all logs in memory, even without a clean way to show them.

[brisvag]

Yes... but isn't that what we want? Would be good to be able to get these logs programmatically as well. We can also discard old logs if we go above a certain size.

[Czaki]

My personal feeling is that we should do this, like with notifications (warnigs), but I may be wrong.

[brisvag]

do what? I'm not sure I follow ^^'

[Czaki]

It will be nice to connect to all loggers and be able to filter messages based on logger (so someone could filter logs only from a given plugin logger.

[brisvag]

True... I'm not sure how to do that though; I guess we somehow get the root logger? And btw, is there a way to get these logging parameters (level, thread, etc) "raw" instead of formatting to string and then de-formatting?

[brisvag]

EDIT: I changed to use the root logger and filter for napari by default. Probably less finnicky than registering specific plugins.

[codecov]

Codecov Report

Attention: Patch coverage is 93.58974% with 10 lines in your changes missing coverage. Please review.

Project coverage is 92.94%. Comparing base (7fa8c78) to head (a9302e1).
Report is 9 commits behind head on main.

Files with missing lines	Patch %	Lines
napari/_qt/widgets/qt_logger.py	93.33%	5 Missing ⚠️
napari/utils/_logging.py	92.98%	4 Missing ⚠️
napari/_qt/_qapp_model/qactions/_help.py	66.66%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #6900      +/-   ##
==========================================
- Coverage   92.98%   92.94%   -0.05%     
==========================================
  Files         635      641       +6     
  Lines       59857    60213     +356     
==========================================
+ Hits        55661    55963     +302     
- Misses       4196     4250      +54     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[brisvag]

This is starting to look fun. Try with this:

import logging
logger = logging.getLogger()
logger.setLevel('DEBUG')

import napari

v = napari.Viewer()

logging.getLogger('napari').debug('some debug info')
logging.getLogger('napari.something').warning('this will show (sublogger of napari)')
logging.getLogger('napari-plugin').warning('will would also show, if napari-plugin was registered')
logging.getLogger('other-logger').warning('will not show!')
logging.getLogger('napari').error('very important!')

Then open the log from the help menu:

napari_logger.mp4

[brisvag]

Main things that I don't know how to deal with:

• log messages seem to now be completely taken over by our logger, and no longer appear on the console
• I don't think there's a way to get debug-level logging for us without forcing debug-level logs to be sent to all handlers, which is quite annoying

[brisvag]

@psobolewskiPhD I'm sure you'll like this :P

[jni]

log messages seem to now be completely taken over by our logger, and no longer appear on the console

This SO question and answers have lots of suggestions for using multiple handlers.

It may mean that we need to explicitly declare handlers and no longer use the top level logging. calls?

[brisvag]

Actually, I "solved it" by explicitly readding to the handlers the default "fallback" handler. But yes, by default as soon as you add a handler, the base one no longer gets used. I'm not sure what's the best practice here, but since now we're handling everything including the root logger, I think it's better not to interfrere with other logging activities :P

[psobolewskiPhD]

Looks sweet!
I did the logger.setLevel('DEBUG') and got some ipykernel stuff there so it's working.

I couldn't figure out how to get it to log notifications, like if something uses napari show_warning.
Also, I found it a bit frustrating that it's modal, that I can't interact with napari while it's open.
For reviewing logs it's nice though, so something to put on the ToDo is to make it dockable?

cc: @goanpeca this is relevant to napari/napari-plugin-manager#69

[brisvag]

I couldn't figure out how to get it to log notifications, like if something uses napari show_warning.

Yeah those are not calls to logging... I guess we can redirect notifications there too, since we have our own functions. But I don't know if there's a way to get all warnings. In general, I don't like that in napari we have a random assortment of warnings.warn and logging.warn calls... Not sure if there's any reason not to just always use logging.

Also, I found it a bit frustrating that it's modal, that I can't interact with napari while it's open. For reviewing logs it's nice though, so something to put on the ToDo is to make it dockable?

Good point. I mostly copied the qt code from other places, I'm not experienced with this stuff. But yeah can always be done after, maybe with help from some qt pro :P

[brisvag]

Good point. I mostly copied the qt code from other places, I'm not experienced with this stuff. But yeah can always be done after, maybe with help from some qt pro :P

Acutally, done xD

[jni]

Hmmm. Something's not working. If I try the code from an earlier comment (updated to use get_app_model instead of the deprecated get_app), I see some logs printed to the terminal, and nothing in the log viewer:

#!/usr/bin/env python3

import logging
logger = logging.getLogger()
logger.setLevel('DEBUG')

import napari

v = napari.Viewer()

logging.getLogger('napari').debug('some debug info')
logging.getLogger('other-logger').warning('will also show')
logging.getLogger('napari').error('very important!')

from napari._app_model._app import get_app_model
get_app_model().commands.execute_command('napari.window.help.show_log')

napari.run()

viewer:

(note: those two messages appear after I press some keys to take the screenshot)

terminal output:

will also show
very important!

[jni]

Right. I see that the fix in 2812f0b means that we don't register the logger at import, we register for the lifetime of the viewer. I can't decide whether that loses some of the appeal, but maybe it's ok for now. Thoughts @Czaki @brisvag?

The other change I was about to push is to change "show_log" to "show_logs" (both function name and action name). I think some folks (🙋) naturally would type "logs", which shows nothing in the command palette without the rename. (And typing only "log" prioritises the Shepp-Logan phantom sample dataset.)

[jni]

we register for the lifetime of the viewer. I can't decide whether that loses some of the appeal, but maybe it's ok for now.

it's a bit worse than that, it's when the app runs. Even though the messages are logged after the viewer is created, they necessarily happen before napari.run(), and they are missed.

I think this might be bad, and maybe the context can live on the viewer itself rather than on the app. What do you think @Czaki, do you think this would be easy to achieve? Or even desirable?

[jni]

The other change I was about to push is to change "show_log" to "show_logs" (both function name and action name).

pushed. I'm going to wait for feedback about the current state of this PR with the context manager before merging.

[Czaki]

it's a bit worse than that, it's when the app runs. Even though the messages are logged after the viewer is created, they necessarily happen before napari.run(), and they are missed.

I think this might be bad, and maybe the context can live on the viewer itself rather than on the app. What do you think @Czaki, do you think this would be easy to achieve? Or even desirable?

My opinion is that enabling logger on import or even on viewer creation is a bad practice. We do not know if users are using napari as an application or in other scenarios. The problem will be bigger when we introduce napari-lite.

Of course, we could register logger on viewer creation, but as I have above written, it does not look like a good idea for me. Also, it will be difficult to decide when to unregister.

[brisvag]

Of course, we could register logger on viewer creation, but as I have above written, it does not look like a good idea for me. Also, it will be difficult to decide when to unregister.

Sorry, I can't find where you're saying this "above". Why is this bad? If the problem is "tests crash", let's just test differently and xfail that specific qt+debugger mix.

[Czaki]

Sorry, I can't find where you're saying this "above".

the paragraph above.

Why is this bad? If the problem is "tests crash", let's just test differently and xfail that specific qt+debugger mix.

Because we started collecting logs even in situations when it cannot be seen, but still consumes memory and CPU cycles.

[brisvag]

Sorry, I can't find where you're saying this "above".

the paragraph above.

Ah, lol, I thought you meant you had an explanation on the why, sorry :P

Because we started collecting logs even in situations when it cannot be seen, but still consumes memory and CPU cycles.

but say the viewer crasher before starting, those logs might be the thing that helps us debugging. Of course, we need to actually save them to file, which is planned. Is memory and cpu cycles really of concerns here? Like, does it even factor in compared to the import costs of our dependencies??

[Czaki]

Is memory and cpu cycles really of concerns here? Like, does it even factor in compared to the import costs of our dependencies??

For long-running programs, through multiple hours, where every logging call is registered and saved? Yes.

but say the viewer crasher before starting, those logs might be the thing that helps us debugging.

if it is our program (someone start napari from bundle for example) we may enable it earlier.

If it is someone's script he may read log from termianl.

[brisvag]

ok, so you're saying let's merge this as is and consider this only a GUI logging tool, period?

[Czaki]

ok, so you're saying let's merge this as is and consider this only a GUI logging tool, period?

In my opinion yes.

We may further work around this problem. For example, add enable_logging function that will allow user to enable it earlier.

BTW. I think that is more important now to have 100% test coverage for this code, as code for debugging should not crash itself.

[brisvag]

Ok, color me convinced!

[jni]

Ok, I'll merge as-is, and we can always tweak in the future to handle more and/or let users opt-in to handle more.

[jni]

(Thank you both for the discussion! It's great to walk away for a bit and come back to have a decision made for you! 😂)

[imagesc-bot]

This pull request has been mentioned on Image.sc Forum. There might be relevant details there:

https://forum.image.sc/t/napari-0-6-0-released/112147/1