log session end - again

Started by Andrew Dunstanalmost 22 years ago30 messages
#1Andrew Dunstan
andrew@dunslane.net
1 attachment(s)

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by the
config setting "log_session_end - true". It produces lines like these:

for a local connection:
[21340]: LOG: session end: duration: 0:00:23.41 user=andrew database=template1 host=[local]
database=template1 host=[local]

for a tcp connection:
[21351]: LOG: session end: duration: 0:00:20.22 user=andrew database=template1 host=127.0.0.1 port=33419
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373]: LOG: session end: duration: 0:00:02.25 user=andrew database=template1 host=alphonso port=33421
database=template1 host=alphonso port=33421

enjoy

andrew

Attachments:

log_session_end.patchtext/plain; name=log_session_end.patchDownload
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.235
diff -c -r1.235 runtime.sgml
*** doc/src/sgml/runtime.sgml	27 Jan 2004 16:51:43 -0000	1.235
--- doc/src/sgml/runtime.sgml	2 Feb 2004 19:08:42 -0000
***************
*** 1825,1830 ****
--- 1825,1844 ----
  
  
       <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>
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.364
diff -c -r1.364 postmaster.c
*** src/backend/postmaster/postmaster.c	28 Jan 2004 21:02:40 -0000	1.364
--- src/backend/postmaster/postmaster.c	2 Feb 2004 19:08:43 -0000
***************
*** 2438,2443 ****
--- 2438,2450 ----
  	 * Signal handlers setting is moved to tcop/postgres...
  	 */
  
+ 	/* save start time for end of session reporting */
+ 	gettimeofday(&(port->session_start),NULL);
+ 
+ 	/* set these to empty in case they are needed before we set them up */
+ 	port->remote_host = "";
+ 	port->remote_port = "";
+ 
  	/* Save port etc. for ps status */
  	MyProcPort = port;
  
***************
*** 2492,2497 ****
--- 2499,2510 ----
  		snprintf(tmphost, sizeof(tmphost), "%s:%s", remote_host, remote_port);
  		StrNCpy(remote_host, tmphost, sizeof(remote_host));
  	}
+ 
+ 	/*
+ 	 * save remote_host and remote_port in port stucture
+ 	 */
+ 	port->remote_host = strdup(remote_host);
+ 	port->remote_port = strdup(remote_port);
  
  	/*
  	 * Ready to begin client interaction.  We will give up and exit(0)
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.387
diff -c -r1.387 postgres.c
*** src/backend/tcop/postgres.c	28 Jan 2004 21:02:40 -0000	1.387
--- src/backend/tcop/postgres.c	2 Feb 2004 19:08:43 -0000
***************
*** 84,89 ****
--- 84,92 ----
  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
   */
***************
*** 149,154 ****
--- 152,158 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);
  
  
  /* ----------------------------------------------------------------
***************
*** 2406,2412 ****
--- 2410,2419 ----
  	 * 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)
***************
*** 2435,2440 ****
--- 2442,2453 ----
  			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);
  	}
  
  	/*
***************
*** 3172,3175 ****
--- 3185,3246 ----
  			 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/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.182
diff -c -r1.182 guc.c
*** src/backend/utils/misc/guc.c	31 Jan 2004 05:09:41 -0000	1.182
--- src/backend/utils/misc/guc.c	2 Feb 2004 19:08:44 -0000
***************
*** 65,70 ****
--- 65,71 ----
  
  /* XXX these should appear in other modules' header files */
  extern bool Log_connections;
+ extern bool Log_session_end;
  extern bool check_function_bodies;
  extern int	PreAuthDelay;
  extern int	AuthenticationTimeout;
***************
*** 499,504 ****
--- 500,513 ----
  			NULL
  		},
  		&Log_connections,
