Re: Adding the extension name to EData / log_line_prefix

On Mon, May 13, 2024 at 5:51 PM Andres Freund <andres(at)anarazel(dot)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