pg_regress: Emit TAP compliant output

This converts pg_regress output format to emit TAP compliant output
while keeping it as human readable as possible for use without TAP
test harnesses. As verbose harness related information isn't really
supported by TAP this also reduces the verbosity of pg_regress runs
which makes scrolling through log output in buildfarm/CI runs a bit
easier as well.

As the meson TAP parser conumes whitespace, the leading indentation
for differentiating parallel tests from sequential tests has been
changed to a single character prefix.

This patch has been around for an extended period of time, reviewers
listed below may have been involved in reviewing a version quite
different from the version in this commit.  The original idea for
this patch was a hacking session with Jinbao Chen.

TAP format testing is also enabled in meson as of this.

Reviewed-by: Andres Freund <andres@anarazel.de>
Reviewed-by: Tom Lane <tgl@sss.pgh.pa.us>
Reviewed-by: Nikolay Shaplov <dhyan@nataraj.su>
Reviewed-by: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
Reviewed-by: Peter Eisentraut <peter.eisentraut@enterprisedb.com>
Discussion: https://postgr.es/m/BD4B107D-7E53-4794-ACBA-275BEB4327C9@yesql.se
Discussion: https://postgr.es/m/20220221164736.rq3ornzjdkmwk2wo@alap3.anarazel.de

2 files changed, 319 insertions, 259 deletions

diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index fb3e197fc06..736dd1ed5ed 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -444,7 +444,7 @@ ifeq ($(enable_tap_tests),yes)
 
 ifndef PGXS
 define prove_installcheck
-echo "+++ tap install-check in $(subdir) +++" && \
+echo "# +++ tap install-check in $(subdir) +++" && \
 rm -rf '$(CURDIR)'/tmp_check && \
 $(MKDIR_P) '$(CURDIR)'/tmp_check && \
 cd $(srcdir) && \
@@ -457,7 +457,7 @@ cd $(srcdir) && \
 endef
 else # PGXS case
 define prove_installcheck
-echo "+++ tap install-check in $(subdir) +++" && \
+echo "# +++ tap install-check in $(subdir) +++" && \
 rm -rf '$(CURDIR)'/tmp_check && \
 $(MKDIR_P) '$(CURDIR)'/tmp_check && \
 cd $(srcdir) && \
@@ -471,7 +471,7 @@ endef
 endif # PGXS
 
 define prove_check
-echo "+++ tap check in $(subdir) +++" && \
+echo "# +++ tap check in $(subdir) +++" && \
 rm -rf '$(CURDIR)'/tmp_check && \
 $(MKDIR_P) '$(CURDIR)'/tmp_check && \
 cd $(srcdir) && \
@@ -665,7 +665,7 @@ pg_regress_locale_flags = $(if $(ENCODING),--encoding=$(ENCODING)) $(NOLOCALE)
 pg_regress_clean_files = results/ regression.diffs regression.out tmp_check/ tmp_check_iso/ log/ output_iso/
 
 pg_regress_check = \
-    echo "+++ regress check in $(subdir) +++" && \
+    echo "\# +++ regress check in $(subdir) +++" && \
     $(with_temp_install) \
     $(top_builddir)/src/test/regress/pg_regress \
     --temp-instance=./tmp_check \
@@ -674,14 +674,14 @@ pg_regress_check = \
     $(TEMP_CONF) \
     $(pg_regress_locale_flags) $(EXTRA_REGRESS_OPTS)
 pg_regress_installcheck = \
-    echo "+++ regress install-check in $(subdir) +++" && \
+    echo "\# +++ regress install-check in $(subdir) +++" && \
     $(top_builddir)/src/test/regress/pg_regress \
     --inputdir=$(srcdir) \
     --bindir='$(bindir)' \
     $(pg_regress_locale_flags) $(EXTRA_REGRESS_OPTS)
 
 pg_isolation_regress_check = \
-    echo "+++ isolation check in $(subdir) +++" && \
+    echo "\# +++ isolation check in $(subdir) +++" && \
     $(with_temp_install) \
     $(top_builddir)/src/test/isolation/pg_isolation_regress \
     --temp-instance=./tmp_check_iso \
@@ -690,7 +690,7 @@ pg_isolation_regress_check = \
     $(TEMP_CONF) \
     $(pg_regress_locale_flags) $(EXTRA_REGRESS_OPTS)
 pg_isolation_regress_installcheck = \
-    echo "+++ isolation install-check in $(subdir) +++" && \
+    echo "\# +++ isolation install-check in $(subdir) +++" && \
     $(top_builddir)/src/test/isolation/pg_isolation_regress \
     --inputdir=$(srcdir) --outputdir=output_iso \
     --bindir='$(bindir)' \
diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 7b23cc80dcd..f7bcb30ca4f 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -68,6 +68,25 @@ const char *basic_diff_opts = "-w";
 const char *pretty_diff_opts = "-w -U3";
 #endif
 
+/*
+ * The width of the testname field when printing to ensure vertical alignment
+ * of test runtimes. This number is somewhat arbitrarily chosen to match the
+ * older pre-TAP output format.
+ */
+#define TESTNAME_WIDTH 36
+
+typedef enum TAPtype
+{
+	DIAG = 0,
+	BAIL,
+	NOTE,
+	NOTE_DETAIL,
+	NOTE_END,
+	TEST_STATUS,
+	PLAN,
+	NONE
+}			TAPtype;
+
 /* options settable from command line */
 _stringlist *dblist = NULL;
 bool		debug = false;
@@ -103,6 +122,8 @@ static const char *sockdir;
 static const char *temp_sockdir;
 static char sockself[MAXPGPATH];
 static char socklock[MAXPGPATH];
