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, 30 insertions, 51 deletions

diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 82511e34ac3..bd284446f8d 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -19,6 +19,7 @@
 #include <win32.h>
 #endif
 
+#include "fe_utils/logging.h"
 #include "fe_utils/string_utils.h"
 #include "portability/instr_time.h"
 
@@ -67,7 +68,7 @@ openQueryOutputFile(const char *fname, FILE **fout, bool *is_pipe)
 
 	if (*fout == NULL)
 	{
-		psql_error("%s: %s\n", fname, strerror(errno));
+		pg_log_error("%s: %m", fname);
 		return false;
 	}
 
@@ -156,7 +157,7 @@ psql_get_variable(const char *varname, PsqlScanQuoteType quote,
 
 				if (!pset.db)
 				{
-					psql_error("cannot escape without active connection\n");
+					pg_log_error("cannot escape without active connection");
 					return NULL;
 				}
 
@@ -171,7 +172,7 @@ psql_get_variable(const char *varname, PsqlScanQuoteType quote,
 				{
 					const char *error = PQerrorMessage(pset.db);
 
-					psql_error("%s", error);
+					pg_log_info("%s", error);
 					return NULL;
 				}
 
@@ -197,7 +198,7 @@ psql_get_variable(const char *varname, PsqlScanQuoteType quote,
 				initPQExpBuffer(&buf);
 				if (!appendShellStringNoError(&buf, value))
 				{
-					psql_error("shell command argument contains a newline or carriage return: \"%s\"\n",
+					pg_log_error("shell command argument contains a newline or carriage return: \"%s\"",
 							   value);
 					free(buf.data);
 					return NULL;
@@ -214,35 +215,13 @@ psql_get_variable(const char *varname, PsqlScanQuoteType quote,
 
 
 /*
- * Error reporting for scripts. Errors should look like
- *	 psql:filename:lineno: message
- */
-void
-psql_error(const char *fmt,...)
-{
-	va_list		ap;
-
-	fflush(stdout);
-	if (pset.queryFout && pset.queryFout != stdout)
-		fflush(pset.queryFout);
-
-	if (pset.inputfile)
-		fprintf(stderr, "%s:%s:" UINT64_FORMAT ": ", pset.progname, pset.inputfile, pset.lineno);
-	va_start(ap, fmt);
-	vfprintf(stderr, _(fmt), ap);
-	va_end(ap);
-}
-
-
-
-/*
  * for backend Notice messages (INFO, WARNING, etc)
  */
 void
 NoticeProcessor(void *arg, const char *message)
 {
 	(void) arg;					/* not used */
-	psql_error("%s", message);
+	pg_log_info("%s", message);
 }
 
 
@@ -413,23 +392,23 @@ CheckConnection(void)
 	{
 		if (!pset.cur_cmd_interactive)
 		{
-			psql_error("connection to server was lost\n");
+			pg_log_fatal("connection to server was lost");
 			exit(EXIT_BADCONN);
 		}
 
-		psql_error("The connection to the server was lost. Attempting reset: ");
+		fprintf(stderr, _("The connection to the server was lost. Attempting reset: "));
 		PQreset(pset.db);
 		OK = ConnectionUp();
 		if (!OK)
 		{
-			psql_error("Failed.\n");
+			fprintf(stderr, _("Failed.\n"));
 			PQfinish(pset.db);
 			pset.db = NULL;
 			ResetCancelConn();
 			UnsyncVariables();
 		}
 		else
-			psql_error("Succeeded.\n");
+			fprintf(stderr, _("Succeeded.\n"));
 	}
 
 	return OK;
@@ -529,7 +508,7 @@ AcceptResult(const PGresult *result)
 
 			default:
 				OK = false;
-				psql_error("unexpected PQresultStatus: %d\n",
+				pg_log_error("unexpected PQresultStatus: %d",
 						   PQresultStatus(result));
 				break;
 		}
@@ -539,7 +518,7 @@ AcceptResult(const PGresult *result)
 		const char *error = PQerrorMessage(pset.db);
 
 		if (strlen(error))
-			psql_error("%s", error);
+			pg_log_info("%s", error);
 
 		CheckConnection();
 	}
@@ -693,7 +672,7 @@ PSQLexec(const char *query)
 
 	if (!pset.db)
 	{
-		psql_error("You are currently not connected to a database.\n");
+		pg_log_error("You are currently not connected to a database.");
 		return NULL;
 	}
 
@@ -751,7 +730,7 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
 
 	if (!pset.db)
 	{
-		psql_error("You are currently not connected to a database.\n");
+		pg_log_error("You are currently not connected to a database.");
 		return 0;
 	}
 
@@ -799,19 +778,19 @@ PSQLexecWatch(const char *query, const printQueryOpt *opt)
 			break;
 
 		case PGRES_EMPTY_QUERY:
-			psql_error("\\watch cannot be used with an empty query\n");
+			pg_log_error("\\watch cannot be used with an empty query");
 			PQclear(res);
 			return -1;
 
 		case PGRES_COPY_OUT:
 		case PGRES_COPY_IN:
 		case PGRES_COPY_BOTH:
-			psql_error("\\watch cannot be used with COPY\n");
+			pg_log_error("\\watch cannot be used with COPY");
 			PQclear(res);
 			return -1;
 
 		default:
-			psql_error("unexpected result status for \\watch\n");
+			pg_log_error("unexpected result status for \\watch");
 			PQclear(res);
 			return -1;
 	}
@@ -907,12 +886,12 @@ StoreQueryTuple(const PGresult *result)
 
 	if (PQntuples(result) < 1)
 	{
-		psql_error("no rows returned for \\gset\n");
+		pg_log_error("no rows returned for \\gset");
 		success = false;
 	}
 	else if (PQntuples(result) > 1)
 	{
-		psql_error("more than one row returned for \\gset\n");
+		pg_log_error("more than one row returned for \\gset");
 		success = false;
 	}
 	else
@@ -1081,7 +1060,7 @@ ProcessResult(PGresult **results)
 			default:
 				/* AcceptResult() should have caught anything else. */
 				is_copy = false;
-				psql_error("unexpected PQresultStatus: %d\n", result_status);
+				pg_log_error("unexpected PQresultStatus: %d", result_status);
 				break;
 		}
 
@@ -1298,7 +1277,7 @@ PrintQueryResults(PGresult *results)
 
 		default:
 			success = false;
-			psql_error("unexpected PQresultStatus: %d\n",
+			pg_log_error("unexpected PQresultStatus: %d",
 					   PQresultStatus(results));
 			break;
 	}
@@ -1334,7 +1313,7 @@ SendQuery(const char *query)
 
 	if (!pset.db)
 	{
-		psql_error("You are currently not connected to a database.\n");
+		pg_log_error("You are currently not connected to a database.");
 		goto sendquery_cleanup;
 	}
 
@@ -1380,7 +1359,7 @@ SendQuery(const char *query)
 		results = PQexec(pset.db, "BEGIN");
 		if (PQresultStatus(results) != PGRES_COMMAND_OK)
 		{
-			psql_error("%s", PQerrorMessage(pset.db));
+			pg_log_info("%s", PQerrorMessage(pset.db));
 			ClearOrSaveResult(results);
 			ResetCancelConn();
 			goto sendquery_cleanup;
@@ -1398,7 +1377,7 @@ SendQuery(const char *query)
 		{
 			char		sverbuf[32];
 
-			psql_error("The server (version %s) does not support savepoints for ON_ERROR_ROLLBACK.\n",
+			pg_log_warning("The server (version %s) does not support savepoints for ON_ERROR_ROLLBACK.",
 					   formatPGVersionNumber(pset.sversion, false,
 											 sverbuf, sizeof(sverbuf)));
 			on_error_rollback_warning = true;
@@ -1408,7 +1387,7 @@ SendQuery(const char *query)
 			results = PQexec(pset.db, "SAVEPOINT pg_psql_temporary_savepoint");
 			if (PQresultStatus(results) != PGRES_COMMAND_OK)
 			{
-				psql_error("%s", PQerrorMessage(pset.db));
+				pg_log_info("%s", PQerrorMessage(pset.db));
 				ClearOrSaveResult(results);
 				ResetCancelConn();
 				goto sendquery_cleanup;
@@ -1461,7 +1440,7 @@ SendQuery(const char *query)
 	}
 
 	if (!OK && pset.echo == PSQL_ECHO_ERRORS)
-		psql_error("STATEMENT:  %s\n", query);
+		pg_log_info("STATEMENT:  %s", query);
 
 	/* If we made a temporary savepoint, possibly release/rollback */
 	if (on_error_rollback_savepoint)
@@ -1504,7 +1483,7 @@ SendQuery(const char *query)
 				OK = false;
 				/* PQTRANS_UNKNOWN is expected given a broken connection. */
 				if (transaction_status != PQTRANS_UNKNOWN || ConnectionUp())
-					psql_error("unexpected transaction status (%d)\n",
+					pg_log_error("unexpected transaction status (%d)",
 							   transaction_status);
 				break;
 		}
@@ -1516,7 +1495,7 @@ SendQuery(const char *query)
 			svptres = PQexec(pset.db, svptcmd);
 			if (PQresultStatus(svptres) != PGRES_COMMAND_OK)
 			{
-				psql_error("%s", PQerrorMessage(pset.db));
+				pg_log_info("%s", PQerrorMessage(pset.db));
 				ClearOrSaveResult(svptres);
 				OK = false;
 
@@ -1619,7 +1598,7 @@ DescribeQuery(const char *query, double *elapsed_msec)
 	results = PQprepare(pset.db, "", query, 0, NULL);
 	if (PQresultStatus(results) != PGRES_COMMAND_OK)
 	{
-		psql_error("%s", PQerrorMessage(pset.db));
+		pg_log_info("%s", PQerrorMessage(pset.db));
 		SetResultVariables(results, false);
 		ClearOrSaveResult(results);
 		return false;
@@ -1657,7 +1636,7 @@ DescribeQuery(const char *query, double *elapsed_msec)
 
 				if (escname == NULL)
 				{
-					psql_error("%s", PQerrorMessage(pset.db));
+					pg_log_info("%s", PQerrorMessage(pset.db));
 					PQclear(results);
 					termPQExpBuffer(&buf);
 					return false;