public inbox for [email protected]  
help / color / mirror / Atom feed
[PATCH v2] windows: Only consider us to be running as service if stderr is invalid.
26+ messages / 6 participants
[nested] [flat]

* [PATCH v2] windows: Only consider us to be running as service if stderr is invalid.
@ 2021-03-03 05:24  Andres Freund <[email protected]>
  0 siblings, 0 replies; 26+ messages in thread

From: Andres Freund @ 2021-03-03 05:24 UTC (permalink / raw)

Previously pgwin32_is_service() would falsely return true when
postgres is started from somewhere within a service, but not as a
service. That is e.g. always the case with windows docker containers,
which some CI services use to run windows tests in.

In addition to this change, it likely would be a good idea to have
pg_ctl runservice pass down a flag indicating that postgres is running
as a service.

Author: Andres Freund <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
 src/port/win32security.c | 13 +++++++++++--
 src/bin/pg_ctl/pg_ctl.c  | 33 +++++++++++++++++++++++++++++++++
 2 files changed, 44 insertions(+), 2 deletions(-)

diff --git a/src/port/win32security.c b/src/port/win32security.c
index 4a673fde19a..b57ce61d752 100644
--- a/src/port/win32security.c
+++ b/src/port/win32security.c
@@ -95,8 +95,9 @@ pgwin32_is_admin(void)
  * We consider ourselves running as a service if one of the following is
  * true:
  *
- * 1) We are running as LocalSystem (only used by services)
- * 2) Our token contains SECURITY_SERVICE_RID (automatically added to the
+ * 1) Standard error is not valid (always the case for services)
+ * 2) We are running as LocalSystem (only used by services)
+ * 3) Our token contains SECURITY_SERVICE_RID (automatically added to the
  *	  process token by the SCM when starting a service)
  *
  * The check for LocalSystem is needed, because surprisingly, if a service
@@ -121,11 +122,19 @@ pgwin32_is_service(void)
 	PSID		ServiceSid;
 	PSID		LocalSystemSid;
 	SID_IDENTIFIER_AUTHORITY NtAuthority = {SECURITY_NT_AUTHORITY};
+	HANDLE		stderr_handle;
 
 	/* Only check the first time */
 	if (_is_service != -1)
 		return _is_service;
 
