From c8e8b5a6e20bf471d83059aebe64bca16f184057 Mon Sep 17 00:00:00 2001 From: Robert Haas Date: Fri, 21 Oct 2011 13:26:40 -0400 Subject: [PATCH] Try to log current the query string when a backend crashes. To avoid minimize risk inside the postmaster, we subject this feature to a number of significant limitations. We very much wish to avoid doing any complex processing inside the postmaster, due to the posssibility that the crashed backend has completely corrupted shared memory. To that end, no encoding conversion is done; instead, we just replace anything that doesn't look like an ASCII character with a question mark. We limit the amount of data copied to 1024 characters, and carefully sanity check the source of that data. While these restrictions would doubtless be unacceptable in a general-purpose logging facility, even this limited facility seems like an improvement over the status quo ante. Marti Raudsepp, reviewed by PDXPUG and myself --- src/backend/postmaster/pgstat.c | 73 ++++++++++++++++++++++++++++- src/backend/postmaster/postmaster.c | 22 +++++++-- src/backend/utils/adt/ascii.c | 34 ++++++++++++++ src/include/pgstat.h | 2 + src/include/utils/ascii.h | 1 + 5 files changed, 125 insertions(+), 7 deletions(-) diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index 44956c15b5..ba64f2395c 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -58,6 +58,7 @@ #include "storage/pg_shmem.h" #include "storage/pmsignal.h" #include "storage/procsignal.h" +#include "utils/ascii.h" #include "utils/guc.h" #include "utils/memutils.h" #include "utils/ps_status.h" @@ -2228,6 +2229,7 @@ static PgBackendStatus *MyBEEntry = NULL; static char *BackendClientHostnameBuffer = NULL; static char *BackendAppnameBuffer = NULL; static char *BackendActivityBuffer = NULL; +static Size BackendActivityBufferSize = 0; /* @@ -2310,9 +2312,12 @@ CreateSharedBackendStatus(void) } /* Create or attach to the shared activity buffer */ - size = mul_size(pgstat_track_activity_query_size, MaxBackends); + BackendActivityBufferSize = mul_size(pgstat_track_activity_query_size, + MaxBackends); BackendActivityBuffer = (char *) - ShmemInitStruct("Backend Activity Buffer", size, &found); + ShmemInitStruct("Backend Activity Buffer", + BackendActivityBufferSize, + &found); if (!found) { @@ -2751,6 +2756,70 @@ pgstat_get_backend_current_activity(int pid, bool checkUser) return ""; } +/* ---------- + * pgstat_get_crashed_backend_activity() - + * + * Return a string representing the current activity of the backend with + * the specified PID. Like the function above, but reads shared memory with + * the expectation that it may be corrupt. Returns either a pointer to a + * constant string, or writes into the 'buffer' argument and returns it. + * + * This function is only intended to be used by postmaster to report the + * query that crashed the backend. In particular, no attempt is made to + * follow the correct concurrency protocol when accessing the + * BackendStatusArray. But that's OK, in the worst case we'll return a + * corrupted message. We also must take care not to trip on ereport(ERROR). + * + * Note: return strings for special cases match pg_stat_get_backend_activity. + * ---------- + */ +const char * +pgstat_get_crashed_backend_activity(int pid, char *buffer, + int len) +{ + volatile PgBackendStatus *beentry; + int i; + + beentry = BackendStatusArray; + for (i = 1; i <= MaxBackends; i++) + { + if (beentry->st_procpid == pid) + { + /* Read pointer just once, so it can't change after validation */ + const char *activity = beentry->st_activity; + const char *activity_last; + + /* + * We can't access activity pointer before we verify that it + * falls into BackendActivityBuffer. To make sure that the entire + * string including its ending is contained within the buffer, + * we subtract one activity length from it. + */ + activity_last = BackendActivityBuffer + BackendActivityBufferSize + - pgstat_track_activity_query_size; + + if (activity < BackendActivityBuffer || + activity > activity_last) + return ""; + + if (*(activity) == '\0') + return ""; + + /* + * Copy only ASCII-safe characters so we don't run into encoding + * problems when reporting the message. + */ + ascii_safe_strncpy(buffer, activity, len); + + return buffer; + } + + beentry++; + } + + /* PID not found */ + return ""; +} /* ------------------------------------------------------------ * Local support functions follow diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index dd7493cf9d..5476975f76 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -2777,6 +2777,13 @@ HandleChildCrash(int pid, int exitstatus, const char *procname) static void LogChildExit(int lev, const char *procname, int pid, int exitstatus) { + char activity_buffer[1024]; /* default track_activity_query_size */ + const char *activity; + + activity = pgstat_get_crashed_backend_activity(pid, + activity_buffer, + sizeof(activity_buffer)); + if (WIFEXITED(exitstatus)) ereport(lev, @@ -2784,7 +2791,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus) translator: %s is a noun phrase describing a child process, such as "server process" */ (errmsg("%s (PID %d) exited with exit code %d", - procname, pid, WEXITSTATUS(exitstatus)))); + procname, pid, WEXITSTATUS(exitstatus)), + errdetail("Running query: %s", activity))); else if (WIFSIGNALED(exitstatus)) #if defined(WIN32) ereport(lev, @@ -2794,7 +2802,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus) "server process" */ (errmsg("%s (PID %d) was terminated by exception 0x%X", procname, pid, WTERMSIG(exitstatus)), - errhint("See C include file \"ntstatus.h\" for a description of the hexadecimal value."))); + errhint("See C include file \"ntstatus.h\" for a description of the hexadecimal value."), + errdetail("Running query: %s", activity))); #elif defined(HAVE_DECL_SYS_SIGLIST) && HAVE_DECL_SYS_SIGLIST ereport(lev, @@ -2804,7 +2813,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus) (errmsg("%s (PID %d) was terminated by signal %d: %s", procname, pid, WTERMSIG(exitstatus), WTERMSIG(exitstatus) < NSIG ? - sys_siglist[WTERMSIG(exitstatus)] : "(unknown)"))); + sys_siglist[WTERMSIG(exitstatus)] : "(unknown)"), + errdetail("Running query: %s", activity))); #else ereport(lev, @@ -2812,7 +2822,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus) translator: %s is a noun phrase describing a child process, such as "server process" */ (errmsg("%s (PID %d) was terminated by signal %d", - procname, pid, WTERMSIG(exitstatus)))); + procname, pid, WTERMSIG(exitstatus)), + errdetail("Running query: %s", activity))); #endif else ereport(lev, @@ -2821,7 +2832,8 @@ LogChildExit(int lev, const char *procname, int pid, int exitstatus) translator: %s is a noun phrase describing a child process, such as "server process" */ (errmsg("%s (PID %d) exited with unrecognized status %d", - procname, pid, exitstatus))); + procname, pid, exitstatus), + errdetail("Running query: %s", activity))); } /* diff --git a/src/backend/utils/adt/ascii.c b/src/backend/utils/adt/ascii.c index 7ecf4949b5..7c9e96a04f 100644 --- a/src/backend/utils/adt/ascii.c +++ b/src/backend/utils/adt/ascii.c @@ -158,3 +158,37 @@ to_ascii_default(PG_FUNCTION_ARGS) PG_RETURN_TEXT_P(encode_to_ascii(data, enc)); } + +/* ---------- + * "Escape" a string in unknown encoding to a valid ASCII string. + * Replace non-ASCII bytes with '?' + * This must not trigger ereport(ERROR), as it is called from postmaster. + * + * Unlike C strncpy(), the result is always terminated with exactly one null + * byte. + * ---------- + */ +void +ascii_safe_strncpy(char *dest, const char *src, int len) +{ + int i; + + for (i = 0; i < (len - 1); i++) + { + unsigned char ch = src[i]; /* use unsigned char here to avoid compiler warning */ + + if (ch == '\0') + break; + /* Keep printable ASCII characters */ + if (32 <= ch && ch <= 127) + dest[i] = ch; + /* White-space is also OK */ + else if (ch == '\n' || ch == '\r' || ch == '\t') + dest[i] = ch; + /* Everything else is replaced with '?' */ + else + dest[i] = '?'; + } + + dest[i] = '\0'; +} diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 20c4d4354e..d0f1927efb 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -720,6 +720,8 @@ extern void pgstat_report_appname(const char *appname); extern void pgstat_report_xact_timestamp(TimestampTz tstamp); extern void pgstat_report_waiting(bool waiting); extern const char *pgstat_get_backend_current_activity(int pid, bool checkUser); +extern const char *pgstat_get_crashed_backend_activity(int pid, char *buffer, + int len); extern PgStat_TableStatus *find_tabstat_entry(Oid rel_id); extern PgStat_BackendFunctionEntry *find_funcstat_entry(Oid func_id); diff --git a/src/include/utils/ascii.h b/src/include/utils/ascii.h index ad70e037bd..adeddb5626 100644 --- a/src/include/utils/ascii.h +++ b/src/include/utils/ascii.h @@ -16,5 +16,6 @@ extern Datum to_ascii_encname(PG_FUNCTION_ARGS); extern Datum to_ascii_enc(PG_FUNCTION_ARGS); extern Datum to_ascii_default(PG_FUNCTION_ARGS); +extern void ascii_safe_strncpy(char *dest, const char *src, int len); #endif /* _ASCII_H_ */