Here is a patch to clean up elog():

	ftp://candle.pha.pa.us/pub/postgresql/mypatches/elog

Here is the detail:


REALLYFATAL => PANIC
STOP => PANIC
New INFO level the prints to client by default
New LOG level the prints to server log by default
Cause VACUUM information to print only to the client in verbose mode
VACUUM doesn't output to server logs
NOTICE => INFO where purely information messages are sent
DEBUG => LOG for purely server status messages
DEBUG removed, kept as backward compatible (will be added near 7.3)
DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1 added
DebugLvl removed in favor of new DEBUG[1-5] symbols
New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...
Server startup now logged with LOG instead of DEBUG
Postmaster -d flag effects only postmaster message, not backend messages
Remove debug_level GUC parameter
elog() numbers now start at 10
Add test to print error message if older elog() values are passed to elog()
Bootstrap mode now has a -d that requires an argument, like postmaster
This clears the -d debug level on backend start.  Is that done correctly?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Thu, 28 Feb 2002 00:10:24 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
elog() patch
Bruce Momjian writes:

> REALLYFATAL => PANIC
> STOP => PANIC

The annoying thing about the choice PANIC is that while the previous
suggestions may not give you the most accurate idea about what the action
really is, PANIC is just about the worst possible choice, because "panic"
is *no* action at all, it's just a state of mind.

> New INFO level the prints to client by default

I doubt this idea.  NOTICE should really print to the client only.  This
again comes down to the user-level errors vs. server-side errors issue.
But INFO doesn't convey either of these meanings.

> DEBUG removed, kept as backward compatible (will be added near 7.3)
> DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1 added
> DebugLvl removed in favor of new DEBUG[1-5] symbols

Since you've made us stick with 1-5, are there any meanings attached to
those numbers?

> New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
> New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...

Now that is *really* confusing.  Two different ways to number the same
things.

> Postmaster -d flag effects only postmaster message, not backend messages

Why?

> Remove debug_level GUC parameter

Why?

> Bootstrap mode now has a -d that requires an argument, like postmaster

OK

> This clears the -d debug level on backend start.  Is that done correctly?

Why?

-- 
Peter Eisentraut   peter_e@gmx.net


Thu, 28 Feb 2002 00:43:49 -0500 (EST)
Peter Eisentraut <peter_e@gmx.net>
Re: elog() patch
Peter Eisentraut wrote:
> Bruce Momjian writes:
> 
> > REALLYFATAL => PANIC
> > STOP => PANIC
> 
> The annoying thing about the choice PANIC is that while the previous
> suggestions may not give you the most accurate idea about what the action
> really is, PANIC is just about the worst possible choice, because "panic"
> is *no* action at all, it's just a state of mind.

Yes, but PANIC was chosen by vote, and it does match the kernel-level
description.

> > New INFO level the prints to client by default
> 
> I doubt this idea.  NOTICE should really print to the client only.  This
> again comes down to the user-level errors vs. server-side errors issue.
> But INFO doesn't convey either of these meanings.

We could call it TIP or something like that. I think INFO is used
because it isn't a NOTICE or ERROR or something major.  It is only INFO.
It is neutral information.

> > DEBUG removed, kept as backward compatible (will be added near 7.3)
> > DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1 added
> > DebugLvl removed in favor of new DEBUG[1-5] symbols
> 
> Since you've made us stick with 1-5, are there any meanings attached to
> those numbers?

5 is max, 1 is for higher level messages.  I just followed what was
already there.  We can adjsut these.

> > New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
> > New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...
> 
> Now that is *really* confusing.  Two different ways to number the same
> things.

Sure is, but it was agreed to by the group discussing it as the cleanest
solution.  postgresql.conf has these levels documented, as does the SGML
docs.

> > Postmaster -d flag effects only postmaster message, not backend messages
> 
> Why?

This allows you to see postmaster connection-level debug stuff without
the query debug stuff from the backend. If you want both, you have to
set the postgres -d flag too.  Seemed clearer but I can remove it if
people don't want it.

> > Remove debug_level GUC parameter
> 
> Why?

No longer needed with new DEBUG* levels.

> > This clears the -d debug level on backend start.  Is that done correctly?
> 
> Why?

Again, seemed clearer.  The way things are in the patch, you can't do -d
0 in the backend to turn off debug on the backend, so you have to
explicitly enable it. Of course, with these new GUC paramaters, the need
for -d is less anyway, and you can see all the messages in your client
if you wish.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Thu, 28 Feb 2002 10:58:16 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian writes:

> Yes, but PANIC was chosen by vote, and it does match the kernel-level
> description.

What is the kernel-level description?

