From dfb17c0b1804b9e54a287e6a058d02dd1be27ffb Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehrope@jackdb.com>
Date: Tue, 31 Aug 2021 10:00:54 -0400
Subject: [PATCH 2/4] Add TAP test for csvlog

---
 src/bin/pg_ctl/t/005_csvlog.pl | 118 +++++++++++++++++++++++++++++++++
 1 file changed, 118 insertions(+)
 create mode 100644 src/bin/pg_ctl/t/005_csvlog.pl

diff --git a/src/bin/pg_ctl/t/005_csvlog.pl b/src/bin/pg_ctl/t/005_csvlog.pl
new file mode 100644
index 0000000000..c6ab0ddbcc
--- /dev/null
+++ b/src/bin/pg_ctl/t/005_csvlog.pl
@@ -0,0 +1,118 @@
+use strict;
+use warnings;
+
+use PostgresNode;
+use TestLib;
+use Test::More tests => 4;
+use Time::HiRes qw(usleep);
+
+# Set up node with logging collector
+my $node = PostgresNode->new('primary');
+$node->init();
+$node->append_conf(
+	'postgresql.conf', qq(
+logging_collector = on
+lc_messages = 'C'
+log_destination = 'csvlog'
+));
+
+$node->start();
+
+note "Before sleep";
+usleep(100_000);
+note "Before rotate";
+$node->logrotate();
+note "After rotate";
+usleep(100_000);
+note "After rotate sleep";
+
+# Verify that log output gets to the file
+
+$node->psql('postgres', 'SELECT 1/0');
+
+my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+
+for(my $tmp=0;$tmp < 10;$tmp++) {
+   my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+   note "current_logfiles = $current_logfiles";
+   usleep(100_000);
+}
+
+
+like(
+	$current_logfiles,
+	qr|^csvlog log/postgresql-.*$|,
+	'current_logfiles is sane');
+
+my $lfname = $current_logfiles;
+$lfname =~ s/^csvlog //;
+chomp $lfname;
+
+note "current_logfiles = $current_logfiles";
+note "lfname = $lfname";
+
+# 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++)
+{
+    my $foo = $node->data_dir . '/' . $lfname;
+    note "will slurp: $foo";
+    $first_logfile = slurp_file($node->data_dir . '/' . $lfname);
+	last if $first_logfile =~ m/division by zero/;
+	usleep(100_000);
+}
+
+note "first_logfile = $first_logfile";
+# Our log entry should the error message and errant SQL
+like(
+	$first_logfile,
+	qr/division by zero.*"SELECT 1\/0"/,
+	'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|^csvlog log/postgresql-.*$|,
+	'new current_logfiles is sane');
+
+$lfname = $new_current_logfiles;
+$lfname =~ s/^csvlog //;
+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,
+	# Our log entry should have our bad string wrapped in quotes after the error
+	qr/syntax error.*,"fee fi fo fum"/,
+	'found expected log file content in new log file');
+
+$node->stop();
-- 
2.17.1