--- /dev/null
+.. 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`
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
------------------
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)
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
assert not self.__branch_from
if self._echo:
- self.engine.logger.info("BEGIN (implicit)")
+ self._log_info("BEGIN (implicit)")
self.__in_begin = True
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:
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:
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)
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(
),
)
else:
- self.engine.logger.info(
+ self._log_info(
"[%s] [SQL parameters hidden due to hide_parameters=True]"
% (stats,)
)
)
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 (
()
: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
# 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))
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
import logging.handlers
+import re
import sqlalchemy as tsa
from sqlalchemy import bindparam
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",)
projects / thirdparty / sqlalchemy / sqlalchemy.git / commitdiff