+static StringInfo failed_tests = NULL;
+static bool in_note = false;
 
 static _resultmap *resultmap = NULL;
 
@@ -115,13 +136,30 @@ static int	fail_count = 0;
 static bool directory_exists(const char *dir);
 static void make_directory(const char *dir);
 
-static void header(const char *fmt,...) pg_attribute_printf(1, 2);
-static void status(const char *fmt,...) pg_attribute_printf(1, 2);
+static void test_status_print(bool ok, const char *testname, double runtime, bool parallel);
+static void test_status_ok(const char *testname, double runtime, bool parallel);
+static void test_status_failed(const char *testname, double runtime, bool parallel);
+static void bail_out(bool noatexit, const char *fmt,...) pg_attribute_printf(2, 3);
+static void emit_tap_output(TAPtype type, const char *fmt,...) pg_attribute_printf(2, 3);
+static void emit_tap_output_v(TAPtype type, const char *fmt, va_list argp) pg_attribute_printf(2, 0);
+
 static StringInfo psql_start_command(void);
 static void psql_add_command(StringInfo buf, const char *query,...) pg_attribute_printf(2, 3);
 static void psql_end_command(StringInfo buf, const char *database);
 
 /*
+ * Convenience macros for printing TAP output with a more shorthand syntax
+ * aimed at making the code more readable.
+ */
+#define plan(x)				emit_tap_output(PLAN, "1..%i", (x))
+#define note(...)			emit_tap_output(NOTE, __VA_ARGS__)
+#define note_detail(...)	emit_tap_output(NOTE_DETAIL, __VA_ARGS__)
+#define diag(...)			emit_tap_output(DIAG, __VA_ARGS__)
+#define note_end()			emit_tap_output(NOTE_END, "\n");
+#define bail_noatexit(...)	bail_out(true, __VA_ARGS__)
+#define bail(...)			bail_out(false, __VA_ARGS__)
+
+/*
  * allow core files if possible.
  */
 #if defined(HAVE_GETRLIMIT)
@@ -133,9 +171,7 @@ unlimit_core_size(void)
 	getrlimit(RLIMIT_CORE, &lim);
 	if (lim.rlim_max == 0)
 	{
-		fprintf(stderr,
-				_("%s: could not set core size: disallowed by hard limit\n"),
-				progname);
+		diag("could not set core size: disallowed by hard limit");
 		return;
 	}
 	else if (lim.rlim_max == RLIM_INFINITY || lim.rlim_cur < lim.rlim_max)
@@ -201,53 +237,172 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 }
 
 /*
- * Print a progress banner on stdout.
+ * Bailing out is for unrecoverable errors which prevents further testing to
+ * occur and after which the test run should be aborted. By passing noatexit
+ * as true the process will terminate with _exit(2) and skipping registered
+ * exit handlers, thus avoid any risk of bottomless recursion calls to exit.
  */
 static void
