Index: trac/attachment.py =================================================================== --- trac/attachment.py (revision 7412) +++ trac/attachment.py (working copy) @@ -113,6 +113,7 @@ self.resource = Resource(parent_realm_or_attachment_resource, parent_id).child('attachment', filename) self.env = env + self.log = self.env.get_logger(__name__) self.parent_realm = self.resource.parent.realm self.parent_id = unicode(self.resource.parent.id) if self.resource.id: @@ -181,13 +182,13 @@ try: os.unlink(self.path) except OSError: - self.env.log.error('Failed to delete attachment file %s', - self.path, exc_info=True) + self.log.error('Failed to delete attachment file %s', + self.path, exc_info=True) if handle_ta: db.rollback() raise TracError(_('Could not delete attachment')) - self.env.log.info('Attachment removed: %s' % self.title) + self.log.info('Attachment removed: %s', self.title) if handle_ta: db.commit() @@ -234,8 +235,7 @@ shutil.copyfileobj(fileobj, targetfile) self.resource.id = self.filename = filename - self.env.log.info('New attachment: %s by %s', self.title, - self.author) + self.log.info('New attachment: %s by %s', self.title, self.author) if handle_ta: db.commit() @@ -270,6 +270,7 @@ As this is usually done while deleting the parent resource, the `db` argument is ''not'' optional here. """ + log = env.get_logger(__name__) attachment_dir = None for attachment in list(cls.select(env, parent_realm, parent_id, db)): attachment_dir = os.path.dirname(attachment.path) @@ -278,14 +279,14 @@ try: os.rmdir(attachment_dir) except OSError: - env.log.error("Can't delete attachment directory %s", - attachment_dir, exc_info=True) + log.error("Can't delete attachment directory %s", + attachment_dir, exc_info=True) select = classmethod(select) delete_all = classmethod(delete_all) def open(self): - self.env.log.debug('Trying to open attachment at %s', self.path) + self.log.debug('Trying to open attachment at %s', self.path) try: fd = open(self.path, 'rb') except IOError: @@ -694,8 +695,8 @@ add_link(req, 'alternate', raw_href, _('Original Format'), mime_type) - self.log.debug("Rendering preview of file %s with mime-type %s" - % (attachment.filename, mime_type)) + self.log.debug("Rendering preview of file %s with mime-type %s", + attachment.filename, mime_type) data['preview'] = mimeview.preview_data( Context.from_request(req, attachment.resource), fd, @@ -772,9 +773,9 @@ if legacy_action: decision = legacy_action in perm if not decision: - self.env.log.debug('LegacyAttachmentPolicy denied %s ' - 'access to %s. User needs %s' % - (username, resource, legacy_action)) + self.log.debug('LegacyAttachmentPolicy denied %s ' + 'access to %s. User needs %s', + username, resource, legacy_action) return decision else: for d in self.delegates: Index: trac/env.py =================================================================== --- trac/env.py (revision 7412) +++ trac/env.py (working copy) @@ -2,6 +2,7 @@ # # Copyright (C) 2003-2008 Edgewall Software # Copyright (C) 2003-2007 Jonas Borgström +# Copyright (C) 2008 Pedro Algarvio # All rights reserved. # # This software is licensed as described in the file COPYING, which @@ -14,6 +15,7 @@ # # Author: Jonas Borgström +import logging import os try: import threading @@ -147,14 +149,36 @@ - $(path)s the path for the current environment - $(basename)s the last path component of the current environment - $(project)s the project name - - Note the usage of `$(...)s` instead of `%(...)s` as the latter form - would be interpreted by the ConfigParser itself. - - Example: + + Note the usage of `$(...)s` instead of `%(...)s` as the latter form + would be interpreted by the ConfigParser itself. + + Example: ($(thread)d) Trac[$(basename)s:$(module)s] $(levelname)s: $(message)s - - (since 0.10.5)""") + + (since 0.10.5)""") + log_filters = ListOption('logging', 'log_filters', [], doc= + """Custom logging handlers. + + If nothing set, logging will be as it was, nothing is changed. + + Example usage is: + log_filters = trac:WARNING, trac.ticket:DEBUG + + The above would translate to: + * all messages who's module name starts with `trac` and log level + is higher than `WARNING` are logged; + * all messages who's module name starts with `trac.ticket` and log + level is higher than `DEBUG` are logged; + * all other messages who's module name does not start with any of + the above and for which their level is higher than the default + `log_level` will be logged; + + This way you can narrow the debugging messages to the modules you + wish to. The same applies to a plugin you're coding: + log_filters = trac:ERROR, my.plug.module:DEBUG + + (since 0.12)""") def __init__(self, path, create=False, options=[]): """Initialize the Trac environment. @@ -201,7 +225,9 @@ environment configuration) and `log` (a logger object).""" component.env = self component.config = self.config - component.log = self.log + component.log = logging.getLogger( + "%s.%s" % (self.path, component.__class__.__module__) + ) def is_component_enabled(self, cls): """Implemented to only allow activation of components that are not @@ -353,7 +379,7 @@ def setup_log(self): """Initialize the logging sub-system.""" - from trac.log import logger_factory + from trac.log import setup_logging logtype = self.log_type logfile = self.log_file if logtype == 'file' and not os.path.isabs(logfile): @@ -364,8 +390,39 @@ .replace('%(path)s', self.path) \ .replace('%(basename)s', os.path.basename(self.path)) \ .replace('%(project)s', self.project_name) - self.log = logger_factory(logtype, logfile, self.log_level, self.path, - format=format) + # Setup but don't keep the root logger + setup_logging(logtype, logfile, self.log_level, self.path, + format, self.log_filters) + + class CheckDeprecatedLoggingUsage(object): + """Proxy class to warn users of bad logging usage""" + log = logging.getLogger("%s.%s" % (self.path, __name__)) + def check_deprecated_use(self): + import inspect + caller = inspect.stack()[2] + if 'env.log' in caller[4][0]: + self.log.warn( + _("""Please stop logging through "env.log" on "%s". \ +The code issuing this is "%s". This usage is now deprecated. Instead, if \ +it's a trac Component, please use "self.log", if it's just a function which \ +get's passed a trac env, get a logger like "log = env.get_logger(__name__)" \ +and log through that. This practice provides good and usefull logging."""), + caller[1], caller[4][0].strip()) + del caller + def __getattribute__(self, name): + if name in ('log', 'check_deprecated_use'): + return object.__getattribute__(self, name) + self.check_deprecated_use() + return getattr(self.log, name) + + # Get a logger for this module + self.log = CheckDeprecatedLoggingUsage() + + def get_logger(self, name): + """Get the correct logger for classes/functions which an env is passed, + yet, it's not subclassing Component.""" + from trac.log import get_logger + return get_logger(self.path, name) def get_known_users(self, cnx=None): """Generator that yields information about all known users, i.e. users @@ -557,10 +614,12 @@ env.log.info('Reloading environment due to configuration ' 'change') env.shutdown() - if hasattr(env.log, '_trac_handler'): - hdlr = env.log._trac_handler - env.log.removeHandler(hdlr) + env_root_logger = logging.getLogger(env.path) + if hasattr(env_root_logger, '_trac_handler'): + hdlr = env_root_logger._trac_handler + env_root_logger.removeHandler(hdlr) hdlr.close() + del env_root_logger del env_cache[env_path] env = None if env is None: Index: trac/mimeview/enscript.py =================================================================== --- trac/mimeview/enscript.py (revision 7412) +++ trac/mimeview/enscript.py (working copy) @@ -136,7 +136,7 @@ mimetype = mimetype.split(';', 1)[0] # strip off charset mode = self._types[mimetype][0] cmdline += ' --color -h -q --language=html -p - -E%s' % mode - self.env.log.debug("Enscript command line: %s" % cmdline) + self.log.debug("Enscript command line: %s", cmdline) np = NaivePopen(cmdline, content.encode('utf-8'), capturestderr=1) if np.errorlevel or np.err: Index: trac/mimeview/php.py =================================================================== --- trac/mimeview/php.py (revision 7412) +++ trac/mimeview/php.py (working copy) @@ -81,7 +81,7 @@ def render(self, context, mimetype, content, filename=None, rev=None): # -n to ignore php.ini so we're using default colors cmdline = '%s -sn' % self.path - self.env.log.debug("PHP command line: %s" % cmdline) + self.log.debug("PHP command line: %s", cmdline) content = content_to_unicode(self.env, content, mimetype) content = content.encode('utf-8') Index: trac/ticket/tests/query.py =================================================================== --- trac/ticket/tests/query.py (revision 7412) +++ trac/ticket/tests/query.py (working copy) @@ -1,4 +1,4 @@ -from trac.log import logger_factory +from trac.log import setup_logging from trac.mimeview import Context from trac.test import Mock, EnvironmentStub, MockPerm from trac.ticket.query import Query, QueryModule Index: trac/ticket/report.py =================================================================== --- trac/ticket/report.py (revision 7412) +++ trac/ticket/report.py (working copy) @@ -547,7 +547,7 @@ # The column name is obtained. get_col_name_sql = 'SELECT * FROM ( ' + sql + ' ) AS tab LIMIT 1' cursor.execute(get_col_name_sql, args) - self.env.log.debug("Query SQL(Get col names): " + get_col_name_sql) + self.log.debug("Query SQL(Get col names): " + get_col_name_sql) cols = get_column_names(cursor) sort_col = req.args.get('sort', '') Index: trac/ticket/model.py =================================================================== --- trac/ticket/model.py (revision 7412) +++ trac/ticket/model.py (working copy) @@ -40,6 +40,7 @@ def __init__(self, env, tkt_id=None, db=None, version=None): self.env = env + self.log = self.env.get_logger(__name__) self.resource = Resource('ticket', tkt_id, version) self.fields = TicketSystem(self.env).get_ticket_fields() self.values = {} @@ -77,9 +78,9 @@ try: default = options[int(default)] except (ValueError, IndexError): - self.env.log.warning('Invalid default value "%s" ' - 'for custom field "%s"' - % (default, field['name'])) + self.log.warning('Invalid default value "%s" for ' + 'custom field "%s"', default, + field['name']) if default: self.values.setdefault(field['name'], default) @@ -350,6 +351,7 @@ if not self.ticket_col: self.ticket_col = self.type self.env = env + self.log = self.env.get_logger(__name__) if name: name = simplify_whitespace(name) if name: @@ -379,7 +381,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Deleting %s %s' % (self.type, self.name)) + self.log.info('Deleting %s %s', self.type, self.name) cursor.execute("DELETE FROM enum WHERE type=%s AND value=%s", (self.type, self._old_value)) # Re-order any enums that have higher value than deleted (close gap) @@ -407,7 +409,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.debug("Creating new %s '%s'" % (self.type, self.name)) + self.log.debug("Creating new %s '%s'", self.type, self.name) if not self.value: cursor.execute(("SELECT COALESCE(MAX(%s),0) FROM enum " "WHERE type=%%s") % db.cast('value', 'int'), @@ -432,7 +434,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Updating %s "%s"' % (self.type, self.name)) + self.log.info('Updating %s "%s"', self.type, self.name) cursor.execute("UPDATE enum SET name=%s,value=%s " "WHERE type=%s AND name=%s", (self.name, self.value, self.type, self._old_name)) @@ -494,6 +496,7 @@ def __init__(self, env, name=None, db=None): self.env = env + self.log = self.env.get_logger(__name__) if name: name = simplify_whitespace(name) if name: @@ -525,7 +528,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Deleting component %s' % self.name) + self.log.info('Deleting component %s', self.name) cursor.execute("DELETE FROM component WHERE name=%s", (self.name,)) self.name = self._old_name = None @@ -544,7 +547,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.debug("Creating new component '%s'" % self.name) + self.log.debug("Creating new component '%s'", self.name) cursor.execute("INSERT INTO component (name,owner,description) " "VALUES (%s,%s,%s)", (self.name, self.owner, self.description)) @@ -563,7 +566,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Updating component "%s"' % self.name) + self.log.info('Updating component "%s"', self.name) cursor.execute("UPDATE component SET name=%s,owner=%s,description=%s " "WHERE name=%s", (self.name, self.owner, self.description, @@ -596,6 +599,7 @@ def __init__(self, env, name=None, db=None): self.env = env + self.log = self.env.get_logger(__name__) if name: self._fetch(name, db) self._old_name = name @@ -641,7 +645,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Deleting milestone %s' % self.name) + self.log.info('Deleting milestone %s', self.name) cursor.execute("DELETE FROM milestone WHERE name=%s", (self.name,)) # Retarget/reset tickets associated with this milestone @@ -667,7 +671,7 @@ self.name = simplify_whitespace(self.name) cursor = db.cursor() - self.env.log.debug("Creating new milestone '%s'" % self.name) + self.log.debug("Creating new milestone '%s'", self.name) cursor.execute("INSERT INTO milestone (name,due,completed,description) " "VALUES (%s,%s,%s,%s)", (self.name, to_timestamp(self.due), to_timestamp(self.completed), @@ -686,14 +690,14 @@ self.name = simplify_whitespace(self.name) cursor = db.cursor() - self.env.log.info('Updating milestone "%s"' % self.name) + self.log.info('Updating milestone "%s"', self.name) cursor.execute("UPDATE milestone SET name=%s,due=%s," "completed=%s,description=%s WHERE name=%s", (self.name, to_timestamp(self.due), to_timestamp(self.completed), self.description, self._old_name)) - self.env.log.info('Updating milestone field of all tickets ' - 'associated with milestone "%s"' % self.name) + self.log.info('Updating milestone field of all tickets associated ' + 'with milestone "%s"', self.name) cursor.execute("UPDATE ticket SET milestone=%s WHERE milestone=%s", (self.name, self._old_name)) self._old_name = self.name @@ -726,6 +730,7 @@ def __init__(self, env, name=None, db=None): self.env = env + self.log = self.env.get_logger(__name__) if name: if not db: db = self.env.get_db_cnx() @@ -755,7 +760,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Deleting version %s' % self.name) + self.log.info('Deleting version %s', self.name) cursor.execute("DELETE FROM version WHERE name=%s", (self.name,)) self.name = self._old_name = None @@ -774,7 +779,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.debug("Creating new version '%s'" % self.name) + self.log.debug("Creating new version '%s'", self.name) cursor.execute("INSERT INTO version (name,time,description) " "VALUES (%s,%s,%s)", (self.name, to_timestamp(self.time), self.description)) @@ -793,7 +798,7 @@ handle_ta = False cursor = db.cursor() - self.env.log.info('Updating version "%s"' % self.name) + self.log.info('Updating version "%s"', self.name) cursor.execute("UPDATE version SET name=%s,time=%s,description=%s " "WHERE name=%s", (self.name, to_timestamp(self.time), self.description, Index: trac/ticket/roadmap.py =================================================================== --- trac/ticket/roadmap.py (revision 7412) +++ trac/ticket/roadmap.py (working copy) @@ -648,8 +648,8 @@ cursor.execute("UPDATE ticket SET milestone=%s WHERE " "milestone=%s and status != 'closed'", (retarget_to, old_name)) - self.env.log.info('Tickets associated with milestone %s ' - 'retargeted to %s' % (old_name, retarget_to)) + self.log.info('Tickets associated with milestone %s ' + 'retargeted to %s' % (old_name, retarget_to)) else: milestone.insert() db.commit() Index: trac/ticket/query.py =================================================================== --- trac/ticket/query.py (revision 7412) +++ trac/ticket/query.py (working copy) @@ -53,6 +53,7 @@ order=None, desc=0, group=None, groupdesc=0, verbose=0, rows=None, page=None, max=None): self.env = env + self.log = self.env.get_logger(__name__) self.id = report # if not None, it's the corresponding saved query self.constraints = constraints or {} self.order = order @@ -235,14 +236,14 @@ cursor = db.cursor() count_sql = 'SELECT COUNT(*) FROM (' + sql + ') AS foo' - # self.env.log.debug("Count results in Query SQL: " + count_sql % - # tuple([repr(a) for a in args])) + # self.log.debug("Count results in Query SQL: " + count_sql % + # tuple([repr(a) for a in args])) cnt = 0 cursor.execute(count_sql, args); for cnt, in cursor: break - self.env.log.debug("Count results in Query: %d" % cnt) + self.log.debug("Count results in Query: %d", cnt) return cnt def execute(self, req, db=None, cached_ids=None): @@ -266,7 +267,7 @@ raise TracError(_('Page %(page)s is beyond the number of ' 'pages in the query', page=self.page)) - self.env.log.debug("Query SQL: " + sql % tuple([repr(a) for a in args])) + self.log.debug("Query SQL: " + sql % tuple([repr(a) for a in args])) cursor.execute(sql, args) columns = get_column_names(cursor) fields = [] Index: trac/htdocs/css/admin.css =================================================================== --- trac/htdocs/css/admin.css (revision 7412) +++ trac/htdocs/css/admin.css (working copy) @@ -21,7 +21,7 @@ #tabcontent { padding: 0.4em 2em; margin-left: 12em; min-height: 300px; } #tabcontent h2 { color: #333; margin-top: 0; } -p.help { color: #666; font-size: 90%; margin: 1em .5em .5em; } +div.help, p.help { color: #666; font-size: 90%; margin: 1em .5em .5em; } #enumlist tbody td { vertical-align: middle; } Index: trac/db/mysql_backend.py =================================================================== --- trac/db/mysql_backend.py (revision 7412) +++ trac/db/mysql_backend.py (working copy) @@ -87,7 +87,7 @@ from trac.db_default import schema for table in schema: for stmt in self.to_sql(table): - self.env.log.debug(stmt) + self.log.debug(stmt) cursor.execute(stmt) cnx.commit() Index: trac/versioncontrol/tests/svn_fs.py =================================================================== --- trac/versioncontrol/tests/svn_fs.py (revision 7412) +++ trac/versioncontrol/tests/svn_fs.py (working copy) @@ -30,7 +30,7 @@ except: has_svn = False -from trac.log import logger_factory +from trac.log import setup_logging from trac.test import TestSetup from trac.core import TracError from trac.util.datefmt import utc @@ -85,7 +85,7 @@ def setUp(self): self.repos = SubversionRepository(REPOS_PATH, None, - logger_factory('test')) + setup_logging('test')) def tearDown(self): self.repos = None @@ -460,7 +460,7 @@ def setUp(self): self.repos = SubversionRepository(REPOS_PATH + '/trunk', None, - logger_factory('test')) + setup_logging('test')) def tearDown(self): self.repos = None @@ -688,7 +688,7 @@ def setUp(self): self.repos = SubversionRepository(REPOS_PATH + '/trunk/dir1', None, - logger_factory('test')) + setup_logging('test')) def tearDown(self): self.repos = None @@ -708,7 +708,7 @@ def setUp(self): self.repos = SubversionRepository(REPOS_PATH + '/tags/v1', None, - logger_factory('test')) + setup_logging('test')) def tearDown(self): self.repos = None @@ -726,7 +726,7 @@ def setUp(self): self.repos = SubversionRepository(REPOS_PATH + '/branches', None, - logger_factory('test')) + setup_logging('test')) def tearDown(self): self.repos = None Index: trac/versioncontrol/tests/cache.py =================================================================== --- trac/versioncontrol/tests/cache.py (revision 7412) +++ trac/versioncontrol/tests/cache.py (working copy) @@ -16,7 +16,7 @@ from datetime import datetime -from trac.log import logger_factory +from trac.log import setup_logging from trac.test import Mock, InMemoryDatabase from trac.util.datefmt import to_timestamp, utc from trac.versioncontrol import Repository, Changeset, Node, NoSuchChangeset @@ -30,7 +30,7 @@ def setUp(self): self.db = InMemoryDatabase() - self.log = logger_factory('test') + self.log = setup_logging('test') cursor = self.db.cursor() cursor.execute("INSERT INTO system (name, value) VALUES (%s,%s)", ('youngest_rev', '')) Index: trac/admin/web_ui.py =================================================================== --- trac/admin/web_ui.py (revision 7412) +++ trac/admin/web_ui.py (working copy) @@ -2,6 +2,7 @@ # # Copyright (C) 2005-2008 Edgewall Software # Copyright (C) 2005 Jonas Borgström +# Copyright (C) 2008 Pedro Algarvio # All rights reserved. # # This software is licensed as described in the file COPYING, which @@ -215,6 +216,11 @@ log_level = self.env.log_level log_file = self.env.log_file log_dir = os.path.join(self.env.path, 'log') + log_filters = self.config.getlist('logging', 'log_filters') + for idx, filter in enumerate(log_filters): + filter = filter.split(':') + if not (len(filter) > 1 and filter[1]): + log_filters[idx] = "%s:%s" % (filter[0], log_level) log_types = [ dict(name='', label=_('None'), selected=False, disabled=False), @@ -233,46 +239,77 @@ if req.method == 'POST': changed = False - - new_type = req.args.get('log_type') - if new_type and new_type not in ('stderr', 'file', 'syslog', - 'eventlog'): - raise TracError( - _('Unknown log type %(type)s', type=new_type), - _('Invalid log type') - ) - if new_type != log_type: - self.config.set('logging', 'log_type', new_type or 'none') + if 'add_filter' in req.args: + filter_module_name = req.args.get('filter_modname') + if not filter_module_name: + raise TracError(_("Filter module name must not be empty")) + filter_log_level = req.args.get('filter_loglevel') + if filter_log_level and filter_log_level not in log_levels: + raise TracError(_('Unknown log level %(level)s', + level=filter_log_level), + _('Invalid log level')) + for filter in log_filters: + if filter.split(':')[0] == filter_module_name or \ + filter.split(':')[0].rstrip('.*') == filter_module_name: + raise TracError( + _("A filter for module '%(module)s' already exists." + " Remove that one first.", + module=filter_module_name), + _("Filter already exists")) + new_log_filter = "%s:%s" % (filter_module_name.rstrip('.*'), + filter_log_level) + log_filters.append(new_log_filter) + self.log.debug("Adding new filter '%s' to log_filters", + new_log_filter) + self.config.set('logging', 'log_filters',', '.join(log_filters)) changed = True - log_type = new_type - - if log_type: - new_level = req.args.get('log_level') - if new_level and new_level not in log_levels: + elif 'delete_filters' in req.args: + selected = req.args.getlist('sel') + for filter in selected: + self.log.debug("Removing filter '%s' from log_filters", + filter) + log_filters.pop(log_filters.index(filter)) + self.config.set('logging', 'log_filters',', '.join(log_filters)) + changed = True + else: + new_type = req.args.get('log_type') + if new_type and new_type not in ('stderr', 'file', 'syslog', + 'eventlog'): raise TracError( - _('Unknown log level %(level)s', level=new_level), - _('Invalid log level')) - if new_level and new_level != log_level: - self.config.set('logging', 'log_level', new_level) + _('Unknown log type %(type)s', type=new_type), + _('Invalid log type') + ) + if new_type != log_type: + self.config.set('logging', 'log_type', new_type or 'none') changed = True - log_evel = new_level - else: - self.config.remove('logging', 'log_level') - changed = True + log_type = new_type - if log_type == 'file': - new_file = req.args.get('log_file', 'trac.log') - if new_file != log_file: - self.config.set('logging', 'log_file', new_file or '') + if log_type: + new_level = req.args.get('log_level') + if new_level and new_level not in log_levels: + raise TracError( + _('Unknown log level %(level)s', level=new_level), + _('Invalid log level')) + if new_level and new_level != log_level: + self.config.set('logging', 'log_level', new_level) + changed = True + log_evel = new_level + else: + self.config.remove('logging', 'log_level') changed = True - log_file = new_file - if log_type == 'file' and not log_file: - raise TracError(_('You must specify a log file'), - _('Missing field')) - else: - self.config.remove('logging', 'log_file') - changed = True + if log_type == 'file': + new_file = req.args.get('log_file', 'trac.log') + if new_file != log_file: + self.config.set('logging', 'log_file', new_file or '') + changed = True + log_file = new_file + if log_type == 'file' and not log_file: + raise TracError(_('You must specify a log file'), + _('Missing field')) + else: + self.config.remove('logging', 'log_file') + changed = True if changed: self.config.save() req.redirect(req.href.admin(cat, page)) @@ -280,7 +317,8 @@ data = { 'type': log_type, 'types': log_types, 'level': log_level, 'levels': log_levels, - 'file': log_file, 'dir': log_dir + 'file': log_file, 'dir': log_dir, + 'filters': log_filters } return 'admin_logging.html', {'log': data} Index: trac/admin/tests/console.py =================================================================== --- trac/admin/tests/console.py (revision 7412) +++ trac/admin/tests/console.py (working copy) @@ -71,8 +71,8 @@ return True def setup_log(self): - from trac.log import logger_factory - self.log = logger_factory('null') + from trac.log import setup_logging + self.log = setup_logging('null') def is_component_enabled(self, cls): return cls.__module__.startswith('trac.') and \ Index: trac/admin/templates/admin_logging.html =================================================================== --- trac/admin/templates/admin_logging.html (revision 7412) +++ trac/admin/templates/admin_logging.html (working copy) @@ -54,6 +54,92 @@ + +
+ Logging Filters + +
+
+ Add New Logging Filter + + + + + + + + + +
+ +
+
+ +
+
+
+ +

If nothing set, logging will be as it was, nothing is + changed.

+ +
+
+ + + + + + + + + + + + + + + + + + +
 ModuleLog level
$mod$level
+
No Filters Available
+
+
+
+ +
+ +
+

Example usage is:

+
+  [logging]
+  log_filters = trac:WARNING, trac.ticket:DEBUG
+
+

The above would translate to:

+
    +
  • all messages who's module name starts with trac + and log level is higher than WARNING are logged;
    • + +
  • all messages who's module name starts with trac.ticket + and log level is higher than DEBUG are logged;
    • + +
  • all other messages who's module name does not start with either + trac or trac.ticket will be logged if + their level is higher than the default log_level;
    • +
+ +

This way you can narrow the debugging messages to the modules you wish to.

+

The same applies to a plugin you're coding:

+
+  [logging]
+  log_filters = trac:ERROR, my.plug.module:DEBUG
+
+
+
+
Index: trac/perm.py =================================================================== --- trac/perm.py (revision 7412) +++ trac/perm.py (working copy) @@ -224,7 +224,7 @@ cursor = db.cursor() cursor.execute("INSERT INTO permission VALUES (%s, %s)", (username, action)) - self.log.info('Granted permission for %s to %s' % (action, username)) + self.log.info('Granted permission for %s to %s', action, username) db.commit() def revoke_permission(self, username, action): @@ -233,7 +233,7 @@ cursor = db.cursor() cursor.execute("DELETE FROM permission WHERE username=%s AND action=%s", (username, action)) - self.log.info('Revoked permission for %s to %s' % (action, username)) + self.log.info('Revoked permission for %s to %s', action, username) db.commit() @@ -424,12 +424,12 @@ perm) if decision is not None: if not decision: - self.log.debug("%s denies %s performing %s on %r" % - (policy.__class__.__name__, username, - action, resource)) + self.log.debug("%s denies %s performing %s on %r", + policy.__class__.__name__, username, + action, resource) return decision - self.log.debug("No policy allowed %s performing %s on %r" % - (username, action, resource)) + self.log.debug("No policy allowed %s performing %s on %r", + username, action, resource) return False # IPermissionRequestor methods @@ -548,8 +548,8 @@ def permissions(self): """Deprecated (but still used by the HDF compatibility layer)""" - self.env.log.warning('perm.permissions() is deprecated and ' - 'is only present for HDF compatibility') + self.log.warning('perm.permissions() is deprecated and ' + 'is only present for HDF compatibility') perm = PermissionSystem(self.env) actions = perm.get_user_permissions(self.username) return [action for action in actions if action in self] Index: trac/loader.py =================================================================== --- trac/loader.py (revision 7412) +++ trac/loader.py (working copy) @@ -39,29 +39,30 @@ distributions, errors = working_set.find_plugins( pkg_resources.Environment(search_path) ) + log = env.get_logger(__name__) for dist in distributions: - env.log.debug('Adding plugin %s from %s', dist, dist.location) + log.debug('Adding plugin %s from %s', dist, dist.location) working_set.add(dist) def _log_error(item, e): if isinstance(e, DistributionNotFound): - env.log.debug('Skipping "%s": ("%s" not found)', item, e) + log.debug('Skipping "%s": ("%s" not found)', item, e) elif isinstance(e, VersionConflict): - env.log.error('Skipping "%s": (version conflict "%s")', - item, e) + log.error('Skipping "%s": (version conflict "%s")', + item, e) elif isinstance(e, UnknownExtra): - env.log.error('Skipping "%s": (unknown extra "%s")', item, e) + log.error('Skipping "%s": (unknown extra "%s")', item, e) elif isinstance(e, ImportError): - env.log.error('Skipping "%s": (can\'t import "%s")', item, e) + log.error('Skipping "%s": (can\'t import "%s")', item, e) else: - env.log.error('Skipping "%s": (error "%s")', item, e) + log.error('Skipping "%s": (error "%s")', item, e) for dist, e in errors.iteritems(): _log_error(dist, e) for entry in working_set.iter_entry_points(entry_point_name): - env.log.debug('Loading %s from %s', entry.name, - entry.dist.location) + log.debug('Loading %s from %s', entry.name, + entry.dist.location) try: entry.load(require=True) except (ImportError, DistributionNotFound, VersionConflict, @@ -78,20 +79,21 @@ manager if they define any components. """ def _load_py_files(env, search_path, auto_enable=None): + log = env.get_logger(__name__) for path in search_path: plugin_files = glob(os.path.join(path, '*.py')) for plugin_file in plugin_files: try: plugin_name = os.path.basename(plugin_file[:-3]) - env.log.debug('Loading file plugin %s from %s' % \ - (plugin_name, plugin_file)) + log.debug('Loading file plugin %s from %s', + plugin_name, plugin_file) if plugin_name not in sys.modules: module = imp.load_source(plugin_name, plugin_file) if path == auto_enable: _enable_plugin(env, plugin_name) except Exception, e: - env.log.error('Failed to load plugin from %s', plugin_file, - exc_info=True) + log.error('Failed to load plugin from %s', plugin_file, + exc_info=True) return _load_py_files Index: trac/tests/attachment.py =================================================================== --- trac/tests/attachment.py (revision 7412) +++ trac/tests/attachment.py (working copy) @@ -7,7 +7,7 @@ import time from trac.attachment import Attachment, AttachmentModule -from trac.log import logger_factory +from trac.log import setup_logging from trac.test import EnvironmentStub, Mock from trac.wiki.formatter import Formatter Index: trac/wiki/model.py =================================================================== --- trac/wiki/model.py (revision 7412) +++ trac/wiki/model.py (working copy) @@ -47,6 +47,7 @@ self.readonly = 0 self.old_text = self.text self.old_readonly = self.readonly + self.log = self.env.get_logger(__name__) def _fetch(self, name, version=None, db=None): if not db: @@ -91,12 +92,12 @@ if version is None: # Delete a wiki page completely cursor.execute("DELETE FROM wiki WHERE name=%s", (self.name,)) - self.env.log.info('Deleted page %s' % self.name) + self.log.info('Deleted page %s' % self.name) else: # Delete only a specific page version cursor.execute("DELETE FROM wiki WHERE name=%s and version=%s", (self.name, version)) - self.env.log.info('Deleted version %d of page %s' + self.log.info('Deleted version %d of page %s' % (version, self.name)) if version is None or version == self.version: Index: trac/wiki/formatter.py =================================================================== --- trac/wiki/formatter.py (revision 7412) +++ trac/wiki/formatter.py (working copy) @@ -74,6 +74,7 @@ """ self.formatter = formatter self.env = formatter.env + self.log = self.env.get_logger(__name__) self.name = name self.args = args self.error = None @@ -127,7 +128,7 @@ stream = Stream(HTMLParser(StringIO(text))) return (stream | self._sanitizer).render('xhtml', encoding=None) except ParseError, e: - self.env.log.warn(e) + self.log.warn(e) line = unicode(text).splitlines()[e.lineno - 1].strip() return system_message(_('HTML parsing error: %(message)s', message=escape(e.msg)), line) @@ -154,14 +155,14 @@ # generic processors def _legacy_macro_processor(self, text): # TODO: remove in 0.12 - self.env.log.warning('Executing pre-0.11 Wiki macro %s by provider %s' - % (self.name, self.macro_provider)) + self.log.warning('Executing pre-0.11 Wiki macro %s by provider %s', + self.name, self.macro_provider) return self.macro_provider.render_macro(self.formatter.req, self.name, text) def _macro_processor(self, text): - self.env.log.debug('Executing Wiki macro %s by provider %s' - % (self.name, self.macro_provider)) + self.log.debug('Executing Wiki macro %s by provider %s', + self.name, self.macro_provider) return self.macro_provider.expand_macro(self.formatter, self.name, text) @@ -225,6 +226,7 @@ def __init__(self, env, context): """Note: `req` is still temporarily used.""" self.env = env + self.log = self.env.get_logger(__name__) self.context = context self.req = context.req self.href = context.href @@ -467,8 +469,7 @@ macro = WikiProcessor(self, name) return macro.process(args, in_paragraph=True) except Exception, e: - self.env.log.error('Macro %s(%s) failed' % (name, args), - exc_info=True) + self.log.error('Macro %s(%s) failed', name, args, exc_info=True) return system_message('Error: Macro %s(%s) failed' % (name, args), e) Index: trac/test.py =================================================================== --- trac/test.py (revision 7412) +++ trac/test.py (working copy) @@ -186,8 +186,8 @@ # better solution than this. load_workflow_config_snippet(self.config, 'basic-workflow.ini') - from trac.log import logger_factory - self.log = logger_factory('test') + from trac.log import setup_logging + self.log = setup_logging(logid='test') from trac.web.href import Href self.href = Href('/trac.cgi') Index: trac/log.py =================================================================== --- trac/log.py (revision 7412) +++ trac/log.py (working copy) @@ -3,6 +3,7 @@ # Copyright (C) 2003-2008 Edgewall Software # Copyright (C) 2003-2005 Daniel Lundin # Copyright (C) 2006 Christian Boos +# Copyright (C) 2008 Pedro Algarvio # All rights reserved. # # This software is licensed as described in the file COPYING, which @@ -19,16 +20,20 @@ import logging.handlers import sys -def logger_factory(logtype='syslog', logfile=None, level='WARNING', - logid='Trac', format=None): - logger = logging.getLogger(logid) +from trac.util.compat import sorted +from trac.util.translation import _ + + +def setup_logging(logtype='syslog', logfile=None, level='WARNING', logid='Trac', + format=None, filters=()): + env_root_logger = logging.getLogger(logid) + logtype = logtype.lower() if logtype == 'file': hdlr = logging.FileHandler(logfile) elif logtype in ('winlog', 'eventlog', 'nteventlog'): # Requires win32 extensions - hdlr = logging.handlers.NTEventLogHandler(logid, - logtype='Application') + hdlr = logging.handlers.NTEventLogHandler(logid, logtype='Application') elif logtype in ('syslog', 'unix'): hdlr = logging.handlers.SysLogHandler('/dev/log') elif logtype in ('stderr'): @@ -47,20 +52,87 @@ datefmt = '%X' level = level.upper() if level in ('DEBUG', 'ALL'): - logger.setLevel(logging.DEBUG) + env_root_logger.setLevel(logging.DEBUG) elif level == 'INFO': - logger.setLevel(logging.INFO) + env_root_logger.setLevel(logging.INFO) elif level == 'ERROR': - logger.setLevel(logging.ERROR) + env_root_logger.setLevel(logging.ERROR) elif level == 'CRITICAL': - logger.setLevel(logging.CRITICAL) + env_root_logger.setLevel(logging.CRITICAL) else: - logger.setLevel(logging.WARNING) - formatter = logging.Formatter(format, datefmt) - hdlr.setFormatter(formatter) - logger.addHandler(hdlr) + env_root_logger.setLevel(logging.WARNING) + hdlr.setFormatter(TracFormatter(logid, format, datefmt)) + # Assign handler right away to be able to log filter errors + env_root_logger.addHandler(hdlr) + + if filters: + hdlr.addFilter(TracFilter(filters, level, logid)) + # Remember our handler so that we can remove it later - logger._trac_handler = hdlr + env_root_logger._trac_handler = hdlr + + # Return env logger for tests that expect it + # For components, they will have self.log + # For classes/functions which get passed an env use env.get_logger(__name__) + return env_root_logger + + +class TracFilter(logging.Filter): + def __init__(self, trac_filters=(), default_level='DEBUG', name=''): + self.qns = [] + for filter in trac_filters: + filter = filter.split(':') + if len(filter) > 1 and filter[1]: + qn, lvl = filter[0].rstrip('.*'), filter[1] + else: + qn, lvl = filter[0].rstrip('.*'), default_level + path_and_qn = "%s.%s" % (name, qn) + + if lvl == 'ALL': + lvl = 'DEBUG' + + if lvl not in logging._levelNames: + logging.getLogger("%s.%s" % (name, __name__)).warning( + _("Level '%(level)s' for filter '%(filter)s' not know. " + "Ignoring filter.", + level=lvl.upper(), filter=':'.join(filter))) + continue + + self.qns.append((path_and_qn, logging.getLevelName(lvl.upper()))) + + self.qns = sorted(self.qns, key=lambda x: len(x[0]), reverse=True) + + logging.Filter.__init__(self, name) + + def filter(self, record): + for qn, level in self.qns: + if record.name.startswith("%s." % qn) or record.name == qn: + # Match trac, trac.web but not tracforge + if level <= record.levelno: + return 1 + return 0 + # No point returning `logging.Filter.filter(self, record)` + # All logging messages will arrive to the filter with self.name at + # least equal to environment path, ie, self.name + return 1 + + +class TracFormatter(logging.Formatter): + + def __init__(self, env_path, fmt, datefmt): + self.env_path = env_path + # Calculate strip length at init time, no need to keep calculating it + self.strip_length = len(env_path)+1 + logging.Formatter.__init__(self, fmt, datefmt) + + def format(self, record): + # get full dotted module name and stick that under record.module + if record.name.startswith(self.env_path): + record.module = record.name[self.strip_length:] + return logging.Formatter.format(self, record) - return logger +def get_logger(env_path, name): + """Helper function to get the correct logger for the passed class or + env and name.""" + return logging.getLogger("%s.%s" % (env_path, name)) Index: trac/web/tests/session.py =================================================================== --- trac/web/tests/session.py (revision 7412) +++ trac/web/tests/session.py (working copy) @@ -3,7 +3,7 @@ import unittest from trac.core import TracError -from trac.log import logger_factory +from trac.log import setup_logging from trac.test import EnvironmentStub, Mock from trac.web.href import Href from trac.web.session import DetachedSession, Session, PURGE_AGE, UPDATE_INTERVAL Index: trac/web/session.py =================================================================== --- trac/web/session.py (revision 7412) +++ trac/web/session.py (working copy) @@ -33,6 +33,7 @@ def __init__(self, env, sid): dict.__init__(self) self.env = env + self.log = self.env.get_logger(__name__) self.sid = None self.last_visit = 0 self._new = True @@ -43,7 +44,7 @@ self.authenticated = False def get_session(self, sid, authenticated=False): - self.env.log.debug('Retrieving session for ID %r', sid) + self.log.debug('Retrieving session for ID %r', sid) db = self.env.get_db_cnx() cursor = db.cursor() @@ -111,14 +112,14 @@ # so that session doesn't get purged if now - self.last_visit > UPDATE_INTERVAL: self.last_visit = now - self.env.log.info("Refreshing session %s" % self.sid) + self.log.info("Refreshing session %s", self.sid) cursor.execute('UPDATE session SET last_visit=%s ' 'WHERE sid=%s AND authenticated=%s', (self.last_visit, self.sid, authenticated)) # Purge expired sessions. We do this only when the session was # changed as to minimize the purging. mintime = now - PURGE_AGE - self.env.log.debug('Purging old, expired, sessions.') + self.log.debug('Purging old, expired, sessions.') cursor.execute("DELETE FROM session_attribute " "WHERE authenticated=0 AND sid " "IN (SELECT sid FROM session WHERE " @@ -182,7 +183,7 @@ raise TracError(Markup('Session "%s" already exists.
' 'Please choose a different session ID.') % new_sid, 'Error renaming session') - self.env.log.debug('Changing session ID %s to %s' % (self.sid, new_sid)) + self.log.debug('Changing session ID %s to %s', self.sid, new_sid) cursor.execute("UPDATE session SET sid=%s WHERE sid=%s " "AND authenticated=0", (new_sid, self.sid)) cursor.execute("UPDATE session_attribute SET sid=%s " @@ -216,9 +217,9 @@ if not authenticated_flags[0]: # Update the anomymous session records so that the session ID # becomes the user name, and set the authenticated flag. - self.env.log.debug('Promoting anonymous session %s to ' - 'authenticated session for user %s', - sid, self.req.authname) + self.log.debug('Promoting anonymous session %s to ' + 'authenticated session for user %s', + sid, self.req.authname) cursor.execute("UPDATE session SET sid=%s,authenticated=1 " "WHERE sid=%s AND authenticated=0", (self.req.authname, sid)) Index: trac/web/main.py =================================================================== --- trac/web/main.py (revision 7412) +++ trac/web/main.py (working copy) @@ -412,7 +412,8 @@ environ['trac.web.version'])) except TracError, e: env_error = e - + + log = env.get_logger(__name__) req = Request(environ, start_response) try: return _dispatch_request(req, env, env_error) @@ -426,15 +427,16 @@ # objects with a __del__ method caught in a cycle) ##gc.set_debug(gc.DEBUG_UNCOLLECTABLE) unreachable = gc.collect() - env.log.debug("%d unreachable objects found.", unreachable) + log.debug("%d unreachable objects found.", unreachable) ##uncollectable = len(gc.garbage) ##if uncollectable: ## del gc.garbage[:] - ## env.log.warn("%d uncollectable objects found.", uncollectable) + ## log.warn("%d uncollectable objects found.", uncollectable) def _dispatch_request(req, env, env_error): resp = [] + log = env.get_logger(__name__) # fixup env.abs_href if `[trac] base_url` was not specified if env and not env.abs_href.base: env._abs_href = req.abs_href @@ -451,7 +453,7 @@ except HTTPException, e: if env: - env.log.warn(e) + log.warn(e) title = 'Error' if e.reason: if 'error' in e.reason.lower(): @@ -467,7 +469,7 @@ except Exception, e: if env: - env.log.exception(e) + log.exception(e) exc_info = sys.exc_info() try: Index: trac/notification.py =================================================================== --- trac/notification.py (revision 7412) +++ trac/notification.py (working copy) @@ -114,6 +114,7 @@ def __init__(self, env): self.env = env + self.log = self.env.get_logger(__name__) self.config = env.config self.db = env.get_db_cnx() @@ -284,7 +285,7 @@ if domain: address = "%s@%s" % (address, domain) else: - self.env.log.info("Email address w/o domain: %s" % address) + self.log.info("Email address w/o domain: %s", address) return None mo = self.shortaddr_re.search(address) @@ -293,7 +294,7 @@ mo = self.longaddr_re.search(address) if mo: return mo.group(2) - self.env.log.info("Invalid email address: %s" % address) + self.log.info("Invalid email address: %s", address) return None def encode_header(self, key, value): @@ -371,7 +372,7 @@ # if there is not valid recipient, leave immediately if len(recipients) < 1: - self.env.log.info('no recipient for a ticket notification') + self.log.info('no recipient for a ticket notification') return pcc = accaddrs @@ -397,8 +398,8 @@ msg.set_charset(self._charset) self.add_headers(msg, headers); self.add_headers(msg, mime_headers); - self.env.log.info("Sending SMTP notification to %s:%d to %s" - % (self.smtp_server, self.smtp_port, recipients)) + self.log.info("Sending SMTP notification to %s:%d to %s", + self.smtp_server, self.smtp_port, recipients) msgtext = msg.as_string() # Ensure the message complies with RFC2822: use CRLF line endings recrlf = re.compile("\r?\n")