> > I doubt this idea.  NOTICE should really print to the client only.  This
> > again comes down to the user-level errors vs. server-side errors issue.
> > But INFO doesn't convey either of these meanings.
>
> We could call it TIP or something like that. I think INFO is used
> because it isn't a NOTICE or ERROR or something major.  It is only INFO.
> It is neutral information.

That's what NOTICE is.  NOTICE is only neutral information.  NOTICE could
go to the client by default, whereas if you want something in the server
log you use LOG.  I doubt an extra level is needed.

> > > New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
> > > New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...
> >
> > Now that is *really* confusing.  Two different ways to number the same
> > things.
>
> Sure is, but it was agreed to by the group discussing it as the cleanest
> solution.  postgresql.conf has these levels documented, as does the SGML
> docs.

I doubt that agreement.

Consider, what and how much I want to debug is really quite independent of
what amount of regular "neutral" messages I want to see where.  The latter
is a rather permanent administrative decision, whereas the former is a
temporary decision to isolate problems.  A "debug level" is really a
universal concept in any package, and I hate to see it go.

Secondly, once I have decided how much debugging I want to do, it is
unlikely that I want to do a different amount of debugging on the client
and on the server.  I can see users becoming confused by this:  "I already
set the debugging level to 5, but I still only see the same messages in
the client".  I think that the current debug_level, plus a new Boolean
setting "debug_to_client" or such is sufficient and much clearer.

As far as the non-debug levels go, there isn't much choice.  ERROR and
above really needs to be communicated to the client anyway.  So you might
be able to tune which one of LOG, INFO, NOTICE goes where.  But that's
about all.

> > > Postmaster -d flag effects only postmaster message, not backend messages
> >
> > Why?
>
> This allows you to see postmaster connection-level debug stuff without
> the query debug stuff from the backend. If you want both, you have to
> set the postgres -d flag too.  Seemed clearer but I can remove it if
> people don't want it.

We had wanted to get rid of the discrepancy between postmaster and
postgres flag, not add new ones.

-- 
Peter Eisentraut   peter_e@gmx.net


Thu, 28 Feb 2002 14:20:08 -0500 (EST)
Peter Eisentraut <peter_e@gmx.net>
Re: elog() patch
Peter Eisentraut wrote:
> Bruce Momjian writes:
> 
> > Yes, but PANIC was chosen by vote, and it does match the kernel-level
> > description.
> 
> What is the kernel-level description?

Kernel stops, can't continue.  kernel panic.

> > > I doubt this idea.  NOTICE should really print to the client only.  This
> > > again comes down to the user-level errors vs. server-side errors issue.
> > > But INFO doesn't convey either of these meanings.
> >
> > We could call it TIP or something like that. I think INFO is used
> > because it isn't a NOTICE or ERROR or something major.  It is only INFO.
> > It is neutral information.
> 
> That's what NOTICE is.  NOTICE is only neutral information.  NOTICE could
> go to the client by default, whereas if you want something in the server
> log you use LOG.  I doubt an extra level is needed.

Notice isn't as neutral.  It is for truncation of long identifiers and
stuff like that.

> > > > New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
> > > > New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...
> > >
> > > Now that is *really* confusing.  Two different ways to number the same
> > > things.
> >
> > Sure is, but it was agreed to by the group discussing it as the cleanest
> > solution.  postgresql.conf has these levels documented, as does the SGML
> > docs.
> 
> I doubt that agreement.

Well, we discussed it on the lists, and no one objected after this
result was found.


> Consider, what and how much I want to debug is really quite independent of
> what amount of regular "neutral" messages I want to see where.  The latter
> is a rather permanent administrative decision, whereas the former is a
> temporary decision to isolate problems.  A "debug level" is really a
> universal concept in any package, and I hate to see it go.

Well, yes, but unless we want a really complicated setup, we may as well
just emit the neutral messages with the debug.  It has to be simple. 
There is usually one neutral message per query, if any, so I don't see
the point.


> Secondly, once I have decided how much debugging I want to do, it is
> unlikely that I want to do a different amount of debugging on the client
> and on the server.  I can see users becoming confused by this:  "I already
> set the debugging level to 5, but I still only see the same messages in
> the client".  I think that the current debug_level, plus a new Boolean
> setting "debug_to_client" or such is sufficient and much clearer.

I disagree.  The patch gives us clear control over the various levels. 
Tom wanted the DebugLvl variable stuff rolled into elog, and I think
this is a very clean solution.

I think Tom's point was that we want to control the independently, and
that is what this does.  I think it a valid use.