-header(const char *fmt,...)
+bail_out(bool noatexit, const char *fmt,...)
 {
-	char		tmp[64];
 	va_list		ap;
 
 	va_start(ap, fmt);
-	vsnprintf(tmp, sizeof(tmp), fmt, ap);
+	emit_tap_output_v(BAIL, fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	if (noatexit)
+		_exit(2);
+
+	exit(2);
 }
 
 /*
- * Print "doing something ..." --- supplied text should not end with newline
+ * Print the result of a test run and associated metadata like runtime. Care
+ * is taken to align testnames and runtimes vertically to ensure the output
+ * is human readable while still TAP compliant. Tests run in parallel are
+ * prefixed with a '+' and sequential tests with a '-'. This distinction was
+ * previously indicated by 'test' prefixing sequential tests while parallel
+ * tests were indented by four leading spaces. The meson TAP parser consumes
+ * leading space however, so a non-whitespace prefix of the same length is
+ * required for both.
  */
 static void
-status(const char *fmt,...)
+test_status_print(bool ok, const char *testname, double runtime, bool parallel)
 {
-	va_list		ap;
+	int			testnumber = fail_count + success_count;
 
-	va_start(ap, fmt);
-	vfprintf(stdout, fmt, ap);
-	fflush(stdout);
-	va_end(ap);
+	/*
+	 * Testnumbers are padded to 5 characters to ensure that testnames align
+	 * vertically (assuming at most 9999 tests).  Testnames are prefixed with
+	 * a leading character to indicate being run in parallel or not. A leading
+	 * '+' indicates a parellel test, '-' indicates a single test.
+	 */
+	emit_tap_output(TEST_STATUS, "%sok %-5i%*s %c %-*s %8.0f ms",
+					(ok ? "" : "not "),
+					testnumber,
+	/* If ok, indent with four spaces matching "not " */
+					(ok ? (int) strlen("not ") : 0), "",
+	/* Prefix a parallel test '+' and a single test with '-' */
+					(parallel ? '+' : '-'),
+	/* Testnames are padded to align runtimes */
+					TESTNAME_WIDTH, testname,
+					runtime);
+}
 
-	if (logfile)
-	{
-		va_start(ap, fmt);
-		vfprintf(logfile, fmt, ap);
-		va_end(ap);
-	}
+static void
+test_status_ok(const char *testname, double runtime, bool parallel)
+{
+	success_count++;
+
+	test_status_print(true, testname, runtime, parallel);
 }
 
-/*
- * Done "doing something ..."
- */
 static void
-status_end(void)
+test_status_failed(const char *testname, double runtime, bool parallel)
+{
+	/*
+	 * Save failed tests in a buffer such that we can print a summary at the
+	 * end with diag() to ensure it's shown even under test harnesses.
+	 */
+	if (!failed_tests)
+		failed_tests = makeStringInfo();
+	else
+		appendStringInfoChar(failed_tests, ',');
+
+	appendStringInfo(failed_tests, " %s", testname);
+
+	fail_count++;
+
+	test_status_print(false, testname, runtime, parallel);
+}
+
+
+static void
+emit_tap_output(TAPtype type, const char *fmt,...)
 {
-	fprintf(stdout, "\n");
-	fflush(stdout);
+	va_list		argp;
+
+	va_start(argp, fmt);
+	emit_tap_output_v(type, fmt, argp);
+	va_end(argp);
+}
+
+static void
+emit_tap_output_v(TAPtype type, const char *fmt, va_list argp)
+{
+	va_list		argp_logfile;
+	FILE	   *fp;
+
+	/*
+	 * Diagnostic output will be hidden by prove unless printed to stderr. The
+	 * Bail message is also printed to stderr to aid debugging under a harness
+	 * which might otherwise not emit such an important message.
+	 */
+	if (type == DIAG || type == BAIL)
+		fp = stderr;
+	else
+		fp = stdout;
+
+	/*
+	 * If we are ending a note_detail line we can avoid further processing and
+	 * immediately return following a newline.
+	 */
+	if (type == NOTE_END)
+	{
+		in_note = false;
+		fprintf(fp, "\n");
+		if (logfile)
+			fprintf(logfile, "\n");
+		return;
+	}
+
+	/* Make a copy of the va args for printing to the logfile */
+	va_copy(argp_logfile, argp);
+
+	/*
+	 * Non-protocol output such as diagnostics or notes must be prefixed by a
+	 * '#' character. We print the Bail message like this too.
+	 */
+	if ((type == NOTE || type == DIAG || type == BAIL)
+		|| (type == NOTE_DETAIL && !in_note))
+	{
+		fprintf(fp, "# ");
+		if (logfile)
+			fprintf(logfile, "# ");
+	}
+	vfprintf(fp, fmt, argp);
 	if (logfile)
-		fprintf(logfile, "\n");
+		vfprintf(logfile, fmt, argp_logfile);
+
+	/*
+	 * If we are entering into a note with more details to follow, register
+	 * that the leading '#' has been printed such that subsequent details
+	 * aren't prefixed as well.
+	 */
+	if (type == NOTE_DETAIL)
+		in_note = true;
+
+	/*
+	 * If this was a Bail message, the bail protocol message must go to stdout
+	 * separately.
+	 */
+	if (type == BAIL)
+	{
+		fprintf(stdout, "Bail out!");
+		if (logfile)
+			fprintf(logfile, "Bail out!");
+	}
+
+	va_end(argp_logfile);
+
+	if (type != NOTE_DETAIL)
+	{
+		fprintf(fp, "\n");
+		if (logfile)
+			fprintf(logfile, "\n");
+	}
+	fflush(NULL);
 }
 
 /*
@@ -271,9 +426,8 @@ stop_postmaster(void)
 		r = system(buf);
 		if (r != 0)
 		{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
-			_exit(2);			/* not exit(), that could be recursive */
+			/* Not using the normal bail() as we want _exit */
+			bail_noatexit(_("could not stop postmaster: exit code was %d"), r);
 		}
 
 		postmaster_running = false;
@@ -331,9 +485,8 @@ make_temp_sockdir(void)
 	temp_sockdir = mkdtemp(template);
 	if (temp_sockdir == NULL)
 	{
-		fprintf(stderr, _("%s: could not create directory \"%s\": %s\n"),
-				progname, template, strerror(errno));
-		exit(2);
+		bail("could not create directory \"%s\": %s",
+			 template, strerror(errno));
 	}
 
 	/* Stage file names for remove_temp().  Unsafe in a signal handler. */
@@ -455,9 +608,8 @@ load_resultmap(void)
 		/* OK if it doesn't exist, else complain */
 		if (errno == ENOENT)
 			return;
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, buf, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for reading: %s",
+			 buf, strerror(errno));
 	}
 
 	while (fgets(buf, sizeof(buf), f))
@@ -476,26 +628,20 @@ load_resultmap(void)
 		file_type = strchr(buf, ':');
 		if (!file_type)
 		{
-			fprintf(stderr, _("incorrectly formatted resultmap entry: %s\n"),
-					buf);
-			exit(2);
+			bail("incorrectly formatted resultmap entry: %s", buf);
 		}
 		*file_type++ = '\0';
 
 		platform = strchr(file_type, ':');
 		if (!platform)
 		{
-			fprintf(stderr, _("incorrectly formatted resultmap entry: %s\n"),
-					buf);
-			exit(2);
+			bail("incorrectly formatted resultmap entry: %s", buf);
 		}
 		*platform++ = '\0';
 		expected = strchr(platform, '=');
 		if (!expected)
 		{
-			fprintf(stderr, _("incorrectly formatted resultmap entry: %s\n"),
-					buf);
-			exit(2);
+			bail("incorrectly formatted resultmap entry: %s", buf);
 		}
 		*expected++ = '\0';
 
