Fixed #30148 -- Logged COPY ... TO statements in connection.queries on PostgreSQL.

[kingbuzzman]

I ran into an issue where I was running postgres commands copy_expert() / copy_to() and my queries weren't showing up on my connection.queries while DEBUG=True. I figured no one has needed this before, but I need it for my tests to pass.

https://code.djangoproject.com/ticket/30148#ticket

[timgraham]

Seems okay, however, I'd like to see if the logic in the existing CursorDebugWrapper could be refactored into a contextmanager or something so that the boilerplate doesn't need to be repeated in every method.

[kingbuzzman]

@timgraham I thought of the same thing... i was trying to keep the changes to a minimum. I can work on that.

[rixx]

Looks pretty clean with the decorator to my eyes – can you address the failing tests, @kingbuzzman?

[kingbuzzman]

@rixx Believe me it's in my todo list, havent had a chance to readdress this, i'll be in a plane tomorrow for 8+ hours, hopefully i will do it then.

[kingbuzzman]

@timgraham i think this is not my error. can you verify? @rixx i had some time :D -- dumb bug took me a good hour to find

[felixxm]

@kingbuzzman Thanks for this patch 👍 Can you squash all commits and split changes into two, first with refactoring (Refs #30148 -- ...) and second with fix (Fixed #30148 -- ...)?

What do you think about using contextmanager and moving debug_sql() to the CursorDebugWrapper? it looks much simpler IMO, also you've changed sql format in executemany() what is not expected. Please find below proposed diff:

diff --git a/django/db/backends/postgresql/utils.py b/django/db/backends/postgresql/utils.py
index 3adfb775ad..e78622ee65 100644
--- a/django/db/backends/postgresql/utils.py
+++ b/django/db/backends/postgresql/utils.py
@@ -1,6 +1,4 @@
-from django.db.backends.utils import (
-    CursorDebugWrapper as BaseCursorDebugWrapper, debug_sql,
-)
+from django.db.backends.utils import CursorDebugWrapper as BaseCursorDebugWrapper
 from django.utils.timezone import utc
 
 
@@ -12,10 +10,10 @@ def utc_tzinfo_factory(offset):
 
 class CursorDebugWrapper(BaseCursorDebugWrapper):
 
-    @debug_sql()
     def copy_expert(self, sql, file, *args):
-        return self.cursor.copy_expert(sql, file, *args)
+        with self.debug_sql(sql):
+            return self.cursor.copy_expert(sql, file, *args)
 
-    @debug_sql(sql='COPY {table} TO STDOUT')
     def copy_to(self, file, table, *args, **kwargs):
-        return self.cursor.copy_to(file, table, *args, **kwargs)
+        with self.debug_sql(sql='COPY %s TO STDOUT' % table):
+            return self.cursor.copy_to(file, table, *args, **kwargs)
diff --git a/django/db/backends/utils.py b/django/db/backends/utils.py
index 3ff6b907c8..3063c2b47a 100644
--- a/django/db/backends/utils.py
+++ b/django/db/backends/utils.py
@@ -2,9 +2,8 @@ import datetime
 import decimal
 import functools
 import hashlib
-import inspect
 import logging
-from functools import wraps
+from contextlib import contextmanager
 from time import time
 
 from django.conf import settings
@@ -91,48 +90,41 @@ class CursorWrapper:
             return self.cursor.executemany(sql, param_list)
 
 
-def debug_sql(sql='{sql}', params_name=None, use_last_executed_query=False):
-    _sql = sql
-    _params_name = params_name
-    _use_last_executed_query = use_last_executed_query
-
-    def wrapper(fn):
-        @wraps(fn)
-        def wrapped(self, *args, **kwargs):
-            start = time()
-            arguments = inspect.signature(fn).bind(self, *args, **kwargs).arguments
-            try:
-                return fn(**arguments)
-            finally:
-                params = arguments.get(_params_name)
-                sql = _sql.format(**arguments)
-                if _use_last_executed_query:
-                    sql = self.db.ops.last_executed_query(self.cursor, sql, params)
-                stop = time()
-                duration = stop - start
-                self.db.queries_log.append({
-                    'sql': sql,
-                    'time': "%.3f" % duration,
-                })
-                logger.debug(
-                    '(%.3f) %s; args=%s', duration, sql, params,
-                    extra={'duration': duration, 'sql': sql, 'params': params}
-                )
-        return wrapped
-    return wrapper
-
-
 class CursorDebugWrapper(CursorWrapper):
 
     # XXX callproc isn't instrumented at this time.
 
-    @debug_sql(params_name='params', use_last_executed_query=True)
     def execute(self, sql, params=None):
-        return super().execute(sql, params)
+        with self.debug_sql(sql, params, use_last_executed_query=True):
+            return super().execute(sql, params)
 
-    @debug_sql(params_name='param_list')
     def executemany(self, sql, param_list):
-        return super().executemany(sql, param_list)
+        with self.debug_sql(sql, param_list, many=True):
+            return super().executemany(sql, param_list)
+
+    @contextmanager
+    def debug_sql(self, sql=None, params=None, use_last_executed_query=False, many=False):
+        start = time()
+        try:
+            yield
+        finally:
+            if use_last_executed_query:
+                sql = self.db.ops.last_executed_query(self.cursor, sql, params)
+            stop = time()
+            duration = stop - start
+            try:
+                times = len(params) if many else ''
+            except TypeError:
+                # params could be an iterator.
+                times = '?'
+            self.db.queries_log.append({
+                'sql': '%s times: %s' % (times, sql) if many else sql,
+                'time': "%.3f" % duration,
+            })
+            logger.debug(
+                '(%.3f) %s; args=%s', duration, sql, params,
+                extra={'duration': duration, 'sql': sql, 'params': params}
+            )
 
 
 ###############################################

[kingbuzzman]

@felixxm I think that looks great! Yeah! Probably get to this by next week. Thanks!

[kingbuzzman]

@felixxm looks like everything is passing.

[felixxm]

@kingbuzzman Thanks for updates 👍 I rebased from master, added short release note, and made some cosmetic changes.