Attached is a patch for tagging log lines produced by backends. It is 
not quite ready for application - this is for people to look over and 
play with.

For my testing I used the following settings:

log_connections = true
log_disconnections = true
log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
log_statement = true
log_hostname = true
log_source_port = true


Comments welcome

(Rod Taylor has suggested adding in escapes for remote host and remote 
port. This can be done easily enough - I want to call a halt at some 
stage and get the basics of this in. Extending it will then be easy).

cheers

andrew
Mon, 23 Feb 2004 13:09:06 -0500
Andrew Dunstan <andrew@dunslane.net>
log_line_info

I haven't had any other feedback on this patch that I posted. However, 
I'm a bit dissatisfied with it for a couple of reasons:

. when a connection is logged we don't yet know the user and database, 
because we haven't processed the initial packet yet. That causes %U and 
%D to produce empty strings, which looks mildly ugly. I'm inclined in 
this case to emit something like "****" or "[unknown]" for these escapes.

. we don't produce any output for postmaster, stats collector etc. 
processes. If we really want to get rid of log_pid and log_timestamp 
this needs to be dealt with, IMNSHO. We could handle that in a few ways:
  - have a separate GUC var (log_line_info_postmaster?) Not much gain 
over keeping the existing vars, though
  - have a special marker in the string (%X maybe) that says stop 
processing for postmaster here.
    Example: "%T [%P]:%X %U@%D(%C:%S %I line:%L "
  - have a special marker where what follows is the postmaster variant, 
defaulting to the beginning if not found.
    Examples: "%T [%P]: " (everybody gets timestamp and pid)
              "%T [%P]: %U@%D(%C:%S %I line:%L %X%T [%P]:" (same effect 
as example under previous point)
  - something else I haven't thought of ;-)

Comments welcome

cheers

andrew


Andrew Dunstan wrote:

>
> Attached is a patch for tagging log lines produced by backends. It is 
> not quite ready for application - this is for people to look over and 
> play with.
>
> For my testing I used the following settings:
>
> log_connections = true
> log_disconnections = true
> log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
> log_statement = true
> log_hostname = true
> log_source_port = true
>
>
> Comments welcome
>
> (Rod Taylor has suggested adding in escapes for remote host and remote 
> port. This can be done easily enough - I want to call a halt at some 
> stage and get the basics of this in. Extending it will then be easy).



Thu, 26 Feb 2004 09:57:03 -0500
Andrew Dunstan <andrew@dunslane.net>
log_line_info
Andrew Dunstan wrote:
> 
> Attached is a patch for tagging log lines produced by backends. It is 
> not quite ready for application - this is for people to look over and 
> play with.
> 
> For my testing I used the following settings:
> 
> log_connections = true
> log_disconnections = true
> log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
> log_statement = true
> log_hostname = true
> log_source_port = true
> 
> 
> Comments welcome
> 
> (Rod Taylor has suggested adding in escapes for remote host and remote 
> port. This can be done easily enough - I want to call a halt at some 
> stage and get the basics of this in. Extending it will then be easy).
>   #log_disconnections = false
>   #log_duration = false
>   #log_pid = false
> + #log_line_info = ''         # e.g. '<%U%%%D> ' 
> +                             #  %U=username %D=databasename %C=sessionid
> + 	                    #  %P=PID %T=timestamp %L=session line number
> +                             #  %S=session start timestamp %I=command tag
> +                             #  %%=%
>   #log_statement = false

Nice.  Only two comments --- does this mean we should remove log_pid? 
Seems it is now duplicate functionality.  Is that the only duplication?
Also, I don't see any documention changes in the patch, but I assume you
will work on that before final.

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

Sat, 28 Feb 2004 20:27:45 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: log_line_info


Bruce Momjian wrote:

>Andrew Dunstan wrote:
>  
>
>>Attached is a patch for tagging log lines produced by backends. It is 
>>not quite ready for application - this is for people to look over and 
>>play with.
>>
>>For my testing I used the following settings:
>>
>>log_connections = true
>>log_disconnections = true
>>log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
>>log_statement = true
>>log_hostname = true
>>log_source_port = true
>>
>>
>>Comments welcome
>>
>>(Rod Taylor has suggested adding in escapes for remote host and remote 
>>port. This can be done easily enough - I want to call a halt at some 
>>stage and get the basics of this in. Extending it will then be easy).
>>  #log_disconnections = false
>>  #log_duration = false
>>  #log_pid = false
>>+ #log_line_info = ''         # e.g. '<%U%%%D> ' 
>>+                             #  %U=username %D=databasename %C=sessionid
>>+ 	                    #  %P=PID %T=timestamp %L=session line number
>>+                             #  %S=session start timestamp %I=command tag
>>+                             #  %%=%
>>  #log_statement = false
>>    
>>
>
>Nice.  Only two comments --- does this mean we should remove log_pid? 
>Seems it is now duplicate functionality.  Is that the only duplication?
>Also, I don't see any documention changes in the patch, but I assume you
>will work on that before final.
>