@@ -741,13 +887,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			note("using postmaster on %s, port %s", pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			note("using postmaster on %s, default port", pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			note("using postmaster on Unix socket, port %s", pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			note("using postmaster on Unix socket, default port");
 	}
 
 	load_resultmap();
@@ -796,35 +942,26 @@ current_windows_user(const char **acct, const char **dom)
 
 	if (!OpenProcessToken(GetCurrentProcess(), TOKEN_READ, &token))
 	{
-		fprintf(stderr,
-				_("%s: could not open process token: error code %lu\n"),
-				progname, GetLastError());
-		exit(2);
+		bail("could not open process token: error code %lu", GetLastError());
 	}
 
 	if (!GetTokenInformation(token, TokenUser, NULL, 0, &retlen) && GetLastError() != 122)
 	{
-		fprintf(stderr,
-				_("%s: could not get token information buffer size: error code %lu\n"),
-				progname, GetLastError());
-		exit(2);
+		bail("could not get token information buffer size: error code %lu",
+			 GetLastError());
 	}
 	tokenuser = pg_malloc(retlen);
 	if (!GetTokenInformation(token, TokenUser, tokenuser, retlen, &retlen))
 	{
-		fprintf(stderr,
-				_("%s: could not get token information: error code %lu\n"),
-				progname, GetLastError());
-		exit(2);
+		bail("could not get token information: error code %lu",
+			 GetLastError());
 	}
 
 	if (!LookupAccountSid(NULL, tokenuser->User.Sid, accountname, &accountnamesize,
 						  domainname, &domainnamesize, &accountnameuse))
 	{
-		fprintf(stderr,
-				_("%s: could not look up account SID: error code %lu\n"),
-				progname, GetLastError());
-		exit(2);
+		bail("could not look up account SID: error code %lu",
+			 GetLastError());
 	}
 
 	free(tokenuser);
@@ -870,8 +1007,7 @@ config_sspi_auth(const char *pgdata, const char *superuser_name)
 		superuser_name = get_user_name(&errstr);
 		if (superuser_name == NULL)
 		{
-			fprintf(stderr, "%s: %s\n", progname, errstr);
-			exit(2);
+			bail("%s", errstr);
 		}
 	}
 
@@ -902,9 +1038,8 @@ config_sspi_auth(const char *pgdata, const char *superuser_name)
 	do { \
 		if (!(cond)) \
 		{ \
-			fprintf(stderr, _("%s: could not write to file \"%s\": %s\n"), \
-					progname, fname, strerror(errno)); \
-			exit(2); \
+			bail("could not write to file \"%s\": %s", \
+				 fname, strerror(errno)); \
 		} \
 	} while (0)
 
@@ -915,15 +1050,13 @@ config_sspi_auth(const char *pgdata, const char *superuser_name)
 		 * Truncating this name is a fatal error, because we must not fail to
 		 * overwrite an original trust-authentication pg_hba.conf.
 		 */
-		fprintf(stderr, _("%s: directory name too long\n"), progname);
-		exit(2);
+		bail("directory name too long");
 	}
 	hba = fopen(fname, "w");
 	if (hba == NULL)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for writing: %s\n"),
-				progname, fname, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for writing: %s",
+			 fname, strerror(errno));
 	}
 	CW(fputs("# Configuration written by config_sspi_auth()\n", hba) >= 0);
 	CW(fputs("host all all 127.0.0.1/32  sspi include_realm=1 map=regress\n",
@@ -937,9 +1070,8 @@ config_sspi_auth(const char *pgdata, const char *superuser_name)
 	ident = fopen(fname, "w");
 	if (ident == NULL)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for writing: %s\n"),
-				progname, fname, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for writing: %s",
+			 fname, strerror(errno));
 	}
 	CW(fputs("# Configuration written by config_sspi_auth()\n", ident) >= 0);
 
@@ -973,7 +1105,7 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X -q",
 					 bindir ? bindir : "",
 					 bindir ? "/" : "");
 	return buf;
@@ -1029,8 +1161,7 @@ psql_end_command(StringInfo buf, const char *database)
 	if (system(buf->data) != 0)
 	{
 		/* psql probably already reported the error */
-		fprintf(stderr, _("command failed: %s\n"), buf->data);
-		exit(2);
+		bail("command failed: %s", buf->data);
 	}
 
 	/* Clean up */
@@ -1071,9 +1202,7 @@ spawn_process(const char *cmdline)
 	pid = fork();
 	if (pid == -1)
 	{
-		fprintf(stderr, _("%s: could not fork: %s\n"),
-				progname, strerror(errno));
-		exit(2);
+		bail("could not fork: %s", strerror(errno));
 	}
 	if (pid == 0)
 	{
@@ -1088,9 +1217,8 @@ spawn_process(const char *cmdline)
 
 		cmdline2 = psprintf("exec %s", cmdline);
 		execl(shellprog, shellprog, "-c", cmdline2, (char *) NULL);
-		fprintf(stderr, _("%s: could not exec \"%s\": %s\n"),
-				progname, shellprog, strerror(errno));
-		_exit(1);				/* not exit() here... */
+		/* Not using the normal bail() here as we want _exit */
+		bail_noatexit("could not exec \"%s\": %s", shellprog, strerror(errno));
 	}
 	/* in parent */
 	return pid;
@@ -1128,8 +1256,8 @@ file_size(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		diag("could not open file \"%s\" for reading: %s",
+			 file, strerror(errno));
 		return -1;
 	}
 	fseek(f, 0, SEEK_END);
@@ -1150,8 +1278,8 @@ file_line_count(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		diag("could not open file \"%s\" for reading: %s",
+			 file, strerror(errno));
 		return -1;
 	}
 	while ((c = fgetc(f)) != EOF)
