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
>From 1c59c465f2d359e8c47cf91d1ea458ea3b64ec84 Mon Sep 17 00:00:00 2001
From: Andres Freund <and...@anarazel.de>
Date: Mon, 13 May 2024 13:47:41 -0700
Subject: [PATCH v1] WIP: Track shared library in which elog/ereport is called
---
src/include/fmgr.h | 1 +
src/include/utils/elog.h | 18 +++++++++++++-----
src/backend/utils/error/elog.c | 33 ++++++++++++++++++++++++---------
src/backend/utils/fmgr/dfmgr.c | 30 ++++++++++++++++++++++++++++++
4 files changed, 68 insertions(+), 14 deletions(-)
diff --git a/src/include/fmgr.h b/src/include/fmgr.h
index ccb4070a251..3c7cfd7fee9 100644
--- a/src/include/fmgr.h
+++ b/src/include/fmgr.h
@@ -504,6 +504,7 @@ PG_MAGIC_FUNCTION_NAME(void) \
static const Pg_magic_struct Pg_magic_data = PG_MODULE_MAGIC_DATA; \
return &Pg_magic_data; \
} \
+PGDLLEXPORT const char *Pg_extension_filename = NULL; \
extern int no_such_variable
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 054dd2bf62f..5e57f01823d 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -137,6 +137,13 @@ struct Node;
* prevents gcc from making the unreachability deduction at optlevel -O0.
*----------
*/
+#ifdef BUILDING_DLL
+#define ELOG_EXTNAME NULL
+#else
+extern PGDLLEXPORT const char *Pg_extension_filename;
+#define ELOG_EXTNAME Pg_extension_filename
+#endif
+
#ifdef HAVE__BUILTIN_CONSTANT_P
#define ereport_domain(elevel, domain, ...) \
do { \
@@ -144,7 +151,7 @@ struct Node;
if (__builtin_constant_p(elevel) && (elevel) >= ERROR ? \
errstart_cold(elevel, domain) : \
errstart(elevel, domain)) \
- __VA_ARGS__, errfinish(__FILE__, __LINE__, __func__); \
+ __VA_ARGS__, errfinish(__FILE__, __LINE__, __func__, ELOG_EXTNAME); \
if (__builtin_constant_p(elevel) && (elevel) >= ERROR) \
pg_unreachable(); \
} while(0)
@@ -154,7 +161,7 @@ struct Node;
const int elevel_ = (elevel); \
pg_prevent_errno_in_scope(); \
if (errstart(elevel_, domain)) \
- __VA_ARGS__, errfinish(__FILE__, __LINE__, __func__); \
+ __VA_ARGS__, errfinish(__FILE__, __LINE__, __func__, ELOG_EXTNAME); \
if (elevel_ >= ERROR) \
pg_unreachable(); \
} while(0)
@@ -169,7 +176,7 @@ extern bool message_level_is_interesting(int elevel);
extern bool errstart(int elevel, const char *domain);
extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
-extern void errfinish(const char *filename, int lineno, const char *funcname);
+extern void errfinish(const char *filename, int lineno, const char *funcname, const char *extfile);
extern int errcode(int sqlerrcode);
@@ -268,7 +275,7 @@ extern int getinternalerrposition(void);
struct Node *context_ = (context); \
pg_prevent_errno_in_scope(); \
if (errsave_start(context_, domain)) \
- __VA_ARGS__, errsave_finish(context_, __FILE__, __LINE__, __func__); \
+ __VA_ARGS__, errsave_finish(context_, __FILE__, __LINE__, __func__, ELOG_EXTNAME); \
} while(0)
#define errsave(context, ...) \
@@ -293,7 +300,7 @@ extern int getinternalerrposition(void);
extern bool errsave_start(struct Node *context, const char *domain);
extern void errsave_finish(struct Node *context,
const char *filename, int lineno,
- const char *funcname);
+ const char *funcname, const char *extname);
/* Support for constructing error strings separately from ereport() calls */
@@ -449,6 +456,7 @@ typedef struct ErrorData
const char *funcname; /* __func__ of ereport() call */
const char *domain; /* message domain */
const char *context_domain; /* message domain for context message */
+ const char *extname; /* extension filename or NULL */
int sqlerrcode; /* encoded ERRSTATE */
char *message; /* primary error message (translated) */
char *detail; /* detail error message */
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index d91a85cb2d7..1d34e89d7f5 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -180,7 +180,7 @@ static ErrorData *get_error_stack_entry(void);
static void set_stack_entry_domain(ErrorData *edata, const char *domain);
static void set_stack_entry_location(ErrorData *edata,
const char *filename, int lineno,
- const char *funcname);
+ const char *funcname, const char *extname);
static bool matches_backtrace_functions(const char *funcname);
static pg_noinline void set_backtrace(ErrorData *edata, int num_skip);
static void set_errdata_field(MemoryContextData *cxt, char **ptr, const char *str);
@@ -474,7 +474,7 @@ errstart(int elevel, const char *domain)
* return to the caller. See elog.h for the error level definitions.
*/
void
-errfinish(const char *filename, int lineno, const char *funcname)
+errfinish(const char *filename, int lineno, const char *funcname, const char *extname)
{
ErrorData *edata = &errordata[errordata_stack_depth];
int elevel;
@@ -485,7 +485,7 @@ errfinish(const char *filename, int lineno, const char *funcname)
CHECK_STACK_DEPTH();
/* Save the last few bits of error state into the stack entry */
- set_stack_entry_location(edata, filename, lineno, funcname);
+ set_stack_entry_location(edata, filename, lineno, funcname, extname);
elevel = edata->elevel;
@@ -683,7 +683,7 @@ errsave_start(struct Node *context, const char *domain)
*/
void
errsave_finish(struct Node *context, const char *filename, int lineno,
- const char *funcname)
+ const char *funcname, const char *extname)
{
ErrorSaveContext *escontext = (ErrorSaveContext *) context;
ErrorData *edata = &errordata[errordata_stack_depth];
@@ -697,7 +697,7 @@ errsave_finish(struct Node *context, const char *filename, int lineno,
*/
if (edata->elevel >= ERROR)
{
- errfinish(filename, lineno, funcname);
+ errfinish(filename, lineno, funcname, extname);
pg_unreachable();
}
@@ -708,7 +708,7 @@ errsave_finish(struct Node *context, const char *filename, int lineno,
recursion_depth++;
/* Save the last few bits of error state into the stack entry */
- set_stack_entry_location(edata, filename, lineno, funcname);
+ set_stack_entry_location(edata, filename, lineno, funcname, extname);
/* Replace the LOG value that errsave_start inserted */
edata->elevel = ERROR;
@@ -798,7 +798,7 @@ set_stack_entry_domain(ErrorData *edata, const char *domain)
static void
set_stack_entry_location(ErrorData *edata,
const char *filename, int lineno,
- const char *funcname)
+ const char *funcname, const char *extname)
{
if (filename)
{
@@ -817,6 +817,7 @@ set_stack_entry_location(ErrorData *edata,
edata->filename = filename;
edata->lineno = lineno;
edata->funcname = funcname;
+ edata->extname = extname;
}
/*
@@ -1903,7 +1904,7 @@ ThrowErrorData(ErrorData *edata)
recursion_depth--;
/* Process the error. */
- errfinish(edata->filename, edata->lineno, edata->funcname);
+ errfinish(edata->filename, edata->lineno, edata->funcname, edata->extname);
}
/*
@@ -2000,7 +2001,7 @@ pg_re_throw(void)
*/
error_context_stack = NULL;
- errfinish(edata->filename, edata->lineno, edata->funcname);
+ errfinish(edata->filename, edata->lineno, edata->funcname, edata->extname);
}
/* Doesn't return ... */
@@ -3110,6 +3111,20 @@ log_status_format(StringInfo buf, const char *format, ErrorData *edata)
else
appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
break;
+ case 'E':
+ {
+ const char *extname = edata->extname;
+
+ if (!extname)
+ extname = "postgres";
+
+ if (padding != 0)
+ appendStringInfo(buf, "%*s", padding,
+ extname);
+ else
+ appendStringInfoString(buf, extname);
+ break;
+ }
case 'Q':
if (padding != 0)
appendStringInfo(buf, "%*lld", padding,
diff --git a/src/backend/utils/fmgr/dfmgr.c b/src/backend/utils/fmgr/dfmgr.c
index eafa0128ef0..873868b6a15 100644
--- a/src/backend/utils/fmgr/dfmgr.c
+++ b/src/backend/utils/fmgr/dfmgr.c
@@ -36,6 +36,7 @@
#include "storage/fd.h"
#include "storage/shmem.h"
#include "utils/hsearch.h"
+#include "utils/memutils.h"
/* signature for PostgreSQL-specific library init function */
@@ -268,6 +269,35 @@ internal_load_library(const char *libname)
/* issue suitable complaint */
incompatible_module_error(libname, &module_magic_data);
}
+
+ {
+ const char **extname;
+ char *libname_short;
+
+ extname = dlsym(file_scanner->handle,
+ "Pg_extension_filename");
+ if (!extname)
+ elog(ERROR, "couldn't find Pg_extension_filename");
+
+ /*
+ * For loaded libraries, the filename, without file ending,
+ * ought to be unique. Pg_extension_filename is intended for
+ * logging, a full file path would be onerous.
+ */
+ libname_short = last_dir_separator(libname) + 1;
+ libname_short = MemoryContextStrdup(TopMemoryContext,
+ last_dir_separator(libname) + 1);
+
+ for (int i = strlen(libname_short); i >= 0; i--)
+ {
+ if (libname_short[i] == '.')
+ {
+ libname_short[i] = '\0';
+ break;
+ }
+ }
+ *extname = MemoryContextStrdup(TopMemoryContext, libname_short);
+ }
}
else
{
--
2.44.0.279.g3bd955d269
