diff options
| -rw-r--r-- | doc/build/changelog/unreleased_14/6002.rst | 9 | ||||
| -rw-r--r-- | lib/sqlalchemy/engine/base.py | 36 | ||||
| -rw-r--r-- | test/engine/test_logging.py | 85 |
3 files changed, 123 insertions, 7 deletions
diff --git a/doc/build/changelog/unreleased_14/6002.rst b/doc/build/changelog/unreleased_14/6002.rst new file mode 100644 index 000000000..ded1ff3fa --- /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 aa657cc52..b5a37f67e 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 ffabddb37..2c90b9bf1 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) |