Merge pull request #1052 from psycopg/connection-log

Add connection log info

Author: dvarrazzo

psycopg/psycopg/generators.py

@@ -56,7 +56,7 @@
 READY_W = Ready.W
 READY_RW = Ready.RW
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("psycopg")
 
 
 def _connect(conninfo: str, *, timeout: float = 0.0) -> PQGenConn[PGconn]:
@@ -65,7 +65,15 @@ def _connect(conninfo: str, *, timeout: float = 0.0) -> PQGenConn[PGconn]:
     """
     deadline = monotonic() + timeout if timeout else 0.0
 
+    # To debug slowdown during connection:
+    #
+    #   $ PSYCOPG_IMPL=python python
+    #   >>> import logging
+    #   >>> logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(message)s')
+    #   >>> logging.getLogger("psycopg").setLevel(logging.DEBUG)
+
     conn = pq.PGconn.connect_start(conninfo.encode())
+    logger.debug("connection started: %s", conn)
     while True:
         if conn.status == BAD:
             encoding = conninfo_encoding(conninfo)
@@ -74,6 +82,7 @@ def _connect(conninfo: str, *, timeout: float = 0.0) -> PQGenConn[PGconn]:
             )
 
         status = conn.connect_poll()
+        logger.debug("connection polled: %s", conn)
 
         if status == POLL_READING or status == POLL_WRITING:
             wait = WAIT_R if status == POLL_READING else WAIT_W

psycopg/psycopg/pq/misc.py

@@ -162,7 +162,12 @@ def connection_summary(pgconn: abc.PGconn) -> str:
         parts.append(("database", pgconn.db.decode()))
 
     else:
-        status = ConnStatus(pgconn.status).name
+        try:
+            status = ConnStatus(pgconn.status).name
+        except ValueError:
+            # It might happen if a new status on connection appears
+            # before upgrading the ConnStatus enum.
+            status = f"status={pgconn.status} (unkndown)"
 
     if sparts := " ".join(("%s=%s" % part for part in parts)):
         sparts = f" ({sparts})"

psycopg_c/psycopg_c/_psycopg/generators.pyx

@@ -42,6 +42,7 @@ def connect(conninfo: str, *, timeout: float = 0.0) -> PQGenConn[abc.PGconn]:
     if timeout:
         deadline = monotonic() + timeout
 
+    logger.debug("connection started: %s", conn)
     while True:
         if conn_status == libpq.CONNECTION_BAD:
             encoding = conninfo_encoding(conninfo)
@@ -52,6 +53,7 @@ def connect(conninfo: str, *, timeout: float = 0.0) -> PQGenConn[abc.PGconn]:
 
         with nogil:
             poll_status = libpq.PQconnectPoll(pgconn_ptr)
+        logger.debug("connection polled: %s", conn)
 
         if poll_status == libpq.PGRES_POLLING_READING \
         or poll_status == libpq.PGRES_POLLING_WRITING: