add: Log actual host and port of listener connection

Diagnosing problems with listener channel notifications not being handled properly by PostgREST connected to read replicas is difficult. Issues might be related to lost connections and listener not being connected to the right host after failover or database server restarts.
This patch adds logging of actual host:port used by libpq connection opened by the listener. It should make it easier to find out if PostgREST is connected to the right host.

CHANGELOG.md

@@ -9,6 +9,7 @@ All notable changes to this project will be documented in this file. From versio
 - Log error when `db-schemas` config contains schema `pg_catalog` or `information_schema` by @taimoorzaeem in #4359
 - Add a `HINT` when the LISTEN channel stops working due to a PostgreSQL bug by @laurenceisla in #4581
 - Add string slicing operator for `jwt-role-claim-key` by @taimoorzaeem in #4599
+- Log the actual host and port of listener database connection by @mkleczek in #4617
 
 ### Fixed
 

src/PostgREST/Listener.hs

@@ -17,8 +17,11 @@ import           PostgREST.Version     (prettyVersion)
 import qualified PostgREST.AppState as AppState
 import qualified PostgREST.Config   as Config
 
-import Data.Either.Combinators (whenRight)
-import Protolude
+import           Control.Arrow             ((&&&))
+import           Data.Bitraversable        (bisequence)
+import           Data.Either.Combinators   (whenRight)
+import qualified Database.PostgreSQL.LibPQ as LibPQ
+import           Protolude
 
 -- | Starts the Listener in a thread
 runListener :: AppState -> IO ()
@@ -70,7 +73,9 @@ retryingListen appState = do
             -- reset the delay
             AppState.putNextListenerDelay appState 1
 
-          observer $ DBListenStart dbChannel
+          (pqHost, pqPort) <- SQL.withLibPQConnection db $ bisequence . (LibPQ.host &&& LibPQ.port)
+          observer $ DBListenStart pqHost pqPort dbChannel
+
           SQL.waitForNotifications handleNotification db
 
         Left err -> do

src/PostgREST/Observation.hs

@@ -44,7 +44,7 @@ data Observation
   | SchemaCacheSummaryObs Text
   | SchemaCacheLoadedObs Double
   | ConnectionRetryObs Int
-  | DBListenStart Text
+  | DBListenStart (Maybe ByteString) (Maybe ByteString) Text -- host, port, channel
   | DBListenFail Text (Either SQL.ConnectionError (Either SomeException ()))
   | DBListenRetry Int
   | DBListenBugHint -- https://github.com/PostgREST/postgrest/issues/3147
@@ -110,8 +110,8 @@ observationMessage = \case
     "Attempting to reconnect to the database in " <> (show delay::Text) <> " seconds..."
   QueryPgVersionError usageErr ->
     "Failed to query the PostgreSQL version. " <> jsonMessage usageErr
-  DBListenStart channel -> do
-    "Listening for database notifications on the " <> show channel <> " channel"
+  DBListenStart host port channel -> do
+    "Listener connected to " <> show (fold $ host <> fmap (":" <>) port) <> " and listening for database notifications on the " <> show channel <> " channel"
   DBListenFail channel listenErr ->
     "Failed listening for database notifications on the " <> show channel <> " channel. " <>
       either showListenerConnError showListenerException listenErr

test/io/test_io.py

@@ -1640,6 +1640,23 @@ def test_log_listener_connection_errors(defaultenv):
         )
 
 
+def test_log_listener_connection_start(defaultenv):
+    "The logs should show the listener connection start message in a single line"
+
+    env = {
+        **defaultenv,
+        "PGRST_DB_CHANNEL_ENABLED": "true",
+    }
+
+    with run(env=env, no_startup_stdout=False, wait_for_readiness=True) as postgrest:
+        output = postgrest.read_stdout(nlines=5)
+        assert any(
+            f'Listener connected to "{defaultenv["PGHOST"]}:5432" and listening for database notifications on the "pgrst" channel'
+            in line
+            for line in output
+        )
+
+
 def test_db_pre_config_with_pg_reserved_words(defaultenv):
     "The db-pre-config should not fail unexpectedly when function name is a postgres reserved word"