Horton

Thread

  1. Logging - events supported

    Tim Holloway <mtsinc@southeast.net> — 1999-10-24T18:22:34Z

    Following is an updated list of the messages to be channeled by the proposed logging system.

THESE AND *ONLY* THESE are slated for implementation. If you have items you want
included, PLEASE LET ME KNOW! As it stands, this is a pretty minimal set.

Bear in mind that the logger is NOT a debugger. Logged messages are expected to be related to administrative events,
including, but not limited to - server status (including load-balancing and fault
reporting), security, user connections, and service requests. Added are the 1xxx class, which is designed to assist the
existing debugging system by providing a linkage between the free-form debugging messages and the formalized log system.
via the LOGBUG macro, which write to both debugging output AND logging.

Hint 1: If you are about to emit a plethora of debugging messages and you want a timestamp and/or entry in a log
database, use LOGBUG and include a unique event ID in the message so that the two can be reconciled.

Hint 2: If you want to log specific debugging info into a database table, format it as appropriate for a table load and
route it to a channel destined for that table. E.g.:

 sprintf( tracebuffer, "'%l|MEMSHORTAGE'|%d|%d", ++event_id, bytes_used, max_bytes);
 LOGBUG( 1003, tracebuffer );

FEEDBACK NEEDED! THANK YOU!

Logging classes:
---------------
1xz - The PostgreSQL server
2xx - User-related information
3xx - Transaction information
4xx - EXPLAIN results (???)
9xx - General system alerts
1000-1999 debugging events

Right now, the following are considered likely candidates,
subject to user feedback:

server info
 Server name, signal ID
101 - Server started
102 - Server shutdown
103 - Signal xxx received
104 - Server ABEND

user session
 userid, port or terminal ID, authentication scheme name
(e.g. md5). session ID
201 - User xxxx connected via port/terminal xxxxxxxx
authenticated by aaaaa
202 - User xxxx disconnected
203 - FORBIDDEN - connection denied for user xxxx via
port/terminal xxxxxxxxxx rejected by aaaaaaa

show commands
 Session ID, command text
301 - SELECT text
302 - INSERT text
303 - UPDATE text
304 - DELETE text

show results
 session ID, count or OID. primary/first/only table ID
affected
401 - SUCCESS - nnn records retrieved
402 - SUCCESS - record inserted at OID
403 - SUCCESS - nnn records updated
404 - SUCCESS - nnn records deleted
405 - FORBIDDEN - action xxxxxx denied to user xxxx on table
xxxxxxxx

explain
 as below:
500 EXPLAIN transaction ID sequence cost rows bytes

miscellaneous
 explanatory text
900 - Logging configuration file "ffff" was not found or
denied read access. Using default logging.
901 - Logging configuration file "ffff" could not be
processed - invalid text at line nnn.
902 - User overrides non-existent message ID nnn
903 - Channel requests non-existent message ID nnn
904 - end of section starting on line nnn was not found
905 - start of section ending on line nnn was not found
906 - (message from logging configuration file)

1000-1999 - LOGBUG macro 
 text - message text
user defines as needed - not standardized

  2. Re: [HACKERS] Logging - events supported

    Massimo Dal Zotto <dz@cs.unitn.it> — 1999-10-24T21:35:24Z

    > Following is an updated list of the messages to be channeled by the proposed logging system.
> 
> THESE AND *ONLY* THESE are slated for implementation. If you have items you want
> included, PLEASE LET ME KNOW! As it stands, this is a pretty minimal set.
> 
> Bear in mind that the logger is NOT a debugger. Logged messages are expected to be related to administrative events,
> including, but not limited to - server status (including load-balancing and fault
> reporting), security, user connections, and service requests. Added are the 1xxx class, which is designed to assist the
> existing debugging system by providing a linkage between the free-form debugging messages and the formalized log system.
> via the LOGBUG macro, which write to both debugging output AND logging.
> 
> Hint 1: If you are about to emit a plethora of debugging messages and you want a timestamp and/or entry in a log
> database, use LOGBUG and include a unique event ID in the message so that the two can be reconciled.
> 
> Hint 2: If you want to log specific debugging info into a database table, format it as appropriate for a table load and
> route it to a channel destined for that table. E.g.:
> 
>  sprintf( tracebuffer, "'%l|MEMSHORTAGE'|%d|%d", ++event_id, bytes_used, max_bytes);
>  LOGBUG( 1003, tracebuffer );
> 
> FEEDBACK NEEDED! THANK YOU!
> 
> Logging classes:
> ---------------
> 1xz - The PostgreSQL server
> 2xx - User-related information
> 3xx - Transaction information
> 4xx - EXPLAIN results (???)
> 9xx - General system alerts
> 1000-1999 debugging events
> 
> Right now, the following are considered likely candidates,
> subject to user feedback:
> 
> server info
>  Server name, signal ID
> 101 - Server started
> 102 - Server shutdown
> 103 - Signal xxx received
> 104 - Server ABEND
               ^^^^^