@@ -1192,9 +1320,7 @@ make_directory(const char *dir)
 {
 	if (mkdir(dir, S_IRWXU | S_IRWXG | S_IRWXO) < 0)
 	{
-		fprintf(stderr, _("%s: could not create directory \"%s\": %s\n"),
-				progname, dir, strerror(errno));
-		exit(2);
+		bail("could not create directory \"%s\": %s", dir, strerror(errno));
 	}
 }
 
@@ -1244,8 +1370,7 @@ run_diff(const char *cmd, const char *filename)
 	r = system(cmd);
 	if (!WIFEXITED(r) || WEXITSTATUS(r) > 1)
 	{
-		fprintf(stderr, _("diff command failed with status %d: %s\n"), r, cmd);
-		exit(2);
+		bail("diff command failed with status %d: %s", r, cmd);
 	}
 #ifdef WIN32
 
@@ -1255,8 +1380,7 @@ run_diff(const char *cmd, const char *filename)
 	 */
 	if (WEXITSTATUS(r) == 1 && file_size(filename) <= 0)
 	{
-		fprintf(stderr, _("diff command not found: %s\n"), cmd);
-		exit(2);
+		bail("diff command not found: %s", cmd);
 	}
 #endif
 
@@ -1327,9 +1451,8 @@ results_differ(const char *testname, const char *resultsfile, const char *defaul
 		alt_expectfile = get_alternative_expectfile(expectfile, i);
 		if (!alt_expectfile)
 		{
-			fprintf(stderr, _("Unable to check secondary comparison files: %s\n"),
-					strerror(errno));
-			exit(2);
+			bail("Unable to check secondary comparison files: %s",
+				 strerror(errno));
 		}
 
 		if (!file_exists(alt_expectfile))
@@ -1444,9 +1567,7 @@ wait_for_tests(PID_TYPE * pids, int *statuses, instr_time *stoptimes,
 
 		if (p == INVALID_PID)
 		{
-			fprintf(stderr, _("failed to wait for subprocesses: %s\n"),
-					strerror(errno));
-			exit(2);
+			bail("failed to wait for subprocesses: %s", strerror(errno));
 		}
 #else
 		DWORD		exit_status;
@@ -1455,9 +1576,8 @@ wait_for_tests(PID_TYPE * pids, int *statuses, instr_time *stoptimes,
 		r = WaitForMultipleObjects(tests_left, active_pids, FALSE, INFINITE);
 		if (r < WAIT_OBJECT_0 || r >= WAIT_OBJECT_0 + tests_left)
 		{
-			fprintf(stderr, _("failed to wait for subprocesses: error code %lu\n"),
-					GetLastError());
-			exit(2);
+			bail("failed to wait for subprocesses: error code %lu",
+				 GetLastError());
 		}
 		p = active_pids[r - WAIT_OBJECT_0];
 		/* compact the active_pids array */
@@ -1476,7 +1596,7 @@ wait_for_tests(PID_TYPE * pids, int *statuses, instr_time *stoptimes,
 				statuses[i] = (int) exit_status;
 				INSTR_TIME_SET_CURRENT(stoptimes[i]);
 				if (names)
-					status(" %s", names[i]);
+					note_detail(" %s", names[i]);
 				tests_left--;
 				break;
 			}
@@ -1495,21 +1615,20 @@ static void
 log_child_failure(int exitstatus)
 {
 	if (WIFEXITED(exitstatus))
-		status(_(" (test process exited with exit code %d)"),
-			   WEXITSTATUS(exitstatus));
+		diag("(test process exited with exit code %d)",
+			 WEXITSTATUS(exitstatus));
 	else if (WIFSIGNALED(exitstatus))
 	{
 #if defined(WIN32)
-		status(_(" (test process was terminated by exception 0x%X)"),
-			   WTERMSIG(exitstatus));
+		diag("(test process was terminated by exception 0x%X)",
+			 WTERMSIG(exitstatus));
 #else
-		status(_(" (test process was terminated by signal %d: %s)"),
-			   WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
+		diag("(test process was terminated by signal %d: %s)",
+			 WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
 #endif
 	}
 	else
-		status(_(" (test process exited with unrecognized status %d)"),
-			   exitstatus);
+		diag("(test process exited with unrecognized status %d)", exitstatus);
 }
 
 /*
@@ -1540,9 +1659,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	scf = fopen(schedule, "r");
 	if (!scf)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, schedule, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for reading: %s",
+			 schedule, strerror(errno));
 	}
 
 	while (fgets(scbuf, sizeof(scbuf), scf))
@@ -1566,9 +1684,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 			test = scbuf + 6;
 		else
 		{
-			fprintf(stderr, _("syntax error in schedule file \"%s\" line %d: %s\n"),
-					schedule, line_num, scbuf);
-			exit(2);
+			bail("syntax error in schedule file \"%s\" line %d: %s",
+				 schedule, line_num, scbuf);
 		}
 
 		num_tests = 0;
@@ -1584,9 +1701,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 
 					if (num_tests >= MAX_PARALLEL_TESTS)
 					{
-						fprintf(stderr, _("too many parallel tests (more than %d) in schedule file \"%s\" line %d: %s\n"),
-								MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
-						exit(2);
+						bail("too many parallel tests (more than %d) in schedule file \"%s\" line %d: %s",
+							 MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
 					}
 					sav = *c;
 					*c = '\0';
@@ -1608,14 +1724,12 @@ run_schedule(const char *schedule, test_start_function startfunc,
 
 		if (num_tests == 0)
 		{
-			fprintf(stderr, _("syntax error in schedule file \"%s\" line %d: %s\n"),
-					schedule, line_num, scbuf);
-			exit(2);
+			bail("syntax error in schedule file \"%s\" line %d: %s",
+				 schedule, line_num, scbuf);
 		}
 
 		if (num_tests == 1)
 		{
-			status(_("test %-28s ... "), tests[0]);
 			pids[0] = (startfunc) (tests[0], &resultfiles[0], &expectfiles[0], &tags[0]);
 			INSTR_TIME_SET_CURRENT(starttimes[0]);
 			wait_for_tests(pids, statuses, stoptimes, NULL, 1);
@@ -1623,16 +1737,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else if (max_concurrent_tests > 0 && max_concurrent_tests < num_tests)
 		{
-			fprintf(stderr, _("too many parallel tests (more than %d) in schedule file \"%s\" line %d: %s\n"),
-					max_concurrent_tests, schedule, line_num, scbuf);
-			exit(2);
+			bail("too many parallel tests (more than %d) in schedule file \"%s\" line %d: %s",
+				 max_concurrent_tests, schedule, line_num, scbuf);
 		}
 		else if (max_connections > 0 && max_connections < num_tests)
 		{
 			int			oldest = 0;
 
-			status(_("parallel group (%d tests, in groups of %d): "),
-				   num_tests, max_connections);
+			note_detail("parallel group (%d tests, in groups of %d): ",
+						num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1648,18 +1761,18 @@ run_schedule(const char *schedule, test_start_function startfunc,
 			wait_for_tests(pids + oldest, statuses + oldest,
 						   stoptimes + oldest,
 						   tests + oldest, i - oldest);
-			status_end();
+			note_end();
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			note_detail("parallel group (%d tests): ", num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
 				INSTR_TIME_SET_CURRENT(starttimes[i]);
 			}
 			wait_for_tests(pids, statuses, stoptimes, tests, num_tests);
-			status_end();
+			note_end();
 		}
 
 		/* Check results for all tests */
@@ -1670,8 +1783,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
-			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1692,36 +1804,27 @@ run_schedule(const char *schedule, test_start_function startfunc,
 				newdiff = results_differ(tests[i], rl->str, el->str);
 				if (newdiff && tl)
 				{
-					printf("%s ", tl->str);
+					diag("tag: %s", tl->str);
 				}
 				differ |= newdiff;
 			}
 
 			if (statuses[i] != 0)
 			{
-				status(_("FAILED"));
+				test_status_failed(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]), (num_tests > 1));
 				log_child_failure(statuses[i]);
-				fail_count++;
 			}
 			else
 			{
-
 				if (differ)
 				{
-					status(_("FAILED"));
-					fail_count++;
+					test_status_failed(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]), (num_tests > 1));
 				}
 				else
 				{
-					status(_("ok    "));	/* align with FAILED */
-					success_count++;
+					test_status_ok(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]), (num_tests > 1));
 				}
 			}
