1
0
mirror of https://github.com/postgres/postgres.git synced 2025-07-02 09:02:37 +03:00

Unified logging system for command-line programs

This unifies the various ad hoc logging (message printing, error
printing) systems used throughout the command-line programs.

Features:

- Program name is automatically prefixed.

- Message string does not end with newline.  This removes a common
  source of inconsistencies and omissions.

- Additionally, a final newline is automatically stripped, simplifying
  use of PQerrorMessage() etc., another common source of mistakes.

- I converted error message strings to use %m where possible.

- As a result of the above several points, more translatable message
  strings can be shared between different components and between
  frontends and backend, without gratuitous punctuation or whitespace
  differences.

- There is support for setting a "log level".  This is not meant to be
  user-facing, but can be used internally to implement debug or
  verbose modes.

- Lazy argument evaluation, so no significant overhead if logging at
  some level is disabled.

- Some color in the messages, similar to gcc and clang.  Set
  PG_COLOR=auto to try it out.  Some colors are predefined, but can be
  customized by setting PG_COLORS.

- Common files (common/, fe_utils/, etc.) can handle logging much more
  simply by just using one API without worrying too much about the
  context of the calling program, requiring callbacks, or having to
  pass "progname" around everywhere.

- Some programs called setvbuf() to make sure that stderr is
  unbuffered, even on Windows.  But not all programs did that.  This
  is now done centrally.

Soft goals:

- Reduces vertical space use and visual complexity of error reporting
  in the source code.

- Encourages more deliberate classification of messages.  For example,
  in some cases it wasn't clear without analyzing the surrounding code
  whether a message was meant as an error or just an info.

- Concepts and terms are vaguely aligned with popular logging
  frameworks such as log4j and Python logging.

This is all just about printing stuff out.  Nothing affects program
flow (e.g., fatal exits).  The uses are just too varied to do that.
Some existing code had wrappers that do some kind of print-and-exit,
and I adapted those.

I tried to keep the output mostly the same, but there is a lot of
historical baggage to unwind and special cases to consider, and I
might not always have succeeded.  One significant change is that
pg_rewind used to write all error messages to stdout.  That is now
changed to stderr.

Reviewed-by: Donald Dong <xdong@csumb.edu>
Reviewed-by: Arthur Zakirov <a.zakirov@postgrespro.ru>
Discussion: https://www.postgresql.org/message-id/flat/6a609b43-4f57-7348-6480-bd022f924310@2ndquadrant.com
This commit is contained in:
Peter Eisentraut
2019-04-01 14:24:37 +02:00
parent b4cc19ab01
commit cc8d415117
132 changed files with 2555 additions and 2686 deletions

View File

