logging enhancements, minor code cleanup

On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:

The attached patch does 3 things:

. logs connection ends if log_connections = true

Should this be a separate GUC variable? Personally, I'd rather not have
my log files bloated with info on both the beginning *and* the end of
each connection.

. provides a new option "log_line_format" which allows addition of extra
information on a log line before the keyword.

This patch should also update the documentation.

Some minor stylistic comments follow...

Index: backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.357
diff -c -w -r1.357 postgres.c
*** backend/tcop/postgres.c	6 Aug 2003 17:46:45 -0000	1.357
--- backend/tcop/postgres.c	9 Aug 2003 21:17:13 -0000
+ 	gettimeofday(&end,NULL);
+ 	if (end.tv_usec < port->session_start.tv_usec)
+ 	{
+ 		end.tv_sec--;
+ 		end.tv_usec += 1000000;
+ 	}
+ 	end.tv_sec -= port->session_start.tv_sec;

Can you add an assertion that end.tv_sec >= port->session_start.tv_sec before
this line, please?

Index: backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.119
diff -c -w -r1.119 elog.c
*** backend/utils/error/elog.c	8 Aug 2003 21:42:11 -0000	1.119
--- backend/utils/error/elog.c	9 Aug 2003 21:17:14 -0000
***************
*** 1019,1024 ****
--- 1021,1089 ----
}
#endif   /* HAVE_SYSLOG */

+ /*
+  * Formatted extra info for log if option is set and we have a data,
+  * or empty string otherwise.
+  */

This comment is a little awkward: "we have a data"?

+ static const char * 
+ log_line_extra(void)
+ {
+ 	/* space for option string + 2 identifiers */
+ 	/* Note: if more identifers are built in this will have to increase */

"Identifier" is incorrectly spelled.

+ static char *result = NULL;

Why is this static? IMHO it would be much cleaner to just return a palloc'ed
string.

+ 	int flen = strlen(Log_line_format_str);
+ 	int i,j;
+ 	int tlen = 2*NAMEDATALEN + flen +3 ;

Can we choose some more helpful variable names than "flen" and
"tlen", please? Also, you can move the declaration of i & j to
the scope of the if statement.

+ 	{
+ 		char * dbname = MyProcPort->database_name;
+ 		char * username = MyProcPort->user_name;
+ 		if (dbname == NULL)
+ 			dbname="";
+ 		if (username == NULL)
+ 			username = "";

Could either of these ever be NULL?

diff -c -w -r1.87 postgresql.conf.sample
*** backend/utils/misc/postgresql.conf.sample	29 Jul 2003 00:03:18 -0000	1.87
--- backend/utils/misc/postgresql.conf.sample	9 Aug 2003 21:17:15 -0000
***************
*** 173,178 ****
--- 173,179 ----
#log_connections = false
#log_duration = false
#log_pid = false
+ #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%

Shouldn't the commented-out line have the default value? (which is "", right?)

-Neil

Thanks. Responses interspersed below.

cheers

andrew

Neil Conway wrote:

On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:

The attached patch does 3 things:

. logs connection ends if log_connections = true

Should this be a separate GUC variable? Personally, I'd rather not have
my log files bloated with info on both the beginning *and* the end of
each connection.

Sure. Very easy. Nobody suggested it when I floated the idea of logging
session end on the hackers list, but it's a simple change. How does
'log_session_end' sound? Or else we could make log_connections have
levels - 0 = none, 1 = start, 2 = start + end. What's the concensus?

. provides a new option "log_line_format" which allows addition of extra
information on a log line before the keyword.

This patch should also update the documentation.

I'll submit a doc patch when the code is accepted. That's what I did
with the pg_hba.conf CIDR stuff and nobody objected. I think this is a
good way to operate, since I might make changes (for example, as a
result of your response), and would rather do the docs once.

Some minor stylistic comments follow...

Index: backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.357
diff -c -w -r1.357 postgres.c
*** backend/tcop/postgres.c	6 Aug 2003 17:46:45 -0000	1.357
--- backend/tcop/postgres.c	9 Aug 2003 21:17:13 -0000
+ 	gettimeofday(&end,NULL);
+ 	if (end.tv_usec < port->session_start.tv_usec)
+ 	{
+ 		end.tv_sec--;
+ 		end.tv_usec += 1000000;
+ 	}
+ 	end.tv_sec -= port->session_start.tv_sec;

Can you add an assertion that end.tv_sec >= port->session_start.tv_sec before
this line, please?

Sure. Presumably to catch the situation where the machine's time is
changed (backwards) during the session - an event with fairly low
probability.

Index: backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.119
diff -c -w -r1.119 elog.c
*** backend/utils/error/elog.c	8 Aug 2003 21:42:11 -0000	1.119
--- backend/utils/error/elog.c	9 Aug 2003 21:17:14 -0000
***************
*** 1019,1024 ****
--- 1021,1089 ----
}
#endif   /* HAVE_SYSLOG */

+ /*
+  * Formatted extra info for log if option is set and we have a data,
+  * or empty string otherwise.
+  */

This comment is a little awkward: "we have a data"?

Typo. will fix.

+ static const char * 
+ log_line_extra(void)
+ {
+ 	/* space for option string + 2 identifiers */
+ 	/* Note: if more identifers are built in this will have to increase */

"Identifier" is incorrectly spelled.

Typo again. will fix.

+ static char *result = NULL;

Why is this static? IMHO it would be much cleaner to just return a palloc'ed
string.

print_timestamp() and print_pid() in the same file use static buffers
which they return, so I just copied the style more or less, making
allowance for the fact I don't know the reasonable size at compile time.
It doesn't seem very efficient to palloc the string over and over
instead of once per backend. Wouldn't I then have to pfree it at a
remote spot in the code so as not to have a memory leak? That strikes me
as much more error prone.

+ 	int flen = strlen(Log_line_format_str);
+ 	int i,j;
+ 	int tlen = 2*NAMEDATALEN + flen +3 ;

Can we choose some more helpful variable names than "flen" and
"tlen", please? Also, you can move the declaration of i & j to
the scope of the if statement.

Sure. Will do.

+ 	{
+ 		char * dbname = MyProcPort->database_name;
+ 		char * username = MyProcPort->user_name;
+ 		if (dbname == NULL)
+ 			dbname="";
+ 		if (username == NULL)
+ 			username = "";

Could either of these ever be NULL?

I don't know. Maybe not. This was by way of defensive programming.

diff -c -w -r1.87 postgresql.conf.sample
*** backend/utils/misc/postgresql.conf.sample	29 Jul 2003 00:03:18 -0000	1.87
--- backend/utils/misc/postgresql.conf.sample	9 Aug 2003 21:17:15 -0000
***************
*** 173,178 ****
--- 173,179 ----
#log_connections = false
#log_duration = false
#log_pid = false
+ #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%

Shouldn't the commented-out line have the default value? (which is "", right?)

Yes, default is "". I'll move the example to the comment, if you like.

On Sun, Aug 10, 2003 at 06:19:05PM -0400, Andrew Dunstan wrote:

Neil Conway wrote:

On Sat, Aug 09, 2003 at 07:22:56PM -0400, Andrew Dunstan wrote:

Sure. Very easy. Nobody suggested it when I floated the idea of logging
session end on the hackers list, but it's a simple change. How does
'log_session_end' sound? Or else we could make log_connections have
levels - 0 = none, 1 = start, 2 = start + end. What's the concensus?

Either one works for me.

This patch should also update the documentation.

I'll submit a doc patch when the code is accepted.

Fine with me -- at one point, I believe there was a policy that the docs
needed to be updated before a patch was committed (to avoid people
intending to update the docs but never remembering too), but I'm not
sure how strictely we're following that.

Can you add an assertion that end.tv_sec >= port->session_start.tv_sec
before
this line, please?

Sure. Presumably to catch the situation where the machine's time is
changed (backwards) during the session - an event with fairly low
probability.

No -- an assertion should test a condition that always yields true, unless
some critical assumption about the state of the world has been violated
(i.e. something has gone wrong). Your point about changing the time is
a good one, although I agree the probability of it actually occurring
is very small. It's your call: if you want to worry about that case,
add actual code (not an assertion) to handle it.

print_timestamp() and print_pid() in the same file use static buffers
which they return, so I just copied the style more or less, making
allowance for the fact I don't know the reasonable size at compile time.

Fair enough -- if the other code in that area uses the same style,
that's fine. It's worth noting that if the format string changes
between calls to the function, you may end up writing off the end of
your malloc'ed buffer -- since the GUC var can be set only after a
SIGHUP, I believe this can't happen, but IMHO it speaks to the
hokiness of using static variables unless really necessary.

Shouldn't the commented-out line have the default value? (which is "",
right?)

Yes, default is "". I'll move the example to the comment, if you like.

Please do.

-Neil

----- Original Message -----
From: "Neil Conway" <neilc@samurai.com>

Fair enough -- if the other code in that area uses the same style,
that's fine. It's worth noting that if the format string changes
between calls to the function, you may end up writing off the end of
your malloc'ed buffer -- since the GUC var can be set only after a
SIGHUP, I believe this can't happen, but IMHO it speaks to the
hokiness of using static variables unless really necessary.

Actually, the code is written to ensure it *NEVER* overflows the buffer. The
result might be truncated but never overflowed. It doesn't require a format
change - if a user has long user/dbnames and uses them more than once in the
format string that will ensure a result which but for the overflow checks
would cause overflow ('%U%D%U%D' could do it) but actually causes
truncation.

Of course, I could parse the string when setting up the buffer looking for
the number of expansions required. Instead I made the (I think reasonable)
assumption that each possible expansion would be wanted at most once.

andrew

"Andrew Dunstan" <andrew@dunslane.net> writes:

Of course, I could parse the string when setting up the buffer looking for
the number of expansions required. Instead I made the (I think reasonable)
assumption that each possible expansion would be wanted at most once.

I think that's a reasonable assumption; the question was just about
whether your code acts sanely if the assumption isn't true.

regards, tom lane

Answer = sane == 'fill buffer, don't overfill buffer' ? 'yes' : 'no';

:-)

Seriously, I will add comments when I submit the revised patch to
demonstrate the loop invariants etc. so nobody need get worried when
reading the code.

As for session end logging, I'm leaning in favor of a new
log_session_end or log_connection_end boolean, so that there is minimal
backwards compatibility impact. (Interestingly, that is actually the
only part of this stuff that is of any use to me right now).

cheers

andrew

Tom Lane wrote:

Andrew Dunstan wrote:

Answer = sane == 'fill buffer, don't overfill buffer' ? 'yes' : 'no';

:-)

Seriously, I will add comments when I submit the revised patch to
demonstrate the loop invariants etc. so nobody need get worried when
reading the code.

As for session end logging, I'm leaning in favor of a new
log_session_end or log_connection_end boolean, so that there is minimal
backwards compatibility impact. (Interestingly, that is actually the
only part of this stuff that is of any use to me right now).

Agreed. A separate boolean is more self-documenting than 0/1/2.

-- 
  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

Would you add remote hostname and source port so we then have all
connection parameters available for line output.

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

Andrew Dunstan wrote:

The attached patch does 3 things:

. logs connection ends if log_connections = true
. provides a new option "log_line_format" which allows addition of extra
information on a log line before the keyword. Currently supported are
user name and database name, but it is easily extensible. The string is
in the flavor of a printf format, where "%U" means user name, "%D" means
database name, "%%" means "%" and anything else means itself, literally.
. minor code cleanup for consistency in calling gettimeofday().

cheers

andrew

Index: backend/commands/vacuum.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/commands/vacuum.c,v
retrieving revision 1.259
diff -c -w -r1.259 vacuum.c
*** backend/commands/vacuum.c	4 Aug 2003 02:39:58 -0000	1.259
--- backend/commands/vacuum.c	9 Aug 2003 21:17:11 -0000
***************
*** 3109,3118 ****
void
vac_init_rusage(VacRUsage *ru0)
{
- 	struct timezone tz;
- 
getrusage(RUSAGE_SELF, &ru0->ru);
! 	gettimeofday(&ru0->tv, &tz);
}

