From: Markus Gerstel Date: Wed, 26 Jan 2022 09:56:40 +0000 (-0500) Subject: Fix up Python logging metadata X-Git-Tag: rel_2_0_0b1~506 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=f24a34140f6007cada900a8ae5ed03fe40ce2631;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 --- 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 f7d02e3b0c..b67a212c83 100644 --- 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 e9ab8f4236..885163ecbd 100644 --- 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 0c3d5e43be..ff8c3fc56d 100644 --- 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):