+ 		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
  	},
  	{
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.101
diff -c -r1.101 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample	24 Jan 2004 20:00:45 -0000	1.101
--- src/backend/utils/misc/postgresql.conf.sample	2 Feb 2004 19:08:44 -0000
***************
*** 179,184 ****
--- 179,185 ----
  #debug_print_plan = false
  #debug_pretty_print = false
  #log_connections = false
+ #log_session_end = false
  #log_duration = false
  #log_pid = false
  #log_statement = false
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.39
diff -c -r1.39 libpq-be.h
*** src/include/libpq/libpq-be.h	20 Dec 2003 17:31:21 -0000	1.39
--- src/include/libpq/libpq-be.h	2 Feb 2004 19:08:45 -0000
***************
*** 47,52 ****
--- 47,55 ----
  	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 */
  	CAC_state	canAcceptConnections;	/* postmaster connection status */
  
  	/*
#2Peter Eisentraut
peter_e@gmx.net
In reply to: Andrew Dunstan (#1)
Re: log session end - again

Andrew Dunstan wrote:

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by
the config setting "log_session_end - true". It produces lines like
these:

If we log "session" end, shouldn't we also log "session" start, rather
than "connection" start? It seems there should be some symmetry here,
also for the configuration parameter names.

#3Andrew Dunstan
andrew@dunslane.net
In reply to: Peter Eisentraut (#2)
Re: [PATCHES] log session end - again

[redirecting to hackers]

If you like. I originally just made it happen if log_connections was
set, but Neil wanted a separate setting for it. What is the consensus
about a name?

cheers

andrew

Peter Eisentraut wrote:

Show quoted text

Andrew Dunstan wrote:

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by
the config setting "log_session_end - true". It produces lines like
these:

If we log "session" end, shouldn't we also log "session" start, rather
than "connection" start? It seems there should be some symmetry here,
also for the configuration parameter names.

#4Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Andrew Dunstan (#3)
Re: [PATCHES] log session end - again

Andrew Dunstan wrote:

[redirecting to hackers]

If you like. I originally just made it happen if log_connections was
set, but Neil wanted a separate setting for it. What is the consensus
about a name?

log_disconnect?

-- 
  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
#5Andrew Dunstan
andrew@dunslane.net
In reply to: Bruce Momjian (#4)
Re: [PATCHES] log session end - again

Bruce Momjian wrote:

Andrew Dunstan wrote:

[redirecting to hackers]

If you like. I originally just made it happen if log_connections was
set, but Neil wanted a separate setting for it. What is the consensus
about a name?

log_disconnect?

Not bad. Maybe for symmetry "log_disconnections" would be better.

Here's what the log lines look like:

for a local connection:
[21340]: LOG: session end: duration: 0:00:23.41 user=andrew database=template1 host=[local]
database=template1 host=[local]

for a tcp connection:
[21351]: LOG: session end: duration: 0:00:20.22 user=andrew database=template1 host=127.0.0.1 port=33419
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373]: LOG: session end: duration: 0:00:02.25 user=andrew database=template1 host=alphonso port=33421
database=template1 host=alphonso port=33421

Do we want to change those too? Maybe "session end: duration:" should be
"disconnection: session time:" or some such.

cheers

andrew

#6Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Andrew Dunstan (#5)
Re: [PATCHES] log session end - again

Also, Andrew, on your other patch for log_session_info line, Magnus had
the idea of giving each session an id based on the first transaction of
the session. That seems like a useful addition to that variable, though
I am not sure what value to give a session before it executes its first
query.

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

Andrew Dunstan wrote:

Bruce Momjian wrote:

Andrew Dunstan wrote:

[redirecting to hackers]

If you like. I originally just made it happen if log_connections was
set, but Neil wanted a separate setting for it. What is the consensus
about a name?

log_disconnect?

Not bad. Maybe for symmetry "log_disconnections" would be better.

Here's what the log lines look like:

for a local connection:
[21340] LOG: session end: duration: 0:00:23.41 user=andrew
database=template1 host=[local]

for a tcp connection:
[21351] LOG: session end: duration: 0:00:20.22 user=andrew
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373] LOG: session end: duration: 0:00:02.25 user=andrew
database=template1 host=alphonso port=33421

Do we want to change those too? Maybe "session end: duration:" should be
"disconnection: session time:" or some such.

cheers

andrew

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

-- 
  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
#7Andrew Dunstan
andrew@dunslane.net
In reply to: Bruce Momjian (#6)
Re: [PATCHES] log session end - again

Bruce Momjian wrote:

Also, Andrew, on your other patch for log_session_info line, Magnus had
the idea of giving each session an id based on the first transaction of
the session. That seems like a useful addition to that variable, though
I am not sure what value to give a session before it executes its first
query.

We can think about that. I am planning to tackle these separately (hence
today's patch).

I did think about using a cluster-wide sequence, if we can make such a
thing (might also be useful for system generated UIDs too).

cheers

andrew

#8Tom Lane
tgl@sss.pgh.pa.us
In reply to: Andrew Dunstan (#7)
Re: [PATCHES] log session end - again

Andrew Dunstan <andrew@dunslane.net> writes:

Bruce Momjian wrote:

Also, Andrew, on your other patch for log_session_info line, Magnus had
the idea of giving each session an id based on the first transaction of
the session.

I did think about using a cluster-wide sequence, if we can make such a
thing (might also be useful for system generated UIDs too).

Not a good idea IMHO. If you do that, then there will be no such thing
as a purely read-only transaction, because *every* transaction will
include a nextval() call. That means even read-only transactions cannot
commit till the disk spins.

If we want a unique id for transient purposes like logging, then make
some kind of counter in shared memory. Don't use a sequence, it's much
too heavyweight.

regards, tom lane

#9Andrew Dunstan
andrew@dunslane.net
In reply to: Tom Lane (#8)
Re: [PATCHES] log session end - again

Tom Lane wrote:

Andrew Dunstan <andrew@dunslane.net> writes:

Bruce Momjian wrote:

Also, Andrew, on your other patch for log_session_info line, Magnus had
the idea of giving each session an id based on the first transaction of
the session.

I did think about using a cluster-wide sequence, if we can make such a
thing (might also be useful for system generated UIDs too).

Not a good idea IMHO. If you do that, then there will be no such thing
as a purely read-only transaction, because *every* transaction will
include a nextval() call. That means even read-only transactions cannot
commit till the disk spins.

If we want a unique id for transient purposes like logging, then make
some kind of counter in shared memory. Don't use a sequence, it's much
too heavyweight.

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call nextval()
once per connection, and, for the other purpose where I suggested it
would be useful, once per "create user". That doesn't seem very heavyweight.

cheers

andrew

#10Andrew Dunstan
andrew@dunslane.net
In reply to: Andrew Dunstan (#9)
session IDs

[note change of subject]

I wrote:

Tom Lane wrote:

Andrew Dunstan <andrew@dunslane.net> writes:

I did think about using a cluster-wide sequence, if we can make such
a thing (might also be useful for system generated UIDs too).

Not a good idea IMHO. If you do that, then there will be no such thing
as a purely read-only transaction, because *every* transaction will
include a nextval() call. That means even read-only transactions cannot
commit till the disk spins.

If we want a unique id for transient purposes like logging, then make
some kind of counter in shared memory. Don't use a sequence, it's much
too heavyweight.

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call
nextval() once per connection, and, for the other purpose where I
suggested it would be useful, once per "create user". That doesn't
seem very heavyweight.

If we really want a loggable session id then ISTM it should be not
transient at all, but in fact unique even across server restart. One
moderately simple scheme that occurred to me is to have to postmaster
keep a 64 bit counter, initialised by a call to gettimeofday(), and
bumped on every connection. The postmaster would just put the new
counter value into the port structure for the backend (and in the exec
case it would be written out and then read back by the backend, along
with the other port stuff set by postmaster). No need for a persistent
sequence or for shared memory, and it would be unique unless time went
backwards by exactly the right amount between server starts (you do run
ntp on your machines, don't you?).

I am less sure of the utility of such an ID, though. After all, if you
see a disconnect log message for a given PID you must know that any
reuse of that PID indicates a new session, or even if you just see a
connection message you know it must be a new session. OTOH, having a
unique SessionID might simplify the logic required of log analysis tools.

cheers

andrew

#11Kris Jurka
books@ejurka.com
In reply to: Andrew Dunstan (#10)
Re: session IDs

Tom Lane wrote:

Andrew Dunstan <andrew@dunslane.net> writes:

I did think about using a cluster-wide sequence, if we can make such
a thing (might also be useful for system generated UIDs too).

Not a good idea IMHO. If you do that, then there will be no such thing
as a purely read-only transaction, because *every* transaction will
include a nextval() call. That means even read-only transactions cannot
commit till the disk spins.

A sequence could be used if it was created with a sufficiently large CACHE
value, so a read only transaction would only have to hit the disk if it
happened to be the one to hit an exhausted cache.

Kris Jurka

#12Tom Lane
tgl@sss.pgh.pa.us
In reply to: Andrew Dunstan (#9)
Re: [PATCHES] log session end - again

Andrew Dunstan <andrew@dunslane.net> writes:

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call nextval()
once per connection,

Oh, okay, I misunderstood. But why not just use the PID?

regards, tom lane

#13Peter Eisentraut
peter_e@gmx.net
In reply to: Andrew Dunstan (#10)
Re: session IDs

Andrew Dunstan wrote:

I am less sure of the utility of such an ID, though. After all, if
you see a disconnect log message for a given PID you must know that
any reuse of that PID indicates a new session, or even if you just
see a connection message you know it must be a new session. OTOH,
having a unique SessionID might simplify the logic required of log
analysis tools.

The PID *is* a unique session ID. Why is it not sufficient?

#14Andrew Dunstan
andrew@dunslane.net
In reply to: Peter Eisentraut (#13)
Re: session IDs

Peter Eisentraut wrote:

Andrew Dunstan wrote:

I am less sure of the utility of such an ID, though. After all, if
you see a disconnect log message for a given PID you must know that
any reuse of that PID indicates a new session, or even if you just
see a connection message you know it must be a new session. OTOH,
having a unique SessionID might simplify the logic required of log
analysis tools.

The PID *is* a unique session ID. Why is it not sufficient?

It's unique for the duration of the session, but it won't be for logs
covering a sufficient period of time, because PIDs are reused, in some
cases not even by cycling but being allocated randomly.

As I said elsewhere, I can live with that, but others wanted something
that was more unique (if such a term has meaning ;-)

cheers

andrew ("You are unique. Just like everybody else.")

#15Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Tom Lane (#12)
Re: [PATCHES] log session end - again

Andrew Dunstan wrote:

Tom Lane said:

Andrew Dunstan <andrew@dunslane.net> writes:

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call
nextval() once per connection,

Oh, okay, I misunderstood. But why not just use the PID?

Bruce and others have suggested that PID is not sufficiently unique.
Personally, I can live with it :-)

The nice things about using xid for session id is that is is unique for
a long time, rather than pid.

-- 
  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
#16Andrew Dunstan
andrew@dunslane.net
In reply to: Tom Lane (#12)
Re: [PATCHES] log session end - again

Tom Lane said:

Andrew Dunstan <andrew@dunslane.net> writes:

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call
nextval() once per connection,

Oh, okay, I misunderstood. But why not just use the PID?

Bruce and others have suggested that PID is not sufficiently unique.
Personally, I can live with it :-)

cheers

andrew

#17Larry Rosenman
ler@lerctr.org
In reply to: Andrew Dunstan (#14)
Re: session IDs

--On Tuesday, February 03, 2004 11:12:03 -0500 Andrew Dunstan
<andrew@dunslane.net> wrote:

Peter Eisentraut wrote:

Andrew Dunstan wrote:

I am less sure of the utility of such an ID, though. After all, if
you see a disconnect log message for a given PID you must know that
any reuse of that PID indicates a new session, or even if you just
see a connection message you know it must be a new session. OTOH,
having a unique SessionID might simplify the logic required of log
analysis tools.

The PID *is* a unique session ID. Why is it not sufficient?

It's unique for the duration of the session, but it won't be for logs
covering a sufficient period of time, because PIDs are reused, in some
cases not even by cycling but being allocated randomly.

As I said elsewhere, I can live with that, but others wanted something
that was more unique (if such a term has meaning ;-)

How about pid+unix time of start of backend?

LER

cheers

andrew ("You are unique. Just like everybody else.")

---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.org

--
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 972-414-9812 E-Mail: ler@lerctr.org
US Mail: 1905 Steamboat Springs Drive, Garland, TX 75044-6749

#18Tom Lane
tgl@sss.pgh.pa.us
In reply to: Bruce Momjian (#15)
Re: [PATCHES] log session end - again

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

Andrew Dunstan wrote:

Bruce and others have suggested that PID is not sufficiently unique.

The nice things about using xid for session id is that is is unique for
a long time, rather than pid.

Hmm. Now that I think about it, InitPostgres() always runs a
transaction during backend startup. If we simply saved aside the XID
assigned to that transaction, it would cost next to nothing to do and
would provide a reasonably unique ID. However, this happens much later
than the postmaster currently prints the log_connection message ...

regards, tom lane

#19Andrew Dunstan
andrew@dunslane.net
In reply to: Tom Lane (#18)
Re: [PATCHES] log session end - again

Tom Lane wrote:

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

Andrew Dunstan wrote:

Bruce and others have suggested that PID is not sufficiently unique.

The nice things about using xid for session id is that is is unique for
a long time, rather than pid.

Hmm. Now that I think about it, InitPostgres() always runs a
transaction during backend startup. If we simply saved aside the XID
assigned to that transaction, it would cost next to nothing to do and
would provide a reasonably unique ID. However, this happens much later
than the postmaster currently prints the log_connection message ...

Right. And if we have sessionids we would want them logged there, I
think. And that would rule out anything based on xid or backend pid.
OTOH I am quite sure I can implement the time based counter idea I
suggested earlier with a very small amount of disturbance and very low
cost. Unless someone can see a flaw in the scheme.

cheers

andrew

#20Tom Lane
tgl@sss.pgh.pa.us
In reply to: Andrew Dunstan (#19)
Re: [PATCHES] log session end - again

Andrew Dunstan <andrew@dunslane.net> writes:

Right. And if we have sessionids we would want them logged there, I
think. And that would rule out anything based on xid or backend pid.

Uh, what's wrong with backend pid? Since we fork before we start doing
anything with a connection, it should surely be available soon enough
for the connection log message.

Larry's idea about combining PID and backend start time didn't sound too
unreasonable to me.

regards, tom lane

#21Andrew Dunstan
andrew@dunslane.net
In reply to: Tom Lane (#20)
Re: [PATCHES] log session end - again

Tom Lane said:

Andrew Dunstan <andrew@dunslane.net> writes:

Right. And if we have sessionids we would want them logged there, I
think. And that would rule out anything based on xid or backend pid.

Uh, what's wrong with backend pid? Since we fork before we start doing
anything with a connection, it should surely be available soon enough
for the connection log message.

Larry's idea about combining PID and backend start time didn't sound
too unreasonable to me.

It did to me too. I was just looking at this code 2 days ago. Somehow when
I looked again I thought we logged connections in the postmaster. Larry's
idea should work just fine. For log compactness I think I'd hexencode it -
the SessionID doesn't need any semantics, it's just like a cookie.

cheers

andrew

#22Andrew Dunstan
andrew@dunslane.net
In reply to: Peter Eisentraut (#2)
1 attachment(s)
Re: log session end - again

Peter Eisentraut wrote:

Andrew Dunstan wrote:

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by
the config setting "log_session_end - true". It produces lines like
these:

If we log "session" end, shouldn't we also log "session" start, rather
than "connection" start? It seems there should be some symmetry here,
also for the configuration parameter names.

OK, this version of the patch uses the config parameter name
"log_disconnections" for the sake of symmetry, and changes the message
wording slightly accordingly.

cheers

andrew

Attachments:

log_disconnections.patchtext/plain; name=log_disconnections.patchDownload
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.235
diff -c -r1.235 runtime.sgml
*** doc/src/sgml/runtime.sgml	27 Jan 2004 16:51:43 -0000	1.235
--- doc/src/sgml/runtime.sgml	2 Feb 2004 19:08:42 -0000
***************
*** 1825,1830 ****
--- 1825,1844 ----
  
  
       <varlistentry>
+       <term><varname>log_disconnections</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>
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.364
diff -c -r1.364 postmaster.c
*** src/backend/postmaster/postmaster.c	28 Jan 2004 21:02:40 -0000	1.364
--- src/backend/postmaster/postmaster.c	2 Feb 2004 19:08:43 -0000
***************
*** 2438,2443 ****
--- 2438,2450 ----
  	 * Signal handlers setting is moved to tcop/postgres...
  	 */
  
+ 	/* save start time for end of session reporting */
+ 	gettimeofday(&(port->session_start),NULL);
+ 
+ 	/* set these to empty in case they are needed before we set them up */
+ 	port->remote_host = "";
+ 	port->remote_port = "";
+ 
  	/* Save port etc. for ps status */
  	MyProcPort = port;
  
***************
*** 2492,2497 ****
--- 2499,2510 ----
  		snprintf(tmphost, sizeof(tmphost), "%s:%s", remote_host, remote_port);
  		StrNCpy(remote_host, tmphost, sizeof(remote_host));
  	}