/*
--- 3109,3116 ----
void
vac_init_rusage(VacRUsage *ru0)
{
getrusage(RUSAGE_SELF, &ru0->ru);
! 	gettimeofday(&ru0->tv, NULL);
}

/*
Index: backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.340
diff -c -w -r1.340 postmaster.c
*** backend/postmaster/postmaster.c	4 Aug 2003 02:40:02 -0000	1.340
--- backend/postmaster/postmaster.c	9 Aug 2003 21:17:13 -0000
***************
*** 995,1004 ****
int			nSockets;
struct timeval now,
later;
- 	struct timezone tz;
int			i;

! gettimeofday(&now, &tz);

nSockets = initMasks(&readmask);

--- 995,1003 ----
int			nSockets;
struct timeval now,
later;
int			i;

! gettimeofday(&now, NULL);

nSockets = initMasks(&readmask);

***************
*** 1080,1086 ****
*/
while (random_seed == 0)
{
! gettimeofday(&later, &tz);

/*
* We are not sure how much precision is in tv_usec, so we
--- 1079,1085 ----
*/
while (random_seed == 0)
{
! 			gettimeofday(&later, NULL);

/*
* We are not sure how much precision is in tv_usec, so we
***************
*** 2302,2308 ****
int i;
int status;
struct timeval now;
- struct timezone tz;
char remote_host[NI_MAXHOST];
char remote_port[NI_MAXSERV];

--- 2301,2306 ----
***************
*** 2324,2332 ****
/* Close the postmaster's other sockets */
ClosePostmasterPorts(true);

- /* Save port etc. for ps status */
- MyProcPort = port;
-
/* Reset MyProcPid to new backend's pid */
MyProcPid = getpid();

--- 2322,2327 ----
***************
*** 2398,2403 ****
--- 2393,2405 ----
elog(FATAL, "could not set timer for authorization timeout");

/*
+ 	 * Save port etc. for ps status 
+ 	 * do this after we log connections or auth failures so that we don't use
+ 	 * the format line before the details are filled in 
+ 	 */
+ 	MyProcPort = port;
+ 
+ 	/*
* Receive the startup packet (which might turn out to be a cancel
* request packet).
*/
***************
*** 2438,2444 ****
* start a new random sequence in the random() library function.
*/
random_seed = 0;
! 	gettimeofday(&now, &tz);
srandom((unsigned int) now.tv_usec);

/* ----------------
--- 2440,2446 ----
* start a new random sequence in the random() library function.
*/
random_seed = 0;
! 	gettimeofday(&now, NULL);
srandom((unsigned int) now.tv_usec);

/* ----------------
***************
*** 2521,2526 ****
--- 2523,2536 ----
MemoryContextSwitchTo(TopMemoryContext);
MemoryContextDelete(PostmasterContext);
PostmasterContext = NULL;
+ 
+ 	/*
+ 	 * set up remaining members of port stucture while in the
+ 	 * TopMemoryContext
+ 	 */
+ 	port->remote_host = pstrdup(remote_host);
+ 	port->remote_port = pstrdup(remote_port);
+ 	gettimeofday(&(port->session_start),NULL);

/*
* Debug: print arguments being passed to backend
Index: backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.357
diff -c -w -r1.357 postgres.c
*** backend/tcop/postgres.c	6 Aug 2003 17:46:45 -0000	1.357
--- backend/tcop/postgres.c	9 Aug 2003 21:17:13 -0000
***************
*** 68,73 ****
--- 68,74 ----
extern int	optind;
extern char *optarg;

+ extern bool Log_connections;

/* ----------------
*		global variables
***************
*** 150,155 ****
--- 151,157 ----
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);

/* ----------------------------------------------------------------
***************
*** 2453,2458 ****
--- 2455,2465 ----
gucopts = lnext(gucopts);
SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
}
+ 	   /*
+ 		* set up handler to log session end.
+ 		*/
+ 		if (IsUnderPostmaster && Log_connections)
+ 			on_proc_exit(log_session_end,0);
}

/*
***************
*** 3190,3193 ****
--- 3197,3243 ----
errdetail("%s", str.data)));

pfree(str.data);
+ }
+ 
+ 
+ /*
+  * on_proc_exit handler to log end of session
+  */
+ static void 
+ log_session_end(void)
+ {
+ 	Port * port = MyProcPort;
+ 	struct timeval end;
+ 	int  hours, minutes, seconds;
+ 
+ 	char session_time[20];
+ 	char uname[6+NAMEDATALEN];
+ 	char dbname[10+NAMEDATALEN];
+ 	
+ 	snprintf(uname, sizeof(uname)," user=%s",port->user_name);
+ 	snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
+ 
+ 
+ 	gettimeofday(&end,NULL);
+ 	if (end.tv_usec < port->session_start.tv_usec)
+ 	{
+ 		end.tv_sec--;
+ 		end.tv_usec += 1000000;
+ 	}
+ 	end.tv_sec -= port->session_start.tv_sec;
+ 	end.tv_usec -= port->session_start.tv_usec;
+ 
+ 	hours = end.tv_sec / 3600;
+ 	end.tv_sec %= 3600;
+ 	minutes = end.tv_sec / 60;
+ 	seconds = end.tv_sec % 60;
+ 
+ 	snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
+ 			 hours, minutes, seconds, 
+ 			 end.tv_usec/10000);
+ 	
+ 	ereport(LOG,
+ 			(errmsg("session ended: duration: %s%s%s",
+ 					session_time,uname,dbname)));
+ 
}
Index: backend/utils/adt/nabstime.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/adt/nabstime.c,v
retrieving revision 1.113
diff -c -w -r1.113 nabstime.c
*** backend/utils/adt/nabstime.c	4 Aug 2003 02:40:05 -0000	1.113
--- backend/utils/adt/nabstime.c	9 Aug 2003 21:17:13 -0000
***************
*** 1745,1757 ****
timeofday(PG_FUNCTION_ARGS)
{
struct timeval tp;
- 	struct timezone tpz;
char		templ[100];
char		buf[100];
text	   *result;
int			len;

! 	gettimeofday(&tp, &tpz);
strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
localtime((time_t *) &tp.tv_sec));
snprintf(buf, sizeof(buf), templ, tp.tv_usec);
--- 1745,1756 ----
timeofday(PG_FUNCTION_ARGS)
{
struct timeval tp;
char		templ[100];
char		buf[100];
text	   *result;
int			len;

! 	gettimeofday(&tp, NULL);
strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
localtime((time_t *) &tp.tv_sec));
snprintf(buf, sizeof(buf), templ, tp.tv_usec);
Index: backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.119
diff -c -w -r1.119 elog.c
*** backend/utils/error/elog.c	8 Aug 2003 21:42:11 -0000	1.119
--- backend/utils/error/elog.c	9 Aug 2003 21:17:14 -0000
***************
*** 72,77 ****
--- 72,78 ----
bool		Log_timestamp = false;		/* show timestamps in stderr
* output */
bool		Log_pid = false;	/* show PIDs in stderr output */
+ char        *Log_line_format_str = ""; /* format for extra log line info */

