Improving log capture of TAP tests with IPC::Run

On Thu, June 25, 2015 06:14, Michael Paquier wrote:

I have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()

IPC::Run is not in perl core and will not always be available.
It looks like this patch doesn't take this into account (when no IPC::Run skip the test or whatever)
Shouldn't that be changed?

Thanks,

Erik Rijkers

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Thu, Jun 25, 2015 at 3:59 PM, Erik Rijkers <er@xs4all.nl> wrote:

IPC::Run is not in perl core and will not always be available.
It looks like this patch doesn't take this into account (when no IPC::Run skip the test or whatever)
Shouldn't that be changed?

Yes, there have been discussions on the matter already:
/messages/by-id/20141102190024.GA538247@tornado.leadboat.com
We may want to be able to capture easily the outputs of stdout and
stderr as well though and not only get the exit code. That looks
important to improve the debuggability of the whole thing when kicking
in commands. And to have that working on Windows as well..
Regards,
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 06/25/2015 07:14 AM, Michael Paquier wrote:

After looking at the issues with the TAP test suite that hamster faced
a couple of days ago, which is what has been discussed on this thread:
/messages/by-id/13002.1434307025@sss.pgh.pa.us

I have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
that is not able to help much) that has already been sent on the
thread above.

This is a massive improvement to the usability of TAP tests. They are
practically impossible to debug currently. Thanks for working on this!

The patch redirects the output of all "system_or_bail" commands to a log
file. That's a good start, but I wish we could get *everything* in the
same log file. That includes also:

* stdout and stderr of *all* commands. Including all the commands run
with command_ok/command_fails.

* the command line of commands being executed. It's difficult to follow
the log when you don't know which output corresponds to which command.

* whenever a test case is reported as success/fail.

Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes a copy of them (when? at program startup I guess..). That would be
much more convenient than decorating every run call with ">> logfile".

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Wed, Jul 8, 2015 at 6:10 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

On 06/25/2015 07:14 AM, Michael Paquier wrote:

After looking at the issues with the TAP test suite that hamster faced
a couple of days ago, which is what has been discussed on this thread:
/messages/by-id/13002.1434307025@sss.pgh.pa.us

I have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
that is not able to help much) that has already been sent on the
thread above.

This is a massive improvement to the usability of TAP tests. They are
practically impossible to debug currently. Thanks for working on this!

The patch redirects the output of all "system_or_bail" commands to a log
file. That's a good start, but I wish we could get *everything* in the same
log file. That includes also:

* stdout and stderr of *all* commands. Including all the commands run with
command_ok/command_fails.

That makes sense. I have switched command_ok, command_exit_is and
command_fails to show up their output instead of having them sent to
void.

* the command line of commands being executed. It's difficult to follow the
log when you don't know which output corresponds to which command.

OK, I have added some stuff for that. Let me know your thoughts. Each
command started is printed in the log file before starting with a
message mentioning what is the type of test used.

* whenever a test case is reported as success/fail.

Just to be sure, does this concern the "ok/not ok" messages printed
out by each test run? Or is it a custom message that you have in mind?

Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More takes
a copy of them (when? at program startup I guess..). That would be much more
convenient than decorating every run call with ">> logfile".

Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;

While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file. Also, the output can be correctly captured by just
appending that to a couple of places:
[ '>>', $test_logfile, '2>&1']
And this solution proves to work as well on Windows...
--
Michael

On 07/08/2015 11:26 AM, Michael Paquier wrote:

On Wed, Jul 8, 2015 at 6:10 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

* whenever a test case is reported as success/fail.

Just to be sure, does this concern the "ok/not ok" messages printed
out by each test run? Or is it a custom message that you have in mind?

Right. It would be nice to have the same output that's printed to the
console also in the log.

Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More takes
a copy of them (when? at program startup I guess..). That would be much more
convenient than decorating every run call with ">> logfile".

Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;

While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.

Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But
it's Windows, so who knows..

I came up with the attached, which does that. It also plays some tricks
with perl "tie", to copy the "ok - ..." lines that go to the console, to
the log.

I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?

Also, the output can be correctly captured by just
appending that to a couple of places:
[ '>>', $test_logfile, '2>&1']
And this solution proves to work as well on Windows...

Yeah, but that's tedious.

- Heikki

On Thu, Jul 9, 2015 at 12:49 AM, Heikki Linnakangas wrote:

Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes
a copy of them (when? at program startup I guess..). That would be much
more
convenient than decorating every run call with ">> logfile".

Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the
tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;

While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.

Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But it's
Windows, so who knows..

And actually your patch works even on Windows. Tests are running and
log can be captured in the same shape as Linux and OSX!

I came up with the attached, which does that. It also plays some tricks with
perl "tie", to copy the "ok - ..." lines that go to the console, to the log.

I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?

I simply downloaded them from CPAN and put them in PERL5LIB. And it
worked. For Windows, you will also need some adjustments to make the
tests able to run (see the other thread related to support TAP in MSVC
/messages/by-id/CAB7nPqTQwphkDfZP07w7yBnbFNDhW_JBAMyCFAkarE2VWg8irQ@mail.gmail.com)
like using SSPI for connection, adjusting listen_addresses. The patch
attached, which is a merge of your patch and my MSVC stuff, is able to
do that. This is just intended for testing, so feel free to use it if
you want to check by yourself how logs are captured. I'll repost a new
version of it on the other thread depending on the outcome here.

-    system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+    system_or_bail('pg_basebackup', '-D', $test_standby_datadir,
+                   '-p', $port_master, '-x';
A parenthesis is missing here.

-               my $result = run(
-                       [   'pg_rewind',
-                               "--source-server",
-                               "port=$port_standby dbname=postgres",
-                               "--target-pgdata=$test_master_datadir" ],
-                       '>>',
-                       $log_path,
-                       '2>&1');
-               ok($result, 'pg_rewind remote');
+               command_ok(['pg_rewind',
+                                       "--source-server",
+                                       "port=$port_standby dbname=postgres",
+                                       "--target-pgdata=$test_master_datadir"],
+                                  'pg_rewind remote');
As long as we are on it, I think that we should add --debug here to
make the logs more useful.

Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.
Regards,
--
Michael

On 07/09/2015 04:50 AM, Michael Paquier wrote:

On Thu, Jul 9, 2015 at 12:49 AM, Heikki Linnakangas wrote:

Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes
a copy of them (when? at program startup I guess..). That would be much
more
convenient than decorating every run call with ">> logfile".

Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the
tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;

While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.

Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But it's
Windows, so who knows..

And actually your patch works even on Windows. Tests are running and
log can be captured in the same shape as Linux and OSX!

Great!

I came up with the attached, which does that. It also plays some tricks with
perl "tie", to copy the "ok - ..." lines that go to the console, to the log.

I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?

I simply downloaded them from CPAN and put them in PERL5LIB. And it
worked. For Windows, you will also need some adjustments to make the
tests able to run (see the other thread related to support TAP in MSVC
/messages/by-id/CAB7nPqTQwphkDfZP07w7yBnbFNDhW_JBAMyCFAkarE2VWg8irQ@mail.gmail.com)
like using SSPI for connection, adjusting listen_addresses. The patch
attached, which is a merge of your patch and my MSVC stuff, is able to
do that. This is just intended for testing, so feel free to use it if
you want to check by yourself how logs are captured. I'll repost a new
version of it on the other thread depending on the outcome here.

-    system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+    system_or_bail('pg_basebackup', '-D', $test_standby_datadir,
+                   '-p', $port_master, '-x';
A parenthesis is missing here.

-               my $result = run(
-                       [   'pg_rewind',
-                               "--source-server",
-                               "port=$port_standby dbname=postgres",
-                               "--target-pgdata=$test_master_datadir" ],
-                       '>>',
-                       $log_path,
-                       '2>&1');
-               ok($result, 'pg_rewind remote');
+               command_ok(['pg_rewind',
+                                       "--source-server",
+                                       "port=$port_standby dbname=postgres",
+                                       "--target-pgdata=$test_master_datadir"],
+                                  'pg_rewind remote');
As long as we are on it, I think that we should add --debug here to
make the logs more useful.

Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.

Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Thu, Jul 9, 2015 at 7:29 PM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

Thanks, fixed the parenthesis and committed.

Thanks. I imagine that this is going to need some tuning with the
buildfarm before this becomes really useful. I will re-enable the TAP
tests of hamster once that's the case.
@Andrew: do you need a patch for the buildfarm client?

The missing --debug is a separate issue.

I won't argue against that, but is it worth creating a new thread just
for this one-liner? The local mode of pg_rewind uses it already.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 07/09/2015 04:09 PM, Michael Paquier wrote:

On Thu, Jul 9, 2015 at 7:29 PM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:

The missing --debug is a separate issue.

I won't argue against that, but is it worth creating a new thread just
for this one-liner? The local mode of pg_rewind uses it already.

Pushed, thanks.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Heikki Linnakangas <hlinnaka@iki.fi> writes:

Pushed, thanks.

Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Thu, Jul 9, 2015 at 10:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Heikki Linnakangas <hlinnaka@iki.fi> writes:

Pushed, thanks.

Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.

1ea0620 can be directly cherry-picked on REL9_5_STABLE. For
REL9_4_STABLE the attached looks to work fine.

buildfarm will need to be patched btw... Here is the result of a run
including the log improvements:
http://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=dangomushi&amp;dt=2015-07-09%2019%3A53%3A02&amp;stg=bin-check
--
Michael

On Thu, Jul 9, 2015 at 9:43 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Heikki Linnakangas <hlinnaka@iki.fi> writes:

Pushed, thanks.

Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.

+1.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 07/09/2015 06:29 AM, Heikki Linnakangas wrote:

On 07/09/2015 04:50 AM, Michael Paquier wrote:

Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.

Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.

What was the reason for not backpatching this? I have a fix for the
execrable treatment of vpath builds, but it only applies to the tip
branch because it relies on this.

cheers

andrew

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 07/28/2015 05:49 PM, Andrew Dunstan wrote:

On 07/09/2015 06:29 AM, Heikki Linnakangas wrote:

On 07/09/2015 04:50 AM, Michael Paquier wrote:

Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.

Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.

What was the reason for not backpatching this? I have a fix for the
execrable treatment of vpath builds, but it only applies to the tip
branch because it relies on this.

No reason, other than the general only-backpatch-bug-fixes rule. Several
people requested it, and it seems reasonable to me too, but it fell off
my radar. Feel free to backpatch...

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers