pg_rewind and log messages

Started by Fujii Masaoabout 11 years ago14 messageshackers
Jump to latest
#1Fujii Masao
masao.fujii@gmail.com

Hi,

I found that pg_rewind has several problems about its log messages.

(1)
It outputs an error message to stdout not stderr.

(2)
The tool name should be added at the head of log message as follows,
but not in pg_rewind.

pg_basebackup: no target directory specified

(3)

if (datadir_source == NULL && connstr_source == NULL)
{
pg_fatal("no source specified (--source-pgdata or --source-server)\n");
pg_fatal("Try \"%s --help\" for more information.\n", progname);
exit(1);

Since the first call of pg_fatal exits with 1, the subsequent pg_fatal and exit
will never be called.

(4)
ISTM that set_pglocale_pgservice() needs to be called, but not in pg_rewind.

(5)
printf() is used to output an error in some files, e.g., timeline.c and
parsexlog.c. These printf() should be replaced with pg_log or pg_fatal?

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#2Michael Paquier
michael@paquier.xyz
In reply to: Fujii Masao (#1)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 12:57 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

(1)
It outputs an error message to stdout not stderr.
(2)
The tool name should be added at the head of log message as follows,
but not in pg_rewind.

pg_basebackup: no target directory specified

Agreed. That's inconsistent.

(3)

if (datadir_source == NULL && connstr_source == NULL)
{
pg_fatal("no source specified (--source-pgdata or --source-server)\n");
pg_fatal("Try \"%s --help\" for more information.\n", progname);
exit(1);

Since the first call of pg_fatal exits with 1, the subsequent pg_fatal and exit
will never be called.

True.

(4)
ISTM that set_pglocale_pgservice() needs to be called, but not in pg_rewind.

True. I think that we should consider a call to get_restricted_token()
as well now that I look at it.

(5)
printf() is used to output an error in some files, e.g., timeline.c and
parsexlog.c. These printf() should be replaced with pg_log or pg_fatal?

On top of that, datapagemap.c has a debug message as well using
printf, as well as filemap.c in print_filemap().

I guess that you are working on a patch? If not, you are looking for one?
Regards,
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#3Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#2)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 1:41 PM, Michael Paquier wrote:

I guess that you are working on a patch? If not, you are looking for one?

Code-speaking, this gives the patch attached. I eliminated a bunch of
newlines in the log messages that seemed really unnecessary to me,
simplifying a bit the whole. While hacking this stuff, I noticed as
well that pg_rewind could be called as root on non-Windows platform,
that's dangerous from a security point of view as process manipulates
files in PGDATA. Hence let's block that. On Windows, a restricted
token should be used.
Regards,
--
Michael

Attachments:

0001-Fix-inconsistent-error-and-process-handling-in-pg_re.patchtext/x-patch; charset=US-ASCII; name=0001-Fix-inconsistent-error-and-process-handling-in-pg_re.patchDownload+144-139
#4Fujii Masao
masao.fujii@gmail.com
In reply to: Michael Paquier (#3)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 5:33 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Mon, Apr 6, 2015 at 1:41 PM, Michael Paquier wrote:

I guess that you are working on a patch? If not, you are looking for one?

Code-speaking, this gives the patch attached.

Thanks! Here are the review comments:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

         case PG_FATAL:
-            printf("\n%s", _(message));
-            printf("%s", _("Failure, exiting\n"));
+            fprintf(stderr, _("\n%s: fatal: %s\n"), progname, message);
+            fprintf(stderr, _("Failure, exiting\n"));

Why do we need to output the error level like fatal? This seems also
inconsistent with the log message policy of other tools.

Why do we need to output \n at the head of the message?

The second message "Failure, exiting" is really required?

I eliminated a bunch of
newlines in the log messages that seemed really unnecessary to me,
simplifying a bit the whole. While hacking this stuff, I noticed as
well that pg_rewind could be called as root on non-Windows platform,
that's dangerous from a security point of view as process manipulates
files in PGDATA. Hence let's block that. On Windows, a restricted
token should be used.

Good catch! I think it's better to implement it as a separate patch
because it's very different from log message problem.

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#5Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Fujii Masao (#4)
Re: pg_rewind and log messages

Fujii Masao wrote:

On Mon, Apr 6, 2015 at 5:33 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Mon, Apr 6, 2015 at 1:41 PM, Michael Paquier wrote:

I guess that you are working on a patch? If not, you are looking for one?

Code-speaking, this gives the patch attached.

Thanks! Here are the review comments:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

It's not necessary for pg_fatal and the like, because those functions
are marked to have their first argument automatically translated in
nls.mk. This means that the string literal is automatically extracted
into pg_rewind.pot for translators. Of course, the function itself must
call _() (or some variant thereof) to actually fetch the translated
string at run time.

I'm not sure about translation of generic strings such as "%s: %s". My
first impression is that they shouldn't be translated, but maybe it is
important that they are for languages I don't know nothing about such as
Japanese.

Another thing is compound messages like "foo has happened\nSee --help
for usage.\n" and "bar didn't happen\.See --help for usage". In those
cases, the "see --help" part would need to be translated over and over,
so it's best to separate them in phrases to avoid repetitive work for
translators. Not sure how to do this -- maybe something like
_("foo has happened\n") _("See --help")
but I'm not sure how to appease the compiler. Having them in two
separate pg_log() calls (or whatever) was handy for this reason.

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#6Michael Paquier
michael@paquier.xyz
In reply to: Alvaro Herrera (#5)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 10:01 PM, Alvaro Herrera wrote:

I'm not sure about translation of generic strings such as "%s: %s". My
first impression is that they shouldn't be translated, but maybe it is
important that they are for languages I don't know nothing about such as
Japanese.

I misunderstood things here, pg_fatal and others should not use _()
directly for generic strings. It seems like an overkill.

Another thing is compound messages like "foo has happened\nSee --help
for usage.\n" and "bar didn't happen\.See --help for usage". In those
cases, the "see --help" part would need to be translated over and over,
so it's best to separate them in phrases to avoid repetitive work for
translators. Not sure how to do this -- maybe something like
_("foo has happened\n") _("See --help")
but I'm not sure how to appease the compiler. Having them in two
separate pg_log() calls (or whatever) was handy for this reason.

OK, let's switch to two calls to pg_log or similar in those cases to
make the life of translators easier.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#7Michael Paquier
michael@paquier.xyz
In reply to: Fujii Masao (#4)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 9:10 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

I think I addressed those things...

case PG_FATAL:
-            printf("\n%s", _(message));
-            printf("%s", _("Failure, exiting\n"));
+            fprintf(stderr, _("\n%s: fatal: %s\n"), progname, message);
+            fprintf(stderr, _("Failure, exiting\n"));

Why do we need to output the error level like fatal? This seems also
inconsistent with the log message policy of other tools.

initdb and psql do not for a couple of warning messages, but perhaps I
am just taking consistency with the original code too seriously.

Why do we need to output \n at the head of the message?
The second message "Failure, exiting" is really required?

I think that those things were here to highlight the fact that this is
a fatal bailout, but the error code would help the same way I guess...

I eliminated a bunch of
newlines in the log messages that seemed really unnecessary to me,
simplifying a bit the whole. While hacking this stuff, I noticed as
well that pg_rewind could be called as root on non-Windows platform,
that's dangerous from a security point of view as process manipulates
files in PGDATA. Hence let's block that. On Windows, a restricted
token should be used.

Good catch! I think it's better to implement it as a separate patch
because it's very different from log message problem.

Attached are new patches:
- 0001 fixes the restriction issues: restricted token on Windows, and
forbid non-root user on non-Windows.
- 0002 includes the improvements for logging, addressing the comments above.

Regards,
--
Michael

Attachments:

0001-Fix-process-handling-of-pg_rewind.patchtext/x-patch; charset=US-ASCII; name=0001-Fix-process-handling-of-pg_rewind.patchDownload+16-1
0002-Fix-inconsistent-handling-of-logs-in-pg_rewind.patchtext/x-patch; charset=US-ASCII; name=0002-Fix-inconsistent-handling-of-logs-in-pg_rewind.patchDownload+122-129
#8Fujii Masao
masao.fujii@gmail.com
In reply to: Alvaro Herrera (#5)
Re: pg_rewind and log messages

On Mon, Apr 6, 2015 at 10:01 PM, Alvaro Herrera
<alvherre@2ndquadrant.com> wrote:

Fujii Masao wrote:

On Mon, Apr 6, 2015 at 5:33 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Mon, Apr 6, 2015 at 1:41 PM, Michael Paquier wrote:

I guess that you are working on a patch? If not, you are looking for one?

Code-speaking, this gives the patch attached.

Thanks! Here are the review comments:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

It's not necessary for pg_fatal and the like, because those functions
are marked to have their first argument automatically translated in
nls.mk. This means that the string literal is automatically extracted
into pg_rewind.pot for translators. Of course, the function itself must
call _() (or some variant thereof) to actually fetch the translated
string at run time.

Understood. Thanks!

BTW, as far as I read pg_rewind's nls.mk correctly, it also has two problems.

(1) file_ops.c should be added into GETTEXT_FILES.
(2) pg_log should be pg_log:2 in GETTEXT_TRIGGERS

Another thing is compound messages like "foo has happened\nSee --help
for usage.\n" and "bar didn't happen\.See --help for usage". In those
cases, the "see --help" part would need to be translated over and over,
so it's best to separate them in phrases to avoid repetitive work for
translators. Not sure how to do this -- maybe something like
_("foo has happened\n") _("See --help")
but I'm not sure how to appease the compiler. Having them in two
separate pg_log() calls (or whatever) was handy for this reason.

Yep.

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#9Fujii Masao
masao.fujii@gmail.com
In reply to: Michael Paquier (#7)
Re: pg_rewind and log messages

On Tue, Apr 7, 2015 at 11:59 AM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Mon, Apr 6, 2015 at 9:10 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

I think I addressed those things...

case PG_FATAL:
-            printf("\n%s", _(message));
-            printf("%s", _("Failure, exiting\n"));
+            fprintf(stderr, _("\n%s: fatal: %s\n"), progname, message);
+            fprintf(stderr, _("Failure, exiting\n"));

Why do we need to output the error level like fatal? This seems also
inconsistent with the log message policy of other tools.

initdb and psql do not for a couple of warning messages, but perhaps I
am just taking consistency with the original code too seriously.

Why do we need to output \n at the head of the message?
The second message "Failure, exiting" is really required?

I think that those things were here to highlight the fact that this is
a fatal bailout, but the error code would help the same way I guess...

I eliminated a bunch of
newlines in the log messages that seemed really unnecessary to me,
simplifying a bit the whole. While hacking this stuff, I noticed as
well that pg_rewind could be called as root on non-Windows platform,
that's dangerous from a security point of view as process manipulates
files in PGDATA. Hence let's block that. On Windows, a restricted
token should be used.

Good catch! I think it's better to implement it as a separate patch
because it's very different from log message problem.

Attached are new patches:
- 0001 fixes the restriction issues: restricted token on Windows, and
forbid non-root user on non-Windows.

Thanks for the patch! I'd like to push this patch at first. But one comment is

+ "You must run %s as the PostgreSQL superuser.\n",

Isn't the term "PostgreSQL superuser" confusing? I'm afraid that a user might
confuse "PostgreSQL superuser" with a database superuser. I see you just
borrowed that term from pg_resetxlog.c, though. BTW, initdb and pg_ctl also
have the same check and the error message is as follows. Isn't this better?
Thought?

("%s: cannot be run as root\n"
"Please log in (using, e.g., \"su\") as the "
"(unprivileged) user that will\n"
"own the server process.\n

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#10Michael Paquier
michael@paquier.xyz
In reply to: Fujii Masao (#8)
Re: pg_rewind and log messages

On Tue, Apr 7, 2015 at 4:16 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

On Mon, Apr 6, 2015 at 10:01 PM, Alvaro Herrera
<alvherre@2ndquadrant.com> wrote:

Fujii Masao wrote:

On Mon, Apr 6, 2015 at 5:33 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Mon, Apr 6, 2015 at 1:41 PM, Michael Paquier wrote:

I guess that you are working on a patch? If not, you are looking for one?

Code-speaking, this gives the patch attached.

Thanks! Here are the review comments:

I'm not familiar with native language support (sorry), but don't we need to
add the shortcut of gettext into every calls of pg_log and pg_fatal, e.g.,
change pg_fatal("xxx") to pg_fatal(_("xxx"))? I know that fprintf() in
pg_Log_v() has such shortcut, but I'm not sure if that's enough or not.

It's not necessary for pg_fatal and the like, because those functions
are marked to have their first argument automatically translated in
nls.mk. This means that the string literal is automatically extracted
into pg_rewind.pot for translators. Of course, the function itself must
call _() (or some variant thereof) to actually fetch the translated
string at run time.

Understood. Thanks!

BTW, as far as I read pg_rewind's nls.mk correctly, it also has two problems.

(1) file_ops.c should be added into GETTEXT_FILES.

And ../../common/restricted_tokens.c.

(2) pg_log should be pg_log:2 in GETTEXT_TRIGGERS

Seems so.
--
Michael

Attachments:

0001-Fix-process-handling-of-pg_rewind.patchtext/x-patch; charset=US-ASCII; name=0001-Fix-process-handling-of-pg_rewind.patchDownload+18-2
0002-Fix-inconsistent-handling-of-logs-in-pg_rewind.patchtext/x-patch; charset=US-ASCII; name=0002-Fix-inconsistent-handling-of-logs-in-pg_rewind.patchDownload+125-133
#11Michael Paquier
michael@paquier.xyz
In reply to: Fujii Masao (#9)
Re: pg_rewind and log messages

On Tue, Apr 7, 2015 at 4:33 PM, Fujii Masao wrote:

Isn't the term "PostgreSQL superuser" confusing? I'm afraid that a user might
confuse "PostgreSQL superuser" with a database superuser. I see you just
borrowed that term from pg_resetxlog.c, though. BTW, initdb and pg_ctl also
have the same check and the error message is as follows. Isn't this better?
Thought?

("%s: cannot be run as root\n"
"Please log in (using, e.g., \"su\") as the "
"(unprivileged) user that will\n"
"own the server process.\n

I'm fine with that as well. Why not updating the message of
pg_resetxlog as well then? It would be good to be consistent.

I guess that the call to set_pglocale_pgservice() should be added as
well in the first patch (see last version upthread), this has nothing
to do with the logging issues.
--
Michael

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#12Heikki Linnakangas
heikki.linnakangas@enterprisedb.com
In reply to: Michael Paquier (#7)
Re: pg_rewind and log messages

On 04/07/2015 05:59 AM, Michael Paquier wrote:

On Mon, Apr 6, 2015 at 9:10 PM, Fujii Masao <masao.fujii@gmail.com> wrote:

I eliminated a bunch of newlines in the log messages that seemed
really unnecessary to me, simplifying a bit the whole.

So the patch removed the newlines from the error messages, and added the
newline into pg_fatal/log instead. Perhaps that's good idea, but it's
not actually consistent with what we do in other utilities in src/bin.
See write_msg() and exit_horribly() in pg_dump, write_stderr() in
pg_ctl, and psql_error() in psql. If we want to change that in pg_rewind
(IMHO we shouldn't), let's do that as a completely separate patch.

While hacking this stuff, I noticed as

well that pg_rewind could be called as root on non-Windows platform,
that's dangerous from a security point of view as process manipulates
files in PGDATA. Hence let's block that. On Windows, a restricted
token should be used.

Good catch! I think it's better to implement it as a separate patch
because it's very different from log message problem.

Attached are new patches:
- 0001 fixes the restriction issues: restricted token on Windows, and
forbid non-root user on non-Windows.

Committed this one.

- 0002 includes the improvements for logging, addressing the comments above.

This is a bit of a mixed bag. I'll comment on the three points from the
commit message separately:

Fix inconsistent handling of logs in pg_rewind

pg_rewind was handling a couple of things differently compared to the
other src/bin utilities:
- Logging output needs to be flushed on stderr, not stdout

Agreed in general. But there's also precedent in printing some stuff to
stdout: pg_ctl does that for the status message, like "server starting".
As does initdb.

I'm pretty unclear on what the rule here is.

- Logging messages should be prefixed with the application name

We tend to do that for error messages, but not for other messages. Seems
inappropriate for the progress messages.

- pg_fatal exits with error code of 1, but it was sometimes followed by
subsequent logs, making this information lost in the process.

Fixed.

- Heikki

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#13Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Heikki Linnakangas (#12)
Re: pg_rewind and log messages

Heikki Linnakangas wrote:

On 04/07/2015 05:59 AM, Michael Paquier wrote:

Fix inconsistent handling of logs in pg_rewind

pg_rewind was handling a couple of things differently compared to the
other src/bin utilities:
- Logging output needs to be flushed on stderr, not stdout

Agreed in general. But there's also precedent in printing some stuff to
stdout: pg_ctl does that for the status message, like "server starting". As
does initdb.

I'm pretty unclear on what the rule here is.

One principle that sometimes helps is to consider what happens if you
use the command as part of a larger pipeline; progress messages can be
read by some other command further down (and perhaps report them in a
dialog box, if you embed the program in a GUI, say), but error messages
should probably be processed differently; normally the pipeline would be
aborted as a whole.

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#14Fujii Masao
masao.fujii@gmail.com
In reply to: Alvaro Herrera (#13)
Re: pg_rewind and log messages

On Wed, Apr 8, 2015 at 5:53 AM, Alvaro Herrera <alvherre@2ndquadrant.com> wrote:

Heikki Linnakangas wrote:

On 04/07/2015 05:59 AM, Michael Paquier wrote:

Fix inconsistent handling of logs in pg_rewind

pg_rewind was handling a couple of things differently compared to the
other src/bin utilities:
- Logging output needs to be flushed on stderr, not stdout

Agreed in general. But there's also precedent in printing some stuff to
stdout: pg_ctl does that for the status message, like "server starting". As
does initdb.

I'm pretty unclear on what the rule here is.

One principle that sometimes helps is to consider what happens if you
use the command as part of a larger pipeline; progress messages can be
read by some other command further down (and perhaps report them in a
dialog box, if you embed the program in a GUI, say), but error messages
should probably be processed differently; normally the pipeline would be
aborted as a whole.

Make sense.

Regards,

--
Fujii Masao

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers