- logging scale-back; the echo_uow flag on Session is deprecated, and unit of work logging is now

class level like all the other logging.
- trimmed back the logging API, centralized class_logger() as the single point of configuration for
logging, removed per-instance logging checks from ORM.
- Engine and Pool logging remain at the instance level.  The modulus of "instance ids" has been upped
to 65535.  I'd like to remove the modulus altogether but I do see a couple of users each month
calling create_engine() on a per-request basis, an incorrect practice but I'd rather their applications
don't just run out of memory.

CHANGES

@@ -69,6 +69,9 @@ CHANGES
       may now be a mix of lists and tuples.  (Previously members
       were always lists.)
 
+    - The `echo_uow` flag on `Session` is deprecated, and unit-of-work
+      logging is now application-level only, not per-session level.
+      
 - schema
     - Added "sorted_tables" accessor to MetaData, which returns
       Table objects sorted in order of dependency as a list.

lib/sqlalchemy/databases/mysql.py

@@ -2664,7 +2664,7 @@ class MySQLSchemaReflector(object):
 
         return self._re_keyexprs.findall(identifiers)
 
-MySQLSchemaReflector.logger = log.class_logger(MySQLSchemaReflector)
+log.class_logger(MySQLSchemaReflector)
 
 
 class _MySQLIdentifierPreparer(compiler.IdentifierPreparer):

lib/sqlalchemy/databases/oracle.py

@@ -566,8 +566,6 @@ class OracleDialect(default.DefaultDialect):
             table.append_constraint(schema.ForeignKeyConstraint(value[0], value[1], name=name))
 
 
-OracleDialect.logger = log.class_logger(OracleDialect)
-
 class _OuterJoinColumn(sql.ClauseElement):
     __visit_name__ = 'outer_join_column'
     def __init__(self, column):

lib/sqlalchemy/log.py

@@ -6,16 +6,13 @@
 
 """Logging control and utilities.
 
-Provides a few functions used by instances to turn on/off their logging,
-including support for the usual "echo" parameter.
-
 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, and for
-instance-level logging, the hex id of the instance is appended.
+'sqlalchemy'.  For class-level logging, the class name is appended.
 
-The "echo" keyword parameter which is available on some SA objects corresponds
-to an instance-level logger for that instance.
+The "echo" keyword parameter which is available on SQLA ``Engine``
+and ``Pool`` objects corresponds to a logger specific to that 
+instance only.
 
 E.g.::
 
@@ -26,11 +23,12 @@ is equivalent to::
     import logging
     logger = logging.getLogger('sqlalchemy.engine.Engine.%s' % hex(id(engine)))
     logger.setLevel(logging.DEBUG)
+    
 """
 
 import logging
 import sys
-import weakref
+
 
 rootlogger = logging.getLogger('sqlalchemy')
 if rootlogger.level == logging.NOTSET:
@@ -48,27 +46,34 @@ def default_logging(name):
             '%(asctime)s %(levelname)s %(name)s %(message)s'))
         rootlogger.addHandler(handler)
 
-def _get_instance_name(instance):
-    # since getLogger() does not have any way of removing logger objects from
-    # memory, instance logging displays the instance id as a modulus of 16 to
-    # prevent endless memory growth also speeds performance as logger
-    # initialization is apparently slow
-    return "%s.%s.0x..%s" % (instance.__class__.__module__,
-                             instance.__class__.__name__,
-                             hex(id(instance))[-2:])
-
-def class_logger(cls):
-    return logging.getLogger(cls.__module__ + "." + cls.__name__)
-
-def is_debug_enabled(logger):
-    return logger.isEnabledFor(logging.DEBUG)
-
-def is_info_enabled(logger):
-    return logger.isEnabledFor(logging.INFO)
+def class_logger(cls, enable=False):
+    logger = logging.getLogger(cls.__module__ + "." + cls.__name__)
+    if enable == 'debug':
+        logger.setLevel(logging.DEBUG)
+    elif enable == 'info':
+        logger.setLevel(logging.INFO)
+    cls._should_log_debug = logger.isEnabledFor(logging.DEBUG)
+    cls._should_log_info = logger.isEnabledFor(logging.INFO)
+    cls.logger = logger
 
 def instance_logger(instance, echoflag=None):