This reminds too much the old IBM dinosaurs. Maybe `crash' is more modern.


> user session
>  userid, port or terminal ID, authentication scheme name
> (e.g. md5). session ID
> 201 - User xxxx connected via port/terminal xxxxxxxx
> authenticated by aaaaa
> 202 - User xxxx disconnected
> 203 - FORBIDDEN - connection denied for user xxxx via
> port/terminal xxxxxxxxxx rejected by aaaaaaa
> 
> show commands
>  Session ID, command text
> 301 - SELECT text
> 302 - INSERT text
> 303 - UPDATE text
> 304 - DELETE text


Utility commands? Sequences? Table alteration commands?


> show results
>  session ID, count or OID. primary/first/only table ID
> affected
> 401 - SUCCESS - nnn records retrieved
> 402 - SUCCESS - record inserted at OID
> 403 - SUCCESS - nnn records updated
> 404 - SUCCESS - nnn records deleted
> 405 - FORBIDDEN - action xxxxxx denied to user xxxx on table
> xxxxxxxx
> 
> explain
>  as below:
> 500 EXPLAIN transaction ID sequence cost rows bytes
> 
> miscellaneous
>  explanatory text
> 900 - Logging configuration file "ffff" was not found or
> denied read access. Using default logging.
> 901 - Logging configuration file "ffff" could not be
> processed - invalid text at line nnn.
> 902 - User overrides non-existent message ID nnn
> 903 - Channel requests non-existent message ID nnn
> 904 - end of section starting on line nnn was not found
> 905 - start of section ending on line nnn was not found
> 906 - (message from logging configuration file)
> 
> 1000-1999 - LOGBUG macro 
>  text - message text
> user defines as needed - not standardized
> 
> ************
> 


I suggest also the following things:

1)	each log entry should be a single line. This would greatly simplify
	the automatic processing of log files using standard unix tools,
	including loading entries into a database table.

2)	each entry should be prefixed by a timestamp and the backend pid,
	more or less like the syslog entries. I suggest the following
	format, which is the one currently implemented by elog_timestamp()

	991020.14:29:56.699 [7172] started: host=127.0.0.1 user=dz database=dz
	991020.14:31:02.723 [7172] query: select * from pg_user

3)	the logging level can be changed on-the-fly by sending a SIGHUP to
	the postmaster and then automatically to all the backends. Currently
	it reloads the pg_options file, which was originally designed exactly
	for controlling the debug and log messages without restarting the
	postmaster and all backends, but it could also reload any other
	configuration file.

-- 
Massimo Dal Zotto

+----------------------------------------------------------------------+
|  Massimo Dal Zotto               email: dz@cs.unitn.it               |
|  Via Marconi, 141                phone: ++39-0461534251              |
|  38057 Pergine Valsugana (TN)      www: http://www.cs.unitn.it/~dz/  |
|  Italy                             pgp: finger dz@tango.cs.unitn.it  |
+----------------------------------------------------------------------+

  3. Re: [HACKERS] Logging - events supported

    Tim Holloway <mtsinc@southeast.net> — 1999-10-24T23:08:24Z

    
Massimo Dal Zotto wrote:
> 
...
> > 104 - Server ABEND
>                ^^^^^
> 
> This reminds too much the old IBM dinosaurs. Maybe `crash' is more modern.
> 

My past lies exposed! But that's locale=specific. You can just as easily make it report
"La comedia es finito". Or whatever.

> 
> I suggest also the following things:
> 
> 1)      each log entry should be a single line. This would greatly simplify
>         the automatic processing of log files using standard unix tools,
>         including loading entries into a database table.
> 
> 2)      each entry should be prefixed by a timestamp and the backend pid,
>         more or less like the syslog entries. I suggest the following
>         format, which is the one currently implemented by elog_timestamp()
> 
>         991020.14:29:56.699 [7172] started: host=127.0.0.1 user=dz database=dz
>         991020.14:31:02.723 [7172] query: select * from pg_user
>

Well, again, the format of the log output is under the administrator's control. If you
look at how Apache does it, you'll see the idea. Only the "magic codes" have changed to
reflect the differing types of data.
 
> 3)      the logging level can be changed on-the-fly by sending a SIGHUP to
>         the postmaster and then automatically to all the backends. Currently
>         it reloads the pg_options file, which was originally designed exactly
>         for controlling the debug and log messages without restarting the
>         postmaster and all backends, but it could also reload any other
>         configuration file.
>

This was Tom's suggestion as well. It seems good. Unless something prevents it,
that is how it shall work.

    Thanks,

     Tim Holloway

  4. Re: [HACKERS] Logging - events supported

    Ben Bennett <fiji@ayup.limey.net> — 1999-10-25T11:39:02Z

    Not sure if I missed something, but it would be nice to be able to log
performance information such as "query 'XYZ' performed a table scan on
a 3,000,000 row table", "query 'XYZ' took 3000 seconds to complete",
"query 'XYZ' forced a sort of a 4,000,000 row table", etc. where the
thresholds could be set by the administrator.  This would allow you to
periodically audit your server to make sure that there were sufficient
indices and that users/programmers were not writing really bad
queries.

Although I am not sure how difficult adding this to the backend is but
I would love to be able to hook a tool onto the logfile and see what
bad queries were being run while I ran an appliation against the
server.  This is especially useful if my application allows dynamic
queries.

		-ben

  5. Re: [ADMIN] Logging - events supported

    Herouth Maoz <herouth@oumail.openu.ac.il> — 1999-10-27T15:30:16Z

    At 20:22 +0200 on 24/10/1999, Tim Holloway wrote:


> show commands
>  Session ID, command text
> 301 - SELECT text
> 302 - INSERT text
> 303 - UPDATE text
> 304 - DELETE text

FWIW, don't forget CREATE, ALTER, DROP - DDL items in general. Nor COPY in
and out, perhaps SET.

Herouth

--
Herouth Maoz, Internet developer.
Open University of Israel - Telem project
http://telem.openu.ac.il/~herutma