> As far as the non-debug levels go, there isn't much choice.  ERROR and
> above really needs to be communicated to the client anyway.  So you might
> be able to tune which one of LOG, INFO, NOTICE goes where.  But that's
> about all.

Yes, that is all the options you have for client, ERROR and below.

> > > > Postmaster -d flag effects only postmaster message, not backend messages
> > >
> > > Why?
> >
> > This allows you to see postmaster connection-level debug stuff without
> > the query debug stuff from the backend. If you want both, you have to
> > set the postgres -d flag too.  Seemed clearer but I can remove it if
> > people don't want it.
> 
> We had wanted to get rid of the discrepancy between postmaster and
> postgres flag, not add new ones.

We now separate them so they act independently.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Thu, 28 Feb 2002 16:35:05 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
> > Postmaster -d flag effects only postmaster message, not backend messages
> 
> Why?

OK, how about this?  What if we add a new GUC parameter,
postmaster_min_messages, and that controls the postmaster printing to
the server logs.  (Postmaster has no client to print to.)  Then, we can
propogate the -d flag to the backends, and if someone wants just
postmaster loggging, they can use the GUC parameter.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Thu, 28 Feb 2002 18:07:20 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch

OK, I have talked with Peter via phone and he is OK with the patch
assuming the changes I have outlined below.  This is not a total
overhaul of elog() but rather a major cleanup.  These changes are in the
direction of where we want to head.

Peter is also concerned if allowing clients to see elog() messages is a
security problem.  Clients can't see postmaster messages because there
is no client at the time, but backend messages will be visible.  I can't
think of any server log messages that shouldn't be seen by the client. 
Does anyone else?

> Here is a patch to clean up elog():
> 
> 	ftp://candle.pha.pa.us/pub/postgresql/mypatches/elog
> 
> Here is the detail:
> 
> 
> REALLYFATAL => PANIC
> STOP => PANIC
> New INFO level the prints to client by default
> New LOG level the prints to server log by default
> Cause VACUUM information to print only to the client in verbose mode
> VACUUM doesn't output to server logs
> NOTICE => INFO where purely information messages are sent
> DEBUG => LOG for purely server status messages
> DEBUG removed, kept as backward compatible (will be added near 7.3)
> DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1 added
> DebugLvl removed in favor of new DEBUG[1-5] symbols
> New server_min_messages GUC parameter with values DEBUG[5-1], INFO, LOG, ...
> New client_min_messages GUC parameter with values DEBUG[5-1], LOG, INFO, ...
> Server startup now logged with LOG instead of DEBUG
> Postmaster -d flag effects only postmaster message, not backend messages

Changed.  Postmaster -d propogates to backends, like current.  New -d 0
postgres parameter allows this propogation to be turned off.

> Remove debug_level GUC parameter
> elog() numbers now start at 10
> Add test to print error message if older elog() values are passed to elog()
> Bootstrap mode now has a -d that requires an argument, like postmaster

> This clears the -d debug level on backend start.  Is that done correctly?

I cleared this up with Peter.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Fri, 1 Mar 2002 00:00:23 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Peter is also concerned if allowing clients to see elog() messages is a
> security problem.  Clients can't see postmaster messages because there
> is no client at the time, but backend messages will be visible.  I can't
> think of any server log messages that shouldn't be seen by the client. 

The only thing I can think of is the detailed authorization-failure
messages that the postmaster has traditionally logged but not sent to
the client.  We need to be sure that the client cannot change that
behavior by setting PGOPTIONS.  I *think* this is OK, since client
options aren't processed till after the auth cycle finishes --- but
check it.  If you are using IsUnderPostmaster to control things then
you might have a problem, because that gets set too soon.

			regards, tom lane

Fri, 01 Mar 2002 00:46:29 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Peter is also concerned if allowing clients to see elog() messages is a
> > security problem.  Clients can't see postmaster messages because there
> > is no client at the time, but backend messages will be visible.  I can't
> > think of any server log messages that shouldn't be seen by the client. 
> 
> The only thing I can think of is the detailed authorization-failure
> messages that the postmaster has traditionally logged but not sent to
> the client.  We need to be sure that the client cannot change that
> behavior by setting PGOPTIONS.  I *think* this is OK, since client
> options aren't processed till after the auth cycle finishes --- but
> check it.  If you are using IsUnderPostmaster to control things then
> you might have a problem, because that gets set too soon.

Is this what you were looking for?  I set client_min_messages to the max
of debug5 and the output is attached.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

DEBUG:  ./bin/postmaster child[10023]: starting with (
DEBUG:  postgres 
DEBUG:  -v131072 
DEBUG:  -p 
DEBUG:  test 
DEBUG:  )

