From: Mike Bayer Date: Fri, 5 Mar 2021 17:27:09 +0000 (-0500) Subject: Clarify COMMIT/ROLLBACK logging when autocommit is turned on X-Git-Tag: rel_1_4_0~17^2 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6d97d0c97de01e67a2d2d59c5bec1bbf3782de10;p=thirdparty%2Fsqlalchemy%2Fsqlalchemy.git Clarify COMMIT/ROLLBACK logging when autocommit is turned on Improved engine logging to note ROLLBACK and COMMIT which is logged while the DBAPI driver is in AUTOCOMMIT mode. These ROLLBACK/COMMIT are library level and do not have any effect when AUTOCOMMIT is in effect, however it's still worthwhile to log as these indicate where SQLAlchemy sees the "transaction" demarcation. Fixes: #6002 Change-Id: I723636515193e0addc86dd0a3132bc23deadb81b --- diff --git a/doc/build/changelog/unreleased_14/6002.rst b/doc/build/changelog/unreleased_14/6002.rst new file mode 100644 index 0000000000..ded1ff3fa1 --- /dev/null +++ b/doc/build/changelog/unreleased_14/6002.rst @@ -0,0 +1,9 @@ +.. change:: + :tags: bug, engine + :tickets: 6002 + + Improved engine logging to note ROLLBACK and COMMIT which is logged while + the DBAPI driver is in AUTOCOMMIT mode. These ROLLBACK/COMMIT are library + level and do not have any effect when AUTOCOMMIT is in effect, however it's + still worthwhile to log as these indicate where SQLAlchemy sees the + "transaction" demarcation. \ No newline at end of file diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py index aa657cc52e..b5a37f67e3 100644 --- a/lib/sqlalchemy/engine/base.py +++ b/lib/sqlalchemy/engine/base.py @@ -826,6 +826,12 @@ class Connection(Connectable): and self._nested_transaction.is_active ) + def _is_autocommit(self): + return ( + self._execution_options.get("isolation_level", None) + == "AUTOCOMMIT" + ) + def get_transaction(self): """Return the current root transaction in progress, if any. @@ -876,7 +882,13 @@ class Connection(Connectable): if self._still_open_and_dbapi_connection_is_valid: if self._echo: - self._log_info("ROLLBACK") + if self._is_autocommit(): + self._log_info( + "ROLLBACK using DBAPI connection.rollback(), " + "DBAPI should ignore due to autocommit mode" + ) + else: + self._log_info("ROLLBACK") try: self.engine.dialect.do_rollback(self.connection) except BaseException as e: @@ -889,11 +901,7 @@ class Connection(Connectable): # if a connection has this set as the isolation level, we can skip # the "autocommit" warning as the operation will do "autocommit" # in any case - if ( - autocommit - and self._execution_options.get("isolation_level", None) - != "AUTOCOMMIT" - ): + if autocommit and not self._is_autocommit(): util.warn_deprecated_20( "The current statement is being autocommitted using " "implicit autocommit, which will be removed in " @@ -906,7 +914,13 @@ class Connection(Connectable): self.dispatch.commit(self) if self._echo: - self._log_info("COMMIT") + if self._is_autocommit(): + self._log_info( + "COMMIT using DBAPI connection.commit(), " + "DBAPI should ignore due to autocommit mode" + ) + else: + self._log_info("COMMIT") try: self.engine.dialect.do_commit(self.connection) except BaseException as e: @@ -1056,7 +1070,15 @@ class Connection(Connectable): if self._dbapi_connection is not None: conn = self._dbapi_connection + + # this will do a reset-on-return every time, even if we + # called rollback() already. it might be worth optimizing + # this for the case that we are able to close without issue conn.close() + + # this is in fact never true outside of a bunch of + # artificial scenarios created by the test suite and its + # fixtures. the reset_agent should no longer be necessary. if conn._reset_agent is self._transaction: conn._reset_agent = None diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py index ffabddb37c..2c90b9bf11 100644 --- a/test/engine/test_logging.py +++ b/test/engine/test_logging.py @@ -586,6 +586,91 @@ class LoggingNameTest(fixtures.TestBase): self._assert_no_name_in_execute(eng) +class TransactionContextLoggingTest(fixtures.TestBase): + @testing.fixture() + def assert_buf(self, 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 logging_engine(self, testing_engine): + kw = {"echo": True, "future": True} + e = testing_engine(options=kw) + e.connect().close() + return e + + def test_begin_once_block(self, logging_engine, assert_buf): + with logging_engine.begin(): + pass + + assert_buf(["BEGIN (implicit)", "COMMIT"]) + + def test_commit_as_you_go_block_commit(self, logging_engine, assert_buf): + with logging_engine.connect() as conn: + conn.begin() + conn.commit() + + assert_buf(["BEGIN (implicit)", "COMMIT"]) + + def test_commit_as_you_go_block_rollback(self, logging_engine, assert_buf): + with logging_engine.connect() as conn: + conn.begin() + conn.rollback() + + assert_buf(["BEGIN (implicit)", "ROLLBACK"]) + + def test_commit_as_you_go_block_commit_autocommit( + self, logging_engine, assert_buf + ): + with logging_engine.connect().execution_options( + isolation_level="AUTOCOMMIT" + ) as conn: + conn.begin() + conn.commit() + + assert_buf( + [ + "BEGIN (implicit)", + "COMMIT using DBAPI connection.commit(), DBAPI " + "should ignore due to autocommit mode", + ] + ) + + def test_commit_as_you_go_block_rollback_autocommit( + self, logging_engine, assert_buf + ): + with logging_engine.connect().execution_options( + isolation_level="AUTOCOMMIT" + ) as conn: + conn.begin() + conn.rollback() + + assert_buf( + [ + "BEGIN (implicit)", + "ROLLBACK using DBAPI connection.rollback(), DBAPI " + "should ignore due to autocommit mode", + ] + ) + + class LoggingTokenTest(fixtures.TestBase): def setup_test(self): self.buf = logging.handlers.BufferingHandler(100)