pgsql: Unified logging system for command-line programs

Started by Peter Eisentrautalmost 7 years ago10 messages

peter@eisentraut.org

almost 7 years ago

Unified logging system for command-line programs

This unifies the various ad hoc logging (message printing, error
printing) systems used throughout the command-line programs.

Features:

- Program name is automatically prefixed.

- Message string does not end with newline. This removes a common
source of inconsistencies and omissions.

- Additionally, a final newline is automatically stripped, simplifying
use of PQerrorMessage() etc., another common source of mistakes.

- I converted error message strings to use %m where possible.

- As a result of the above several points, more translatable message
strings can be shared between different components and between
frontends and backend, without gratuitous punctuation or whitespace
differences.

- There is support for setting a "log level". This is not meant to be
user-facing, but can be used internally to implement debug or
verbose modes.

- Lazy argument evaluation, so no significant overhead if logging at
some level is disabled.

- Some color in the messages, similar to gcc and clang. Set
PG_COLOR=auto to try it out. Some colors are predefined, but can be
customized by setting PG_COLORS.

- Common files (common/, fe_utils/, etc.) can handle logging much more
simply by just using one API without worrying too much about the
context of the calling program, requiring callbacks, or having to
pass "progname" around everywhere.

- Some programs called setvbuf() to make sure that stderr is
unbuffered, even on Windows. But not all programs did that. This
is now done centrally.

Soft goals:

- Reduces vertical space use and visual complexity of error reporting
in the source code.

- Encourages more deliberate classification of messages. For example,
in some cases it wasn't clear without analyzing the surrounding code
whether a message was meant as an error or just an info.

- Concepts and terms are vaguely aligned with popular logging
frameworks such as log4j and Python logging.

This is all just about printing stuff out. Nothing affects program
flow (e.g., fatal exits). The uses are just too varied to do that.
Some existing code had wrappers that do some kind of print-and-exit,
and I adapted those.

I tried to keep the output mostly the same, but there is a lot of
historical baggage to unwind and special cases to consider, and I
might not always have succeeded. One significant change is that
pg_rewind used to write all error messages to stdout. That is now
changed to stderr.

Reviewed-by: Donald Dong <xdong@csumb.edu>
Reviewed-by: Arthur Zakirov <a.zakirov@postgrespro.ru>
Discussion: /messages/by-id/6a609b43-4f57-7348-6480-bd022f924310@2ndquadrant.com

Branch
------
master

Details
-------
https://git.postgresql.org/pg/commitdiff/cc8d41511721d25d557fc02a46c053c0a602fed0

Christoph Berg

myon@debian.org

almost 7 years ago