#ifdef HAVE_SYSLOG
/*
***************
*** 145,150 ****
--- 146,152 ----
static const char *error_severity(int elevel);
static const char *print_timestamp(void);
static const char *print_pid(void);
+ static const char *log_line_extra(void);

/*
***************
*** 1019,1024 ****
--- 1021,1089 ----
}
#endif   /* HAVE_SYSLOG */

+ /*
+  * Formatted extra info for log if option is set and we have a data,
+  * or empty string otherwise.
+  */
+ static const char * 
+ log_line_extra(void)
+ {
+ 	/* space for option string + 2 identifiers */
+ 	/* Note: if more identifers are built in this will have to increase */
+ 	static char *result = NULL;
+ 	int flen = strlen(Log_line_format_str);
+ 	int i,j;
+ 	int tlen = 2*NAMEDATALEN + flen +3 ;
+ 	if (result == NULL)
+ 		result = malloc(tlen);
+ 	result[0] = '\0';
+ 	
+ 	if (flen > 0 && MyProcPort)
+ 	{
+ 		char * dbname = MyProcPort->database_name;
+ 		char * username = MyProcPort->user_name;
+ 		if (dbname == NULL)
+ 			dbname="";
+ 		if (username == NULL)
+ 			username = "";
+ 		j = 0;
+ 		for (i = 0; i < flen && j < tlen-1; i++)
+ 		{
+ 			if(Log_line_format_str[i] != '%')
+ 			{
+ 				result[j]=Log_line_format_str[i];
+ 				j++;
+ 				result[j] = '\0';
+ 				continue;
+ 			}
+ 			else if (i == flen - 1)
+ 			{
+ 				/* format error - just skip it */
+ 				continue;
+ 			}
+ 			i++;
+ 			switch (Log_line_format_str[i])
+ 			{
+ 				case 'U': 
+ 					j += snprintf(result+j,tlen-j,"%s",username);
+ 					break;
+ 				case 'D': 
+ 					j += snprintf(result+j,tlen-j,"%s",dbname);
+ 					break;
+ 				case '%': 
+ 					result[j] = '%';
+ 					j++;
+ 					result[j] = '\0';
+ 					break;
+ 				default:
+ 					/* format error - skip it */
+ 					break;
+ 			}
+ 		}
+ 	}
+ 	return result;
+ }
+ 

/*
* Write error report to server's log
***************
*** 1028,1036 ****
{
StringInfoData buf;

initStringInfo(&buf);

! appendStringInfo(&buf, "%s: ", error_severity(edata->elevel));

if (Log_error_verbosity >= PGERROR_VERBOSE)
{
--- 1093,1105 ----
{
StringInfoData buf;

+ 	const char *extra_info = log_line_extra();
+ 
initStringInfo(&buf);

! appendStringInfo(&buf, "%s%s: ",
! extra_info,
! error_severity(edata->elevel));

if (Log_error_verbosity >= PGERROR_VERBOSE)
{
***************
*** 1062,1080 ****
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
if (edata->detail)
! 			appendStringInfo(&buf, gettext("DETAIL:  %s\n"), edata->detail);
if (edata->hint)
! 			appendStringInfo(&buf, gettext("HINT:  %s\n"), edata->hint);
if (edata->context)
! 			appendStringInfo(&buf, gettext("CONTEXT:  %s\n"), edata->context);
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
if (edata->funcname && edata->filename)
! 				appendStringInfo(&buf, gettext("LOCATION:  %s, %s:%d\n"),
edata->funcname, edata->filename,
edata->lineno);
else if (edata->filename)
! 				appendStringInfo(&buf, gettext("LOCATION:  %s:%d\n"),
edata->filename, edata->lineno);
}
}
--- 1131,1157 ----
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
if (edata->detail)
! 			appendStringInfo(&buf, gettext("%sDETAIL:  %s\n"), 
! 							 extra_info,
! 							 edata->detail);
if (edata->hint)
! 			appendStringInfo(&buf, gettext("%sHINT:  %s\n"), 
! 							 extra_info,
! 							 edata->hint);
if (edata->context)
! 			appendStringInfo(&buf, gettext("%sCONTEXT:  %s\n"), 
! 							 extra_info,
! 							 edata->context);
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
if (edata->funcname && edata->filename)
! 				appendStringInfo(&buf, gettext("%sLOCATION:  %s, %s:%d\n"),
! 								 extra_info,
edata->funcname, edata->filename,
edata->lineno);
else if (edata->filename)
! 				appendStringInfo(&buf, gettext("%sLOCATION:  %s:%d\n"),
! 								 extra_info,
edata->filename, edata->lineno);
}
}
***************
*** 1086,1092 ****
* improve?
*/
if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
! 		appendStringInfo(&buf, gettext("STATEMENT:  %s\n"),
debug_query_string);

