serverlog rotation/functions

Andreas Pflug <pgadmin@pse-consulting.de> writes:

The attached patch includes serverlog rotation with minimal shared
memory usage as discussed and functions to access it.

This patch is still unsafe and unworkable. Why would you make the
mechanism dependent on shared memory *and* an intermediate data file
*and* an inherited file handle to access that data file? The inherited
handle is subject to race conditions (because you've got different
processes fseeking the same file descriptor with no interlocking) and
I don't really see that it's buying anything anyway. If you stored the
value of time(NULL) to use in shared memory, you'd not need the data
file because every process could compute the correct logfile name for
itself.

An issue that doesn't matter a whole lot on Unix, but I think would
matter on Windows, is that with the patch as given a process will not
reopen the log file until it's got something to write there. Non-chatty
processes could easily hold open the old log file indefinitely. It
might be a good idea to force the log file to be reopened at SIGHUP,
and for the "rotate" command to do such a SIGHUP.

Overall though, I still quite fail to see the point of doing it this
way compared to piping the postmaster's stderr into something that can
rotate log files. The fundamental objection to this whole feature is
that it can only capture elog output, which is not everything of
interest. (For example, dynamic linker failures will usually be
reported to stderr, a behavior that we cannot override.)

regards, tom lane

Tom Lane wrote:

Andreas Pflug <pgadmin@pse-consulting.de> writes:

The attached patch includes serverlog rotation with minimal shared
memory usage as discussed and functions to access it.

This patch is still unsafe and unworkable. Why would you make the
mechanism dependent on shared memory *and* an intermediate data file
*and* an inherited file handle to access that data file? The inherited
handle is subject to race conditions (because you've got different
processes fseeking the same file descriptor with no interlocking) and
I don't really see that it's buying anything anyway. If you stored the
value of time(NULL) to use in shared memory, you'd not need the data
file because every process could compute the correct logfile name for
itself.

'k, the timestamp may be used as a flag to reopen too, probably better
than that filehandle stuff. I can rewrite that.

An issue that doesn't matter a whole lot on Unix, but I think would
matter on Windows, is that with the patch as given a process will not
reopen the log file until it's got something to write there. Non-chatty
processes could easily hold open the old log file indefinitely. It
might be a good idea to force the log file to be reopened at SIGHUP,
and for the "rotate" command to do such a SIGHUP.

Why do you expect problems on win32 here? I intentionally did *not* tie
this to a SIGHUP, which I consider to be quite an expensive signal for
this case, to reopen a file that is (hopefully) rarely used. Imagine 100
backends, SIGHUPping every minute or so. But certainly a backend could
check for the logfile to be current when SIGHUP is received.

Overall though, I still quite fail to see the point of doing it this
way compared to piping the postmaster's stderr into something that can
rotate log files. The fundamental objection to this whole feature is
that it can only capture elog output, which is not everything of
interest. (For example, dynamic linker failures will usually be
reported to stderr, a behavior that we cannot override.)

If this "something" is tightly coupled to the postmaster, and can be
retrieved over a database connection, fine.
The restriction about messages going to stderr are valid for
log_destination syslog too, so the new log_destination=file is no
regression. What would you use on win32? Piping stderr isn't really
popular there, and eventlog is shared between all apps (that's probably
the reason why M$ uses an own log infrastructure for MSSQL).

Regards,
Andreas

Updated version.

Only timestamp of fresh logfile in shared mem, with sanity checks.
On SIGHUP, timestamp is checked if rotation was issued, as well as
changed log_filename setting from postgresql.conf.

Regards,
Andreas

How is this patch supposed to work? Do people need to modify
postgresql.conf and then sighup the postmaster? It seems more logical
for the super-user to call a server-side function. You have
pg_logfile_rotate(), but that doesn't send a sighup to the postmaster so
all the backends will reread the global log file name.

Also, what mechanism is there to prevent backends from reading the log
filename _while_ it is being modified?

Also there are no documenttion changes.

However, looking at the issue of backends all reloading their
postgresql.conf files at different times and sending output to different
files, I wonder if it would be best to create a log process and have
each backend connect to that. That way, all the logging happens in one
process.

---------------------------------------------------------------------------

Andreas Pflug wrote:

Updated version.

Only timestamp of fresh logfile in shared mem, with sanity checks.
On SIGHUP, timestamp is checked if rotation was issued, as well as
changed log_filename setting from postgresql.conf.

Regards,
Andreas

Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.405
diff -u -r1.405 postmaster.c
--- src/backend/postmaster/postmaster.c	24 Jun 2004 21:02:55 -0000	1.405
+++ src/backend/postmaster/postmaster.c	6 Jul 2004 22:12:22 -0000
@@ -729,6 +729,11 @@
reset_shared(PostPortNumber);

