Log the store connection early in TPC. On PostgreSQL, this includes t…

…he backend PID.

Fixes #460

CHANGES.rst

@@ -5,7 +5,8 @@
 3.4.3 (unreleased)
 ==================
 
-- Nothing changed yet.
+- PostgreSQL: Log the backend PID at the start of TPC. This can help
+  correlate error messages from the server. See :issue:`460`.
 
 
 3.4.2 (2021-04-21)

src/relstorage/adapters/connections.py

@@ -49,6 +49,7 @@ def __init__(self, connmanager):
         self.connection = None
         self.connmanager = connmanager
         self._cursor = None
+        self._connection_description = None
         self.active = False
         self._new_connection = getattr(connmanager, self._NEW_CONNECTION_NAME)
         self._restart = getattr(connmanager, self._RESTART_NAME)
@@ -156,6 +157,7 @@ def _open_connection(self):
         """
         new_conn, new_cursor = self._new_connection()
         self.connection, self._cursor = new_conn, new_cursor
+        self._connection_description = self.connmanager.describe_connection(new_conn, new_cursor)
         self.on_opened(new_conn, new_cursor)
 
     @staticmethod
@@ -279,10 +281,11 @@ def server_side_cursor(self):
             self.connmanager.close(cursor=ss_cursor)
 
     def __repr__(self):
-        return "<%s at 0x%x active=%s, conn=%r cur=%r>" % (
+        return "<%s at 0x%x active=%s description=%s conn=%r cur=%r>" % (
             self.__class__.__name__,
             id(self),
             self.active,
+            self._connection_description,
             self.connection,
             self._cursor
         )

src/relstorage/adapters/connmanager.py

@@ -397,3 +397,6 @@ def restart_store(self, conn, cursor, needs_rollback=True):
         self._after_opened_for_store(conn, cursor)
         self._call_hooks(self._on_store_opened, conn, cursor,
                          cursor, restart=True)
+
+    def describe_connection(self, conn, cursor): # pylint:disable=unused-argument
+        return "<unknown>"

src/relstorage/adapters/interfaces.py

@@ -529,6 +529,15 @@ def add_on_load_opened(f):
         .. versionadded:: 2.1a1
         """
 
