Proposal: Kivy-internal logs should rely on module name rather than manual specification of type
ngoonee opened this issue · 15 comments
Please refer initial issue - #4102 regarding Kivy not handling calls to python's logging module.
As-is, kivy's logs have this format in terminal:-
[TYPE ][CALLER ] Content
And in the log-file, we have:-
[TYPE ]CALLER: Content
To support this, every call to Logger.{info,debug,etc} passes text of this format:-
"CALLER: Content"
This is a duplication of module level info which is already available from name. I feel that it is more useful to use the standard logging.getLogger(name) by default, and that this would provide more information (module hierarchy). Also, other potentially relevant information (especially the timestamp of the call to the log) is missing.
I propose:-
- logger.py should set logging.Logger.manager.root = Logger
- All instances of msg.split(':', 1) in logger.py be replaced appropriately to use the name of the logger instead. The formatter should also implement the formatTime and formatException methods (this would also require using the logging module's config)
- Calls to Logger be replaced with calls to module-specific (or function-specific) logging.getLogger() instances
Benefits:-
- Contributors need not specify where the logger is being called from
- Refactoring functions to other locations (rare) would be slightly easier
Cons:-
- Touches many files in source
- Probably not possible to maintain identical output as prior to this change
While this seems a relatively simple (if tedious) change, the last con means it items 2 and 3 of this proposal might need to wait for a major release etc. (I think). However item 1 should be trivially do-able, unless I've missed some implications where it would break something.
If this proposal is acceptable I'll try to get a PR up. Point 1 is simple, points 2 and 3 should be do-able without too much effort as well.
I concur.
Re point 3, this could in general be achieved by Logger.getChild(), regardless of point 1.
I agree with most of the proposal, except for redefining the root logger, we should avoid that.
Hi @dessant , any particular reason to avoid that? As I understand it we're effectively doing that already, since any kivy app currently must either use Kivy's logger module (including changes to internal possibly 3rd-party modules) or redefine a separate logging path from what the rest of Kivy is using.
@ngoonee, it could be ok for a small script, but in an app you may want to handle logs coming from different libs in different ways. What happens if all of them starts to hijack the root logger? 🔥
A number of python libs have been doing this and it never turned out well, one of them being tornado.
Here is a scary motivation why celery has an option for it (I think they are moving away from these logging practices):
Btw, the reason it hijacks the root logger is because some badly written libraries sets up logging, something a library should never do, resulting in users experiencing no output from the celeryd worker :(
@dessant noted. I think of Kivy as 'the' app rather than 'a' library though. Noted that that can cause serious problems. Current behaviour is to redefine logging.root, which is probably not what should be done? Does this need to change?
Yes. 😋
Noted, probably needs fairly significant rewriting then. Let me take a look.
I too think of kivy as a app rather than a library. So I'm not sure setting root is wrong. What issues do you see with us setting root? Kivy is a app which intends to run everything from it, so it makes sense it gets all the logs through it..
As for creating a logger for each module, I think that is wrong because it creates a logger based on internal details of how we structure our files which has no meaning to a user. Instead, it needs to be named by a higher level grouping. Imagine someone getting an error [warning][kivy.core.text._sdl_text] blah. That has less meaning than [warning][text] blah.
I don't feel super strongly about this, but I would definitely like to get more input from others before this is modified.
@matham, when you have a third-party lib/module it becomes difficult to route that log and handle it separately if kivy replaces the root logger, no? I don't see why must people modify and adapt external libs in certain cases for their logging solutions to keep working when kivy is imported.
Do you have an example where that would be an issue? Personally I don't feel very strong about setting root or not. By default I'd think we shouldn't, but kivy is the main app which manages everything including all the logs so it's not that inappropriate.
I now do however think that using getLogger(__name__) is not appropriate because that has less meaning to outside users than a higher level organization, e.g. video, audio, etc. like we currently use. I certainly don't see what we'd gain from such a switch as typically, for detailed errors, there's an associated full traceback anyway which gives the module name.
One of the benefits of getLogger(__name__) is simply consistency, not relying on authors doing the 'right thing' in labelling log entries. I agree that it doesn't look as visually appealing, though.
Regarding the root logger, can Kivy even be used as a lib? Because if it's only used as the main app (I'm not sure that this is the case, by the way), then all libs imported inherit from kivy, no? In particular by both replacing logging.root and logging.Logger.manager.root, at least in my own app this results in lib logs being sent to Kivy's logs.
This would only affect libs which handle their own logging separately.
Kivy is a framework, not an application. The application is what you make with Kivy. It should indeed hijack the root logger (optionally, but by default), as then it can control the formatting, log files, etc. of library logging as well. However, it should probably do this when actually running (MyApp().run() or runTouchApp(x)), rather than immediately at module level.
In other words, this really shouldn't happen:
ryan@ryan-mk3:~/g/k/kivy (master:✖)$ ipython
Python 2.7.11+ (default, Apr 17 2016, 14:00:29)
Type "copyright", "credits" or "license" for more information.
IPython 2.4.1 -- An enhanced Interactive Python.
? -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help -> Python's own help system.
object? -> Details about 'object', use 'object??' for extra details.
In [1]: import kivy
[WARNING] [Config ] Older configuration version detected (14 instead of 15)
[WARNING] [Config ] Upgrading configuration in progress.
[DEBUG ] [Config ] Upgrading from 14 to 15
[INFO ] [Logger ] Record log in /home/ryan/.kivy/logs/kivy_16-06-06_9.txt
[INFO ] [Factory ] 193 symbols loaded
[DEBUG ] [Cache ] register <kv.image> with limit=None, timeout=60
[DEBUG ] [Cache ] register <kv.atlas> with limit=None, timeout=None
[INFO ] [Image ] Providers: img_tex, img_dds, img_gif, img_sdl2, img_pil (img_ffpyplayer ignored)
[DEBUG ] [Cache ] register <kv.texture> with limit=1000, timeout=60
[DEBUG ] [Cache ] register <kv.shader> with limit=1000, timeout=3600
[DEBUG ] [Cache ] register <kv.lang> with limit=None, timeout=None
[INFO ] [Text ] Provider: sdl2
[DEBUG ] [Cache ] register <textinput.label> with limit=None, timeout=60.0
[DEBUG ] [Cache ] register <textinput.width> with limit=None, timeout=60.0
[INFO ] [Kivy ] v1.9.2-dev0
[INFO ] [Python ] v2.7.11+ (default, Apr 17 2016, 14:00:29)
[GCC 5.3.1 20160413]
In [2]:
But of course, the import side effects emitting those messages shouldn't happen in the first place.
One of the benefits of getLogger(name) is simply consistency, not relying on authors doing the 'right thing' in labelling log entries. I agree that it doesn't look as visually appealing, though.
So far I don't think consistency has been an issue to justify changing to __name__. Authors can easily tell what's a meaningful group to emit the log under, while using __name__ it'll basically lead to non-meaningful messages most times because it wouldn't align with higher level groups. Kivy is not the kind of library where you have to filter logs and detailed errors from the logs other than the basic errors to justify this kind of module level logging.
However, it should probably do this when actually running (MyApp().run() or runTouchApp(x)), rather than immediately at module level.
I agree with that. Although that is part of the long standing issue of aggressive kivy imports.
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
I ran into a similar issue which I initially filed here: pallets/flask#2999 An example of setting root messing things up is running a flask app which hides useful information while doing development 😞