Fix up Python logging metadata

Adjusted the logging for key SQLAlchemy components including
:class:`_engine.Engine`, :class:`_engine.Connection` to establish an
appropriate stack level parameter, so that the Python logging tokens
``funcName`` and ``lineno`` when used in custom logging formatters will
report the correct information, which can be useful when filtering log
output; supported on Python 3.8 and above. Pull request courtesy Markus
Gerstel.

Fixes: #7612
Closes: #7615
Pull-request: https://github.com/sqlalchemy/sqlalchemy/pull/7615
Pull-request-sha: cf9567beb06680df320cb12dde1f15baa68e1eb5

Change-Id: Iff23c92ef3453ac93cbd0d190e7efbf8ea4457a2
(cherry picked from commit f24a34140f6007cada900a8ae5ed03fe40ce2631)

diff --git a/doc/build/changelog/unreleased_14/7612.rst b/doc/build/changelog/unreleased_14/7612.rst
new file mode 100644 (file)
index 0000000..c899204
--- /dev/null
+++ b/doc/build/changelog/unreleased_14/7612.rst
@@ -0,0 +1,11 @@
+.. change::
+    :tags: bug, engine
+    :tickets: 7612
+
+    Adjusted the logging for key SQLAlchemy components including
+    :class:`_engine.Engine`, :class:`_engine.Connection` to establish an
+    appropriate stack level parameter, so that the Python logging tokens
+    ``funcName`` and ``lineno`` when used in custom logging formatters will
+    report the correct information, which can be useful when filtering log
+    output; supported on Python 3.8 and above. Pull request courtesy Markus
+    Gerstel.

diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index 0e695f65a551a488f8994a4f594e8a178fc53186..cf6a14728b1caef26cc59bd14e8aa02532906e52 100644 (file)
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -133,6 +133,9 @@ class Connection(Connectable):
         if fmt:
             message = fmt(message)
 
+        if util.py38:
+            kw["stacklevel"] = 2
+
         self.engine.logger.info(message, *arg, **kw)
 
     def _log_debug(self, message, *arg, **kw):
@@ -141,6 +144,9 @@ class Connection(Connectable):
         if fmt:
             message = fmt(message)
 
+        if util.py38:
+            kw["stacklevel"] = 2
+
         self.engine.logger.debug(message, *arg, **kw)
 
     @property

diff --git a/lib/sqlalchemy/log.py b/lib/sqlalchemy/log.py
index 55511c27b823562a5884c23b9b205605204c4c1e..07c5eff287c0933bb3c5c5c99ff757e344ffe717 100644 (file)
--- a/lib/sqlalchemy/log.py
+++ b/lib/sqlalchemy/log.py
@@ -21,6 +21,7 @@ instance only.
 import logging
 import sys
 
+from .util import py38
 
 # set initial level to WARN.  This so that
 # log statements don't occur in the absence of explicit
@@ -160,6 +161,9 @@ class InstanceLogger(object):
             selected_level = self.logger.getEffectiveLevel()
 
         if level >= selected_level:
+            if py38:
+                kwargs["stacklevel"] = kwargs.get("stacklevel", 1) + 1
+
             self.logger._log(level, msg, args, **kwargs)
 
     def isEnabledFor(self, level):

diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py
index c5f8b69b64d38f6274f4c9f9854b280df012aed6..806336368b183a127330f26c215084b054015070 100644 (file)
--- a/test/engine/test_logging.py
+++ b/test/engine/test_logging.py
@@ -587,6 +587,30 @@ class LoggingNameTest(fixtures.TestBase):
 
 
 class TransactionContextLoggingTest(fixtures.TestBase):
+    __only_on__ = "sqlite"
+
+    @testing.fixture()
+    def plain_assert_buf(self, plain_logging_engine):
+        buf = logging.handlers.BufferingHandler(100)
+        for log in [
+            logging.getLogger("sqlalchemy.engine"),
+        ]:
+            log.addHandler(buf)
+
+        def go(expected):
+            assert buf.buffer
+
+            buflines = [rec.msg % rec.args for rec in buf.buffer]
+
+            eq_(buflines, expected)
+            buf.flush()
+
+        yield go
+        for log in [
+            logging.getLogger("sqlalchemy.engine"),
+        ]:
+            log.removeHandler(buf)
+
     @testing.fixture()
     def assert_buf(self, logging_engine):
         buf = logging.handlers.BufferingHandler(100)
@@ -616,6 +640,21 @@ class TransactionContextLoggingTest(fixtures.TestBase):
         e.connect().close()
         return e
 
+    @testing.fixture()
+    def plain_logging_engine(self, testing_engine):
+        # deliver an engine with logging using the plain logging API,
+        # not the echo parameter
+        log = logging.getLogger("sqlalchemy.engine")
+        existing_level = log.level
+        log.setLevel(logging.DEBUG)
+
+        try:
+            e = testing_engine(future=True)
+            e.connect().close()
+            yield e
+        finally:
+            log.setLevel(existing_level)
+
     def test_begin_once_block(self, logging_engine, assert_buf):
         with logging_engine.begin():
             pass
@@ -670,6 +709,73 @@ class TransactionContextLoggingTest(fixtures.TestBase):
             ]
         )
 
+    def test_logging_compatibility(
+        self, plain_assert_buf, plain_logging_engine
+    ):
+        """ensure plain logging doesn't produce API errors.
+
+        Added as part of #7612
+
+        """
+        e = plain_logging_engine
+
+        with e.connect() as conn:
+            result = conn.exec_driver_sql("select 1")
+            result.all()
+
+        plain_assert_buf(
+            [
+                "BEGIN (implicit)",
+                "select 1",
+                "[raw sql] ()",
+                "Col ('1',)",
+                "Row (1,)",
+                "ROLLBACK",
+            ]
+        )
+
+    @testing.requires.python38
+    def test_log_messages_have_correct_metadata_plain(
+        self, plain_logging_engine
+    ):
+        """test #7612"""
+        self._test_log_messages_have_correct_metadata(plain_logging_engine)
+
+    @testing.requires.python38
+    def test_log_messages_have_correct_metadata_echo(self, logging_engine):
+        """test #7612"""
+        self._test_log_messages_have_correct_metadata(logging_engine)
+
+    def _test_log_messages_have_correct_metadata(self, logging_engine):
+        buf = logging.handlers.BufferingHandler(100)
+        log = logging.getLogger("sqlalchemy.engine")
+        try:
+            log.addHandler(buf)
+
+            with logging_engine.connect().execution_options(
+                isolation_level="AUTOCOMMIT"
+            ) as conn:
+                conn.begin()
+                conn.rollback()
+        finally:
+            log.removeHandler(buf)
+
+        assert len(buf.buffer) >= 2
+
+        # log messages must originate from functions called 'begin'/'rollback'
+        logging_functions = {rec.funcName for rec in buf.buffer}
+        assert any(
+            "begin" in fn for fn in logging_functions
+        ), logging_functions
+        assert any(
+            "rollback" in fn for fn in logging_functions
+        ), logging_functions
+
+        # log messages must originate from different lines
+        log_lines = {rec.lineno for rec in buf.buffer}
+        assert len(log_lines) > 1, log_lines
+        buf.flush()
+
 
 class LoggingTokenTest(fixtures.TestBase):
     def setup_test(self):