+    """create a logger for an instance.
+    
+    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.
+    
+    """
+    
+    # limit the number of loggers by chopping off the hex(id).
+    # many novice users unfortunately create an unlimited number 
+    # of Engines in their applications which would otherwise
+    # cause the app to run out of memory.
+    name = "%s.%s.0x...%s" % (instance.__class__.__module__,
+                             instance.__class__.__name__,
+                             hex(id(instance))[-4:])
+    
     if echoflag is not None:
-        name = _get_instance_name(instance)
         l = logging.getLogger(name)
         if echoflag == 'debug':
             default_logging(name)
@@ -78,15 +83,8 @@ def instance_logger(instance, echoflag=None):
             l.setLevel(logging.INFO)
         elif echoflag is False:
             l.setLevel(logging.NOTSET)
-
-        def cleanup(ref):
-            # the id() of an instance may be reused again after the
-            # previous instance has been gc'ed.  set a cleanup handler
-            # to remove logging config
-            logging.getLogger(name).setLevel(logging.NOTSET)
-        instance._logging_cleanup = weakref.ref(instance, cleanup)
     else:
-        l = logging.getLogger(_get_instance_name(instance))
+        l = logging.getLogger(name)
     instance._should_log_debug = l.isEnabledFor(logging.DEBUG)
     instance._should_log_info = l.isEnabledFor(logging.INFO)
     return l
@@ -95,7 +93,6 @@ class echo_property(object):
     __doc__ = """\
     When ``True``, enable log output for this element.
 
-
     This has the effect of setting the Python logging level for the namespace
     of this element's class and object reference.  A value of boolean ``True``
     indicates that the loglevel ``logging.INFO`` will be set for the logger,

lib/sqlalchemy/orm/dynamic.py

@@ -29,7 +29,7 @@ class DynaLoader(strategies.AbstractRelationLoader):
     def create_row_processor(self, selectcontext, path, mapper, row, adapter):
         return (None, None)
 
-DynaLoader.logger = log.class_logger(DynaLoader)
+log.class_logger(DynaLoader)
 
 class DynamicAttributeImpl(attributes.AttributeImpl):
     uses_objects = True

lib/sqlalchemy/orm/interfaces.py

@@ -623,8 +623,6 @@ class PropertyOption(MapperOption):
         self._process(query, False)
 
     def _process(self, query, raiseerr):
-        if self._should_log_debug:
-            self.logger.debug("applying option to Query, property key '%s'" % self.key)
         paths = self.__get_paths(query, raiseerr)
         if paths:
             self.process_query_property(query, paths)
@@ -703,9 +701,6 @@ class PropertyOption(MapperOption):
 
         return l
 
-PropertyOption.logger = log.class_logger(PropertyOption)
-PropertyOption._should_log_debug = log.is_debug_enabled(PropertyOption.logger)
-
 class AttributeExtension(object):
     """An abstract class which specifies `append`, `delete`, and `set`
     event handlers to be attached to an object property.

lib/sqlalchemy/orm/mapper.py

@@ -189,9 +189,6 @@ class Mapper(object):
 
         self.compiled = False
 
-        self.__should_log_info = log.is_info_enabled(self.logger)
-        self.__should_log_debug = log.is_debug_enabled(self.logger)
-
         self.__compile_inheritance()
         self.__compile_extensions()
         self.__compile_class()
@@ -202,11 +199,11 @@ class Mapper(object):
         self.__log("constructed")
 
     def __log(self, msg):
-        if self.__should_log_info:
+        if self._should_log_info:
             self.logger.info("(" + self.class_.__name__ + "|" + (self.local_table and self.local_table.description or str(self.local_table)) + (self.non_primary and "|non-primary" or "") + ") " + msg)
 
     def __log_debug(self, msg):
-        if self.__should_log_debug:
+        if self._should_log_debug:
             self.logger.debug("(" + self.class_.__name__ + "|" + (self.local_table and self.local_table.description or str(self.local_table)) + (self.non_primary and "|non-primary" or "") + ") " + msg)
 
     def _is_orphan(self, state):
@@ -1042,7 +1039,7 @@ class Mapper(object):
         mapper which does not inherit from any other mapper.
         """
 
-        if self.__should_log_debug:
+        if self._should_log_debug:
             self.__log_debug("_save_obj() start, " + (single and "non-batched" or "batched"))
 
         # if batch=false, call _save_obj separately for each object
@@ -1080,7 +1077,7 @@ class Mapper(object):
                 existing = attributes.instance_state(instance)
                 if not uowtransaction.is_deleted(existing):
                     raise exc.FlushError("New instance %s with identity key %s conflicts with persistent instance %s" % (state_str(state), str(instance_key), state_str(existing)))
-                if self.__should_log_debug:
+                if self._should_log_debug:
                     self.__log_debug("detected row switch for identity %s.  will update %s, remove %s from transaction" % (instance_key, state_str(state), state_str(existing)))
                 uowtransaction.set_row_switch(existing)
 
@@ -1102,7 +1099,7 @@ class Mapper(object):
                 pks = mapper._pks_by_table[table]
                 instance_key = mapper._identity_key_from_state(state)
 
-                if self.__should_log_debug:
+                if self._should_log_debug:
                     self.__log_debug("_save_obj() table '%s' instance %s identity %s" % (table.name, state_str(state), str(instance_key)))
 
                 isinsert = not instance_key in uowtransaction.session.identity_map and not postupdate and not has_identity
@@ -1119,7 +1116,7 @@ class Mapper(object):
                             if value is not None:
                                 params[col.key] = value
                         elif mapper.polymorphic_on and mapper.polymorphic_on.shares_lineage(col):
-                            if self.__should_log_debug:
+                            if self._should_log_debug:
                                 self.__log_debug("Using polymorphic identity '%s' for insert column '%s'" % (mapper.polymorphic_identity, col.key))
                             value = mapper.polymorphic_identity
                             if ((col.default is None and
@@ -1297,7 +1294,7 @@ class Mapper(object):
         flush operation.
         """
 
-        if self.__should_log_debug:
+        if self._should_log_debug:
             self.__log_debug("_delete_obj() start")
 
         if 'connection_callable' in uowtransaction.mapper_flush_opts:
@@ -1479,7 +1476,7 @@ class Mapper(object):
                 instance = session_identity_map[identitykey]
                 state = attributes.instance_state(instance)
 
-                if self.__should_log_debug:
+                if self._should_log_debug:
                     self.__log_debug("_instance(): using existing instance %s identity %s" % (instance_str(instance), str(identitykey)))
 
                 isnew = state.runid != context.runid
@@ -1498,7 +1495,7 @@ class Mapper(object):
                 currentload = True
                 loaded_instance = False
             else:
-                if self.__should_log_debug:
+                if self._should_log_debug:
                     self.__log_debug("_instance(): identity key %s not in session" % str(identitykey))
 
                 if self.allow_null_pks:
@@ -1527,7 +1524,7 @@ class Mapper(object):
                 else:
                     instance = self.class_manager.new_instance()
 
-                if self.__should_log_debug:
+                if self._should_log_debug:
                     self.__log_debug("_instance(): created new instance %s identity %s" % (instance_str(instance), str(identitykey)))
 
                 state = attributes.instance_state(instance)
@@ -1633,7 +1630,7 @@ class Mapper(object):
         cond = sql.and_(*allconds)
         return sql.select(tables, cond, use_labels=True)
 
-Mapper.logger = log.class_logger(Mapper)
+log.class_logger(Mapper)
 
 
 def reconstructor(fn):

lib/sqlalchemy/orm/properties.py

@@ -96,7 +96,7 @@ class ColumnProperty(StrategizedProperty):
     def __str__(self):
         return str(self.parent.class_.__name__) + "." + self.key
 
-ColumnProperty.logger = log.class_logger(ColumnProperty)
+log.class_logger(ColumnProperty)
 
 class CompositeProperty(ColumnProperty):
     """subclasses ColumnProperty to provide composite type support."""
@@ -204,7 +204,8 @@ class SynonymProperty(MapperProperty):
 
     def merge(self, session, source, dest, dont_load, _recursive):
         pass