+    def describe_connection(conn, cursor):
+        """
+        Return an object that describes the connection.
+
+        The object should have a useful `str` value.
+
+        .. versionadded:: 3.4.3
+        """
+
 
 class IManagedDBConnection(Interface):
     """

src/relstorage/adapters/postgresql/__init__.py

@@ -19,89 +19,3 @@
 
 
 assert PostgreSQLAdapter
-
-
-def debug_locks(cursor, me_only=False, exclusive_only=False): # pragma: no cover
-    if me_only:
-        conn = cursor.connection
-        try:
-            pid = conn.info.backend_pid
-        except AttributeError:
-            # connection.info was added to psycopg2 in 2.8.0
-            cursor.execute("SELECT pg_backend_pid()")
-            pid = cursor.fetchall()[0][0]
-        params = (pid,)
-        pid_clause = ' AND a.pid = %s '
-    else:
-        pid_clause = ''
-        params = ()
-    excl_clause = ''
-    if exclusive_only:
-        excl_clause = """ AND l.mode like '%%Exclu%%' """
-
-    stmt = """
-    SELECT
-         a.datname,
-         l.relation::regclass,
-         l.locktype,
-         l.mode,
-         l.pid,
-         l.virtualxid, l.transactionid,
-         l.objid, l.objsubid,
-         l.virtualtransaction,
-         l.granted
-    FROM pg_stat_activity a
-    JOIN pg_locks l ON l.pid = a.pid
-    WHERE l.locktype <> 'virtualxid'
-    {pid_clause}
-    {excl_clause}
-    ORDER BY a.pid
-    """.format(
-        pid_clause=pid_clause,
-        excl_clause=excl_clause
-    )
-    cursor.execute(stmt, params)
-    return cursor
-
-def debug_my_locks(cursor, exclusive_only=False): # pragma: no cover
-    return debug_locks(cursor, me_only=True, exclusive_only=exclusive_only)
-
-def print_size_report(cursor): # pragma: no cover
-    extra_query = ''
-    query = """
-    SELECT table_name,
-        pg_size_pretty(total_bytes) AS total,
-        pg_size_pretty(index_bytes) AS INDEX,
-        pg_size_pretty(toast_bytes) AS toast,
-        pg_size_pretty(table_bytes) AS TABLE
-    FROM (
-    SELECT *, total_bytes-index_bytes-COALESCE(toast_bytes,0) AS table_bytes FROM (
-    SELECT c.oid,nspname AS table_schema, relname AS TABLE_NAME
-          , c.reltuples AS row_estimate
-          , pg_total_relation_size(c.oid) AS total_bytes
-          , pg_indexes_size(c.oid) AS index_bytes
-          , pg_total_relation_size(reltoastrelid) AS toast_bytes
-      FROM pg_class c
-      LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
-      WHERE relkind = 'r'
-        ) a
-    ) a
-    WHERE (table_name NOT LIKE 'pg_%' and table_name not like 'abstract_%'
-    )
-    AND table_schema <> 'pg_catalog' and table_schema <> 'information_schema'
-    ORDER BY total_bytes DESC
-    """
-
-    cursor.execute(query)
-    keys = ['table_name', 'total', 'index', 'toast', 'table']
-    rows = [dict(zip(keys, row)) for row in cursor]
-
-    rows.insert(0, {k: k for k in keys})
-    print()
-    fmt = "| {table_name:35s} | {total:10s} | {index:10s} | {toast:10s} | {table:10s}"
-    for row in rows:
-        if not extra_query and row['total'] in ('72 kB', '32 kB', '24 kB', '16 kB', '8192 bytes'):
-            continue
-        print(fmt.format(
-            **{k: v if v else '<null>' for k, v in row.items()}
-        ))

src/relstorage/adapters/postgresql/connmanager.py

@@ -19,6 +19,7 @@
 
 from ..._util import metricmethod
 from ..connmanager import AbstractConnectionManager
+from .util import backend_pid_for_connection
 
 logger = logging.getLogger(__name__)
 
@@ -134,3 +135,6 @@ def _do_open_for_load(self):
             replica_selector=self.ro_replica_selector,
             application_name='RS: Load'
         )
+
+    def describe_connection(self, conn, cursor):
+        return {'backend_pid': backend_pid_for_connection(conn, cursor)}

src/relstorage/adapters/postgresql/locker.py

@@ -60,7 +60,7 @@ def _get_commit_lock_debug_info(self, cursor, was_failure=False):
             cursor.connection.rollback()
             return 'Transaction failed; no lock info available'
 
-        from . import debug_locks
+        from .util import debug_locks
         debug_locks(cursor)
         return self._rows_as_pretty_string(cursor)
 

src/relstorage/adapters/postgresql/util.py

@@ -0,0 +1,106 @@
+##############################################################################
+#
+# Copyright (c) 2008 Zope Foundation and Contributors.
+# All Rights Reserved.
+#
+# This software is subject to the provisions of the Zope Public License,
+# Version 2.1 (ZPL).  A copy of the ZPL should accompany this distribution.
+# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
+# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
+# FOR A PARTICULAR PURPOSE.
+#
+##############################################################################
+"""PostgreSQL utilities."""
+from __future__ import absolute_import
+from __future__ import print_function
+
+def backend_pid_for_connection(conn, cursor):
+    try:
+        pid = conn.info.backend_pid
+    except AttributeError:
+        # connection.info was added to psycopg2 in 2.8.0
+        cursor.execute("SELECT pg_backend_pid()")
+        pid = cursor.fetchall()[0][0]
+    return pid
+
+
+def debug_locks(cursor, me_only=False, exclusive_only=False): # pragma: no cover
+    if me_only:
+        conn = cursor.connection
+        pid = backend_pid_for_connection(conn, cursor)
+        params = (pid,)
+        pid_clause = ' AND a.pid = %s '
+    else:
+        pid_clause = ''
+        params = ()
+    excl_clause = ''
+    if exclusive_only:
+        excl_clause = """ AND l.mode like '%%Exclu%%' """
+
+    stmt = """
+    SELECT
+         a.datname,
+         l.relation::regclass,
+         l.locktype,
+         l.mode,
+         l.pid,
+         l.virtualxid, l.transactionid,
+         l.objid, l.objsubid,
+         l.virtualtransaction,
+         l.granted
+    FROM pg_stat_activity a
+    JOIN pg_locks l ON l.pid = a.pid
+    WHERE l.locktype <> 'virtualxid'
+    {pid_clause}
+    {excl_clause}
+    ORDER BY a.pid
+    """.format(
+        pid_clause=pid_clause,
+        excl_clause=excl_clause
+    )
+    cursor.execute(stmt, params)
+    return cursor
+
+def debug_my_locks(cursor, exclusive_only=False): # pragma: no cover
+    return debug_locks(cursor, me_only=True, exclusive_only=exclusive_only)
+
+def print_size_report(cursor): # pragma: no cover
+    extra_query = ''
+    query = """
+    SELECT table_name,
+        pg_size_pretty(total_bytes) AS total,
+        pg_size_pretty(index_bytes) AS INDEX,
+        pg_size_pretty(toast_bytes) AS toast,
+        pg_size_pretty(table_bytes) AS TABLE
+    FROM (
+    SELECT *, total_bytes-index_bytes-COALESCE(toast_bytes,0) AS table_bytes FROM (
+    SELECT c.oid,nspname AS table_schema, relname AS TABLE_NAME
+          , c.reltuples AS row_estimate
+          , pg_total_relation_size(c.oid) AS total_bytes
+          , pg_indexes_size(c.oid) AS index_bytes
+          , pg_total_relation_size(reltoastrelid) AS toast_bytes
+      FROM pg_class c
+      LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
+      WHERE relkind = 'r'
+        ) a
+    ) a
+    WHERE (table_name NOT LIKE 'pg_%' and table_name not like 'abstract_%'
+    )
+    AND table_schema <> 'pg_catalog' and table_schema <> 'information_schema'
+    ORDER BY total_bytes DESC
+    """
+
+    cursor.execute(query)
+    keys = ['table_name', 'total', 'index', 'toast', 'table']
+    rows = [dict(zip(keys, row)) for row in cursor]
+
+    rows.insert(0, {k: k for k in keys})
+    print()
+    fmt = "| {table_name:35s} | {total:10s} | {index:10s} | {toast:10s} | {table:10s}"
+    for row in rows:
+        if not extra_query and row['total'] in ('72 kB', '32 kB', '24 kB', '16 kB', '8192 bytes'):
+            continue
+        print(fmt.format(
+            **{k: v if v else '<null>' for k, v in row.items()}
+        ))

src/relstorage/storage/tpc/__init__.py

@@ -45,7 +45,7 @@
 
 from .temporary_storage import TemporaryStorage
 
-log = logging.getLogger("relstorage")
+logger = logging.getLogger(__name__)
 
 _CLOSED_CONNECTION = ClosedConnection()
 
@@ -111,7 +111,11 @@ def __init__(self, initial_state, storage, transaction):
 
     @_LazyResource
     def store_connection(self):
-        return self._storage._store_connection_pool.borrow()
+        conn = self._storage._store_connection_pool.borrow()
+        # Report on the connection we will use.
+        # https://github.com/zodb/relstorage/issues/460
+        logger.info("Using store connection %s", conn)
+        return conn
 
     @store_connection.aborter
     def store_connection(self, storage, store_connection, force):

src/relstorage/tests/__init__.py

@@ -341,6 +341,9 @@ def cursor_for_connection(self, conn):
     def open_and_call(self, func):
         return func(*self.open_for_load())
 
+    def describe_connection(self, _conn, _cursor):
+        return "<MockConnectionManager>"
+
 class MockPackUndo(object):
     pass