DB queries log entries are duplicated

Bug #1278860 reported by Roman Podoliaka
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
oslo-incubator
Fix Released
Medium
Eugeniya Kudryashova

Bug Description

In oslo.db we can enable logging of DB queries by the means of CONF.database.connection_debug options. It's implemented by passing of echo=True/'debug' to SQLAlchemy create_engine() factory function, which internally calls logging.basicConfig(), that adds handler to the root logger.

But we also set up handlers for the root logger in openstack.common.log setup() function. This results in attaching of two handlers writing entries to stderr to the root logger. And it's clearly stated in SQLAlchemy docs: "...when using Python logging, ensure all echo flags are set to False at all times, to avoid getting duplicate log lines."(http://docs.sqlalchemy.org/en/rel_0_9/core/engines.html#dbengine-logging)

To fix this we need to stop passing echo=True to create_engine() in oslo.db and replace it with setting the correct log level directly on the logger (in this case it's 'sqlalchemy.engine').

Snippet to reproduce (it's not using oslo code, but effectively behaves the same way):

import logging

import sqlalchemy as sa

# this is a simplified version of what we are doing in openstack.common.log
root = logging.getLogger()
root.addHandler(logging.StreamHandler())

# log entries of DB queries are duplicated
eng = sa.create_engine('sqlite://', echo=True)
eng.execute('select 1;')

Tags: db
Changed in oslo:
assignee: nobody → Eugeniya Kudryashova (ekudryashova)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to oslo-incubator (master)

Fix proposed to branch: master
Review: https://review.openstack.org/72669

Changed in oslo:
status: New → In Progress
Ben Nemec (bnemec)
Changed in oslo:
importance: Undecided → Medium
Changed in oslo:
milestone: none → icehouse-3
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to oslo-incubator (master)

Reviewed: https://review.openstack.org/72669
Committed: https://git.openstack.org/cgit/openstack/oslo-incubator/commit/?id=0545121145ba3dceea33ec6832a45985240ac15a
Submitter: Jenkins
Branch: master

commit 0545121145ba3dceea33ec6832a45985240ac15a
Author: ekudryashova <email address hidden>
Date: Tue Feb 11 16:29:03 2014 +0200

    Fix duplicating of SQL queries in logs

    Remove setting and passing echo parameter to create_engine()
    function and replace it with configuring log level directly on
    logger sqlalchemy.engine (this prevents adding of multiple
    handlers writing to stderr to the root logger).

    Change-Id: I799341a347cfcacdd27c70b91ed9b9e3cc70727f
    Closes-Bug: #1278860

Changed in oslo:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in oslo:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in oslo:
milestone: icehouse-3 → 2014.1
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.