Improve logging with "filters"

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

Here's a suggestion for an improvement on trac's logging.

First of all, this change is backwards compatible with the old way trac handled it's logging.

What I suggest is some more explicit module names, ie, full dotted module path, because, web_ui ain't that explicit, right? trac itself has several of those; and the ability to filter what modules we really want logging from.

This will help debugging parts of trac and also plugin development.

This change introduces a new config variable under [logging], log_filters and it's syntax is:

[logging]
log_filters = trac:ERROR, my.plugin:DEBUG

What the above means is:

• all logging messages that come from a module that starts with trac(trac.web, trac.ticket, tracforge, etc) and which it's level is higher that ERROR are logged and shown to the user;
• all logging messages that come from a module that starts with my.plugin and which it's level is higher than DEBUG are also logged.
• all other messages that do not match the above "filters" and which their logging level is higher than what's defined on log_level will be shown to the user.

This will also simplify logging for plugin' development. Currently if our class is inheriting from Component we have access to logging on self.log. If our class is not inheriting from Component we have to pass env and access logging from env.log. What this change introduces is the ability to do, from anywhere:

import logging
log = logging.getLogger(__name__)

We're now able to log just by calling log.

There's only one catch on the above code. At least the root logger must be configured to be able to log, ie, adding the above code to genshi/__init__.py won't work because genshi is called prior to the logging has been setup, but that's it.

Note that regarding trac, there won't be any issues because, environment is the first thing being initialized and it calls the function to setup logging at an early stage.

Now you ask, why did he talked about genshi!?

Well, with this change, and how logging is configured, we can access logging from trac, it's plugins and packages trac uses, like genshi.

Hope the code is good enough.

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

First glitch on the proposed change, this will for if running a trac env for a single interpreter. If running tracd -e which handles multiple environments the above won't work that great, the logging config from one env wins over the other. dam….

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

The correct patch I just added, keeps the main logger object as it was, we won't be able to get logging from other packages, like the example I posted for genshi, but, it will work correctly for multiple environments running in a single interpreter.

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

This last patch is the one to consider, please anyone with ATTACHMENT_DELETE, could you delete the corrected_enhanced_logging*.patch patches except corrected_enhanced_logging.5.patch.

This introduces a performance enhancement as per suggestion of coderanger plus an addition to filter matching; trac:DEBUG will now match for modules trac, trac.web, trac.whatever but not tracforge like it previously did.

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

Removed extreme copyright on my behalf :)

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

With corrected_enhanced_logging.2.patch fixed dynamic reloading not removing _trac_handler correctly.

Fixed the filter implementation, if it does not match our criterea, let it log. Log warnings to user for wrong log levels.

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

3rd version of the patch is the same as the 2nd plus corrections on classes which inherit from Component yet, still log to self.env.log meaning that they will show up as logging from trac.env and not trac.mimeview.php for example.

I also suggest that classes that do not inherit from Component, yet are passed an env, get their own self.log as, for example:

self.log = logging.getLogger("%s.%s" % (env.path, __name__))

The above would be applied for example on trac.web.session which logs to env.log apearing as trac.env and not as a more suggestible name trac.web.session.

[Pedro Algarvio, aka, s0undt3ch <ufs@…>]

This last patch goes all the way, ie, no more calling env.log even for classes that do not subclass Component or functions which get passed an env. This will mean that all modules that log will have the correct full dotted module path as %(module)s. For example, trac.mimeview.php will be what's shown as %(module)s when logging from there. Useful logging, from the useful place, with useful info.

With this patch, all tests pass, including functional, except "Admin create milestone with a space" which also fails on pristine trac [7184], so it's not a fail introduced by my patch.

As a note, for classes that do not subclass Component or functions which get passed an env, to get the correct logger, simply use:

env.get_logger(__name__)

ie, one of:

self.log = env.get_logger(__name__)
self.log = self.env.get_logger(__name__)

[Noah Kantrowitz]

Any legacy systems that call env.log directly will show up against trac.env. I wonder if there is a decent way to fix this (and issue a deprecation warning)?

Also retargeting to 0.12 since the patch looks very good to me.

[Pedro Algarvio, aka, s0undt3ch]

Replying to nkantrowitz:

Any legacy systems that call env.log directly will show up against trac.env. I wonder if there is a decent way to fix this (and issue a deprecation warning)?

I'll try to see if we can do this cleanly.

Also retargeting to 0.12 since the patch looks very good to me.

Which of the versions of the patch? The regular patch or the all-the-way?

[Pedro Algarvio, aka, s0undt3ch]

This one also issues some warnings of bad env.log deprecated usage.

[Pedro Algarvio, aka, s0undt3ch]

Well, now the patch also issues some warnings through self.log regarding some bad env.log explaining how to port the old code.

The question left is, should we use the warnings.warn instead?

[Pedro Algarvio, aka, s0undt3ch]

Removed a testing log line

[Pedro Algarvio, aka, s0undt3ch]

Updated patch to work with [7480].

[Pedro Algarvio, aka, s0undt3ch]

Updated to [7715]

[Christian Boos]

Interesting patch. Seems OK to target it to 0.12.

Did you measure any speed impact when no filters are defined?

[Pedro Algarvio, aka, s0undt3ch]

Nope, no speed tests were done ;)

[Christian Boos]

Eventually at some later point.

What would be nice is to separate the s/self.env.log/self.log fixes from the logging filter enhancement. A patch for the former will certainly get applied sooner.

[Pedro Algarvio, aka, s0undt3ch]

Well, this work is complete and working for me. You decide if you want to apply it in 2.0, or better, re-do it since code will change. Actually, the latest patch is 8 months old, it probably has already changed enough for the patch to fail to apply. (No heart broken)

[Christian Boos]

Milestone 2.0 deleted

[Christian Boos]

Remy, I see you picked this up a while back. Do you still think we need this?

The parts in the patch doing s/self.env.log/self.log/ are good, though I suspect most of it is already done by now. The filter mechanism itself seems overkill to me, in retrospect. If you're debugging something, you can just live with the increased log size during the time you've enable DEBUG level, and you can easily search (or grep) for the lines you're interested in.

[Remy Blank]

It does feel overkill, you're right. I'll go through the self.env.log -> self.log changes and apply the missing ones, and then… close or unscheduled?

[Remy Blank]

Cleanup done in [10554]. As for the rest, the increase in complexity feels too high for the added benefit.