Revision control
Copy as Markdown
#!/usr/bin/env perl
use 5.010;
use strict;
use warnings;
=head1 NAME
21-testrunner-flaky.t - test testrunner's `flaky' plugin for unstable tests
=head1 SYNOPSIS
perl ./21-testrunner-flaky.t
This test will run the testrunner.pl script with some artificially unstable
processes and verify that the flaky plugin generates the expected output.
=cut
use Capture::Tiny qw( capture );
use English qw( -no_match_vars );
use File::Basename;
use File::Slurp qw( read_file );
use File::Temp qw( tempdir );
use FindBin;
use Readonly;
use Test::More;
use lib "$FindBin::Bin/../../lib/perl5";
use QtQA::Test::More qw( is_or_like );
# error from a stable failing test
Readonly my $ERROR_STABLE_FAILURE => <<'END_MESSAGE';
QtQA::App::TestRunner: test failed, running again to see if it is flaky...
QtQA::App::TestRunner: test failure could be reproduced twice consecutively
END_MESSAGE
# perl to simulate a test which fails, then succeeds.
Readonly my $PERL_VANISHING_FAILURE => <<'END_SCRIPT';
$|++;
if ($ENV{ QTQA_APP_TESTRUNNER_ATTEMPT } == 1) {
print qq{First attempt; failing...\n};
exit 13;
}
print qq{Second attempt; causing much vexation by passing!\n};
END_SCRIPT
# perl to simulate a test which eventually fails, then eventually succeeds.
Readonly my $PERL_VANISHING_FAILURE_TIMEOUT_WARNING => <<'END_SCRIPT';
sleep 2;
$|++;
if ($ENV{ QTQA_APP_TESTRUNNER_ATTEMPT } == 1) {
print qq{First attempt; failing...\n};
exit 13;
}
print qq{Second attempt; causing much vexation by passing!\n};
END_SCRIPT
# stdout from the above
Readonly my $OUTPUT_VANISHING_FAILURE => <<'END_MESSAGE';
First attempt; failing...
Second attempt; causing much vexation by passing!
END_MESSAGE
# error from the above
Readonly my $ERROR_VANISHING_FAILURE => <<'END_MESSAGE';
QtQA::App::TestRunner: test failed, running again to see if it is flaky...
QtQA::App::TestRunner: test failed on first attempt and passed on second attempt!
QtQA::App::TestRunner: first attempt: exited with exit code 13
QtQA::App::TestRunner: the test seems to be flaky, please fix this
END_MESSAGE
# above, in `pass' flaky mode
Readonly my $ERROR_VANISHING_FAILURE_MODE_BEST => $ERROR_VANISHING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a PASS
END_MESSAGE
# above, in `fail' flaky mode
Readonly my $ERROR_VANISHING_FAILURE_MODE_WORST => $ERROR_VANISHING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a FAIL
END_MESSAGE
# above, in `ignore' flaky mode
Readonly my $ERROR_VANISHING_FAILURE_MODE_IGNORE => $ERROR_VANISHING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being ignored
END_MESSAGE
# perl to simulate a test which fails by crashing, then succeeds.
Readonly my $PERL_VANISHING_CRASH => <<'END_SCRIPT';
$|++;
if ($ENV{ QTQA_APP_TESTRUNNER_ATTEMPT } == 1) {
print qq{First attempt; crashing...\n};
kill 11, $$;
}
print qq{Second attempt; causing much vexation by passing!\n};
END_SCRIPT
# stdout from the above
Readonly my $OUTPUT_VANISHING_CRASH => <<'END_MESSAGE';
First attempt; crashing...
Second attempt; causing much vexation by passing!
END_MESSAGE
# helper regexes for building up the larger regexes below
Readonly my $RE => {
flaky_first_fail => qr{
\QQtQA::App::TestRunner: test failed, running again to see if it is flaky...\E\n
}xms,
core_backtrace => qr{
\QQtQA::App::TestRunner: ============================== backtrace follows: ==============================\E \n
(?:QtQA::App::TestRunner: [^\n]+ \n)*
\QQtQA::App::TestRunner: Program terminated with signal \E(?:11|SIGSEGV)\Q, Segmentation fault.\E \n
(?:QtQA::App::TestRunner: [^\n]+ \n)*
\QQtQA::App::TestRunner: ================================================================================\E \n
}xms,
exited_with_signal11 => ($OSNAME =~ m{win32}i) ? qr{} : qr{
\QQtQA::App::TestRunner: Process exited due to signal 11; dumped core\E \n
}xms,
exited_with_any_signal => ($OSNAME =~ m{win32}i) ? qr{} : qr{
\QQtQA::App::TestRunner: Process exited due to signal \E \d+ (?:\Q; dumped core\E)? \n
}xms,
flaky_second_pass => qr{
\QQtQA::App::TestRunner: test failed on first attempt and passed on second attempt!\E \n
\QQtQA::App::TestRunner: first attempt: exited with signal 11\E \n
\QQtQA::App::TestRunner: the test seems to be flaky, please fix this\E \n
\QQtQA::App::TestRunner: this flaky test is being treated as a FAIL\E \n
}xms,
verbose_begin => qr{\QQtQA::App::TestRunner: begin \E.*?:\Q [perl]\E[^\n]*},
verbose_end => qr{\QQtQA::App::TestRunner: end \E[^:]+\Q: \E[^\n]*},
};
# perl to simulate a test which hangs (for 10 seconds)
Readonly my $PERL_HANGING_FAILURE => <<'END_SCRIPT';
$|++;
print qq{About to hang for a few seconds...\n};
sleep 10;
print qq{Still alive!?!? Most unexpected ...\n};
exit 0;
END_SCRIPT
# stdout from the above
Readonly my $OUTPUT_HANGING_FAILURE => <<'END_MESSAGE';
About to hang for a few seconds...
About to hang for a few seconds...
END_MESSAGE
# error from hanging test
Readonly my $ERROR_HANGING_FAILURE => qr|
\QQtQA::App::TestRunner: Timed out after \E \d+ \Q seconds\E \n
$RE->{ exited_with_any_signal }
\QQtQA::App::TestRunner: test failed, running again to see if it is flaky...\E \n
\QQtQA::App::TestRunner: Timed out after \E \d+ \Q seconds\E \n
$RE->{ exited_with_any_signal }
\QQtQA::App::TestRunner: test failure could be reproduced twice consecutively\E \n
|xms;
# error from the above (when using "flaky" and "core" plugins, in that order)
# note: hardcoded 3328 == (13 << 8)
Readonly my $ERROR_VANISHING_CRASH_WITH_FLAKY_AND_CORE => qr|
\A
$RE->{ exited_with_signal11 } # testrunner tells us that the test exited with signal 11...
$RE->{ flaky_first_fail } # `flaky' says it fails, will try again...
$RE->{ core_backtrace } # `core' shows the backtrace from the first fail
$RE->{ flaky_second_pass } # `flaky' says it passed on second try
\z
|xms;
# merged stdout/stderr from the above
Readonly my $LOG_VANISHING_CRASH_WITH_FLAKY_AND_CORE => qr|
\A
\QFirst attempt; crashing...\E \n
$RE->{ exited_with_signal11 }
$RE->{ flaky_first_fail }
$RE->{ core_backtrace }
\QSecond attempt; causing much vexation by passing!\E \n
$RE->{ flaky_second_pass }
\z
|xms;
# error from the above (when using "core" and "flaky" plugins, in that order)
# Note the only difference from above is that some output order is switched
Readonly my $ERROR_VANISHING_CRASH_WITH_CORE_AND_FLAKY => qr|
\A
$RE->{ exited_with_signal11 } # testrunner tells us that the test exited with signal 11
$RE->{ core_backtrace } # `core' shows the backtrace from the first fail
$RE->{ flaky_first_fail } # `flaky' says it fails, will try again...
$RE->{ flaky_second_pass } # `flaky' says it passed on second try
\z
|xms;
# merged stdout/stderr from the above
Readonly my $LOG_VANISHING_CRASH_WITH_CORE_AND_FLAKY => qr|
\A
\QFirst attempt; crashing...\E \n
$RE->{ exited_with_signal11 }
$RE->{ core_backtrace }
$RE->{ flaky_first_fail }
\QSecond attempt; causing much vexation by passing!\E \n
$RE->{ flaky_second_pass }
\z
|xms;
# perl to simulate a test which fails, then fails again in a different way
Readonly my $PERL_DIFFERING_FAILURE => <<'END_SCRIPT';
$|++;
if ($ENV{ QTQA_APP_TESTRUNNER_ATTEMPT } == 1) {
print qq{First attempt; failing...\n};
exit 13;
}
print qq{Second attempt; failing again, differently\n};
exit 22;
END_SCRIPT
# stdout from the above
Readonly my $OUTPUT_DIFFERING_FAILURE => <<'END_MESSAGE';
First attempt; failing...
Second attempt; failing again, differently
END_MESSAGE
# error from the above
Readonly my $ERROR_DIFFERING_FAILURE => <<'END_MESSAGE';
QtQA::App::TestRunner: test failed, running again to see if it is flaky...
QtQA::App::TestRunner: test failed on first and second attempts, but with different behavior each time:
QtQA::App::TestRunner: first attempt: exited with exit code 13
QtQA::App::TestRunner: second attempt: exited with exit code 22
QtQA::App::TestRunner: the test seems to be flaky, please fix this
END_MESSAGE
# above, in `pass' flaky mode
Readonly my $ERROR_DIFFERING_FAILURE_MODE_BEST => $ERROR_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a FAIL
END_MESSAGE
# above, in `fail' flaky mode
Readonly my $ERROR_DIFFERING_FAILURE_MODE_WORST => $ERROR_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a FAIL
END_MESSAGE
# above, with --verbose
Readonly my $VERBOSE_ERROR_DIFFERING_FAILURE_MODE_WORST => qr|
\A
$RE->{ verbose_begin }\n
\Q$ERROR_DIFFERING_FAILURE_MODE_WORST\E
$RE->{ verbose_end }\Q, exit code 22\E\n
|xms;
# above, in `ignore' flaky mode
Readonly my $ERROR_DIFFERING_FAILURE_MODE_IGNORE => $ERROR_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being ignored
END_MESSAGE
# stdout & stderr mixed from the above
Readonly my $LOG_DIFFERING_FAILURE => <<'END_MESSAGE';
First attempt; failing...
QtQA::App::TestRunner: test failed, running again to see if it is flaky...
Second attempt; failing again, differently
QtQA::App::TestRunner: test failed on first and second attempts, but with different behavior each time:
QtQA::App::TestRunner: first attempt: exited with exit code 13
QtQA::App::TestRunner: second attempt: exited with exit code 22
QtQA::App::TestRunner: the test seems to be flaky, please fix this
END_MESSAGE
# above, in `pass' flaky mode
Readonly my $LOG_DIFFERING_FAILURE_MODE_BEST => $LOG_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a FAIL
END_MESSAGE
# above, in `fail' flaky mode
Readonly my $LOG_DIFFERING_FAILURE_MODE_WORST => $LOG_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being treated as a FAIL
END_MESSAGE
# above, in `ignore' flaky mode
Readonly my $LOG_DIFFERING_FAILURE_MODE_IGNORE => $LOG_DIFFERING_FAILURE . <<"END_MESSAGE";
QtQA::App::TestRunner: this flaky test is being ignored
END_MESSAGE
# perl to check if -silent argument is passed (and fail)
Readonly my $PERL_SILENT_CHECK => <<'END_SCRIPT';
if (grep { $_ eq '-silent' } @ARGV) {
print qq{-silent argument is given; }.scalar(@ARGV).qq{ args\n};
} else {
print qq{-silent argument is not given; }.scalar(@ARGV).qq{ args\n};
}
exit 16;
END_SCRIPT
# expected output from the above, when run with -silent -foo
Readonly my $OUTPUT_SILENT_CHECK => <<'END_MESSAGE';
-silent argument is given; 2 args
-silent argument is not given; 1 args
END_MESSAGE
# expected stderr from the above
Readonly my $ERROR_SILENT_CHECK => <<'END_MESSAGE';
QtQA::App::TestRunner: test failed, running again to see if it is flaky...
QtQA::App::TestRunner: test failure could be reproduced twice consecutively
END_MESSAGE
sub test_run
{
my ($params_ref) = @_;
my @args = @{$params_ref->{ args }};
my $expected_stdout = $params_ref->{ expected_stdout };
my $expected_stderr = $params_ref->{ expected_stderr };
my $expected_success = $params_ref->{ expected_success };
my $expected_logfile = $params_ref->{ expected_logfile };
my $expected_logtext = $params_ref->{ expected_logtext } // "";
my $testname = $params_ref->{ testname } // q{};
my $status;
my ($output, $error) = capture {
$status = system( 'perl', "$FindBin::Bin/../testrunner.pl", @args );
};
if ($expected_success) {
is ( $status, 0, "$testname exits zero" );
}
else {
isnt( $status, 0, "$testname exits non-zero" );
}
is_or_like( $output, $expected_stdout, "$testname output looks correct" );
is_or_like( $error, $expected_stderr, "$testname error looks correct" );
# The rest of the verification steps are only applicable if a log file is expected and created
return if (!$expected_logfile);
return if (!ok( -e $expected_logfile, "$testname created $expected_logfile" ));
my $logtext = read_file( $expected_logfile ); # dies on error
is_or_like( $logtext, $expected_logtext, "$testname logtext is as expected" );
return;
}
sub test_testrunner_flaky
{
# control; check that `--plugin flaky' has no effect if a test doesn't fail
# flaky-mode should have no effect
foreach my $mode_args (
[],
['--flaky-mode', 'worst'],
['--flaky-mode', 'best'],
['--flaky-mode', 'ignore'],
) {
test_run({
testname => "plugin loads OK 0 exitcode (@{ $mode_args })",
args => [ qw(--plugin flaky), @{ $mode_args }, qw(-- perl -e),
'print STDOUT q{Hi}; print STDERR q{there!}' ],
expected_success => 1,
expected_stdout => q{Hi},
expected_stderr => q{there!},
});
}
# stable failure
# flaky-mode should have no effect
foreach my $mode_args (
[],
['--flaky-mode', 'worst'],
['--flaky-mode', 'best'],
['--flaky-mode', 'ignore'],
) {
test_run({
testname => "stable failure (@{ $mode_args })",
args => [ qw(--plugin flaky), @{ $mode_args }, qw(-- perl -e),
'print qq{Failing...\n}; exit 42' ],
expected_success => 0,
expected_stdout => qq{Failing...\n} x 2, # x 2 since retried once
expected_stderr => $ERROR_STABLE_FAILURE,
});
}
# test which fails once, then passes
test_run({
testname => 'vanishing failure',
args => [ qw(--plugin flaky -- perl -e), $PERL_VANISHING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_VANISHING_FAILURE,
expected_stderr => $ERROR_VANISHING_FAILURE_MODE_WORST,
});
test_run({
testname => 'vanishing failure (flaky-mode worst)',
args => [ qw(--plugin flaky --flaky-mode worst -- perl -e), $PERL_VANISHING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_VANISHING_FAILURE,
expected_stderr => $ERROR_VANISHING_FAILURE_MODE_WORST,
});
test_run({
testname => 'vanishing failure (flaky-mode best)',
args => [ qw(--plugin flaky --flaky-mode best -- perl -e), $PERL_VANISHING_FAILURE ],
expected_success => 1,
expected_stdout => $OUTPUT_VANISHING_FAILURE,
expected_stderr => $ERROR_VANISHING_FAILURE_MODE_BEST,
});
test_run({
testname => 'vanishing failure (flaky-mode ignore)',
args => [ qw(--plugin flaky --flaky-mode ignore -- perl -e), $PERL_VANISHING_FAILURE ],
expected_success => 1,
expected_stdout => $OUTPUT_VANISHING_FAILURE,
expected_stderr => $ERROR_VANISHING_FAILURE_MODE_IGNORE,
});
# test which eventually fails once, then eventually passes
# this also tests timeout warning by setting a smalltimeout value
test_run({
testname => 'vanishing failure; with timeoutwarning test',
args => [ qw(--plugin flaky --timeout 5 -- perl -e), $PERL_VANISHING_FAILURE_TIMEOUT_WARNING ],
expected_success => 0,
expected_stdout => $OUTPUT_VANISHING_FAILURE,
expected_stderr => $ERROR_VANISHING_FAILURE_MODE_WORST,
});
# test which fails once, then again in a different way
test_run({
testname => 'differing failure',
args => [ qw(--plugin flaky -- perl -e), $PERL_DIFFERING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_DIFFERING_FAILURE,
expected_stderr => $ERROR_DIFFERING_FAILURE_MODE_WORST,
});
test_run({
testname => 'differing failure (flaky-mode worst)',
args => [ qw(--verbose --plugin flaky --flaky-mode worst -- perl -e), $PERL_DIFFERING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_DIFFERING_FAILURE,
expected_stderr => $VERBOSE_ERROR_DIFFERING_FAILURE_MODE_WORST,
});
test_run({
testname => 'differing failure (flaky-mode best)',
args => [ qw(--plugin flaky --flaky-mode best -- perl -e), $PERL_DIFFERING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_DIFFERING_FAILURE,
expected_stderr => $ERROR_DIFFERING_FAILURE_MODE_BEST,
});
test_run({
testname => 'differing failure (flaky-mode ignore)',
args => [ qw(--plugin flaky --flaky-mode ignore -- perl -e), $PERL_DIFFERING_FAILURE ],
expected_success => 1,
expected_stdout => $OUTPUT_DIFFERING_FAILURE,
expected_stderr => $ERROR_DIFFERING_FAILURE_MODE_IGNORE,
});
# test -silent argument is omitted on second run
test_run({
testname => 'silent removed',
args => [ qw(--plugin flaky -- perl -e), $PERL_SILENT_CHECK, '--', '-silent', '-foo' ],
expected_success => 0,
expected_stdout => $OUTPUT_SILENT_CHECK,
expected_stderr => $ERROR_SILENT_CHECK,
});
# test which hangs should be retried as usual
test_run({
testname => "hanging failure",
args => [ qw(--timeout 2 --plugin flaky -- perl -e), $PERL_HANGING_FAILURE ],
expected_success => 0,
expected_stdout => $OUTPUT_HANGING_FAILURE,
expected_stderr => $ERROR_HANGING_FAILURE,
});
my $tempdir = tempdir( basename($0).'.XXXXXX', TMPDIR => 1, CLEANUP => 1 );
# basic check of interaction with logging
test_run({
testname => 'flaky with log',
args => [
'--capture-logs',
$tempdir,
'--plugin',
'flaky',
'--',
'perl',
'-e',
$PERL_DIFFERING_FAILURE,
],
expected_success => 0,
expected_stdout => q{},
expected_stderr => q{},
expected_logfile => "$tempdir/perl-00.txt",
expected_logtext => $LOG_DIFFERING_FAILURE_MODE_WORST,
});
# interaction with core
# (core only works on linux)
if ($OSNAME =~ m{linux}i) {
test_run({
testname => 'flaky with tee log and core (flaky, core)',
args => [
'--tee-logs',
$tempdir,
'--plugin',
'flaky',
'--flaky-mode', # note we are testing mixing of plugin args
'worst', # with global testrunner args.
'--plugin',
'core',
'--',
'perl',
'-e',
$PERL_VANISHING_CRASH,
],
expected_success => 0,
expected_stdout => $OUTPUT_VANISHING_CRASH,
expected_stderr => $ERROR_VANISHING_CRASH_WITH_FLAKY_AND_CORE,
expected_logfile => "$tempdir/perl-01.txt",
expected_logtext => $LOG_VANISHING_CRASH_WITH_FLAKY_AND_CORE,
});
# switch the order and verify that this affects the plugin order
test_run({
testname => 'flaky with tee log and core (core, flaky)',
args => [
'--tee-logs',
$tempdir,
'--plugin',
'core',
'--plugin',
'flaky',
'--',
'perl',
'-e',
$PERL_VANISHING_CRASH,
],
expected_success => 0,
expected_stdout => $OUTPUT_VANISHING_CRASH,
expected_stderr => $ERROR_VANISHING_CRASH_WITH_CORE_AND_FLAKY,
expected_logfile => "$tempdir/perl-02.txt",
expected_logtext => $LOG_VANISHING_CRASH_WITH_CORE_AND_FLAKY,
});
}
return;
}
sub run
{
test_testrunner_flaky;
done_testing;
return;
}
run if (!caller);
1;