Edgewall Software
Modify

Opened 6 years ago

Closed 4 years ago

#7286 closed enhancement (wontfix)

Improve logging with "filters"

Reported by: Pedro Algarvio, aka, s0undt3ch <ufs@…> Owned by: rblank
Priority: normal Milestone:
Component: general Version: 0.12dev
Severity: normal Keywords: logging
Cc:
Release Notes:
API 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@…> 6 years ago.
corrected_enhanced_logging.8.patch (15.1 KB) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 6 years ago.
Removed extreme copyright on my behalf :)
corrected_enhanced_logging.patch (19.5 KB) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 6 years ago.
corrected_enhanced_logging.2.patch (20.1 KB) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 6 years ago.
corrected_enhanced_logging.3.patch (25.1 KB) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 6 years ago.
all-the-way_enhanced_logging.patch (58.5 KB) - added by Pedro Algarvio, aka, s0undt3ch <ufs@…> 6 years ago.
all-the-way_enhanced_logging.2.patch (58.9 KB) - added by palgarvio 6 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 palgarvio 6 years ago.
Removed a testing log line
all-the-way_enhanced_logging.4.patch (58.4 KB) - added by palgarvio 6 years ago.
all-the-way_enhanced_logging.5.patch (58.4 KB) - added by palgarvio 6 years ago.
Updated to [7715]

Download all attachments as: .zip

Change History (29)

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

comment:1 Changed 6 years ago by 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….

comment:2 Changed 6 years ago by 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.

comment:3 Changed 6 years ago by 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.

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

Removed extreme copyright on my behalf :)

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

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

comment:4 Changed 6 years ago by 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.

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

comment:5 Changed 6 years ago by 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.

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

comment:6 Changed 6 years ago by 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__)

comment:7 follow-up: Changed 6 years ago by nkantrowitz

  • Milestone changed from 0.13 to 0.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.

comment:8 in reply to: ↑ 7 Changed 6 years ago by palgarvio

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?

Changed 6 years ago by palgarvio

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

comment:9 Changed 6 years ago by palgarvio

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?

Changed 6 years ago by palgarvio

Removed a testing log line

Changed 6 years ago by palgarvio

comment:10 Changed 6 years ago by palgarvio

Updated patch to work with [7480].

Changed 6 years ago by palgarvio

Updated to [7715]

comment:11 Changed 6 years ago by cboos

Interesting patch. Seems OK to target it to 0.12.

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

comment:12 Changed 6 years ago by palgarvio

Nope, no speed tests were done ;)

comment:13 Changed 5 years ago by cboos

  • Milestone changed from 0.12 to 2.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 Changed 5 years ago by palgarvio

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 Changed 5 years ago by cboos

  • Milestone changed from 2.0 to unscheduled

Milestone 2.0 deleted

comment:16 Changed 4 years ago by rblank

  • Milestone changed from triaging to 0.13
  • Owner changed from jonas to rblank

comment:17 Changed 4 years ago by cboos

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 Changed 4 years ago by rblank

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 Changed 4 years ago by rblank

  • Milestone 0.13 deleted
  • Resolution set to wontfix
  • Status changed from new to closed

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

Add Comment

Modify Ticket

Change Properties
<Author field>
Action
as closed The owner will remain rblank.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from rblank to the specified user.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.