+ 
+ 	/*
+ 	 * save remote_host and remote_port in port stucture
+ 	 */
+ 	port->remote_host = strdup(remote_host);
+ 	port->remote_port = strdup(remote_port);
  
  	/*
  	 * Ready to begin client interaction.  We will give up and exit(0)
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.387
diff -c -r1.387 postgres.c
*** src/backend/tcop/postgres.c	28 Jan 2004 21:02:40 -0000	1.387
--- src/backend/tcop/postgres.c	2 Feb 2004 19:08:43 -0000
***************
*** 84,89 ****
--- 84,92 ----
  bool		Warn_restart_ready = false;
  bool		InError = false;
  
+ /* flag for logging end of session */
+ bool        Log_disconnections = false;
+ 
  /*
   * Flags for expensive function optimization -- JMH 3/9/92
   */
***************
*** 149,154 ****
--- 152,158 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);
  
  
  /* ----------------------------------------------------------------
***************
*** 2406,2412 ****
--- 2410,2419 ----
  	 * other output options.
  	 */
  	if (debug_flag >= 1)
+ 	{
  		SetConfigOption("log_connections", "true", debug_context, gucsource);
+ 		SetConfigOption("log_disconnections", "true", debug_context, gucsource);
+ 	}
  	if (debug_flag >= 2)
  		SetConfigOption("log_statement", "true", debug_context, gucsource);
  	if (debug_flag >= 3)
