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

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 f7d02e3b0c946d171c324ceda19a97f6de2adb20..b67a212c83c935a66a2eb80130f40613a817961a 100644 (file)
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -136,6 +136,9 @@ class Connection(ConnectionEventsTarget, inspection.Inspectable["Inspector"]):
         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):
@@ -144,6 +147,9 @@ class Connection(ConnectionEventsTarget, inspection.Inspectable["Inspector"]):
         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 e9ab8f423698a6f2132787f34785044266590f9e..885163ecbdf53a9cf5cd27ef000f2274294e648b 100644 (file)
--- a/lib/sqlalchemy/log.py
+++ b/lib/sqlalchemy/log.py
@@ -27,6 +27,7 @@ from typing import Type
 from typing import TypeVar
 from typing import Union
 
+from .util import py38
 from .util.typing import Literal
 
 _IT = TypeVar("_IT", bound="Identified")
@@ -181,6 +182,9 @@ class InstanceLogger:
             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: int) -> bool:

diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py
index 0c3d5e43be92f6519b34020a2fdc1b94264fae73..ff8c3fc56dc42c8eb1bff7efe6344b704c8cbc8c 100644 (file)
--- a/test/engine/test_logging.py
+++ b/test/engine/test_logging.py
@@ -572,6 +572,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)
@@ -601,6 +625,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()
+            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
@@ -655,6 +694,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):