I will do docs. We could sensibly get rid of log_pid and log_timestamp 
with my latest patch. I would also suggest getting rid of 
log_source_port, since there really isn't any reason *not* to log the 
source port. Do you want me to make those changes in my patch? Or I can 
leave them for now and we can get rid of them when everyone is happy.

cheers

andrew



Sat, 28 Feb 2004 22:22:49 -0500
Andrew Dunstan <andrew@dunslane.net>
Re: log_line_info
Andrew Dunstan wrote:
> >Nice.  Only two comments --- does this mean we should remove log_pid? 
> >Seems it is now duplicate functionality.  Is that the only duplication?
> >Also, I don't see any documention changes in the patch, but I assume you
> >will work on that before final.
> >
> 
> I will do docs. We could sensibly get rid of log_pid and log_timestamp 
> with my latest patch. I would also suggest getting rid of 
> log_source_port, since there really isn't any reason *not* to log the 
> source port. Do you want me to make those changes in my patch? Or I can 
> leave them for now and we can get rid of them when everyone is happy.

I agree, but let's make it a separate patch.

Oh, I think we still need log_timestamp for postmaster-generated lines,
no?  What does log_line_info output for postmaster-generated logs?

Also, should we call the option just log_line?  Is that clearer, or
log_line_prefix?

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

Sat, 28 Feb 2004 23:31:53 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: [PATCHES] log_line_info


Bruce Momjian wrote:

>Andrew Dunstan wrote:
>  
>
>>>Nice.  Only two comments --- does this mean we should remove log_pid? 
>>>Seems it is now duplicate functionality.  Is that the only duplication?
>>>Also, I don't see any documention changes in the patch, but I assume you
>>>will work on that before final.
>>>
>>>      
>>>
>>I will do docs. We could sensibly get rid of log_pid and log_timestamp 
>>with my latest patch. I would also suggest getting rid of 
>>log_source_port, since there really isn't any reason *not* to log the 
>>source port. Do you want me to make those changes in my patch? Or I can 
>>leave them for now and we can get rid of them when everyone is happy.
>>    
>>
>
>I agree, but let's make it a separate patch.
>
>Oh, I think we still need log_timestamp for postmaster-generated lines,
>no?  What does log_line_info output for postmaster-generated logs?
>

I have fixed the postmaster lines issue. There is a new escape %X that 
says "postmaster and friends stop here".

Example, with log_timestamp = false and log_pid = false and 
log_line_info = '%T [%P] %X %U@%D(%C:%S) %R %I line:%L ' :


2004-02-28 20:24:49 [11154] LOG:  database system was shut down at 
2004-02-28 20:24:20 EST
2004-02-28 20:24:49 [11154] LOG:  checkpoint record is at 0/9D1874
2004-02-28 20:24:49 [11154] LOG:  redo record is at 0/9D1874; undo 
record is at 0/0; shutdown TRUE
2004-02-28 20:24:49 [11154] LOG:  next transaction ID: 467; next OID: 17145
2004-02-28 20:24:49 [11154] LOG:  database system is ready
2004-02-28 20:25:30 [11158]  
[unknown]@[unknown](40413f8a.2b96:2004-02-28 20:25:30)   line:1 LOG:  
connection received: host=alphonso port=45621
2004-02-28 20:25:30 [11158]  andrew@blurflx(40413f8a.2b96:2004-02-28 
20:25:30) alphonso:45621 authentication line:2 LOG:  connection 
authorized: user=andrew database=blurflx
2004-02-28 20:25:34 [11158]  andrew@blurflx(40413f8a.2b96:2004-02-28 
20:25:30) alphonso:45621 idle line:3 LOG:  statement: SELECT n.nspname 
as "Schema",
          c.relname as "Name",
          CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 