***************
*** 2435,2440 ****
--- 2442,2453 ----
  			gucopts = lnext(gucopts);
  			SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
  		}
+ 
+ 		/*
+ 		 * set up handler to log session end.
+ 		 */
+ 		if (IsUnderPostmaster && Log_disconnections)
+ 			on_proc_exit(log_session_end,0);
  	}
  
  	/*
***************
*** 3172,3175 ****
--- 3185,3246 ----
  			 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("disconnection: session time: %s%s%s%s%s",
+ 				session_time,uname,dbname,remote_host,remote_port)));
+ 
  }
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.182
diff -c -r1.182 guc.c
*** src/backend/utils/misc/guc.c	31 Jan 2004 05:09:41 -0000	1.182
--- src/backend/utils/misc/guc.c	2 Feb 2004 19:08:44 -0000
***************
*** 65,70 ****
--- 65,71 ----
  
  /* XXX these should appear in other modules' header files */
  extern bool Log_connections;
+ extern bool Log_disconnections;
  extern bool check_function_bodies;
  extern int	PreAuthDelay;
  extern int	AuthenticationTimeout;
***************
*** 499,504 ****
--- 500,513 ----
  			NULL
  		},
  		&Log_connections,
+ 		false, NULL, NULL
+ 	},
+ 	{
+ 		{"log_disconnections", PGC_BACKEND, LOGGING_WHAT,
+ 		 gettext_noop("Logs end of a session, including duration"),
+ 		 NULL
+ 		},
+ 		&Log_disconnections,
  		false, 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.101
diff -c -r1.101 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample	24 Jan 2004 20:00:45 -0000	1.101
--- src/backend/utils/misc/postgresql.conf.sample	2 Feb 2004 19:08:44 -0000
***************
*** 179,184 ****
--- 179,185 ----
  #debug_print_plan = false
  #debug_pretty_print = false
  #log_connections = false
+ #log_disconnections = false
  #log_duration = false
  #log_pid = false
  #log_statement = false
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.39
diff -c -r1.39 libpq-be.h
*** src/include/libpq/libpq-be.h	20 Dec 2003 17:31:21 -0000	1.39
--- src/include/libpq/libpq-be.h	2 Feb 2004 19:08:45 -0000
***************
*** 47,52 ****
--- 47,55 ----
  	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 */
  	CAC_state	canAcceptConnections;	/* postmaster connection status */
  
  	/*
#23Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Tom Lane (#20)
Re: [PATCHES] log session end - again

Tom Lane wrote:

Andrew Dunstan <andrew@dunslane.net> writes:

Right. And if we have sessionids we would want them logged there, I
think. And that would rule out anything based on xid or backend pid.

Uh, what's wrong with backend pid? Since we fork before we start doing
anything with a connection, it should surely be available soon enough
for the connection log message.

Larry's idea about combining PID and backend start time didn't sound too
unreasonable to me.

Wow, like the idea too --- pid plus time_t start time of backend.
Actully, it would be good to have star time first so you can sort
everything in order of start time.

-- 
  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
#24Andrew Dunstan
andrew@dunslane.net
In reply to: Bruce Momjian (#23)
Re: [PATCHES] log session end - again

Bruce Momjian wrote:

Tom Lane wrote:

Larry's idea about combining PID and backend start time didn't sound too
unreasonable to me.

Wow, like the idea too --- pid plus time_t start time of backend.
Actully, it would be good to have star time first so you can sort
everything in order of start time.

Yes. Of course, you would need either to sort additionally on log
timestamp or use an order-preserving sort.

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

cheers

andrew

#25Chester Kustarz
chester@arbor.net
In reply to: Bruce Momjian (#23)
Re: [PATCHES] log session end - again

On Thu, 5 Feb 2004, Bruce Momjian wrote:

Wow, like the idea too --- pid plus time_t start time of backend.
Actully, it would be good to have star time first so you can sort
everything in order of start time.

Why not just add a printf like pattern so the user can output
whatever they like?
%p - backend pid
%t - connect time
%C - standard connection string "%t:%p"
%a - autoincrement number
...

People could add more in later if they want more options.

#26Andrew Dunstan
andrew@dunslane.net
In reply to: Chester Kustarz (#25)
Re: [PATCHES] log session end - again

Chester Kustarz wrote:

On Thu, 5 Feb 2004, Bruce Momjian wrote:

Wow, like the idea too --- pid plus time_t start time of backend.
Actully, it would be good to have star time first so you can sort
everything in order of start time.

Why not just add a printf like pattern so the user can output
whatever they like?
%p - backend pid
%t - connect time
%C - standard connection string "%t:%p"
%a - autoincrement number

log_line_info where this would be implemented is indeed done with a
printf like string, which is easily extensible The following is adapted
from the description of the original patch which it is my intention to
bring up to date soon and resubmit:

Prefixes each message in the server log file or syslog with extra
information as specified in the string. The default is an empty
string. The following sequences in the string are translated:
'%U' is replace with the username,
'%D' is replaced by the database name,
and '%%' is replaced by '%'.
All other characters are copied literally to the log. For example,
log_line_info = '<%U%%%D> '
will produce output like this:
<myuser%mydb> LOG: query: create table foo(blah text);

cheers

andrew

#27Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Andrew Dunstan (#24)
Re: [PATCHES] log session end - again

Andrew Dunstan wrote:

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

Andrew, I can't find the log_disconnections patch. I know I saw it, but
I can't find it now. Would you resent it please?

-- 
  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
#28Andrew Dunstan
andrew@dunslane.net
In reply to: Bruce Momjian (#27)
Re: [PATCHES] log session end - again

You can find it here.

http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php

I know Neil was reviewing it and had a minor doc style quibble, as well
as the question he raised on -hackers about psql tab completion.

cheers

andrew

Bruce Momjian wrote:

Show quoted text

Andrew Dunstan wrote:

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

Andrew, I can't find the log_disconnections patch. I know I saw it, but
I can't find it now. Would you resent it please?

#29Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Andrew Dunstan (#28)
Re: [PATCHES] log session end - again

Your patch has been added to the PostgreSQL unapplied patches list at:

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

I will try to apply it within the next 48 hours.

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

Andrew Dunstan wrote:

You can find it here.

http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php

I know Neil was reviewing it and had a minor doc style quibble, as well
as the question he raised on -hackers about psql tab completion.

cheers

andrew

Bruce Momjian wrote:

Andrew Dunstan wrote:

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

Andrew, I can't find the log_disconnections patch. I know I saw it, but
I can't find it now. Would you resent it please?

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faqs/FAQ.html

-- 
  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
#30Bruce Momjian
pgman@candle.pha.pa.us
In reply to: Andrew Dunstan (#28)
1 attachment(s)
Re: [PATCHES] log session end - again

Patch applied. Thanks.

I modified the doc wording a bit --- patch attached.

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

Andrew Dunstan wrote:

You can find it here.

http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php

I know Neil was reviewing it and had a minor doc style quibble, as well
as the question he raised on -hackers about psql tab completion.

cheers

andrew

Bruce Momjian wrote:

Andrew Dunstan wrote:

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

Andrew, I can't find the log_disconnections patch. I know I saw it, but
I can't find it now. Would you resent it please?

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faqs/FAQ.html

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

Attachments:

/bjm/4text/plainDownload
<http://ads.postgresql.org/redirect.php?lvl=sponsor> 	

Search for:

Search:

Format:  Results/page:
 

	<http://ads.postgresql.org/redirect.php?lvl=free>
pgsql-announce <http://archives.postgresql.org/pgsql-announce>

*Users Lists*
pgsql-admin <http://archives.postgresql.org/pgsql-admin>
pgsql-advocacy <http://archives.postgresql.org/pgsql-advocacy>
pgsql-benchmarks <http://archives.postgresql.org/pgsql-benchmarks>
pgsql-bugs <http://archives.postgresql.org/pgsql-bugs>
pgsql-chat <http://archives.postgresql.org/pgsql-chat>
pgsql-docs <http://archives.postgresql.org/pgsql-docs>
pgsql-cygwin <http://archives.postgresql.org/pgsql-cygwin>
pgsql-general <http://archives.postgresql.org/pgsql-general>
pgsql-interfaces <http://archives.postgresql.org/pgsql-interfaces>
pgsql-jdbc <http://archives.postgresql.org/pgsql-jdbc>
pgsql-jobs <http://archives.postgresql.org/pgsql-jobs>
pgsql-novice <http://archives.postgresql.org/pgsql-novice>
pgsql-odbc <http://archives.postgresql.org/pgsql-odbc>
pgsql-performance <http://archives.postgresql.org/pgsql-performance>
pgsql-php <http://archives.postgresql.org/pgsql-php>
pgsql-ports <http://archives.postgresql.org/pgsql-ports>
pgsql-sql <http://archives.postgresql.org/pgsql-sql>
pgsql-www <http://archives.postgresql.org/pgsql-www>

*Developer Lists*
pgsql-committers <http://archives.postgresql.org/pgsql-committers>
pgsql-hackers <http://archives.postgresql.org/pgsql-hackers>
pgsql-hackers-win32 <http://archives.postgresql.org/pgsql-hackers-win32>
pgsql-patches <http://archives.postgresql.org/pgsql-patches>

*Regional Lists*
pgsql-de-allgemein <http://archives.postgresql.org/pgsql-de-allgemein>
pgsql-fr-generale <http://archives.postgresql.org/pgsql-fr-generale>
pgsql-tr-genel <http://archives.postgresql.org/pgsql-tr-genel>

*Project Lists*
pgadmin-hackers <http://archives.postgresql.org/pgadmin-hackers>
pgadmin-support <http://archives.postgresql.org/pgadmin-support>

*User Groups*
San Francisco <http://archives.postgresql.org/sfpug>

	


    Re: log session end - again

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

    * *From*: *Andrew Dunstan <andrew ( at ) dunslane ( dot ) net
      <mailto:andrew@DOMAIN.HIDDEN>>*
    * *To*: *"Patches (PostgreSQL)" <pgsql-patches ( at ) postgresql (
      dot ) org <mailto:pgsql-patches@DOMAIN.HIDDEN>>*
    * *Subject*: *Re: log session end - again*
    * Date: Tue, 03 Feb 2004 20:03:42 -0500

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


Peter Eisentraut wrote:

    Andrew Dunstan wrote:


        This patch brings up to date what I did last year (now unfortunately
        bitrotted) to allow the logging of the end of a session, enabled by
        the config setting "log_session_end - true". It produces lines like
        these:



    If we log "session" end, shouldn't we also log "session" start,
    rather than "connection" start? It seems there should be some
    symmetry here, also for the configuration parameter names.




OK, this version of the patch uses the config parameter name
"log_disconnections" for the sake of symmetry, and changes the message
wording slightly accordingly.

cheers

andrew

Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.235
diff -c -r1.235 runtime.sgml
*** doc/src/sgml/runtime.sgml	27 Jan 2004 16:51:43 -0000	1.235
--- doc/src/sgml/runtime.sgml	2 Feb 2004 19:08:42 -0000
***************
*** 1825,1830 ****
--- 1825,1844 ----
  
  
       <varlistentry>
+       <term><varname>log_disconnections</varname> (<type>boolean</type>)</term>
+       <listitem>
+        <para>
+        This outputs a line in the server logs similar to LOG_CONNECTIONS 
+        but at session termination, and includes 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>
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/postmaster/postmaster.c,v
retrieving revision 1.364
diff -c -r1.364 postmaster.c
*** src/backend/postmaster/postmaster.c	28 Jan 2004 21:02:40 -0000	1.364
--- src/backend/postmaster/postmaster.c	2 Feb 2004 19:08:43 -0000
***************
*** 2438,2443 ****
--- 2438,2450 ----
  	 * Signal handlers setting is moved to tcop/postgres...
  	 */
  
+ 	/* save start time for end of session reporting */
+ 	gettimeofday(&(port->session_start),NULL);
+ 
+ 	/* set these to empty in case they are needed before we set them up */
+ 	port->remote_host = "";
+ 	port->remote_port = "";
+ 
  	/* Save port etc. for ps status */
  	MyProcPort = port;
  
***************
*** 2492,2497 ****
--- 2499,2510 ----
  		snprintf(tmphost, sizeof(tmphost), "%s:%s", remote_host, remote_port);
  		StrNCpy(remote_host, tmphost, sizeof(remote_host));
  	}
