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

1 files changed, 38 insertions, 56 deletions

diff --git a/src/bin/pg_dump/pg_backup_custom.c b/src/bin/pg_dump/pg_backup_custom.c
index 96f44e88b11..5641d5d20fc 100644
--- a/src/bin/pg_dump/pg_backup_custom.c
+++ b/src/bin/pg_dump/pg_backup_custom.c
@@ -29,6 +29,7 @@
 #include "parallel.h"
 #include "pg_backup_utils.h"
 #include "common/file_utils.h"
+#include "fe_utils/logging.h"
 
 /*--------
  * Routines in the format interface
@@ -91,10 +92,6 @@ static pgoff_t _getFilePos(ArchiveHandle *AH, lclContext *ctx);
 static void _CustomWriteFunc(ArchiveHandle *AH, const char *buf, size_t len);
 static size_t _CustomReadFunc(ArchiveHandle *AH, char **buf, size_t *buflen);
 
-/* translator: this is a module name */
-static const char *modulename = gettext_noop("custom archiver");
-
-
 
 /*
  *	Init routine required by ALL formats. This is a global routine
@@ -159,15 +156,13 @@ InitArchiveFmt_Custom(ArchiveHandle *AH)
 		{
 			AH->FH = fopen(AH->fSpec, PG_BINARY_W);
 			if (!AH->FH)
-				exit_horribly(modulename, "could not open output file \"%s\": %s\n",
-							  AH->fSpec, strerror(errno));
+				fatal("could not open output file \"%s\": %m", AH->fSpec);
 		}
 		else
 		{
 			AH->FH = stdout;
 			if (!AH->FH)
-				exit_horribly(modulename, "could not open output file: %s\n",
-							  strerror(errno));
+				fatal("could not open output file: %m");
 		}
 
 		ctx->hasSeek = checkSeek(AH->FH);
@@ -178,15 +173,13 @@ InitArchiveFmt_Custom(ArchiveHandle *AH)
 		{
 			AH->FH = fopen(AH->fSpec, PG_BINARY_R);
 			if (!AH->FH)
-				exit_horribly(modulename, "could not open input file \"%s\": %s\n",
-							  AH->fSpec, strerror(errno));
+				fatal("could not open input file \"%s\": %m", AH->fSpec);
 		}
 		else
 		{
 			AH->FH = stdin;
 			if (!AH->FH)
-				exit_horribly(modulename, "could not open input file: %s\n",
-							  strerror(errno));
+				fatal("could not open input file: %m");
 		}
 
 		ctx->hasSeek = checkSeek(AH->FH);
@@ -381,7 +374,7 @@ _StartBlob(ArchiveHandle *AH, TocEntry *te, Oid oid)
 	lclContext *ctx = (lclContext *) AH->formatData;
 
 	if (oid == 0)
-		exit_horribly(modulename, "invalid OID for large object\n");
+		fatal("invalid OID for large object");
 
 	WriteInt(AH, oid);
 
@@ -451,8 +444,7 @@ _PrintTocData(ArchiveHandle *AH, TocEntry *te)
 					break;
 
 				default:		/* Always have a default */
-					exit_horribly(modulename,
-								  "unrecognized data block type (%d) while searching archive\n",
+					fatal("unrecognized data block type (%d) while searching archive",
 								  blkType);
 					break;
 			}
@@ -463,8 +455,7 @@ _PrintTocData(ArchiveHandle *AH, TocEntry *te)
 	{
 		/* We can just seek to the place we need to be. */
 		if (fseeko(AH->FH, tctx->dataPos, SEEK_SET) != 0)
-			exit_horribly(modulename, "error during file seek: %s\n",
-						  strerror(errno));
+			fatal("error during file seek: %m");
 
 		_readBlockHeader(AH, &blkType, &id);
 	}
@@ -473,24 +464,24 @@ _PrintTocData(ArchiveHandle *AH, TocEntry *te)
 	if (blkType == EOF)
 	{
 		if (tctx->dataState == K_OFFSET_POS_NOT_SET)
-			exit_horribly(modulename, "could not find block ID %d in archive -- "
-						  "possibly due to out-of-order restore request, "
-						  "which cannot be handled due to lack of data offsets in archive\n",
-						  te->dumpId);
+			fatal("could not find block ID %d in archive -- "
+				  "possibly due to out-of-order restore request, "
+				  "which cannot be handled due to lack of data offsets in archive",
+				  te->dumpId);
 		else if (!ctx->hasSeek)
-			exit_horribly(modulename, "could not find block ID %d in archive -- "
-						  "possibly due to out-of-order restore request, "
-						  "which cannot be handled due to non-seekable input file\n",
-						  te->dumpId);
+			fatal("could not find block ID %d in archive -- "
+				  "possibly due to out-of-order restore request, "
+				  "which cannot be handled due to non-seekable input file",
+				  te->dumpId);
 		else					/* huh, the dataPos led us to EOF? */
-			exit_horribly(modulename, "could not find block ID %d in archive -- "
-						  "possibly corrupt archive\n",
-						  te->dumpId);
+			fatal("could not find block ID %d in archive -- "
+				  "possibly corrupt archive",
+				  te->dumpId);
 	}
 
 	/* Are we sane? */
 	if (id != te->dumpId)