DEBUG:  InitPostgres
DEBUG:  StartTransactionCommand
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
Welcome to psql, the PostgreSQL interactive terminal.

Type:  \copyright for distribution terms
       \h for help with SQL commands
       \? for help on internal slash commands
       \g or terminate with semicolon to execute query
       \q to quit

test=> show client_min_messages;
DEBUG:  StartTransactionCommand
DEBUG:  ProcessUtility
INFO:  client_min_messages is debug5
DEBUG:  CommitTransactionCommand
SHOW VARIABLE
test=> \q
Sat, 2 Mar 2002 18:00:43 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Is this what you were looking for?  I set client_min_messages to the max
> of debug5 and the output is attached.

If the DBA wants to do that, I don't have a problem with it.  I'm
wondering what happens if an unprivileged user tries to do it,
via either PGOPTIONS or Peter's new user/database-local options.

Please note also that I'm wondering about the messages emitted during
an authorization *failure*, not a successful connection.

			regards, tom lane

Sat, 02 Mar 2002 18:19:54 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Is this what you were looking for?  I set client_min_messages to the max
> > of debug5 and the output is attached.
> 
> If the DBA wants to do that, I don't have a problem with it.  I'm
> wondering what happens if an unprivileged user tries to do it,
> via either PGOPTIONS or Peter's new user/database-local options.
> 
> Please note also that I'm wondering about the messages emitted during
> an authorization *failure*, not a successful connection.

You ask a very good question here.  I never tested authentication with
debug sent to the client.  The answer is that it doesn't work without
the attached patch.  Now, I am not about to apply this because it does
change getNotice() to an extern and moves its prototype to libpq-int.h. 
This is necessary because I now use getNotice() in fe-connect.c.

The second issue is that this isn't going to work for pre-7.2 clients
because the protocol doesn't expect 'N' messages during the
authentication phase.  I think we can live with a client_min_messages
level of debug* not working on old clients, though we should make a
mention of it in the release notes.

And finally, here is the output from a failed password login with the
patch applied:

	$ psql test
	Password: 
	DEBUG:  received password packet with len=12, pw=lkjasdf
	
	DEBUG:  received password packet with len=12, pw=lkjasdf
	
	psql: FATAL:  Password authentication failed for user "postgres"

Basically it echoes the failed password back to the user.  Again, this
is only with client_min_messages set to debug1-5.  I don't know how to
fix this because we specifically set things up so the client could see
everything the server logs see.  I wonder if echoing the failed password
into the logs is a good idea either.  I don't think so.

Someone please advise on patch application.  Are there other places that
don't expect a NOTICE in the middle of a protocol handshake?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Index: src/interfaces/libpq/fe-connect.c
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/fe-connect.c,v
retrieving revision 1.182
diff -c -r1.182 fe-connect.c
*** src/interfaces/libpq/fe-connect.c	2 Mar 2002 00:49:22 -0000	1.182
--- src/interfaces/libpq/fe-connect.c	3 Mar 2002 02:33:51 -0000
***************
*** 1296,1301 ****
--- 1296,1310 ----
  					return PGRES_POLLING_READING;
  				}
  
+ 				/* Grab NOTICE/INFO/DEBUG and discard them. */
+ 				while (beresp == 'N')
+ 				{
+ 					if (getNotice(conn))
+ 						return PGRES_POLLING_READING;
+ 					if (pqGetc(&beresp, conn))
+ 						return PGRES_POLLING_READING;
+ 				}
+ 
  				/* Handle errors. */
  				if (beresp == 'E')
  				{
***************
*** 1314,1319 ****
--- 1323,1337 ----
  					 */
  					appendPQExpBufferChar(&conn->errorMessage, '\n');
  					goto error_return;
+ 				}
+ 
+ 				/* Grab NOTICE/INFO/DEBUG and discard them. */
+ 				while (beresp == 'N')
+ 				{
+ 					if (getNotice(conn))
+ 						return PGRES_POLLING_READING;
+ 					if (pqGetc(&beresp, conn))
+ 						return PGRES_POLLING_READING;
  				}
  
  				/* Otherwise it should be an authentication request. */
Index: src/interfaces/libpq/fe-exec.c
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/fe-exec.c,v
retrieving revision 1.113
diff -c -r1.113 fe-exec.c
*** src/interfaces/libpq/fe-exec.c	25 Oct 2001 05:50:13 -0000	1.113
--- src/interfaces/libpq/fe-exec.c	3 Mar 2002 02:33:52 -0000
***************
*** 54,60 ****
  static int	getRowDescriptions(PGconn *conn);
  static int	getAnotherTuple(PGconn *conn, int binary);
  static int	getNotify(PGconn *conn);