+ 
+ 	/*
+ 	 * save remote_host and remote_port in port stucture
+ 	 */
+ 	port->remote_host = strdup(remote_host);
+ 	port->remote_port = strdup(remote_port);
  
  	/*
  	 * Ready to begin client interaction.  We will give up and exit(0)
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.387
diff -c -r1.387 postgres.c
*** src/backend/tcop/postgres.c	28 Jan 2004 21:02:40 -0000	1.387
--- src/backend/tcop/postgres.c	2 Feb 2004 19:08:43 -0000
***************
*** 84,89 ****
--- 84,92 ----
  bool		Warn_restart_ready = false;
  bool		InError = false;
  
+ /* flag for logging end of session */
+ bool        Log_disconnections = false;
+ 
  /*
   * Flags for expensive function optimization -- JMH 3/9/92
   */
***************
*** 149,154 ****
--- 152,158 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
+ static void log_session_end(void);
  
  
  /* ----------------------------------------------------------------
***************
*** 2406,2412 ****
--- 2410,2419 ----
  	 * other output options.
  	 */
  	if (debug_flag >= 1)
+ 	{
  		SetConfigOption("log_connections", "true", debug_context, gucsource);
+ 		SetConfigOption("log_disconnections", "true", debug_context, gucsource);
+ 	}
  	if (debug_flag >= 2)
  		SetConfigOption("log_statement", "true", debug_context, gucsource);
  	if (debug_flag >= 3)
