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, 24 insertions, 38 deletions

diff --git a/src/bin/pg_dump/parallel.c b/src/bin/pg_dump/parallel.c
index 41aa78a9533..3dfdae3a579 100644
--- a/src/bin/pg_dump/parallel.c
+++ b/src/bin/pg_dump/parallel.c
@@ -197,8 +197,6 @@ bool		parallel_init_done = false;
 DWORD		mainThreadId;
 #endif							/* WIN32 */
 
-static const char *modulename = gettext_noop("parallel archiver");
-
 /* Local function prototypes */
 static ParallelSlot *GetMyPSlot(ParallelState *pstate);
 static void archive_close_connection(int code, void *arg);
@@ -262,7 +260,7 @@ init_parallel_dump_utils(void)
 		err = WSAStartup(MAKEWORD(2, 2), &wsaData);
 		if (err != 0)
 		{
-			fprintf(stderr, _("%s: WSAStartup failed: %d\n"), progname, err);
+			pg_log_error("WSAStartup failed: %d", err);
 			exit_nicely(1);
 		}
 		/* ... and arrange to shut it down at exit */
@@ -404,8 +402,8 @@ archive_close_connection(int code, void *arg)
  * Forcibly shut down any remaining workers, waiting for them to finish.
  *
  * Note that we don't expect to come here during normal exit (the workers
- * should be long gone, and the ParallelState too).  We're only here in an
- * exit_horribly() situation, so intervening to cancel active commands is
+ * should be long gone, and the ParallelState too).  We're only here in a
+ * fatal() situation, so intervening to cancel active commands is
  * appropriate.
  */
 static void
@@ -697,7 +695,7 @@ consoleHandler(DWORD dwCtrlType)
 
 		/*
 		 * Report we're quitting, using nothing more complicated than
-		 * write(2).  (We might be able to get away with using write_msg()
+		 * write(2).  (We might be able to get away with using pg_log_*()
 		 * here, but since we terminated other threads uncleanly above, it
 		 * seems better to assume as little as possible.)
 		 */
@@ -967,9 +965,7 @@ ParallelBackupStart(ArchiveHandle *AH)
 
 		/* Create communication pipes for this worker */
 		if (pgpipe(pipeMW) < 0 || pgpipe(pipeWM) < 0)
-			exit_horribly(modulename,
-						  "could not create communication channels: %s\n",
-						  strerror(errno));
+			fatal("could not create communication channels: %m");
 
 		pstate->te[i] = NULL;	/* just for safety */
 
@@ -1032,9 +1028,7 @@ ParallelBackupStart(ArchiveHandle *AH)
 		else if (pid < 0)
 		{
 			/* fork failed */
-			exit_horribly(modulename,
-						  "could not create worker process: %s\n",
-						  strerror(errno));
+			fatal("could not create worker process: %m");
 		}
 
 		/* In Master after successful fork */
@@ -1163,8 +1157,7 @@ parseWorkerCommand(ArchiveHandle *AH, TocEntry **te, T_Action *act,
 		Assert(*te != NULL);
 	}
 	else
-		exit_horribly(modulename,
-					  "unrecognized command received from master: \"%s\"\n",
+		fatal("unrecognized command received from master: \"%s\"",
 					  msg);
 }
 
@@ -1207,8 +1200,7 @@ parseWorkerResponse(ArchiveHandle *AH, TocEntry *te,
 		AH->public.n_errors += n_errors;
 	}
 	else
-		exit_horribly(modulename,
-					  "invalid message received from worker: \"%s\"\n",
+		fatal("invalid message received from worker: \"%s\"",
 					  msg);
 
 	return status;
@@ -1340,11 +1332,10 @@ lockTableForWorker(ArchiveHandle *AH, TocEntry *te)
 	res = PQexec(AH->connection, query->data);
 
 	if (!res || PQresultStatus(res) != PGRES_COMMAND_OK)
-		exit_horribly(modulename,
-					  "could not obtain lock on relation \"%s\"\n"
-					  "This usually means that someone requested an ACCESS EXCLUSIVE lock "
-					  "on the table after the pg_dump parent process had gotten the "
-					  "initial ACCESS SHARE lock on the table.\n", qualId);
+		fatal("could not obtain lock on relation \"%s\"\n"
+			  "This usually means that someone requested an ACCESS EXCLUSIVE lock "
+			  "on the table after the pg_dump parent process had gotten the "
+			  "initial ACCESS SHARE lock on the table.", qualId);
 
 	PQclear(res);
 	destroyPQExpBuffer(query);
@@ -1430,7 +1421,7 @@ ListenToWorkers(ArchiveHandle *AH, ParallelState *pstate, bool do_wait)
 	{
 		/* If do_wait is true, we must have detected EOF on some socket */
 		if (do_wait)
-			exit_horribly(modulename, "a worker process died unexpectedly\n");
+			fatal("a worker process died unexpectedly");
 		return false;
 	}
 
@@ -1447,8 +1438,7 @@ ListenToWorkers(ArchiveHandle *AH, ParallelState *pstate, bool do_wait)
 		pstate->te[worker] = NULL;
 	}
 	else
