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 (file)
index 0000000..ded1ff3
--- /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 aa657cc52e88cde92a1ba7f69f78511c68fbdd87..b5a37f67e368eae15858edf1c1e5a0d70c46049c 100644 (file)
--- 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 ffabddb37c39625a2d9fba9a8d1bc2203651d1aa..2c90b9bf11442ea27dc9d716692938fe7430051f 100644 (file)
--- 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)