gistfile2.sh

vinay@zeta-lucid:~/tools/sqlalchemy$ diff /tmp/test1 /tmp/test2 
2633c2633
< AssertionError: 'SELECT users.id AS users_id, users.name AS users_name FROM users' != 'SELECT users.id AS users_id, users.name AS users_name FROM users USE INDEX (col1_index,col2_index)' on dialect <sqlalchemy.dialects.mysql.mysqldb.MySQLDialect_mysqldb object at 0xb0e3f0c>
---
> AssertionError: 'SELECT users.id AS users_id, users.name AS users_name FROM users' != 'SELECT users.id AS users_id, users.name AS users_name FROM users USE INDEX (col1_index,col2_index)' on dialect <sqlalchemy.dialects.mysql.mysqldb.MySQLDialect_mysqldb object at 0xbee3acc>
2643c2643
< Ran 2433 tests in 97.937s
---
> Ran 2433 tests in 117.417s

sa.diff

diff -r 37b592baa1b6 lib/sqlalchemy/log.py
--- a/lib/sqlalchemy/log.py	Wed Sep 22 23:48:17 2010 -0400
+++ b/lib/sqlalchemy/log.py	Thu Sep 23 13:52:12 2010 +0100
@@ -68,31 +68,129 @@
         # cause the app to run out of memory.
         return "0x...%s" % hex(id(self))[-4:]
 
+class InstanceLogger:
+    """
+    A logger adapter (wrapper) for 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)
-    
-    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)
-    else:
-        l = logging.getLogger(name)
+    # Map echo settings to logger levels
+    _echo_map = {
+        None: logging.NOTSET,
+        False: logging.NOTSET,
+        True: logging.INFO,
+        'debug': logging.DEBUG,
+    }
+
+    def __init__(self, instance, name):
+        self.instance = instance
+        self.logger = logging.getLogger(name)
+
+    def process(self, msg, kwargs):
+        """
+        Used to put context-specific information into the logs.
+        
+        The instance id is used here just as an example.
+        """
+        #kwargs["extra"] = { 'instance': hex(id(self.instance)) }
+        return msg, kwargs
+
+    #
+    # 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, after adding
+        contextual information from this adapter instance.
+        """
+        if self.isEnabledFor(level):
+            msg, kwargs = self.process(msg, kwargs)
+            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.instance.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`.    
+    """
+
+    name = "%s.%s" % (instance.__class__.__module__,
+                      instance.__class__.__name__)
+
+    # We store the echo value in the instance because we need to 
+    # return it in echo_property.__get__.
+    # Otherwise, echo_property.__get__ calls instance._should_log_debug
+    # which leads to unterminated recursion.
+    instance._echo = echoflag
+    l = InstanceLogger(instance, name)
     instance._should_log_debug = lambda: l.isEnabledFor(logging.DEBUG)
     instance._should_log_info = lambda: l.isEnabledFor(logging.INFO)
     return l
@@ -112,8 +210,9 @@
         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._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 -r 37b592baa1b6 test/engine/test_execute.py
--- a/test/engine/test_execute.py	Wed Sep 22 23:48:17 2010 -0400
+++ b/test/engine/test_execute.py	Thu Sep 23 13:52:12 2010 +0100
@@ -202,10 +202,9 @@
             log.removeHandler(buf)
         
         names = set([b.name for b in buf.buffer])
-        assert 'sqlalchemy.engine.base.Engine.%s' % (eng_name,) in names
-        assert 'sqlalchemy.pool.%s.%s' % (eng.pool.__class__.__name__,
-                pool_name) in names
-        
+        assert 'sqlalchemy.engine.base.Engine' in names
+        assert 'sqlalchemy.pool.%s' % (eng.pool.__class__.__name__) in names
+
     def test_named_logger(self):
         options = {'echo':'debug', 'echo_pool':'debug',
             'logging_name':'myenginename',

I had to change the unit tests for loggers, too.
I ran the unit tests before making any changes and piped the output to /tmp/test1.
After the changes, I ran the unit tests again and piped the output to /tmp/test2.
The diff between /tmp/test1 and /tmp/test2 shows that the results are effectively the same (w.r.t. the changes I made).