-		exit_horribly(modulename,
-					  "invalid message received from worker: \"%s\"\n",
+		fatal("invalid message received from worker: \"%s\"",
 					  msg);
 
 	/* Free the string returned from getMessageFromWorker */
@@ -1553,9 +1543,7 @@ sendMessageToMaster(int pipefd[2], const char *str)
 	int			len = strlen(str) + 1;
 
 	if (pipewrite(pipefd[PIPE_WRITE], str, len) != len)
-		exit_horribly(modulename,
-					  "could not write to the communication channel: %s\n",
-					  strerror(errno));
+		fatal("could not write to the communication channel: %m");
 }
 
 /*
@@ -1632,7 +1620,7 @@ getMessageFromWorker(ParallelState *pstate, bool do_wait, int *worker)
 	}
 
 	if (i < 0)
-		exit_horribly(modulename, "select() failed: %s\n", strerror(errno));
+		fatal("select() failed: %m");
 
 	for (i = 0; i < pstate->numWorkers; i++)
 	{
@@ -1671,9 +1659,7 @@ sendMessageToWorker(ParallelState *pstate, int worker, const char *str)
 
 	if (pipewrite(pstate->parallelSlot[worker].pipeWrite, str, len) != len)
 	{
-		exit_horribly(modulename,
-					  "could not write to the communication channel: %s\n",
-					  strerror(errno));
+		fatal("could not write to the communication channel: %m");
 	}
 }
 
@@ -1757,7 +1743,7 @@ pgpipe(int handles[2])
 	 */
 	if ((s = socket(AF_INET, SOCK_STREAM, 0)) == PGINVALID_SOCKET)
 	{
-		write_msg(modulename, "pgpipe: could not create socket: error code %d\n",
+		pg_log_error("pgpipe: could not create socket: error code %d",
 				  WSAGetLastError());
 		return -1;
 	}
@@ -1768,21 +1754,21 @@ pgpipe(int handles[2])
 	serv_addr.sin_addr.s_addr = pg_hton32(INADDR_LOOPBACK);
 	if (bind(s, (SOCKADDR *) &serv_addr, len) == SOCKET_ERROR)
 	{
-		write_msg(modulename, "pgpipe: could not bind: error code %d\n",
+		pg_log_error("pgpipe: could not bind: error code %d",
 				  WSAGetLastError());
 		closesocket(s);
 		return -1;
 	}
 	if (listen(s, 1) == SOCKET_ERROR)
 	{
-		write_msg(modulename, "pgpipe: could not listen: error code %d\n",
+		pg_log_error("pgpipe: could not listen: error code %d",
 				  WSAGetLastError());
 		closesocket(s);
 		return -1;
 	}
 	if (getsockname(s, (SOCKADDR *) &serv_addr, &len) == SOCKET_ERROR)
 	{
-		write_msg(modulename, "pgpipe: getsockname() failed: error code %d\n",
+		pg_log_error("pgpipe: getsockname() failed: error code %d",
 				  WSAGetLastError());
 		closesocket(s);
 		return -1;
@@ -1793,7 +1779,7 @@ pgpipe(int handles[2])
 	 */
 	if ((tmp_sock = socket(AF_INET, SOCK_STREAM, 0)) == PGINVALID_SOCKET)
 	{
-		write_msg(modulename, "pgpipe: could not create second socket: error code %d\n",
+		pg_log_error("pgpipe: could not create second socket: error code %d",
 				  WSAGetLastError());
 		closesocket(s);
 		return -1;
@@ -1802,7 +1788,7 @@ pgpipe(int handles[2])
 
 	if (connect(handles[1], (SOCKADDR *) &serv_addr, len) == SOCKET_ERROR)
 	{
-		write_msg(modulename, "pgpipe: could not connect socket: error code %d\n",
+		pg_log_error("pgpipe: could not connect socket: error code %d",
 				  WSAGetLastError());
 		closesocket(handles[1]);
 		handles[1] = -1;
@@ -1811,7 +1797,7 @@ pgpipe(int handles[2])
 	}
 	if ((tmp_sock = accept(s, (SOCKADDR *) &serv_addr, &len)) == PGINVALID_SOCKET)
 	{
-		write_msg(modulename, "pgpipe: could not accept connection: error code %d\n",
+		pg_log_error("pgpipe: could not accept connection: error code %d",
 				  WSAGetLastError());
 		closesocket(handles[1]);
 		handles[1] = -1;