+	stderr_handle = GetStdHandle(STD_ERROR_HANDLE);
+	if (stderr_handle != INVALID_HANDLE_VALUE && stderr_handle != NULL)
+	{
+		_is_service = 0;
+		return _is_service;
+	}
+
 	/* First check for LocalSystem */
 	if (!AllocateAndInitializeSid(&NtAuthority, 1,
 								  SECURITY_LOCAL_SYSTEM_RID, 0, 0, 0, 0, 0, 0, 0,
diff --git a/src/bin/pg_ctl/pg_ctl.c b/src/bin/pg_ctl/pg_ctl.c
index 7985da0a943..c99e3c507de 100644
--- a/src/bin/pg_ctl/pg_ctl.c
+++ b/src/bin/pg_ctl/pg_ctl.c
@@ -1737,6 +1737,31 @@ typedef BOOL (WINAPI * __SetInformationJobObject) (HANDLE, JOBOBJECTINFOCLASS, L
 typedef BOOL (WINAPI * __AssignProcessToJobObject) (HANDLE, HANDLE);
 typedef BOOL (WINAPI * __QueryInformationJobObject) (HANDLE, JOBOBJECTINFOCLASS, LPVOID, DWORD, LPDWORD);
 
+/*
+ * Set up STARTUPINFO for the new process to inherit this process' handles.
+ *
+ * Process started as services appear to have "empty" handles (GetStdHandle()
+ * returns NULL) rather than invalid ones. But passing down NULL ourselves
+ * doesn't work, it's interpreted as STARTUPINFO->hStd* not being set. But we
+ * can pass down INVALID_HANDLE_VALUE - which makes GetStdHandle() in the new
+ * process (and its child processes!) return INVALID_HANDLE_VALUE. Which
+ * achieves the goal of postmaster running in a similar environment as pg_ctl.
+ */
+static void
+InheritStdHandles(STARTUPINFO* si)
+{
+	si->dwFlags |= STARTF_USESTDHANDLES;
+	si->hStdInput = GetStdHandle(STD_INPUT_HANDLE);
+	if (si->hStdInput == NULL)
+		si->hStdInput = INVALID_HANDLE_VALUE;
+	si->hStdOutput = GetStdHandle(STD_OUTPUT_HANDLE);
+	if (si->hStdOutput == NULL)
+		si->hStdOutput = INVALID_HANDLE_VALUE;
+	si->hStdError = GetStdHandle(STD_ERROR_HANDLE);
+	if (si->hStdError == NULL)
+		si->hStdError = INVALID_HANDLE_VALUE;
+}
+
 /*
  * Create a restricted token, a job object sandbox, and execute the specified
  * process with it.
@@ -1774,6 +1799,14 @@ CreateRestrictedProcess(char *cmd, PROCESS_INFORMATION *processInfo, bool as_ser
 	ZeroMemory(&si, sizeof(si));
 	si.cb = sizeof(si);
 
+	/*
+	 * Set stdin/stdout/stderr handles to be inherited in the child
+	 * process. That allows postmaster and the processes it starts to perform
+	 * additional checks to see if running in a service (otherwise they get
+	 * the default console handles - which point to "somewhere").
+	 */
+	InheritStdHandles(&si);
+
 	Advapi32Handle = LoadLibrary("ADVAPI32.DLL");
 	if (Advapi32Handle != NULL)
 	{
-- 
2.29.2.540.g3cf59784d4


--pm3lfdw7knjptu4k--





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* TAP output format in pg_regress
@ 2022-02-21 23:08  Daniel Gustafsson <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Daniel Gustafsson @ 2022-02-21 23:08 UTC (permalink / raw)
  To: PostgreSQL Developers <[email protected]>; Andres Freund <[email protected]>

Starting a new thread on the TAP patch from the "[RFC] building postgres with
meson" thread at [email protected] to have
somewhere to discuss this patch.

> On 21 Feb 2022, at 17:52, Andres Freund <[email protected]> wrote:
> On 2021-10-13 13:54:10 +0200, Daniel Gustafsson wrote:

>> I added a --tap option for TAP output to pg_regress together with Jinbao Chen
>> for giggles and killing some time a while back.
> 
> Sorry for not replying to this earlier. I somehow thought I had, but the
> archives disagree.

No worries, I had forgotten about it myself.

> I think this would be great.

Cool, I'll pick it up again then.  I didn't have time to dig into the patch
tonight but the attached is a rebased version which just cleans up the bitrot
it had accumulated to the point where it at least compiles and seems to run.

>> One thing that came out of this, is that we don't really handle the ignored
>> tests in the way the code thinks it does for normal output, the attached treats
>> ignored tests as SKIP tests.
> 
> I can't really parse the first sentence...

I admittedly don't remember exactly what I meant, but I'm fairly sure it's
wrong.  I think I thought ignored tests were counted incorrectly, but skimming
the patch just now I think it's doing it wrong as it counts ignored as failed
even if they passed.  I'll fix that.

>> 	if (exit_status != 0)
>> 		log_child_failure(exit_status);
>> @@ -2152,6 +2413,7 @@ regression_main(int argc, char *argv[],
>> 		{"config-auth", required_argument, NULL, 24},
>> 		{"max-concurrent-tests", required_argument, NULL, 25},
>> 		{"make-testtablespace-dir", no_argument, NULL, 26},
>> +		{"tap", no_argument, NULL, 27},
>> 		{NULL, 0, NULL, 0}
>> 	};
> 
> I'd make it a --format=(regress|tap) or such.

That makes sense, done in the attached.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v2-0001-pg_regress-TAP-output-format.patch (15.3K, ../../[email protected]/2-v2-0001-pg_regress-TAP-output-format.patch)
  download | inline diff:
From f31d962c1d1101b7d90ab1956e18b4c94eda63b8 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Fri, 18 Feb 2022 15:13:54 +0100
Subject: [PATCH v2] pg_regress TAP output format

---
 src/test/regress/pg_regress.c | 396 +++++++++++++++++++++++++++-------
 1 file changed, 317 insertions(+), 79 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index e6f71c7582..81f3bb7bab 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -95,6 +95,8 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static char *format = NULL;
+static char *psql_formatting = NULL;
 
 /* internal variables */
 static const char *progname;
@@ -120,11 +122,73 @@ static int	fail_ignore_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);
+struct output_func
+{
+	void (*header)(const char *line);
+	void (*footer)(const char *difffilename, const char *logfilename);
+	void (*comment)(const char *comment);
+
+	void (*test_status_preamble)(const char *testname);
+
+	void (*test_status_ok)(const char *testname);
+	void (*test_status_failed)(const char *testname);
+	void (*test_status_ignored)(const char *testname);
+
+	void (*test_runtime)(const char *testname, double runtime);
+};
+
+
+void (*test_runtime)(const char *testname, double runtime);
+/* Text output format */
+static void header_text(const char *line);
+static void footer_text(const char *difffilename, const char *logfilename);
+static void comment_text(const char *comment);
+static void test_status_preamble_text(const char *testname);
+static void test_status_ok_text(const char *testname);
+static void test_status_failed_text(const char *testname);
+static void test_runtime_text(const char *testname, double runtime);
+
+struct output_func output_func_text =
+{
+	header_text,
+	footer_text,
+	comment_text,
+	test_status_preamble_text,
+	test_status_ok_text,
+	test_status_failed_text,
+	NULL,
+	test_runtime_text
+};
+
+/* TAP output format */
+static void header_tap(const char *line);
+static void footer_tap(const char *difffilename, const char *logfilename);
+static void comment_tap(const char *comment);
+static void test_status_ok_tap(const char *testname);
+static void test_status_failed_tap(const char *testname);
+static void test_status_ignored_tap(const char *testname);
+
+struct output_func output_func_tap =
+{
+	header_tap,
+	footer_tap,
+	comment_tap,
+	NULL,
+	test_status_ok_tap,
+	test_status_failed_tap,
+	test_status_ignored_tap,
+	NULL
+};
+
+struct output_func *output = &output_func_text;
+
+static void test_status_ok(const char *testname);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -208,18 +272,214 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 /*
  * Print a progress banner on stdout.
  */
+static void
+header_text(const char *line)
+{
+	fprintf(stdout, "============== %-38s ==============\n", line);
+	fflush(stdout);
+}
+
+static void
+header_tap(const char *line)
+{
+	fprintf(stdout, "# %s\n", line);
+	fflush(stdout);
+}
+
 static void
 header(const char *fmt,...)
 {
 	char		tmp[64];
 	va_list		ap;
 
+	if (!output->header)
+		return;
+
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	output->header(tmp);
+}
+
+static void
+footer_tap(const char *difffilename, const char *logfilename)
+{
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
+	status_end();
+}
+
+static void
+footer(const char *difffilename, const char *logfilename)
+{
+	if (output->footer)
+		output->footer(difffilename, logfilename);
+}
+
+static void
+comment_text(const char *comment)
+{
+	status("%s", comment);
+}
+
+static void
+comment_tap(const char *comment)
+{
+	status("# %s", comment);
+}
+
+static void
+comment(const char *fmt,...)
+{
+	char		tmp[256];
+	va_list		ap;
+
+	if (!output->comment)
+		return;
+
+	va_start(ap, fmt);
+	vsnprintf(tmp, sizeof(tmp), fmt, ap);
+	va_end(ap);
+
+	output->comment(tmp);
+}
+
+static void
+test_status_preamble_text(const char *testname)
+{
+	status(_("test %-28s ... "), testname);
+}
+
+static void
+test_status_preamble(const char *testname)
+{
+	if (output->test_status_preamble)
+		output->test_status_preamble(testname);
+}
+
+static void
+test_status_ok_tap(const char *testname)
+{
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %i - %s",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_status_ok_text(const char *testname)
+{
+	(void) testname; /* unused */
+	status(_("ok    "));	/* align with FAILED */
+}
+
+static void
+test_status_ok(const char *testname)
+{
+	success_count++;
+	if (output->test_status_ok)
+		output->test_status_ok(testname);
+}
+
+static void
+test_status_failed_tap(const char *testname)
+{
+	status("not ok %i - %s",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_status_failed_text(const char *testname)
+{
+	status(_("FAILED"));
+}
+
+static void
+test_status_failed(const char *testname)
+{
+	fail_count++;
+	if (output->test_status_failed)
+		output->test_status_failed(testname);
+}
+
+static void
+test_status_ignored(const char *testname)
+{
+	fail_ignore_count++;
+	if (output->test_status_ignored)
+		output->test_status_ignored(testname);
+}
+
+static void
+test_status_ignored_tap(const char *testname)
+{
+	status("ok %i - %s # SKIP (ignored)",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_runtime_text(const char *testname, double runtime)
+{
+	(void)testname;
+	status(_(" %8.0f ms"), runtime);
+}
+
+static void
+runtime(const char *testname, double runtime)
+{
+	if (output->test_runtime)
+		output->test_runtime(testname, runtime);
+}
+
+static void
+footer_text(const char *difffilename, const char *logfilename)
+{
+	char buf[256];
+
+	/*
+	 * Emit nice-looking summary message
+	 */
+	if (fail_count == 0 && fail_ignore_count == 0)
+		snprintf(buf, sizeof(buf),
+				 _(" All %d tests passed. "),
+				 success_count);
+	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
+				 success_count,
+				 success_count + fail_ignore_count,
+				 fail_ignore_count);
+	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed. "),
+				 fail_count,
+				 success_count + fail_count);
+	else
+		/* fail_count>0 && fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed, %d of these failures ignored. "),
+				 fail_count + fail_ignore_count,
+				 success_count + fail_count + fail_ignore_count,
+				 fail_ignore_count);
+
+	putchar('\n');
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	printf("\n%s\n", buf);
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	putchar('\n');
+	putchar('\n');
+
+	if (difffilename && logfilename)
+	{
+		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);
+	}
 }
 
 /*
@@ -752,13 +1012,13 @@ initialize_environment(void)
 #endif
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			comment(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			comment(_("(using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			comment(_("(using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			comment(_("(using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -984,9 +1244,10 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X %s",
 					 bindir ? bindir : "",
-					 bindir ? "/" : "");
+					 bindir ? "/" : "",
+					 psql_formatting ? psql_formatting : "");
 	return buf;
 }
 
@@ -1585,6 +1846,9 @@ run_schedule(const char *schedule, test_start_function startfunc,
 				c++;
 			add_stringlist_item(&ignorelist, c);
 
+			test_status_ignored(c);
+			status_end();
+
 			/*
 			 * Note: ignore: lines do not run the test, they just say that
 			 * failure of this test when run later on is to be ignored. A bit
@@ -1643,7 +1907,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 
 		if (num_tests == 1)
 		{
-			status(_("test %-28s ... "), tests[0]);
+			test_status_preamble(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);
@@ -1659,8 +1923,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		{
 			int			oldest = 0;
 
-			status(_("parallel group (%d tests, in groups of %d): "),
-				   num_tests, max_connections);
+			comment(_("parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1680,7 +1944,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			comment(_("parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1699,7 +1963,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 			bool		differ = false;
 
 			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+				test_status_preamble(tests[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1739,27 +2003,18 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					}
 				}
 				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
+					test_status_ignored(tests[i]);
 				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+					test_status_failed(tests[i]);
 			}
 			else
-			{
-				status(_("ok    "));	/* align with FAILED */
-				success_count++;
-			}
+				test_status_ok(tests[i]);
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
 			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 
 			status_end();
 		}
@@ -1798,7 +2053,7 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *tl;
 	bool		differ = false;
 
-	status(_("test %-28s ... "), test);
+	test_status_preamble(test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
@@ -1828,15 +2083,9 @@ run_single_test(const char *test, test_start_function startfunc,
 	}
 
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
@@ -1983,6 +2232,7 @@ help(void)
 	printf(_("      --debug                   turn on debug mode in programs that are run\n"));
 	printf(_("      --dlpath=DIR              look for dynamic libraries in DIR\n"));
 	printf(_("      --encoding=ENCODING       use ENCODING as the encoding\n"));
+	printf(_("      --format=(regress|tap)    output format to use\n"));
 	printf(_("  -h, --help                    show this help, then exit\n"));
 	printf(_("      --inputdir=DIR            take input files from DIR (default \".\")\n"));
 	printf(_("      --launcher=CMD            use CMD as launcher of psql\n"));
@@ -2046,6 +2296,7 @@ regression_main(int argc, char *argv[],
 		{"load-extension", required_argument, NULL, 22},
 		{"config-auth", required_argument, NULL, 24},
 		{"max-concurrent-tests", required_argument, NULL, 25},
+ 		{"format", required_argument, NULL, 26},
 		{NULL, 0, NULL, 0}
 	};
 
@@ -2175,6 +2426,9 @@ regression_main(int argc, char *argv[],
 			case 25:
 				max_concurrent_tests = atoi(optarg);
 				break;
+			case 26:
+				format = pg_strdup(optarg);
+				break;
 			default:
 				/* getopt_long already emitted a complaint */
 				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
@@ -2201,6 +2455,24 @@ regression_main(int argc, char *argv[],
 		exit(0);
 	}
 
+	/*
+	 * text (regress) is the default so we don't need to set any variables in
+	 * that case.
+	 */
+	if (format)
+	{
+		if (strcmp(format, "tap") == 0)
+		{
+			output = &output_func_tap;
+			psql_formatting = pg_strdup("-q");
+		}
+		else if (strcmp(format, "regress") != 0)
+		{
+			fprintf(stderr, _("\n%s: invalid format specified: \"%s\". Supported formats are \"tap\" and \"regress\"\n"), progname, format);
+			exit(2);
+		}
+	}
+
 	if (temp_instance && !port_specified_by_user)
 
 		/*
@@ -2523,54 +2795,20 @@ regression_main(int argc, char *argv[],
 
 	fclose(logfile);
 
-	/*
-	 * Emit nice-looking summary message
-	 */
-	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
-	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
-
-	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);
-	}
-	else
+	if (file_size(difffilename) <= 0)
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	footer(difffilename, logfilename);
+	status_end();
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.24.3 (Apple Git-128)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-02-22 14:10  Daniel Gustafsson <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  0 siblings, 2 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-02-22 14:10 UTC (permalink / raw)
  To: PostgreSQL Developers <[email protected]>; Andres Freund <[email protected]>

> On 22 Feb 2022, at 00:08, Daniel Gustafsson <[email protected]> wrote:

> I'll fix that.

The attached v3 fixes that thinko, and cleans up a lot of the output which
isn't diagnostic per the TAP spec to make it less noisy.  It also fixes tag
support used in the ECPG tests and a few small cleanups.  There is a blank line
printed which needs to be fixed, but I'm running out of time and wanted to get
a non-broken version on the list before putting it aside for today.

The errorpaths that exit(2) the testrun should be converted to "bail out" lines
when running with TAP output, but apart from that I think it's fairly spec
compliant.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v3-0001-pg_regress-TAP-output-format.patch (17.1K, ../../[email protected]/2-v3-0001-pg_regress-TAP-output-format.patch)
  download | inline diff:
From 800f96a6c50f2b75184c42e417d8cd440b473766 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Fri, 18 Feb 2022 15:13:54 +0100
Subject: [PATCH v3] pg_regress TAP output format

---
 src/test/regress/pg_regress.c | 412 +++++++++++++++++++++++++++-------
 1 file changed, 326 insertions(+), 86 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index e6f71c7582..5853c3668f 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -95,6 +95,8 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static char *format = NULL;
+static char *psql_formatting = NULL;
 
 /* internal variables */
 static const char *progname;
@@ -120,11 +122,68 @@ static int	fail_ignore_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);
+struct output_func
+{
+	void (*header)(const char *line);
+	void (*footer)(const char *difffilename, const char *logfilename);
+	void (*comment)(bool diagnostic, const char *comment);
+
+	void (*test_status_preamble)(const char *testname);
+
+	void (*test_status_ok)(const char *testname);
+	void (*test_status_failed)(const char *testname, bool ignore, char *tags);
+
+	void (*test_runtime)(const char *testname, double runtime);
+};
+
+
+void (*test_runtime)(const char *testname, double runtime);
+/* Text output format */
+static void header_text(const char *line);
+static void footer_text(const char *difffilename, const char *logfilename);
+static void comment_text(bool diagnostic, const char *comment);
+static void test_status_preamble_text(const char *testname);
+static void test_status_ok_text(const char *testname);
+static void test_status_failed_text(const char *testname, bool ignore, char *tags);
+static void test_runtime_text(const char *testname, double runtime);
+
+struct output_func output_func_text =
+{
+	header_text,
+	footer_text,
+	comment_text,
+	test_status_preamble_text,
+	test_status_ok_text,
+	test_status_failed_text,
+	test_runtime_text
+};
+
+/* TAP output format */
+static void footer_tap(const char *difffilename, const char *logfilename);
+static void comment_tap(bool diagnostic, const char *comment);
+static void test_status_ok_tap(const char *testname);
+static void test_status_failed_tap(const char *testname, bool ignore, char *tags);
+
+struct output_func output_func_tap =
+{
+	NULL,
+	footer_tap,
+	comment_tap,
+	NULL,
+	test_status_ok_tap,
+	test_status_failed_tap,
+	NULL
+};
+
+struct output_func *output = &output_func_text;
+
+static void test_status_ok(const char *testname);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -208,18 +267,216 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 /*
  * Print a progress banner on stdout.
  */
+static void
+header_text(const char *line)
+{
+	fprintf(stdout, "============== %-38s ==============\n", line);
+	fflush(stdout);
+}
+
 static void
 header(const char *fmt,...)
 {
 	char		tmp[64];
 	va_list		ap;
 
+	if (!output->header)
+		return;
+
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	output->header(tmp);
+}
+
+static void
+footer_tap(const char *difffilename, const char *logfilename)
+{
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
+	status_end();
+}
+
+static void
+footer(const char *difffilename, const char *logfilename)
+{
+	if (output->footer)
+		output->footer(difffilename, logfilename);
+}
+
+static void
+comment_text(bool diagnostic, const char *comment)
+{
+	status("%s", comment);
+}
+
+static void
+comment_tap(bool diagnostic, const char *comment)
+{
+	if (!diagnostic)
+		return;
+
+	status("# %s", comment);
+}
+
+static void
+comment(bool diagnostic, const char *fmt,...)
+{
+	char		tmp[256];
+	va_list		ap;
+
+	if (!output->comment)
+		return;
+
+	va_start(ap, fmt);
+	vsnprintf(tmp, sizeof(tmp), fmt, ap);
+	va_end(ap);
+
+	output->comment(diagnostic, tmp);
+}
+
+static void
+test_status_preamble_text(const char *testname)
+{
+	status(_("test %-28s ... "), testname);
+}
+
+static void
+test_status_preamble(const char *testname)
+{
+	if (output->test_status_preamble)
+		output->test_status_preamble(testname);
+}
+
+static void
+test_status_ok_tap(const char *testname)
+{
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %i - %s",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_status_ok_text(const char *testname)
+{
+	(void) testname; /* unused */
+	status(_("ok    "));	/* align with FAILED */
+}
+
+static void
+test_status_ok(const char *testname)
+{
+	success_count++;
+	if (output->test_status_ok)
+		output->test_status_ok(testname);
+}
+
+static void
+test_status_failed_tap(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+	{
+		status("ok %i - %s ",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+		comment(true, "SKIP (ignored)");
+	}
+	else
+		status("not ok %i - %s",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+
+	if (tags && strlen(tags) > 0)
+	{
+		fprintf(stdout, "\n");
+		comment(true, tags);
+	}
+}
+
+
+static void
+test_status_failed_text(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+		status(_("%s failed (ignored)"), tags);
+	else
+		status(_("%s FAILED"), tags);
+}
+
+static void
+test_status_failed(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	if (output->test_status_failed)
+		output->test_status_failed(testname, ignore, tags);
+}
+
+static void
+test_runtime_text(const char *testname, double runtime)
+{
+	(void)testname;
+	status(_(" %8.0f ms"), runtime);
+}
+
+static void
+runtime(const char *testname, double runtime)
+{
+	if (output->test_runtime)
+		output->test_runtime(testname, runtime);
+}
+
+static void
+footer_text(const char *difffilename, const char *logfilename)
+{
+	char buf[256];
+
+	/*
+	 * Emit nice-looking summary message
+	 */
+	if (fail_count == 0 && fail_ignore_count == 0)
+		snprintf(buf, sizeof(buf),
+				 _(" All %d tests passed. "),
+				 success_count);
+	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
+				 success_count,
+				 success_count + fail_ignore_count,
+				 fail_ignore_count);
+	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed. "),
+				 fail_count,
+				 success_count + fail_count);
+	else
+		/* fail_count>0 && fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed, %d of these failures ignored. "),
+				 fail_count + fail_ignore_count,
+				 success_count + fail_count + fail_ignore_count,
+				 fail_ignore_count);
+
+	putchar('\n');
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	printf("\n%s\n", buf);
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	putchar('\n');
+	putchar('\n');
+
+	if (difffilename && logfilename)
+	{
+		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);
+	}
 }
 
 /*
@@ -752,13 +1009,13 @@ initialize_environment(void)
 #endif
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			comment(false, _("(using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			comment(false, _("(using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			comment(false, _("(using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			comment(false, _("(using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -984,9 +1241,10 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X %s",
 					 bindir ? bindir : "",
-					 bindir ? "/" : "");
+					 bindir ? "/" : "",
+					 psql_formatting ? psql_formatting : "");
 	return buf;
 }
 
@@ -1489,7 +1747,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]);
+					comment(false, " %s", names[i]);
 				tests_left--;
 				break;
 			}
@@ -1545,12 +1803,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	scf = fopen(schedule, "r");
 	if (!scf)
 	{
@@ -1643,7 +1904,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 
 		if (num_tests == 1)
 		{
-			status(_("test %-28s ... "), tests[0]);
+			test_status_preamble(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);
@@ -1659,8 +1920,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		{
 			int			oldest = 0;
 
-			status(_("parallel group (%d tests, in groups of %d): "),
-				   num_tests, max_connections);
+			comment(false, _("parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1680,7 +1941,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			comment(false, _("parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1698,8 +1959,10 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
+			resetStringInfo(&tagbuf);
+
 			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+				test_status_preamble(tests[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1720,7 +1983,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1738,28 +2001,17 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data);
 			}
 			else
-			{
-				status(_("ok    "));	/* align with FAILED */
-				success_count++;
-			}
+				test_status_ok(tests[i]);
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
 			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 
 			status_end();
 		}
@@ -1774,6 +2026,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1797,11 +2050,13 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
+	test_status_preamble(test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1822,27 +2077,23 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
 	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	runtime(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1983,6 +2234,7 @@ help(void)
 	printf(_("      --debug                   turn on debug mode in programs that are run\n"));
 	printf(_("      --dlpath=DIR              look for dynamic libraries in DIR\n"));
 	printf(_("      --encoding=ENCODING       use ENCODING as the encoding\n"));
+	printf(_("      --format=(regress|tap)    output format to use\n"));
 	printf(_("  -h, --help                    show this help, then exit\n"));
 	printf(_("      --inputdir=DIR            take input files from DIR (default \".\")\n"));
 	printf(_("      --launcher=CMD            use CMD as launcher of psql\n"));
@@ -2046,6 +2298,7 @@ regression_main(int argc, char *argv[],
 		{"load-extension", required_argument, NULL, 22},
 		{"config-auth", required_argument, NULL, 24},
 		{"max-concurrent-tests", required_argument, NULL, 25},
+ 		{"format", required_argument, NULL, 26},
 		{NULL, 0, NULL, 0}
 	};
 
@@ -2175,6 +2428,9 @@ regression_main(int argc, char *argv[],
 			case 25:
 				max_concurrent_tests = atoi(optarg);
 				break;
+			case 26:
+				format = pg_strdup(optarg);
+				break;
 			default:
 				/* getopt_long already emitted a complaint */
 				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
@@ -2201,6 +2457,24 @@ regression_main(int argc, char *argv[],
 		exit(0);
 	}
 
+	/*
+	 * text (regress) is the default so we don't need to set any variables in
+	 * that case.
+	 */
+	if (format)
+	{
+		if (strcmp(format, "tap") == 0)
+		{
+			output = &output_func_tap;
+			psql_formatting = pg_strdup("-q");
+		}
+		else if (strcmp(format, "regress") != 0)
+		{
+			fprintf(stderr, _("\n%s: invalid format specified: \"%s\". Supported formats are \"tap\" and \"regress\"\n"), progname, format);
+			exit(2);
+		}
+	}
+
 	if (temp_instance && !port_specified_by_user)
 
 		/*
@@ -2455,7 +2729,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		comment(false, _("running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2523,54 +2797,20 @@ regression_main(int argc, char *argv[],
 
 	fclose(logfile);
 
-	/*
-	 * Emit nice-looking summary message
-	 */
-	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
-	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
-
-	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);
-	}
-	else
+	if (file_size(difffilename) <= 0)
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	footer(difffilename, logfilename);
+	status_end();
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.24.3 (Apple Git-128)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-02-22 17:13  Andres Freund <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  1 sibling, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-02-22 17:13 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

Hi,

Thanks for the updated version!

On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:
> The errorpaths that exit(2) the testrun should be converted to "bail out" lines
> when running with TAP output, but apart from that I think it's fairly spec
> compliant.

I'd much rather not use BAIL - I haven't gotten around to doing anything about
it, but I really want to get rid of nearly all our uses of bail:

https://www.postgresql.org/message-id/20220213232249.7sevhlioapydla37%40alap3.anarazel.de

Greetings,

Andres Freund






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-02-22 21:04  Daniel Gustafsson <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 0 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-02-22 21:04 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

> On 22 Feb 2022, at 18:13, Andres Freund <[email protected]> wrote:
> On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:

>> The errorpaths that exit(2) the testrun should be converted to "bail out" lines
>> when running with TAP output, but apart from that I think it's fairly spec
>> compliant.
> 
> I'd much rather not use BAIL - I haven't gotten around to doing anything about
> it, but I really want to get rid of nearly all our uses of bail:

Point.  We already error out on stderr in pg_regress so we could probably make
die() equivalent output to keep the TAP parsing consistent.  At any rate,
awaiting the conclusions on the bail thread and simply (for some value of)
replicating that in this patch is probably the best option?

--
Daniel Gustafsson		https://vmware.com/







^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-03-21 23:49  Andres Freund <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  1 sibling, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-03-21 23:49 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

Hi,

On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:
> > On 22 Feb 2022, at 00:08, Daniel Gustafsson <[email protected]> wrote:
> 
> > I'll fix that.
> 
> The attached v3 fixes that thinko, and cleans up a lot of the output which
> isn't diagnostic per the TAP spec to make it less noisy.  It also fixes tag
> support used in the ECPG tests and a few small cleanups.  There is a blank line
> printed which needs to be fixed, but I'm running out of time and wanted to get
> a non-broken version on the list before putting it aside for today.
> 
> The errorpaths that exit(2) the testrun should be converted to "bail out" lines
> when running with TAP output, but apart from that I think it's fairly spec
> compliant.

This is failing with segmentation faults on cfbot:
https://cirrus-ci.com/task/4879227009892352?logs=test_world#L21

Looks like something around isolationtester is broken?

Unfortunately there's no useful backtraces for isolationtester. Not sure
what's up there.


Seems like we might not have energy to push this forward in the next two
weeks, so maybe the CF entry should be marked returned or moved for now?

Greetings,

Andres Freund






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-03-24 12:44  Daniel Gustafsson <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Daniel Gustafsson @ 2022-03-24 12:44 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

> On 22 Mar 2022, at 00:49, Andres Freund <[email protected]> wrote:

> This is failing with segmentation faults on cfbot:
> https://cirrus-ci.com/task/4879227009892352?logs=test_world#L21
> 
> Looks like something around isolationtester is broken?

It could be triggered by plpgsql tests as well, and was (as usual) a silly
mistake easily fixed when found.  The attached survices repeated check-world
for me.

> Seems like we might not have energy to push this forward in the next two
> weeks, so maybe the CF entry should be marked returned or moved for now?

Since there is little use for this without the Meson branch, it should target
the same version as that patch. I'll move the patch to the next CF for now.

As we discussed off-list I extended this patchset with an attempt to minimize
noise as per [email protected], but it's not
yet done.  The attached has a rough draft of adding a --verbose option which
gives the current output (and potentially more for debugging), but which by
default is off producing minimal noise.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v4-0002-Reduce-noise-in-pg_regress-default-output.patch (10.3K, ../../[email protected]/2-v4-0002-Reduce-noise-in-pg_regress-default-output.patch)
  download | inline diff:
From a208d3f8d7ccd6dd7a012019ab13f41e61cb3ab0 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Fri, 4 Mar 2022 11:54:00 +0100
Subject: [PATCH v4 2/2] Reduce noise in pg_regress default output

A first stab at adding a --verbose flag to pg_regress to reduce the
amount of noise printed during a test run.
---
 src/test/regress/pg_regress.c | 106 ++++++++++++++++++++++------------
 1 file changed, 69 insertions(+), 37 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index dbf646d5ec..82109fed84 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -74,6 +74,7 @@ const char *pretty_diff_opts = "-w -U3";
 /* options settable from command line */
 _stringlist *dblist = NULL;
 bool		debug = false;
+bool		verbose = false;
 char	   *inputdir = ".";
 char	   *outputdir = ".";
 char	   *bindir = PGBINDIR;
@@ -122,11 +123,17 @@ static int	fail_ignore_count = 0;
 static bool directory_exists(const char *dir);
 static void make_directory(const char *dir);
 
+typedef enum
+{
+	COMMENT_DIAGNOSTIC,
+	COMMENT_VERBOSE
+}			CommentLevel;
+
 struct output_func
 {
 	void (*header)(const char *line);
 	void (*footer)(const char *difffilename, const char *logfilename);
-	void (*comment)(bool diagnostic, const char *comment);
+	void (*comment)(CommentLevel level, const char *comment);
 
 	void (*test_status_preamble)(const char *testname);
 
@@ -141,7 +148,7 @@ void (*test_runtime)(const char *testname, double runtime);
 /* Text output format */
 static void header_text(const char *line);
 static void footer_text(const char *difffilename, const char *logfilename);
-static void comment_text(bool diagnostic, const char *comment);
+static void comment_text(CommentLevel level, const char *comment);
 static void test_status_preamble_text(const char *testname);
 static void test_status_ok_text(const char *testname);
 static void test_status_failed_text(const char *testname, bool ignore, char *tags);
@@ -160,7 +167,7 @@ struct output_func output_func_text =
 
 /* TAP output format */
 static void footer_tap(const char *difffilename, const char *logfilename);
-static void comment_tap(bool diagnostic, const char *comment);
+static void comment_tap(CommentLevel level, const char *comment);
 static void test_status_ok_tap(const char *testname);
 static void test_status_failed_tap(const char *testname, bool ignore, char *tags);
 
@@ -270,6 +277,9 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 static void
 header_text(const char *line)
 {
+	if (!verbose)
+		return;
+
 	fprintf(stdout, "============== %-38s ==============\n", line);
 	fflush(stdout);
 }
@@ -305,22 +315,25 @@ footer(const char *difffilename, const char *logfilename)
 }
 
 static void
-comment_text(bool diagnostic, const char *comment)
+comment_text(CommentLevel level, const char *comment)
 {
+	if (level == COMMENT_VERBOSE && !verbose)
+		return;
+
 	status("%s", comment);
 }
 
 static void
-comment_tap(bool diagnostic, const char *comment)
+comment_tap(CommentLevel level, const char *comment)
 {
-	if (!diagnostic)
+	if (level != COMMENT_DIAGNOSTIC)
 		return;
 
 	status("# %s", comment);
 }
 
 static void
-comment(bool diagnostic, const char *fmt,...)
+comment(CommentLevel level, const char *fmt,...)
 {
 	char		tmp[256];
 	va_list		ap;
@@ -332,7 +345,7 @@ comment(bool diagnostic, const char *fmt,...)
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	output->comment(diagnostic, tmp);
+	output->comment(level, tmp);
 }
 
 static void
@@ -380,7 +393,7 @@ test_status_failed_tap(const char *testname, bool ignore, char *tags)
 		status("ok %i - %s ",
 			   (fail_count + fail_ignore_count + success_count),
 			   testname);
-		comment(true, "SKIP (ignored)");
+		comment(COMMENT_DIAGNOSTIC, "SKIP (ignored)");
 	}
 	else
 		status("not ok %i - %s",
@@ -390,7 +403,7 @@ test_status_failed_tap(const char *testname, bool ignore, char *tags)
 	if (tags && strlen(tags) > 0)
 	{
 		fprintf(stdout, "\n");
-		comment(true, tags);
+		comment(COMMENT_DIAGNOSTIC, tags);
 	}
 }
 
@@ -440,42 +453,52 @@ footer_text(const char *difffilename, const char *logfilename)
 	 */
 	if (fail_count == 0 && fail_ignore_count == 0)
 		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
+				 _("All %d tests passed. "),
 				 success_count);
 	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
 		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
+				 _("%d of %d tests passed, %d failed test(s) ignored. "),
 				 success_count,
 				 success_count + fail_ignore_count,
 				 fail_ignore_count);
 	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
 		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
+				 _("%d of %d tests failed. "),
 				 fail_count,
 				 success_count + fail_count);
 	else
 		/* fail_count>0 && fail_ignore_count>0 */
 		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
+				 _("%d of %d tests failed, %d of these failures ignored. "),
 				 fail_count + fail_ignore_count,
 				 success_count + fail_count + fail_ignore_count,
 				 fail_ignore_count);
 
-	putchar('\n');
-	for (int i = strlen(buf); i > 0; i--)
-		putchar('=');
-	printf("\n%s\n", buf);
-	for (int i = strlen(buf); i > 0; i--)
-		putchar('=');
-	putchar('\n');
-	putchar('\n');
+	if (verbose)
+	{
+		putchar('\n');
+		for (int i = strlen(buf); i > 0; i--)
+			putchar('=');
+		printf("\n %s\n", buf);
+		for (int i = strlen(buf); i > 0; i--)
+			putchar('=');
+		putchar('\n');
+		putchar('\n');
 
-	if (difffilename && logfilename)
+		if (difffilename && logfilename)
+		{
+			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);
+		}
+	}
+	else
 	{
-		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);
+		printf("\n%s\n", buf);
+		if (difffilename && logfilename)
+			printf(_("Failing diffs: \"%s\"\nTest summary: \"%s\"\n"),
+					difffilename, logfilename);
 	}
 }
 
