Hi,
While working on adding a new log_destination I noticed that the
syslogger piping would need to be updated. At the moment both ends
only handle stderr/csvlog as the pipe message header has a char
"is_last" that is either t/f (stderr last, stderr partial) or T/F
(csvlog last, csvlog partial). Couple approaches came to mind:
1. Use additional pairs of chars for each additional destination (e.g.
x/X, y/Y, ...) and mimic the logic of csvlog.
2. Repurpose the char "is_last" as a bitmap of the log destination
with the highest order bit indicating whether it's the last chunk.
3. Add a separate field "dest" for the log destination and leave
"is_last" as a t/f indicating whether it's the last chunk.
Attached are patches for each approach (fun exercise!). Also attached
is a basic TAP test to invoke the csvlog destination. It's a clone of
pg_ctl log rotation test that looks for .csv logs. If there's interest
in the test I was thinking of expanding it a bit to include "big"
output that would span multiple messages to test the partial/combining
path. My thoughts on the approaches:
#1 doesn't change the header types or size but seems ugly as it leads
to new pairs of constants and logic in multiple places. In particular,
both send and receive ends have to encode and decode the destination.
#2 is cleaner as there's a logical separation of the dest fields and
no need for new constant pairs when adding new destinations. Would
also need to ensure new LOG_DESTINATION_xyz constants do not use that
last bit (there's already four now so room for three more).
#3 leads to the cleanest code though you lose 4-bytes of max data size
per chunk.
Which would be preferable? I'd like to validate the approach as the
new log destination would be built atop it. I leaning toward #3 though
if the 4-byte loss is a deal breaker then #2.
Regards,
-- Sehrope Sarkuni
Founder & CEO | JackDB, Inc. | https://www.jackdb.com/
From 9ec38a587b0c2645bc9fd73398c1debdf9fa962b Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehr...@jackdb.com>
Date: Wed, 10 Jul 2019 09:27:44 -0400
Subject: [PATCH 1/2] Add basic test for csvlog
---
src/bin/pg_ctl/t/005_csvlog.pl | 94 ++++++++++++++++++++++++++++++++++
1 file changed, 94 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..b74c373bb6
--- /dev/null
+++ b/src/bin/pg_ctl/t/005_csvlog.pl
@@ -0,0 +1,94 @@
+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 = get_new_node('primary');
+$node->init();
+$node->append_conf(
+ 'postgresql.conf', qq(
+logging_collector = on
+lc_messages = 'C'
+log_destination = 'csvlog'
+));
+
+$node->start();
+
+# Verify that log output gets to the file
+
+$node->psql('postgres', 'SELECT 1/0');
+
+my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+
+note "current_logfiles = $current_logfiles";
+
+like(
+ $current_logfiles,
+ qr|^csvlog log/postgresql-.*csv$|,
+ 'current_logfiles is sane');
+
+my $lfname = $current_logfiles;
+$lfname =~ s/^csvlog //;
+chomp $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++)
+{
+ $first_logfile = slurp_file($node->data_dir . '/' . $lfname);
+ last if $first_logfile =~ m/division by zero/;
+ usleep(100_000);
+}
+
+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|^csvlog log/postgresql-.*csv$|,
+ '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,
+ qr/syntax error/,
+ 'found expected log file content in new log file');
+
+$node->stop();
--
2.17.1
From 7b9d827e5059445945d214388371138f0676b306 Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehr...@jackdb.com>
Date: Wed, 10 Jul 2019 07:17:58 -0400
Subject: [PATCH 2/2] Refactor PipeProtoHeader.is_last constants
Adds constants for PipeProtoHeader.is_last and refactors the
syslogger pipe sending and receiving code to use them in place
of the hard coded char codes.
---
src/backend/postmaster/syslogger.c | 13 ++++++++-----
src/backend/utils/error/elog.c | 10 ++++++++--
src/include/postmaster/syslogger.h | 14 ++++++++++++--
3 files changed, 28 insertions(+), 9 deletions(-)
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index bafd31d22b..86ad86cf7f 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -892,8 +892,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
- (p.is_last == 't' || p.is_last == 'f' ||
- p.is_last == 'T' || p.is_last == 'F'))
+ (p.is_last == PIPE_DEST_STDERR_LAST || p.is_last == PIPE_DEST_STDERR_PART ||
+ p.is_last == PIPE_DEST_CSVLOG_LAST || p.is_last == PIPE_DEST_CSVLOG_PART))
{
List *buffer_list;
ListCell *cell;
@@ -907,8 +907,10 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (count < chunklen)
break;
- dest = (p.is_last == 'T' || p.is_last == 'F') ?
- LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
+ if (p.is_last == PIPE_DEST_CSVLOG_LAST || p.is_last == PIPE_DEST_CSVLOG_PART)
+ dest = LOG_DESTINATION_CSVLOG;
+ else
+ dest = LOG_DESTINATION_STDERR;
/* Locate any existing buffer for this source pid */
buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
@@ -925,7 +927,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
free_slot = buf;
}
- if (p.is_last == 'f' || p.is_last == 'F')
+ if (p.is_last == PIPE_DEST_CSVLOG_PART ||
+ p.is_last == PIPE_DEST_STDERR_PART)
{
/*
* Save a complete non-final chunk in a per-pid buffer
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8b4720ef3a..16615ed2b8 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -3089,7 +3089,10 @@ write_pipe_chunks(char *data, int len, int dest)
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
{
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f');
+ if (dest == LOG_DESTINATION_CSVLOG)
+ p.proto.is_last = PIPE_DEST_CSVLOG_PART;
+ else
+ p.proto.is_last = PIPE_DEST_STDERR_PART;
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
rc = write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
@@ -3099,7 +3102,10 @@ write_pipe_chunks(char *data, int len, int dest)
}
/* write the last chunk */
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't');
+ if (dest == LOG_DESTINATION_CSVLOG)
+ p.proto.is_last = PIPE_DEST_CSVLOG_LAST;
+ else
+ p.proto.is_last = PIPE_DEST_STDERR_LAST;
p.proto.len = len;
memcpy(p.proto.data, data, len);
rc = write(fd, &p, PIPE_HEADER_SIZE + len);
diff --git a/src/include/postmaster/syslogger.h b/src/include/postmaster/syslogger.h
index 3a61104573..df60fdcb96 100644
--- a/src/include/postmaster/syslogger.h
+++ b/src/include/postmaster/syslogger.h
@@ -46,8 +46,7 @@ typedef struct
char nuls[2]; /* always \0\0 */
uint16 len; /* size of this chunk (counts data only) */
int32 pid; /* writer's pid */
- char is_last; /* last chunk of message? 't' or 'f' ('T' or
- * 'F' for CSV case) */
+ char is_last; /* see PIPE_DEST_ constants */
char data[FLEXIBLE_ARRAY_MEMBER]; /* data payload starts here */
} PipeProtoHeader;
@@ -60,6 +59,17 @@ typedef union
#define PIPE_HEADER_SIZE offsetof(PipeProtoHeader, data)
#define PIPE_MAX_PAYLOAD ((int) (PIPE_CHUNK_SIZE - PIPE_HEADER_SIZE))
+/*
+ * Possible values for PipeProtoHeader.is_last to identify the log
+ * destination and whether the message is complete.
+ *
+ * Values suffixed by _PART indicate a partial chunk of a message.
+ * Values suffxied by _LAST indicate the last chunk of a message.
+ */
+#define PIPE_DEST_STDERR_PART 'f'
+#define PIPE_DEST_STDERR_LAST 't'
+#define PIPE_DEST_CSVLOG_PART 'F'
+#define PIPE_DEST_CSVLOG_LAST 'T'
/* GUC options */
extern bool Logging_collector;
--
2.17.1
From ad3fd72018fec9b180860c7d868de766ee7c1c4f Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehr...@jackdb.com>
Date: Wed, 10 Jul 2019 09:29:15 -0400
Subject: [PATCH 2/2] Use log destination bitmap in log pipe protocol
Replaces the dest field in PipeProtoHeader with dest_last, a
bitmap of the log destination and whether the message is the
last chunk of a message.
---
src/backend/postmaster/syslogger.c | 12 +++++-------
src/backend/utils/error/elog.c | 4 ++--
src/include/postmaster/syslogger.h | 5 +++--
src/include/utils/elog.h | 5 ++++-
4 files changed, 14 insertions(+), 12 deletions(-)
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index bafd31d22b..f8a8cee401 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -879,21 +879,22 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
char *cursor = logbuffer;
int count = *bytes_in_logbuffer;
- int dest = LOG_DESTINATION_STDERR;
/* While we have enough for a header, process data... */
while (count >= (int) (offsetof(PipeProtoHeader, data) + 1))
{
PipeProtoHeader p;
int chunklen;
+ int dest;
/* Do we have a valid header? */
memcpy(&p, cursor, offsetof(PipeProtoHeader, data));
+ dest = p.dest_last & ~PIPE_MESSAGE_IS_LAST;
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
- (p.is_last == 't' || p.is_last == 'f' ||
- p.is_last == 'T' || p.is_last == 'F'))
+ (dest == LOG_DESTINATION_CSVLOG ||
+ dest == LOG_DESTINATION_STDERR))
{
List *buffer_list;
ListCell *cell;
@@ -907,9 +908,6 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (count < chunklen)
break;
- dest = (p.is_last == 'T' || p.is_last == 'F') ?
- LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
-
/* Locate any existing buffer for this source pid */
buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
foreach(cell, buffer_list)
@@ -925,7 +923,7 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
free_slot = buf;
}
- if (p.is_last == 'f' || p.is_last == 'F')
+ if (!(p.dest_last & PIPE_MESSAGE_IS_LAST))
{
/*
* Save a complete non-final chunk in a per-pid buffer
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8b4720ef3a..e69fb6b87c 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -3089,7 +3089,7 @@ write_pipe_chunks(char *data, int len, int dest)
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
{
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f');
+ p.proto.dest_last = (unsigned char) dest;
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
rc = write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
@@ -3099,7 +3099,7 @@ write_pipe_chunks(char *data, int len, int dest)
}
/* write the last chunk */
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't');
+ p.proto.dest_last = (unsigned char) (dest | PIPE_MESSAGE_IS_LAST);
p.proto.len = len;
memcpy(p.proto.data, data, len);
rc = write(fd, &p, PIPE_HEADER_SIZE + len);
diff --git a/src/include/postmaster/syslogger.h b/src/include/postmaster/syslogger.h
index 3a61104573..3b95700cdb 100644
--- a/src/include/postmaster/syslogger.h
+++ b/src/include/postmaster/syslogger.h
@@ -46,8 +46,8 @@ typedef struct
char nuls[2]; /* always \0\0 */
uint16 len; /* size of this chunk (counts data only) */
int32 pid; /* writer's pid */
- char is_last; /* last chunk of message? 't' or 'f' ('T' or
- * 'F' for CSV case) */
+ unsigned char dest_last; /* bitmap for log destination and whether
+ * this is the last chunk of message */
char data[FLEXIBLE_ARRAY_MEMBER]; /* data payload starts here */
} PipeProtoHeader;
@@ -60,6 +60,7 @@ typedef union
#define PIPE_HEADER_SIZE offsetof(PipeProtoHeader, data)
#define PIPE_MAX_PAYLOAD ((int) (PIPE_CHUNK_SIZE - PIPE_HEADER_SIZE))
+#define PIPE_MESSAGE_IS_LAST (1<<7)
/* GUC options */
extern bool Logging_collector;
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index dbfd8efd26..c9f33c8a5f 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -408,7 +408,10 @@ extern char *Log_destination_string;
extern bool syslog_sequence_numbers;
extern bool syslog_split_messages;
-/* Log destination bitmap */
+/*
+ * Log destination bitmap
+ * Max value is 1<<6 as PipeProtoHeader.dest_last uses the last bit as a flag.
+ */
#define LOG_DESTINATION_STDERR 1
#define LOG_DESTINATION_SYSLOG 2
#define LOG_DESTINATION_EVENTLOG 4
--
2.17.1
From 09c12681becf43bbf3d6a62a927fa30c7ffa59a9 Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehr...@jackdb.com>
Date: Wed, 10 Jul 2019 10:02:31 -0400
Subject: [PATCH 2/2] Adds separate dest field to log protocol PipeProtoHeader
Adds a separate dest field to PipeProtoHeader to store the log destination
requested by the sending process. Also changes the is_last field to only
store whether the chunk is the last one for a message rather than also
including whether the destination is csvlog.
---
src/backend/postmaster/syslogger.c | 15 ++++++---------
src/backend/utils/error/elog.c | 5 +++--
src/include/postmaster/syslogger.h | 4 ++--
3 files changed, 11 insertions(+), 13 deletions(-)
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index bafd31d22b..92c9af3266 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -879,7 +879,6 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
char *cursor = logbuffer;
int count = *bytes_in_logbuffer;
- int dest = LOG_DESTINATION_STDERR;
/* While we have enough for a header, process data... */
while (count >= (int) (offsetof(PipeProtoHeader, data) + 1))
@@ -892,8 +891,9 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
- (p.is_last == 't' || p.is_last == 'f' ||
- p.is_last == 'T' || p.is_last == 'F'))
+ (p.is_last == 't' || p.is_last == 'f') &&
+ (p.dest == LOG_DESTINATION_CSVLOG ||
+ p.dest == LOG_DESTINATION_STDERR))
{
List *buffer_list;
ListCell *cell;
@@ -907,9 +907,6 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (count < chunklen)
break;
- dest = (p.is_last == 'T' || p.is_last == 'F') ?
- LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
-
/* Locate any existing buffer for this source pid */
buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
foreach(cell, buffer_list)
@@ -925,7 +922,7 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
free_slot = buf;
}
- if (p.is_last == 'f' || p.is_last == 'F')
+ if (p.is_last == 'f')
{
/*
* Save a complete non-final chunk in a per-pid buffer
@@ -971,7 +968,7 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
appendBinaryStringInfo(str,
cursor + PIPE_HEADER_SIZE,
p.len);
- write_syslogger_file(str->data, str->len, dest);
+ write_syslogger_file(str->data, str->len, p.dest);
/* Mark the buffer unused, and reclaim string storage */
existing_slot->pid = 0;
pfree(str->data);
@@ -980,7 +977,7 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
/* The whole message was one chunk, evidently. */
write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
- dest);
+ p.dest);
}
}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8b4720ef3a..e543a22021 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -3085,11 +3085,12 @@ write_pipe_chunks(char *data, int len, int dest)
p.proto.nuls[0] = p.proto.nuls[1] = '\0';
p.proto.pid = MyProcPid;
+ p.proto.dest = (int32) dest;
+ p.proto.is_last = 'f';
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
{
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'F' : 'f');
p.proto.len = PIPE_MAX_PAYLOAD;
memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD);
rc = write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD);
@@ -3099,7 +3100,7 @@ write_pipe_chunks(char *data, int len, int dest)
}
/* write the last chunk */
- p.proto.is_last = (dest == LOG_DESTINATION_CSVLOG ? 'T' : 't');
+ p.proto.is_last = 't';
p.proto.len = len;
memcpy(p.proto.data, data, len);
rc = write(fd, &p, PIPE_HEADER_SIZE + len);
diff --git a/src/include/postmaster/syslogger.h b/src/include/postmaster/syslogger.h
index 3a61104573..ca4782ebeb 100644
--- a/src/include/postmaster/syslogger.h
+++ b/src/include/postmaster/syslogger.h
@@ -46,8 +46,8 @@ typedef struct
char nuls[2]; /* always \0\0 */
uint16 len; /* size of this chunk (counts data only) */
int32 pid; /* writer's pid */
- char is_last; /* last chunk of message? 't' or 'f' ('T' or
- * 'F' for CSV case) */
+ int32 dest; /* log destination */
+ char is_last; /* last chunk of message? 't' or 'f'*/
char data[FLEXIBLE_ARRAY_MEMBER]; /* data payload starts here */
} PipeProtoHeader;
--
2.17.1