-
-			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
-
-			status_end();
 		}
 
 		for (i = 0; i < num_tests; i++)
@@ -1756,7 +1859,6 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *tl;
 	bool		differ = false;
 
-	status(_("test %-28s ... "), test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
@@ -1780,35 +1882,29 @@ run_single_test(const char *test, test_start_function startfunc,
 		newdiff = results_differ(test, rl->str, el->str);
 		if (newdiff && tl)
 		{
-			printf("%s ", tl->str);
+			diag("tag: %s", tl->str);
 		}
 		differ |= newdiff;
 	}
 
+	INSTR_TIME_SUBTRACT(stoptime, starttime);
+
 	if (exit_status != 0)
 	{
-		status(_("FAILED"));
-		fail_count++;
+		test_status_failed(test, false, INSTR_TIME_GET_MILLISEC(stoptime));
 		log_child_failure(exit_status);
 	}
 	else
 	{
 		if (differ)
 		{
-			status(_("FAILED"));
-			fail_count++;
+			test_status_failed(test, false, INSTR_TIME_GET_MILLISEC(stoptime));
 		}
 		else
 		{
-			status(_("ok    "));	/* align with FAILED */
-			success_count++;
+			test_status_ok(test, INSTR_TIME_GET_MILLISEC(stoptime), false);
 		}
 	}
-
-	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
-
-	status_end();
 }
 
 /*
@@ -1830,9 +1926,8 @@ open_result_files(void)
 	logfile = fopen(logfilename, "w");
 	if (!logfile)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for writing: %s\n"),
-				progname, logfilename, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for writing: %s",
+			 logfilename, strerror(errno));
 	}
 
 	/* create the diffs file as empty */
@@ -1841,9 +1936,8 @@ open_result_files(void)
 	difffile = fopen(difffilename, "w");
 	if (!difffile)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for writing: %s\n"),
-				progname, difffilename, strerror(errno));
-		exit(2);
+		bail("could not open file \"%s\" for writing: %s",
+			 difffilename, strerror(errno));
 	}
 	/* we don't keep the diffs file open continuously */
 	fclose(difffile);
@@ -1859,7 +1953,6 @@ drop_database_if_exists(const char *dbname)
 {
 	StringInfo	buf = psql_start_command();
 
-	header(_("dropping database \"%s\""), dbname);
 	/* Set warning level so we don't see chatter about nonexistent DB */
 	psql_add_command(buf, "SET client_min_messages = warning");
 	psql_add_command(buf, "DROP DATABASE IF EXISTS \"%s\"", dbname);
@@ -1876,7 +1969,6 @@ create_database(const char *dbname)
 	 * We use template0 so that any installation-local cruft in template1 will
 	 * not mess up the tests.
 	 */
-	header(_("creating database \"%s\""), dbname);
 	if (encoding)
 		psql_add_command(buf, "CREATE DATABASE \"%s\" TEMPLATE=template0 ENCODING='%s'%s", dbname, encoding,
 						 (nolocale) ? " LC_COLLATE='C' LC_CTYPE='C'" : "");
@@ -1898,10 +1990,7 @@ create_database(const char *dbname)
 	 * this will work whether or not the extension is preinstalled.
 	 */
 	for (sl = loadextension; sl != NULL; sl = sl->next)
-	{
-		header(_("installing %s"), sl->str);
 		psql_command(dbname, "CREATE EXTENSION IF NOT EXISTS \"%s\"", sl->str);
-	}
 }
 
 static void