--- 1163,1170 ----
* improve?
*/
if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
! 		appendStringInfo(&buf, gettext("%sSTATEMENT:  %s\n"),
! 						 extra_info,
debug_query_string);

Index: backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.148
diff -c -w -r1.148 guc.c
*** backend/utils/misc/guc.c	4 Aug 2003 23:59:39 -0000	1.148
--- backend/utils/misc/guc.c	9 Aug 2003 21:17:15 -0000
***************
*** 1334,1339 ****
--- 1334,1348 ----
},
&log_min_error_statement_str,
"panic", assign_min_error_statement, NULL
+ 	},
+ 
+ 	{
+ 		{"log_line_format", PGC_SIGHUP, LOGGING_WHAT,
+ 			gettext_noop("Controls extra information on each log line"),
+ 			gettext_noop("if blank no extra info is logged")
+ 		},
+ 		&Log_line_format_str,
+ 		"", NULL, NULL
},

{
Index: backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.87
diff -c -w -r1.87 postgresql.conf.sample
*** backend/utils/misc/postgresql.conf.sample	29 Jul 2003 00:03:18 -0000	1.87
--- backend/utils/misc/postgresql.conf.sample	9 Aug 2003 21:17:15 -0000
***************
*** 173,178 ****
--- 173,179 ----
#log_connections = false
#log_duration = false
#log_pid = false
+ #log_line_format = '<%U~%D>'     # %U=username %D=databasename %%=%
#log_statement = false
#log_timestamp = false
#log_hostname = false
Index: include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.37
diff -c -w -r1.37 libpq-be.h
*** include/libpq/libpq-be.h	4 Aug 2003 02:40:13 -0000	1.37
--- include/libpq/libpq-be.h	9 Aug 2003 21:17:15 -0000
***************
*** 42,47 ****
--- 42,50 ----
ProtocolVersion proto;		/* FE/BE protocol version */
SockAddr	laddr;			/* local addr (postmaster) */
SockAddr	raddr;			/* remote addr (client) */
+ 	char 		*remote_host;	/* name (or ip addr) of remote host */
+ 	char		*remote_port;	/* text rep of remote port */
+ 	struct timeval	session_start;	/* for session duration logging */

/*
* Information that needs to be saved from the startup packet and
Index: include/utils/elog.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/utils/elog.h,v
retrieving revision 1.63
diff -c -w -r1.63 elog.h
*** include/utils/elog.h	8 Aug 2003 21:42:55 -0000	1.63
--- include/utils/elog.h	9 Aug 2003 21:17:15 -0000
***************
*** 171,176 ****
--- 171,177 ----
extern PGErrorVerbosity Log_error_verbosity;
extern bool Log_timestamp;
extern bool Log_pid;
+ extern char *Log_line_format_str;

#ifdef HAVE_SYSLOG
extern int Use_syslog;

---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to majordomo@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

Good catch - I meant to do that.

cheers

andrew

Bruce Momjian wrote:

revised patch attached, including docco. I think this attends to all the
comments I received.

cheers

andrew

This has been saved for the 7.5 release:

http:/momjian.postgresql.org/cgi-bin/pgpatches2

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

Andrew Dunstan wrote:

revised patch attached, including docco. I think this attends to all the
comments I received.

cheers

andrew

Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.199
diff -c -w -r1.199 runtime.sgml
*** doc/src/sgml/runtime.sgml	10 Aug 2003 01:20:34 -0000	1.199
--- doc/src/sgml/runtime.sgml	13 Aug 2003 20:59:13 -0000
***************
*** 1801,1806 ****
--- 1801,1820 ----

<varlistentry>
+       <term><varname>LOG_SESSION_END</varname> (<type>boolean</type>)</term>
+       <listitem>
+        <para>
+ 	 This outputs a line to the server logs similar to LOG_CONNECTIONS 
+ 	 but at the end of a session, and including the duration of the 
+ 	 session.This is off by default. This option can only be set at 
+ 	 server start or in the <filename>postgresql.conf</filename> 
+ 	 configuration file.
+        </para>
+       </listitem>
+      </varlistentry>
+ 
+ 
+      <varlistentry>
<term><varname>LOG_DURATION</varname> (<type>boolean</type>)</term>
<listitem>
<para>
***************
*** 1825,1830 ****
--- 1839,1876 ----
the process ID.
</para>
</listitem>
+      </varlistentry>
+ 
+      <varlistentry>
+       <term><varname>LOG_LINE_FORMAT</varname> (<type>string</type>)</term>
+       <listitem>
+        <para>
+ 	 Prefixes each message in the server log file or syslog with extra 
+ 	 information as specidied in the string. The default is an empty 
+ 	 string. The following sequences in the string are translated: 
+ 	 <literal>'%U'</literal> is replace with the username, 
+ 	 <literal>'%D'</literal> is replaced by the database name, 
+ 	 and <literal>'%%'</literal> is replaced by <literal>'%'</literal>. 
+ 	 All other characters are copied literally to the log. For example,
+ <programlisting>
+ log_line_format = '&lt;%U%%%D&gt; '
+ </programlisting>
+ 	 will produce output like this:
+ <programlisting>
+ &lt;myuser%mydb&gt; LOG:  query: create table foo(blah text);
+ </programlisting>
+ 	 </para>
+ 	<para>
+ 	 If <varname>LOG_PID</varname> or <varname>LOG_TIMESTAMP</varname> 
+ 	 are turned on the output from <varname>LOG_LINE_FORMAT</varname>
+ 	 will follow those items but precede any other output on the line.
+ 	</para>
+ 	<para>
+ 	 This option can only be set at server start or in the
+         <filename>postgresql.conf</filename> configuration file.
+ 	</para>
+ 	  
+        </listitem>
</varlistentry>

<varlistentry>
Index: src/backend/commands/vacuum.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/commands/vacuum.c,v
retrieving revision 1.259
diff -c -w -r1.259 vacuum.c
*** src/backend/commands/vacuum.c	4 Aug 2003 02:39:58 -0000	1.259
--- src/backend/commands/vacuum.c	13 Aug 2003 20:59:14 -0000
***************
*** 3109,3118 ****
void
vac_init_rusage(VacRUsage *ru0)
{
- 	struct timezone tz;
- 
getrusage(RUSAGE_SELF, &ru0->ru);
! 	gettimeofday(&ru0->tv, &tz);
}

/*
--- 3109,3116 ----
void
vac_init_rusage(VacRUsage *ru0)
{
getrusage(RUSAGE_SELF, &ru0->ru);
! 	gettimeofday(&ru0->tv, NULL);
}

/*
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.341
diff -c -w -r1.341 postmaster.c
*** src/backend/postmaster/postmaster.c	12 Aug 2003 18:23:20 -0000	1.341
--- src/backend/postmaster/postmaster.c	13 Aug 2003 20:59:15 -0000
***************
*** 1000,1009 ****
int			nSockets;
struct timeval now,
later;
- 	struct timezone tz;
int			i;

! gettimeofday(&now, &tz);

nSockets = initMasks(&readmask);

--- 1000,1008 ----
int			nSockets;
struct timeval now,
later;
int			i;

! gettimeofday(&now, NULL);

nSockets = initMasks(&readmask);

***************
*** 1085,1091 ****
*/
while (random_seed == 0)
{
! gettimeofday(&later, &tz);

/*
* We are not sure how much precision is in tv_usec, so we
--- 1084,1090 ----
*/
while (random_seed == 0)
{
! 			gettimeofday(&later, NULL);

/*
* We are not sure how much precision is in tv_usec, so we
***************
*** 2320,2326 ****
int i;
int status;
struct timeval now;
- struct timezone tz;
char remote_host[NI_MAXHOST];
char remote_port[NI_MAXSERV];

--- 2319,2324 ----
***************
*** 2342,2350 ****
/* Close the postmaster's other sockets */
ClosePostmasterPorts(true);

- /* Save port etc. for ps status */
- MyProcPort = port;
-
/* Reset MyProcPid to new backend's pid */
MyProcPid = getpid();

--- 2340,2345 ----
***************
*** 2416,2421 ****
--- 2411,2423 ----
elog(FATAL, "could not set timer for authorization timeout");

/*
+ 	 * Save port etc. for ps status 
+ 	 * do this after we log connections or auth failures so that we don't use
+ 	 * the format line before the details are filled in 
+ 	 */
+ 	MyProcPort = port;
+ 
+ 	/*
* Receive the startup packet (which might turn out to be a cancel
* request packet).
*/
***************
*** 2456,2462 ****
* start a new random sequence in the random() library function.
*/
random_seed = 0;
! 	gettimeofday(&now, &tz);
srandom((unsigned int) now.tv_usec);

/* ----------------
--- 2458,2464 ----
* start a new random sequence in the random() library function.
*/
random_seed = 0;
! 	gettimeofday(&now, NULL);
srandom((unsigned int) now.tv_usec);

/* ----------------
***************
*** 2539,2544 ****
--- 2541,2554 ----
MemoryContextSwitchTo(TopMemoryContext);
MemoryContextDelete(PostmasterContext);
PostmasterContext = NULL;
+ 
+ 	/*
+ 	 * set up remaining members of port stucture while in the
+ 	 * TopMemoryContext
+ 	 */
+ 	port->remote_host = pstrdup(remote_host);
+ 	port->remote_port = pstrdup(remote_port);
+ 	gettimeofday(&(port->session_start),NULL);

/*
* Debug: print arguments being passed to backend
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.359
diff -c -w -r1.359 postgres.c
*** src/backend/tcop/postgres.c	12 Aug 2003 18:52:38 -0000	1.359
--- src/backend/tcop/postgres.c	13 Aug 2003 20:59:15 -0000
***************
*** 85,90 ****
--- 85,93 ----
bool		Warn_restart_ready = false;
bool		InError = false;

+ /* flag for logging end of session */
+ bool        Log_session_end = false;
+ 
/*
* Flags for expensive function optimization -- JMH 3/9/92
*/
***************
*** 150,155 ****
--- 153,159 ----
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);

/* ----------------------------------------------------------------
***************
*** 2426,2432 ****
--- 2430,2439 ----
* other output options.
*/
if (debug_flag >= 1)
+ 	{
SetConfigOption("log_connections", "true", debug_context, gucsource);
+ 		SetConfigOption("log_session_end", "true", debug_context, gucsource);
+ 	}
if (debug_flag >= 2)
SetConfigOption("log_statement", "true", debug_context, gucsource);
if (debug_flag >= 3)
***************
*** 2455,2460 ****
--- 2462,2472 ----
gucopts = lnext(gucopts);
SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
}
+ 	   /*
+ 		* set up handler to log session end.
+ 		*/
+ 		if (IsUnderPostmaster && Log_session_end)
+ 			on_proc_exit(log_session_end,0);
}