-		exit_horribly(modulename, "found unexpected block ID (%d) when reading data -- expected %d\n",
+		fatal("found unexpected block ID (%d) when reading data -- expected %d",
 					  id, te->dumpId);
 
 	switch (blkType)
@@ -504,7 +495,7 @@ _PrintTocData(ArchiveHandle *AH, TocEntry *te)
 			break;
 
 		default:				/* Always have a default */
-			exit_horribly(modulename, "unrecognized data block type %d while restoring archive\n",
+			fatal("unrecognized data block type %d while restoring archive",
 						  blkType);
 			break;
 	}
@@ -584,11 +575,9 @@ _skipData(ArchiveHandle *AH)
 		if ((cnt = fread(buf, 1, blkLen, AH->FH)) != blkLen)
 		{
 			if (feof(AH->FH))
-				exit_horribly(modulename,
-							  "could not read from input file: end of file\n");
+				fatal("could not read from input file: end of file");
 			else
-				exit_horribly(modulename,
-							  "could not read from input file: %s\n", strerror(errno));
+				fatal("could not read from input file: %m");
 		}
 
 		ctx->filePos += blkLen;
@@ -706,8 +695,7 @@ _CloseArchive(ArchiveHandle *AH)
 		/* Remember TOC's seek position for use below */
 		tpos = ftello(AH->FH);
 		if (tpos < 0 && ctx->hasSeek)
-			exit_horribly(modulename, "could not determine seek position in archive file: %s\n",
-						  strerror(errno));
+			fatal("could not determine seek position in archive file: %m");
 		WriteToc(AH);
 		ctx->dataStart = _getFilePos(AH, ctx);
 		WriteDataChunks(AH, NULL);
@@ -724,11 +712,11 @@ _CloseArchive(ArchiveHandle *AH)
 	}
 
 	if (fclose(AH->FH) != 0)
-		exit_horribly(modulename, "could not close archive file: %s\n", strerror(errno));
+		fatal("could not close archive file: %m");
 
 	/* Sync the output file if one is defined */
 	if (AH->dosync && AH->mode == archModeWrite && AH->fSpec)
-		(void) fsync_fname(AH->fSpec, false, progname);
+		(void) fsync_fname(AH->fSpec, false);
 
 	AH->FH = NULL;
 }
@@ -747,36 +735,32 @@ _ReopenArchive(ArchiveHandle *AH)
 	pgoff_t		tpos;
 
 	if (AH->mode == archModeWrite)
-		exit_horribly(modulename, "can only reopen input archives\n");
+		fatal("can only reopen input archives");
 
 	/*
 	 * These two cases are user-facing errors since they represent unsupported
 	 * (but not invalid) use-cases.  Word the error messages appropriately.
 	 */
 	if (AH->fSpec == NULL || strcmp(AH->fSpec, "") == 0)
-		exit_horribly(modulename, "parallel restore from standard input is not supported\n");
+		fatal("parallel restore from standard input is not supported");
 	if (!ctx->hasSeek)
-		exit_horribly(modulename, "parallel restore from non-seekable file is not supported\n");
+		fatal("parallel restore from non-seekable file is not supported");
 
 	tpos = ftello(AH->FH);
 	if (tpos < 0)
-		exit_horribly(modulename, "could not determine seek position in archive file: %s\n",
-					  strerror(errno));
+		fatal("could not determine seek position in archive file: %m");
 
 #ifndef WIN32
 	if (fclose(AH->FH) != 0)
-		exit_horribly(modulename, "could not close archive file: %s\n",
-					  strerror(errno));
+		fatal("could not close archive file: %m");
 #endif
 
 	AH->FH = fopen(AH->fSpec, PG_BINARY_R);
 	if (!AH->FH)
-		exit_horribly(modulename, "could not open input file \"%s\": %s\n",
-					  AH->fSpec, strerror(errno));
+		fatal("could not open input file \"%s\": %m", AH->fSpec);
 
 	if (fseeko(AH->FH, tpos, SEEK_SET) != 0)
-		exit_horribly(modulename, "could not set seek position in archive file: %s\n",
-					  strerror(errno));
+		fatal("could not set seek position in archive file: %m");
 }
 
 /*
@@ -831,8 +815,7 @@ _PrepParallelRestore(ArchiveHandle *AH)
 		pgoff_t		endpos;
 
 		if (fseeko(AH->FH, 0, SEEK_END) != 0)
-			exit_horribly(modulename, "error during file seek: %s\n",
-						  strerror(errno));
+			fatal("error during file seek: %m");
 		endpos = ftello(AH->FH);
 		if (endpos > prev_tctx->dataPos)
 			prev_te->dataLength = endpos - prev_tctx->dataPos;
@@ -853,7 +836,7 @@ _Clone(ArchiveHandle *AH)
 
 	/* sanity check, shouldn't happen */
 	if (ctx->cs != NULL)
-		exit_horribly(modulename, "compressor active\n");
+		fatal("compressor active");
 
 	/*
 	 * Note: we do not make a local lo_buf because we expect at most one BLOBS
@@ -905,11 +888,10 @@ _getFilePos(ArchiveHandle *AH, lclContext *ctx)
 		 */
 		pos = ftello(AH->FH);
 		if (pos < 0)
-			exit_horribly(modulename, "could not determine seek position in archive file: %s\n",
-						  strerror(errno));
+			fatal("could not determine seek position in archive file: %m");
 
 		if (pos != ctx->filePos)
-			write_msg(modulename, "WARNING: ftell mismatch with expected position -- ftell used\n");
+			pg_log_warning("ftell mismatch with expected position -- ftell used");
 	}
 	else
 		pos = ctx->filePos;
@@ -928,7 +910,7 @@ _readBlockHeader(ArchiveHandle *AH, int *type, int *id)
 	int			byt;
 
 	/*
-	 * Note: if we are at EOF with a pre-1.3 input file, we'll exit_horribly
+	 * Note: if we are at EOF with a pre-1.3 input file, we'll fatal()
 	 * inside ReadInt rather than returning EOF.  It doesn't seem worth
 	 * jumping through hoops to deal with that case better, because no such
 	 * files are likely to exist in the wild: only some 7.1 development