'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' END as 
"Type",
          u.usename as "Owner",
         c2.relname as "Table"
        FROM pg_catalog.pg_class c
             JOIN pg_catalog.pg_index i ON i.indexrelid = c.oid
             JOIN pg_catalog.pg_class c2 ON i.indrelid = c2.oid
             LEFT JOIN pg_catalog.pg_user u ON u.usesysid = c.relowner
             LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
        WHERE c.relkind IN ('i','')
              AND n.nspname NOT IN ('pg_catalog', 'pg_toast')
              AND pg_catalog.pg_table_is_visible(c.oid)
        ORDER BY 1,2;
2004-02-28 20:25:38 [11158]  andrew@blurflx(40413f8a.2b96:2004-02-28 
20:25:30) alphonso:45621 idle line:4 LOG:  disconnection: session time: 
0:00:08.50 user=andrew database=blurflx host=alphonso:45621
2004-02-28 20:25:44 [11149] LOG:  received smart shutdown request
2004-02-28 20:25:44 [11170] LOG:  shutting down
2004-02-28 20:25:46 [11170] LOG:  database system is shut down


>
>Also, should we call the option just log_line?  Is that clearer, or
>log_line_prefix?
>  
>

I floated the name log_line_info a while back and noone objected. I 
don't think "log_line" is any clearer - quite the contrary IMNSHO.

cheers

andrew




Sat, 28 Feb 2004 23:44:31 -0500
Andrew Dunstan <andrew@dunslane.net>
Re: [PATCHES] log_line_info
Andrew Dunstan wrote:
> I will do docs. We could sensibly get rid of log_pid and
> log_timestamp with my latest patch. I would also suggest getting rid
> of log_source_port, since there really isn't any reason *not* to log
> the source port.

There is the very definite possibility that people don't care.


Sun, 29 Feb 2004 13:41:10 +0100
Peter Eisentraut <peter_e@gmx.net>
Re: log_line_info
Andrew Dunstan wrote:
> Attached is a patch for tagging log lines produced by backends. It is
> not quite ready for application - this is for people to look over and
> play with.
>
> For my testing I used the following settings:
>
> log_connections = true
> log_disconnections = true
> log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
> log_statement = true
> log_hostname = true
> log_source_port = true
>
>
> Comments welcome

I'm wondering, why did you choose to use capital letters, when normally 
the % codes are lower-case letters when possible?  I think lower-case 
letters are easier to read.


Sun, 29 Feb 2004 13:46:33 +0100
Peter Eisentraut <peter_e@gmx.net>
Re: log_line_info


Peter Eisentraut wrote:

>Andrew Dunstan wrote:
>  
>
>>Attached is a patch for tagging log lines produced by backends. It is
>>not quite ready for application - this is for people to look over and
>>play with.
>>
>>For my testing I used the following settings:
>>
>>log_connections = true
>>log_disconnections = true
>>log_line_info = '%T [%P] %U@%D(%C:%S) %I line:%L '
>>log_statement = true
>>log_hostname = true
>>log_source_port = true
>>
>>
>>Comments welcome
>>    
>>
>
>I'm wondering, why did you choose to use capital letters, when normally 
>the % codes are lower-case letters when possible?  I think lower-case 
>letters are easier to read.
>  
>

I did it to differentiate them from standard printf escapes. I don't 
feel strongly about it, though. I'm currently prepping a final patch and 
docs, so I'd be grateful for an early consensus on this.

cheers

andrew


Sun, 29 Feb 2004 08:11:04 -0500
Andrew Dunstan <andrew@dunslane.net>
Re: log_line_info


Peter Eisentraut wrote:

>Andrew Dunstan wrote:
>  
>
>>I will do docs. We could sensibly get rid of log_pid and
>>log_timestamp with my latest patch. I would also suggest getting rid
>>of log_source_port, since there really isn't any reason *not* to log
>>the source port.
>>    
>>
>
>There is the very definite possibility that people don't care.
>  
>

