Adding the extension name to EData / log_line_prefix - Mailing list pgsql-hackers

From Andres Freund
Subject Adding the extension name to EData / log_line_prefix
Date
Msg-id 20240513205133.dwu33yhkk24qvgqz@awork3.anarazel.de
Whole thread Raw
Responses Re: Adding the extension name to EData / log_line_prefix
List pgsql-hackers
Hi,

It can be very useful to look at the log messages emitted by a larger number
of postgres instances to see if anything unusual is happening. E.g. checking
whether there are an increased number of internal, IO, corruption errors (and
LOGs too, because we emit plenty bad things as LOG) . One difficulty is that
extensions tend to not categorize their errors. But unfortunately errors in
extensions are hard to distinguish from errors emitted by postgres.

A related issue is that it'd be useful to be able to group log messages by
extension, to e.g. see which extensions are emitting disproportionally many
log messages.

Therefore I'd like to collect the extension name in elog/ereport and add a
matching log_line_prefix escape code.


It's not entirely trivial to provide errfinish() with a parameter indicating
the extension, but it's doable:

1) Have PG_MODULE_MAGIC also define a new variable for the extension name,
   empty at that point

2) In internal_load_library(), look up that new variable, and fill it with a,
   mangled, libname.

4) in elog.h, define a new macro depending on BUILDING_DLL (if it is set,
   we're in the server, otherwise an extension). In the backend itself, define
   it to NULL, otherwise to the variable created by PG_MODULE_MAGIC.

5) In elog/ereport/errsave/... pass this new variable to
   errfinish/errsave_finish.


I've attached a *very rough* prototype of this idea. My goal at this stage was
just to show that it's possible, not for the code to be in a reviewable state.


Here's e.g. what this produces with log_line_prefix='%m [%E] '

2024-05-13 13:50:17.518 PDT [postgres] LOG:  database system is ready to accept connections
2024-05-13 13:50:19.138 PDT [cube] ERROR:  invalid input syntax for cube at character 13
2024-05-13 13:50:19.138 PDT [cube] DETAIL:  syntax error at or near "f"
2024-05-13 13:50:19.138 PDT [cube] STATEMENT:  SELECT cube('foo');

2024-05-13 13:43:07.484 PDT [postgres] LOG:  database system is ready to accept connections
2024-05-13 13:43:11.699 PDT [hstore] ERROR:  syntax error in hstore: unexpected end of string at character 15
2024-05-13 13:43:11.699 PDT [hstore] STATEMENT:  SELECT hstore('foo');


It's worth pointing out that this, quite fundamentally, can only work when the
log message is triggered directly by the extension. If the extension code
calls some postgres function and that function then errors out, it'll be seens
as being part of postgres.

But I think that's ok - they're going to be properly errcode-ified etc.


Thoughts?

Greetings,

Andres Freund

Attachment

pgsql-hackers by date:

Previous
From: Peter Eisentraut
Date:
Subject: Re: Large files for relations
Next
From: Nathan Bossart
Date:
Subject: Re: pg_sequence_last_value() for unlogged sequences on standbys