The issue is that you have configured two handlers by setting
handler=consoleHandler in two places, it should only be on "root" typically.
engine.echo uses Python logging underneath and calling engine.echo as a getter
calls logger.isEnabledFor(logging.INFO), so that indicates nothing about the
issue.
On May 9, 2010, at 10:15 PM, hal_robertson wrote:
> Hi there
>
> I have an application that uses the Python logging facility. The
> logging system is configured through a config file
>
> I would like to be able to adjust sqlalchemy logging through the
> config file
>
> However, it seems when I configure the logging system it turns
> sqlalchemy echo to True on my engine, resulting in two log entries for
> each sqlalchemy output.
>
> How do I configure the logging system properly in an external config
> file for sqlalchemy without the double log entries? Or is this not
> possible? Hopefully I've made a simple mistake that's easy to fix.
>
> thanks
>
> Hal
>
> Test program, config file, and output below:
>
> ---- python, sqlalchemy versions:
>
> Python 2.6.5 (r265:79063, Apr 6 2010, 18:52:40)
> [GCC 4.2.1 (Apple Inc. build 5646)] on darwin
> Type "help", "copyright", "credits" or "license" for more information.
>>>> import sqlalchemy
>>>> sqlalchemy.__version__
> '0.6.0'
>
> --- test_logger.py:
>
> from sqlalchemy import MetaData, create_engine, Table, Column, String,
> Integer
> from sqlalchemy.orm import sessionmaker, mapper
> import logging, logging.config
>
> engine = create_engine('sqlite:///dummy.db')
> # reports engine.echo is False
> print 'engine.echo==%s' % engine.echo
>
> # initializing logging after create_engine sets engine.echo to true
> logging.config.fileConfig('config/logging.conf')
> log = logging.getLogger('root')
> log.debug("Logging initialized")
> log.debug("Unexpected: engine.echo==%s",engine.echo)
>
> ## from here on out all sqlalchemy logs are double-logged :(
>
> # If I explicitly force engine.echo back to False nothing gets logged
> from sqlalchemy
> # engine.echo = False
>
> metadata = MetaData()
> Session = sessionmaker(bind=engine)
> session = Session()
>
> # creating a table
> users_table = Table('users', metadata,
> Column('user_id', Integer, primary_key=True),
> Column('user_name', String(40))
> )
> metadata.create_all(engine)
>
> #create a holding class
> class User(object):
> def __repr__(self):
> return '%s(%r,%r)' % (
>
> self.__class__.__name__,self.user_name,self.user_id)
>
> # map the holding class to the table definition
> mapper(User, users_table)
>
> #create an instance of the class
> u1 = User()
> u1.user_name='bonose'
>
> session.add(u1)
> session.commit()
>
>
>
> --- config/logging.conf
>
> [loggers]
> keys=root, sqlalchemy
>
> [handlers]
> keys=consoleHandler
>
> [formatters]
> keys=simpleFormatter
>
> [logger_root]
> level=DEBUG
> handlers=consoleHandler
>
> [logger_sqlalchemy]
> level=INFO
> handlers=consoleHandler
> qualname=sqlalchemy.engine
>
> [handler_consoleHandler]
> class=StreamHandler
> level=DEBUG
> formatter=simpleFormatter
> args=(sys.stdout,)
>
> [formatter_simpleFormatter]
> format=[%(levelname)s] %(asctime)s (%(name)s) %(message)s
> datefmt=
>
>
> ---- OUTPUT
> ---- If I run the above program with the above config file I get
> double log entires to stdout:
>
> engine.echo==False
> [DEBUG] 2010-05-09 23:03:41,860 (root) Logging initialized
> [DEBUG] 2010-05-09 23:03:41,860 (root) Unexpected: engine.echo==True
> [INFO] 2010-05-09 23:03:41,862 (sqlalchemy.engine.base.Engine.
> 0x...ded0) PRAGMA table_info("users")
> [INFO] 2010-05-09 23:03:41,862 (sqlalchemy.engine.base.Engine.
> 0x...ded0) PRAGMA table_info("users")
> [INFO] 2010-05-09 23:03:41,862 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ()
> [INFO] 2010-05-09 23:03:41,862 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ()
> [INFO] 2010-05-09 23:03:41,863 (sqlalchemy.engine.base.Engine.
> 0x...ded0)
> CREATE TABLE users (
> user_id INTEGER NOT NULL,
> user_name VARCHAR(40),
> PRIMARY KEY (user_id)
> )
>
>
> [INFO] 2010-05-09 23:03:41,863 (sqlalchemy.engine.base.Engine.
> 0x...ded0)
> CREATE TABLE users (
> user_id INTEGER NOT NULL,
> user_name VARCHAR(40),
> PRIMARY KEY (user_id)
> )
>
>
> [INFO] 2010-05-09 23:03:41,863 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ()
> [INFO] 2010-05-09 23:03:41,863 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ()
> [INFO] 2010-05-09 23:03:41,864 (sqlalchemy.engine.base.Engine.
> 0x...ded0) COMMIT
> [INFO] 2010-05-09 23:03:41,864 (sqlalchemy.engine.base.Engine.
> 0x...ded0) COMMIT
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) BEGIN
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) BEGIN
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) INSERT INTO users (user_name) VALUES (?)
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) INSERT INTO users (user_name) VALUES (?)
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ('bonose',)
> [INFO] 2010-05-09 23:03:41,866 (sqlalchemy.engine.base.Engine.
> 0x...ded0) ('bonose',)
> [INFO] 2010-05-09 23:03:41,867 (sqlalchemy.engine.base.Engine.
> 0x...ded0) COMMIT
> [INFO] 2010-05-09 23:03:41,867 (sqlalchemy.engine.base.Engine.
> 0x...ded0) COMMIT
>
>
>
> --
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To post to this group, send email to [email protected].
> To unsubscribe from this group, send email to
> [email protected].
> For more options, visit this group at
> http://groups.google.com/group/sqlalchemy?hl=en.
>
--
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To post to this group, send email to [email protected].
To unsubscribe from this group, send email to
[email protected].
For more options, visit this group at
http://groups.google.com/group/sqlalchemy?hl=en.
