- logging has been overhauled such that engines no longer need to encode the

"hex id" string in their logging name in order to maintain separate loggers
per engine. thanks to Vinay Sajip for assistance.  merge of [ticket:1926]

4 files changed, 150 insertions, 56 deletions

diff --git a/lib/sqlalchemy/dialects/postgresql/psycopg2.py b/lib/sqlalchemy/dialects/postgresql/psycopg2.py
index 7c5562064..88e6ce670 100644
--- a/lib/sqlalchemy/dialects/postgresql/psycopg2.py
+++ b/lib/sqlalchemy/dialects/postgresql/psycopg2.py
@@ -177,6 +177,7 @@ class PGExecutionContext_psycopg2(PGExecutionContext):
             return self._connection.connection.cursor()
 
     def get_result_proxy(self):
+        # TODO: ouch
         if logger.isEnabledFor(logging.INFO):
             self._log_notices(self.cursor)
         
diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index 326c33f2d..c07c83a07 100644
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -1624,7 +1624,7 @@ class Engine(Connectable, log.Identified):
             self.logging_name = logging_name
         self.echo = echo
         self.engine = self
-        self.logger = log.instance_logger(self, echoflag=echo)
+        log.instance_logger(self, echoflag=echo)
         if proxy:
 #            util.warn_deprecated("The 'proxy' argument to create_engine() is deprecated.  Use event.listen().")
             interfaces.ConnectionProxy._adapt_listener(self, proxy)
diff --git a/lib/sqlalchemy/log.py b/lib/sqlalchemy/log.py
index 49c779fed..4a97fcc42 100644
--- a/lib/sqlalchemy/log.py
+++ b/lib/sqlalchemy/log.py
@@ -1,5 +1,6 @@
 # log.py - adapt python logging module to SQLAlchemy
 # Copyright (C) 2006, 2007, 2008, 2009, 2010 Michael Bayer mike_mp@zzzcomputing.com
+# Includes alterations by Vinay Sajip vinay_sajip@yahoo.co.uk
 #
 # This module is part of SQLAlchemy and is released under
 # the MIT License: http://www.opensource.org/licenses/mit-license.php
@@ -10,41 +11,28 @@ Control of logging for SA can be performed from the regular python logging
 module.  The regular dotted module namespace is used, starting at
 'sqlalchemy'.  For class-level logging, the class name is appended.
 
-The "echo" keyword parameter which is available on SQLA ``Engine``
-and ``Pool`` objects corresponds to a logger specific to that 
+The "echo" keyword parameter, available on SQLA :class:`.Engine`
+and :class:`.Pool` objects, corresponds to a logger specific to that 
 instance only.
 
-E.g.::
-
-    engine.echo = True
-
-is equivalent to::
-
-    import logging
-    logger = logging.getLogger('sqlalchemy.engine.Engine.%s' % hex(id(engine)))
-    logger.setLevel(logging.DEBUG)
-    
 """
 
 import logging
 import sys
 from sqlalchemy import util
 
+# set initial level to WARN.  This so that
+# log statements don't occur in the absense of explicit
+# logging being enabled for 'sqlalchemy'.
 rootlogger = logging.getLogger('sqlalchemy')
 if rootlogger.level == logging.NOTSET:
     rootlogger.setLevel(logging.WARN)
 
-default_enabled = False
-def default_logging(name):
-    global default_enabled
-    if logging.getLogger(name).getEffectiveLevel() < logging.WARN:
-        default_enabled = True
-    if not default_enabled:
-        default_enabled = True
-        handler = logging.StreamHandler(sys.stdout)
-        handler.setFormatter(logging.Formatter(
-            '%(asctime)s %(levelname)s %(name)s %(message)s'))
-        rootlogger.addHandler(handler)
+def _add_default_handler(logger):
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(logging.Formatter(
+        '%(asctime)s %(levelname)s %(name)s %(message)s'))
+    logger.addHandler(handler)
 
 _logged_classes = set()
 def class_logger(cls, enable=False):
@@ -60,43 +48,149 @@ def class_logger(cls, enable=False):
     
 
 class Identified(object):
-    @util.memoized_property
-    def logging_name(self):
-        # limit the number of loggers by chopping off the hex(id).
-        # some novice users unfortunately create an unlimited number 
-        # of Engines in their applications which would otherwise
-        # cause the app to run out of memory.
-        return "0x...%s" % hex(id(self))[-4:]
+    logging_name = None
+    
+    def _should_log_debug(self):
+        return self.logger.isEnabledFor(logging.DEBUG)
+    
+    def _should_log_info(self):
+        return self.logger.isEnabledFor(logging.INFO)
 
+class InstanceLogger(object):
+    """A logger adapter (wrapper) for :class:`.Identified` subclasses.
     
-def instance_logger(instance, echoflag=None):
-    """create a logger for an instance that implements :class:`Identified`.
+    This allows multiple instances (e.g. Engine or Pool instances)
+    to share a logger, but have its verbosity controlled on a 
+    per-instance basis.
+
+    The basic functionality is to return a logging level
+    which is based on an instance's echo setting.
     
-    Warning: this is an expensive call which also results in a permanent
-    increase in memory overhead for each call.  Use only for 
-    low-volume, long-time-spanning objects.
+    Default implementation is:
     
+    'debug' -> logging.DEBUG
+    True    -> logging.INFO
+    False   -> Effective level of underlying logger
+               (logging.WARNING by default)
+    None    -> same as False
     """
 
