From 798e38c2b9c46ab72e2ee8c33dc822f01b194b1e Mon Sep 17 00:00:00 2001 From: Ilya Bass Date: Thu, 20 Oct 2022 15:14:35 -0700 Subject: [PATCH] Fixed #31090 -- Logged transaction management queries. Thanks to Petter Strandmark for the original idea and Mariusz Felisiak for advice during the DjangoConUS 2022 Sprint! --- AUTHORS | 1 + django/db/backends/base/base.py | 12 ++++-- django/db/backends/oracle/base.py | 3 +- django/db/backends/utils.py | 29 ++++++++++++++ docs/ref/logging.txt | 10 +++-- docs/releases/4.2.txt | 3 +- tests/backends/base/test_base.py | 63 +++++++++++++++++++++++++++++-- 7 files changed, 109 insertions(+), 12 deletions(-) diff --git a/AUTHORS b/AUTHORS index a3848545e64..5b9d8621d96 100644 --- a/AUTHORS +++ b/AUTHORS @@ -410,6 +410,7 @@ answer newbie questions, and generally made Django that much better: Ifedapo Olarewaju Igor Kolar Illia Volochii + Ilya Bass Ilya Semenov Ingo Klöcker I.S. van Oostveen diff --git a/django/db/backends/base/base.py b/django/db/backends/base/base.py index f04bd8882a6..3b845ec9b37 100644 --- a/django/db/backends/base/base.py +++ b/django/db/backends/base/base.py @@ -8,6 +8,8 @@ import warnings 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 @@ class BaseDatabaseWrapper: 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 @@ class BaseDatabaseWrapper: 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 index 29e43d1f62b..845ab8ccf5a 100644 --- a/django/db/backends/oracle/base.py +++ b/django/db/backends/oracle/base.py @@ -13,6 +13,7 @@ from django.conf import settings 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 @@ class DatabaseWrapper(BaseDatabaseWrapper): 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 index d505cd79047..df6532e81fd 100644 --- a/django/db/backends/utils.py +++ b/django/db/backends/utils.py @@ -144,6 +144,35 @@ class CursorDebugWrapper(CursorWrapper): ) +@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 index ba443a0a366..edd9f21ecba 100644 --- 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 index 8ab9242f978..e7d2882edb4 100644 --- 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 index 57d22ce269d..ada2cc33c90 100644 --- 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 @@ class DatabaseWrapperTests(SimpleTestCase): 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):