Fixed #31090 -- Logged transaction management queries.

contextref · felixxm · commit 798e38c2b9c4 · 2022-11-21T09:10:14.000+01:00
Thanks to Petter Strandmark for the original idea and Mariusz Felisiak
for advice during the DjangoConUS 2022 Sprint!
diff --git a/AUTHORS b/AUTHORS
@@ -410,6 +410,7 @@ answer newbie questions, and generally made Django that much better:
     Ifedapo Olarewaju <ifedapoolarewaju@gmail.com>
     Igor Kolar <ike@email.si>
     Illia Volochii <illia.volochii@gmail.com>
+    Ilya Bass
     Ilya Semenov <semenov@inetss.com>
     Ingo Klöcker <djangoproject@ingo-kloecker.de>
     I.S. van Oostveen <v.oostveen@idca.nl>
diff --git a/django/db/backends/base/base.py b/django/db/backends/base/base.py
@@ -8,6 +8,8 @@
 from collections import deque
 from contextlib import contextmanager
 
+from django.db.backends.utils import debug_transaction
+
 try:
     import zoneinfo
 except ImportError:
@@ -307,12 +309,12 @@ def _cursor(self, name=None):
 
     def _commit(self):
         if self.connection is not None:
-            with self.wrap_database_errors:
+            with debug_transaction(self, "COMMIT"), self.wrap_database_errors:
                 return self.connection.commit()
 
     def _rollback(self):
         if self.connection is not None:
-            with self.wrap_database_errors:
+            with debug_transaction(self, "ROLLBACK"), self.wrap_database_errors:
                 return self.connection.rollback()
 
     def _close(self):
