log_line_info

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(at)%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

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(at)%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(at)%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(at)%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).

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(at)%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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian 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(at)%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

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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian 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(at)%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](at)[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(at)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(at)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(at)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

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.

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(at)%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.

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(at)%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

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

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(at)%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(at)%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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian 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(at)%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(at)%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

Andrew Dunstan wrote:
> >> defaulting to the beginning if not found.
> >> Examples: "%T [%P]: " (everybody gets timestamp and pid)
> >> "%T [%P]: %U(at)%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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073