***************
*** 2435,2440 ****
--- 2442,2453 ----
  			gucopts = lnext(gucopts);
  			SetConfigOption(name, value, PGC_BACKEND, PGC_S_CLIENT);
  		}
+ 
+ 		/*
+ 		 * set up handler to log session end.
+ 		 */
+ 		if (IsUnderPostmaster && Log_disconnections)
+ 			on_proc_exit(log_session_end,0);
  	}
  
  	/*
***************
*** 3172,3175 ****
--- 3185,3246 ----
  			 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("disconnection: session time: %s%s%s%s%s",
+ 				session_time,uname,dbname,remote_host,remote_port)));
+ 
  }
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.182
diff -c -r1.182 guc.c
*** src/backend/utils/misc/guc.c	31 Jan 2004 05:09:41 -0000	1.182
--- src/backend/utils/misc/guc.c	2 Feb 2004 19:08:44 -0000
***************
*** 65,70 ****
--- 65,71 ----
  
  /* XXX these should appear in other modules' header files */
  extern bool Log_connections;
+ extern bool Log_disconnections;
  extern bool check_function_bodies;
  extern int	PreAuthDelay;
  extern int	AuthenticationTimeout;
***************
*** 499,504 ****
--- 500,513 ----
  			NULL
  		},
  		&Log_connections,