- static int	getNotice(PGconn *conn);
  
  /* ---------------
   * Escaping arbitrary strings to get valid SQL strings/identifiers.
--- 54,59 ----
***************
*** 1379,1385 ****
   * Exit: returns 0 if successfully consumed Notice message.
   *		 returns EOF if not enough data.
   */
! static int
  getNotice(PGconn *conn)
  {
  	/*
--- 1378,1384 ----
   * Exit: returns 0 if successfully consumed Notice message.
   *		 returns EOF if not enough data.
   */
! int
  getNotice(PGconn *conn)
  {
  	/*
Index: src/interfaces/libpq/libpq-fe.h
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/libpq-fe.h,v
retrieving revision 1.80
diff -c -r1.80 libpq-fe.h
*** src/interfaces/libpq/libpq-fe.h	8 Nov 2001 20:37:52 -0000	1.80
--- src/interfaces/libpq/libpq-fe.h	3 Mar 2002 02:33:56 -0000
***************
*** 252,257 ****
--- 252,258 ----
  extern size_t PQescapeString(char *to, const char *from, size_t length);
  extern unsigned char *PQescapeBytea(unsigned char *bintext, size_t binlen,
  			  size_t *bytealen);
+ extern int	getNotice(PGconn *conn);
  
  /* Simple synchronous query */
  extern PGresult *PQexec(PGconn *conn, const char *query);
Sat, 2 Mar 2002 21:46:05 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
> Basically it echoes the failed password back to the user.  Again, this
> is only with client_min_messages set to debug1-5.  I don't know how to
> fix this because we specifically set things up so the client could see
> everything the server logs see.  I wonder if echoing the failed password
> into the logs is a good idea either.  I don't think so.

Crypt/MD5 authentication does output the password encrypted:

  DEBUG:  received password packet with len=40, pw=md515e315f11670d4ba385d0c1615476780

  DEBUG:  received password packet with len=40, pw=md515e315f11670d4ba385d0c1615476780

  psql: FATAL:  Password authentication failed for user "postgres"

However, I still don't think we should be echoing this to the server
logs or the client.  There is just little value to it and potential
problems, especially with 'password' authentication.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 00:08:41 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Here is a better patch I am inclined to apply.  I fixes the debug
messages during authentication problem in a cleaner way, and removes
password echo to server logs and client.

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

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > Is this what you were looking for?  I set client_min_messages to the max
> > > of debug5 and the output is attached.
> > 
> > If the DBA wants to do that, I don't have a problem with it.  I'm
> > wondering what happens if an unprivileged user tries to do it,
> > via either PGOPTIONS or Peter's new user/database-local options.
> > 
> > Please note also that I'm wondering about the messages emitted during
> > an authorization *failure*, not a successful connection.
> 
> You ask a very good question here.  I never tested authentication with
> debug sent to the client.  The answer is that it doesn't work without
> the attached patch.  Now, I am not about to apply this because it does
> change getNotice() to an extern and moves its prototype to libpq-int.h. 
> This is necessary because I now use getNotice() in fe-connect.c.
> 
> The second issue is that this isn't going to work for pre-7.2 clients
> because the protocol doesn't expect 'N' messages during the
> authentication phase.  I think we can live with a client_min_messages
> level of debug* not working on old clients, though we should make a
> mention of it in the release notes.
> 
> And finally, here is the output from a failed password login with the
> patch applied:
> 
> 	$ psql test
> 	Password: 
> 	DEBUG:  received password packet with len=12, pw=lkjasdf
> 	
> 	DEBUG:  received password packet with len=12, pw=lkjasdf
> 	
> 	psql: FATAL:  Password authentication failed for user "postgres"
> 
> Basically it echoes the failed password back to the user.  Again, this
> is only with client_min_messages set to debug1-5.  I don't know how to
> fix this because we specifically set things up so the client could see
> everything the server logs see.  I wonder if echoing the failed password
> into the logs is a good idea either.  I don't think so.
> 
> Someone please advise on patch application.  Are there other places that
> don't expect a NOTICE in the middle of a protocol handshake?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Index: src/backend/libpq/auth.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/libpq/auth.c,v
retrieving revision 1.76
diff -c -r1.76 auth.c
*** src/backend/libpq/auth.c	2 Mar 2002 21:39:25 -0000	1.76
--- src/backend/libpq/auth.c	3 Mar 2002 21:39:40 -0000
***************
*** 854,861 ****
  		return STATUS_EOF;
  	}
  
! 	elog(DEBUG5, "received password packet with len=%d, pw=%s\n",
! 		len, buf.data);
  
  	result = checkPassword(port, port->user, buf.data);
  	pfree(buf.data);
--- 854,861 ----
  		return STATUS_EOF;
  	}
  
