Improve logrotate test so that it meaningfully exercises syslogger.

Discussion of bug #15804 reveals that this test didn't really prove
that the syslogger child process ever launched successfully, much
less did anything.  It was only checking that the expected log file
gets created, and that's done in the postmaster.  Moreover, the
test assumed it could rename the log file, which is likely to fail
on Windows (cf. commit d611175e5).

Instead, use the default log file name pattern, which should result
in a new file name being chosen after 1 second, and verify that
rotation has occurred by checking for a new file name.  Also add code
to test that messages actually do propagate through the syslogger.

In theory this version of the test should work on Windows, so
revert d611175e5.

Discussion: https://postgr.es/m/15804-3721117bf40fb654@postgresql.org
This commit is contained in:
Tom Lane 2019-05-19 13:55:39 -04:00
parent 8334515529
commit 9d5c22d28f

View File

@ -3,51 +3,86 @@ use warnings;
use PostgresNode;
use TestLib;
use Test::More;
use Test::More tests => 4;
use Time::HiRes qw(usleep);
if ($windows_os)
{
plan skip_all => 'logrotate test not supported on Windows';
exit;
}
else
{
plan tests => 1;
}
my $tempdir = TestLib::tempdir;
# Set up node with logging collector
my $node = get_new_node('primary');
$node->init(allows_streaming => 1);
$node->init();
$node->append_conf(
'postgresql.conf', qq(
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql.log'
lc_messages = 'C'
));
$node->start();
# Rename log file and rotate log. Then log file should appear again.
# Verify that log output gets to the file
my $logfile = $node->data_dir . '/log/postgresql.log';
my $old_logfile = $node->data_dir . '/log/postgresql.old';
rename($logfile, $old_logfile);
$node->psql('postgres', 'SELECT 1/0');
$node->logrotate();
my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
# pg_ctl logrotate doesn't wait until rotation request being completed. So
# we have to wait some time until log file appears.
my $attempts = 0;
note "current_logfiles = $current_logfiles";
like($current_logfiles, qr|^stderr log/postgresql-.*log$|,
'current_logfiles is sane');
my $lfname = $current_logfiles;
$lfname =~ s/^stderr //;
chomp $lfname;
# might need to retry if logging collector process is slow...
my $max_attempts = 180 * 10;
while (not -e $logfile and $attempts < $max_attempts)
my $first_logfile;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
{
$first_logfile = slurp_file($node->data_dir . '/' . $lfname);
last if $first_logfile =~ m/division by zero/;
usleep(100_000);
$attempts++;
}
ok(-e $logfile, "log file exists");
like($first_logfile, qr/division by zero/,
'found expected log file content');
# Sleep 2 seconds and ask for log rotation; this should result in
# output into a different log file name.
sleep(2);
$node->logrotate();
# pg_ctl logrotate doesn't wait for rotation request to be completed.
# Allow a bit of time for it to happen.
my $new_current_logfiles;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
{
$new_current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
last if $new_current_logfiles ne $current_logfiles;
usleep(100_000);
}
note "now current_logfiles = $new_current_logfiles";
like($new_current_logfiles, qr|^stderr log/postgresql-.*log$|,
'new current_logfiles is sane');
$lfname = $new_current_logfiles;
$lfname =~ s/^stderr //;
chomp $lfname;
# Verify that log output gets to this file, too
$node->psql('postgres', 'fee fi fo fum');
my $second_logfile;
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
{
$second_logfile = slurp_file($node->data_dir . '/' . $lfname);
last if $second_logfile =~ m/syntax error/;
usleep(100_000);
}
like($second_logfile, qr/syntax error/,
'found expected log file content in new log file');
$node->stop();