Ticket #7286: all-the-way_enhanced_logging.3.patch

trac/attachment.py

@@ -113 +113 @@
             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 +182 @@
             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 +235 @@
             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 +270 @@
         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 +279 @@
             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 +695 @@
             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 +773 @@
         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:

trac/env.py

@@ -2 +2 @@
 #
 # Copyright (C) 2003-2008 Edgewall Software
 # Copyright (C) 2003-2007 Jonas Borgström <jonas@edgewall.com>
+# Copyright (C) 2008 Pedro Algarvio <ufs@ufsoft.org>
 # All rights reserved.
 #
 # This software is licensed as described in the file COPYING, which
@@ -14 +15 @@
 #
 # Author: Jonas Borgström <jonas@edgewall.com>
 
+import logging
 import os
 try:
     import threading
@@ -147 +149 @@
          - $(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 +225 @@
         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 +379 @@
 
     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 +390 @@
                      .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 +614 @@
                 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:

trac/mimeview/enscript.py

@@ -136 +136 @@
         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:

trac/mimeview/php.py

@@ -81 +81 @@
     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')

trac/ticket/tests/query.py

@@ -1 @@
-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

trac/ticket/report.py

@@ -547 +547 @@
             # 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', '')

trac/ticket/model.py

@@ -40 +40 @@
 
     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 +78 @@
                     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 +351 @@
         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 +381 @@
             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 +409 @@
             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 +434 @@
             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 +496 @@
 
     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 +528 @@
             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 +547 @@
             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 +566 @@
             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 +599 @@
 
     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 +645 @@
             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 +671 @@
 
         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 +690 @@
 
         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 +730 @@
 
     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 +760 @@
             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 +779 @@
             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 +798 @@
             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,

trac/ticket/roadmap.py

@@ -648 +648 @@
                 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()

trac/ticket/query.py

@@ -53 +53 @@
                  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 +236 @@
         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 +267 @@
                 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 = []

trac/htdocs/css/admin.css

@@ -21 +21 @@
 
 #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; }
 

trac/db/mysql_backend.py

@@ -87 +87 @@
         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()
 

trac/versioncontrol/tests/svn_fs.py

@@ -30 +30 @@
 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 +85 @@
 
     def setUp(self):
         self.repos = SubversionRepository(REPOS_PATH, None,
-                                          logger_factory('test'))
+                                          setup_logging('test'))
 
     def tearDown(self):
         self.repos = None
@@ -460 +460 @@
 
     def setUp(self):
         self.repos = SubversionRepository(REPOS_PATH + '/trunk', None,
-                                          logger_factory('test'))
+                                          setup_logging('test'))
 
     def tearDown(self):
         self.repos = None
@@ -688 +688 @@
 
     def setUp(self):
         self.repos = SubversionRepository(REPOS_PATH + '/trunk/dir1', None,
-                                          logger_factory('test'))
+                                          setup_logging('test'))
 
     def tearDown(self):
         self.repos = None
@@ -708 +708 @@
 
     def setUp(self):
         self.repos = SubversionRepository(REPOS_PATH + '/tags/v1', None,
-                                          logger_factory('test'))
+                                          setup_logging('test'))
 
     def tearDown(self):
         self.repos = None
@@ -726 +726 @@
 
     def setUp(self):
         self.repos = SubversionRepository(REPOS_PATH + '/branches', None,
-                                          logger_factory('test'))
+                                          setup_logging('test'))
 
     def tearDown(self):
         self.repos = None

trac/versioncontrol/tests/cache.py

@@ -16 +16 @@
 
 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 +30 @@
 
     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', ''))

trac/admin/web_ui.py

@@ -2 +2 @@
 #
 # Copyright (C) 2005-2008 Edgewall Software
 # Copyright (C) 2005 Jonas Borgström <jonas@edgewall.com>
+# Copyright (C) 2008 Pedro Algarvio <ufs@ufsoft.org>
 # All rights reserved.