Re: TAP output format in pg_regress

Hi,

On 2022-11-22 23:17:44 +0100, Daniel Gustafsson wrote:
> The attached v10 attempts to address the points raised above. Notes and
> diagnostics are printed to stdout/stderr respectively and the TAP emitter is
> changed to move more of the syntax into it making it less painful on the
> translators.

Thanks! I played a bit with it locally and it's nice.

I think it might be worth adding a few more details to the output on stderr,
e.g. a condensed list of failed tests, as that's then printed in the errorlogs
summary in meson after running all tests. As we don't do that in the current
output, that seems more like an optimization for later.

My compiler complains with:

[6/80 7 7%] Compiling C object src/test/regress/pg_regress.p/pg_regress.c.o
../../../../home/andres/src/postgresql/src/test/regress/pg_regress.c: In function ‘emit_tap_output_v’:
../../../../home/andres/src/postgresql/src/test/regress/pg_regress.c:354:9: warning: function ‘emit_tap_output_v’ might be a candidate for ‘gnu_printf’ format attribute [-Wsuggest-attribute=format]
354 | vfprintf(fp, fmt, argp);
| ^~~~~~~~
../../../../home/andres/src/postgresql/src/test/regress/pg_regress.c:356:17: warning: function ‘emit_tap_output_v’ might be a candidate for ‘gnu_printf’ format attribute [-Wsuggest-attribute=format]
356 | vfprintf(logfile, fmt, argp_logfile);
| ^~~~~~~~

Which seems justified and easily remedied via pg_attribute_printf().

I think there might be something slightly wrong with 'tags' - understandable,
since there's basically no comment explaining what it's supposed to do. I
added an intentional failure to 'show.pgc', which then yielded the following
tap output:
ok 51 sql/quote 15 ms
not ok 52 sql/show 9 ms
# tags: stdout source ok 53 sql/insupd 11 ms
ok 54 sql/parser 13 ms

which then subsequently leads meson to complain that
TAP parsing error: out of order test numbers
TAP parsing error: Too few tests run (expected 62, got 61)

Looks like all that's needed is a \n after "tags: %s"

I think the patch is also missing a \n after in log_child_failure().

If I kill postgres during a test I get:

# parallel group (12 tests): regex tstypes geometry type_sanity misc_sanity horology expressions unicode mvcc opr_sanity comments xid
not ok 43 geometry 8 ms
# (test process exited with exit code 2)not ok 44 horology 9 ms
# (test process exited with exit code 2)not ok 45 tstypes 7 ms
# (test process exited with exit code 2)not ok 46 regex 7 ms

> Subject: [PATCH v10 2/2] Experimental: meson: treat regress tests as TAP

I'd just squash that in I think. Isn't really experimental either IMO ;)

> +static void
> +emit_tap_output_v(TAPtype type, const char *fmt, va_list argp)
> +{
> + va_list argp_logfile;
> + FILE *fp = stdout;
> +
> + /* We only need to copy the arg array in case we actually need it */
> if (logfile)
> - fprintf(logfile, "\n");
> + va_copy(argp_logfile, argp);
> +
> + /*
> + * Diagnostic output will be hidden by prove unless printed to stderr.
> + * The Bail message is also printed to stderr to aid debugging under a
> + * harness which might otherwise not emit such an important message.
> + */
> + if (type == DIAG || type == BAIL)
> + fp = stderr;

Personally I'd move the initialization of fp to an else branch here, but
that's a very minor taste thing.

> + /*
> + * Non-protocol output such as diagnostics or notes must be prefixed by
> + * a '#' character. We print the Bail message like this too.
> + */
> + if (type == NOTE || type == DIAG || type == BAIL)
> + {
> + fprintf(fp, "# ");
> + if (logfile)
> + fprintf(logfile, "# ");
> + }
> + vfprintf(fp, fmt, argp);
> + if (logfile)
> + vfprintf(logfile, fmt, argp_logfile);
> + /*
> + * If this was a Bail message, the bail protocol message must go to
> + * stdout separately.
> + */
> + if (type == BAIL)
> + {
> + fprintf(stdout, "Bail Out!");
> + if (logfile)
> + fprintf(logfile, "Bail Out!");

I think this needs a \n.

> + }
> +
> + fflush(NULL);
> }

I was wondering whether it's worth having an printf wrapper that does the
vfprintf(); if (logfile) vfprintf() dance. But it's proably not.

> @@ -1089,9 +1201,8 @@ spawn_process(const char *cmdline)
>
> cmdline2 = psprintf("exec %s", cmdline);
> execl(shellprog, shellprog, "-c", cmdline2, (char *) NULL);
> - fprintf(stderr, _("%s: could not exec \"%s\": %s\n"),
> - progname, shellprog, strerror(errno));
> - _exit(1); /* not exit() here... */
> + /* Not using the normal bail() here as we want _exit */
> + _bail(_("could not exec \"%s\": %s\n"), shellprog, strerror(errno));
> }
> /* in parent */
> return pid;

Not in love with _bail, but I don't immediately have a better idea.

> @@ -1129,8 +1240,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);

Hm. Shouldn't this just use diag()?

> @@ -1708,7 +1811,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,30 +1829,14 @@ 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();
> }

Hm. We probably shouldn't treat the test as a success if statuses[i] != 0?
Although it sure looks like we did so far.

> for (i = 0; i < num_tests; i++)
> @@ -1762,6 +1849,7 @@ run_schedule(const char *schedule, test_start_function startfunc,
> }
> }
>
> + pg_free(tagbuf.data);
> free_stringlist(&ignorelist);
>
> fclose(scf);
> @@ -1785,11 +1873,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,29 +1899,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);

Why does tagbuf exist? Afaict it just is handed off 1:1 to test_status_failed?

While the above may sound like a fair bit of work, I think it's actually not
that much work, and we should strive to get this committed pretty soon!

Greetings,

Andres Freund