@@ -1909,7 +1998,6 @@ drop_role_if_exists(const char *rolename)
 {
 	StringInfo	buf = psql_start_command();
 
-	header(_("dropping role \"%s\""), rolename);
 	/* Set warning level so we don't see chatter about nonexistent role */
 	psql_add_command(buf, "SET client_min_messages = warning");
 	psql_add_command(buf, "DROP ROLE IF EXISTS \"%s\"", rolename);
@@ -1921,7 +2009,6 @@ create_role(const char *rolename, const _stringlist *granted_dbs)
 {
 	StringInfo	buf = psql_start_command();
 
-	header(_("creating role \"%s\""), rolename);
 	psql_add_command(buf, "CREATE ROLE \"%s\" WITH LOGIN", rolename);
 	for (; granted_dbs != NULL; granted_dbs = granted_dbs->next)
 	{
@@ -2143,8 +2230,8 @@ regression_main(int argc, char *argv[],
 				break;
 			default:
 				/* getopt_long already emitted a complaint */
-				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
-						progname);
+				pg_log_error_hint("Try \"%s --help\" for more information.",
+								  progname);
 				exit(2);
 		}
 	}
@@ -2164,9 +2251,7 @@ regression_main(int argc, char *argv[],
 	 */
 	if (!(dblist && dblist->str && dblist->str[0]))
 	{
-		fprintf(stderr, _("%s: no database name was specified\n"),
-				progname);
-		exit(2);
+		bail("no database name was specified");
 	}
 
 	if (config_auth_datadir)
@@ -2217,17 +2302,12 @@ regression_main(int argc, char *argv[],
 
 		if (directory_exists(temp_instance))
 		{
-			header(_("removing existing temp instance"));
 			if (!rmtree(temp_instance, true))
 			{
-				fprintf(stderr, _("\n%s: could not remove temp instance \"%s\"\n"),
-						progname, temp_instance);
-				exit(2);
+				bail("could not remove temp instance \"%s\"", temp_instance);
 			}
 		}
 
-		header(_("creating temporary instance"));
-
 		/* make the temp instance top directory */
 		make_directory(temp_instance);
 
@@ -2237,7 +2317,6 @@ regression_main(int argc, char *argv[],
 			make_directory(buf);
 
 		/* initdb */
-		header(_("initializing database system"));
 		snprintf(buf, sizeof(buf),
 				 "\"%s%sinitdb\" -D \"%s/data\" --no-clean --no-sync%s%s > \"%s/log/initdb.log\" 2>&1",
 				 bindir ? bindir : "",
@@ -2249,8 +2328,10 @@ regression_main(int argc, char *argv[],
 		fflush(NULL);
 		if (system(buf))
 		{
-			fprintf(stderr, _("\n%s: initdb failed\nExamine %s/log/initdb.log for the reason.\nCommand was: %s\n"), progname, outputdir, buf);
-			exit(2);
+			bail("initdb failed\n"
+				 "# Examine \"%s/log/initdb.log\" for the reason.\n"
+				 "# Command was: %s",
+				 outputdir, buf);
 		}
 
 		/*
@@ -2265,8 +2346,8 @@ regression_main(int argc, char *argv[],
 		pg_conf = fopen(buf, "a");
 		if (pg_conf == NULL)
 		{
-			fprintf(stderr, _("\n%s: could not open \"%s\" for adding extra config: %s\n"), progname, buf, strerror(errno));
-			exit(2);
+			bail("could not open \"%s\" for adding extra config: %s",
+				 buf, strerror(errno));
 		}
 		fputs("\n# Configuration added by pg_regress\n\n", pg_conf);
 		fputs("log_autovacuum_min_duration = 0\n", pg_conf);
@@ -2285,8 +2366,8 @@ regression_main(int argc, char *argv[],
 			extra_conf = fopen(temp_config, "r");
 			if (extra_conf == NULL)
 			{
-				fprintf(stderr, _("\n%s: could not open \"%s\" to read extra config: %s\n"), progname, temp_config, strerror(errno));
-				exit(2);
+				bail("could not open \"%s\" to read extra config: %s",
+					 temp_config, strerror(errno));
 			}
 			while (fgets(line_buf, sizeof(line_buf), extra_conf) != NULL)
 				fputs(line_buf, pg_conf);
@@ -2325,14 +2406,13 @@ regression_main(int argc, char *argv[],
 
 				if (port_specified_by_user || i == 15)
 				{
-					fprintf(stderr, _("port %d apparently in use\n"), port);
+					note("port %d apparently in use", port);
 					if (!port_specified_by_user)
-						fprintf(stderr, _("%s: could not determine an available port\n"), progname);
-					fprintf(stderr, _("Specify an unused port using the --port option or shut down any conflicting PostgreSQL servers.\n"));
-					exit(2);
+						note("could not determine an available port");
+					bail("Specify an unused port using the --port option or shut down any conflicting PostgreSQL servers.");
 				}
 
-				fprintf(stderr, _("port %d apparently in use, trying %d\n"), port, port + 1);
+				note("port %d apparently in use, trying %d", port, port + 1);
 				port++;
 				sprintf(s, "%d", port);
 				setenv("PGPORT", s, 1);
@@ -2344,7 +2424,6 @@ regression_main(int argc, char *argv[],
 		/*
 		 * Start the temp postmaster
 		 */
-		header(_("starting postmaster"));
 		snprintf(buf, sizeof(buf),
 				 "\"%s%spostgres\" -D \"%s/data\" -F%s "
 				 "-c \"listen_addresses=%s\" -k \"%s\" "
@@ -2356,11 +2435,7 @@ regression_main(int argc, char *argv[],
 				 outputdir);
 		postmaster_pid = spawn_process(buf);
 		if (postmaster_pid == INVALID_PID)
-		{
-			fprintf(stderr, _("\n%s: could not spawn postmaster: %s\n"),
-					progname, strerror(errno));
-			exit(2);
-		}
+			bail("could not spawn postmaster: %s", strerror(errno));
 
 		/*
 		 * Wait till postmaster is able to accept connections; normally this
@@ -2395,16 +2470,16 @@ regression_main(int argc, char *argv[],
 			if (WaitForSingleObject(postmaster_pid, 0) == WAIT_OBJECT_0)
 #endif
 			{
-				fprintf(stderr, _("\n%s: postmaster failed\nExamine %s/log/postmaster.log for the reason\n"), progname, outputdir);
-				exit(2);
+				bail("postmaster failed, examine \"%s/log/postmaster.log\" for the reason",
+					 outputdir);
 			}
 
 			pg_usleep(1000000L);
 		}
 		if (i >= wait_seconds)
 		{
-			fprintf(stderr, _("\n%s: postmaster did not respond within %d seconds\nExamine %s/log/postmaster.log for the reason\n"),
-					progname, wait_seconds, outputdir);
+			diag("postmaster did not respond within %d seconds, examine \"%s/log/postmaster.log\" for the reason",
+				 wait_seconds, outputdir);
 
 			/*
 			 * If we get here, the postmaster is probably wedged somewhere in
@@ -2413,17 +2488,14 @@ regression_main(int argc, char *argv[],
 			 * attempts.
 			 */
 #ifndef WIN32
-			if (kill(postmaster_pid, SIGKILL) != 0 &&
-				errno != ESRCH)
-				fprintf(stderr, _("\n%s: could not kill failed postmaster: %s\n"),
-						progname, strerror(errno));
+			if (kill(postmaster_pid, SIGKILL) != 0 && errno != ESRCH)
+				bail("could not kill failed postmaster: %s", strerror(errno));
 #else
 			if (TerminateProcess(postmaster_pid, 255) == 0)
-				fprintf(stderr, _("\n%s: could not kill failed postmaster: error code %lu\n"),
-						progname, GetLastError());
+				bail("could not kill failed postmaster: error code %lu",
+					 GetLastError());
 #endif
-
-			exit(2);
+			bail("postmaster failed");
 		}
 
 		postmaster_running = true;
@@ -2434,8 +2506,8 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
-			   port, ULONGPID(postmaster_pid));
+		note("using temp instance on port %d with PID %lu",
+			 port, ULONGPID(postmaster_pid));
 	}
 	else
 	{
@@ -2466,8 +2538,6 @@ regression_main(int argc, char *argv[],
 	/*
 	 * Ready to run the tests
 	 */
-	header(_("running regression test queries"));
-
 	for (sl = schedulelist; sl != NULL; sl = sl->next)
 	{
 		run_schedule(sl->str, startfunc, postfunc);
@@ -2483,7 +2553,6 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance)
 	{
-		header(_("shutting down postmaster"));
 		stop_postmaster();
 	}
 
@@ -2494,42 +2563,30 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance && fail_count == 0)
 	{
-		header(_("removing temporary instance"));
 		if (!rmtree(temp_instance, true))
-			fprintf(stderr, _("\n%s: could not remove temp instance \"%s\"\n"),
-					progname, temp_instance);
+			diag("could not remove temp instance \"%s\"",
+				 temp_instance);
 	}
 
-	fclose(logfile);
+	/*
+	 * Emit a TAP compliant Plan
+	 */
+	plan(fail_count + success_count);
 
 	/*
 	 * Emit nice-looking summary message
 	 */
 	if (fail_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
+		note("All %d tests passed.", success_count);
 	else
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
-
-	putchar('\n');
-	for (i = strlen(buf); i > 0; i--)
-		putchar('=');
-	printf("\n%s\n", buf);
-	for (i = strlen(buf); i > 0; i--)
-		putchar('=');
-	putchar('\n');
-	putchar('\n');
+		diag("%d of %d tests failed.", fail_count, success_count + fail_count);
 
 	if (file_size(difffilename) > 0)
 	{
-		printf(_("The differences that caused some tests to fail can be viewed in the\n"
-				 "file \"%s\".  A copy of the test summary that you see\n"
-				 "above is saved in the file \"%s\".\n\n"),
-			   difffilename, logfilename);
+		diag("The differences that caused some tests to fail can be viewed in the file \"%s\".",
+			 difffilename);
+		diag("A copy of the test summary that you see above is saved in the file \"%s\".",
+			 logfilename);
 	}
 	else
 	{
@@ -2537,6 +2594,9 @@ regression_main(int argc, char *argv[],
 		unlink(logfilename);
 	}
 
+	fclose(logfile);
+	logfile = NULL;
+
 	if (fail_count != 0)
 		exit(1);