Thread: Improving log capture of TAP tests with IPC::Run
Hi all, 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: http://www.postgresql.org/message-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 patch looks worth having in the TAP suite to track problems, hence this thread dedicated to it. The patch has been added as well to the next CF. Regards, -- Michael
Attachment
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
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: http://www.postgresql.org/message-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
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: > http://www.postgresql.org/message-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
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: >> http://www.postgresql.org/message-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
Attachment
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
Attachment
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 http://www.postgresql.org/message-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
Attachment
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 > http://www.postgresql.org/message-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
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
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
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
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&dt=2015-07-09%2019%3A53%3A02&stg=bin-check -- Michael
Attachment
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
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
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