Better more logging

asyncpg/connection.py

@@ -9,6 +9,7 @@
 import asyncpg
 import collections
 import collections.abc
+from datetime import datetime, timezone
 import functools
 import itertools
 import inspect
@@ -305,6 +306,25 @@ def is_in_transaction(self):
         """
         return self._protocol.is_in_transaction()
 
+    def log_statement(self, context: str, statement: str, args=None):
+        when = datetime.now(timezone.utc)
+
+        if self._recent_statements:
+            most_recently_logged = self._recent_statements[-1]
+            # Each entry is (timestamp, calling context, sql statement, args (if any)) tuple.
+            (
+                _,
+                _,
+                prior_statement,
+                _,
+            ) = most_recently_logged
+            if prior_statement == statement:
+                # Do not double-log same query.
+                return
+
+        to_log = (when.strftime("%Y-%m-%d %H:%M:%S UTC"), context, statement, args)
+        self._recent_statements.append(to_log)
+
     async def execute(self, query: str, *args, timeout: float = None) -> str:
         """Execute an SQL command (or commands).
 
@@ -335,12 +355,8 @@ async def execute(self, query: str, *args, timeout: float = None) -> str:
         """
         self._check_open()
 
-        # Append to circular buffer of most recent executed statements
-        # for debugging.
-        self._recent_statements.append(query)
-
         if not args:
-            self._recent_statements.append(query)
+            self.log_statement("execute no args", query)
             return await self._protocol.query(query, timeout)
 
         _, status, _ = await self._execute(
@@ -541,7 +557,7 @@ def cursor(self, query, *args, prefetch=None, timeout=None, record_class=None):
         """
         self._check_open()
 
-        self._recent_statements.append(query)
+        self.log_statement("cursor", query, args)
 
         return cursor.CursorFactory(
             self,
@@ -1802,7 +1818,7 @@ async def _do_execute(
         ignore_custom_codec=False,
         record_class=None,
     ):
-        self._recent_statements.append(query)
+        self.log_statement("_do_execute", query)
         if timeout is None:
             stmt = await self._get_statement(
                 query,

asyncpg/prepared_stmt.py

@@ -15,7 +15,7 @@
 class PreparedStatement(connresource.ConnectionResource):
     """A representation of a prepared statement."""
 
-    __slots__ = ("_state", "_query", "_last_status")
+    __slots__ = ("_state", "_query", "_last_status", "_logged_args")
 
     def __init__(self, connection, query, state):
         super().__init__(connection)
@@ -219,13 +219,16 @@ async def executemany(self, args, *, timeout: float = None):
 
         .. versionadded:: 0.22.0
         """
+        self._logged_args = args
         return await self.__do_execute(
             lambda protocol: protocol.bind_execute_many(self._state, args, "", timeout)
         )
 
     async def __do_execute(self, executor):
         protocol = self._connection._protocol
-        self._connection._recent_statements.append(self._query)
+        self._connection.log_statement(
+            "preparedstatement __do_execute", self._query, self._logged_args
+        )
         try:
             return await executor(protocol)
         except exceptions.OutdatedSchemaCacheError:
@@ -238,6 +241,7 @@ async def __do_execute(self, executor):
             raise
 
     async def __bind_execute(self, args, limit, timeout):
+        self._logged_args = args
         data, status, _ = await self.__do_execute(
             lambda protocol: protocol.bind_execute(
                 self._state, args, "", limit, True, timeout