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

1 files changed, 85 insertions, 0 deletions

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)