@@ -1015,13 +1038,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			comment(false, _("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			comment(COMMENT_VERBOSE, _("(using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			comment(false, _("(using postmaster on %s, default port)\n"), pghost);
+			comment(COMMENT_VERBOSE, _("(using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			comment(false, _("(using postmaster on Unix socket, port %s)\n"), pgport);
+			comment(COMMENT_VERBOSE, _("(using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			comment(false, _("(using postmaster on Unix socket, default port)\n"));
+			comment(COMMENT_VERBOSE, _("(using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -1753,7 +1776,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)
-					comment(false, " %s", names[i]);
+					comment(COMMENT_VERBOSE, " %s", names[i]);
 				tests_left--;
 				break;
 			}
@@ -1926,7 +1949,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		{
 			int			oldest = 0;
 
-			comment(false, _("parallel group (%d tests, in groups of %d): "),
+			comment(COMMENT_VERBOSE, _("parallel group (%d tests, in groups of %d): "),
 					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
@@ -1947,7 +1970,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			comment(false, _("parallel group (%d tests): "), num_tests);
+			comment(COMMENT_VERBOSE, _("parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -2255,6 +2278,7 @@ help(void)
 	printf(_("                                (can be used multiple times to concatenate)\n"));
 	printf(_("      --temp-instance=DIR       create a temporary instance in DIR\n"));
 	printf(_("      --use-existing            use an existing installation\n"));
+	printf(_("  -v, --verbose                 verbose output, only applies to regress output format\n"));
 	printf(_("  -V, --version                 output version information, then exit\n"));
 	printf(_("\n"));
 	printf(_("Options for \"temp-instance\" mode:\n"));
@@ -2283,6 +2307,7 @@ regression_main(int argc, char *argv[],
 	static struct option long_options[] = {
 		{"help", no_argument, NULL, 'h'},
 		{"version", no_argument, NULL, 'V'},
+		{"verbose", no_argument, NULL, 'v'},
 		{"dbname", required_argument, NULL, 1},
 		{"debug", no_argument, NULL, 2},
 		{"inputdir", required_argument, NULL, 3},
@@ -2350,7 +2375,7 @@ regression_main(int argc, char *argv[],
 	if (getenv("PG_REGRESS_DIFF_OPTS"))
 		pretty_diff_opts = getenv("PG_REGRESS_DIFF_OPTS");
 
-	while ((c = getopt_long(argc, argv, "hV", long_options, &option_index)) != -1)
+	while ((c = getopt_long(argc, argv, "hVv", long_options, &option_index)) != -1)
 	{
 		switch (c)
 		{
@@ -2360,6 +2385,9 @@ regression_main(int argc, char *argv[],
 			case 'V':
 				puts("pg_regress (PostgreSQL) " PG_VERSION);
 				exit(0);
+			case 'v':
+				verbose = true;
+				break;
 			case 1:
 
 				/*
@@ -2463,6 +2491,9 @@ regression_main(int argc, char *argv[],
 		exit(0);
 	}
 
+	if (!verbose)
+		psql_formatting = pg_strdup("-q");
+
 	/*
 	 * text (regress) is the default so we don't need to set any variables in
 	 * that case.
@@ -2472,7 +2503,8 @@ regression_main(int argc, char *argv[],
 		if (strcmp(format, "tap") == 0)
 		{
 			output = &output_func_tap;
-			psql_formatting = pg_strdup("-q");
+			if (!psql_formatting)
+				psql_formatting = pg_strdup("-q");
 		}
 		else if (strcmp(format, "regress") != 0)
 		{
@@ -2735,7 +2767,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		comment(false, _("running on port %d with PID %lu\n"),
+		comment(COMMENT_VERBOSE, _("running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
-- 
2.24.3 (Apple Git-128)



  [application/octet-stream] v4-0001-pg_regress-TAP-output-format.patch (17.1K, ../../[email protected]/3-v4-0001-pg_regress-TAP-output-format.patch)
  download | inline diff:
From 6dee6ba8ae2b3917cd9e7a49676cc69dd8f9d455 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Fri, 18 Feb 2022 15:13:54 +0100
Subject: [PATCH v4 1/2] pg_regress TAP output format

---
 src/test/regress/pg_regress.c | 413 +++++++++++++++++++++++++++-------
 1 file changed, 327 insertions(+), 86 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 982801e029..dbf646d5ec 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -95,6 +95,8 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static char *format = NULL;
+static char *psql_formatting = NULL;
 
 /* internal variables */
 static const char *progname;
@@ -120,11 +122,68 @@ static int	fail_ignore_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);
+struct output_func
+{
+	void (*header)(const char *line);
+	void (*footer)(const char *difffilename, const char *logfilename);
+	void (*comment)(bool diagnostic, const char *comment);
+
+	void (*test_status_preamble)(const char *testname);
+
+	void (*test_status_ok)(const char *testname);
+	void (*test_status_failed)(const char *testname, bool ignore, char *tags);
+
+	void (*test_runtime)(const char *testname, double runtime);
+};
+
+
+void (*test_runtime)(const char *testname, double runtime);
+/* Text output format */
+static void header_text(const char *line);
+static void footer_text(const char *difffilename, const char *logfilename);
+static void comment_text(bool diagnostic, const char *comment);
+static void test_status_preamble_text(const char *testname);
+static void test_status_ok_text(const char *testname);
+static void test_status_failed_text(const char *testname, bool ignore, char *tags);
+static void test_runtime_text(const char *testname, double runtime);
+
+struct output_func output_func_text =
+{
+	header_text,
+	footer_text,
+	comment_text,
+	test_status_preamble_text,
+	test_status_ok_text,
+	test_status_failed_text,
+	test_runtime_text
+};
+
+/* TAP output format */
+static void footer_tap(const char *difffilename, const char *logfilename);
+static void comment_tap(bool diagnostic, const char *comment);
+static void test_status_ok_tap(const char *testname);
+static void test_status_failed_tap(const char *testname, bool ignore, char *tags);
+
+struct output_func output_func_tap =
+{
+	NULL,
+	footer_tap,
+	comment_tap,
+	NULL,
+	test_status_ok_tap,
+	test_status_failed_tap,
+	NULL
+};
+
+struct output_func *output = &output_func_text;
+
+static void test_status_ok(const char *testname);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -208,18 +267,216 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 /*
  * Print a progress banner on stdout.
  */
+static void
+header_text(const char *line)
+{
+	fprintf(stdout, "============== %-38s ==============\n", line);
+	fflush(stdout);
+}
+
 static void
 header(const char *fmt,...)
 {
 	char		tmp[64];
 	va_list		ap;
 
+	if (!output->header)
+		return;
+
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	output->header(tmp);
+}
+
+static void
+footer_tap(const char *difffilename, const char *logfilename)
+{
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
+	status_end();
+}
+
+static void
+footer(const char *difffilename, const char *logfilename)
+{
+	if (output->footer)
+		output->footer(difffilename, logfilename);
+}
+
+static void
+comment_text(bool diagnostic, const char *comment)
+{
+	status("%s", comment);
+}
+
+static void
+comment_tap(bool diagnostic, const char *comment)
+{
+	if (!diagnostic)
+		return;
+
+	status("# %s", comment);
+}
+
+static void
+comment(bool diagnostic, const char *fmt,...)
+{
+	char		tmp[256];
+	va_list		ap;
+
+	if (!output->comment)
+		return;
+
+	va_start(ap, fmt);
+	vsnprintf(tmp, sizeof(tmp), fmt, ap);
+	va_end(ap);
+
+	output->comment(diagnostic, tmp);
+}
+
+static void
+test_status_preamble_text(const char *testname)
+{
+	status(_("test %-28s ... "), testname);
+}
+
+static void
+test_status_preamble(const char *testname)
+{
+	if (output->test_status_preamble)
+		output->test_status_preamble(testname);
+}
+
+static void
+test_status_ok_tap(const char *testname)
+{
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %i - %s",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_status_ok_text(const char *testname)
+{
+	(void) testname; /* unused */
+	status(_("ok    "));	/* align with FAILED */
+}
+
+static void
+test_status_ok(const char *testname)
+{
+	success_count++;
+	if (output->test_status_ok)
+		output->test_status_ok(testname);
+}
+
+static void
+test_status_failed_tap(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+	{
+		status("ok %i - %s ",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+		comment(true, "SKIP (ignored)");
+	}
+	else
+		status("not ok %i - %s",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+
+	if (tags && strlen(tags) > 0)
+	{
+		fprintf(stdout, "\n");
+		comment(true, tags);
+	}
+}
+
+
+static void
+test_status_failed_text(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+		status(_("%s failed (ignored)"), tags);
+	else
+		status(_("%s FAILED"), tags);
+}
+
+static void
+test_status_failed(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	if (output->test_status_failed)
+		output->test_status_failed(testname, ignore, tags);
+}
+
+static void
+test_runtime_text(const char *testname, double runtime)
+{
+	(void)testname;
+	status(_(" %8.0f ms"), runtime);
+}
+
+static void
+runtime(const char *testname, double runtime)
+{
+	if (output->test_runtime)
+		output->test_runtime(testname, runtime);
+}
+
+static void
+footer_text(const char *difffilename, const char *logfilename)
+{
+	char buf[256];
+
+	/*
+	 * Emit nice-looking summary message
+	 */
+	if (fail_count == 0 && fail_ignore_count == 0)
+		snprintf(buf, sizeof(buf),
+				 _(" All %d tests passed. "),
+				 success_count);
+	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
+				 success_count,
+				 success_count + fail_ignore_count,
+				 fail_ignore_count);
+	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed. "),
+				 fail_count,
+				 success_count + fail_count);
+	else
+		/* fail_count>0 && fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _(" %d of %d tests failed, %d of these failures ignored. "),
+				 fail_count + fail_ignore_count,
+				 success_count + fail_count + fail_ignore_count,
+				 fail_ignore_count);
+
+	putchar('\n');
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	printf("\n%s\n", buf);
+	for (int i = strlen(buf); i > 0; i--)
+		putchar('=');
+	putchar('\n');
+	putchar('\n');
+
+	if (difffilename && logfilename)
+	{
+		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);
+	}
 }
 
 /*
@@ -758,13 +1015,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			comment(false, _("(using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			comment(false, _("(using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			comment(false, _("(using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			comment(false, _("(using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -990,9 +1247,10 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X %s",
 					 bindir ? bindir : "",
-					 bindir ? "/" : "");
+					 bindir ? "/" : "",
+					 psql_formatting ? psql_formatting : "");
 	return buf;
 }
 
@@ -1495,7 +1753,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]);
+					comment(false, " %s", names[i]);
 				tests_left--;
 				break;
 			}
@@ -1551,12 +1809,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	scf = fopen(schedule, "r");
 	if (!scf)
 	{
@@ -1649,7 +1910,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 
 		if (num_tests == 1)
 		{
-			status(_("test %-28s ... "), tests[0]);
+			test_status_preamble(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);
@@ -1665,8 +1926,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		{
 			int			oldest = 0;
 
-			status(_("parallel group (%d tests, in groups of %d): "),
-				   num_tests, max_connections);
+			comment(false, _("parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1686,7 +1947,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			comment(false, _("parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1704,8 +1965,10 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
+			resetStringInfo(&tagbuf);
+
 			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+				test_status_preamble(tests[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1726,7 +1989,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1744,28 +2007,17 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data);
 			}
 			else
-			{
-				status(_("ok    "));	/* align with FAILED */
-				success_count++;
-			}
+				test_status_ok(tests[i]);
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
 			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 
 			status_end();
 		}
@@ -1780,6 +2032,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1803,11 +2056,13 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
+	test_status_preamble(test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1828,27 +2083,23 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
 	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	runtime(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1989,6 +2240,7 @@ help(void)
 	printf(_("      --debug                   turn on debug mode in programs that are run\n"));
 	printf(_("      --dlpath=DIR              look for dynamic libraries in DIR\n"));
 	printf(_("      --encoding=ENCODING       use ENCODING as the encoding\n"));
+	printf(_("      --format=(regress|tap)    output format to use\n"));
 	printf(_("  -h, --help                    show this help, then exit\n"));
 	printf(_("      --inputdir=DIR            take input files from DIR (default \".\")\n"));
 	printf(_("      --launcher=CMD            use CMD as launcher of psql\n"));
@@ -2052,6 +2304,7 @@ regression_main(int argc, char *argv[],
 		{"load-extension", required_argument, NULL, 22},
 		{"config-auth", required_argument, NULL, 24},
 		{"max-concurrent-tests", required_argument, NULL, 25},
+ 		{"format", required_argument, NULL, 26},
 		{NULL, 0, NULL, 0}
 	};
 
@@ -2181,6 +2434,9 @@ regression_main(int argc, char *argv[],
 			case 25:
 				max_concurrent_tests = atoi(optarg);
 				break;
+			case 26:
+				format = pg_strdup(optarg);
+				break;
 			default:
 				/* getopt_long already emitted a complaint */
 				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
@@ -2207,6 +2463,24 @@ regression_main(int argc, char *argv[],
 		exit(0);
 	}
 
+	/*
+	 * text (regress) is the default so we don't need to set any variables in
+	 * that case.
+	 */
+	if (format)
+	{
+		if (strcmp(format, "tap") == 0)
+		{
+			output = &output_func_tap;
+			psql_formatting = pg_strdup("-q");
+		}
+		else if (strcmp(format, "regress") != 0)
+		{
+			fprintf(stderr, _("\n%s: invalid format specified: \"%s\". Supported formats are \"tap\" and \"regress\"\n"), progname, format);
+			exit(2);
+		}
+	}
+
 	if (temp_instance && !port_specified_by_user)
 
 		/*
@@ -2461,7 +2735,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		comment(false, _("running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2528,55 +2802,22 @@ regression_main(int argc, char *argv[],
 	}
 
 	fclose(logfile);
+	logfile = NULL;
 
-	/*
-	 * Emit nice-looking summary message
-	 */
-	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
-	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
-
-	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);
-	}
-	else
+	if (file_size(difffilename) <= 0)
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	footer(difffilename, logfilename);
+	status_end();
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.24.3 (Apple Git-128)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-06-29 19:50  Daniel Gustafsson <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  0 siblings, 2 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-06-29 19:50 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

Attached is a new version of this patch, which completes the TAP output format
option such that all codepaths emitting output are TAP compliant.  The verbose
option is fixed to to not output extraneous newlines which the previous PoC
did.  The output it made to conform to the original TAP spec since v13/14 TAP
parsers seem less common than those that can handle the original spec.  Support
for the new format additions should be quite simple to add should we want that.

Running pg_regress --verbose should give the current format output.

I did end up combining TAP and --verbose into a single patch, as the TAP format
sort of depends on the verbose flag as TAP has no verbose mode.  I can split it
into two separate should a reviewer prefer that.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v5-0001-pg_regress-TAP-output-format.patch (38.5K, ../../[email protected]/2-v5-0001-pg_regress-TAP-output-format.patch)
  download | inline diff:
From fea1f31702bed856aa32f3e5f3cec19ace8c8bba Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Wed, 29 Jun 2022 21:44:52 +0200
Subject: [PATCH v5] pg_regress TAP output format

TAP is now a supported output format for pg_regress test runs on top
of the existing format which is called regress in this patch. Format
is selected via a new --format=STRING option to pg_regress which can
take tap and regress and parameters.  Output formats are implemented
via a set of function pointers which implements an output API. Using
NULL for all functions will generate a silent mode,  but thats not a
part of this commit.

This also brings a new parameter to pg_regress for deciding  verbose
output, since TAP doesn't have a verbose mode (and the existing mode
was deemed overly chatty).

As all output from pg_regress had to be addressed,  the frontend log
framework was also brought to use as it was already being set up but
not used.
---
 src/test/regress/pg_regress.c | 745 ++++++++++++++++++++++++----------
 1 file changed, 536 insertions(+), 209 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 982801e029..265f9e6148 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -74,6 +74,7 @@ const char *pretty_diff_opts = "-w -U3";
 /* options settable from command line */
 _stringlist *dblist = NULL;
 bool		debug = false;
+bool		verbose = false;
 char	   *inputdir = ".";
 char	   *outputdir = ".";
 char	   *bindir = PGBINDIR;
@@ -95,6 +96,9 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static char *format = NULL;
+static char *psql_formatting = NULL;
+static bool has_status = false;
 
 /* internal variables */
 static const char *progname;
@@ -120,11 +124,96 @@ static int	fail_ignore_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);
+typedef enum
+{
+	COMMENT_TEST_STATUS = 0,
+	COMMENT_DIAGNOSTIC,
+	COMMENT_ERROR,
+	COMMENT_VERBOSE
+}			CommentLevel;
+
+/*
+ * Each supported output format implements the below functions and supplies
+ * a filled out output_func structure. All output functions are voluntary to
+ * implement, using an output_func structure with all NULLs will generate no
+ * output except for program errors.
+ */
+struct output_func
+{
+	void (*header)(const char *line);
+	void (*footer)(const char *difffilename, const char *logfilename);
+	void (*comment)(CommentLevel level, const char *comment);
+
+	void (*test_status_preamble)(const char *testname);
+
+	void (*test_status_ok)(const char *testname);
+	void (*test_status_failed)(const char *testname, bool ignore, char *tags);
+
+	void (*test_runtime)(const char *testname, double runtime);
+	void (*bail)(const char *message);
+};
+
+/*
+ * Main output functions which in turn operate on the function pointers in the
+ * output_func which controls the format.
+ */
+static void header(const char *fmt,...);
+static void footer(const char *difffilename, const char *logfilename);
+static void comment(CommentLevel level, const char *fmt,...);
+static void test_status_preamble(const char *testname);
+static void test_status_ok(const char *testname);
+static void test_status_failed(const char *testname, bool ignore, char *tags);
+static void runtime(const char *testname, double runtime);
+static void bail(const char *fmt,...);
+
+/* Text output format */
+static void header_text(const char *line);
+static void footer_text(const char *difffilename, const char *logfilename);
+static void comment_text(CommentLevel level, const char *comment);
+static void test_status_preamble_text(const char *testname);
+static void test_status_ok_text(const char *testname);
+static void test_status_failed_text(const char *testname, bool ignore, char *tags);
+static void test_runtime_text(const char *testname, double runtime);
+static void bail_text(const char *message);
+
+struct output_func output_func_text =
+{
+	header_text,
+	footer_text,
+	comment_text,
+	test_status_preamble_text,
+	test_status_ok_text,
+	test_status_failed_text,
+	test_runtime_text,
+	bail_text
+};
+
+/* TAP output format */
+static void footer_tap(const char *difffilename, const char *logfilename);
+static void comment_tap(CommentLevel level, const char *comment);
+static void test_status_ok_tap(const char *testname);
+static void test_status_failed_tap(const char *testname, bool ignore, char *tags);
+static void bail_tap(const char *message);
+
+struct output_func output_func_tap =
+{
+	NULL,
+	footer_tap,
+	comment_tap,
+	NULL,
+	test_status_ok_tap,
+	test_status_failed_tap,
+	NULL,
+	bail_tap
+};
+
+struct output_func *output = &output_func_text;
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -138,7 +227,7 @@ unlimit_core_size(void)
 	getrlimit(RLIMIT_CORE, &lim);
 	if (lim.rlim_max == 0)
 	{
-		fprintf(stderr,
+		comment(COMMENT_VERBOSE,
 				_("%s: could not set core size: disallowed by hard limit\n"),
 				progname);
 		return;
@@ -208,18 +297,293 @@ split_to_stringlist(const char *s, const char *delim, _stringlist **listhead)
 /*
  * Print a progress banner on stdout.
  */
+static void
+header_text(const char *line)
+{
+	if (!verbose)
+		return;
+
+	fprintf(stdout, "============== %-38s ==============\n", line);
+	fflush(stdout);
+}
+
 static void
 header(const char *fmt,...)
 {
 	char		tmp[64];
 	va_list		ap;
 
+	if (!output->header)
+		return;
+
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	output->header(tmp);
+}
+
+static void
+footer_text(const char *difffilename, const char *logfilename)
+{
+	char buf[256];
+
+	/*
+	 * Emit nice-looking summary message
+	 */
+	if (fail_count == 0 && fail_ignore_count == 0)
+		snprintf(buf, sizeof(buf),
+				 _("All %d tests passed. "),
+				 success_count);
+	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _("%d of %d tests passed, %d failed test(s) ignored. "),
+				 success_count,
+				 success_count + fail_ignore_count,
+				 fail_ignore_count);
+	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
+		snprintf(buf, sizeof(buf),
+				 _("%d of %d tests failed. "),
+				 fail_count,
+				 success_count + fail_count);
+	else
+		/* fail_count>0 && fail_ignore_count>0 */
+		snprintf(buf, sizeof(buf),
+				 _("%d of %d tests failed, %d of these failures ignored. "),
+				 fail_count + fail_ignore_count,
+				 success_count + fail_count + fail_ignore_count,
+				 fail_ignore_count);
+
+	if (verbose)
+	{
+		putchar('\n');
+		for (int i = strlen(buf); i > 0; i--)
+			putchar('=');
+		printf("\n %s\n", buf);
+		for (int i = strlen(buf); i > 0; i--)
+			putchar('=');
+		putchar('\n');
+		putchar('\n');
+
+		if (difffilename && logfilename)
+		{
+			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);
+		}
+	}
+	else
+	{
+		printf("\n%s\n", buf);
+		if (difffilename && logfilename)
+			printf(_("Failing diffs: \"%s\"\nTest summary: \"%s\"\n"),
+					difffilename, logfilename);
+	}
+}
+
+static void
+footer_tap(const char *difffilename, const char *logfilename)
+{
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
+	status_end();
+}
+
+static void
+footer(const char *difffilename, const char *logfilename)
+{
+	if (!output->footer)
+		return;
+
+	output->footer(difffilename, logfilename);
+}
+
+static void
+comment_text(CommentLevel level, const char *comment)
+{
+	if (level == COMMENT_VERBOSE && !verbose)
+		return;
+
+	if (level == COMMENT_ERROR)
+		pg_log_error("%s", comment);
+	else
+		status("%s", comment);
+}
+
+static void
+comment_tap(CommentLevel level, const char *comment)
+{
+	/* The TAP format doesn't have verbose output */
+	if (level == COMMENT_VERBOSE)
+		return;
+
+	/*
+	 * Diagnostic comments are defined to start on a new line. Errors are
+	 * treated as diagnostics for the current test as there isn't a generic
+	 * error output defined in the TAP specification.
+	 */
+	if (level == COMMENT_DIAGNOSTIC || level == COMMENT_ERROR)
+		status("\n");
+
+	status("# %s", comment);
+}
+
+static void
+comment(CommentLevel level, const char *fmt,...)
+{
+	char		tmp[256];
+	va_list		ap;
+
+	if (!output->comment)
+		return;
+
+	va_start(ap, fmt);
+	vsnprintf(tmp, sizeof(tmp), fmt, ap);
+	va_end(ap);
+
+	output->comment(level, tmp);
+}
+
+/*
+ * Bailing out is for unrecoverable errors which prevents further testing to
+ * occur and after which the test run should be aborted.
+ */
+static void
+bail(const char *fmt,...)
+{
+	char		tmp[256];
+	va_list		ap;
+
+	if (output->bail)
+	{
+		va_start(ap, fmt);
+		vsnprintf(tmp, sizeof(tmp), fmt, ap);
+		va_end(ap);
+
+		output->bail(tmp);
+	}
+
+	status_end();
+	exit(2);
+}
+
+static void
+bail_tap(const char *message)
+{
+	status("\nBail out! %s", message);
+}
+
+static void
+bail_text(const char *message)
+{
+	pg_log_error("%s", message);
+}
+
+static void
+test_status_preamble_text(const char *testname)
+{
+	status(_("test %-28s ... "), testname);
+}
+
+static void
+test_status_preamble(const char *testname)
+{
+	if (!output->test_status_preamble)
+		return;
+
+	output->test_status_preamble(testname);
+}
+
+static void
+test_status_ok_tap(const char *testname)
+{
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %i - %s",
+		   (fail_count + fail_ignore_count + success_count),
+		   testname);
+}
+
+static void
+test_status_ok_text(const char *testname)
+{
+	(void) testname; /* unused */
+	status(_("ok    "));	/* align with FAILED */
+}
+
+static void
+test_status_ok(const char *testname)
+{
+	success_count++;
+	if (!output->test_status_ok)
+		return;
+
+	output->test_status_ok(testname);
+}
+
+static void
+test_status_failed_tap(const char *testname, bool ignore, char *tags)
+{
+	/* There is no NLS translation here as "(not) ok" are protocol messages */
+	if (ignore)
+	{
+		status("ok %i - %s ",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+		comment(COMMENT_TEST_STATUS, "SKIP (ignored)");
+	}
+	else
+		status("not ok %i - %s",
+			   (fail_count + fail_ignore_count + success_count),
+			   testname);
+
+	if (tags && strlen(tags) > 0)
+	{
+		status("\n");
+		comment(COMMENT_DIAGNOSTIC, "tags: %s", tags);
+	}
+}
+
+
+static void
+test_status_failed_text(const char *testname, bool ignore, char *tags)
+{
+	if (tags && strlen(tags) > 0)
+		status("%s ", tags);
+
+	if (ignore)
+		status(_("failed (ignored)"));
+	else
+		status(_("FAILED"));
+}
+
+static void
+test_status_failed(const char *testname, bool ignore, char *tags)
+{
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	if (!output->test_status_failed)
+		return;
+
+	output->test_status_failed(testname, ignore, tags);
+}
+
+static void
+test_runtime_text(const char *testname, double runtime)
+{
+	(void)testname;
+	status(_(" %8.0f ms"), runtime);
+}
+
+static void
+runtime(const char *testname, double runtime)
+{
+	if (!output->test_runtime)
+		return;
+
+	output->test_runtime(testname, runtime);
 }
 
 /*
@@ -230,6 +594,7 @@ status(const char *fmt,...)
 {
 	va_list		ap;
 
+	has_status = true;
 	va_start(ap, fmt);
 	vfprintf(stdout, fmt, ap);
 	fflush(stdout);
@@ -249,6 +614,10 @@ status(const char *fmt,...)
 static void
 status_end(void)
 {
+	if (!has_status)
+		return;
+
+	has_status = false;
 	fprintf(stdout, "\n");
 	fflush(stdout);
 	if (logfile)
@@ -279,8 +648,7 @@ stop_postmaster(void)
 		r = system(buf);
 		if (r != 0)
 		{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			pg_log_error("could not stop postmaster: exit code was %d", r);
 			_exit(2);			/* not exit(), that could be recursive */
 		}
 
@@ -340,9 +708,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. */
@@ -465,9 +832,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))
@@ -486,26 +852,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';
 
@@ -758,13 +1118,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			comment(COMMENT_VERBOSE, _("(using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			comment(COMMENT_VERBOSE, _("(using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			comment(COMMENT_VERBOSE, _("(using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			comment(COMMENT_VERBOSE, _("(using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -813,34 +1173,30 @@ 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());
+		pg_log_error("could not open process token: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not get token information buffer size: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 	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());
+		pg_log_error("could not get token information: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not look up account SID: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
@@ -990,9 +1346,10 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X %s",
 					 bindir ? bindir : "",
-					 bindir ? "/" : "");
+					 bindir ? "/" : "",
+					 psql_formatting ? psql_formatting : "");
 	return buf;
 }
 
@@ -1045,8 +1402,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 */
@@ -1091,9 +1447,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)
 	{
@@ -1108,8 +1462,7 @@ 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));
+		pg_log_error("could not exec \"%s\": %s", shellprog, strerror(errno));
 		_exit(1);				/* not exit() here... */
 	}
 	/* in parent */
@@ -1148,8 +1501,8 @@ file_size(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		comment(COMMENT_ERROR, _("could not open file \"%s\" for reading: %s"),
+				file, strerror(errno));
 		return -1;
 	}
 	fseek(f, 0, SEEK_END);
@@ -1170,8 +1523,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));
+		comment(COMMENT_ERROR, _("could not open file \"%s\" for reading: %s"),
+				file, strerror(errno));
 		return -1;
 	}
 	while ((c = fgetc(f)) != EOF)
@@ -1212,9 +1565,8 @@ 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));
 	}
 }
 
@@ -1263,8 +1615,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
 
@@ -1274,8 +1625,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
 
@@ -1346,9 +1696,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))
@@ -1463,9 +1812,8 @@ 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;
@@ -1474,9 +1822,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 */
@@ -1495,7 +1842,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]);
+					comment(COMMENT_VERBOSE, " %s", names[i]);
 				tests_left--;
 				break;
 			}
@@ -1514,20 +1861,20 @@ static void
 log_child_failure(int exitstatus)
 {
 	if (WIFEXITED(exitstatus))
-		status(_(" (test process exited with exit code %d)"),
+		comment(COMMENT_DIAGNOSTIC, _(" (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)"),
+		comment(COMMENT_DIAGNOSTIC, _(" (test process was terminated by exception 0x%X)"),
 			   WTERMSIG(exitstatus));
 #else
-		status(_(" (test process was terminated by signal %d: %s)"),
+		comment(COMMENT_DIAGNOSTIC, _(" (test process was terminated by signal %d: %s)"),
 			   WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
 #endif
 	}
 	else
-		status(_(" (test process exited with unrecognized status %d)"),
+		comment(COMMENT_DIAGNOSTIC, _(" (test process exited with unrecognized status %d)"),
 			   exitstatus);
 }
 
@@ -1551,18 +1898,20 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	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))
@@ -1600,9 +1949,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		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\n"),
+				 schedule, line_num, scbuf);
 		}
 
 		num_tests = 0;
@@ -1618,9 +1966,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\n"),
+							 MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
 					}
 					sav = *c;
 					*c = '\0';
@@ -1642,14 +1989,13 @@ 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\n"),
+				 schedule, line_num, scbuf);
 		}
 
 		if (num_tests == 1)
 		{
-			status(_("test %-28s ... "), tests[0]);
+			test_status_preamble(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);
@@ -1657,16 +2003,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\n"),
+				 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);
+			comment(COMMENT_VERBOSE, _("parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1686,7 +2031,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			comment(COMMENT_VERBOSE, _("parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1704,8 +2049,10 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
+			resetStringInfo(&tagbuf);
+
 			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+				test_status_preamble(tests[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1726,7 +2073,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1744,28 +2091,17 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data);
 			}
 			else
-			{
-				status(_("ok    "));	/* align with FAILED */
-				success_count++;
-			}
+				test_status_ok(tests[i]);
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
 			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 
 			status_end();
 		}
@@ -1780,6 +2116,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1803,11 +2140,13 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
+	test_status_preamble(test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1828,27 +2167,23 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
 	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	runtime(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1872,9 +2207,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, logfilename, strerror(errno));
 	}
 
 	/* create the diffs file as empty */
@@ -1883,9 +2217,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, difffilename, strerror(errno));
 	}
 	/* we don't keep the diffs file open continuously */
 	fclose(difffile);
