text: Opened 9 years ago
  Closed 6 years ago
  #7286 closed enhancement (wontfix)
  Improve logging with "filters"
  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
  ERRORare logged and shown to the user;
  - all logging messages that come from a module that starts with
  my.pluginand which it's level is higher than
  DEBUGare 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_levelwill 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)
  Change History (29)
  comment:1 Changed 9 years ago by
  comment:2 Changed 9 years ago by
  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 9 years ago by
  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 9 years ago by
  Removed extreme copyright on my behalf :)
  comment:4 Changed 9 years ago by
  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.
  comment:5 Changed 9 years ago by
  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.
  comment:6 Changed 9 years ago by
  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: 8 Changed 8 years ago by
  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 Changed 8 years ago by
  Replying to nkantrowitz:
  Any legacy systems that call
  env.logdirectly 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 8 years ago by
  This one also issues some warnings of bad
  env.log deprecated usage.
  comment:9 Changed 8 years ago by
  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 8 years ago by
  Removed a testing log line
  Changed 8 years ago by
  comment:10 Changed 8 years ago by
  Changed 8 years ago by
  comment:11 Changed 8 years ago by
  Interesting patch. Seems OK to target it to 0.12.
  Did you measure any speed impact when no filters are defined?
  comment:12 Changed 8 years ago by
  Nope, no speed tests were done ;)
  comment:13 Changed 7 years ago by
  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 7 years ago by
  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 7 years ago by
  Milestone 2.0 deleted
  comment:16 Changed 6 years ago by
  comment:17 Changed 6 years ago by
  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 6 years ago by
  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?
  First glitch on the proposed change, this will for if running a trac env for a single interpreter. If running
  tracd -ewhich handles multiple environments the above won't work that great, the logging config from one env wins over the other. dam….