/*
***************
*** 3195,3198 ****
--- 3207,3269 ----
errdetail("%s", str.data)));

pfree(str.data);
+ }
+ 
+ 
+ /*
+  * on_proc_exit handler to log end of session
+  */
+ static void 
+ log_session_end(void)
+ {
+ 	Port * port = MyProcPort;
+ 	struct timeval end;
+ 	int  hours, minutes, seconds;
+ 
+ 	char session_time[20];
+ 	char uname[6+NAMEDATALEN];
+ 	char dbname[10+NAMEDATALEN];
+ 	char remote_host[7 + NI_MAXHOST];
+ 	char remote_port[7 + NI_MAXSERV];
+ 	
+ 	snprintf(uname, sizeof(uname)," user=%s",port->user_name);
+ 	snprintf(dbname, sizeof(dbname)," database=%s",port->database_name);
+ 	snprintf(remote_host,sizeof(remote_host)," host=%s",
+ 			 port->remote_host);
+ 	/* prevent redundant or empty reporting of port */
+ 	if (!LogSourcePort && strlen(port->remote_port))
+ 		snprintf(remote_port,sizeof(remote_port)," port=%s",port->remote_port);
+ 	else
+ 		remote_port[0] = '\0';
+ 
+ 
+ 	gettimeofday(&end,NULL);
+ 
+ 	if (end.tv_usec < port->session_start.tv_usec)
+ 	{
+ 		end.tv_sec--;
+ 		end.tv_usec += 1000000;
+ 	}
+ 	end.tv_sec -= port->session_start.tv_sec;
+ 	end.tv_usec -= port->session_start.tv_usec;
+ 
+ 	hours = end.tv_sec / 3600;
+ 	end.tv_sec %= 3600;
+ 	minutes = end.tv_sec / 60;
+ 	seconds = end.tv_sec % 60;
+ 
+ 	/* if time has gone backwards for some reason say so, or print time */
+ 
+ 	if (end.tv_sec < 0)
+ 		snprintf(session_time,sizeof(session_time),"negative!");
+ 	else
+ 		/* for stricter accuracy here we could round - this is close enough */
+ 		snprintf(session_time, sizeof(session_time),"%d:%02d:%02d.%02ld",
+ 			 hours, minutes, seconds, end.tv_usec/10000);
+ 	
+ 	ereport(
+ 		LOG,
+ 		(errmsg("session end: duration: %s%s%s%s%s",
+ 			session_time,uname,dbname,remote_host,remote_port)));
+ 
}
Index: src/backend/utils/adt/nabstime.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/adt/nabstime.c,v
retrieving revision 1.113
diff -c -w -r1.113 nabstime.c
*** src/backend/utils/adt/nabstime.c	4 Aug 2003 02:40:05 -0000	1.113
--- src/backend/utils/adt/nabstime.c	13 Aug 2003 20:59:16 -0000
***************
*** 1745,1757 ****
timeofday(PG_FUNCTION_ARGS)
{
struct timeval tp;
- 	struct timezone tpz;
char		templ[100];
char		buf[100];
text	   *result;
int			len;

! 	gettimeofday(&tp, &tpz);
strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
localtime((time_t *) &tp.tv_sec));
snprintf(buf, sizeof(buf), templ, tp.tv_usec);
--- 1745,1756 ----
timeofday(PG_FUNCTION_ARGS)
{
struct timeval tp;
char		templ[100];
char		buf[100];
text	   *result;
int			len;

! 	gettimeofday(&tp, NULL);
strftime(templ, sizeof(templ), "%a %b %d %H:%M:%S.%%06d %Y %Z",
localtime((time_t *) &tp.tv_sec));
snprintf(buf, sizeof(buf), templ, tp.tv_usec);
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.119
diff -c -w -r1.119 elog.c
*** src/backend/utils/error/elog.c	8 Aug 2003 21:42:11 -0000	1.119
--- src/backend/utils/error/elog.c	13 Aug 2003 20:59:16 -0000
***************
*** 72,77 ****
--- 72,78 ----
bool		Log_timestamp = false;		/* show timestamps in stderr
* output */
bool		Log_pid = false;	/* show PIDs in stderr output */
+ char        *Log_line_format_str = ""; /* format for extra log line info */

#ifdef HAVE_SYSLOG
/*
***************
*** 145,150 ****
--- 146,152 ----
static const char *error_severity(int elevel);
static const char *print_timestamp(void);
static const char *print_pid(void);
+ static const char *log_line_extra(void);

/*
***************
*** 1019,1024 ****
--- 1021,1099 ----
}
#endif   /* HAVE_SYSLOG */

+ /*
+  * Formatted extra info for log if option is set and we have data,
+  * or empty string otherwise.
+  */
+ static const char * 
+ log_line_extra(void)
+ {
+ 	/* space for option string + 2 identifiers */
+ 	/* Note: if more identifiers are built in this will have to increase */
+ 	static char *result = NULL;
+ 	int format_len = strlen(Log_line_format_str);
+ 	int result_len = 2*NAMEDATALEN + format_len +3 ;
+ 	if (result == NULL)
+ 		result = malloc(result_len);
+ 	result[0] = '\0';
+ 	
+ 	if (format_len > 0 && MyProcPort)
+ 	{
+ 		int i,j;
+ 		char * dbname = MyProcPort->database_name;
+ 		char * username = MyProcPort->user_name;
+ 		if (dbname == NULL)
+ 			dbname="";
+ 		if (username == NULL)
+ 			username = "";
+ 
+ 		/*
+ 		 * invariant through each iteration of this loop:
+ 		 *  . j is the index of the trailing null on result
+ 		 *  . result_len - j is the number of chars we have room for
+ 		 *    including the trailing null
+ 		 *  . there is room to write at least one more non-null char plus the
+ 		 *    trailing null
+ 		 */
+ 		for (i = 0, j=0; i < format_len && j < result_len-1; i++)
+ 		{
+ 			if(Log_line_format_str[i] != '%')
+ 			{
+ 				/* literal char, just copy */
+ 				result[j]=Log_line_format_str[i];
+ 				j++;
+ 				result[j] = '\0';
+ 				continue;
+ 			}
+ 			else if (i == format_len - 1)
+ 			{
+ 				/* format error - skip it */
+ 				continue;
+ 			}
+ 			/* go to char after '%', take action accordingly */
+ 			i++;
+ 			switch (Log_line_format_str[i])
+ 			{
+ 				case 'U': 
+ 					j += snprintf(result+j,result_len-j,"%s",username);
+ 					break;
+ 				case 'D': 
+ 					j += snprintf(result+j,result_len-j,"%s",dbname);
+ 					break;
+ 				case '%': 
+ 					result[j] = '%';
+ 					j++;
+ 					result[j] = '\0';
+ 					break;
+ 				default:
+ 					/* format error - skip it */
+ 					break;
+ 			}
+ 		}
+ 	}
+ 	return result;
+ }
+ 

/*
* Write error report to server's log
***************
*** 1028,1036 ****
{
StringInfoData buf;

initStringInfo(&buf);

! appendStringInfo(&buf, "%s: ", error_severity(edata->elevel));

if (Log_error_verbosity >= PGERROR_VERBOSE)
{
--- 1103,1115 ----
{
StringInfoData buf;

+ 	const char *extra_info = log_line_extra();
+ 
initStringInfo(&buf);

! appendStringInfo(&buf, "%s%s: ",
! extra_info,
! error_severity(edata->elevel));

if (Log_error_verbosity >= PGERROR_VERBOSE)
{
***************
*** 1062,1080 ****
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
if (edata->detail)
! 			appendStringInfo(&buf, gettext("DETAIL:  %s\n"), edata->detail);
if (edata->hint)
! 			appendStringInfo(&buf, gettext("HINT:  %s\n"), edata->hint);
if (edata->context)
! 			appendStringInfo(&buf, gettext("CONTEXT:  %s\n"), edata->context);
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
if (edata->funcname && edata->filename)
! 				appendStringInfo(&buf, gettext("LOCATION:  %s, %s:%d\n"),
edata->funcname, edata->filename,
edata->lineno);
else if (edata->filename)
! 				appendStringInfo(&buf, gettext("LOCATION:  %s:%d\n"),
edata->filename, edata->lineno);
}
}
--- 1141,1167 ----
if (Log_error_verbosity >= PGERROR_DEFAULT)
{
if (edata->detail)
! 			appendStringInfo(&buf, gettext("%sDETAIL:  %s\n"), 
! 							 extra_info,
! 							 edata->detail);
if (edata->hint)
! 			appendStringInfo(&buf, gettext("%sHINT:  %s\n"), 
! 							 extra_info,
! 							 edata->hint);
if (edata->context)
! 			appendStringInfo(&buf, gettext("%sCONTEXT:  %s\n"), 
! 							 extra_info,
! 							 edata->context);
if (Log_error_verbosity >= PGERROR_VERBOSE)
{
if (edata->funcname && edata->filename)
! 				appendStringInfo(&buf, gettext("%sLOCATION:  %s, %s:%d\n"),
! 								 extra_info,
edata->funcname, edata->filename,
edata->lineno);
else if (edata->filename)
! 				appendStringInfo(&buf, gettext("%sLOCATION:  %s:%d\n"),
! 								 extra_info,
edata->filename, edata->lineno);
}
}
***************
*** 1086,1092 ****
* improve?
*/
if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
! 		appendStringInfo(&buf, gettext("STATEMENT:  %s\n"),
debug_query_string);

--- 1173,1180 ----
* improve?
*/
if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
! 		appendStringInfo(&buf, gettext("%sSTATEMENT:  %s\n"),
! 						 extra_info,
debug_query_string);

Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.149
diff -c -w -r1.149 guc.c
*** src/backend/utils/misc/guc.c	11 Aug 2003 23:04:49 -0000	1.149
--- src/backend/utils/misc/guc.c	13 Aug 2003 20:59:17 -0000
***************
*** 66,71 ****
--- 66,72 ----

/* XXX these should appear in other modules' header files */
extern bool Log_connections;
+ extern bool Log_session_end;
extern int	PreAuthDelay;
extern int	AuthenticationTimeout;
extern int	CheckPointTimeout;
***************
*** 488,493 ****
--- 489,502 ----
false, NULL, NULL
},
{
+ 		{"log_session_end", PGC_BACKEND, LOGGING_WHAT,
+ 			gettext_noop("Logs end of a session, including duration"),
+ 			NULL
+ 		},
+ 		&Log_session_end,
+ 		false, NULL, NULL
+ 	},
+ 	{
{"log_timestamp", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Prefixes server log messages with a time stamp"),
NULL
***************
*** 1334,1339 ****
--- 1343,1357 ----
},
&log_min_error_statement_str,
"panic", assign_min_error_statement, NULL
+ 	},
+ 
+ 	{
+ 		{"log_line_format", PGC_SIGHUP, LOGGING_WHAT,
+ 			gettext_noop("Controls extra information on each log line"),
+ 			gettext_noop("if blank no extra info is logged")
+ 		},
+ 		&Log_line_format_str,
+ 		"", NULL, NULL
},

