RAISE INFO show in the PostgREST logs

[steve-chavez]

Problem

Doing:

create function raise_blah() returns void
  language plpgsql
  as $$
begin
    raise INFO 'Blah-1';
    raise 'Blah-2';
    raise DEBUG 'Blah-3';
    raise LOG 'Blah-4';
    raise NOTICE 'Blah-5';
    raise WARNING 'Blah-6';
end
$$;

curl localhost:3000/rpc/raise_blah

Results in this:

25/Jun/2024:13:58:39 -0500: Starting PostgREST 12.3 (bf9b6d8)...
25/Jun/2024:13:58:39 -0500: Attempting to connect to the database...
25/Jun/2024:13:58:39 -0500: Listening on port 3000
25/Jun/2024:13:58:39 -0500: Successfully connected to PostgreSQL 15.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 13.2.0, 64-bit
25/Jun/2024:13:58:39 -0500: Listening for notifications on the "pgrst" channel
25/Jun/2024:13:58:39 -0500: Config reloaded
25/Jun/2024:13:58:39 -0500: Schema cache queried in 11.6 milliseconds
25/Jun/2024:13:58:39 -0500: Schema cache loaded 266 Relations, 221 Relationships, 144 Functions, 15 Domain Representations, 45 Media Type Handlers

INFO:  Blah-1

It doesn't matter if client_min_messages is set:

alter role postgrest_test_authenticator set client_min_messages to WARNING;

Because:

INFO level messages are always sent to the client.
https://www.postgresql.org/docs/current/runtime-config-client.html#GUC-CLIENT-MIN-MESSAGES

All of this PostgREST behavior is undocumented.

Solution

Document it.

Notes

• Should we add timestamp to the RAISE logs?
• Should we try to adjust these logs with a config? Logs flooding could be a problem.

[wolfgangwalther]

create function raise_blah() returns void
  language plpgsql
  as $$
begin
    raise INFO 'Blah-1';
    raise 'Blah-2';
    raise DEBUG 'Blah-3';
    raise LOG 'Blah-4';
    raise NOTICE 'Blah-5';
    raise WARNING 'Blah-6';
end
$$;

This is kind of an odd test-case, I think. The second raise will throw an error, so stop execution of that block - so none of the others will be executed. Wouldn't it be better if that breaking raise came last? Would any of the others result in log output, too?

[steve-chavez]

Right, my mistake. Using:

create function raise_blah() returns void
  language plpgsql
  as $$
begin
    raise INFO 'Blah-1';
    raise DEBUG 'Blah-3';
    raise LOG 'Blah-4';
    raise NOTICE 'Blah-5';
    raise WARNING 'Blah-6';
    raise 'Blah-2';
end
$$;

alter role postgrest_test_authenticator set client_min_messages to DEBUG5;

$ curl localhost:3000/rpc/raise_blah
{"code":"P0001","details":null,"hint":null,"message":"Blah-2"}

I get:

LOG:  statement: SET client_encoding = 'UTF8';SET client_min_messages TO WARNING;
25/Jun/2024:18:16:46 -0500: Listening for notifications on the "pgrst" channel
25/Jun/2024:18:16:46 -0500: Config reloaded
25/Jun/2024:18:16:46 -0500: Schema cache queried in 14.4 milliseconds
25/Jun/2024:18:16:46 -0500: Schema cache loaded 266 Relations, 221 Relationships, 144 Functions, 15 Domain Representations, 45 Media Type Handlers
INFO:  Blah-1
WARNING:  Blah-6

Something is always setting SET client_min_messages TO WARNING;, that's why the other RAISEs don't show. Maybe it's the connection pool.