Inconsistent output handling in 002_pg_upgrade.pl test logs

Hi hackers,

I've noticed some inconsistency in 002_pg_upgrade.pl in how it handles output
during test failures. Currently, it uses note to print the header:

note "=== contents of $log ===\n";

but print for the log content and footer:

print slurp_file($log);
print "=== EOF ===\n";

This results in the header appearing in the TAP test output, while the actual
log content and the EOF-footer are directed to
./build/testrun/pg_upgrade/002_pg_upgrade/log/regress_log_002_pg_upgrade

This split means the log content is separate from its header and footer,
making it harder to interpret during test failures.

Example of current behavior:

In the console output:
# executing test in ./build/testrun/pg_upgrade/002_pg_upgrade group pg_upgrade test 002_pg_upgrade
...omitted...
not ok 15 - pg_upgrade_output.d/ removed after pg_upgrade success
# === contents of ./build/testrun/pg_upgrade/002_pg_upgrade/data/t_002_pg_upgrade_new_node_data/pgdata/pg_upgrade_output.d/20241028T140145.267/log/pg_upgrade_dump_5.log ===
# === contents of ./build/testrun/pg_upgrade/002_pg_upgrade/data/t_002_pg_upgrade_new_node_data/pgdata/pg_upgrade_output.d/20241028T140145.267/log/pg_upgrade_dump_1.log ===

But the actual log content and footers are only visible in regress_log_002_pg_upgrade.

Suggested solutions:

Option 1: Keep output together using note

If we want all messages (header, content, and footer) to be in the TAP output
for easier readability, we could replace print with note for both the content
and footer:

foreach my $log (@log_files)
{
note "=== contents of $log ===\n";
note slurp_file($log);
note "=== EOF ===\n";
}

Option 2: Adjust header message for separate logs

If we intentionally want the log content to remain in the separate regression
log for brevity, we could clarify the header message to indicate where
the actual content can be found, and ensure the "=== contents of $log ===\n"
message goes into the same file as the content:

foreach my $log (@log_files)
{
note "=== contents of $log logged to $path_to_regress_log_002_pg_upgrade ===\n";
print "=== contents of $log ===\n";
print slurp_file($log);
print "=== EOF ===\n";
}

Thoughts on these options?

/Joel

> On 28 Oct 2024, at 13:38, Joel Jacobson <joel(at)compiler(dot)org> wrote:
>
> Hi hackers,
>
> I've noticed some inconsistency in 002_pg_upgrade.pl in how it handles output
> during test failures. Currently, it uses note to print the header:
>
> note "=== contents of $log ===\n";
>
> but print for the log content and footer:
>
> print slurp_file($log);
> print "=== EOF ===\n";

Ugh, nice catch.

> Option 1: Keep output together using note

> Option 2: Adjust header message for separate logs

> Thoughts on these options?

I would prefer to output this to the log only and not the TAP output, to avoid
the risk of not seeing the test output for all the log output on the screen.

--
Daniel Gustafsson

On Mon, Oct 28, 2024, at 13:44, Daniel Gustafsson wrote:
>> On 28 Oct 2024, at 13:38, Joel Jacobson <joel(at)compiler(dot)org> wrote:
>>
>> Hi hackers,
>>
>> I've noticed some inconsistency in 002_pg_upgrade.pl in how it handles output
>> during test failures. Currently, it uses note to print the header:
>>
>> note "=== contents of $log ===\n";
>>
>> but print for the log content and footer:
>>
>> print slurp_file($log);
>> print "=== EOF ===\n";
>
> Ugh, nice catch.
>
>> Option 1: Keep output together using note
>
>> Option 2: Adjust header message for separate logs
>
>> Thoughts on these options?
>
> I would prefer to output this to the log only and not the TAP output, to avoid
> the risk of not seeing the test output for all the log output on the screen.

I also think that's best, and in line with what we do in other parts of the same script.

Patch attached.

/Joel

On Mon, Oct 28, 2024 at 04:44:48PM +0100, Joel Jacobson wrote:
> On Mon, Oct 28, 2024, at 13:44, Daniel Gustafsson wrote:
>>> On 28 Oct 2024, at 13:38, Joel Jacobson <joel(at)compiler(dot)org> wrote:
>>> Option 1: Keep output together using note
>>
>>> Option 2: Adjust header message for separate logs
>>
>>> Thoughts on these options?
>>
>> I would prefer to output this to the log only and not the TAP output, to avoid
>> the risk of not seeing the test output for all the log output on the screen.

My apologies for the late reply, this comes from 73db8f4d17ed so
this confision is on me.

The contents of the logs could be very long depending on the dump
used for the upgrade test, so agreed to print() the contents of the
logs as in option 2, without using note() everywhere.

> I also think that's best, and in line with what we do in other parts
> of the same script.

+ my $test_logfile = $PostgreSQL::Test::Utils::test_logfile;
+
+ note "=== pg_upgrade logs found - appending to $test_logfile ===\n";
foreach my $log (@log_files)
{
- note "=== contents of $log ===\n";
+ note "=== appending $log ===\n";
+ print "=== contents of $log ===\n";
print slurp_file($log);
print "=== EOF ===\n";
}

That's a clear improvement, thanks for the report. I'll see about a
backpatch, as well.
--
Michael