Fix up Python logging metadata

Log messages emitted via sqlalchemy.engine.base and sqlalchemy.log may
report incorrect function names and line numbers, as they may be based
off a helper function stack frame. Add, and increment, the stacklevel
keyword argument to function calls to ensure that helper functions are
not themselves visible in the log records.

Fixes: #7612

diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index f7d02e3b0c946d171c324ceda19a97f6de2adb20..3d59142aa7d11b32d5f259541a635b61083cb916 100644 (file)
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -136,7 +136,7 @@ class Connection(ConnectionEventsTarget, inspection.Inspectable["Inspector"]):
         if fmt:
             message = fmt(message)
 
-        self.engine.logger.info(message, *arg, **kw)
+        self.engine.logger.info(message, *arg, stacklevel=2, **kw)
 
     def _log_debug(self, message, *arg, **kw):
         fmt = self._message_formatter
@@ -144,7 +144,7 @@ class Connection(ConnectionEventsTarget, inspection.Inspectable["Inspector"]):
         if fmt:
             message = fmt(message)
 
-        self.engine.logger.debug(message, *arg, **kw)
+        self.engine.logger.debug(message, *arg, stacklevel=2, **kw)
 
     @property
     def _schema_translate_map(self):

diff --git a/lib/sqlalchemy/log.py b/lib/sqlalchemy/log.py
index e9ab8f423698a6f2132787f34785044266590f9e..4c09b57579519b66187c33d8623ca504221303ed 100644 (file)
--- a/lib/sqlalchemy/log.py
+++ b/lib/sqlalchemy/log.py
@@ -161,7 +161,14 @@ class InstanceLogger:
 
         self.log(logging.CRITICAL, msg, *args, **kwargs)
 
-    def log(self, level: int, msg: str, *args: Any, **kwargs: Any) -> None:
+    def log(
+        self,
+        level: int,
+        msg: str,
+        *args: Any,
+        stacklevel: int = 1,
+        **kwargs: Any,
+    ) -> None:
         """Delegate a log call to the underlying logger.
 
         The level here is determined by the echo
@@ -181,7 +188,9 @@ class InstanceLogger:
             selected_level = self.logger.getEffectiveLevel()
 
         if level >= selected_level:
-            self.logger._log(level, msg, args, **kwargs)
+            self.logger._log(
+                level, msg, args, stacklevel=stacklevel + 1, **kwargs
+            )
 
     def isEnabledFor(self, level: int) -> bool:
         """Is this logger enabled for level 'level'?"""

diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py
index 0c3d5e43be92f6519b34020a2fdc1b94264fae73..808df5d2cb4f94a1a734753c1974a1fd766623d6 100644 (file)
--- a/test/engine/test_logging.py
+++ b/test/engine/test_logging.py
@@ -655,6 +655,36 @@ class TransactionContextLoggingTest(fixtures.TestBase):
             ]
         )
 
+    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):