! 	/* For security reasons, do not output contents of password packet */
! 	elog(DEBUG5, "received password packet");
  
  	result = checkPassword(port, port->user, buf.data);
  	pfree(buf.data);
Index: src/interfaces/libpq/fe-connect.c
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/fe-connect.c,v
retrieving revision 1.182
diff -c -r1.182 fe-connect.c
*** src/interfaces/libpq/fe-connect.c	2 Mar 2002 00:49:22 -0000	1.182
--- src/interfaces/libpq/fe-connect.c	3 Mar 2002 21:39:42 -0000
***************
*** 1296,1301 ****
--- 1296,1310 ----
  					return PGRES_POLLING_READING;
  				}
  
+ 				/* Grab NOTICE/INFO/DEBUG and discard them. */
+ 				while (beresp == 'N')
+ 				{
+ 					if (getNotice(conn))
+ 						return PGRES_POLLING_READING;
+ 					if (pqGetc(&beresp, conn))
+ 						return PGRES_POLLING_READING;
+ 				}
+ 
  				/* Handle errors. */
  				if (beresp == 'E')
  				{
Index: src/interfaces/libpq/fe-exec.c
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/fe-exec.c,v
retrieving revision 1.113
diff -c -r1.113 fe-exec.c
*** src/interfaces/libpq/fe-exec.c	25 Oct 2001 05:50:13 -0000	1.113
--- src/interfaces/libpq/fe-exec.c	3 Mar 2002 21:39:44 -0000
***************
*** 54,60 ****
  static int	getRowDescriptions(PGconn *conn);
  static int	getAnotherTuple(PGconn *conn, int binary);
  static int	getNotify(PGconn *conn);
- static int	getNotice(PGconn *conn);
  
  /* ---------------
   * Escaping arbitrary strings to get valid SQL strings/identifiers.
--- 54,59 ----
***************
*** 1379,1385 ****
   * Exit: returns 0 if successfully consumed Notice message.
   *		 returns EOF if not enough data.
   */
! static int
  getNotice(PGconn *conn)
  {
  	/*
--- 1378,1384 ----
   * Exit: returns 0 if successfully consumed Notice message.
   *		 returns EOF if not enough data.
   */
! int
  getNotice(PGconn *conn)
  {
  	/*
Index: src/interfaces/libpq/libpq-int.h
===================================================================
RCS file: /cvsroot/pgsql/src/interfaces/libpq/libpq-int.h,v
retrieving revision 1.44
diff -c -r1.44 libpq-int.h
*** src/interfaces/libpq/libpq-int.h	5 Nov 2001 17:46:38 -0000	1.44
--- src/interfaces/libpq/libpq-int.h	3 Mar 2002 21:39:44 -0000
***************
*** 305,310 ****
--- 305,311 ----
  extern void *pqResultAlloc(PGresult *res, size_t nBytes, bool isBinary);
  extern char *pqResultStrdup(PGresult *res, const char *str);
  extern void pqClearAsyncResult(PGconn *conn);
+ extern int	getNotice(PGconn *conn);
  
  /* === in fe-misc.c === */
Sun, 3 Mar 2002 17:27:00 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Here is a better patch I am inclined to apply.

Please do not ... I am about to commit a patch that fixes it properly,
ie, suppresses all non-error reports to the client during
authentication.  I do not think that we can assume that clients will
be prepared to handle notice messages in the auth cycle.

			regards, tom lane

Sun, 03 Mar 2002 17:38:35 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Here is a better patch I am inclined to apply.
> 
> Please do not ... I am about to commit a patch that fixes it properly,
> ie, suppresses all non-error reports to the client during
> authentication.  I do not think that we can assume that clients will
> be prepared to handle notice messages in the auth cycle.

OK, great.  Can you take care of the echo of entered password too, or I
will fix it once you are done?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 17:48:11 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Can you take care of the echo of entered password too,

I'm unconvinced that that's wrong, and will not change it without
more discussion.  (1) The reason it was put in was to allow debugging
of "that's the wrong password" mistakes.  (2) The postmaster log
inherently contains a great deal of sensitive information, so anyone
who runs with it world-readable has a problem already.  (3) The password
is not emitted unless the message level is a lot lower than anyone would
routinely use.  (4) If you're using the recommended MD5 encryption
approach, then what's logged is encrypted; it seems no more dangerous
than having encrypted passwords in pg_shadow.

			regards, tom lane

Sun, 03 Mar 2002 17:53:48 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Can you take care of the echo of entered password too,
> 
> I'm unconvinced that that's wrong, and will not change it without
> more discussion.  (1) The reason it was put in was to allow debugging
> of "that's the wrong password" mistakes.  (2) The postmaster log
> inherently contains a great deal of sensitive information, so anyone
> who runs with it world-readable has a problem already.  (3) The password
> is not emitted unless the message level is a lot lower than anyone would
> routinely use.  (4) If you're using the recommended MD5 encryption
> approach, then what's logged is encrypted; it seems no more dangerous
> than having encrypted passwords in pg_shadow.

That's a good point, particularly that MD5 echos the MD5 string and not
the actual password.  We can leave it and wait to see if anyone
complains.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 17:55:36 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Can you take care of the echo of entered password too,
> 
> I'm unconvinced that that's wrong, and will not change it without
> more discussion.  (1) The reason it was put in was to allow debugging
> of "that's the wrong password" mistakes.  (2) The postmaster log
> inherently contains a great deal of sensitive information, so anyone
> who runs with it world-readable has a problem already.  (3) The password
> is not emitted unless the message level is a lot lower than anyone would
> routinely use.  (4) If you're using the recommended MD5 encryption
> approach, then what's logged is encrypted; it seems no more dangerous
> than having encrypted passwords in pg_shadow.

I assume with your changes that the password will no longer be echoed to
the client on failure at debug5, right?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 18:04:47 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> I assume with your changes that the password will no longer be echoed to
> the client on failure at debug5, right?

Nope.

I've noticed a bunch of breakage with this patch at high (or is it low?)
debug output levels; for example client disconnection leaves this in the
log:
	DEBUG:  proc_exit(0)
	DEBUG:  shmem_exit(0)
	LOG:  pq_flush: send() failed: Broken pipe
	DEBUG:  exit(0)
	LOG:  pq_flush: send() failed: Bad file number
	DEBUG:  reaping dead processes
	DEBUG:  child process (pid 12462) exited with exit code 0
The problem is that elog is still trying to send stuff to the client
after client disconnection.  I propose to fix that by resetting
whereToSendOutput to None as soon as we detect client disconnect.

A more serious problem has to do with error reports for communication
problems, for example this fragment in pqcomm.c:

            /*
             * Careful: an elog() that tries to write to the client
             * would cause recursion to here, leading to stack overflow
             * and core dump!  This message must go *only* to the postmaster
             * log.  elog(LOG) is presently safe.
             */
            elog(LOG, "pq_recvbuf: recv() failed: %m");

elog(LOG) is NOT safe anymore :-(.

I am thinking of inventing an additional elog level, perhaps called
COMMERR, to be used specifically for reports of client communication
trouble.  This could be treated the same as LOG as far as output to
the server log goes, but we would hard-wire it to never be reported
to the client (for fear of recursive failure).

Comments?

BTW, I am also looking at normalizing all the backend/libpq reports
that look like
		snprintf(PQerrormsg, ...);
		fputs(PQerrormsg, stderr);
		pqdebug("%s", PQerrormsg);
to just use elog.  As-is this code is fairly broken since it doesn't
honor the syslog option.  Any objections?

			regards, tom lane

Sun, 03 Mar 2002 18:21:07 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > I assume with your changes that the password will no longer be echoed to
> > the client on failure at debug5, right?
> 
> Nope.
> 
> I've noticed a bunch of breakage with this patch at high (or is it low?)
> debug output levels; for example client disconnection leaves this in the
> log:
> 	DEBUG:  proc_exit(0)
> 	DEBUG:  shmem_exit(0)
> 	LOG:  pq_flush: send() failed: Broken pipe
> 	DEBUG:  exit(0)
> 	LOG:  pq_flush: send() failed: Bad file number
> 	DEBUG:  reaping dead processes
> 	DEBUG:  child process (pid 12462) exited with exit code 0
> The problem is that elog is still trying to send stuff to the client
> after client disconnection.  I propose to fix that by resetting
> whereToSendOutput to None as soon as we detect client disconnect.

That is exactly the solution I would recommend.  Clearly we are
stressing elog() and the client by forcing more information than we used
to.

> A more serious problem has to do with error reports for communication
> problems, for example this fragment in pqcomm.c:
> 
>             /*
>              * Careful: an elog() that tries to write to the client
>              * would cause recursion to here, leading to stack overflow
>              * and core dump!  This message must go *only* to the postmaster
>              * log.  elog(LOG) is presently safe.
>              */
>             elog(LOG, "pq_recvbuf: recv() failed: %m");
> 
> elog(LOG) is NOT safe anymore :-(.

Sure isn't.  We know we can always output to the server logs, but not
always to the client.


> I am thinking of inventing an additional elog level, perhaps called
> COMMERR, to be used specifically for reports of client communication
> trouble.  This could be treated the same as LOG as far as output to
> the server log goes, but we would hard-wire it to never be reported
> to the client (for fear of recursive failure).
> 
> Comments?

Couldn't we just set whereToSendOutput to None to fix this, or is there
a sense that we may be able to send messages later.

If needed, we can put COMMERR into the existing numbering.  I would be
glad to add it for you if you wish.  There would be no mention of it in
the docs because it is just like LOG but only to server logs.

> BTW, I am also looking at normalizing all the backend/libpq reports
> that look like
> 		snprintf(PQerrormsg, ...);
> 		fputs(PQerrormsg, stderr);
> 		pqdebug("%s", PQerrormsg);
> to just use elog.  As-is this code is fairly broken since it doesn't
> honor the syslog option.  Any objections?

Yes, I never liked this stuff.  Please remove it.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 18:27:43 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
>> I am thinking of inventing an additional elog level, perhaps called
>> COMMERR, to be used specifically for reports of client communication
>> trouble.  This could be treated the same as LOG as far as output to
>> the server log goes, but we would hard-wire it to never be reported
>> to the client (for fear of recursive failure).

> Couldn't we just set whereToSendOutput to None to fix this, or is there
> a sense that we may be able to send messages later.

We might as well just do proc_exit() as do that: once you reset
whereToSendOutput, you are effectively done talking to the client
(because SELECT won't send results to the client anymore).  The
errors that libpq notices might or might not be hard failures, but
I don't want to take the approach of changing global state in order
to report them.

			regards, tom lane

Sun, 03 Mar 2002 18:40:13 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> >> I am thinking of inventing an additional elog level, perhaps called
> >> COMMERR, to be used specifically for reports of client communication
> >> trouble.  This could be treated the same as LOG as far as output to
> >> the server log goes, but we would hard-wire it to never be reported
> >> to the client (for fear of recursive failure).
> 
> > Couldn't we just set whereToSendOutput to None to fix this, or is there
> > a sense that we may be able to send messages later.
> 
> We might as well just do proc_exit() as do that: once you reset
> whereToSendOutput, you are effectively done talking to the client
> (because SELECT won't send results to the client anymore).  The
> errors that libpq notices might or might not be hard failures, but
> I don't want to take the approach of changing global state in order
> to report them.

Oh, I thought whereToSendOutput only affected elog().  I now see it is
used in many places.  Sure new log-only code is fine.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Sun, 3 Mar 2002 18:42:17 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Can you take care of the echo of entered password too,
> 
> I'm unconvinced that that's wrong, and will not change it without
> more discussion.  (1) The reason it was put in was to allow debugging
> of "that's the wrong password" mistakes.  (2) The postmaster log
> inherently contains a great deal of sensitive information, so anyone
> who runs with it world-readable has a problem already.  (3) The password
> is not emitted unless the message level is a lot lower than anyone would
> routinely use.  (4) If you're using the recommended MD5 encryption
> approach, then what's logged is encrypted; it seems no more dangerous
> than having encrypted passwords in pg_shadow.

OK, I have thought about how we display invalid passwords in the server
logs.  This isn't an issue if the password is the same as stored in
pg_shadow.  However, if the invalid password was incorrect because it
was their Unix password or a password on another machine, I think we do
have an issue storing it in the server logs.  I can't think of any unix
utility that stores invalid passwords in the log, no matter what the
debugging level, and I don't think we should be doing it either.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Tue, 5 Mar 2002 01:43:43 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> OK, I have thought about how we display invalid passwords in the server
> logs.  This isn't an issue if the password is the same as stored in
> pg_shadow.  However, if the invalid password was incorrect because it
> was their Unix password or a password on another machine, I think we do
> have an issue storing it in the server logs.

Good point.  Okay, yank it out ...

			regards, tom lane

Tue, 05 Mar 2002 01:47:57 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: elog() patch 
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > OK, I have thought about how we display invalid passwords in the server
> > logs.  This isn't an issue if the password is the same as stored in
> > pg_shadow.  However, if the invalid password was incorrect because it
> > was their Unix password or a password on another machine, I think we do
> > have an issue storing it in the server logs.
> 
> Good point.  Okay, yank it out ...

Done.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 853-3000
  +  If your life is a hard drive,     |  830 Blythe Avenue
  +  Christ can be your backup.        |  Drexel Hill, Pennsylvania 19026

Tue, 5 Mar 2002 01:52:02 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: elog() patch