@ -28,6 +28,9 @@
#include "catalog/pg_control.h"
#include "common/controldata_utils.h"
#include "common/file_perm.h"
#ifdef FRONTEND
#include "fe_utils/logging.h"
#endif
#include "port/pg_crc32c.h"
#ifndef FRONTEND
@ -45,7 +48,7 @@
* file data is correct.
*/
ControlFileData *
get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
get_controlfile(const char *DataDir, bool *crc_ok_p)
{
ControlFileData *ControlFile;
int fd;
@ -67,8 +70,8 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
#else
if ((fd = open(ControlFilePath, O_RDONLY | PG_BINARY, 0)) == -1)
{
fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not open file \"%s\" for reading: %m",
ControlFilePath);
exit(EXIT_FAILURE);
}
#endif
@ -83,8 +86,7 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
errmsg("could not read file \"%s\": %m", ControlFilePath)));
#else
{
fprintf(stderr, _("%s: could not read file \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not read file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
}
#endif
@ -96,8 +98,8 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
ControlFilePath, r, sizeof(ControlFileData))));
#else
{
fprintf(stderr, _("%s: could not read file \"%s\": read %d of %zu\n"),
progname, ControlFilePath, r, sizeof(ControlFileData));
pg_log_fatal("could not read file \"%s\": read %d of %zu",
ControlFilePath, r, sizeof(ControlFileData));
exit(EXIT_FAILURE);
}
#endif
@ -112,8 +114,7 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
#else
if (close(fd))
{
fprintf(stderr, _("%s: could not close file \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not close file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
}
#endif
@ -133,10 +134,10 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
#ifndef FRONTEND
elog(ERROR, _("byte ordering mismatch"));
#else
printf(_("WARNING: possible byte ordering mismatch\n"
"The byte ordering used to store the pg_control file might not match the one\n"
"used by this program. In that case the results below would be incorrect, and\n"
"the PostgreSQL installation would be incompatible with this data directory.\n"));
pg_log_warning("possible byte ordering mismatch\n"
"The byte ordering used to store the pg_control file might not match the one\n"
"used by this program. In that case the results below would be incorrect, and\n"
"the PostgreSQL installation would be incompatible with this data directory.");
#endif
return ControlFile;
@ -152,7 +153,7 @@ get_controlfile(const char *DataDir, const char *progname, bool *crc_ok_p)
* routine in the backend.
*/
void
update_controlfile(const char *DataDir, const char *progname,
update_controlfile(const char *DataDir,
ControlFileData *ControlFile, bool do_sync)
{
int fd;
@ -199,8 +200,7 @@ update_controlfile(const char *DataDir, const char *progname,
if ((fd = open(ControlFilePath, O_WRONLY | PG_BINARY,
pg_file_create_mode)) == -1)
{
fprintf(stderr, _("%s: could not open file \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not open file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
}
#endif
@ -221,8 +221,7 @@ update_controlfile(const char *DataDir, const char *progname,
errmsg("could not write file \"%s\": %m",
ControlFilePath)));
#else
fprintf(stderr, _("%s: could not write \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not write file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
#endif
}
@ -243,8 +242,7 @@ update_controlfile(const char *DataDir, const char *progname,
#else
if (fsync(fd) != 0)
{
fprintf(stderr, _("%s: could not fsync file \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not fsync file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
}
#endif
@ -258,8 +256,7 @@ update_controlfile(const char *DataDir, const char *progname,
errmsg("could not close file \"%s\": %m",
ControlFilePath)));
#else
fprintf(stderr, _("%s: could not close file \"%s\": %s\n"),
progname, ControlFilePath, strerror(errno));
pg_log_fatal("could not close file \"%s\": %m", ControlFilePath);
exit(EXIT_FAILURE);
#endif
}

View File

@ -20,6 +20,7 @@
#include <unistd.h>
#include "common/file_utils.h"
#include "fe_utils/logging.h"
/* Define PG_FLUSH_DATA_WORKS if we have an implementation for pg_flush_data */
@ -35,12 +36,11 @@
#define MINIMUM_VERSION_FOR_PG_WAL 100000
#ifdef PG_FLUSH_DATA_WORKS
static int pre_sync_fname(const char *fname, bool isdir,
const char *progname);
static int pre_sync_fname(const char *fname, bool isdir);
#endif
static void walkdir(const char *path,
int (*action) (const char *fname, bool isdir, const char *progname),
bool process_symlinks, const char *progname);
int (*action) (const char *fname, bool isdir),
bool process_symlinks);
/*
* Issue fsync recursively on PGDATA and all its contents.
@ -56,7 +56,6 @@ static void walkdir(const char *path,
*/
void
fsync_pgdata(const char *pg_data,
const char *progname,
int serverVersion)
{
bool xlog_is_symlink;
@ -79,8 +78,7 @@ fsync_pgdata(const char *pg_data,
struct stat st;
if (lstat(pg_wal, &st) < 0)
fprintf(stderr, _("%s: could not stat file \"%s\": %s\n"),
progname, pg_wal, strerror(errno));
pg_log_error("could not stat file \"%s\": %m", pg_wal);
else if (S_ISLNK(st.st_mode))
xlog_is_symlink = true;
}
@ -94,10 +92,10 @@ fsync_pgdata(const char *pg_data,
* directory and its contents.
*/
#ifdef PG_FLUSH_DATA_WORKS
walkdir(pg_data, pre_sync_fname, false, progname);
walkdir(pg_data, pre_sync_fname, false);
if (xlog_is_symlink)
walkdir(pg_wal, pre_sync_fname, false, progname);
walkdir(pg_tblspc, pre_sync_fname, true, progname);
walkdir(pg_wal, pre_sync_fname, false);
walkdir(pg_tblspc, pre_sync_fname, true);
#endif
/*
@ -109,10 +107,10 @@ fsync_pgdata(const char *pg_data,
* in pg_tblspc, they'll get fsync'd twice. That's not an expected case
* so we don't worry about optimizing it.
*/
walkdir(pg_data, fsync_fname, false, progname);
walkdir(pg_data, fsync_fname, false);
if (xlog_is_symlink)
walkdir(pg_wal, fsync_fname, false, progname);
walkdir(pg_tblspc, fsync_fname, true, progname);
walkdir(pg_wal, fsync_fname, false);
walkdir(pg_tblspc, fsync_fname, true);
}
/*
@ -121,17 +119,17 @@ fsync_pgdata(const char *pg_data,
* This is a convenient wrapper on top of walkdir().
*/
void
fsync_dir_recurse(const char *dir, const char *progname)
fsync_dir_recurse(const char *dir)
{
/*
* If possible, hint to the kernel that we're soon going to fsync the data
* directory and its contents.
*/
#ifdef PG_FLUSH_DATA_WORKS
walkdir(dir, pre_sync_fname, false, progname);
walkdir(dir, pre_sync_fname, false);
#endif
walkdir(dir, fsync_fname, false, progname);
walkdir(dir, fsync_fname, false);
}
/*
@ -150,8 +148,8 @@ fsync_dir_recurse(const char *dir, const char *progname)
*/
static void
walkdir(const char *path,
int (*action) (const char *fname, bool isdir, const char *progname),
bool process_symlinks, const char *progname)
int (*action) (const char *fname, bool isdir),
bool process_symlinks)
{
DIR *dir;
struct dirent *de;
@ -159,8 +157,7 @@ walkdir(const char *path,
dir = opendir(path);
if (dir == NULL)
{
fprintf(stderr, _("%s: could not open directory \"%s\": %s\n"),
progname, path, strerror(errno));
pg_log_error("could not open directory \"%s\": %m", path);
return;
}
@ -183,20 +180,18 @@ walkdir(const char *path,
if (sret < 0)
{
fprintf(stderr, _("%s: could not stat file \"%s\": %s\n"),
progname, subpath, strerror(errno));
pg_log_error("could not stat file \"%s\": %m", subpath);
continue;
}
if (S_ISREG(fst.st_mode))
(*action) (subpath, false, progname);
(*action) (subpath, false);
else if (S_ISDIR(fst.st_mode))
walkdir(subpath, action, false, progname);
walkdir(subpath, action, false);
}
if (errno)
fprintf(stderr, _("%s: could not read directory \"%s\": %s\n"),
progname, path, strerror(errno));
pg_log_error("could not read directory \"%s\": %m", path);
(void) closedir(dir);
@ -206,7 +201,7 @@ walkdir(const char *path,
* synced. Recent versions of ext4 have made the window much wider but
* it's been an issue for ext3 and other filesystems in the past.
*/
(*action) (path, true, progname);
(*action) (path, true);
}
/*
@ -218,7 +213,7 @@ walkdir(const char *path,
#ifdef PG_FLUSH_DATA_WORKS
static int
pre_sync_fname(const char *fname, bool isdir, const char *progname)
pre_sync_fname(const char *fname, bool isdir)
{
int fd;
@ -228,8 +223,7 @@ pre_sync_fname(const char *fname, bool isdir, const char *progname)
{
if (errno == EACCES || (isdir && errno == EISDIR))
return 0;
fprintf(stderr, _("%s: could not open file \"%s\": %s\n"),
progname, fname, strerror(errno));
pg_log_error("could not open file \"%s\": %m", fname);
return -1;
}
@ -260,7 +254,7 @@ pre_sync_fname(const char *fname, bool isdir, const char *progname)
* other errors non-fatally.
*/
int
fsync_fname(const char *fname, bool isdir, const char *progname)
fsync_fname(const char *fname, bool isdir)
{
int fd;
int flags;
@ -288,8 +282,7 @@ fsync_fname(const char *fname, bool isdir, const char *progname)
{
if (errno == EACCES || (isdir && errno == EISDIR))
return 0;
fprintf(stderr, _("%s: could not open file \"%s\": %s\n"),
progname, fname, strerror(errno));
pg_log_error("could not open file \"%s\": %m", fname);
return -1;
}
@ -301,8 +294,7 @@ fsync_fname(const char *fname, bool isdir, const char *progname)
*/
if (returncode != 0 && !(isdir && (errno == EBADF || errno == EINVAL)))
{
fprintf(stderr, _("%s: could not fsync file \"%s\": %s\n"),
progname, fname, strerror(errno));
pg_log_error("could not fsync file \"%s\": %m", fname);
(void) close(fd);
return -1;
}
@ -318,7 +310,7 @@ fsync_fname(const char *fname, bool isdir, const char *progname)
* an OS crash or power failure.
*/
int
fsync_parent_path(const char *fname, const char *progname)
fsync_parent_path(const char *fname)
{
char parentpath[MAXPGPATH];
@ -333,7 +325,7 @@ fsync_parent_path(const char *fname, const char *progname)
if (strlen(parentpath) == 0)
strlcpy(parentpath, ".", MAXPGPATH);
if (fsync_fname(parentpath, true, progname) != 0)
if (fsync_fname(parentpath, true) != 0)
return -1;
return 0;
@ -345,7 +337,7 @@ fsync_parent_path(const char *fname, const char *progname)
* Wrapper around rename, similar to the backend version.
*/
int
durable_rename(const char *oldfile, const char *newfile, const char *progname)
durable_rename(const char *oldfile, const char *newfile)
{
int fd;
@ -356,7 +348,7 @@ durable_rename(const char *oldfile, const char *newfile, const char *progname)
* because it's then guaranteed that either source or target file exists
* after a crash.
*/
if (fsync_fname(oldfile, false, progname) != 0)
if (fsync_fname(oldfile, false) != 0)
return -1;
fd = open(newfile, PG_BINARY | O_RDWR, 0);
@ -364,8 +356,7 @@ durable_rename(const char *oldfile, const char *newfile, const char *progname)
{
if (errno != ENOENT)
{
fprintf(stderr, _("%s: could not open file \"%s\": %s\n"),
progname, newfile, strerror(errno));
pg_log_error("could not open file \"%s\": %m", newfile);
return -1;
}
}
@ -373,8 +364,7 @@ durable_rename(const char *oldfile, const char *newfile, const char *progname)
{
if (fsync(fd) != 0)
{
fprintf(stderr, _("%s: could not fsync file \"%s\": %s\n"),
progname, newfile, strerror(errno));
pg_log_error("could not fsync file \"%s\": %m", newfile);
close(fd);
return -1;
}
@ -384,8 +374,8 @@ durable_rename(const char *oldfile, const char *newfile, const char *progname)
/* Time to do the real deal... */
if (rename(oldfile, newfile) != 0)
{
fprintf(stderr, _("%s: could not rename file \"%s\" to \"%s\": %s\n"),
progname, oldfile, newfile, strerror(errno));
pg_log_error("could not rename file \"%s\" to \"%s\": %m",
oldfile, newfile);
return -1;
}
@ -393,10 +383,10 @@ durable_rename(const char *oldfile, const char *newfile, const char *progname)
* To guarantee renaming the file is persistent, fsync the file with its
* new name, and its containing directory.
*/
if (fsync_fname(newfile, false, progname) != 0)
if (fsync_fname(newfile, false) != 0)
return -1;
if (fsync_parent_path(newfile, progname) != 0)
if (fsync_parent_path(newfile) != 0)
return -1;
return 0;

View File

@ -20,6 +20,12 @@
#include <dirent.h>
#ifndef FRONTEND
#define pg_log_warning(...) elog(WARNING, __VA_ARGS__)
#else
#include "fe_utils/logging.h"
#endif
/*
* pgfnames
*
@ -39,12 +45,7 @@ pgfnames(const char *path)
dir = opendir(path);
if (dir == NULL)
{
#ifndef FRONTEND
elog(WARNING, "could not open directory \"%s\": %m", path);
#else
fprintf(stderr, _("could not open directory \"%s\": %s\n"),
path, strerror(errno));
#endif
pg_log_warning("could not open directory \"%s\": %m", path);
return NULL;
}
@ -65,26 +66,12 @@ pgfnames(const char *path)
}
if (errno)
{
#ifndef FRONTEND
elog(WARNING, "could not read directory \"%s\": %m", path);
#else
fprintf(stderr, _("could not read directory \"%s\": %s\n"),
path, strerror(errno));
#endif
}
pg_log_warning("could not read directory \"%s\": %m", path);
filenames[numnames] = NULL;
if (closedir(dir))
{
#ifndef FRONTEND
elog(WARNING, "could not close directory \"%s\": %m", path);
#else
fprintf(stderr, _("could not close directory \"%s\": %s\n"),
path, strerror(errno));
#endif
}
pg_log_warning("could not close directory \"%s\": %m", path);
return filenames;
}

View File

@ -21,6 +21,7 @@
#include "postgres_fe.h"
#include "common/restricted_token.h"
#include "fe_utils/logging.h"
#ifdef WIN32
@ -43,7 +44,7 @@ typedef BOOL (WINAPI * __CreateRestrictedToken) (HANDLE, DWORD, DWORD, PSID_AND_
* NOT execute anything.
*/
HANDLE
CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char *progname)
CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo)
{
BOOL b;
STARTUPINFO si;
@ -65,7 +66,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
if (_CreateRestrictedToken == NULL)
{
fprintf(stderr, _("%s: WARNING: cannot create restricted tokens on this platform\n"), progname);
pg_log_warning("cannot create restricted tokens on this platform");
if (Advapi32Handle != NULL)
FreeLibrary(Advapi32Handle);
return 0;
@ -74,7 +75,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
/* Open the current token to use as a base for the restricted one */
if (!OpenProcessToken(GetCurrentProcess(), TOKEN_ALL_ACCESS, &origToken))
{
fprintf(stderr, _("%s: could not open process token: error code %lu\n"), progname, GetLastError());
pg_log_error("could not open process token: error code %lu", GetLastError());
return 0;
}
@ -87,8 +88,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
SECURITY_BUILTIN_DOMAIN_RID, DOMAIN_ALIAS_RID_POWER_USERS, 0, 0, 0, 0, 0,
0, &dropSids[1].Sid))
{
fprintf(stderr, _("%s: could not allocate SIDs: error code %lu\n"),
progname, GetLastError());
pg_log_error("could not allocate SIDs: error code %lu", GetLastError());
return 0;
}
@ -107,8 +107,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
if (!b)
{
fprintf(stderr, _("%s: could not create restricted token: error code %lu\n"),
progname, GetLastError());
pg_log_error("could not create restricted token: error code %lu", GetLastError());
return 0;
}
@ -129,7 +128,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
processInfo))
{
fprintf(stderr, _("%s: could not start process for command \"%s\": error code %lu\n"), progname, cmd, GetLastError());
pg_log_error("could not start process for command \"%s\": error code %lu", cmd, GetLastError());
return 0;
}
@ -143,7 +142,7 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, const char
* On other platforms do nothing.
*/
void
get_restricted_token(const char *progname)
get_restricted_token(void)
{
#ifdef WIN32
HANDLE restrictedToken;
@ -165,9 +164,9 @@ get_restricted_token(const char *progname)
putenv("PG_RESTRICT_EXEC=1");
if ((restrictedToken = CreateRestrictedProcess(cmdline, &pi, progname)) == 0)
if ((restrictedToken = CreateRestrictedProcess(cmdline, &pi)) == 0)
{
fprintf(stderr, _("%s: could not re-execute with restricted token: error code %lu\n"), progname, GetLastError());
pg_log_error("could not re-execute with restricted token: error code %lu", GetLastError());
}
else
{
@ -183,7 +182,7 @@ get_restricted_token(const char *progname)
if (!GetExitCodeProcess(pi.hProcess, &x))
{
fprintf(stderr, _("%s: could not get exit code from subprocess: error code %lu\n"), progname, GetLastError());
pg_log_error("could not get exit code from subprocess: error code %lu", GetLastError());
exit(1);
}
exit(x);

View File

@ -20,6 +20,12 @@
#include <unistd.h>
#include <sys/stat.h>
#ifndef FRONTEND
#define pg_log_warning(...) elog(WARNING, __VA_ARGS__)
#else
#include "fe_utils/logging.h"
#endif
/*
* rmtree
@ -70,13 +76,8 @@ rmtree(const char *path, bool rmtopdir)
{
if (errno != ENOENT)
{
#ifndef FRONTEND
elog(WARNING, "could not stat file or directory \"%s\": %m",
pg_log_warning("could not stat file or directory \"%s\": %m",
pathbuf);
#else
fprintf(stderr, _("could not stat file or directory \"%s\": %s\n"),
pathbuf, strerror(errno));
#endif
result = false;
}
continue;
@ -97,13 +98,8 @@ rmtree(const char *path, bool rmtopdir)
{
if (errno != ENOENT)
{
#ifndef FRONTEND
elog(WARNING, "could not remove file or directory \"%s\": %m",
pg_log_warning("could not remove file or directory \"%s\": %m",
pathbuf);
#else
fprintf(stderr, _("could not remove file or directory \"%s\": %s\n"),
pathbuf, strerror(errno));
#endif
result = false;
}
}
@ -114,13 +110,8 @@ rmtree(const char *path, bool rmtopdir)
{
if (rmdir(path) != 0)
{
#ifndef FRONTEND
elog(WARNING, "could not remove file or directory \"%s\": %m",
pg_log_warning("could not remove file or directory \"%s\": %m",
path);
#else
fprintf(stderr, _("could not remove file or directory \"%s\": %s\n"),
path, strerror(errno));
#endif
result = false;
}
}