+ 		false, NULL, NULL
+ 	},
+ 	{
+ 		{"log_disconnections", PGC_BACKEND, LOGGING_WHAT,
+ 		 gettext_noop("Logs end of a session, including duration"),
+ 		 NULL
+ 		},
+ 		&Log_disconnections,
  		false, 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.101
diff -c -r1.101 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample	24 Jan 2004 20:00:45 -0000	1.101
--- src/backend/utils/misc/postgresql.conf.sample	2 Feb 2004 19:08:44 -0000
***************
*** 179,184 ****
--- 179,185 ----
  #debug_print_plan = false
  #debug_pretty_print = false
  #log_connections = false
+ #log_disconnections = false
  #log_duration = false
  #log_pid = false
  #log_statement = false
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /projects/cvsroot/pgsql-server/src/include/libpq/libpq-be.h,v
retrieving revision 1.39
diff -c -r1.39 libpq-be.h
*** src/include/libpq/libpq-be.h	20 Dec 2003 17:31:21 -0000	1.39
--- src/include/libpq/libpq-be.h	2 Feb 2004 19:08:45 -0000
***************
*** 47,52 ****
--- 47,55 ----
  	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 */
  	CAC_state	canAcceptConnections;	/* postmaster connection status */
  
  	/*

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

    * *References*:
          o *log session end - again <msg00047.php>*
                + /From:/ Andrew Dunstan
          o *Re: log session end - again <msg00048.php>*
                + /From:/ Peter Eisentraut

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

    * Prev by Date: *New win32 signals patch (3) <msg00071.php>*
    * Next by Date: *Re: fix memcpy() overlap <msg00073.php>*
    * Previous by thread: *Re: log session end - again <msg00048.php>*
    * Next by thread: *fix memcpy() overlap <msg00049.php>*
    * Index(es):
          o *Main* <index.php#00072>
          o *Thread* <threads.php#00072>

* Home <http://archives.postgresql.org/> | Main Index <index.php> |
Thread Index <threads.php> *