/*
+	 * Opens alternate log file
+	 */
+	LogFileInit();
+
+	/*
* Estimate number of openable files.  This must happen after setting
* up semaphores, because on some platforms semaphores count as open
* files.
Index: src/backend/utils/adt/misc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/adt/misc.c,v
retrieving revision 1.35
diff -u -r1.35 misc.c
--- src/backend/utils/adt/misc.c	2 Jul 2004 18:59:22 -0000	1.35
+++ src/backend/utils/adt/misc.c	6 Jul 2004 22:12:34 -0000
@@ -202,3 +202,137 @@
FreeDir(fctx->dirdesc);
SRF_RETURN_DONE(funcctx);
}
+
+
+extern FILE *logfile; // in elog.c
+#define MAXLOGFILECHUNK 50000
+
+static char *absClusterPath(text *arg)
+{
+	char *filename;
+
+	if (is_absolute_path(VARDATA(arg)))
+		filename=VARDATA(arg);
+	else
+	{
+		filename = palloc(strlen(DataDir)+VARSIZE(arg)+2);
+		sprintf(filename, "%s/%s", DataDir, VARDATA(arg));
+	}
+	return filename;
+}
+
+
+Datum pg_logfile_get(PG_FUNCTION_ARGS)
+{
+	size_t size=MAXLOGFILECHUNK;
+	char *buf=0;
+	size_t nbytes;
+	FILE *f;
+
+	if (!PG_ARGISNULL(0))
+		size = PG_GETARG_INT32(0);
+	if (size > MAXLOGFILECHUNK)
+	{
+		size = MAXLOGFILECHUNK;
+		ereport(WARNING,
+				(errcode(ERRCODE_OUT_OF_MEMORY),
+				 errmsg("Maximum size is %d.", size)));
+	}
+
+	if (PG_ARGISNULL(2))
+		f = logfile;
+	else
+	{
+        /* explicitely named logfile */
+		char *filename = absClusterPath(PG_GETARG_TEXT_P(2));
+		f = fopen(filename, "r");
+		if (!f)
+		{
+			ereport(WARNING,
+					(errcode_for_file_access(),
+					 errmsg("file not found %s", filename)));
+			PG_RETURN_NULL();
+		}
+	}
+
+	if (f)
+	{
+
+		if (PG_ARGISNULL(1))
+			fseek(f, -size, SEEK_END);
+		else
+		{
+			long pos = PG_GETARG_INT32(1);
+			if (pos >= 0)
+				fseek(f, pos, SEEK_SET);
+			else
+				fseek(f, pos, SEEK_END);
+		}
+		buf = palloc(size+1);
+		nbytes = fread(buf, 1, size, f);
+		buf[nbytes] = 0;
+
+		fseek(f, 0, SEEK_END);
+
+		if (!PG_ARGISNULL(2))
+			fclose(f);
+	}
+
+	if (buf)
+		PG_RETURN_CSTRING(buf);
+	else
+		PG_RETURN_NULL();
+}
+
+
+Datum pg_logfile_length(PG_FUNCTION_ARGS)
+{
+	if (PG_ARGISNULL(0))
+	{
+		if (logfile)
+		{
+			fflush(logfile);
+			PG_RETURN_INT32(ftell(logfile));
+		}
+	}
+	else
+	{
+		struct stat fst;
+		fst.st_size=0;
+		stat(absClusterPath(PG_GETARG_TEXT_P(0)), &fst);
+
+		PG_RETURN_INT32(fst.st_size);
+	}
+	PG_RETURN_INT32(0);
+}
+
+
+Datum pg_logfile_name(PG_FUNCTION_ARGS)
+{
+	char *filename=LogFileName();
+	if (filename)
+	{
+		if (strncmp(filename, DataDir, strlen(DataDir)))
+			PG_RETURN_CSTRING(filename);
+		else
+			PG_RETURN_CSTRING(filename+strlen(DataDir)+1);
+	}
+	PG_RETURN_NULL();
+}
+
+
+Datum pg_logfile_rotate(PG_FUNCTION_ARGS)
+{
+	char *renamedFile = LogFileRotate();
+
+	if (renamedFile)
+	{
+		if (strncmp(renamedFile, DataDir, strlen(DataDir)))
+			PG_RETURN_CSTRING(renamedFile);
+		else
+			PG_RETURN_CSTRING(renamedFile+strlen(DataDir)+1);
+	}
+	else
+		PG_RETURN_NULL();
+}
+
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.142
diff -u -r1.142 elog.c
--- src/backend/utils/error/elog.c	24 Jun 2004 21:03:13 -0000	1.142
+++ src/backend/utils/error/elog.c	6 Jul 2004 22:12:37 -0000
@@ -63,7 +63,6 @@
#include "utils/memutils.h"
#include "utils/guc.h"

-
/* Global variables */
ErrorContextCallback *error_context_stack = NULL;

@@ -71,9 +70,17 @@
PGErrorVerbosity Log_error_verbosity = PGERROR_VERBOSE;
char *Log_line_prefix = NULL; /* format for extra log line info */
unsigned int Log_destination = LOG_DESTINATION_STDERR;
+char *Log_filename = NULL;

bool in_fatal_exit = false;

+FILE *logfile = NULL;                     /* the logfile we're writing to */
+static char logfileName[MAXPGPATH];       /* current filename */
+static pg_time_t logfileTimestamp=0;      /* logfile version this backend is currently using */
+
+static pg_time_t *globalLogfileTimestamp = NULL; /* logfile version the backend should be using (shared mem) */
+
+
#ifdef HAVE_SYSLOG
char	   *Syslog_facility;	/* openlog() parameters */
char	   *Syslog_ident;
@@ -140,6 +147,9 @@
static const char *error_severity(int elevel);
static void append_with_tabs(StringInfo buf, const char *str);