-    name = "%s.%s.%s" % (instance.__class__.__module__,
-                       instance.__class__.__name__, instance.logging_name)
+    # Map echo settings to logger levels
+    _echo_map = {
+        None: logging.NOTSET,
+        False: logging.NOTSET,
+        True: logging.INFO,
+        'debug': logging.DEBUG,
+    }
+
+    def __init__(self, echo, name):
+        self.echo = echo
+        self.logger = logging.getLogger(name)
+        
+        # if echo flag is enabled and no handlers,
+        # add a handler to the list
+        if self._echo_map[echo] <= logging.INFO \
+            and not self.logger.handlers:
+            _add_default_handler(self.logger)
+
+    #
+    # Boilerplate convenience methods
+    #
+    def debug(self, msg, *args, **kwargs):
+        """Delegate a debug call to the underlying logger."""
+        
+        self.log(logging.DEBUG, msg, *args, **kwargs)
+
+    def info(self, msg, *args, **kwargs):
+        """Delegate an info call to the underlying logger."""
+        
+        self.log(logging.INFO, msg, *args, **kwargs)
+
+    def warning(self, msg, *args, **kwargs):
+        """Delegate a warning call to the underlying logger."""
+        
+        self.log(logging.WARNING, msg, *args, **kwargs)
+
+    warn = warning
+
+    def error(self, msg, *args, **kwargs):
+        """
+        Delegate an error call to the underlying logger.
+        """
+        self.log(logging.ERROR, msg, *args, **kwargs)
+
+    def exception(self, msg, *args, **kwargs):
+        """Delegate an exception call to the underlying logger."""
+        
+        kwargs["exc_info"] = 1
+        self.log(logging.ERROR, msg, *args, **kwargs)
+
+    def critical(self, msg, *args, **kwargs):
+        """Delegate a critical call to the underlying logger."""
+        
+        self.log(logging.CRITICAL, msg, *args, **kwargs)
+
+    def log(self, level, msg, *args, **kwargs):
+        """Delegate a log call to the underlying logger.
+        
+        The level here is determined by the echo
+        flag as well as that of the underlying logger, and
+        logger._log() is called directly.
+        
+        """
+
+        # inline the logic from isEnabledFor(),
+        # getEffectiveLevel(), to avoid overhead.
+        
+        if self.logger.manager.disable >= level:
+            return
+
+        selected_level = self._echo_map[self.echo]
+        if selected_level == logging.NOTSET:
+            selected_level = self.logger.getEffectiveLevel()
+
+        if level >= selected_level:
+            self.logger._log(level, msg, args, **kwargs)
+
+    def isEnabledFor(self, level):
+        """Is this logger enabled for level 'level'?"""
+        
+        if self.logger.manager.disable >= level:
+            return False
+        return level >= self.getEffectiveLevel()
+
+    def getEffectiveLevel(self):
+        """What's the effective level for this logger?"""
+        
+        level = self._echo_map[self.echo]
+        if level == logging.NOTSET:
+            level = self.logger.getEffectiveLevel()
+        return level
+
+def instance_logger(instance, echoflag=None):
+    """create a logger for an instance that implements :class:`Identified`."""
+
+    if instance.logging_name:
+        name = "%s.%s.%s" % (instance.__class__.__module__,
+                      instance.__class__.__name__, instance.logging_name)
+    else:
+        name = "%s.%s" % (instance.__class__.__module__,
+                  instance.__class__.__name__)
+        
+    instance._echo = echoflag
     
-    if echoflag is not None:
-        l = logging.getLogger(name)
-        if echoflag == 'debug':
-            default_logging(name)
-            l.setLevel(logging.DEBUG)
-        elif echoflag is True:
-            default_logging(name)
-            l.setLevel(logging.INFO)
-        elif echoflag is False:
-            l.setLevel(logging.WARN)
+    if echoflag in (False, None):
+        # if no echo setting or False, return a Logger directly,
+        # avoiding overhead of filtering
+        logger = logging.getLogger(name)
     else:
-        l = logging.getLogger(name)
-    instance._should_log_debug = lambda: l.isEnabledFor(logging.DEBUG)
-    instance._should_log_info = lambda: l.isEnabledFor(logging.INFO)
-    return l
-
+        # if a specified echo flag, return an EchoLogger,
+        # which checks the flag, overrides normal log 
+        # levels by calling logger._log()
+        logger = InstanceLogger(echoflag, name)
+            
+    instance.logger = logger
+    
 class echo_property(object):
     __doc__ = """\
     When ``True``, enable log output for this element.
@@ -112,8 +206,7 @@ class echo_property(object):
         if instance is None:
             return self
         else:
-            return instance._should_log_debug() and 'debug' or \
-                            (instance._should_log_info() and True or False)
+            return instance._echo
 
     def __set__(self, instance, value):
         instance_logger(instance, echoflag=value)
diff --git a/lib/sqlalchemy/pool.py b/lib/sqlalchemy/pool.py
index 4c8797fd5..e1dc06fe9 100644
--- a/lib/sqlalchemy/pool.py
+++ b/lib/sqlalchemy/pool.py
@@ -118,7 +118,7 @@ class Pool(log.Identified):
         else:
             self._orig_logging_name = None
             
-        self.logger = log.instance_logger(self, echoflag=echo)
+        log.instance_logger(self, echoflag=echo)
         self._threadconns = threading.local()
         self._creator = creator
         self._recycle = recycle