Channel retrying message doesn't doesn't follow log format

[steve-chavez]

Problem

When doing:

$ postgrest-with-postgresql-16 -f test/spec/fixtures/load.sql postgrest-run

select pg_terminate_backend(pid) from pg_stat_activity where application_name ilike '%postgrest%' and query ilike '%listen%';

The following logs are produced:

08/Mar/2024:10:34:43 -0500: Starting PostgREST 12.1...
08/Mar/2024:10:34:43 -0500: Attempting to connect to the database...
08/Mar/2024:10:34:43 -0500: Successfully connected to PostgreSQL 14.10 (Ubuntu 14.10-0ubuntu0.22.04.1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
08/Mar/2024:10:34:43 -0500: Listening on port 3000
08/Mar/2024:10:34:43 -0500: Listening for notifications on the pgrst channel
08/Mar/2024:10:34:43 -0500: Config reloaded
08/Mar/2024:10:34:43 -0500: Schema cache queried in 2.3 milliseconds
08/Mar/2024:10:34:43 -0500: Schema cache loaded 1 Relations, 0 Relationships, 8 Functions, 0 Domain Representations, 4 Media Type Handlers
08/Mar/2024:10:34:43 -0500: Schema cache loaded in 0.1 milliseconds
FATAL:  terminating connection due to administrator command
08/Mar/2024:10:35:12 -0500: Retrying listening for notifications on the pgrst channel..

Note the FATAL: terminating connection due to administrator command, it doesn't follow the same format.

Maybe there's a die (prints to stderr) somewhere in our code or hasql-notifications.

Related

• Computed Relations slow at first request or after idle #3313 (reply in thread)

[steve-chavez]

This might be another issue. But I've noticed that hasql-notification is ignoring an error. Check:

void $ PQ.consumeInput pqCon

https://github.com/diogob/hasql-notifications/blob/master/src/Hasql/Notifications.hs#L175

And the pg docs say:

PQconsumeInput normally returns 1 indicating “no error”, but returns 0 if there was some kind of trouble (in which case PQerrorMessage can be consulted).

Edit: Reported this on diogob/hasql-notifications#20.

[steve-chavez]

FATAL: terminating connection due to administrator command
Maybe there's a die (prints to stderr) somewhere in our code or hasql-notifications.

I think the above doesn't come from hasql-notifications but rather from hasql-pool.

[laurenceisla]

It looks like it comes from the LibPQ library.

It can be traced first in the hasql-notifications code. I used Debug.Trace to check exactly where this happened:

import Debug.Trace (traceIO)
-- ...
waitForNotifications sendNotification con =
  withLibPQConnection con $ void . forever . pqFetch
  where
    pqFetch pqCon = do
      traceIO "Before notifies"
      mNotification <- PQ.notifies pqCon
      traceIO "After notifies"
-- ...

Then, after executing the pg_terminate_backend command, the logs start with:

Before notifies
FATAL:  terminating connection due to administrator command
After notifies

Which leads to the postgresql-libpq code:

-- ...
notifies connection =
    withConn connection $ \ptr ->
           traceIO "Before PQnotifies"
           mn <- c_PQnotifies ptr
           traceIO "After PQnotifies"
-- ...

And it logs:

Before PQnotifies
FATAL:  terminating connection due to administrator command
After PQnotifies

So maybe somewhere in the PQnotifies function of the LibPQ library, it logs this error?

Some notes:

• It does return an error message that could be used, although it does it after the FATAL: ... log.
• Not sure if the FATAL:.. log can be stopped/modified at the hasql-notifications or postgresql-libpq libraries.