@@ -488,9 +490,11 @@ def set_autocommit(
 
         if start_transaction_under_autocommit:
             self._start_transaction_under_autocommit()
-        else:
+        elif autocommit:
             self._set_autocommit(autocommit)
-
+        else:
+            with debug_transaction(self, "BEGIN"):
+                self._set_autocommit(autocommit)
         self.autocommit = autocommit
 
         if autocommit and self.run_commit_hooks_on_set_autocommit_on:
diff --git a/django/db/backends/oracle/base.py b/django/db/backends/oracle/base.py
@@ -13,6 +13,7 @@
 from django.core.exceptions import ImproperlyConfigured
 from django.db import IntegrityError
 from django.db.backends.base.base import BaseDatabaseWrapper
+from django.db.backends.utils import debug_transaction
 from django.utils.asyncio import async_unsafe
 from django.utils.encoding import force_bytes, force_str
 from django.utils.functional import cached_property
@@ -306,7 +307,7 @@ def create_cursor(self, name=None):
 
     def _commit(self):
         if self.connection is not None:
-            with wrap_oracle_errors():
+            with debug_transaction(self, "COMMIT"), wrap_oracle_errors():
                 return self.connection.commit()
 
     # Oracle doesn't support releasing savepoints. But we fake them when query
diff --git a/django/db/backends/utils.py b/django/db/backends/utils.py
@@ -144,6 +144,35 @@ def debug_sql(
             )
 
 
+@contextmanager
+def debug_transaction(connection, sql):
+    start = time.monotonic()
+    try:
+        yield
+    finally:
+        if connection.queries_logged:
+            stop = time.monotonic()
+            duration = stop - start
+            connection.queries_log.append(
+                {
+                    "sql": "%s" % sql,
+                    "time": "%.3f" % duration,
+                }
+            )
+            logger.debug(
+                "(%.3f) %s; args=%s; alias=%s",
+                duration,
+                sql,
+                None,
+                connection.alias,
+                extra={
+                    "duration": duration,
+                    "sql": sql,
+                    "alias": connection.alias,
+                },
+            )
+
+
 def split_tzname_delta(tzname):
     """
     Split a time zone name into a 3-tuple of (name, sign, offset).
diff --git a/docs/ref/logging.txt b/docs/ref/logging.txt
@@ -196,9 +196,13 @@ For performance reasons, SQL logging is only enabled when
 level or handlers that are installed.
 
 This logging does not include framework-level initialization (e.g.
-``SET TIMEZONE``) or transaction management queries (e.g. ``BEGIN``,
-``COMMIT``, and ``ROLLBACK``). Turn on query logging in your database if you
-wish to view all database queries.
+``SET TIMEZONE``). Turn on query logging in your database if you wish to view
+all database queries.
+
+.. versionchanged:: 4.2
+
+    Support for logging transaction management queries (``BEGIN``, ``COMMIT``,
+    and ``ROLLBACK``) was added.
 
 .. _django-security-logger:
 
diff --git a/docs/releases/4.2.txt b/docs/releases/4.2.txt
@@ -199,7 +199,8 @@ Internationalization
 Logging
 ~~~~~~~
 
-* ...
+* The :ref:`django-db-logger` logger now logs transaction management queries
+  (``BEGIN``, ``COMMIT``, and ``ROLLBACK``) at the ``DEBUG`` level.
 
 Management Commands
 ~~~~~~~~~~~~~~~~~~~
diff --git a/tests/backends/base/test_base.py b/tests/backends/base/test_base.py
@@ -1,10 +1,16 @@
 from unittest.mock import MagicMock, patch
 
-from django.db import DEFAULT_DB_ALIAS, connection, connections
+from django.db import DEFAULT_DB_ALIAS, connection, connections, transaction
 from django.db.backends.base.base import BaseDatabaseWrapper
-from django.test import SimpleTestCase, TestCase, skipUnlessDBFeature
+from django.test import (
+    SimpleTestCase,
+    TestCase,
+    TransactionTestCase,
+    skipUnlessDBFeature,
+)
+from django.test.utils import CaptureQueriesContext, override_settings
 
-from ..models import Square
+from ..models import Person, Square
 
 
 class DatabaseWrapperTests(SimpleTestCase):
@@ -55,6 +61,57 @@ def test_check_database_version_supported_with_none_as_database_version(self):
             connection.check_database_version_supported()
 
 
+class DatabaseWrapperLoggingTests(TransactionTestCase):
+    available_apps = []
+
+    @override_settings(DEBUG=True)
+    def test_commit_debug_log(self):
+        conn = connections[DEFAULT_DB_ALIAS]
+        with CaptureQueriesContext(conn):
+            with self.assertLogs("django.db.backends", "DEBUG") as cm:
+                with transaction.atomic():
+                    Person.objects.create(first_name="first", last_name="last")
+
+                self.assertGreaterEqual(len(conn.queries_log), 3)
+                self.assertEqual(conn.queries_log[-3]["sql"], "BEGIN")
+                self.assertRegex(
+                    cm.output[0],
+                    r"DEBUG:django.db.backends:\(\d+.\d{3}\) "
+                    rf"BEGIN; args=None; alias={DEFAULT_DB_ALIAS}",
+                )
+                self.assertEqual(conn.queries_log[-1]["sql"], "COMMIT")
+                self.assertRegex(
+                    cm.output[-1],
+                    r"DEBUG:django.db.backends:\(\d+.\d{3}\) "
+                    rf"COMMIT; args=None; alias={DEFAULT_DB_ALIAS}",
+                )
+
+    @override_settings(DEBUG=True)
+    def test_rollback_debug_log(self):
+        conn = connections[DEFAULT_DB_ALIAS]
+        with CaptureQueriesContext(conn):
+            with self.assertLogs("django.db.backends", "DEBUG") as cm:
+                with self.assertRaises(Exception), transaction.atomic():
+                    Person.objects.create(first_name="first", last_name="last")
+                    raise Exception("Force rollback")
+
+                self.assertEqual(conn.queries_log[-1]["sql"], "ROLLBACK")
+                self.assertRegex(
+                    cm.output[-1],
+                    r"DEBUG:django.db.backends:\(\d+.\d{3}\) "
+                    rf"ROLLBACK; args=None; alias={DEFAULT_DB_ALIAS}",
+                )
+
+    def test_no_logs_without_debug(self):
+        with self.assertNoLogs("django.db.backends", "DEBUG"):
+            with self.assertRaises(Exception), transaction.atomic():
+                Person.objects.create(first_name="first", last_name="last")
+                raise Exception("Force rollback")
+
+            conn = connections[DEFAULT_DB_ALIAS]
+            self.assertEqual(len(conn.queries_log), 0)
+
+
 class ExecuteWrapperTests(TestCase):
     @staticmethod
     def call_execute(connection, params=None):

-Original file line number
+Diff line change
     Ifedapo Olarewaju <[email protected]>
     Igor Kolar <[email protected]>
     Illia Volochii <[email protected]>
 +    Ilya Bass
     Ilya Semenov <[email protected]>
     Ingo Klöcker <[email protected]>
     I.S. van Oostveen <[email protected]>