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

From Fabrízio de Royes Mello
Subject Re: Adding the extension name to EData / log_line_prefix
Date
Msg-id CAFcNs+oppAQ64UjhYd2xT0tCnXAVTjMZyD2EcoS5ecMs1tgKbg@mail.gmail.com
Whole thread Raw
In response to Adding the extension name to EData / log_line_prefix  (Andres Freund <andres@anarazel.de>)
Responses Re: Adding the extension name to EData / log_line_prefix
List pgsql-hackers


On Mon, May 13, 2024 at 5:51 PM Andres Freund <andres@anarazel.de> wrote:
>
> 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.
>

I liked the idea ... It is very helpful for troubleshooting problems in production.


> 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.
>

Then every extension should define their own Pg_extension_filename, right?


> 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');
>
>

Was not able to build your patch by simply:

./configure --prefix=/tmp/pg
...
make -j
...
/usr/bin/ld: ../../src/port/libpgport_srv.a(path_srv.o): warning: relocation against `Pg_extension_filename' in read-only section `.text'
/usr/bin/ld: access/brin/brin.o: in function `brininsert':
/data/src/pg/main/src/backend/access/brin/brin.c:403: undefined reference to `Pg_extension_filename'
/usr/bin/ld: access/brin/brin.o: in function `brinbuild':
/data/src/pg/main/src/backend/access/brin/brin.c:1107: undefined reference to `Pg_extension_filename'
/usr/bin/ld: access/brin/brin.o: in function `brin_summarize_range':
/data/src/pg/main/src/backend/access/brin/brin.c:1383: undefined reference to `Pg_extension_filename'
/usr/bin/ld: /data/src/pg/main/src/backend/access/brin/brin.c:1389: undefined reference to `Pg_extension_filename'
/usr/bin/ld: /data/src/pg/main/src/backend/access/brin/brin.c:1434: undefined reference to `Pg_extension_filename'
/usr/bin/ld: access/brin/brin.o:/data/src/pg/main/src/backend/access/brin/brin.c:1450: more undefined references to `Pg_extension_filename' follow
/usr/bin/ld: warning: creating DT_TEXTREL in a PIE
collect2: error: ld returned 1 exit status
make[2]: *** [Makefile:67: postgres] Error 1
make[2]: Leaving directory '/data/src/pg/main/src/backend'
make[1]: *** [Makefile:42: all-backend-recurse] Error 2
make[1]: Leaving directory '/data/src/pg/main/src'
make: *** [GNUmakefile:11: all-src-recurse] Error 2


> 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.
>

Hmmm, depending on the extension it can extensively call/use postgres code so would be nice if we can differentiate if the code is called from Postgres itself or from an extension.

Regards,

--
Fabrízio de Royes Mello

pgsql-hackers by date:

Previous
From: Nathan Bossart
Date:
Subject: Re: pg_sequence_last_value() for unlogged sequences on standbys
Next
From: Artur Formella
Date:
Subject: Re: Allowing additional commas between columns, and at the end of the SELECT clause