-SynonymProperty.logger = log.class_logger(SynonymProperty)
+        
+log.class_logger(SynonymProperty)
 
 class ComparableProperty(MapperProperty):
     """Instruments a Python property for use in query expressions."""
@@ -735,7 +736,7 @@ class PropertyLoader(StrategizedProperty):
 
 
     def _post_init(self):
-        if log.is_info_enabled(self.logger):
+        if self._should_log_info:
             self.logger.info(str(self) + " setup primary join %s" % self.primaryjoin)
             self.logger.info(str(self) + " setup secondary join %s" % self.secondaryjoin)
             self.logger.info(str(self) + " synchronize pairs [%s]" % ",".join("(%s => %s)" % (l, r) for l, r in self.synchronize_pairs))
@@ -861,7 +862,7 @@ class PropertyLoader(StrategizedProperty):
         if not self.viewonly:
             self._dependency_processor.register_dependencies(uowcommit)
 
-PropertyLoader.logger = log.class_logger(PropertyLoader)
+log.class_logger(PropertyLoader)
 
 class BackRef(object):
     """Attached to a PropertyLoader to indicate a complementary reverse relationship.

lib/sqlalchemy/orm/query.py

@@ -1693,7 +1693,7 @@ class _ColumnEntity(_QueryEntity):
     def __str__(self):
         return str(self.column)
 
-Query.logger = log.class_logger(Query)
+log.class_logger(Query)
 
 class QueryContext(object):
     def __init__(self, query):

lib/sqlalchemy/orm/session.py

@@ -135,8 +135,7 @@ def sessionmaker(bind=None, class_=None, autoflush=True, autocommit=False,
       directly to the constructor for ``Session``.
 
     echo_uow
-      When ``True``, configure Python logging to dump all unit-of-work
-      transactions. This is the equivalent of
+      Deprecated.  Use
       ``logging.getLogger('sqlalchemy.orm.unitofwork').setLevel(logging.DEBUG)``.
 
     extension
@@ -526,7 +525,7 @@ class Session(object):
 
     def __init__(self, bind=None, autoflush=True, expire_on_commit=True,
                 _enable_transaction_accounting=True,
-                 autocommit=False, twophase=False, echo_uow=False,
+                 autocommit=False, twophase=False, echo_uow=None,
                  weak_identity_map=True, binds=None, extension=None, query_cls=query.Query):
         """Construct a new Session.
 
@@ -534,7 +533,13 @@ class Session(object):
         [sqlalchemy.orm#sessionmaker()] function.
 
         """
-        self.echo_uow = echo_uow
+        
+        if echo_uow is not None:
+            util.warn_deprecated(
+                "echo_uow is deprecated. "
+                "Use logging.getLogger('sqlalchemy.orm.unitofwork').setLevel(logging.DEBUG).")
+            log.class_logger(UOWTransaction, echo_uow)
+
         if weak_identity_map:
             self._identity_cls = identity.WeakInstanceDict
         else:

lib/sqlalchemy/orm/strategies.py

@@ -40,13 +40,12 @@ class DefaultColumnLoader(LoaderStrategy):
                     active_history=active_history
                     )
 
-DefaultColumnLoader.logger = log.class_logger(DefaultColumnLoader)
+log.class_logger(DefaultColumnLoader)
     
 class ColumnLoader(DefaultColumnLoader):
     
     def init(self):
         self.columns = self.parent_property.columns
-        self._should_log_debug = log.is_debug_enabled(self.logger)
         self.is_composite = hasattr(self.parent_property, 'composite_class')
         
     def setup_query(self, context, entity, path, adapter, column_collection=None, **kwargs):
@@ -91,7 +90,7 @@ class ColumnLoader(DefaultColumnLoader):
                 self.logger.debug("%s deferring load" % self)
             return (new_execute, None)
 
-ColumnLoader.logger = log.class_logger(ColumnLoader)
+log.class_logger(ColumnLoader)
 
 class CompositeColumnLoader(ColumnLoader):
     def init_class_attribute(self):
@@ -146,7 +145,7 @@ class CompositeColumnLoader(ColumnLoader):
 
             return (new_execute, None)
 
-CompositeColumnLoader.logger = log.class_logger(CompositeColumnLoader)
+log.class_logger(CompositeColumnLoader)
     
 class DeferredColumnLoader(DefaultColumnLoader):
     """Deferred column loader, a per-column or per-column-group lazy loader."""
@@ -176,7 +175,6 @@ class DeferredColumnLoader(DefaultColumnLoader):
             raise NotImplementedError("Deferred loading for composite types not implemented yet")
         self.columns = self.parent_property.columns
         self.group = self.parent_property.group
-        self._should_log_debug = log.is_debug_enabled(self.logger)
 
     def init_class_attribute(self):
         self.is_class_level = True
@@ -213,7 +211,7 @@ class DeferredColumnLoader(DefaultColumnLoader):
     def setup_loader(self, state, props=None, create_statement=None):
         return LoadDeferredColumns(state, self.key, props)
                 
-DeferredColumnLoader.logger = log.class_logger(DeferredColumnLoader)
+log.class_logger(DeferredColumnLoader)
 
 class LoadDeferredColumns(object):
     """serializable loader object used by DeferredColumnLoader"""
@@ -289,7 +287,6 @@ class AbstractRelationLoader(LoaderStrategy):
     def init(self):
         for attr in ['mapper', 'target', 'table', 'uselist']:
             setattr(self, attr, getattr(self.parent_property, attr))
-        self._should_log_debug = log.is_debug_enabled(self.logger)
         
     def _init_instance_attribute(self, state, callable_=None):
         if callable_:
@@ -335,7 +332,7 @@ class NoLoader(AbstractRelationLoader):
             )
         return (new_execute, None)
 
-NoLoader.logger = log.class_logger(NoLoader)
+log.class_logger(NoLoader)
         
 class LazyLoader(AbstractRelationLoader):
     def init(self):
@@ -485,7 +482,7 @@ class LazyLoader(AbstractRelationLoader):
         return (lazywhere, bind_to_col, equated_columns)
     _create_lazy_clause = classmethod(_create_lazy_clause)
     
-LazyLoader.logger = log.class_logger(LazyLoader)
+log.class_logger(LazyLoader)
 
 class LoadLazyAttribute(object):
     """serializable loader object used by LazyLoader"""
@@ -743,7 +740,7 @@ class EagerLoader(AbstractRelationLoader):
                 self.logger.debug("%s degrading to lazy loader" % self)
             return self.parent_property._get_strategy(LazyLoader).create_row_processor(context, path, mapper, row, adapter)
 
-EagerLoader.logger = log.class_logger(EagerLoader)
+log.class_logger(EagerLoader)
 
 class EagerLazyOption(StrategizedOption):
     def __init__(self, key, lazy=True, chained=False, mapper=None):

lib/sqlalchemy/orm/unitofwork.py

@@ -85,8 +85,6 @@ def register_attribute(class_, key, *args, **kwargs):
     return attributes.register_attribute(class_, key, *args, **kwargs)
 
 
-
-
 class UOWTransaction(object):
     """Handles the details of organizing and executing transaction
     tasks during a UnitOfWork object's flush() operation.
@@ -111,9 +109,7 @@ class UOWTransaction(object):
         # dictionary used by external actors to store arbitrary state
         # information.
         self.attributes = {}
-
-        self.logger = log.instance_logger(self, echoflag=session.echo_uow)
-
+        
     def get_attribute_history(self, state, key, passive=True):
         hashkey = ("history", state, key)
 
@@ -313,6 +309,8 @@ class UOWTransaction(object):
             self.logger.debug("Dependency sort:\n"+ str(ret))
         return ret
 
+log.class_logger(UOWTransaction)
+
 class UOWTask(object):
     """Represents all of the objects in the UOWTransaction which correspond to
     a particular mapper.

test/orm/inheritance/polymorph2.py

@@ -692,7 +692,7 @@ class GenerativeTest(TestBase, AssertsExecutionResults):
         manager_mapper  = mapper(Manager, managers, inherits=person_mapper, polymorphic_identity='manager')
         car_mapper      = mapper(Car, cars, properties= {'employee':relation(person_mapper), 'status':relation(status_mapper)})
 
-        session = create_session(echo_uow=False)
+        session = create_session()
 
         active = Status(name="active")
         dead = Status(name="dead")