In reply to: Peter Eisentraut (#1)

PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

Re: Peter Eisentraut 2019-04-01 <E1hB1d6-00051m-1s@gemulon.postgresql.org>

- Some color in the messages, similar to gcc and clang. Set
PG_COLOR=auto to try it out. Some colors are predefined, but can be
customized by setting PG_COLORS.

Can we rename PG_COLOR to PGCOLOR? This is the only PG* environment
variable prefixed with the extra underscore, and remembering that will
be confusing. (Like pgbench should really be named pg_bench for
consistency.) Even if it's not a libpq variable, but that's an
implementation detail that users shouldn't have to worry about.

From reindexdb(1):

NAME
reindexdb - reindex a PostgreSQL database

ENVIRONMENT
PGDATABASE
PGHOST
PGPORT
PGUSER
Default connection parameters

PG_COLOR
Specifies whether to use color in diagnostics messages. Possible values are always, auto, never.

Also, why doesn't this default to 'auto'? Lots of programs have moved
to using colors by default over the last years, including git and gcc.

Christoph

Peter Eisentraut

peter.eisentraut@2ndquadrant.com

almost 7 years ago

In reply to: Christoph Berg (#2)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

On 2019-04-09 11:22, Christoph Berg wrote:

Can we rename PG_COLOR to PGCOLOR? This is the only PG* environment
variable prefixed with the extra underscore, and remembering that will
be confusing. (Like pgbench should really be named pg_bench for
consistency.) Even if it's not a libpq variable, but that's an
implementation detail that users shouldn't have to worry about.

I'm okay with changing it. As you indicate, I chose the name so that it
doesn't look like a libpq variable. There are some other PG_ variables
throughout the code, but those appear to be mostly for internal use.
Also, there is GCC_COLORS, LS_COLORS, etc. But perhaps this wisdom will
be lost on users who just read the man page and get confused. ;-)

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Christoph Berg

myon@debian.org

almost 7 years ago

In reply to: Peter Eisentraut (#1)

Re: pgsql: Unified logging system for command-line programs

Re: Peter Eisentraut 2019-04-01 <E1hB1d6-00051m-1s@gemulon.postgresql.org>

- There is support for setting a "log level". This is not meant to be
user-facing, but can be used internally to implement debug or
verbose modes.

I'm not entirely sure what happened here, but I think this made
pg_restore verbose by default (and there is no --quiet option).
At least that's what the apt.pg.o upgrade regression tests say for
11->12:

09:12:49 ok 59 - pg_upgradecluster reported successful operation
09:12:49 not ok 60 - no error messages during upgrade
09:12:49 # Failed test 'no error messages during upgrade'
09:12:49 # at ./t/040_upgrade.t line 160.
09:12:49 pg_restore: connecting to database for restore
09:12:49 pg_restore: executing BLOB 1234
09:12:49 pg_restore: disabling triggers for tstab
09:12:49 pg_restore: processing data for table "public.tstab"
09:12:49 pg_restore: enabling triggers for tstab
09:12:49 pg_restore: processing BLOBS
09:12:49 pg_restore: restoring large object with OID 1234
09:12:49 pg_restore: restored 1 large object
09:12:49 pg_restore: connecting to database for restore
09:12:49 pg_restore: connecting to database for restore
09:12:49 pg_restore: disabling triggers for nums
09:12:49 pg_restore: processing data for table "public.nums"
09:12:49 pg_restore: enabling triggers for nums
09:12:49 pg_restore: connecting to database for restore
09:12:49 pg_restore: connecting to database for restore
09:12:49 pg_restore: disabling triggers for old
09:12:49 pg_restore: processing data for table "old.old"
09:12:49 pg_restore: enabling triggers for old
09:12:49 pg_restore: disabling triggers for phone
09:12:49 pg_restore: processing data for table "public.phone"
09:12:49 pg_restore: enabling triggers for phone
09:12:49 pg_restore: executing SEQUENCE SET odd10ok 61 - pg_lsclusters -h
09:12:49 ok 62 - pg_lsclusters output

https://pgdgbuild.dus.dg-i.net/view/Testsuite/job/upgrade-11-12/lastFailedBuild/architecture=amd64,distribution=sid/console

The code running there is:

print 'Upgrading database ', $db, "...\n";
open SOURCE, '-|', $pg_dump, '-h', $oldsocket, '-p', $info{'port'},
'-Fc', '--quote-all-identifiers', $db or
error 'Could not execute pg_dump for old cluster';

# start pg_restore and copy over everything
my @restore_argv = ($pg_restore, '-h', $newsocket, '-p',
$newinfo{'port'}, '--data-only', '-d', $db,
'--disable-triggers', '--no-data-for-failed-tables');
open SINK, '|-', @restore_argv or
error 'Could not execute pg_restore for new cluster';

https://salsa.debian.org/postgresql/postgresql-common/blob/master/pg_upgradecluster#L511-521

Christoph

Christoph Berg

myon@debian.org

almost 7 years ago

In reply to: Peter Eisentraut (#3)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

Re: Peter Eisentraut 2019-04-09 <d483cdb6-db98-9b2f-7f2b-eed0f4bd975d@2ndquadrant.com>

I'm okay with changing it. As you indicate, I chose the name so that it
doesn't look like a libpq variable. There are some other PG_ variables
throughout the code, but those appear to be mostly for internal use.
Also, there is GCC_COLORS, LS_COLORS, etc. But perhaps this wisdom will
be lost on users who just read the man page and get confused. ;-)

Do we need two variables to control this? I was only looking at
PG_COLOR, and noticed PG_COLORS only later. Keeping PG_COLORS aligned
with {GCC,LS}_COLORS makes sense. How about removing PG_COLOR, and
making "auto" the default? (Maybe we could still support "PG_COLORS=off")

Christoph

Peter Eisentraut

peter.eisentraut@2ndquadrant.com

almost 7 years ago

In reply to: Christoph Berg (#4)

Re: pgsql: Unified logging system for command-line programs

On 2019-04-09 13:58, Christoph Berg wrote:

I'm not entirely sure what happened here, but I think this made
pg_restore verbose by default (and there is no --quiet option).

That was by accident. Fixed.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Masahiko Sawada

sawada.mshk@gmail.com

over 6 years ago

In reply to: Christoph Berg (#5)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

On Tue, Apr 9, 2019 at 9:01 PM Christoph Berg <myon@debian.org> wrote:

Re: Peter Eisentraut 2019-04-09 <d483cdb6-db98-9b2f-7f2b-eed0f4bd975d@2ndquadrant.com>

I'm okay with changing it. As you indicate, I chose the name so that it
doesn't look like a libpq variable. There are some other PG_ variables
throughout the code, but those appear to be mostly for internal use.
Also, there is GCC_COLORS, LS_COLORS, etc. But perhaps this wisdom will
be lost on users who just read the man page and get confused. ;-)

Do we need two variables to control this? I was only looking at
PG_COLOR, and noticed PG_COLORS only later. Keeping PG_COLORS aligned
with {GCC,LS}_COLORS makes sense. How about removing PG_COLOR, and
making "auto" the default? (Maybe we could still support "PG_COLORS=off")

I think the if we keep two variables user can set the same value to
both GCC_COLORS and PG_COLORS. Rather I think it's a problem that
there is no documentation of PG_COLORS. Thoughts?

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Peter Eisentraut

peter.eisentraut@2ndquadrant.com

over 6 years ago

In reply to: Masahiko Sawada (#7)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

On 2019-06-06 11:08, Masahiko Sawada wrote:

On Tue, Apr 9, 2019 at 9:01 PM Christoph Berg <myon@debian.org> wrote:

Re: Peter Eisentraut 2019-04-09 <d483cdb6-db98-9b2f-7f2b-eed0f4bd975d@2ndquadrant.com>

I'm okay with changing it. As you indicate, I chose the name so that it
doesn't look like a libpq variable. There are some other PG_ variables
throughout the code, but those appear to be mostly for internal use.
Also, there is GCC_COLORS, LS_COLORS, etc. But perhaps this wisdom will
be lost on users who just read the man page and get confused. ;-)

Do we need two variables to control this? I was only looking at
PG_COLOR, and noticed PG_COLORS only later. Keeping PG_COLORS aligned
with {GCC,LS}_COLORS makes sense. How about removing PG_COLOR, and
making "auto" the default? (Maybe we could still support "PG_COLORS=off")

I think the if we keep two variables user can set the same value to
both GCC_COLORS and PG_COLORS. Rather I think it's a problem that
there is no documentation of PG_COLORS. Thoughts?

It looks like there is documentation for PG_COLORS in the release notes
now, which seems like an odd place. Suggestions for a better place?

And any more opinions for PG_COLORS vs PGCOLORS naming?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Tom Lane

tgl@sss.pgh.pa.us

over 6 years ago

In reply to: Peter Eisentraut (#8)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:

On 2019-06-06 11:08, Masahiko Sawada wrote:

Do we need two variables to control this? I was only looking at
PG_COLOR, and noticed PG_COLORS only later. Keeping PG_COLORS aligned
with {GCC,LS}_COLORS makes sense. How about removing PG_COLOR, and
making "auto" the default? (Maybe we could still support "PG_COLORS=off")

I think the if we keep two variables user can set the same value to
both GCC_COLORS and PG_COLORS. Rather I think it's a problem that
there is no documentation of PG_COLORS. Thoughts?

It looks like there is documentation for PG_COLORS in the release notes
now, which seems like an odd place. Suggestions for a better place?

I stuck that in because Bruce's text didn't make any sense to me,
so I went and read the code to see what it was actually doing.
I didn't know that it hadn't been correctly documented in the first
place ;-)

I'm not for forcing "auto" mode all the time; that will surely break
things for some people. So I think the behavior is fine and
we should just fix the docs. (Possibly my opinion is biased here
by the fact that I hate all forms of colorized output with a deep,
abiding passion, as Robert would put it. So off-by-default is just
fine with me.)

And any more opinions for PG_COLORS vs PGCOLORS naming?

Following the precedent of LS_COLORS makes sense from here.

regards, tom lane

#10

Tom Lane

tgl@sss.pgh.pa.us

over 6 years ago

In reply to: Peter Eisentraut (#8)

Re: PGCOLOR? (Re: pgsql: Unified logging system for command-line programs)

Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:

It looks like there is documentation for PG_COLORS in the release notes
now, which seems like an odd place. Suggestions for a better place?

BTW, as far as that goes, it looks like PG_COLOR is documented separately
in each frontend program's "Environment" man page section. That's a bit
duplicative but I don't think we have a better answer right now. Seems
like you just need to add boilerplate text about PG_COLORS alongside
each of those.

regards, tom lane