@@ -1989,6 +2322,7 @@ help(void)
 	printf(_("      --debug                   turn on debug mode in programs that are run\n"));
 	printf(_("      --dlpath=DIR              look for dynamic libraries in DIR\n"));
 	printf(_("      --encoding=ENCODING       use ENCODING as the encoding\n"));
+	printf(_("      --format=(regress|tap)    output format to use\n"));
 	printf(_("  -h, --help                    show this help, then exit\n"));
 	printf(_("      --inputdir=DIR            take input files from DIR (default \".\")\n"));
 	printf(_("      --launcher=CMD            use CMD as launcher of psql\n"));
@@ -2003,6 +2337,7 @@ help(void)
 	printf(_("                                (can be used multiple times to concatenate)\n"));
 	printf(_("      --temp-instance=DIR       create a temporary instance in DIR\n"));
 	printf(_("      --use-existing            use an existing installation\n"));
+	printf(_("  -v, --verbose                 verbose output, only applies to regress output format\n"));
 	printf(_("  -V, --version                 output version information, then exit\n"));
 	printf(_("\n"));
 	printf(_("Options for \"temp-instance\" mode:\n"));
@@ -2031,6 +2366,7 @@ regression_main(int argc, char *argv[],
 	static struct option long_options[] = {
 		{"help", no_argument, NULL, 'h'},
 		{"version", no_argument, NULL, 'V'},
+		{"verbose", no_argument, NULL, 'v'},
 		{"dbname", required_argument, NULL, 1},
 		{"debug", no_argument, NULL, 2},
 		{"inputdir", required_argument, NULL, 3},
@@ -2052,6 +2388,7 @@ regression_main(int argc, char *argv[],
 		{"load-extension", required_argument, NULL, 22},
 		{"config-auth", required_argument, NULL, 24},
 		{"max-concurrent-tests", required_argument, NULL, 25},
+		{"format", required_argument, NULL, 26},
 		{NULL, 0, NULL, 0}
 	};
 
@@ -2097,7 +2434,7 @@ regression_main(int argc, char *argv[],
 	if (getenv("PG_REGRESS_DIFF_OPTS"))
 		pretty_diff_opts = getenv("PG_REGRESS_DIFF_OPTS");
 
-	while ((c = getopt_long(argc, argv, "hV", long_options, &option_index)) != -1)
+	while ((c = getopt_long(argc, argv, "hVv", long_options, &option_index)) != -1)
 	{
 		switch (c)
 		{
@@ -2107,6 +2444,9 @@ regression_main(int argc, char *argv[],
 			case 'V':
 				puts("pg_regress (PostgreSQL) " PG_VERSION);
 				exit(0);
+			case 'v':
+				verbose = true;
+				break;
 			case 1:
 
 				/*
@@ -2181,9 +2521,12 @@ regression_main(int argc, char *argv[],
 			case 25:
 				max_concurrent_tests = atoi(optarg);
 				break;
+			case 26:
+				format = pg_strdup(optarg);
+				break;
 			default:
 				/* getopt_long already emitted a complaint */
-				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
+				pg_log_error_hint("Try \"%s --help\" for more information.",
 						progname);
 				exit(2);
 		}
@@ -2207,6 +2550,29 @@ regression_main(int argc, char *argv[],
 		exit(0);
 	}
 
+	if (!verbose)
+		psql_formatting = pg_strdup("-q");
+
+	/*
+	 * text (regress) is the default so we don't need to set any variables in
+	 * that case.
+	 */
+	if (format)
+	{
+		if (strcmp(format, "tap") == 0)
+		{
+			output = &output_func_tap;
+			if (!psql_formatting)
+				psql_formatting = pg_strdup("-q");
+		}
+		else if (strcmp(format, "regress") != 0)
+		{
+			pg_log_error("%s: invalid format specified: \"%s\". Supported formats are \"tap\" and \"regress\"",
+						 progname, format);
+			exit(2);
+		}
+	}
+
 	if (temp_instance && !port_specified_by_user)
 
 		/*
@@ -2248,9 +2614,8 @@ regression_main(int argc, char *argv[],
 			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(_("%s: could not remove temp instance \"%s\""),
+							 progname, temp_instance);
 			}
 		}
 
@@ -2276,8 +2641,8 @@ regression_main(int argc, char *argv[],
 				 outputdir);
 		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(_("%s: initdb failed\nExamine %s/log/initdb.log for the reason.\nCommand was: %s"),
+				 progname, outputdir, buf);
 		}
 
 		/*
@@ -2292,8 +2657,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( _("%s: could not open \"%s\" for adding extra config: %s"),
+				 progname, buf, strerror(errno));
 		}
 		fputs("\n# Configuration added by pg_regress\n\n", pg_conf);
 		fputs("log_autovacuum_min_duration = 0\n", pg_conf);
@@ -2312,8 +2677,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(_("%s: could not open \"%s\" to read extra config: %s"),
+					 progname, temp_config, strerror(errno));
 			}
 			while (fgets(line_buf, sizeof(line_buf), extra_conf) != NULL)
 				fputs(line_buf, pg_conf);
@@ -2353,14 +2718,16 @@ regression_main(int argc, char *argv[],
 
 				if (port_specified_by_user || i == 15)
 				{
-					fprintf(stderr, _("port %d apparently in use\n"), port);
+					comment(COMMENT_VERBOSE, _("port %d apparently in use\n"),
+							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);
+						comment(COMMENT_VERBOSE,
+								_("could not determine an available port\n"));
+					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);
+				comment(COMMENT_VERBOSE, _("port %d apparently in use, trying %d\n"),
+						port, port + 1);
 				port++;
 				sprintf(s, "%d", port);
 				setenv("PGPORT", s, 1);
@@ -2384,11 +2751,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\n"), strerror(errno));
 
 		/*
 		 * Wait till postmaster is able to accept connections; normally this
@@ -2422,16 +2785,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\nExamine %s/log/postmaster.log for the reason\n"),
+					 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);
+			comment(COMMENT_VERBOSE, _("postmaster did not respond within %d seconds\nExamine %s/log/postmaster.log for the reason\n"),
+					wait_seconds, outputdir);
 
 			/*
 			 * If we get here, the postmaster is probably wedged somewhere in
@@ -2440,16 +2803,13 @@ 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);
 		}
 
@@ -2461,7 +2821,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		comment(COMMENT_VERBOSE, _("running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2514,6 +2874,23 @@ regression_main(int argc, char *argv[],
 		stop_postmaster();
 	}
 
+	fclose(logfile);
+	logfile = NULL;
+
+	if (file_size(difffilename) <= 0)
+	{
+		unlink(difffilename);
+		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
+	}
+
+	footer(difffilename, logfilename);
+	status_end();
+
 	/*
 	 * If there were no errors, remove the temp instance immediately to
 	 * conserve disk space.  (If there were errors, we leave the instance in
@@ -2523,58 +2900,8 @@ regression_main(int argc, char *argv[],
 	{
 		header(_("removing temporary instance"));
 		if (!rmtree(temp_instance, true))
-			fprintf(stderr, _("\n%s: could not remove temp instance \"%s\"\n"),
-					progname, temp_instance);
-	}
-
-	fclose(logfile);
-
-	/*
-	 * Emit nice-looking summary message
-	 */
-	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
-	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
-
-	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);
-	}
-	else
-	{
-		unlink(difffilename);
-		unlink(logfilename);
+			pg_log_error("could not remove temp instance \"%s\"",
+						 temp_instance);
 	}
 
 	if (fail_count != 0)
-- 
2.32.1 (Apple Git-133)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 14:27  Peter Eisentraut <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  1 sibling, 2 replies; 26+ messages in thread

From: Peter Eisentraut @ 2022-07-04 14:27 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; Andres Freund <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

On 29.06.22 21:50, Daniel Gustafsson wrote:
> Attached is a new version of this patch, which completes the TAP output format
> option such that all codepaths emitting output are TAP compliant.  The verbose
> option is fixed to to not output extraneous newlines which the previous PoC
> did.  The output it made to conform to the original TAP spec since v13/14 TAP
> parsers seem less common than those that can handle the original spec.  Support
> for the new format additions should be quite simple to add should we want that.
> 
> Running pg_regress --verbose should give the current format output.
> 
> I did end up combining TAP and --verbose into a single patch, as the TAP format
> sort of depends on the verbose flag as TAP has no verbose mode.  I can split it
> into two separate should a reviewer prefer that.

I'm not sure what to make of all these options.  I think providing a TAP 
output for pg_regress is a good idea.  But then do we still need the old 
output?  Is it worth maintaining two output formats that display exactly 
the same thing in slightly different ways?

What is the purpose of the --verbose option?  When and how is one 
supposed to activate that?  The proposed default format now hides the 
fact that some tests are started in parallel.  I remember the last time 
I wanted to tweak the output of the parallel tests, people were very 
attached to the particular timing and spacing of the current output.  So 
I'm not sure people will like this.

The timing output is very popular.  Where is that in the TAP output?

More generally, what do you envision we do with this feature?  Who is it 
for, what are the tradeoffs, etc.?






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 14:39  Tom Lane <[email protected]>
  parent: Peter Eisentraut <[email protected]>
  1 sibling, 3 replies; 26+ messages in thread

From: Tom Lane @ 2022-07-04 14:39 UTC (permalink / raw)
  To: Peter Eisentraut <[email protected]>; +Cc: Daniel Gustafsson <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Developers <[email protected]>

Peter Eisentraut <[email protected]> writes:
> I'm not sure what to make of all these options.  I think providing a TAP 
> output for pg_regress is a good idea.  But then do we still need the old 
> output?  Is it worth maintaining two output formats that display exactly 
> the same thing in slightly different ways?

Probably is, because this is bad:

> ... The proposed default format now hides the 
> fact that some tests are started in parallel.  I remember the last time 
> I wanted to tweak the output of the parallel tests, people were very 
> attached to the particular timing and spacing of the current output.  So 
> I'm not sure people will like this.

and so is this:

> The timing output is very popular.  Where is that in the TAP output?

Both of those things are fairly critical for test development.  You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

More generally, I'm unhappy about the proposal that TAP should become
the default output.  There is nothing particularly human-friendly
about it, whereas the existing format is something we have tuned to
our liking over literally decades.  I don't mind if there's a way to
get TAP when you're actually intending to feed it into a TAP-parsing
tool, but I am not a TAP-parsing tool and I don't see why I should
have to put up with it.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 19:33  Peter Eisentraut <[email protected]>
  parent: Tom Lane <[email protected]>
  2 siblings, 0 replies; 26+ messages in thread

From: Peter Eisentraut @ 2022-07-04 19:33 UTC (permalink / raw)
  To: Tom Lane <[email protected]>; +Cc: Daniel Gustafsson <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Developers <[email protected]>

On 04.07.22 16:39, Tom Lane wrote:
> Probably is, because this is bad:
> 
>> ... The proposed default format now hides the
>> fact that some tests are started in parallel.  I remember the last time
>> I wanted to tweak the output of the parallel tests, people were very
>> attached to the particular timing and spacing of the current output.  So
>> I'm not sure people will like this.
> and so is this:
> 
>> The timing output is very popular.  Where is that in the TAP output?
> Both of those things are fairly critical for test development.  You
> need to know what else might be running in parallel with a test case,
> and you need to know whether you just bloated the runtime unreasonably.

I don't think there is a reason these couldn't be shown in TAP output as 
well.

Even if we keep the two output formats in parallel, it would be good if 
they showed the same set of information.





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 20:06  Andres Freund <[email protected]>
  parent: Tom Lane <[email protected]>
  2 siblings, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-07-04 20:06 UTC (permalink / raw)
  To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Daniel Gustafsson <[email protected]>; PostgreSQL Developers <[email protected]>

Hi,

> Peter Eisentraut <[email protected]> writes:
> > I'm not sure what to make of all these options.  I think providing a TAP
> > output for pg_regress is a good idea.  But then do we still need the old
> > output?  Is it worth maintaining two output formats that display exactly
> > the same thing in slightly different ways?
>
> Probably is, because this is bad:

> > ... The proposed default format now hides the
> > fact that some tests are started in parallel.  I remember the last time
> > I wanted to tweak the output of the parallel tests, people were very
> > attached to the particular timing and spacing of the current output.  So
> > I'm not sure people will like this.
>
> and so is this:
>
> > The timing output is very popular.  Where is that in the TAP output?
>
> Both of those things are fairly critical for test development.  You
> need to know what else might be running in parallel with a test case,
> and you need to know whether you just bloated the runtime unreasonably.

That should be doable with tap as well - afaics the output of that could
nearly be the same as now, preceded by a #.

The test timing output could (and I think should) also be output - but if I
read the tap specification correctly, we'd either need to make it part of the
test "description" or on a separate line.


On 2022-07-04 10:39:37 -0400, Tom Lane wrote:
> More generally, I'm unhappy about the proposal that TAP should become
> the default output.  There is nothing particularly human-friendly
> about it, whereas the existing format is something we have tuned to
> our liking over literally decades.  I don't mind if there's a way to
> get TAP when you're actually intending to feed it into a TAP-parsing
> tool, but I am not a TAP-parsing tool and I don't see why I should
> have to put up with it.

I'm mostly interested in the tap format because meson's testrunner can parse
it - unsurprisingly it doesn't understand the current regress output. It's a
lot nicer to immediately be pointed to the failed test(s) than having to scan
through the output "manually".

Greetings,

Andres Freund





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 20:13  Andres Freund <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  1 sibling, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-07-04 20:13 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

Hi,

On 2022-06-29 21:50:45 +0200, Daniel Gustafsson wrote:
> @@ -279,8 +648,7 @@ stop_postmaster(void)
>  		r = system(buf);
>  		if (r != 0)
>  		{
> -			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
> -					progname, r);
> +			pg_log_error("could not stop postmaster: exit code was %d", r);
>  			_exit(2);			/* not exit(), that could be recursive */
>  		}

There's a lot of stuff like this. Perhaps worth doing separately? I'm not sure
I unerstand where you used bail and where not. I assume it's mostly arund use
uf _exit() vs exit()?


> +				test_status_ok(tests[i]);
>  
>  			if (statuses[i] != 0)
>  				log_child_failure(statuses[i]);
>  
>  			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
> -			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
> +			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));

