Duplicate lines in logging from SQLAlchemy

Bug #746435 reported by Andrey Brindeyev
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Glance
Fix Released
Low
Jay Pipes

Bug Description

$ glance-registry --log-config=/etc/glance/logging.cnf
2011-03-31 17:11:47,016 INFO sqlalchemy.engine.base.Engine.0x...5590 PRAGMA table_info("images")
2011-03-31 17:11:47,017 INFO sqlalchemy.engine.base.Engine.0x...5590 ()
2011-03-31 17:11:47,017 INFO sqlalchemy.engine.base.Engine.0x...5590 PRAGMA table_info("image_properties")
2011-03-31 17:11:47,017 INFO sqlalchemy.engine.base.Engine.0x...5590 ()

# cat glance.log
2011-03-31 17:11:47,016 sqlalchemy.engine.base.Engine.0x...5590: INFO base _cursor_execute PRAGMA table_info("images")
2011-03-31 17:11:47,017 sqlalchemy.engine.base.Engine.0x...5590: INFO base _cursor_execute ()
2011-03-31 17:11:47,017 sqlalchemy.engine.base.Engine.0x...5590: INFO base _cursor_execute PRAGMA table_info("image_properties")
2011-03-31 17:11:47,017 sqlalchemy.engine.base.Engine.0x...5590: INFO base _cursor_execute ()
2011-03-31 17:11:47,019 eventlet.wsgi.server: DEBUG wsgi write (1936) wsgi starting up on http://0.0.0.0:9191/

Look explanation here: http://www.sqlalchemy.org/docs/core/engines.html#configuring-logging
The echo flags present as keyword arguments to create_engine() and others as well as the echo property on Engine, when set to True, will first attempt to ensure that logging is enabled. Unfortunately, the logging module provides no way of determining if output has already been configured (note we are referring to if a logging configuration has been set up, not just that the logging level is set). For this reason, any echo=True flags will result in a call to logging.basicConfig() using sys.stdout as the destination. It also sets up a default format using the level name, timestamp, and logger name. Note that this configuration has the affect of being configured in addition to any existing logger configurations. Therefore, when using Python logging, ensure all echo flags are set to False at all times, to avoid getting duplicate log lines.

Related branches

Jay Pipes (jaypipes)
Changed in glance:
status: New → Triaged
importance: Undecided → Low
milestone: none → cactus-2011-04-07
Jay Pipes (jaypipes)
Changed in glance:
assignee: nobody → Jay Pipes (jaypipes)
status: Triaged → In Progress
Changed in glance:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in glance:
milestone: cactus-2011-04-07 → 2011.2
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.