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

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

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

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

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

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

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

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

[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

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

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

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

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?

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.")

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

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

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

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

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

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

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

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

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.

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.
Thedefault is an empty       string. The following sequences in the string are translated:       '%U' is replace with
theusername,       '%D' is replaced by the database name,       and '%%' is replaced by '%'.       All other characters
arecopied 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

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

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

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

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