+static char *logfile_getname(pg_time_t timestamp);
+static void logfile_reopen(void);
+

/*
* errstart --- begin an error-reporting cycle
@@ -931,11 +941,181 @@
/*
* And let errfinish() finish up.
*/
+
errfinish(0);
}

/*
+ * Initialize shared mem for logfile rotation
+ */
+
+void
+LogFileInit(void)
+{
+	if (!globalLogfileTimestamp && Log_filename && (Log_destination & LOG_DESTINATION_FILE))
+	{
+        /* allocate logfile version shared memory segment for rotation signaling */
+		globalLogfileTimestamp = ShmemAlloc(sizeof(pg_time_t));
+		if (!globalLogfileTimestamp)
+		{
+			ereport(FATAL,
+					(errcode(ERRCODE_OUT_OF_MEMORY),
+					 errmsg("Out of shared memory")));
+			return;
+		}
+			
+		*globalLogfileTimestamp = time(NULL);
+
+		/* open logfile after we successfully initialized */
+		logfile_reopen();
+	}
+}
+
+
+/*
+ * Rotate log file
+ */
+char *
+LogFileRotate(void)
+{
+	char *filename;
+	char *oldFilename;
+	pg_time_t now;
+
+	if (!globalLogfileTimestamp || !logfileName || !(Log_destination & LOG_DESTINATION_FILE))
+		return NULL;
+
+	now = time(NULL);
+
+	filename = logfile_getname(now);
+	if (!filename)
+		return NULL;
+
+	if (!strcmp(filename, logfileName))
+	{
+		ereport(ERROR,
+				(errcode(ERRCODE_CONFIG_FILE_ERROR),
+				 errmsg("Log_filename not suitable for rotation.")));
+		return NULL;
+	}
+
+	oldFilename = pstrdup(logfileName);
+	*globalLogfileTimestamp = now;
+
+	ereport(NOTICE,
+			(errcode(ERRCODE_WARNING),
+			 errmsg("Opened new log file %s; previous logfile %s", filename, oldFilename)));
+
+	return oldFilename;
+}
+
+
+/*
+ * return current log file name
+ */
+char*
+LogFileName(void)
+{
+	if (logfileName)
+		return pstrdup(logfileName);
+	return NULL;
+}
+
+
+/*
+ * check if logfile has to be reopened
+ * if called from ProcessConfigFile after SIGHUP, also check for filename template change
+ */
+void LogFileCheckReopen(bool fromSIGHUP)
+{
+	if (globalLogfileTimestamp)
+	{
+		if (*globalLogfileTimestamp != logfileTimestamp)
+		{
+			/* sanity check: if it's in the future, shmem probably corrupted */
+			pg_time_t now=time(NULL);
+			if (*globalLogfileTimestamp > now)
+				*globalLogfileTimestamp = now;
+
+			logfile_reopen();
+		}
+		else if (fromSIGHUP)
+		{
+			char *filename = logfile_getname(logfileTimestamp);
+			if (filename && strcmp(filename, logfileName))
+			{
+				/* template for logfile was changed */
+				logfile_reopen();
+				pfree(filename);
+			}
+		}
+	}
+}
+
+
+/*
+ * creates logfile name using timestamp information
+ */
+static char*
+logfile_getname(pg_time_t timestamp)
+{
+	char *filetemplate;
+	char *filename;
+
+	if (is_absolute_path(Log_filename))
+		filetemplate = pstrdup(Log_filename);
+	else
+	{
+		filetemplate = palloc(strlen(DataDir) + strlen(Log_filename) + 2);
+		sprintf(filetemplate, "%s/%s", DataDir, Log_filename);
+	}
+	filename = palloc(MAXPGPATH);
+	pg_strftime(filename, MAXPGPATH, filetemplate, pg_localtime(&timestamp));
+
+	pfree(filetemplate);
+
+	return filename;
+}
+
+
+/*
+ * reopen log file.
+ */
+static void
+logfile_reopen(void)
+{
+	if (logfile)
+	{
+		fclose(logfile);
+		logfile = NULL;
+	}
+
+	if ((Log_destination & LOG_DESTINATION_FILE) && globalLogfileTimestamp)
+	{
+		char *fn;
+
+		logfileTimestamp = *globalLogfileTimestamp;
+
+		fn=logfile_getname(logfileTimestamp);
+
+		if (fn)
+		{
+			logfile = fopen(fn, "a+");
+			
+			if (!logfile)
+				ereport(ERROR,
+						(errcode_for_file_access(),
+						 errmsg("failed to open log file %s", fn)));
+
+			strcpy(logfileName, fn);
+			pfree(fn);
+		}
+	}
+}
+
+
+/*
* Initialization of error output file
*/
void
@@ -1455,6 +1635,20 @@
if ((Log_destination & LOG_DESTINATION_STDERR) || whereToSendOutput == Debug)
{
fprintf(stderr, "%s", buf.data);
+	}
+
+	/* Write to file, if enabled */
+	if (logfile && (Log_destination & LOG_DESTINATION_FILE))
+	{
+		/* check if logfile changed */
+		LogFileCheckReopen(false);
+
+		if (logfile)
+		{
+			fseek(logfile, 0, SEEK_END);
+			fprintf(logfile, "%s", buf.data);
+			fflush(logfile);
+		}
}