Based on the discussion downthread, let's just always compute this and display
it even in the tap format?


Greetings,

Andres Freund





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 21:48  Daniel Gustafsson <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 0 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-07-04 21:48 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: PostgreSQL Developers <[email protected]>

> On 4 Jul 2022, at 22:13, Andres Freund <[email protected]> wrote:
> 
> Hi,
> 
> On 2022-06-29 21:50:45 +0200, Daniel Gustafsson wrote:
>> @@ -279,8 +648,7 @@ stop_postmaster(void)
>> 		r = system(buf);
>> 		if (r != 0)
>> 		{
>> -			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
>> -					progname, r);
>> +			pg_log_error("could not stop postmaster: exit code was %d", r);
>> 			_exit(2);			/* not exit(), that could be recursive */
>> 		}
> 
> There's a lot of stuff like this. Perhaps worth doing separately? I'm not sure
> I unerstand where you used bail and where not. I assume it's mostly arund use
> uf _exit() vs exit()?

Since bail will cause the entire testrun to be considered a failure, the idea
was to avoid using bail() for any errors in tearing down the test harness after
an otherwise successful test run.

Moving to pg_log_error() can for sure be broken out into a separate patch from
the rest of the set (if we at all want to do that, but it seemed logical to
address when dealing with other output routines).

>> +				test_status_ok(tests[i]);
>> 
>> 			if (statuses[i] != 0)
>> 				log_child_failure(statuses[i]);
>> 
>> 			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
>> -			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
>> +			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
> 
> Based on the discussion downthread, let's just always compute this and display
> it even in the tap format?

Sure, it's easy enough to do and include in the test description.  The reason I
left it out is that the test runners I played around with all hide those
details and only show a running total.  That of course doesn't mean that all
runners will do that (and anyone running TAP output for human consumption will
want it), so I agree with putting it in, I'll fix that up in a v6 shortly.

--
Daniel Gustafsson		https://vmware.com/






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 22:06  Daniel Gustafsson <[email protected]>
  parent: Peter Eisentraut <[email protected]>
  1 sibling, 1 reply; 26+ messages in thread

From: Daniel Gustafsson @ 2022-07-04 22:06 UTC (permalink / raw)
  To: Peter Eisentraut <[email protected]>; +Cc: Andres Freund <[email protected]>; PostgreSQL Developers <[email protected]>

> On 4 Jul 2022, at 16:27, Peter Eisentraut <[email protected]> wrote:
> 
> On 29.06.22 21:50, Daniel Gustafsson wrote:
>> Attached is a new version of this patch, which completes the TAP output format
>> option such that all codepaths emitting output are TAP compliant.  The verbose
>> option is fixed to to not output extraneous newlines which the previous PoC
>> did.  The output it made to conform to the original TAP spec since v13/14 TAP
>> parsers seem less common than those that can handle the original spec.  Support
>> for the new format additions should be quite simple to add should we want that.
>> Running pg_regress --verbose should give the current format output.
>> I did end up combining TAP and --verbose into a single patch, as the TAP format
>> sort of depends on the verbose flag as TAP has no verbose mode.  I can split it
>> into two separate should a reviewer prefer that.
> 
> I'm not sure what to make of all these options.  I think providing a TAP output for pg_regress is a good idea.  But then do we still need the old output?  Is it worth maintaining two output formats that display exactly the same thing in slightly different ways?

If we believe that TAP is good enough for human consumption and not just as
input to test runners then we don't.  Personally I think the traditional format
is more pleasant to read than raw TAP output when running tests.

> What is the purpose of the --verbose option?  When and how is one supposed to activate that?  The proposed default format now hides the fact that some tests are started in parallel.

The discussion on this was in [email protected]
where it was proposed that we could cut the boilerplate.  Thinking on it I
agree that the parallel run info should be included even without --verbose so
I'll add that back.  In general, running with --verbose should ideally only be
required for troubleshooting setup/teardown issues with testing.

>  I remember the last time I wanted to tweak the output of the parallel tests, people were very attached to the particular timing and spacing of the current output.  So I'm not sure people will like this.
> 
> The timing output is very popular.  Where is that in the TAP output?

As I mentioned in the mail upthread, TAP runners generally hide that info and
only show a running total.  That being said, I do agree with adding back so
I'll do that in a new version of the patch.

> More generally, what do you envision we do with this feature?  Who is it for, what are the tradeoffs, etc.?

In general, my thinking with this was that normal testruns started with make
check (or similar) by developers would use the traditional format (albeit less
verbose) and that the TAP output was for automated test runners in general and
the meson test runner in particular.  The TAP format is an opt-in with the
traditional format being the default.

The tradeoff is of course that maintaining two output formats is more work than
maintaining one, but it's not really something we change all that often so that
might not be too heavy a burden.

I personally didn't see us replacing the traditional format for "human
readable" runs, if that's where the discussion is heading then the patch can
look quite different.  Having test output format parity with supported back
branches seemed like a good idea to me at the time of writing at least.

--
Daniel Gustafsson		https://vmware.com/






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 22:06  Tom Lane <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 0 replies; 26+ messages in thread

From: Tom Lane @ 2022-07-04 22:06 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Daniel Gustafsson <[email protected]>; PostgreSQL Developers <[email protected]>

Andres Freund <[email protected]> writes:
>> Both of those things are fairly critical for test development.  You
>> need to know what else might be running in parallel with a test case,
>> and you need to know whether you just bloated the runtime unreasonably.

> That should be doable with tap as well - afaics the output of that could
> nearly be the same as now, preceded by a #.

I don't mind minor changes like prefixing # --- I just don't want
to lose information.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 22:11  Daniel Gustafsson <[email protected]>
  parent: Tom Lane <[email protected]>
  2 siblings, 0 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-07-04 22:11 UTC (permalink / raw)
  To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Developers <[email protected]>

> On 4 Jul 2022, at 16:39, Tom Lane <[email protected]> wrote:
> 
> Peter Eisentraut <[email protected]> writes:
>> I'm not sure what to make of all these options.  I think providing a TAP 
>> output for pg_regress is a good idea.  But then do we still need the old 
>> output?  Is it worth maintaining two output formats that display exactly 
>> the same thing in slightly different ways?
> 
> Probably is, because this is bad:
> 
>> ... The proposed default format now hides the 
>> fact that some tests are started in parallel.  I remember the last time 
>> I wanted to tweak the output of the parallel tests, people were very 
>> attached to the particular timing and spacing of the current output.  So 
>> I'm not sure people will like this.
> 
> and so is this:
> 
>> The timing output is very popular.  Where is that in the TAP output?
> 
> Both of those things are fairly critical for test development.  You
> need to know what else might be running in parallel with a test case,
> and you need to know whether you just bloated the runtime unreasonably.
> 
> More generally, I'm unhappy about the proposal that TAP should become
> the default output.  

That's not my proposal though, my proposal is that the traditional format
should be the default output (with the parallel test info added back, that was
my bad), and that TAP is used in automated test runners like in meson.  Hiding
the timing in TAP was (as mentioned upthread) since TAP test runners generally
never show that anyways, but I'll add it back since it clearly doesn't hurt to
have even there.

> There is nothing particularly human-friendly
> about it, whereas the existing format is something we have tuned to
> our liking over literally decades.  I don't mind if there's a way to
> get TAP when you're actually intending to feed it into a TAP-parsing
> tool, but I am not a TAP-parsing tool and I don't see why I should
> have to put up with it.

I totally agree, and that's why the patch has the traditional format - without
all the boilerplate - as the default.  Unless opting-in there is no change over
today, apart from the boilerplate.

--
Daniel Gustafsson		https://vmware.com/






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-04 22:58  Andres Freund <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-07-04 22:58 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

Hi,

On 2022-07-05 00:06:04 +0200, Daniel Gustafsson wrote:
> > On 4 Jul 2022, at 16:27, Peter Eisentraut <[email protected]> wrote:
> >
> > On 29.06.22 21:50, Daniel Gustafsson wrote:
> >> Attached is a new version of this patch, which completes the TAP output format
> >> option such that all codepaths emitting output are TAP compliant.  The verbose
> >> option is fixed to to not output extraneous newlines which the previous PoC
> >> did.  The output it made to conform to the original TAP spec since v13/14 TAP
> >> parsers seem less common than those that can handle the original spec.  Support
> >> for the new format additions should be quite simple to add should we want that.
> >> Running pg_regress --verbose should give the current format output.
> >> I did end up combining TAP and --verbose into a single patch, as the TAP format
> >> sort of depends on the verbose flag as TAP has no verbose mode.  I can split it
> >> into two separate should a reviewer prefer that.
> >
> > I'm not sure what to make of all these options.  I think providing a TAP output for pg_regress is a good idea.  But then do we still need the old output?  Is it worth maintaining two output formats that display exactly the same thing in slightly different ways?
>
> If we believe that TAP is good enough for human consumption and not just as
> input to test runners then we don't.  Personally I think the traditional format
> is more pleasant to read than raw TAP output when running tests.

I think with a bit of care the tap output could be nearly the same
"quality". It might not be the absolute "purest" tap output, but who cares.


test tablespace                   ... ok          418 ms
parallel group (20 tests):  oid char int2 varchar name int4 text pg_lsn regproc txid money boolean uuid float4 int8 float8 bit enum rangetypes numeric
     boolean                      ... ok           34 ms
     char                         ... ok           20 ms
     name                         ... ok           26 ms

isn't that different from

ok 1 - tablespace           418ms
# parallel group (20 tests):  oid char int2 varchar name int4 text pg_lsn regproc txid money boolean uuid float4 int8 float8 bit enum rangetypes numeric
ok 2 -      boolean        34ms
ok 3 -      char           20ms
ok 4 -      name           26ms

or whatever.

For non-parallel tests I think we currently print the test name before running
the test, which obviously doesn't work well when needing to print the 'ok'
'not ok' first. We could just print
# non-parallel group tablespace
or such? That doesn't


I wonder if for parallel tests we should print the test number based on the
start of the test rather than the finish time? Hm, it also looks like it's
legal to just leave the test number out?


> The discussion on this was in [email protected]
> where it was proposed that we could cut the boilerplate.

I think that was more about things like CREATE DATABASE etc. And I'm not sure
we need an option to keep showing those details.


> >  I remember the last time I wanted to tweak the output of the parallel tests, people were very attached to the particular timing and spacing of the current output.  So I'm not sure people will like this.
> >
> > The timing output is very popular.  Where is that in the TAP output?
>
> As I mentioned in the mail upthread, TAP runners generally hide that info and
> only show a running total.  That being said, I do agree with adding back so
> I'll do that in a new version of the patch.

FWIW, meson's testrunner shows the individual tap output when using -v.

One test where using -v is a problem is pg_dump's tests - the absurd number of
8169 tests makes showing that decidedly not fun.


> Having test output format parity with supported back branches seemed like a
> good idea to me at the time of writing at least.

That's of course nice, but it also kind of corners us into not evolving the
default format, which I don't think is warranted...

Greetings,

Andres Freund





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-05 01:56  Tom Lane <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Tom Lane @ 2022-07-05 01:56 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: Daniel Gustafsson <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

Andres Freund <[email protected]> writes:
> I think with a bit of care the tap output could be nearly the same
> "quality". It might not be the absolute "purest" tap output, but who cares.

+1

> For non-parallel tests I think we currently print the test name before running
> the test, which obviously doesn't work well when needing to print the 'ok'
> 'not ok' first.

Is this still a consideration?  We got rid of serial_schedule some
time ago.

> I wonder if for parallel tests we should print the test number based on the
> start of the test rather than the finish time?

I think we need the test number to be stable, so it had better be the
ordering appearing in the schedule file.  But we already print the
results in that order.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-07-05 02:40  Andres Freund <[email protected]>
  parent: Tom Lane <[email protected]>
  0 siblings, 2 replies; 26+ messages in thread

From: Andres Freund @ 2022-07-05 02:40 UTC (permalink / raw)
  To: Tom Lane <[email protected]>; +Cc: Daniel Gustafsson <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

Hi,

On 2022-07-04 21:56:24 -0400, Tom Lane wrote:
> > For non-parallel tests I think we currently print the test name before running
> > the test, which obviously doesn't work well when needing to print the 'ok'
> > 'not ok' first.
> 
> Is this still a consideration?  We got rid of serial_schedule some
> time ago.

Not really for the main tests, there's a few serial steps, but not enough that
a bit additional output would be an issue. I think all tests in contrib are
serial though, and some have enough tests that it might be annoying?


> > I wonder if for parallel tests we should print the test number based on the
> > start of the test rather than the finish time?
> 
> I think we need the test number to be stable, so it had better be the
> ordering appearing in the schedule file.  But we already print the
> results in that order.

I remembered some asynchronizity, but apparently that's just the "parallel
group" line.

Greetings,

Andres Freund





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-08-02 18:44  Jacob Champion <[email protected]>
  parent: Andres Freund <[email protected]>
  1 sibling, 0 replies; 26+ messages in thread

From: Jacob Champion @ 2022-08-02 18:44 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; Tom Lane <[email protected]>; +Cc: Daniel Gustafsson <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

This entry has been waiting on author input for a while (our current
threshold is roughly two weeks), so I've marked it Returned with
Feedback.

Once you think the patchset is ready for review again, you (or any
interested party) can resurrect the patch entry by visiting

    https://commitfest.postgresql.org/38/3559/

and changing the status to "Needs Review", and then changing the
status again to "Move to next CF". (Don't forget the second step;
hopefully we will have streamlined this in the near future!)

Thanks,
--Jacob





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-08-17 21:04  Daniel Gustafsson <[email protected]>
  parent: Andres Freund <[email protected]>
  1 sibling, 1 reply; 26+ messages in thread

From: Daniel Gustafsson @ 2022-08-17 21:04 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: Tom Lane <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

Attached is a new version of the pg_regress TAP patch which - per reviewer
feedback - does away with dual output formats and just converts the existing
output to be TAP complaint.  The idea was to keep it fairly human readable
while still be TAP compliant enough that running it with prove (with a tiny
Perl wrapper) works.  This version also strips away the verbose output which
these days isn't terribly useful and mainly consume vertical space.  Another
feature of the patch is to switch error logging to using the common frontend
logging rather than pg_regress rolling its own.  The output from pg_log_error
is emitted verbatim by prove as it's on stderr.

I based the support on the original TAP specification and not the new v13 or
v14 since it seemed unclear how well those are supported in testrunners.  If
v14 is adopted by testrunners there are some better functionality for reporting
errors that we could use, but for how this version seems a safer option.

A normal "make check" with this patch applied now looks like this:


+++ regress check in src/test/regress +++
# running on port 61696 with PID 57910
ok 1 - test_setup                       326 ms
ok 2 - tablespace                       401 ms
# parallel group (20 tests):  varchar char oid pg_lsn txid int4 regproc money int2 uuid float4 text name boolean int8 enum float8 bit numeric rangetypes
ok 3 - boolean                          129 ms
ok 4 - char                              73 ms
ok 5 - name                             117 ms
ok 6 - varchar                           68 ms
<...snip...>
ok 210 - memoize                        137 ms
ok 211 - stats                          851 ms
# parallel group (2 tests):  event_trigger oidjoins
ok 212 - event_trigger                  138 ms
not ok 213 - oidjoins                   190 ms
ok 214 - fast_default                   149 ms
1..214
# 1 of 214 tests failed.
# The differences that caused some tests to fail can be viewed in the
# file "/<path>/src/test/regress/regression.diffs".  A copy of the test summary that you see
# above is saved in the file "/<path>/src/test/regress/regression.out".


The ending comment isn't currently shown when executed via prove as it has to
go to STDERR for that to work, and I'm not sure that's something we want to do
in the general case.  I don't expect running the pg_regress tests via prove is
going to be the common case.  How does the meson TAP ingestion handle
stdout/stderr?

And for the sake of completeness, even though we all know this by heart, a
similar run from the current output format looks like:


+++ regress check in src/test/regress +++
============== creating temporary instance            ==============
============== initializing database system           ==============
============== starting postmaster                    ==============
running on port 61696 with PID 61955
============== creating database "regression"         ==============
CREATE DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
============== running regression test queries        ==============
test test_setup                   ... ok          469 ms
test tablespace                   ... ok          415 ms
parallel group (20 tests):  varchar char oid name int2 pg_lsn int4 txid text uuid regproc boolean money float4 int8 float8 bit enum numeric rangetypes
     boolean                      ... ok          105 ms
     char                         ... ok           64 ms
     name                         ... ok           70 ms
     varchar                      ... ok           55 ms
<...snip...>
     memoize                      ... ok          149 ms
     stats                        ... ok          873 ms
parallel group (2 tests):  event_trigger oidjoins
     event_trigger                ... FAILED      142 ms
     oidjoins                     ... FAILED      208 ms
test fast_default                 ... ok          172 ms
============== shutting down postmaster               ==============

========================
 2 of 214 tests failed.
========================

The differences that caused some tests to fail can be viewed in the
file "/<path>/src/test/regress/regression.diffs".  A copy of the test summary that you see
above is saved in the file "/<path>/src/test/regress/regression.out".


There is a slight reduction in information, for example around tests run
serially vs in a parallel group.  This could perhaps be handled by marking the
test name in some way like "tablespace (serial) or prefixing with a symbol or
somerthing.  I can take a stab at that in case we think that level of detail is
important to preserve.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v6-0001-Make-pg_regress-output-format-TAP-compliant.patch (31.5K, ../../[email protected]/2-v6-0001-Make-pg_regress-output-format-TAP-compliant.patch)
  download | inline diff:
From 0eaf6a8a7aa44ac1cf4cca81b787600e2d0d03dc Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Wed, 17 Aug 2022 22:53:48 +0200
Subject: [PATCH v6] Make pg_regress output format TAP compliant

This converts pg_regress output format to emit TAP complient 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 all output from pg_regress had to be addressed,  the frontend log
framework was also brought to use as it was already being set up but
not used.
---
 src/test/regress/pg_regress.c | 439 +++++++++++++++++-----------------
 1 file changed, 224 insertions(+), 215 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 9ca1a8d906..3989b12535 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -92,6 +92,7 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static bool has_status = false;
 
 /* internal variables */
 static const char *progname;
@@ -115,11 +116,15 @@ static int	fail_ignore_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 test_status_ok(const char *testname, double runtime);
+static void test_status_failed(const char *testname, bool ignore, char *tags, double runtime);
+static void bail(const char *fmt,...);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -133,9 +138,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);
+		pg_log_error(_("could not set core size: disallowed by hard limit"));
 		return;
 	}
 	else if (lim.rlim_max == RLIM_INFINITY || lim.rlim_cur < lim.rlim_max)
@@ -201,20 +204,79 @@ 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.
  */
 static void
-header(const char *fmt,...)
+bail(const char *fmt,...)
 {
-	char		tmp[64];
+	char		tmp[256];
 	va_list		ap;
 
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	status("\nBail out! %s", tmp);
+
+	status_end();
+	exit(2);
+}
+
+static void
+test_status_ok(const char *testname, double runtime)
+{
+	int		testnumber;
+	int 	indent;
+
+	success_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 28 - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %i - %-*s %8.0f ms",
+		   testnumber, indent,
+		   testname,
+		   runtime);
+}
+
+
+static void
+test_status_failed(const char *testname, bool ignore, char *tags, double runtime)
+{
+	int		testnumber;
+	int		indent;
+
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 28 - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "(not) ok" are protocol messages */
+	if (ignore)
+	{
+		status("ok %i - %-*s %8.0f ms # SKIP (ignored)",
+			   testnumber, indent,
+			   testname,
+			   runtime);
+	}
+	else
+	{
+		indent -= 4;
+		status("not ok %i - %-*s %8.0f ms",
+			   testnumber, indent,
+			   testname,
+			   runtime);
+	}
+
+	if (tags && strlen(tags) > 0)
+		status("\n# tags: %s", tags);
 }
 
 /*
@@ -225,6 +287,7 @@ status(const char *fmt,...)
 {
 	va_list		ap;
 
+	has_status = true;
 	va_start(ap, fmt);
 	vfprintf(stdout, fmt, ap);
 	fflush(stdout);
@@ -244,6 +307,10 @@ status(const char *fmt,...)
 static void
 status_end(void)
 {
+	if (!has_status)
+		return;
+
+	has_status = false;
 	fprintf(stdout, "\n");
 	fflush(stdout);
 	if (logfile)
@@ -274,8 +341,9 @@ stop_postmaster(void)
 		r = system(buf);
 		if (r != 0)
 		{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			/* Not using the normal bail() as we want _exit */
+			status("\nBail out! ");
+			status(_("could not stop postmaster: exit code was %d"), r);
 			_exit(2);			/* not exit(), that could be recursive */
 		}
 
@@ -334,9 +402,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. */
@@ -458,9 +525,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))
@@ -479,26 +545,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';
 
@@ -744,13 +804,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			status(_("# (using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			status(_("# (using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			status(_("# (using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			status(_("# (using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -799,34 +859,30 @@ 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());
+		pg_log_error("could not open process token: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not get token information buffer size: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 	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());
+		pg_log_error("could not get token information: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not look up account SID: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
@@ -976,7 +1032,7 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X -q",
 					 bindir ? bindir : "",
 					 bindir ? "/" : "");
 	return buf;
@@ -1031,8 +1087,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 */
@@ -1077,9 +1132,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)
 	{
@@ -1094,8 +1147,9 @@ 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));
+		/* Not using the normal bail() here as we want _exit */
+		status("\nBail out! ");
+		status(_("could not exec \"%s\": %s"), shellprog, strerror(errno));
 		_exit(1);				/* not exit() here... */
 	}
 	/* in parent */
@@ -1134,8 +1188,8 @@ file_size(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+					 file, strerror(errno));
 		return -1;
 	}
 	fseek(f, 0, SEEK_END);
@@ -1156,8 +1210,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));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+				file, strerror(errno));
 		return -1;
 	}
 	while ((c = fgetc(f)) != EOF)
@@ -1198,9 +1252,8 @@ 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));
 	}
 }
 
@@ -1249,8 +1302,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
 
@@ -1260,8 +1312,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
 
@@ -1332,9 +1383,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))
@@ -1449,9 +1499,8 @@ 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;
@@ -1460,9 +1509,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 */
@@ -1500,20 +1548,20 @@ static void
 log_child_failure(int exitstatus)
 {
 	if (WIFEXITED(exitstatus))
-		status(_(" (test process exited with exit code %d)"),
+		status(_("# (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)"),
+		status(_("# (test process was terminated by exception 0x%X)"),
 			   WTERMSIG(exitstatus));
 #else
-		status(_(" (test process was terminated by signal %d: %s)"),
+		status(_("# (test process was terminated by signal %d: %s)"),
 			   WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
 #endif
 	}
 	else
-		status(_(" (test process exited with unrecognized status %d)"),
+		status(_("# (test process exited with unrecognized status %d)"),
 			   exitstatus);
 }
 
@@ -1537,18 +1585,20 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	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))
@@ -1586,9 +1636,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		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\n"),
+				 schedule, line_num, scbuf);
 		}
 
 		num_tests = 0;
@@ -1604,9 +1653,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\n"),
+							 MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
 					}
 					sav = *c;
 					*c = '\0';
@@ -1628,14 +1676,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\n"),
+				 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);
@@ -1643,16 +1689,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\n"),
+				 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);
+			status(_("# parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1672,7 +1717,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			status(_("# parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1690,8 +1735,9 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
-			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+			resetStringInfo(&tagbuf);
+
+			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1712,7 +1758,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1730,29 +1776,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data, INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 			}
 			else
-			{
-				status(_("ok    "));	/* align with FAILED */
-				success_count++;
-			}
+				test_status_ok(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
-			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
-
 			status_end();
 		}
 
@@ -1766,6 +1798,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1789,11 +1822,12 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1814,27 +1848,22 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
+	INSTR_TIME_SUBTRACT(stoptime, starttime);
+
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data, INSTR_TIME_GET_MILLISEC(stoptime));
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test, INSTR_TIME_GET_MILLISEC(stoptime));
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
-	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1858,9 +1887,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, logfilename, strerror(errno));
 	}
 
 	/* create the diffs file as empty */
@@ -1869,9 +1897,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, difffilename, strerror(errno));
 	}
 	/* we don't keep the diffs file open continuously */
 	fclose(difffile);
@@ -1887,7 +1914,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);
@@ -1904,7 +1930,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'" : "");
@@ -1926,10 +1951,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
@@ -1937,7 +1959,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);
@@ -1949,7 +1970,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)
 	{
@@ -2166,7 +2186,7 @@ regression_main(int argc, char *argv[],
 				break;
 			default:
 				/* getopt_long already emitted a complaint */
-				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
+				pg_log_error_hint("Try \"%s --help\" for more information.",
 						progname);
 				exit(2);
 		}
@@ -2228,17 +2248,13 @@ 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(_("%s: could not remove temp instance \"%s\""),
+							 progname, temp_instance);
 			}
 		}
 
-		header(_("creating temporary instance"));
-
 		/* make the temp instance top directory */
 		make_directory(temp_instance);
 
@@ -2248,7 +2264,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 : "",
@@ -2259,8 +2274,8 @@ regression_main(int argc, char *argv[],
 				 outputdir);
 		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(_("%s: initdb failed\nExamine %s/log/initdb.log for the reason.\nCommand was: %s"),
+				 progname, outputdir, buf);
 		}
 
 		/*
@@ -2275,8 +2290,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( _("%s: could not open \"%s\" for adding extra config: %s"),
+				 progname, buf, strerror(errno));
 		}
 		fputs("\n# Configuration added by pg_regress\n\n", pg_conf);
 		fputs("log_autovacuum_min_duration = 0\n", pg_conf);
@@ -2295,8 +2310,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(_("%s: could not open \"%s\" to read extra config: %s"),
+					 progname, temp_config, strerror(errno));
 			}
 			while (fgets(line_buf, sizeof(line_buf), extra_conf) != NULL)
 				fputs(line_buf, pg_conf);
@@ -2334,14 +2349,14 @@ regression_main(int argc, char *argv[],
 
 				if (port_specified_by_user || i == 15)
 				{
-					fprintf(stderr, _("port %d apparently in use\n"), port);
+					status(_("# port %d apparently in use\n"), 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);
+						status(_("# could not determine an available port\n"));
+					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);
+				status(_("# port %d apparently in use, trying %d\n"),
+						port, port + 1);
 				port++;
 				sprintf(s, "%d", port);
 				setenv("PGPORT", s, 1);
@@ -2353,7 +2368,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\" "
@@ -2365,11 +2379,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\n"), strerror(errno));
 
 		/*
 		 * Wait till postmaster is able to accept connections; normally this
@@ -2403,16 +2413,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\nExamine %s/log/postmaster.log for the reason\n"),
+					 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);
+			status(_("# postmaster did not respond within %d seconds\nExamine %s/log/postmaster.log for the reason\n"),
+					wait_seconds, outputdir);
 
 			/*
 			 * If we get here, the postmaster is probably wedged somewhere in
@@ -2421,17 +2431,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;
@@ -2442,7 +2449,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		status(_("# running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2474,8 +2481,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);
@@ -2491,7 +2496,6 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance)
 	{
-		header(_("shutting down postmaster"));
 		stop_postmaster();
 	}
 
@@ -2502,62 +2506,67 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance && fail_count == 0 && fail_ignore_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);
+			pg_log_error("could not remove temp instance \"%s\"",
+						 temp_instance);
 	}
 
-	fclose(logfile);
+	/*
+	 * Emit a TAP compliant Plan
+	 */
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
 
 	/*
 	 * Emit nice-looking summary message
 	 */
 	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
+		status(_("# All %d tests passed."), success_count);
+	/* fail_count=0, fail_ignore_count>0 */
+	else if (fail_count == 0)
+		status(_("# %d of %d tests passed, %d failed test(s) ignored."),
+			   success_count,
+			   success_count + fail_ignore_count,
+			   fail_ignore_count);
+	/* fail_count>0 && fail_ignore_count=0 */
+	else if (fail_ignore_count == 0)
+		status(_("# %d of %d tests failed."),
+			   fail_count,
+			   success_count + fail_count);
+	/* fail_count>0 && fail_ignore_count>0 */
 	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
+		status(_("# %d of %d tests failed, %d of these failures ignored."),
+			   fail_count + fail_ignore_count,
+			   success_count + fail_count + fail_ignore_count,
+			   fail_ignore_count);
 
+	/*
+	 * In order for this information (or any error information) to be shown
+	 * when running pg_regress test suites under prove it needs to be emitted
+	 * stderr instead of stdout.
+	 */
 	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"),
+		status(_("\n# 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);
 	}
 	else
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	status_end();
+
+	fclose(logfile);
+	logfile = NULL;
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.32.1 (Apple Git-133)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-08-17 22:49  Andres Freund <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Andres Freund @ 2022-08-17 22:49 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; +Cc: Tom Lane <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

Hi,

On 2022-08-17 23:04:20 +0200, Daniel Gustafsson wrote:
> Attached is a new version of the pg_regress TAP patch which - per reviewer
> feedback - does away with dual output formats and just converts the existing
> output to be TAP complaint.

Cool.


> while still be TAP compliant enough that running it with prove (with a tiny
> Perl wrapper) works.

Wonder if we could utilize that for making failures of 002_pg_upgrade.pl and
027_stream_regress.pl easier to understand, by reporting pg_regress' steps as
part of the outer test. But that'd probably be at least somewhat hard, due to
the embedded test count etc.


> This version also strips away the verbose output which these days isn't
> terribly useful and mainly consume vertical space.

Yay.


> Another feature of the patch is to switch error logging to using the common
> frontend logging rather than pg_regress rolling its own.  The output from
> pg_log_error is emitted verbatim by prove as it's on stderr.

Sounds good.


> I based the support on the original TAP specification and not the new v13 or
> v14 since it seemed unclear how well those are supported in testrunners.  If
> v14 is adopted by testrunners there are some better functionality for reporting
> errors that we could use, but for how this version seems a safer option.

Yep, that makes sense.

> A normal "make check" with this patch applied now looks like this:
>
>
> +++ regress check in src/test/regress +++
> # running on port 61696 with PID 57910
> ok 1 - test_setup                       326 ms
> ok 2 - tablespace                       401 ms
> # parallel group (20 tests):  varchar char oid pg_lsn txid int4 regproc money int2 uuid float4 text name boolean int8 enum float8 bit numeric rangetypes
> ok 3 - boolean                          129 ms
> ok 4 - char                              73 ms
> ok 5 - name                             117 ms
> ok 6 - varchar                           68 ms
> <...snip...>
> ok 210 - memoize                        137 ms
> ok 211 - stats                          851 ms
> # parallel group (2 tests):  event_trigger oidjoins
> ok 212 - event_trigger                  138 ms
> not ok 213 - oidjoins                   190 ms
> ok 214 - fast_default                   149 ms
> 1..214
> # 1 of 214 tests failed.
> # The differences that caused some tests to fail can be viewed in the
> # file "/<path>/src/test/regress/regression.diffs".  A copy of the test summary that you see
> # above is saved in the file "/<path>/src/test/regress/regression.out".

I'm happy with that compared to our current output.


> The ending comment isn't currently shown when executed via prove as it has to
> go to STDERR for that to work, and I'm not sure that's something we want to do
> in the general case.  I don't expect running the pg_regress tests via prove is
> going to be the common case.  How does the meson TAP ingestion handle
> stdout/stderr?

It'll parse stdout for tap output and log stderr output separately.


> There is a slight reduction in information, for example around tests run
> serially vs in a parallel group.  This could perhaps be handled by marking the
> test name in some way like "tablespace (serial) or prefixing with a symbol or
> somerthing.  I can take a stab at that in case we think that level of detail is
> important to preserve.

I think we could just indent the test "description" for tests in parallel
groups:

I.e. instead of

ok 1 - test_setup                       326 ms
ok 2 - tablespace                       401 ms
# parallel group (20 tests):  varchar char oid pg_lsn txid int4 regproc money int2 uuid float4 text name boolean int8 enum float8 bit numeric rangetypes
ok 3 - boolean                          129 ms
ok 4 - char                              73 ms
ok 5 - name                             117 ms
ok 6 - varchar                           68 ms

do

ok 1 - test_setup                       326 ms
ok 2 - tablespace                       401 ms
# parallel group (20 tests):  varchar char oid pg_lsn txid int4 regproc money int2 uuid float4 text name boolean int8 enum float8 bit numeric rangetypes
ok 3 -         boolean                  129 ms
ok 4 -         char                      73 ms
ok 5 -         name                     117 ms
ok 6 -         varchar                   68 ms

that'd make it sufficiently clear, and is a bit more similar to the current
format?


I wonder if we should indent the test name so that the number doesn't cause
wrapping? And perhaps we can skip the - in that case?

I.e. instead of:

ok 9 - name                             117 ms
ok 10 - varchar                          68 ms
..
ok 99 - something                        60 ms
ok 100 - memoize                        137 ms

something like:

ok 9    name                            117 ms
ok 10   varchar                          68 ms
...
ok 99   something                        60 ms
ok 100  memoize                         137 ms


with parallel tests:

ok 9    name                            117 ms
# parallel group (2 tests):  varchar varchar2
ok 10           varchar                  68 ms
ok 11           varchar2                139 ms
ok 12   varchar3                         44 ms
ok 99   something                        60 ms
ok 100  memoize                         137 ms


Greetings,

Andres Freund





^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-08-18 11:24  Daniel Gustafsson <[email protected]>
  parent: Andres Freund <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Daniel Gustafsson @ 2022-08-18 11:24 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: Tom Lane <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

> On 18 Aug 2022, at 00:49, Andres Freund <[email protected]> wrote:

>> while still be TAP compliant enough that running it with prove (with a tiny
>> Perl wrapper) works.
> 
> Wonder if we could utilize that for making failures of 002_pg_upgrade.pl and
> 027_stream_regress.pl easier to understand, by reporting pg_regress' steps as
> part of the outer test. But that'd probably be at least somewhat hard, due to
> the embedded test count etc.

I have a feeling it might require some quite bespoke logic to tie it together
(which may not be worth it in the end) but I'll have a look.

>> A normal "make check" with this patch applied now looks like this:
>> 
>> ...
> 
> I'm happy with that compared to our current output.

Great!  Once this thread has settled on a format, maybe it should go to a
separate -hackers thread to get more visibility and (hopefully) buy-in for such
a change.

One thing I haven't researched yet is if the Buildfarm or CFBot parses the
current output in any way or just check the exit status of the testrun.

>> The ending comment isn't currently shown when executed via prove as it has to
>> go to STDERR for that to work, and I'm not sure that's something we want to do
>> in the general case.  I don't expect running the pg_regress tests via prove is
>> going to be the common case.  How does the meson TAP ingestion handle
>> stdout/stderr?
> 
> It'll parse stdout for tap output and log stderr output separately.

Then I think this patch will be compatible with that.

>> There is a slight reduction in information, for example around tests run
>> serially vs in a parallel group.  This could perhaps be handled by marking the
>> test name in some way like "tablespace (serial) or prefixing with a symbol or
>> somerthing.  I can take a stab at that in case we think that level of detail is
>> important to preserve.
> 
> I think we could just indent the test "description" for tests in parallel
> groups:
> 
> I.e. instead of
> 
> ok 6 - varchar                           68 ms
> ...
> ok 6 -         varchar                   68 ms
> 
> that'd make it sufficiently clear, and is a bit more similar to the current
> format?

Thats a better option, done that way.

> I wonder if we should indent the test name so that the number doesn't cause
> wrapping?

The tricky part there is that we don't know beforehands how many tests will be
run.  We could add a first pass over the schedule, which seems excessive for
this, or align with a fixed max such that 9999 number of tests is the maximum
number of tests which will print neatly aligned.

> And perhaps we can skip the - in that case?

The dash is listed as "Recommended" but not required in the TAP spec (including
up to v14) so we can skip it.

With these changes, the "worst case" output in terms of testnames alignment
would be something like this (assuming at most 9999 tests):

ok 211               stats                          852 ms
# parallel group (2 tests):  event_trigger oidjoins
ok 212               event_trigger                  149 ms
not ok 213           oidjoins                       194 ms
ok 214       fast_default                           178 ms
1..214

I think that's fairly readable, and not that much different from today.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v7-0001-Make-pg_regress-output-format-TAP-compliant.patch (32.2K, ../../[email protected]/2-v7-0001-Make-pg_regress-output-format-TAP-compliant.patch)
  download | inline diff:
From fe168dae50622989a60c51ba4076f6c3f4297c31 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Wed, 17 Aug 2022 22:53:48 +0200
Subject: [PATCH v7] Make pg_regress output format TAP compliant

This converts pg_regress output format to emit TAP complient 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 all output from pg_regress had to be addressed,  the frontend log
framework was also brought to use as it was already being set up but
not used.
---
 src/test/regress/pg_regress.c | 447 ++++++++++++++++++----------------
 1 file changed, 232 insertions(+), 215 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 9ca1a8d906..f2effe06f8 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -92,6 +92,7 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static bool has_status = false;
 
 /* internal variables */
 static const char *progname;
@@ -115,11 +116,15 @@ static int	fail_ignore_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 test_status_ok(const char *testname, double runtime, bool parallel);
+static void test_status_failed(const char *testname, bool ignore, char *tags, double runtime, bool parallel);
+static void bail(const char *fmt,...);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -133,9 +138,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);
+		pg_log_error(_("could not set core size: disallowed by hard limit"));
 		return;
 	}
 	else if (lim.rlim_max == RLIM_INFINITY || lim.rlim_cur < lim.rlim_max)
@@ -201,20 +204,87 @@ 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.
  */
 static void
-header(const char *fmt,...)
+bail(const char *fmt,...)
 {
-	char		tmp[64];
+	char		tmp[256];
 	va_list		ap;
 
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	status("\nBail out! %s", tmp);
+
+	status_end();
+	exit(2);
+}
+
+/*
+ * Testnumbers are padded to 5 characters to ensure that a base 10 increase
+ * doesn't alter testname alignment (assuming at most 9999 tests). Testnames
+ * are indented 8 spaces in case they run as part of a parallel group. The
+ * position for the runtime is then calculated based on the horizontal space
+ * consumed by testname and testnumber.
+ */
+static void
+test_status_ok(const char *testname, double runtime, bool parallel)
+{
+	int		testnumber;
+	int 	indent;
+
+	success_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 36 - (parallel ? 8 : 0) - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %-5i     %s%-*s %8.0f ms",
+		   testnumber, (parallel ? "        " : ""), indent,
+		   testname,
+		   runtime);
+}
+
+/*
+ * For indentation rules, see test_status_ok.
+ */
+static void
+test_status_failed(const char *testname, bool ignore, char *tags, double runtime, bool parallel)
+{
+	int		testnumber;
+	int		indent;
+
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 36 - (parallel ? 8 : 0) - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "(not) ok" are protocol messages */
+	if (ignore)
+	{
+		status("ok %-5i     %s%-*s %8.0f ms # SKIP (ignored)",
+			   testnumber, (parallel ? "        " : ""), indent,
+			   testname,
+			   runtime);
+	}
+	else
+	{
+		status("not ok %-5i %s%-*s %8.0f ms",
+			   testnumber, (parallel ? "        " : ""), indent,
+			   testname,
+			   runtime);
+	}
+
+	if (tags && strlen(tags) > 0)
+		status("\n# tags: %s", tags);
 }
 
 /*
@@ -225,6 +295,7 @@ status(const char *fmt,...)
 {
 	va_list		ap;
 
+	has_status = true;
 	va_start(ap, fmt);
 	vfprintf(stdout, fmt, ap);
 	fflush(stdout);
@@ -244,6 +315,10 @@ status(const char *fmt,...)
 static void
 status_end(void)
 {
+	if (!has_status)
+		return;
+
+	has_status = false;
 	fprintf(stdout, "\n");
 	fflush(stdout);
 	if (logfile)
@@ -274,8 +349,9 @@ stop_postmaster(void)
 		r = system(buf);
 		if (r != 0)
 		{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			/* Not using the normal bail() as we want _exit */
+			status("\nBail out! ");
+			status(_("could not stop postmaster: exit code was %d"), r);
 			_exit(2);			/* not exit(), that could be recursive */
 		}
 
@@ -334,9 +410,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. */
@@ -458,9 +533,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))
@@ -479,26 +553,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';
 
@@ -744,13 +812,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			status(_("# (using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			status(_("# (using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			status(_("# (using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			status(_("# (using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -799,34 +867,30 @@ 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());
+		pg_log_error("could not open process token: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not get token information buffer size: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 	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());
+		pg_log_error("could not get token information: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not look up account SID: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
@@ -976,7 +1040,7 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X -q",
 					 bindir ? bindir : "",
 					 bindir ? "/" : "");
 	return buf;
@@ -1031,8 +1095,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 */
@@ -1077,9 +1140,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)
 	{
@@ -1094,8 +1155,9 @@ 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));
+		/* Not using the normal bail() here as we want _exit */
+		status("\nBail out! ");
+		status(_("could not exec \"%s\": %s"), shellprog, strerror(errno));
 		_exit(1);				/* not exit() here... */
 	}
 	/* in parent */
@@ -1134,8 +1196,8 @@ file_size(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+					 file, strerror(errno));
 		return -1;
 	}
 	fseek(f, 0, SEEK_END);
@@ -1156,8 +1218,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));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+				file, strerror(errno));
 		return -1;
 	}
 	while ((c = fgetc(f)) != EOF)
@@ -1198,9 +1260,8 @@ 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));
 	}
 }
 
@@ -1249,8 +1310,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
 
@@ -1260,8 +1320,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
 
@@ -1332,9 +1391,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))
@@ -1449,9 +1507,8 @@ 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;
@@ -1460,9 +1517,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 */
@@ -1500,20 +1556,20 @@ static void
 log_child_failure(int exitstatus)
 {
 	if (WIFEXITED(exitstatus))
-		status(_(" (test process exited with exit code %d)"),
+		status(_("# (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)"),
+		status(_("# (test process was terminated by exception 0x%X)"),
 			   WTERMSIG(exitstatus));
 #else
-		status(_(" (test process was terminated by signal %d: %s)"),
+		status(_("# (test process was terminated by signal %d: %s)"),
 			   WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
 #endif
 	}
 	else
-		status(_(" (test process exited with unrecognized status %d)"),
+		status(_("# (test process exited with unrecognized status %d)"),
 			   exitstatus);
 }
 
@@ -1537,18 +1593,20 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	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))
@@ -1586,9 +1644,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		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\n"),
+				 schedule, line_num, scbuf);
 		}
 
 		num_tests = 0;
@@ -1604,9 +1661,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\n"),
+							 MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
 					}
 					sav = *c;
 					*c = '\0';
@@ -1628,14 +1684,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\n"),
+				 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);
@@ -1643,16 +1697,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\n"),
+				 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);
+			status(_("# parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1672,7 +1725,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			status(_("# parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1690,8 +1743,9 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
-			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+			resetStringInfo(&tagbuf);
+
+			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1712,7 +1766,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1730,29 +1784,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data, 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));
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
-			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
-
 			status_end();
 		}
 
@@ -1766,6 +1806,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1789,11 +1830,12 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1814,27 +1856,22 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
+	INSTR_TIME_SUBTRACT(stoptime, starttime);
+
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data, INSTR_TIME_GET_MILLISEC(stoptime), false);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test, INSTR_TIME_GET_MILLISEC(stoptime), false);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
-	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1858,9 +1895,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, logfilename, strerror(errno));
 	}
 
 	/* create the diffs file as empty */
@@ -1869,9 +1905,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, difffilename, strerror(errno));
 	}
 	/* we don't keep the diffs file open continuously */
 	fclose(difffile);
@@ -1887,7 +1922,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);
@@ -1904,7 +1938,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'" : "");
@@ -1926,10 +1959,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
@@ -1937,7 +1967,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);
@@ -1949,7 +1978,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)
 	{
@@ -2166,7 +2194,7 @@ regression_main(int argc, char *argv[],
 				break;
 			default:
 				/* getopt_long already emitted a complaint */
-				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
+				pg_log_error_hint("Try \"%s --help\" for more information.",
 						progname);
 				exit(2);
 		}
@@ -2228,17 +2256,13 @@ 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(_("%s: could not remove temp instance \"%s\""),
+							 progname, temp_instance);
 			}
 		}
 
-		header(_("creating temporary instance"));
-
 		/* make the temp instance top directory */
 		make_directory(temp_instance);
 
@@ -2248,7 +2272,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 : "",
@@ -2259,8 +2282,8 @@ regression_main(int argc, char *argv[],
 				 outputdir);
 		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(_("%s: initdb failed\nExamine %s/log/initdb.log for the reason.\nCommand was: %s"),
+				 progname, outputdir, buf);
 		}
 
 		/*
@@ -2275,8 +2298,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( _("%s: could not open \"%s\" for adding extra config: %s"),
+				 progname, buf, strerror(errno));
 		}
 		fputs("\n# Configuration added by pg_regress\n\n", pg_conf);
 		fputs("log_autovacuum_min_duration = 0\n", pg_conf);
@@ -2295,8 +2318,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(_("%s: could not open \"%s\" to read extra config: %s"),
+					 progname, temp_config, strerror(errno));
 			}
 			while (fgets(line_buf, sizeof(line_buf), extra_conf) != NULL)
 				fputs(line_buf, pg_conf);
@@ -2334,14 +2357,14 @@ regression_main(int argc, char *argv[],
 
 				if (port_specified_by_user || i == 15)
 				{
-					fprintf(stderr, _("port %d apparently in use\n"), port);
+					status(_("# port %d apparently in use\n"), 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);
+						status(_("# could not determine an available port\n"));
+					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);
+				status(_("# port %d apparently in use, trying %d\n"),
+						port, port + 1);
 				port++;
 				sprintf(s, "%d", port);
 				setenv("PGPORT", s, 1);
@@ -2353,7 +2376,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\" "
@@ -2365,11 +2387,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\n"), strerror(errno));
 
 		/*
 		 * Wait till postmaster is able to accept connections; normally this
@@ -2403,16 +2421,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\nExamine %s/log/postmaster.log for the reason\n"),
+					 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);
+			status(_("# postmaster did not respond within %d seconds\nExamine %s/log/postmaster.log for the reason\n"),
+					wait_seconds, outputdir);
 
 			/*
 			 * If we get here, the postmaster is probably wedged somewhere in
@@ -2421,17 +2439,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;
@@ -2442,7 +2457,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		status(_("# running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2474,8 +2489,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);
@@ -2491,7 +2504,6 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance)
 	{
-		header(_("shutting down postmaster"));
 		stop_postmaster();
 	}
 
@@ -2502,62 +2514,67 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance && fail_count == 0 && fail_ignore_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);
+			pg_log_error("could not remove temp instance \"%s\"",
+						 temp_instance);
 	}
 
-	fclose(logfile);
+	/*
+	 * Emit a TAP compliant Plan
+	 */
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
 
 	/*
 	 * Emit nice-looking summary message
 	 */
 	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
+		status(_("# All %d tests passed."), success_count);
+	/* fail_count=0, fail_ignore_count>0 */
+	else if (fail_count == 0)
+		status(_("# %d of %d tests passed, %d failed test(s) ignored."),
+			   success_count,
+			   success_count + fail_ignore_count,
+			   fail_ignore_count);
+	/* fail_count>0 && fail_ignore_count=0 */
+	else if (fail_ignore_count == 0)
+		status(_("# %d of %d tests failed."),
+			   fail_count,
+			   success_count + fail_count);
+	/* fail_count>0 && fail_ignore_count>0 */
 	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
+		status(_("# %d of %d tests failed, %d of these failures ignored."),
+			   fail_count + fail_ignore_count,
+			   success_count + fail_count + fail_ignore_count,
+			   fail_ignore_count);
 
+	/*
+	 * In order for this information (or any error information) to be shown
+	 * when running pg_regress test suites under prove it needs to be emitted
+	 * stderr instead of stdout.
+	 */
 	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"),
+		status(_("\n# 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);
 	}
 	else
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	status_end();
+
+	fclose(logfile);
+	logfile = NULL;
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.32.1 (Apple Git-133)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-08-18 14:40  Andrew Dunstan <[email protected]>
  parent: Daniel Gustafsson <[email protected]>
  0 siblings, 1 reply; 26+ messages in thread

From: Andrew Dunstan @ 2022-08-18 14:40 UTC (permalink / raw)
  To: Daniel Gustafsson <[email protected]>; Andres Freund <[email protected]>; +Cc: Tom Lane <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>


On 2022-08-18 Th 07:24, Daniel Gustafsson wrote:
>
> One thing I haven't researched yet is if the Buildfarm or CFBot parses the
> current output in any way or just check the exit status of the testrun.
>
>

Buildfarm: just the status.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com






^ permalink  raw  reply  [nested|flat] 26+ messages in thread

* Re: TAP output format in pg_regress
@ 2022-09-01 12:21  Daniel Gustafsson <[email protected]>
  parent: Andrew Dunstan <[email protected]>
  0 siblings, 0 replies; 26+ messages in thread

From: Daniel Gustafsson @ 2022-09-01 12:21 UTC (permalink / raw)
  To: Andrew Dunstan <[email protected]>; +Cc: Andres Freund <[email protected]>; Tom Lane <[email protected]>; Peter Eisentraut <[email protected]>; PostgreSQL Developers <[email protected]>

> On 18 Aug 2022, at 16:40, Andrew Dunstan <[email protected]> wrote:
> 
> On 2022-08-18 Th 07:24, Daniel Gustafsson wrote:
>> 
>> One thing I haven't researched yet is if the Buildfarm or CFBot parses the
>> current output in any way or just check the exit status of the testrun.
> 
> Buildfarm: just the status.

Thanks for confirming, the same is true for CFBot AFAICT.

Attached is a v8 which fixes a compiler warning detected by the CFBot.

--
Daniel Gustafsson		https://vmware.com/



Attachments:

  [application/octet-stream] v8-0001-Make-pg_regress-output-format-TAP-compliant.patch (32.3K, ../../[email protected]/2-v8-0001-Make-pg_regress-output-format-TAP-compliant.patch)
  download | inline diff:
From fc68fd94895d8306dbbec709409a18b22a1679f7 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Wed, 17 Aug 2022 22:53:48 +0200
Subject: [PATCH v8] Make pg_regress output format TAP compliant

This converts pg_regress output format to emit TAP complient 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 all output from pg_regress had to be addressed,  the frontend log
framework was also brought to use as it was already being set up but
not used.
---
 src/test/regress/pg_regress.c | 448 ++++++++++++++++++----------------
 1 file changed, 233 insertions(+), 215 deletions(-)

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 7290948eee..db86d79071 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -19,6 +19,7 @@
 #include "postgres_fe.h"
 
 #include <ctype.h>
+#include <math.h>
 #include <sys/resource.h>
 #include <sys/stat.h>
 #include <sys/time.h>
@@ -93,6 +94,7 @@ static char *dlpath = PKGLIBDIR;
 static char *user = NULL;
 static _stringlist *extraroles = NULL;
 static char *config_auth_datadir = NULL;
+static bool has_status = false;
 
 /* internal variables */
 static const char *progname;
@@ -116,11 +118,15 @@ static int	fail_ignore_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 test_status_ok(const char *testname, double runtime, bool parallel);
+static void test_status_failed(const char *testname, bool ignore, char *tags, double runtime, bool parallel);
+static void bail(const char *fmt,...);
+
 static void status(const char *fmt,...) pg_attribute_printf(1, 2);
 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);
+static void status_end(void);
 
 /*
  * allow core files if possible.
@@ -134,9 +140,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);
+		pg_log_error(_("could not set core size: disallowed by hard limit"));
 		return;
 	}
 	else if (lim.rlim_max == RLIM_INFINITY || lim.rlim_cur < lim.rlim_max)
@@ -202,20 +206,87 @@ 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.
  */
 static void
-header(const char *fmt,...)
+bail(const char *fmt,...)
 {
-	char		tmp[64];
+	char		tmp[256];
 	va_list		ap;
 
 	va_start(ap, fmt);
 	vsnprintf(tmp, sizeof(tmp), fmt, ap);
 	va_end(ap);
 
-	fprintf(stdout, "============== %-38s ==============\n", tmp);
-	fflush(stdout);
+	status("\nBail out! %s", tmp);
+
+	status_end();
+	exit(2);
+}
+
+/*
+ * Testnumbers are padded to 5 characters to ensure that a base 10 increase
+ * doesn't alter testname alignment (assuming at most 9999 tests). Testnames
+ * are indented 8 spaces in case they run as part of a parallel group. The
+ * position for the runtime is then calculated based on the horizontal space
+ * consumed by testname and testnumber.
+ */
+static void
+test_status_ok(const char *testname, double runtime, bool parallel)
+{
+	int		testnumber;
+	int 	indent;
+
+	success_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 36 - (parallel ? 8 : 0) - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "ok" is a protocol message */
+	status("ok %-5i     %s%-*s %8.0f ms",
+		   testnumber, (parallel ? "        " : ""), indent,
+		   testname,
+		   runtime);
+}
+
+/*
+ * For indentation rules, see test_status_ok.
+ */
+static void
+test_status_failed(const char *testname, bool ignore, char *tags, double runtime, bool parallel)
+{
+	int		testnumber;
+	int		indent;
+
+	if (ignore)
+		fail_ignore_count++;
+	else
+		fail_count++;
+
+	testnumber = fail_count + fail_ignore_count + success_count;
+	/* Calculate an offset to align runtimes vertically */
+	indent = 36 - (parallel ? 8 : 0) - floor(log10(testnumber) + 1);
+
+	/* There is no NLS translation here as "(not) ok" are protocol messages */
+	if (ignore)
+	{
+		status("ok %-5i     %s%-*s %8.0f ms # SKIP (ignored)",
+			   testnumber, (parallel ? "        " : ""), indent,
+			   testname,
+			   runtime);
+	}
+	else
+	{
+		status("not ok %-5i %s%-*s %8.0f ms",
+			   testnumber, (parallel ? "        " : ""), indent,
+			   testname,
+			   runtime);
+	}
+
+	if (tags && strlen(tags) > 0)
+		status("\n# tags: %s", tags);
 }
 
 /*
@@ -226,6 +297,7 @@ status(const char *fmt,...)
 {
 	va_list		ap;
 
+	has_status = true;
 	va_start(ap, fmt);
 	vfprintf(stdout, fmt, ap);
 	fflush(stdout);
@@ -245,6 +317,10 @@ status(const char *fmt,...)
 static void
 status_end(void)
 {
+	if (!has_status)
+		return;
+
+	has_status = false;
 	fprintf(stdout, "\n");
 	fflush(stdout);
 	if (logfile)
@@ -272,8 +348,9 @@ stop_postmaster(void)
 		r = system(buf);
 		if (r != 0)
 		{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			/* Not using the normal bail() as we want _exit */
+			status("\nBail out! ");
+			status(_("could not stop postmaster: exit code was %d"), r);
 			_exit(2);			/* not exit(), that could be recursive */
 		}
 
@@ -332,9 +409,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. */
@@ -456,9 +532,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))
@@ -477,26 +552,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';
 
@@ -742,13 +811,13 @@ initialize_environment(void)
 		}
 
 		if (pghost && pgport)
-			printf(_("(using postmaster on %s, port %s)\n"), pghost, pgport);
+			status(_("# (using postmaster on %s, port %s)\n"), pghost, pgport);
 		if (pghost && !pgport)
-			printf(_("(using postmaster on %s, default port)\n"), pghost);
+			status(_("# (using postmaster on %s, default port)\n"), pghost);
 		if (!pghost && pgport)
-			printf(_("(using postmaster on Unix socket, port %s)\n"), pgport);
+			status(_("# (using postmaster on Unix socket, port %s)\n"), pgport);
 		if (!pghost && !pgport)
-			printf(_("(using postmaster on Unix socket, default port)\n"));
+			status(_("# (using postmaster on Unix socket, default port)\n"));
 	}
 
 	load_resultmap();
@@ -797,34 +866,30 @@ 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());
+		pg_log_error("could not open process token: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not get token information buffer size: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 	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());
+		pg_log_error("could not get token information: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
 	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());
+		pg_log_error("could not look up account SID: error code %lu",
+					 GetLastError());
 		exit(2);
 	}
 
@@ -974,7 +1039,7 @@ psql_start_command(void)
 	StringInfo	buf = makeStringInfo();
 
 	appendStringInfo(buf,
-					 "\"%s%spsql\" -X",
+					 "\"%s%spsql\" -X -q",
 					 bindir ? bindir : "",
 					 bindir ? "/" : "");
 	return buf;
@@ -1030,8 +1095,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 */
@@ -1072,9 +1136,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)
 	{
@@ -1089,8 +1151,9 @@ 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));
+		/* Not using the normal bail() here as we want _exit */
+		status("\nBail out! ");
+		status(_("could not exec \"%s\": %s"), shellprog, strerror(errno));
 		_exit(1);				/* not exit() here... */
 	}
 	/* in parent */
@@ -1129,8 +1192,8 @@ file_size(const char *file)
 
 	if (!f)
 	{
-		fprintf(stderr, _("%s: could not open file \"%s\" for reading: %s\n"),
-				progname, file, strerror(errno));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+					 file, strerror(errno));
 		return -1;
 	}
 	fseek(f, 0, SEEK_END);
@@ -1151,8 +1214,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));
+		pg_log_error(_("# could not open file \"%s\" for reading: %s"),
+				file, strerror(errno));
 		return -1;
 	}
 	while ((c = fgetc(f)) != EOF)
@@ -1193,9 +1256,8 @@ 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));
 	}
 }
 
@@ -1245,8 +1307,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
 
@@ -1256,8 +1317,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
 
@@ -1328,9 +1388,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))
@@ -1445,9 +1504,8 @@ 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;
@@ -1456,9 +1514,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 */
@@ -1496,20 +1553,20 @@ static void
 log_child_failure(int exitstatus)
 {
 	if (WIFEXITED(exitstatus))
-		status(_(" (test process exited with exit code %d)"),
+		status(_("# (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)"),
+		status(_("# (test process was terminated by exception 0x%X)"),
 			   WTERMSIG(exitstatus));
 #else
-		status(_(" (test process was terminated by signal %d: %s)"),
+		status(_("# (test process was terminated by signal %d: %s)"),
 			   WTERMSIG(exitstatus), pg_strsignal(WTERMSIG(exitstatus)));
 #endif
 	}
 	else
-		status(_(" (test process exited with unrecognized status %d)"),
+		status(_("# (test process exited with unrecognized status %d)"),
 			   exitstatus);
 }
 
@@ -1533,18 +1590,20 @@ run_schedule(const char *schedule, test_start_function startfunc,
 	char		scbuf[1024];
 	FILE	   *scf;
 	int			line_num = 0;
+	StringInfoData tagbuf;
 
 	memset(tests, 0, sizeof(tests));
 	memset(resultfiles, 0, sizeof(resultfiles));
 	memset(expectfiles, 0, sizeof(expectfiles));
 	memset(tags, 0, sizeof(tags));
 
+	initStringInfo(&tagbuf);
+
 	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))
@@ -1582,9 +1641,8 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		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\n"),
+				 schedule, line_num, scbuf);
 		}
 
 		num_tests = 0;
@@ -1600,9 +1658,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\n"),
+							 MAX_PARALLEL_TESTS, schedule, line_num, scbuf);
 					}
 					sav = *c;
 					*c = '\0';
@@ -1624,14 +1681,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\n"),
+				 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);
@@ -1639,16 +1694,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\n"),
+				 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);
+			status(_("# parallel group (%d tests, in groups of %d): "),
+					  num_tests, max_connections);
 			for (i = 0; i < num_tests; i++)
 			{
 				if (i - oldest >= max_connections)
@@ -1668,7 +1722,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 		else
 		{
-			status(_("parallel group (%d tests): "), num_tests);
+			status(_("# parallel group (%d tests): "), num_tests);
 			for (i = 0; i < num_tests; i++)
 			{
 				pids[i] = (startfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[i]);
@@ -1686,8 +1740,9 @@ run_schedule(const char *schedule, test_start_function startfunc,
 					   *tl;
 			bool		differ = false;
 
-			if (num_tests > 1)
-				status(_("     %-28s ... "), tests[i]);
+			resetStringInfo(&tagbuf);
+
+			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
 
 			/*
 			 * Advance over all three lists simultaneously.
@@ -1708,7 +1763,7 @@ 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);
+					appendStringInfo(&tagbuf, "%s ", tl->str);
 				}
 				differ |= newdiff;
 			}
@@ -1726,29 +1781,15 @@ run_schedule(const char *schedule, test_start_function startfunc,
 						break;
 					}
 				}
-				if (ignore)
-				{
-					status(_("failed (ignored)"));
-					fail_ignore_count++;
-				}
-				else
-				{
-					status(_("FAILED"));
-					fail_count++;
-				}
+
+				test_status_failed(tests[i], ignore, tagbuf.data, 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));
 
 			if (statuses[i] != 0)
 				log_child_failure(statuses[i]);
 
-			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
-
 			status_end();
 		}
 
@@ -1762,6 +1803,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
 		}
 	}
 
+	pg_free(tagbuf.data);
 	free_stringlist(&ignorelist);
 
 	fclose(scf);
@@ -1785,11 +1827,12 @@ run_single_test(const char *test, test_start_function startfunc,
 			   *el,
 			   *tl;
 	bool		differ = false;
+	StringInfoData tagbuf;
 
-	status(_("test %-28s ... "), test);
 	pid = (startfunc) (test, &resultfiles, &expectfiles, &tags);
 	INSTR_TIME_SET_CURRENT(starttime);
 	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
+	initStringInfo(&tagbuf);
 
 	/*
 	 * Advance over all three lists simultaneously.
@@ -1810,27 +1853,22 @@ 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);
+			appendStringInfo(&tagbuf, "%s ", tl->str);
 		}
 		differ |= newdiff;
 	}
 
+	INSTR_TIME_SUBTRACT(stoptime, starttime);
+
 	if (differ)
-	{
-		status(_("FAILED"));
-		fail_count++;
-	}
+		test_status_failed(test, false, tagbuf.data, INSTR_TIME_GET_MILLISEC(stoptime), false);
 	else
-	{
-		status(_("ok    "));	/* align with FAILED */
-		success_count++;
-	}
+		test_status_ok(test, INSTR_TIME_GET_MILLISEC(stoptime), false);
 
 	if (exit_status != 0)
 		log_child_failure(exit_status);
 
-	INSTR_TIME_SUBTRACT(stoptime, starttime);
-	status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptime));
+	pg_free(tagbuf.data);
 
 	status_end();
 }
@@ -1854,9 +1892,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, logfilename, strerror(errno));
 	}
 
 	/* create the diffs file as empty */
@@ -1865,9 +1902,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(_("%s: could not open file \"%s\" for writing: %s"),
+			 progname, difffilename, strerror(errno));
 	}
 	/* we don't keep the diffs file open continuously */
 	fclose(difffile);
@@ -1883,7 +1919,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);
@@ -1900,7 +1935,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'" : "");
@@ -1922,10 +1956,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
@@ -1933,7 +1964,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);
@@ -1945,7 +1975,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)
 	{
@@ -2167,7 +2196,7 @@ regression_main(int argc, char *argv[],
 				break;
 			default:
 				/* getopt_long already emitted a complaint */
-				fprintf(stderr, _("\nTry \"%s -h\" for more information.\n"),
+				pg_log_error_hint("Try \"%s --help\" for more information.",
 						progname);
 				exit(2);
 		}
@@ -2230,17 +2259,13 @@ 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(_("%s: could not remove temp instance \"%s\""),
+							 progname, temp_instance);
 			}
 		}
 
-		header(_("creating temporary instance"));
-
 		/* make the temp instance top directory */
 		make_directory(temp_instance);
 
@@ -2250,7 +2275,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 : "",
@@ -2262,8 +2286,8 @@ 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(_("%s: initdb failed\nExamine %s/log/initdb.log for the reason.\nCommand was: %s"),
+				 progname, outputdir, buf);
 		}
 
 		/*
@@ -2278,8 +2302,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( _("%s: could not open \"%s\" for adding extra config: %s"),
+				 progname, buf, strerror(errno));
 		}
 		fputs("\n# Configuration added by pg_regress\n\n", pg_conf);
 		fputs("log_autovacuum_min_duration = 0\n", pg_conf);
@@ -2298,8 +2322,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(_("%s: could not open \"%s\" to read extra config: %s"),
+					 progname, temp_config, strerror(errno));
 			}
 			while (fgets(line_buf, sizeof(line_buf), extra_conf) != NULL)
 				fputs(line_buf, pg_conf);
@@ -2338,14 +2362,14 @@ regression_main(int argc, char *argv[],
 
 				if (port_specified_by_user || i == 15)
 				{
-					fprintf(stderr, _("port %d apparently in use\n"), port);
+					status(_("# port %d apparently in use\n"), 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);
+						status(_("# could not determine an available port\n"));
+					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);
+				status(_("# port %d apparently in use, trying %d\n"),
+						port, port + 1);
 				port++;
 				sprintf(s, "%d", port);
 				setenv("PGPORT", s, 1);
@@ -2357,7 +2381,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\" "
@@ -2369,11 +2392,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\n"), strerror(errno));
 
 		/*
 		 * Wait till postmaster is able to accept connections; normally this
@@ -2408,16 +2427,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\nExamine %s/log/postmaster.log for the reason\n"),
+					 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);
+			status(_("# postmaster did not respond within %d seconds\nExamine %s/log/postmaster.log for the reason\n"),
+					wait_seconds, outputdir);
 
 			/*
 			 * If we get here, the postmaster is probably wedged somewhere in
@@ -2426,17 +2445,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;
@@ -2447,7 +2463,7 @@ regression_main(int argc, char *argv[],
 #else
 #define ULONGPID(x) (unsigned long) (x)
 #endif
-		printf(_("running on port %d with PID %lu\n"),
+		status(_("# running on port %d with PID %lu\n"),
 			   port, ULONGPID(postmaster_pid));
 	}
 	else
@@ -2479,8 +2495,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);
@@ -2496,7 +2510,6 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance)
 	{
-		header(_("shutting down postmaster"));
 		stop_postmaster();
 	}
 
@@ -2507,62 +2520,67 @@ regression_main(int argc, char *argv[],
 	 */
 	if (temp_instance && fail_count == 0 && fail_ignore_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);
+			pg_log_error("could not remove temp instance \"%s\"",
+						 temp_instance);
 	}
 
-	fclose(logfile);
+	/*
+	 * Emit a TAP compliant Plan
+	 */
+	status("1..%i\n", (fail_count + fail_ignore_count + success_count));
 
 	/*
 	 * Emit nice-looking summary message
 	 */
 	if (fail_count == 0 && fail_ignore_count == 0)
-		snprintf(buf, sizeof(buf),
-				 _(" All %d tests passed. "),
-				 success_count);
-	else if (fail_count == 0)	/* fail_count=0, fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests passed, %d failed test(s) ignored. "),
-				 success_count,
-				 success_count + fail_ignore_count,
-				 fail_ignore_count);
-	else if (fail_ignore_count == 0)	/* fail_count>0 && fail_ignore_count=0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed. "),
-				 fail_count,
-				 success_count + fail_count);
+		status(_("# All %d tests passed."), success_count);
+	/* fail_count=0, fail_ignore_count>0 */
+	else if (fail_count == 0)
+		status(_("# %d of %d tests passed, %d failed test(s) ignored."),
+			   success_count,
+			   success_count + fail_ignore_count,
+			   fail_ignore_count);
+	/* fail_count>0 && fail_ignore_count=0 */
+	else if (fail_ignore_count == 0)
+		status(_("# %d of %d tests failed."),
+			   fail_count,
+			   success_count + fail_count);
+	/* fail_count>0 && fail_ignore_count>0 */
 	else
-		/* fail_count>0 && fail_ignore_count>0 */
-		snprintf(buf, sizeof(buf),
-				 _(" %d of %d tests failed, %d of these failures ignored. "),
-				 fail_count + fail_ignore_count,
-				 success_count + fail_count + fail_ignore_count,
-				 fail_ignore_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');
+		status(_("# %d of %d tests failed, %d of these failures ignored."),
+			   fail_count + fail_ignore_count,
+			   success_count + fail_count + fail_ignore_count,
+			   fail_ignore_count);
 
+	/*
+	 * In order for this information (or any error information) to be shown
+	 * when running pg_regress test suites under prove it needs to be emitted
+	 * stderr instead of stdout.
+	 */
 	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"),
+		status(_("\n# 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);
 	}
 	else
 	{
 		unlink(difffilename);
 		unlink(logfilename);
+
+		free(difffilename);
+		difffilename = NULL;
+		free(logfilename);
+		logfilename = NULL;
 	}
 
+	status_end();
+
+	fclose(logfile);
+	logfile = NULL;
+
 	if (fail_count != 0)
 		exit(1);
 
-- 
2.32.1 (Apple Git-133)



^ permalink  raw  reply  [nested|flat] 26+ messages in thread


end of thread, other threads:[~2022-09-01 12:21 UTC | newest]

Thread overview: 26+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-03-03 05:24 [PATCH v2] windows: Only consider us to be running as service if stderr is invalid. Andres Freund <[email protected]>
2022-02-21 23:08 TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-02-22 14:10 ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-02-22 17:13   ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-02-22 21:04     ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-03-21 23:49   ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-03-24 12:44     ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-06-29 19:50       ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-07-04 14:27         ` Re: TAP output format in pg_regress Peter Eisentraut <[email protected]>
2022-07-04 14:39           ` Re: TAP output format in pg_regress Tom Lane <[email protected]>
2022-07-04 19:33             ` Re: TAP output format in pg_regress Peter Eisentraut <[email protected]>
2022-07-04 20:06             ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-07-04 22:06               ` Re: TAP output format in pg_regress Tom Lane <[email protected]>
2022-07-04 22:11             ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-07-04 22:06           ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-07-04 22:58             ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-07-05 01:56               ` Re: TAP output format in pg_regress Tom Lane <[email protected]>
2022-07-05 02:40                 ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-08-02 18:44                   ` Re: TAP output format in pg_regress Jacob Champion <[email protected]>
2022-08-17 21:04                   ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-08-17 22:49                     ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-08-18 11:24                       ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-08-18 14:40                         ` Re: TAP output format in pg_regress Andrew Dunstan <[email protected]>
2022-09-01 12:21                           ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>
2022-07-04 20:13         ` Re: TAP output format in pg_regress Andres Freund <[email protected]>
2022-07-04 21:48           ` Re: TAP output format in pg_regress Daniel Gustafsson <[email protected]>

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox