[sqlalchemy] double entries w/ logger config file (echo was set to False, now True after logging configured)

[hal_robertson]

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 sqlal...@googlegroups.com.
To unsubscribe from this group, send email to sqlalchemy+...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/sqlalchemy?hl=en.

[Michael Bayer]

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.

[Dmitry Mugtasimov]

See https://stackoverflow.com/a/76498428/1952977