Edgewall Software
Modify

Opened 16 years ago

Closed 14 years ago

#7286 closed enhancement (wontfix)

Improve logging with "filters"

Reported by: Pedro Algarvio, aka, s0undt3ch <ufs@…> Owned by: Remy Blank
Priority: normal Milestone:
Component: general Version: 0.12dev
Severity: normal Keywords: logging
Cc: Branch:
Release Notes:
API Changes:
Internal Changes:

Description

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.

Attachments (10)

enhanced_logging.patch (23.2 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
corrected_enhanced_logging.8.patch (15.1 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
Removed extreme copyright on my behalf :)
corrected_enhanced_logging.patch (19.5 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
corrected_enhanced_logging.2.patch (20.1 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
corrected_enhanced_logging.3.patch (25.1 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
all-the-way_enhanced_logging.patch (58.5 KB ) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 16 years ago.
all-the-way_enhanced_logging.2.patch (58.9 KB ) - added by Pedro Algarvio, aka, s0undt3ch 16 years ago.
This one also issues some warnings of bad env.log deprecated usage.
all-the-way_enhanced_logging.3.patch (58.5 KB ) - added by Pedro Algarvio, aka, s0undt3ch 16 years ago.
Removed a testing log line
all-the-way_enhanced_logging.4.patch (58.4 KB ) - added by Pedro Algarvio, aka, s0undt3ch 16 years ago.
all-the-way_enhanced_logging.5.patch (58.4 KB ) - added by Pedro Algarvio, aka, s0undt3ch 16 years ago.
Updated to [7715]

Download all attachments as: .zip

Change History (29)

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

Attachment: enhanced_logging.patch added

comment:1 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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….

comment:2 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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.

comment:3 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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.

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

Removed extreme copyright on my behalf :)

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

comment:4 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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.

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

comment:5 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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.

by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

comment:6 by Pedro Algarvio, aka, s0undt3ch <ufs@…>, 16 years ago

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__)

comment:7 by Noah Kantrowitz, 16 years ago

Milestone: 0.130.12

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.

in reply to:  7 comment:8 by Pedro Algarvio, aka, s0undt3ch, 16 years ago

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?

by Pedro Algarvio, aka, s0undt3ch, 16 years ago

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

comment:9 by Pedro Algarvio, aka, s0undt3ch, 16 years ago

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?

by Pedro Algarvio, aka, s0undt3ch, 16 years ago

Removed a testing log line

by Pedro Algarvio, aka, s0undt3ch, 16 years ago

comment:10 by Pedro Algarvio, aka, s0undt3ch, 16 years ago

Updated patch to work with [7480].

by Pedro Algarvio, aka, s0undt3ch, 16 years ago

Updated to [7715]

comment:11 by Christian Boos, 16 years ago

Interesting patch. Seems OK to target it to 0.12.

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

comment:12 by Pedro Algarvio, aka, s0undt3ch, 16 years ago

Nope, no speed tests were done ;)

comment:13 by Christian Boos, 15 years ago

Milestone: 0.122.0

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.

comment:14 by Pedro Algarvio, aka, s0undt3ch, 15 years ago

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)

comment:15 by Christian Boos, 15 years ago

Milestone: 2.0unscheduled

Milestone 2.0 deleted

comment:16 by Remy Blank, 14 years ago

Milestone: triaging0.13
Owner: changed from Jonas Borgström to Remy Blank

comment:17 by Christian Boos, 14 years ago

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.

comment:18 by Remy Blank, 14 years ago

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?

comment:19 by Remy Blank, 14 years ago

Milestone: 0.13
Resolution: wontfix
Status: newclosed

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

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Remy Blank.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Remy Blank to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.