The only thing I can see where it actually makes a difference is in the 
ps display (and it is currently a bit broken anyway, as it uses 
"host:port" there, which won't work nicely with IP6 addresses). 
Connection and disconnection logging currently always log the source 
port, regardless of the setting.

If you think the ability to have it in or out of the ps display is 
important enough, we can certainly leave it in  - either way I will fix it.

cheers

andrew


Sun, 29 Feb 2004 08:19:03 -0500
Andrew Dunstan <andrew@dunslane.net>
Re: log_line_info
Andrew Dunstan wrote:
> 
> I haven't had any other feedback on this patch that I posted. However, 
> I'm a bit dissatisfied with it for a couple of reasons:
> 
> . when a connection is logged we don't yet know the user and database, 
> because we haven't processed the initial packet yet. That causes %U and 
> %D to produce empty strings, which looks mildly ugly. I'm inclined in 
> this case to emit something like "****" or "[unknown]" for these escapes.
> 
> . we don't produce any output for postmaster, stats collector etc. 
> processes. If we really want to get rid of log_pid and log_timestamp 
> this needs to be dealt with, IMNSHO. We could handle that in a few ways:
>   - have a separate GUC var (log_line_info_postmaster?) Not much gain 
> over keeping the existing vars, though
>   - have a special marker in the string (%X maybe) that says stop 
> processing for postmaster here.
>     Example: "%T [%P]:%X %U@%D(%C:%S %I line:%L "
>   - have a special marker where what follows is the postmaster variant, 
> defaulting to the beginning if not found.
>     Examples: "%T [%P]: " (everybody gets timestamp and pid)
>               "%T [%P]: %U@%D(%C:%S %I line:%L %X%T [%P]:" (same effect 
> as example under previous point)
>   - something else I haven't thought of ;-)

Seems the cleanest would be to just print nothing for items that have no
meaning for the postmaster.

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

Wed, 3 Mar 2004 00:03:22 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: log_line_info
Bruce Momjian said:
> Andrew Dunstan wrote:
>>
>> I haven't had any other feedback on this patch that I posted. However,
>>  I'm a bit dissatisfied with it for a couple of reasons:
>>
>> . when a connection is logged we don't yet know the user and database,
>>  because we haven't processed the initial packet yet. That causes %U
>> and  %D to produce empty strings, which looks mildly ugly. I'm
>> inclined in  this case to emit something like "****" or "[unknown]"
>> for these escapes.
>>
>> . we don't produce any output for postmaster, stats collector etc.
>> processes. If we really want to get rid of log_pid and log_timestamp
>> this needs to be dealt with, IMNSHO. We could handle that in a few
>> ways:
>>   - have a separate GUC var (log_line_info_postmaster?) Not much gain
>> over keeping the existing vars, though
>>   - have a special marker in the string (%X maybe) that says stop
>> processing for postmaster here.
>>     Example: "%T [%P]:%X %U@%D(%C:%S %I line:%L "
>>   - have a special marker where what follows is the postmaster
>>   variant,
>> defaulting to the beginning if not found.
>>     Examples: "%T [%P]: " (everybody gets timestamp and pid)
>>               "%T [%P]: %U@%D(%C:%S %I line:%L %X%T [%P]:" (same
>>               effect
>> as example under previous point)
>>   - something else I haven't thought of ;-)
>
> Seems the cleanest would be to just print nothing for items that have
> no meaning for the postmaster.
>

Not quite clean enough - I also want to be able to supress irrelevant
literal characters. See the actual patch sent in on Feb 29th at
http://archives.postgresql.org/pgsql-patches/2004-02/msg00266.php where I
used the first variant I suggested above.

cheers

andrew



Wed, 3 Mar 2004 06:23:44 -0500 (EST)
"Andrew Dunstan" <andrew@dunslane.net>
Re: log_line_info
Andrew Dunstan wrote:
> >> defaulting to the beginning if not found.
> >>     Examples: "%T [%P]: " (everybody gets timestamp and pid)
> >>               "%T [%P]: %U@%D(%C:%S %I line:%L %X%T [%P]:" (same
> >>               effect
> >> as example under previous point)
> >>   - something else I haven't thought of ;-)
> >
> > Seems the cleanest would be to just print nothing for items that have
> > no meaning for the postmaster.
> >
> 
> Not quite clean enough - I also want to be able to supress irrelevant
> literal characters. See the actual patch sent in on Feb 29th at
> http://archives.postgresql.org/pgsql-patches/2004-02/msg00266.php where I
> used the first variant I suggested above.

Yes, I understand there is no way to know if the literal characters are
supposed to print for postmaster message, but is seems easier to just
print them than to do the more complicated options you propose.  One
idea would be to suppress whitespace or perhaps special characters
_after_ an option that is skipped --- not perfect, but this is only log
output.  Of course, if you do <%option>, you get the leading < but not
the >.  Maybe just go with suppressing trailing whitespace of a skipped
option is best.

Also, I think you should switch to lowercase like Peter suggested.  You
aren't supporting any of the printf() letters, so you might as well use
lowercase.

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

Wed, 3 Mar 2004 12:43:04 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: log_line_info