From: Markus Gerstel Date: Wed, 26 Jan 2022 09:56:40 +0000 (-0500) Subject: Fix up Python logging metadata X-Git-Tag: rel_1_4_32~34 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=bcea1d0e7bc8209247ed98a5b549420294fb0a53;p=thirdparty%2Fsqlalchemy%2Fsqlalchemy.git 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 index 0000000000..c8992045fc --- /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 0e695f65a5..cf6a14728b 100644 --- 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 55511c27b8..07c5eff287 100644 --- 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 c5f8b69b64..806336368b 100644 --- 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):