{
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.87
diff -c -w -r1.87 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample	29 Jul 2003 00:03:18 -0000	1.87
--- src/backend/utils/misc/postgresql.conf.sample	13 Aug 2003 20:59:17 -0000
***************
*** 171,178 ****
--- 171,180 ----
#debug_print_plan = false
#debug_pretty_print = false
#log_connections = false
+ #log_session_end = false
#log_duration = false
#log_pid = false
+ #log_line_format = ''     # e.g. '<%U%%%D> ' - %U=username %D=databasename %%=%
#log_statement = false
#log_timestamp = false
#log_hostname = false
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.37
diff -c -w -r1.37 libpq-be.h
*** src/include/libpq/libpq-be.h	4 Aug 2003 02:40:13 -0000	1.37
--- src/include/libpq/libpq-be.h	13 Aug 2003 20:59:17 -0000
***************
*** 42,47 ****
--- 42,50 ----
ProtocolVersion proto;		/* FE/BE protocol version */
SockAddr	laddr;			/* local addr (postmaster) */
SockAddr	raddr;			/* remote addr (client) */
+ 	char 		*remote_host;	/* name (or ip addr) of remote host */
+ 	char		*remote_port;	/* text rep of remote port */
+ 	struct timeval	session_start;	/* for session duration logging */

/*
* Information that needs to be saved from the startup packet and
Index: src/include/utils/elog.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/utils/elog.h,v
retrieving revision 1.63
diff -c -w -r1.63 elog.h
*** src/include/utils/elog.h	8 Aug 2003 21:42:55 -0000	1.63
--- src/include/utils/elog.h	13 Aug 2003 20:59:17 -0000
***************
*** 171,176 ****
--- 171,177 ----
extern PGErrorVerbosity Log_error_verbosity;
extern bool Log_timestamp;
extern bool Log_pid;
+ extern char *Log_line_format_str;

#ifdef HAVE_SYSLOG
extern int Use_syslog;

---------------------------(end of broadcast)---------------------------
TIP 9: the planner will ignore your desire to choose an index scan if your
joining column's datatypes do not match

-- 
  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