From 594f55d974150d6625004f72b3e284a4a1f796c1 Mon Sep 17 00:00:00 2001 From: Mike Bayer Date: Wed, 3 Feb 2021 11:53:18 -0500 Subject: [PATCH] Implement per-connection logging token Added new execution option :paramref:`_engine.Connection.execution_options.logging_token`. This option will add an additional per-message token to log messages generated by the :class:`_engine.Connection` as it executes statements. This token is not part of the logger name itself (that part can be affected using the existing :paramref:`_sa.create_engine.logging_name` parameter), so is appropriate for ad-hoc connection use without the side effect of creating many new loggers. The option can be set at the level of :class:`_engine.Connection` or :class:`_engine.Engine`. Fixes: #5911 Change-Id: Iec9c39b868b3578fcedc1c094dace5b6f64bacea --- doc/build/changelog/unreleased_14/5911.rst | 17 ++++++ doc/build/core/engines.rst | 54 ++++++++++++++++ lib/sqlalchemy/engine/base.py | 61 ++++++++++++++++--- lib/sqlalchemy/engine/create.py | 2 + lib/sqlalchemy/engine/cursor.py | 4 +- test/engine/test_logging.py | 71 ++++++++++++++++++++++ 6 files changed, 198 insertions(+), 11 deletions(-) create mode 100644 doc/build/changelog/unreleased_14/5911.rst diff --git a/doc/build/changelog/unreleased_14/5911.rst b/doc/build/changelog/unreleased_14/5911.rst new file mode 100644 index 0000000000..38cf5d9d0b --- /dev/null +++ b/doc/build/changelog/unreleased_14/5911.rst @@ -0,0 +1,17 @@ +.. change:: + :tags: feature, engine + :tickets: 5911 + + Added new execution option + :paramref:`_engine.Connection.execution_options.logging_token`. This option + will add an additional per-message token to log messages generated by the + :class:`_engine.Connection` as it executes statements. This token is not + part of the logger name itself (that part can be affected using the + existing :paramref:`_sa.create_engine.logging_name` parameter), so is + appropriate for ad-hoc connection use without the side effect of creating + many new loggers. The option can be set at the level of + :class:`_engine.Connection` or :class:`_engine.Engine`. + + .. seealso:: + + :ref:`dbengine_logging_tokens` diff --git a/doc/build/core/engines.rst b/doc/build/core/engines.rst index f843c9794a..6bcd14ac2a 100644 --- a/doc/build/core/engines.rst +++ b/doc/build/core/engines.rst @@ -556,6 +556,60 @@ string. To set this to a specific name, use the 2020-10-24 12:47:04,291 INFO sqlalchemy.engine.Engine.myengine select 'hi' 2020-10-24 12:47:04,292 INFO sqlalchemy.engine.Engine.myengine () +.. _dbengine_logging_tokens: + +Setting Per-Connection / Sub-Engine Tokens +------------------------------------------ + +.. versionadded:: 1.4.0b2 + + +While the logging name is appropriate to establish on an +:class:`_engine.Engine` object that is long lived, it's not flexible enough +to accommodate for an arbitrarily large list of names, for the case of +tracking individual connections and/or transactions in log messages. + +For this use case, the log message itself generated by the +:class:`_engine.Connection` and :class:`_engine.Result` objects may be +augmented with additional tokens such as transaction or request identifiers. +The :paramref:`_engine.Connection.execution_options.logging_token` parameter +accepts a string argument that may be used to establish per-connection tracking +tokens:: + + >>> from sqlalchemy import create_engine + >>> e = create_engine("sqlite://", echo="debug") + >>> with e.connect().execution_options(logging_token="track1") as conn: + ... conn.execute("select 1").all() + 2021-02-03 11:48:45,754 INFO sqlalchemy.engine.Engine [track1] select 1 + 2021-02-03 11:48:45,754 INFO sqlalchemy.engine.Engine [track1] [raw sql] () + 2021-02-03 11:48:45,754 DEBUG sqlalchemy.engine.Engine [track1] Col ('1',) + 2021-02-03 11:48:45,755 DEBUG sqlalchemy.engine.Engine [track1] Row (1,) + +The :paramref:`_engine.Connection.execution_options.logging_token` parameter +may also be established on engines or sub-engines via +:paramref:`_sa.create_engine.execution_options` or :meth:`_engine.Engine.execution_options`. +This may be useful to apply different logging tokens to different components +of an application without creating new engines:: + + >>> from sqlalchemy import create_engine + >>> e = create_engine("sqlite://", echo="debug") + >>> e1 = e.execution_options(logging_token="track1") + >>> e2 = e.execution_options(logging_token="track2") + >>> with e1.connect() as conn: + ... conn.execute("select 1").all() + 2021-02-03 11:51:08,960 INFO sqlalchemy.engine.Engine [track1] select 1 + 2021-02-03 11:51:08,960 INFO sqlalchemy.engine.Engine [track1] [raw sql] () + 2021-02-03 11:51:08,960 DEBUG sqlalchemy.engine.Engine [track1] Col ('1',) + 2021-02-03 11:51:08,961 DEBUG sqlalchemy.engine.Engine [track1] Row (1,) + + >>> with e2.connect() as conn: + ... conn.execute("select 2").all() + 2021-02-03 11:52:05,518 INFO sqlalchemy.engine.Engine [track2] Select 1 + 2021-02-03 11:52:05,519 INFO sqlalchemy.engine.Engine [track2] [raw sql] () + 2021-02-03 11:52:05,520 DEBUG sqlalchemy.engine.Engine [track2] Col ('1',) + 2021-02-03 11:52:05,520 DEBUG sqlalchemy.engine.Engine [track2] Row (1,) + + Hiding Parameters ------------------ diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py index 31bf885dbb..aa657cc52e 100644 --- a/lib/sqlalchemy/engine/base.py +++ b/lib/sqlalchemy/engine/base.py @@ -111,6 +111,30 @@ class Connection(Connectable): if self._has_events or self.engine._has_events: self.dispatch.engine_connect(self, _branch_from is not None) + @util.memoized_property + def _message_formatter(self): + if "logging_token" in self._execution_options: + token = self._execution_options["logging_token"] + return lambda msg: "[%s] %s" % (token, msg) + else: + return None + + def _log_info(self, message, *arg, **kw): + fmt = self._message_formatter + + if fmt: + message = fmt(message) + + self.engine.logger.info(message, *arg, **kw) + + def _log_debug(self, message, *arg, **kw): + fmt = self._message_formatter + + if fmt: + message = fmt(message) + + self.engine.logger.debug(message, *arg, **kw) + @property def _schema_translate_map(self): return self._execution_options.get("schema_translate_map", None) @@ -237,6 +261,25 @@ class Connection(Connectable): used by the ORM internally supersedes a cache dictionary specified here. + :param logging_token: Available on: :class:`_engine.Connection`, + :class:`_engine.Engine`. + + Adds the specified string token surrounded by brackets in log + messages logged by the connection, i.e. the logging that's enabled + either via the :paramref:`_sa.create_engine.echo` flag or via the + ``logging.getLogger("sqlalchemy.engine")`` logger. This allows a + per-connection or per-sub-engine token to be available which is + useful for debugging concurrent connection scenarios. + + .. versionadded:: 1.4.0b2 + + .. seealso:: + + :ref:`dbengine_logging_tokens` - usage example + + :paramref:`_sa.create_engine.logging_name` - adds a name to the + name used by the Python logger object itself. + :param isolation_level: Available on: :class:`_engine.Connection`. Set the transaction isolation level for the lifespan of this @@ -811,7 +854,7 @@ class Connection(Connectable): assert not self.__branch_from if self._echo: - self.engine.logger.info("BEGIN (implicit)") + self._log_info("BEGIN (implicit)") self.__in_begin = True @@ -833,7 +876,7 @@ class Connection(Connectable): if self._still_open_and_dbapi_connection_is_valid: if self._echo: - self.engine.logger.info("ROLLBACK") + self._log_info("ROLLBACK") try: self.engine.dialect.do_rollback(self.connection) except BaseException as e: @@ -863,7 +906,7 @@ class Connection(Connectable): self.dispatch.commit(self) if self._echo: - self.engine.logger.info("COMMIT") + self._log_info("COMMIT") try: self.engine.dialect.do_commit(self.connection) except BaseException as e: @@ -904,7 +947,7 @@ class Connection(Connectable): assert not self.__branch_from if self._echo: - self.engine.logger.info("BEGIN TWOPHASE (implicit)") + self._log_info("BEGIN TWOPHASE (implicit)") if self._has_events or self.engine._has_events: self.dispatch.begin_twophase(self, transaction.xid) @@ -1588,12 +1631,12 @@ class Connection(Connectable): if self._echo: - self.engine.logger.info(statement) + self._log_info(statement) stats = context._get_cache_stats() if not self.engine.hide_parameters: - self.engine.logger.info( + self._log_info( "[%s] %r", stats, sql_util._repr_params( @@ -1601,7 +1644,7 @@ class Connection(Connectable): ), ) else: - self.engine.logger.info( + self._log_info( "[%s] [SQL parameters hidden due to hide_parameters=True]" % (stats,) ) @@ -1702,8 +1745,8 @@ class Connection(Connectable): ) if self._echo: - self.engine.logger.info(statement) - self.engine.logger.info("%r", parameters) + self._log_info(statement) + self._log_info("%r", parameters) try: for fn in ( () diff --git a/lib/sqlalchemy/engine/create.py b/lib/sqlalchemy/engine/create.py index 72d232085e..dd732a09ae 100644 --- a/lib/sqlalchemy/engine/create.py +++ b/lib/sqlalchemy/engine/create.py @@ -332,6 +332,8 @@ def create_engine(url, **kwargs): :ref:`dbengine_logging` - further detail on how to configure logging. + :paramref:`_engine.Connection.execution_options.logging_token` + :param max_identifier_length: integer; override the max_identifier_length diff --git a/lib/sqlalchemy/engine/cursor.py b/lib/sqlalchemy/engine/cursor.py index 80cb98b1c8..a9933c7ae7 100644 --- a/lib/sqlalchemy/engine/cursor.py +++ b/lib/sqlalchemy/engine/cursor.py @@ -1228,7 +1228,7 @@ class BaseCursorResult(object): # is the most common case if echo: - log = self.context.engine.logger.debug + log = self.context.connection._log_debug def log_row(row): log("Row %r", sql_util._repr_row(row)) @@ -1302,7 +1302,7 @@ class BaseCursorResult(object): self, cursor_description ) if self._echo: - context.engine.logger.debug( + context.connection._log_debug( "Col %r", tuple(x[0] for x in cursor_description) ) return metadata diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py index c565892487..ffabddb37c 100644 --- a/test/engine/test_logging.py +++ b/test/engine/test_logging.py @@ -1,4 +1,5 @@ import logging.handlers +import re import sqlalchemy as tsa from sqlalchemy import bindparam @@ -585,6 +586,76 @@ class LoggingNameTest(fixtures.TestBase): self._assert_no_name_in_execute(eng) +class LoggingTokenTest(fixtures.TestBase): + def setup_test(self): + self.buf = logging.handlers.BufferingHandler(100) + for log in [ + logging.getLogger("sqlalchemy.engine"), + ]: + log.addHandler(self.buf) + + def teardown_test(self): + for log in [ + logging.getLogger("sqlalchemy.engine"), + ]: + log.removeHandler(self.buf) + + def _assert_token_in_execute(self, conn, token): + self.buf.flush() + r = conn.execute(select(1)) + r.all() + assert self.buf.buffer + for rec in self.buf.buffer: + line = rec.msg % rec.args + assert re.match(r"\[%s\]" % token, line) + self.buf.flush() + + def _assert_no_tokens_in_execute(self, conn): + self.buf.flush() + r = conn.execute(select(1)) + r.all() + assert self.buf.buffer + for rec in self.buf.buffer: + line = rec.msg % rec.args + assert not re.match(r"\[my_.*?\]", line) + self.buf.flush() + + @testing.fixture() + def token_engine(self, testing_engine): + kw = {"echo": "debug"} + return testing_engine(options=kw) + + def test_logging_token_option_connection(self, token_engine): + eng = token_engine + + c1 = eng.connect().execution_options(logging_token="my_name_1") + c2 = eng.connect().execution_options(logging_token="my_name_2") + c3 = eng.connect() + + self._assert_token_in_execute(c1, "my_name_1") + self._assert_token_in_execute(c2, "my_name_2") + self._assert_no_tokens_in_execute(c3) + + c1.close() + c2.close() + c3.close() + + def test_logging_token_option_engine(self, token_engine): + eng = token_engine + + e1 = eng.execution_options(logging_token="my_name_1") + e2 = eng.execution_options(logging_token="my_name_2") + + with e1.connect() as c1: + self._assert_token_in_execute(c1, "my_name_1") + + with e2.connect() as c2: + self._assert_token_in_execute(c2, "my_name_2") + + with eng.connect() as c3: + self._assert_no_tokens_in_execute(c3) + + class EchoTest(fixtures.TestBase): __requires__ = ("ad_hoc_engines",) -- 2.47.2