From 49bc25665e1a878114d2b89bdab8fd8761e7c432 Mon Sep 17 00:00:00 2001 From: Jacob Champion Date: Wed, 3 Feb 2021 11:04:42 -0800 Subject: [PATCH 1/8] test/kerberos: only search forward in logs The log content tests searched through the entire log file, from the beginning, for every match. If two tests shared the same expected log content, it was possible for the second test to get a false positive by matching against the first test's output. (This could be seen by modifying one of the expected-failure tests to expect the same output as a previous happy-path test.) Store the offset of the previous match, and search forward from there during the next match, resetting the offset every time the log file changes. This could still result in false positives if one test spits out two or more matching log lines, but it should be an improvement over what's there now. --- src/test/kerberos/t/001_auth.pl | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl index 079321bbfc..c721d24dbd 100644 --- a/src/test/kerberos/t/001_auth.pl +++ b/src/test/kerberos/t/001_auth.pl @@ -182,6 +182,9 @@ $node->safe_psql('postgres', 'CREATE USER test1;'); note "running tests"; +my $current_log_name = ''; +my $current_log_position; + # Test connection success or failure, and if success, that query returns true. sub test_access { @@ -221,18 +224,37 @@ sub test_access $lfname =~ s/^stderr //; chomp $lfname; + if ($lfname ne $current_log_name) + { + $current_log_name = $lfname; + + # Search from the beginning of this new file. + $current_log_position = 0; + note "current_log_position = $current_log_position"; + } + # might need to retry if logging collector process is slow... my $max_attempts = 180 * 10; my $first_logfile; for (my $attempts = 0; $attempts < $max_attempts; $attempts++) { $first_logfile = slurp_file($node->data_dir . '/' . $lfname); - last if $first_logfile =~ m/\Q$expect_log_msg\E/; + + # Don't include previously matched text in the search. + $first_logfile = substr $first_logfile, $current_log_position; + if ($first_logfile =~ m/\Q$expect_log_msg\E/g) + { + $current_log_position += pos($first_logfile); + last; + } + usleep(100_000); } like($first_logfile, qr/\Q$expect_log_msg\E/, 'found expected log file content'); + + note "current_log_position = $current_log_position"; } return; -- 2.25.1