pfree(buf.data);
Index: src/backend/utils/misc/guc-file.l
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc-file.l,v
retrieving revision 1.22
diff -u -r1.22 guc-file.l
--- src/backend/utils/misc/guc-file.l	26 May 2004 15:07:38 -0000	1.22
+++ src/backend/utils/misc/guc-file.l	6 Jul 2004 22:12:38 -0000
@@ -276,6 +276,9 @@
set_config_option(item->name, item->value, context,
PGC_S_FILE, false, true);

+    if (context == PGC_SIGHUP)
+        LogFileCheckReopen(true);
+
cleanup_exit:
free_name_value_list(head);
return;
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.213
diff -u -r1.213 guc.c
--- src/backend/utils/misc/guc.c	5 Jul 2004 23:14:14 -0000	1.213
+++ src/backend/utils/misc/guc.c	6 Jul 2004 22:12:46 -0000
@@ -76,6 +76,8 @@
static const char *assign_log_destination(const char *value,
bool doit, GucSource source);

+extern char *Log_filename;
+
#ifdef HAVE_SYSLOG
extern char *Syslog_facility;
extern char *Syslog_ident;
@@ -1606,13 +1608,23 @@
{
{"log_destination", PGC_POSTMASTER, LOGGING_WHERE,
gettext_noop("Sets the target for log output."),
-		 gettext_noop("Valid values are combinations of stderr, syslog "
+		 gettext_noop("Valid values are combinations of stderr, file, syslog "
"and eventlog, depending on platform."),
GUC_LIST_INPUT
},
&log_destination_string,
"stderr", assign_log_destination, NULL
},
+	{
+		{"log_filename", PGC_SIGHUP, LOGGING_WHERE,
+		 gettext_noop("Sets the target filename for log output."),
+		 gettext_noop("May be specified as relative to the cluster directory "
+					  "or as absolute path."),
+		 GUC_LIST_INPUT | GUC_REPORT
+		},
+		&Log_filename,
+		"postgresql.log.%Y-%m-%d_%H%M%S", NULL, NULL
+	},

#ifdef HAVE_SYSLOG
{
@@ -5033,6 +5045,8 @@

if (pg_strcasecmp(tok,"stderr") == 0)
newlogdest |= LOG_DESTINATION_STDERR;
+		else if (pg_strcasecmp(tok,"file") == 0)
+			newlogdest |= LOG_DESTINATION_FILE;
#ifdef HAVE_SYSLOG
else if (pg_strcasecmp(tok,"syslog") == 0)
newlogdest |= LOG_DESTINATION_SYSLOG;
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.113
diff -u -r1.113 postgresql.conf.sample
--- src/backend/utils/misc/postgresql.conf.sample	7 Apr 2004 05:05:50 -0000	1.113
+++ src/backend/utils/misc/postgresql.conf.sample	6 Jul 2004 22:12:47 -0000
@@ -147,9 +147,12 @@

# - Where to Log -

-#log_destination = 'stderr'	# Valid values are combinations of stderr,
+#log_destination = 'stderr'	# Valid values are combinations of stderr, file,
# syslog and eventlog, depending on
# platform.
+#log_filename = 'postgresql.log.%Y-%m-%d_%H%M%S' # filename if
+                                # 'file' log_destination is used.
+
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'

Index: src/include/catalog/pg_proc.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/catalog/pg_proc.h,v
retrieving revision 1.341
diff -u -r1.341 pg_proc.h
--- src/include/catalog/pg_proc.h	2 Jul 2004 22:49:48 -0000	1.341
+++ src/include/catalog/pg_proc.h	6 Jul 2004 22:13:02 -0000
@@ -3595,6 +3595,14 @@
DATA(insert OID = 2556 ( pg_tablespace_databases	PGNSP PGUID 12 f f t t s 1 26 "26" _null_ pg_tablespace_databases - _null_));
DESCR("returns database oids in a tablespace");

+DATA(insert OID = 2557(  pg_logfile_get                PGNSP PGUID 12 f f f f v 3 2275 "23 23 25" _null_ pg_logfile_get - _null_ ));
+DESCR("return log file contents");
+DATA(insert OID = 2558(  pg_logfile_length		       PGNSP PGUID 12 f f f f v 1 23 "25" _null_ pg_logfile_length - _null_ ));
+DESCR("name of log file");
+DATA(insert OID = 2559(  pg_logfile_name		       PGNSP PGUID 12 f f f f v 0 2275 "" _null_ pg_logfile_name - _null_ ));
+DESCR("length of log file");
+DATA(insert OID = 2560(  pg_logfile_rotate		       PGNSP PGUID 12 f f f f v 0 2275 "" _null_ pg_logfile_rotate - _null_ ));
+DESCR("rotate log file");

/*
* Symbolic values for provolatile column: these indicate whether the result
Index: src/include/utils/builtins.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/utils/builtins.h,v
retrieving revision 1.245
diff -u -r1.245 builtins.h
--- src/include/utils/builtins.h	2 Jul 2004 18:59:25 -0000	1.245
+++ src/include/utils/builtins.h	6 Jul 2004 22:13:05 -0000
@@ -358,6 +358,11 @@
extern Datum pg_cancel_backend(PG_FUNCTION_ARGS);
extern Datum pg_tablespace_databases(PG_FUNCTION_ARGS);

+extern Datum pg_logfile_get(PG_FUNCTION_ARGS);
+extern Datum pg_logfile_length(PG_FUNCTION_ARGS);
+extern Datum pg_logfile_name(PG_FUNCTION_ARGS);
+extern Datum pg_logfile_rotate(PG_FUNCTION_ARGS);
+
/* not_in.c */
extern Datum int4notin(PG_FUNCTION_ARGS);
extern Datum oidnotin(PG_FUNCTION_ARGS);
Index: src/include/utils/elog.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/utils/elog.h,v
retrieving revision 1.69
diff -u -r1.69 elog.h
--- src/include/utils/elog.h	24 Jun 2004 21:03:42 -0000	1.69
+++ src/include/utils/elog.h	6 Jul 2004 22:13:05 -0000
@@ -182,10 +182,14 @@
#define LOG_DESTINATION_STDERR   1
#define LOG_DESTINATION_SYSLOG   2
#define LOG_DESTINATION_EVENTLOG 4
+#define LOG_DESTINATION_FILE     8

/* Other exported functions */
extern void DebugFileOpen(void);
-
+extern void LogFileInit(void);
+extern void LogFileCheckReopen(bool fromSIGHUP);
+extern char *LogFileRotate(void);
+extern char *LogFileName(void);
/*
* Write errors to stderr (or by equal means when stderr is
* not available). Used before ereport/elog can be used

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman@candle.pha.pa.us> writes:

However, looking at the issue of backends all reloading their
postgresql.conf files at different times and sending output to different
files, I wonder if it would be best to create a log process and have
each backend connect to that. That way, all the logging happens in one
process.

That was something that bothered me too. I think in the patch as given,
the GUC parameter determining the logfile name would have to be
PGC_POSTMASTER, ie, you could not change it on the fly because the
backends wouldn't all switch together. There may be some finer-grain
timing issues as well.

On the whole I think that capturing all the backends' stderr via a pipe
and doing the file rotation in a single downstream process is a *much*
cleaner solution. However, I've been saying that right along and
haven't been listened to...

regards, tom lane

Bruce Momjian wrote:

How is this patch supposed to work? Do people need to modify
postgresql.conf and then sighup the postmaster? It seems more logical
for the super-user to call a server-side function.

I assume calling pg_logfile_rotate() to be the standard way. calling
pg_logfile_rotate will increment the internal logfile timestamp, so each
backend's next write to the logfile will lead to a reopen. On the other
hand, if nothing is to be logged, nothing happens in the backends.

You have
pg_logfile_rotate(), but that doesn't send a sighup to the postmaster so
all the backends will reread the global log file name.

As long as there's no SIGHUP, the logfile name template will not change,
so each backend can calculate the logfile's name from the timestamp. In
case a SIGHUP *is* issued, the template might have changed, so despite
an unchanged timestamp the filename to create might be different.
Additionally, SIGHUP will force all backends to check for current
logfile name, and close/reopen if their internal timestamp isn't
up-to-date with the common timestamp.

Also, what mechanism is there to prevent backends from reading the log
filename _while_ it is being modified?

I don't understand your concern. There's no place where the name is
stored, only the GUC log_filename which is actually the template, and
the timestamp (probably accessed atomically by the processor).

Also there are no documenttion changes.

Hm, seems I missed this in this posting; the previous had it. I'll
repost it.

However, looking at the issue of backends all reloading their
postgresql.conf files at different times and sending output to different
files,

We might have a fraction of a second in practice, when a SIGHUP was
issued to reread postgresql.conf, with a log_filename change, and a
backend still writing its log to the "old" log because GUC reread is
deferred for queries that started before SIGHUP. I don't really see a
problem with that.

I wonder if it would be best to create a log process and have

each backend connect to that. That way, all the logging happens in one
process.

<sigh> All I wanted was displaying the serverlog </sigh>

While this might be ultimately the best solution (we even might find a
way to catch stderr without interrupting further stderr piping),
currently this doesn't seem to be the right moment. We'd have several
inter process issues (and more with win32), which probably need some
discussion.
OTOH, if the current implementation is replaced by a log process later,
the api interface probably would stay the same.

Regards,
Andreas

Tom Lane wrote:

That was something that bothered me too. I think in the patch as given,
the GUC parameter determining the logfile name would have to be
PGC_POSTMASTER, ie, you could not change it on the fly because the
backends wouldn't all switch together.

In my original posting it was PGC_POSTMASTER, I changed it recently
after I added rotation handling in ProcessConfigFile. If you think this
is critical, we can revert it.

Regards,
Andreas

Tom Lane wrote:

Bruce Momjian <pgman@candle.pha.pa.us> writes:

However, looking at the issue of backends all reloading their
postgresql.conf files at different times and sending output to different
files, I wonder if it would be best to create a log process and have
each backend connect to that. That way, all the logging happens in one
process.

That was something that bothered me too. I think in the patch as given,
the GUC parameter determining the logfile name would have to be
PGC_POSTMASTER, ie, you could not change it on the fly because the
backends wouldn't all switch together. There may be some finer-grain
timing issues as well.

On the whole I think that capturing all the backends' stderr via a pipe
and doing the file rotation in a single downstream process is a *much*
cleaner solution. However, I've been saying that right along and
haven't been listened to...

I saw Andreas demonstrating the viewing of server log files from pgadmin
at Germany Linuxtag, and it certainly was impressive. However, for
heavy, general usage, I don't think this patch is going to work.

Probably the big thing this program was trying to solve was for the
server to know the output file name, even with log file rotation, and I
don't see a pipe and 'rotatelogs' process really addressing this. It
was also interesting to do the log rotate as a database call.

The only idea I have is for the postmaster to close its stderror the
create a pipe to roatelogs and someone send all messages into there, and
pass the file name from postgresql.conf to that rotatelogs program.
Crazy, I know, but that is the best I can think of. We would then need
a use some API to read the log files, and find the valid numbered log
files. We could also control log file rotations via signals to the log
process.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Andreas Pflug wrote:

Bruce Momjian wrote:

How is this patch supposed to work? Do people need to modify
postgresql.conf and then sighup the postmaster? It seems more logical
for the super-user to call a server-side function.

I assume calling pg_logfile_rotate() to be the standard way. calling
pg_logfile_rotate will increment the internal logfile timestamp, so each
backend's next write to the logfile will lead to a reopen. On the other
hand, if nothing is to be logged, nothing happens in the backends.

Oh, I remember now. You had explained it in a previous email. Only the
timestamp is saved in global memory (not the name). Each backend,
before writing, checks the global and reopens if needed. I see the
LogFileCheckReopen() call in elog.c now, and that is the key to the
whole thing. Sorry I got confused.

One question, you open the logfile in a+ (append/read). Isn't "a" alone
correct?

You have
pg_logfile_rotate(), but that doesn't send a sighup to the postmaster so
all the backends will reread the global log file name.

As long as there's no SIGHUP, the logfile name template will not change,
so each backend can calculate the logfile's name from the timestamp. In
case a SIGHUP *is* issued, the template might have changed, so despite
an unchanged timestamp the filename to create might be different.
Additionally, SIGHUP will force all backends to check for current
logfile name, and close/reopen if their internal timestamp isn't
up-to-date with the common timestamp.

Sounds good. I get it now.

Also, what mechanism is there to prevent backends from reading the log
filename _while_ it is being modified?

I don't understand your concern. There's no place where the name is
stored, only the GUC log_filename which is actually the template, and
the timestamp (probably accessed atomically by the processor).

Also there are no documenttion changes.

Hm, seems I missed this in this posting; the previous had it. I'll
repost it.

However, looking at the issue of backends all reloading their
postgresql.conf files at different times and sending output to different
files,

We might have a fraction of a second in practice, when a SIGHUP was
issued to reread postgresql.conf, with a log_filename change, and a
backend still writing its log to the "old" log because GUC reread is
deferred for queries that started before SIGHUP. I don't really see a
problem with that.

You are right. Each backend reads the postgresql.conf file itself so
there is not a real problem except for backends that are delayed
rereading. I don't see that as a huge problem because if you change the
postgresql.conf to log to a different file location (file name aleady
changes with reload call to be current time), you should expect a delay.
The rotate is pretty fast.

While this might be ultimately the best solution (we even might find a
way to catch stderr without interrupting further stderr piping),
currently this doesn't seem to be the right moment. We'd have several
inter process issues (and more with win32), which probably need some
discussion.
OTOH, if the current implementation is replaced by a log process later,
the api interface probably would stay the same.

OK, I withdraw my concerns. It looks quite interesting (with docs you
already have).

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I saw Andreas demonstrating the viewing of server log files from pgadmin
at Germany Linuxtag, and it certainly was impressive. However, for
heavy, general usage, I don't think this patch is going to work.

That's my gut feeling as well.

Probably the big thing this program was trying to solve was for the
server to know the output file name, even with log file rotation, and I
don't see a pipe and 'rotatelogs' process really addressing this.

It could be done. Given the infrastructure we have now, it's possible
to imagine the log capture process being a child of the postmaster that
can respond to GUC SIGHUPs (or forget that and just freeze the file name
pattern at PGC_POSTMASTER time, which isn't really that big a drawback).
You'd need the postmaster to create the pipe and then re-point its own
stdout and stderr at it, but that's doable on Unixen at least (I'm less
sure about Windows).

If the file names are timestamp-driven in any sane fashion then it's
easy enough to tell which is newest, so I don't think there is really a
need for shared memory communication between the log capture program and
the backends that want to grab some of the data. Just legislate that
the naming convention must generate names that sort ASCII-wise into
time order.

In this scenario the log capture process has robustness requirements
similar to the postmaster --- you really DO NOT want it to die, ever.
So the KISS principle applies. That means keep it away from shared
memory and try to minimize the number of signals it has to handle.
(This might be a good reason for treating all its config variables
as PGC_POSTMASTER; then it does not need to respond to SIGHUP.)

It was also interesting to do the log rotate as a database call.

That struck me as not only useless but the deliberately hard way to do
it. To use that in the real world, you'd have to set up a cron job to
trigger the rotation, which means a lot of infrastructure and privilege;
whereas ISTM the point of this feature was to avoid both. The log
capture process should just do its own rotation on a pre-configured
time-interval basis, and/or maximum-file-size basis. I see zero value
added in having it respond to external signals.

I would like to have something like this in 7.5, but it's got to be
designed right. The patch as structured just feels all wrong to me...

The only idea I have is for the postmaster to close its stderror the
create a pipe to roatelogs and someone send all messages into there, and
pass the file name from postgresql.conf to that rotatelogs program.

Right, pretty much the same thing I'm thinking.

regards, tom lane

Now that I understand Andreas's patch, and the way he is using shared
memory to store only the timestamp, and how he checks shared memory on
every elog call, I no longer see problems with his method.

---------------------------------------------------------------------------

Tom Lane wrote:

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I saw Andreas demonstrating the viewing of server log files from pgadmin
at Germany Linuxtag, and it certainly was impressive. However, for
heavy, general usage, I don't think this patch is going to work.

That's my gut feeling as well.

Probably the big thing this program was trying to solve was for the
server to know the output file name, even with log file rotation, and I
don't see a pipe and 'rotatelogs' process really addressing this.

It could be done. Given the infrastructure we have now, it's possible
to imagine the log capture process being a child of the postmaster that
can respond to GUC SIGHUPs (or forget that and just freeze the file name
pattern at PGC_POSTMASTER time, which isn't really that big a drawback).
You'd need the postmaster to create the pipe and then re-point its own
stdout and stderr at it, but that's doable on Unixen at least (I'm less
sure about Windows).

If the file names are timestamp-driven in any sane fashion then it's
easy enough to tell which is newest, so I don't think there is really a
need for shared memory communication between the log capture program and
the backends that want to grab some of the data. Just legislate that
the naming convention must generate names that sort ASCII-wise into
time order.

In this scenario the log capture process has robustness requirements
similar to the postmaster --- you really DO NOT want it to die, ever.
So the KISS principle applies. That means keep it away from shared
memory and try to minimize the number of signals it has to handle.
(This might be a good reason for treating all its config variables
as PGC_POSTMASTER; then it does not need to respond to SIGHUP.)

It was also interesting to do the log rotate as a database call.

That struck me as not only useless but the deliberately hard way to do
it. To use that in the real world, you'd have to set up a cron job to
trigger the rotation, which means a lot of infrastructure and privilege;
whereas ISTM the point of this feature was to avoid both. The log
capture process should just do its own rotation on a pre-configured
time-interval basis, and/or maximum-file-size basis. I see zero value
added in having it respond to external signals.

I would like to have something like this in 7.5, but it's got to be
designed right. The patch as structured just feels all wrong to me...

The only idea I have is for the postmaster to close its stderror the
create a pipe to roatelogs and someone send all messages into there, and
pass the file name from postgresql.conf to that rotatelogs program.

Right, pretty much the same thing I'm thinking.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman@candle.pha.pa.us> writes:

Now that I understand Andreas's patch, and the way he is using shared
memory to store only the timestamp, and how he checks shared memory on
every elog call, I no longer see problems with his method.

The fundamentally unfixable problem with his method is that it can only
capture elog output, not stderr output from libraries that we don't
control (the dynamic linker being the biggest case, but there are
others).

I do not have any faith in the method as regards to switchover
reliability or message synchronization, either. I'm prepared to
grant that those might be only minor problems ... but I don't really see
why we should put up with doubts in this area. When you want to look at
a server log, it's because you are trying to debug a problem. The very
last thing you need is any niggling doubts about whether what you are
reading is the truth.

Finally, I simply do not trust *any* dependency on shared memory in this
connection. Again, I'm sure it works great in the normal case, but the
normal case is not what you need a server log for.

regards, tom lane

Probably the big thing this program was trying to solve was for the
server to know the output file name, even with log file

rotation, and

I don't see a pipe and 'rotatelogs' process really addressing this.

It could be done. Given the infrastructure we have now, it's
possible to imagine the log capture process being a child of
the postmaster that can respond to GUC SIGHUPs (or forget
that and just freeze the file name pattern at PGC_POSTMASTER
time, which isn't really that big a drawback).
You'd need the postmaster to create the pipe and then
re-point its own stdout and stderr at it, but that's doable
on Unixen at least (I'm less sure about Windows).

Given the issues we've had with stdout/stderr on mingw, I'm not
convinced it will work there. But I'm not convinced it won't work either
:-) What would be the portable way to do it on *nix - I could always run
some tests on w32. Just "stderr = mynewpipe;" is a bit too simplistic,
right?

The other option would be to go with a syslog-style implementation,
which you write explicitly to over a socket. But that won't address your
concern below (from other mail).

The fundamentally unfixable problem with his method is that
it can only capture elog output, not stderr output from
libraries that we don't control (the dynamic linker being the
biggest case, but there are others).

How common are these issues really? Just getting to the normal backend
output would probably be a big win in most sitations, wouldn't it? In
the case these libraries put out information, we get an elog() call *as
well*, don't we? Then you could easily redirect stderr somewhere on the
server, while still processing "ordinary elog output" through the log
manager.

//Magnus

"Magnus Hagander" <mha@sollentuna.net> writes:

You'd need the postmaster to create the pipe and then
re-point its own stdout and stderr at it, but that's doable
on Unixen at least (I'm less sure about Windows).

Given the issues we've had with stdout/stderr on mingw, I'm not
convinced it will work there. But I'm not convinced it won't work either
:-) What would be the portable way to do it on *nix - I could always run
some tests on w32. Just "stderr = mynewpipe;" is a bit too simplistic,
right?

Given that you have a pipe, I'd do something like

fclose(stderr);
stderr = fdopen(dup(p[0]), "a");

or possibly just

close(2);
d = dup(p[0]);
Assert(d == 2);

which would substitute the pipe into descriptor 2 without touching the
state of the user-level stderr file. This has the advantage that you
don't have to assume you can assign to the stderr macro. (If you do do
it the first way, you'd probably need an additional call to force the
buffering mode back to linebuffered or unbuffered.)

I don't have a problem with #ifdef'ing this part if something slightly
different is needed on Windows, though.

The fundamentally unfixable problem with his method is that
it can only capture elog output, not stderr output from
libraries that we don't control (the dynamic linker being the
biggest case, but there are others).

How common are these issues really?

Exceedingly. I've lost count of the number of times we've needed to
look at the stderr output of someone's dynamic linker because we had
no other way to debug a problem with loading a shared library. I'm
really not going to accept a "logging" solution that can't handle it.
(And yes, this is one of the big complaints against our syslog
implementation.)

regards, tom lane

I wrote:

close(2);
d = dup(p[0]);
Assert(d == 2);

Having re-read the pipe(2) man page, of course that should be
d = dup(p[1]);
since it's the writing end of the pipe you want to plug stderr into.

BTW, if it wasn't clear: I'd do the same pushup for stdout too,
just in case. I'm not sure there is any output to stdout left in the
backend, but I wouldn't swear there is not, either.

regards, tom lane

We could make the same adjustments when opening a new log file rather
than pipe, no?

---------------------------------------------------------------------------

Tom Lane wrote:

I wrote:

close(2);
d = dup(p[0]);
Assert(d == 2);

Having re-read the pipe(2) man page, of course that should be
d = dup(p[1]);
since it's the writing end of the pipe you want to plug stderr into.

BTW, if it wasn't clear: I'd do the same pushup for stdout too,
just in case. I'm not sure there is any output to stdout left in the
backend, but I wouldn't swear there is not, either.

regards, tom lane

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Tom Lane wrote:

That struck me as not only useless but the deliberately hard way to do
it. To use that in the real world, you'd have to set up a cron job to
trigger the rotation,

Still on my radar...

which means a lot of infrastructure and privilege;

whereas ISTM the point of this feature was to avoid both.

... I was thinking about putting this into the pg_autovacuum process.

The log

capture process should just do its own rotation on a pre-configured
time-interval basis, and/or maximum-file-size basis.

Yup.

I see zero value

added in having it respond to external signals.

I see >0 value. I like to truncate my logfile before doing some
complicated stuff, to have a handy file for debugging purposes.

Regards,
Andreas

Bruce Momjian wrote:

Also there are no documenttion changes.

Here are the missing docs, freshly created against cvs.

Regards,
Andreas

OK, I talked to Tom about this patch and I understand the issues now.

I think the best solution will be to have the postmaster start a child
process that can read the guc variables and create a log file based on
it contents. The child would be responsible to create a new log file
every X seconds as specified in the postgresql.conf file.

Backends wishing to read the log file would call a function to list the
contents of a directory. We can do this by creating a generic backend
super-user-only function that can list the contents of any directory.
Then you would use an API to read a specific file, similar to the log
reading functions you already have. In fact, you could set up the API
so reading a directory would return a list of directory names so you
don't need a separate directory listing function. (Does your API return
file contents as one big text string or as lines. If you return it as
one big text string, the directory idea will not work and you will need
a separate function.)

So, we have:

o use pipe and dup to copy stdout and stderr to your
postmaster child
o new guc variables to specify log destination and rotation times
o a server-side function to force a log rotate
o API to list a directory and show file contents

With this functionality, you can have clients listing the log directory
and choosing the most recent log file or previous ones. You could even
configure it to remove old log files.

Both Tom and I believe this is a more generic and reliable solution.

---------------------------------------------------------------------------

Andreas Pflug wrote:

Bruce Momjian wrote:

Also there are no documenttion changes.

Here are the missing docs, freshly created against cvs.

Regards,
Andreas

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073