Re: Frontend error logging style
Dmitry Koval writes: > Hi! > Commit 9a374b77fb53 (Improve frontend error logging style.) replaced a > line of file src/include/common/logging.h > ``` > extern PGDLLIMPORT enum pg_log_level __pg_log_level; > ``` > to > ``` > extern enum pg_log_level __pg_log_level; > ``` > i.e. it is rollback of commit 8ec569479fc28 (Apply PGDLLIMPORT markings > broadly.) > Is it correct? Yes, since that file is frontend-only. regards, tom lane
Re: Frontend error logging style
Hi! Commit 9a374b77fb53 (Improve frontend error logging style.) replaced a line of file src/include/common/logging.h ``` extern PGDLLIMPORT enum pg_log_level __pg_log_level; ``` to ``` extern enum pg_log_level __pg_log_level; ``` i.e. it is rollback of commit 8ec569479fc28 (Apply PGDLLIMPORT markings broadly.) Is it correct? -- With best regards, Dmitry Koval Postgres Professional: http://postgrespro.com
Re: Frontend error logging style
On 23.05.22 11:53, Peter Eisentraut wrote: On 29.03.22 16:24, Peter Eisentraut wrote: I think I would want the program name/location also in front of the detail and hint lines. I need to think about this a bit more. This shouldn't hold up this patch; it would be a quick localized change. After experiencing this for a bit now, I propose to make this change. It lines up better and allows easier filtering of messages by program. This has been committed.
Re: Frontend error logging style
On 29.03.22 16:24, Peter Eisentraut wrote:
I think I would want the program name/location also in front of the
detail and hint lines. I need to think about this a bit more. This
shouldn't hold up this patch; it would be a quick localized change.
After experiencing this for a bit now, I propose to make this change.
It lines up better and allows easier filtering of messages by program.
Example:
Before:
initdb: error: locale "zh_HK.Big5HKSCS" requires unsupported encoding "BIG5"
detail: Encoding "BIG5" is not allowed as a server-side encoding.
hint: Rerun initdb with a different locale selection.
After:
initdb: error: locale "zh_HK.Big5HKSCS" requires unsupported encoding "BIG5"
initdb: detail: Encoding "BIG5" is not allowed as a server-side encoding.
initdb: hint: Rerun initdb with a different locale selection.From 565fe56ebf9449cd9143424ef1b8083d99019d75 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut
Date: Mon, 23 May 2022 11:44:32 +0200
Subject: [PATCH] logging: Also add the command prefix to detail and hint
messages
This makes the output line up better and allows filtering messages by
command.
---
src/bin/pg_dump/t/003_pg_dump_with_server.pl | 2 +-
src/common/logging.c | 3 +--
2 files changed, 2 insertions(+), 3 deletions(-)
diff --git a/src/bin/pg_dump/t/003_pg_dump_with_server.pl
b/src/bin/pg_dump/t/003_pg_dump_with_server.pl
index a0b23aae0f..8cc9da0659 100644
--- a/src/bin/pg_dump/t/003_pg_dump_with_server.pl
+++ b/src/bin/pg_dump/t/003_pg_dump_with_server.pl
@@ -30,7 +30,7 @@
command_fails_like(
[ "pg_dump", '-p', $port, '--include-foreign-data=s0', 'postgres' ],
- qr/foreign-data wrapper \"dummy\" has no handler\r?\ndetail: Query was:
.*t0/,
+ qr/foreign-data wrapper \"dummy\" has no handler\r?\npg_dump: detail:
Query was: .*t0/,
"correctly fails to dump a foreign table from a dummy FDW");
command_ok(
diff --git a/src/common/logging.c b/src/common/logging.c
index 0b5bcb1a17..64604c5209 100644
--- a/src/common/logging.c
+++ b/src/common/logging.c
@@ -246,8 +246,7 @@ pg_log_generic_v(enum pg_log_level level, enum pg_log_part
part,
fmt = _(fmt);
- if (part == PG_LOG_PRIMARY &&
- (!(log_flags & PG_LOG_FLAG_TERSE) || filename))
+ if (!(log_flags & PG_LOG_FLAG_TERSE) || filename)
{
if (sgr_locus)
fprintf(stderr, ANSI_ESCAPE_FMT, sgr_locus);
--
2.36.1
Re: Frontend error logging style
Peter Eisentraut writes: > On 11.04.22 17:22, Tom Lane wrote: >> The patch I presented keeps the unlikely() checks in the debug-level >> macros. Do you think we should drop those too? I figured that avoiding >> evaluating the arguments would be worth something. > Oh, that's right, the whole thing is to not evaluate the arguments if > the log level isn't adequate. We should probably keep that. I don't think that's nearly as interesting in the frontend as in the backend. Error messages in the backend frequently include catalog lookups and the like in the arguments, but I think nearly all frontend messages are writing nothing more complicated than variables and maybe some indirections or array fetches. So I'm not all that worried about runtime, and would rather save some code space. regards, tom lane
Re: Frontend error logging style
On 11.04.22 17:22, Tom Lane wrote: Peter Eisentraut writes: On 08.04.22 22:26, Tom Lane wrote: I think we should put a centralized level check into logging.c, and get rid of at least the "if (likely())" checks, because those are going to succeed approximately 100.0% of the time. Maybe there's an argument for keeping the unlikely() ones. Yeah, that seems ok to change. The previous coding style is more useful if you have a lot of debug messages in a hot code path, but that usually doesn't apply to where this is used. The patch I presented keeps the unlikely() checks in the debug-level macros. Do you think we should drop those too? I figured that avoiding evaluating the arguments would be worth something. Oh, that's right, the whole thing is to not evaluate the arguments if the log level isn't adequate. We should probably keep that. Is the code size a big problem? ereport() has a bunch of extra code around each call as well. Does it have similar problems?
Re: Frontend error logging style
Peter Eisentraut writes: > On 08.04.22 22:26, Tom Lane wrote: >>> I think we should put a centralized level check >>> into logging.c, and get rid of at least the "if (likely())" >>> checks, because those are going to succeed approximately 100.0% >>> of the time. Maybe there's an argument for keeping the unlikely() >>> ones. > Yeah, that seems ok to change. The previous coding style is more useful > if you have a lot of debug messages in a hot code path, but that usually > doesn't apply to where this is used. The patch I presented keeps the unlikely() checks in the debug-level macros. Do you think we should drop those too? I figured that avoiding evaluating the arguments would be worth something. regards, tom lane
Re: Frontend error logging style
On 08.04.22 22:26, Tom Lane wrote: I wrote: One other loose end is bothering me: I stuck with logging.h's original choice to put "if (likely())" or "if (unlikely())" conditionals into the macros, but I rather suspect that that's just a waste. I think we should put a centralized level check into logging.c, and get rid of at least the "if (likely())" checks, because those are going to succeed approximately 100.0% of the time. Maybe there's an argument for keeping the unlikely() ones. Concretely, something like the attached. As a simple check, I looked at the compiled size of pg_dump. It went from textdata bss dec hex filename 38029840081384 385690 5e29a /home/postgres/testversion/bin/pg_dump to textdata bss dec hex filename 37495440081384 380346 5cdba src/bin/pg_dump/pg_dump for a savings of about 5K or 1.5%. Not a huge amount, but not nothing either, especially considering that the existing coding isn't buying us anything. Yeah, that seems ok to change. The previous coding style is more useful if you have a lot of debug messages in a hot code path, but that usually doesn't apply to where this is used.
Re: Frontend error logging style
I wrote:
> One other loose end is bothering me: I stuck with logging.h's
> original choice to put "if (likely())" or "if (unlikely())"
> conditionals into the macros, but I rather suspect that that's
> just a waste. I think we should put a centralized level check
> into logging.c, and get rid of at least the "if (likely())"
> checks, because those are going to succeed approximately 100.0%
> of the time. Maybe there's an argument for keeping the unlikely()
> ones.
Concretely, something like the attached. As a simple check,
I looked at the compiled size of pg_dump. It went from
textdata bss dec hex filename
38029840081384 385690 5e29a /home/postgres/testversion/bin/pg_dump
to
textdata bss dec hex filename
37495440081384 380346 5cdba src/bin/pg_dump/pg_dump
for a savings of about 5K or 1.5%. Not a huge amount, but
not nothing either, especially considering that the existing
coding isn't buying us anything.
regards, tom lane
diff --git a/src/bin/pg_dump/pg_backup_utils.h b/src/bin/pg_dump/pg_backup_utils.h
index 5b1c51554d..8173bb93cf 100644
--- a/src/bin/pg_dump/pg_backup_utils.h
+++ b/src/bin/pg_dump/pg_backup_utils.h
@@ -34,8 +34,7 @@ extern void exit_nicely(int code) pg_attribute_noreturn();
/* In pg_dump, we modify pg_fatal to call exit_nicely instead of exit */
#undef pg_fatal
#define pg_fatal(...) do { \
- if (likely(__pg_log_level <= PG_LOG_ERROR)) \
- pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
exit_nicely(1); \
} while(0)
diff --git a/src/common/logging.c b/src/common/logging.c
index 18d6669f27..8a061f46b4 100644
--- a/src/common/logging.c
+++ b/src/common/logging.c
@@ -223,6 +223,10 @@ pg_log_generic_v(enum pg_log_level level, enum pg_log_part part,
Assert(fmt);
Assert(fmt[strlen(fmt) - 1] != '\n');
+ /* Do nothing if log level is too low. */
+ if (level < __pg_log_level)
+ return;
+
/*
* Flush stdout before output to stderr, to ensure sync even when stdout
* is buffered.
diff --git a/src/include/common/logging.h b/src/include/common/logging.h
index e213bb70d0..35c7c7b976 100644
--- a/src/include/common/logging.h
+++ b/src/include/common/logging.h
@@ -104,48 +104,39 @@ void pg_log_generic_v(enum pg_log_level level, enum pg_log_part part,
* pg_log_generic[_v] directly, except perhaps in error interface code.
*/
#define pg_log_error(...) do { \
- if (likely(__pg_log_level <= PG_LOG_ERROR)) \
- pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
} while(0)
#define pg_log_error_detail(...) do { \
- if (likely(__pg_log_level <= PG_LOG_ERROR)) \
- pg_log_generic(PG_LOG_ERROR, PG_LOG_DETAIL, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_ERROR, PG_LOG_DETAIL, __VA_ARGS__); \
} while(0)
#define pg_log_error_hint(...) do { \
- if (likely(__pg_log_level <= PG_LOG_ERROR)) \
- pg_log_generic(PG_LOG_ERROR, PG_LOG_HINT, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_ERROR, PG_LOG_HINT, __VA_ARGS__); \
} while(0)
#define pg_log_warning(...) do { \
- if (likely(__pg_log_level <= PG_LOG_WARNING)) \
- pg_log_generic(PG_LOG_WARNING, PG_LOG_PRIMARY, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_WARNING, PG_LOG_PRIMARY, __VA_ARGS__); \
} while(0)
#define pg_log_warning_detail(...) do { \
- if (likely(__pg_log_level <= PG_LOG_WARNING)) \
- pg_log_generic(PG_LOG_WARNING, PG_LOG_DETAIL, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_WARNING, PG_LOG_DETAIL, __VA_ARGS__); \
} while(0)
#define pg_log_warning_hint(...) do { \
- if (likely(__pg_log_level <= PG_LOG_WARNING)) \
- pg_log_generic(PG_LOG_WARNING, PG_LOG_HINT, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_WARNING, PG_LOG_HINT, __VA_ARGS__); \
} while(0)
#define pg_log_info(...) do { \
- if (likely(__pg_log_level <= PG_LOG_INFO)) \
- pg_log_generic(PG_LOG_INFO, PG_LOG_PRIMARY, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_INFO, PG_LOG_PRIMARY, __VA_ARGS__); \
} while(0)
#define pg_log_info_detail(...) do { \
- if (likely(__pg_log_level <= PG_LOG_INFO)) \
- pg_log_generic(PG_LOG_INFO, PG_LOG_DETAIL, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_INFO, PG_LOG_DETAIL, __VA_ARGS__); \
} while(0)
#define pg_log_info_hint(...) do { \
- if (likely(__pg_log_level <= PG_LOG_INFO)) \
- pg_log_generic(PG_LOG_INFO, PG_LOG_HINT, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_INFO, PG_LOG_HINT, __VA_ARGS__); \
} while(0)
#define pg_log_debug(...) do { \
@@ -167,8 +158,7 @@ void pg_log_generic_v(enum pg_log_level level, enum pg_log_part part,
* A common shortcut: pg_log_error() and immediately exit(1).
*/
#define pg_fatal(...) do { \
- if (likely(__pg_log_level <= PG_LOG_ERROR)) \
- pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
+ pg_log_generic(PG_LOG_ERROR, PG_LOG_PRIMARY, __VA_ARGS__); \
exit(1); \
} while(0)
Re: Frontend error logging style
Daniel Gustafsson writes: > On 30 Mar 2022, at 00:38, Tom Lane wrote: >> Feel free to work on a followup editing patch though. > Thats my plan, once this lands I'll rebase the comments on top of your work > and > we can have a separate discussion around them then. The main patch is pushed now. I addressed the complaint Peter had about the messages with "Check your installation" pseudo-hints by getting rid of them; I concur with your observation that those hints were basically useless. I also fixed the one place where the message should clearly be "could not close" not "could not write". Mostly didn't yield to temptation anywhere else. One other loose end is bothering me: I stuck with logging.h's original choice to put "if (likely())" or "if (unlikely())" conditionals into the macros, but I rather suspect that that's just a waste. I think we should put a centralized level check into logging.c, and get rid of at least the "if (likely())" checks, because those are going to succeed approximately 100.0% of the time. Maybe there's an argument for keeping the unlikely() ones. regards, tom lane
Re: Frontend error logging style
> On 30 Mar 2022, at 00:38, Tom Lane wrote: > > Daniel Gustafsson writes: >> On 29 Mar 2022, at 16:38, Peter Eisentraut >> wrote: >>> Most of these should probably be addressed separately from Tom's patch. > >> Yeah, I think so too. > > Agreed. I tried to confine my patch to mechanical changes, except > for changing places where the detail/hint features could be used. > (I don't say that I yielded to temptation nowhere, because I don't > recall that for certain; but editing the message texts was not the > point of my patch.) > > Feel free to work on a followup editing patch though. Thats my plan, once this lands I'll rebase the comments on top of your work and we can have a separate discussion around them then. > Another thing that occurred to me as I looked at your list is that > I think a lot of these are nearly-can't-happen cases that we didn't > put a lot of effort into devising great error messages for. Maybe > we should continue that approach, and in particular not put effort > into translating such messages. That would suggest inventing > "pg_fatal_internal" and so forth, with the same functionality > except for not being gettext triggers, comparable to > errmsg_internal. However, then somebody would have to make > judgment calls about which messages not to bother translating. > Do we want to go down that path? I'm not sure. If, against the odds, these cases do happen then a user of a localized build probably really want to see the error in language they can easily understand and take in. -- Daniel Gustafsson https://vmware.com/
Re: Frontend error logging style
Greg Stark writes: > FYI this patch no longer applies. No surprise :-( > Given it's a Tom patch and due to its nature it'll bitrot rapidly > anyways I'm don't see a point in updating the status though. We now seem to have buy-in on the concept, so my plan is to let this sit till the end of the commitfest, then rebase and push. That should avoid unnecessary churn for other pending patches. regards, tom lane
Re: Frontend error logging style
FYI this patch no longer applies. Given it's a Tom patch and due to its nature it'll bitrot rapidly anyways I'm don't see a point in updating the status though.
Re: Frontend error logging style
Daniel Gustafsson writes: > On 29 Mar 2022, at 16:38, Peter Eisentraut > wrote: >> Most of these should probably be addressed separately from Tom's patch. > Yeah, I think so too. Agreed. I tried to confine my patch to mechanical changes, except for changing places where the detail/hint features could be used. (I don't say that I yielded to temptation nowhere, because I don't recall that for certain; but editing the message texts was not the point of my patch.) Feel free to work on a followup editing patch though. Another thing that occurred to me as I looked at your list is that I think a lot of these are nearly-can't-happen cases that we didn't put a lot of effort into devising great error messages for. Maybe we should continue that approach, and in particular not put effort into translating such messages. That would suggest inventing "pg_fatal_internal" and so forth, with the same functionality except for not being gettext triggers, comparable to errmsg_internal. However, then somebody would have to make judgment calls about which messages not to bother translating. Do we want to go down that path? regards, tom lane
Re: Frontend error logging style
> On 29 Mar 2022, at 16:38, Peter Eisentraut
> wrote:
>
> On 29.03.22 12:13, Daniel Gustafsson wrote:
>
> Most of these should probably be addressed separately from Tom's patch.
Yeah, I think so too. I'll await input from Tom on how he wants to do, but I'm
happy to take these to a new thread. The main point of the review was to find
logic errors in the logging changes, these came as a bonus from reading them
all in one place.
>>> @@ -508,24 +502,15 @@ writefile(char *path, char **lines)
>>> if (fclose(out_file))
>>> - {
>>> - pg_log_error("could not write file \"%s\": %m", path);
>>> - exit(1);
>>> - }
>>> + pg_fatal("could not write file \"%s\": %m", path);
>>> }
>> Should we update this message to differentiate it from the fwrite error case?
>> Something like "an error occurred during writing.."
>
> Should be "could not close ...", no?
Yes, it should, not sure what I was thinking.
>>> @@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale,
>>> char **canonname)
>>>
>>> save = setlocale(category, NULL);
>>> if (!save)
>>> - {
>>> - pg_log_error("setlocale() failed");
>>> - exit(1);
>>> - }
>>> + pg_fatal("setlocale() failed");
>> Should this gain a hint message for those users who have no idea what this
>> really means?
>
> My setlocale() man page says:
>
> ERRORS
> No errors are defined.
>
> So uh ... ;-)
Even more reason to be confused then =) We have a mixed bag in the tree on how
we handle errors from setlocale, in this case we could reword it to say
something like "failed to retrieve locale for %s, category" which IMO would be
slightly more informative. Might be academic though since I guess it rarely, if
ever, happens.
>>> --- a/src/bin/pg_basebackup/receivelog.c
>>> +++ b/src/bin/pg_basebackup/receivelog.c
>>> @@ -140,7 +140,7 @@ open_walfile(StreamCtl *stream, XLogRecPtr startpoint)
>>> /* fsync file in case of a previous crash */
>>> if (stream->walmethod->sync(f) != 0)
>>> {
>>> - pg_log_fatal("could not fsync existing
>>> write-ahead log file \"%s\": %s",
>>> + pg_log_error("could not fsync existing
>>> write-ahead log file \"%s\": %s",
>>> fn,
>>> stream->walmethod->getlasterror());
>>> stream->walmethod->close(f, CLOSE_UNLINK);
>>> exit(1);
>> In the case where we already have IO related errors, couldn't the close()
>> call
>> cause an additional error message which potentially could be helpful for
>> debugging?
>
> Yeah, I think in general we have been sloppy with reporting file-closing
> errors properly. Those presumably happen very rarely, but when they do,
> things are probably very bad.
Agreed. I'm not sure if Tom wants to add net new loggings in this patchset,
else we could do this separately.
>> The ngettext() call seems a bit out of place here since we already know that
>> second form will be taken given the check on PQntuples(res).
>
> See
>
> for a similar case that explains why this is still correct and necessary.
Doh, I knew that, sorry.
>>> }
>>> + pg_fatal("cannot cluster specific table(s) in all
>>> databases");
>> An ngettext() candidate perhaps? There are more like this in main() hunks
>> further down omitted for brevity here.
>
> I would just rephrase this as
>
>"cannot cluster specific tables in all databases"
>
> This is still correct and sensible if the user specified just one table.
That's one way yes. Mostly I'm just a bit allergic to the "foo(s)" which my
unscientifically based gut feeling am concerned about not necessarily always
working well for translations.
--
Daniel Gustafsson https://vmware.com/
Re: Frontend error logging style
On 29.03.22 12:13, Daniel Gustafsson wrote:
Most of these should probably be addressed separately from Tom's patch.
@@ -508,24 +502,15 @@ writefile(char *path, char **lines)
if (fclose(out_file))
- {
- pg_log_error("could not write file \"%s\": %m", path);
- exit(1);
- }
+ pg_fatal("could not write file \"%s\": %m", path);
}
Should we update this message to differentiate it from the fwrite error case?
Something like "an error occurred during writing.."
Should be "could not close ...", no?
@@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale, char
**canonname)
save = setlocale(category, NULL);
if (!save)
- {
- pg_log_error("setlocale() failed");
- exit(1);
- }
+ pg_fatal("setlocale() failed");
Should this gain a hint message for those users who have no idea what this
really means?
My setlocale() man page says:
ERRORS
No errors are defined.
So uh ... ;-)
@@ -3089,18 +2979,14 @@ main(int argc, char *argv[])
else if (strcmp(optarg, "libc") == 0)
locale_provider = COLLPROVIDER_LIBC;
else
- {
- pg_log_error("unrecognized locale provider:
%s", optarg);
- exit(1);
- }
+ pg_fatal("unrecognized locale provider:
%s", optarg);
Should this %s be within quotes to match how we usually emit user-input?
Usually not done after colon, but could be.
@@ -1123,9 +1097,9 @@ verify_btree_slot_handler(PGresult *res, PGconn *conn,
void *context)
pg_log_warning("btree index \"%s.%s.%s\": btree checking
function returned unexpected number of rows: %d",
rel->datinfo->datname,
rel->nspname, rel->relname, ntups);
if (opts.verbose)
- pg_log_info("query was: %s", rel->sql);
- pg_log_warning("Are %s's and amcheck's versions
compatible?",
- progname);
+ pg_log_warning_detail("Query was: %s",
rel->sql);
+ pg_log_warning_hint("Are %s's and amcheck's versions
compatible?",
+ progname);
Should "amcheck's" be a %s parameter to make translation reusable (which it
miht never be) and possibly avoid translation mistake?
We don't have translations set up for contrib modules. Otherwise, this
kind of thing would probably be something to look into.
--- a/src/bin/pg_basebackup/receivelog.c
+++ b/src/bin/pg_basebackup/receivelog.c
@@ -140,7 +140,7 @@ open_walfile(StreamCtl *stream, XLogRecPtr startpoint)
/* fsync file in case of a previous crash */
if (stream->walmethod->sync(f) != 0)
{
- pg_log_fatal("could not fsync existing write-ahead log file
\"%s\": %s",
+ pg_log_error("could not fsync existing write-ahead log file
\"%s\": %s",
fn,
stream->walmethod->getlasterror());
stream->walmethod->close(f, CLOSE_UNLINK);
exit(1);
In the case where we already have IO related errors, couldn't the close() call
cause an additional error message which potentially could be helpful for
debugging?
Yeah, I think in general we have been sloppy with reporting file-closing
errors properly. Those presumably happen very rarely, but when they do,
things are probably very bad.
@@ -597,31 +570,19 @@ main(int argc, char *argv[])
if (ControlFile->data_checksum_version == 0 &&
mode == PG_MODE_CHECK)
- {
- pg_log_error("data checksums are not enabled in cluster");
- exit(1);
- }
+ pg_fatal("data checksums are not enabled in cluster");
Fatal seems sort of out place here, it's not really a case of "something
terrible happened" but rather "the preconditions weren't met". Couldn't these
be a single pg_log_error erroring out with the reason in a pg_log_detail?
"fatal" means error plus exit, so this seems ok. There is no separate
log level for really-bad-error.
@@ -721,7 +721,7 @@ setFilePath(ArchiveHandle *AH, char *buf, const char
*relativeFilename)
dname = ctx->directory;
if (strlen(dname) + 1 + strlen(relativeFilename) + 1 > MAXPGPATH)
Unrelated, but shouldn't that be >= MAXPGPATH?
Seems correct to me as is.
@@ -14951,18 +14942,18 @@ createViewAsClause(Archive *fout, const TableInfo
*tbinfo)
-
Re: Frontend error logging style
On 27.03.22 22:19, Tom Lane wrote:
Here's a rebase up to today's HEAD. I've fixed the merge problems,
but there may be some stray new error calls that could be converted
to use pg_fatal() and haven't been. I don't want to do a full
fresh scan of the code until we're about ready to commit this.
This looks like a good improvement to me.
I think I would want the program name/location also in front of the
detail and hint lines. I need to think about this a bit more. This
shouldn't hold up this patch; it would be a quick localized change.
(I'm also thinking about providing a separate color code for the
secondary messages. Again, this could be a quick follow-up patch.)
The one change I didn't like was
- pg_log_error("The program \"%s\" is needed by %s
but was not found in the\n"
-"same directory as
\"%s\".\n"
-"Check your installation.",
+ pg_log_error("the program \"%s\" is needed by %s
but was not found in the same directory as \"%s\"",
"postgres", progname,
full_path);
This appears to prioritize the guideline "don't punctuate error message
as full sentence" over what should be the actual guideline "don't make
the error message a full sentence".
There are other occurrences of a similar message that were not changed
in the same way by the patch. Maybe we should leave this one alone in
this patch and consider rewriting the message instead.
Re: Frontend error logging style
> On 27 Mar 2022, at 22:19, Tom Lane wrote:
>
> Here's a rebase up to today's HEAD. I've fixed the merge problems,
> but there may be some stray new error calls that could be converted
> to use pg_fatal() and haven't been. I don't want to do a full
> fresh scan of the code until we're about ready to commit this.
I focused on finding any changes in logic (exiting where it previously kept
going after error, or vice versa) and was unable to find any which inspires
confidence. This was a large patch to read through, so I'm fairly sure I've
missed something.
Below are comments (nitpicks to a large extent) which either relates to this
patch or to the messages in general. For the latter, feel free to deem them
out of scope and we can take those comments separately from this work on
-hackers.
As a side-note realization from reading this, there is a tremendous amount of
code paths in pg_dump which leads to a fatal error.. thats not necessarily a
bad thing, it's just striking when reading them all at once.
> @@ -508,24 +502,15 @@ writefile(char *path, char **lines)
> if (fclose(out_file))
> - {
> - pg_log_error("could not write file \"%s\": %m", path);
> - exit(1);
> - }
> + pg_fatal("could not write file \"%s\": %m", path);
> }
Should we update this message to differentiate it from the fwrite error case?
Something like "an error occurred during writing.."
> @@ -2057,10 +2004,7 @@ check_locale_name(int category, const char *locale,
> char **canonname)
>
> save = setlocale(category, NULL);
> if (!save)
> - {
> - pg_log_error("setlocale() failed");
> - exit(1);
> - }
> + pg_fatal("setlocale() failed");
Should this gain a hint message for those users who have no idea what this
really means?
> @@ -2127,15 +2067,14 @@ check_locale_encoding(const char *locale, int
> user_enc)
> user_enc == PG_SQL_ASCII))
> {
> pg_log_error("encoding mismatch");
> - fprintf(stderr,
> - _("The encoding you selected (%s) and the
> encoding that the\n"
> - "selected locale uses (%s) do not match.
> This would lead to\n"
> - "misbehavior in various character string
> processing functions.\n"
> - "Rerun %s and either do not specify an
> encoding explicitly,\n"
> - "or choose a matching combination.\n"),
> - pg_encoding_to_char(user_enc),
> - pg_encoding_to_char(locale_enc),
> - progname);
> + pg_log_error_detail("The encoding you selected (%s) and the
> encoding that the "
> + "selected locale uses
> (%s) do not match. This would lead to "
I will be sad to see double space after period go, but I think I'm rare in
preferring that.
> @@ -2344,10 +2276,7 @@ setup_pgdata(void)
>* have embedded spaces.
>*/
> if (setenv("PGDATA", pg_data, 1) != 0)
> - {
> - pg_log_error("could not set environment");
> - exit(1);
> - }
> + pg_fatal("could not set environment");
Should we be explicit about which env var?
> @@ -3089,18 +2979,14 @@ main(int argc, char *argv[])
> else if (strcmp(optarg, "libc") == 0)
> locale_provider = COLLPROVIDER_LIBC;
> else
> - {
> - pg_log_error("unrecognized locale
> provider: %s", optarg);
> - exit(1);
> - }
> + pg_fatal("unrecognized locale provider:
> %s", optarg);
Should this %s be within quotes to match how we usually emit user-input?
> @@ -1123,9 +1097,9 @@ verify_btree_slot_handler(PGresult *res, PGconn *conn,
> void *context)
> pg_log_warning("btree index \"%s.%s.%s\": btree
> checking function returned unexpected number of rows: %d",
> rel->datinfo->datname,
> rel->nspname, rel->relname, ntups);
> if (opts.verbose)
> - pg_log_info("query was: %s", rel->sql);
> - pg_log_warning("Are %s's and amcheck's versions
> compatible?",
> -progname);
> + pg_log_warning_detail("Query was: %s",
> rel->sql);
> + pg_log_warning_hint("Are %s's and amcheck's versions
> compatible?",
> + progname);
Should "amcheck's" be a %s parameter to make translation reusable (which it
miht never be) and possibly avoid translation mistake?
> ---
Re: Frontend error logging style
Hi, On 2022-03-21 22:00:37 -0400, Tom Lane wrote: > Andres Freund writes: > > This unfortunately has had some bitrot: > > http://cfbot.cputube.org/patch_37_3574.log > > Yeah, I know. That patch touches enough places that it's sure to > break every few days during a commitfest. I'm not real excited about > maintaining it reactively. Makes sense. I'd leave it on waiting-on-author then, so that reviewers looking through the CF don't need to look at it? > Maybe the plan could be to push it at the end of the commitfest? Would make sense to me. Arguably parts of it could be committed sooner than that, e.g. exit(-1). But that'd not make it meaningfully easier to maintain, so ... > But what I'd really like at the moment is buy-in or rejection of the whole > concept, so I know whether it's worth spending more time on. I'm +1. I've not carefully looked through every single changed callsite, but IMO it looks like a clear improvement. Greetings, Andres Freund
Re: Frontend error logging style
Andres Freund writes: > On 2022-02-25 12:15:25 -0500, Tom Lane wrote: >> The attached revision does that, standardizes on pg_fatal() as the >> abbreviation for pg_log_error() + exit(1), and invents detail/hint >> features as per previous discussion. > This unfortunately has had some bitrot: > http://cfbot.cputube.org/patch_37_3574.log Yeah, I know. That patch touches enough places that it's sure to break every few days during a commitfest. I'm not real excited about maintaining it reactively. The flip side of the coin is that pushing it will doubtless break a lot of other uncommitted patches. So I'm not sure how to proceed. Maybe the plan could be to push it at the end of the commitfest? But what I'd really like at the moment is buy-in or rejection of the whole concept, so I know whether it's worth spending more time on. regards, tom lane
Re: Frontend error logging style
Hi, On 2022-02-25 12:15:25 -0500, Tom Lane wrote: > The attached revision does that, standardizes on pg_fatal() as the > abbreviation for pg_log_error() + exit(1), and invents detail/hint > features as per previous discussion. This unfortunately has had some bitrot: http://cfbot.cputube.org/patch_37_3574.log Marked as waiting-on-author. Greetings, Andres
Re: Frontend error logging style
Michael Paquier writes: > Hm. I am not sure to like much this abstraction by having so many > macros that understand the log level through their name. Wouldn't it > be cleaner to have only one pg_log_hint() and one pg_log_detail() with > the log level passed as argument of the macro? Mmm ... that doesn't sound better to me. I think it wouldn't be obvious that pg_log_warning and pg_log_hint are fundamentally different sorts of things: in the first, "warning" refers to an error severity level, while in the second, "hint" refers to a message component. I'm not wedded to the way I did it in this patch, but I think we ought to maintain a notational distinction between those two sorts of concepts. regards, tom lane
Re: Frontend error logging style
On Fri, Feb 25, 2022 at 12:15:25PM -0500, Tom Lane wrote:
> I feel that the reasonable alternatives are either to drop the FATAL
> log level, or try to make it actually mean something by consistently
> using it for errors that are indeed fatal. I had a go at doing the
> latter, but eventually concluded that that way madness lies. It's
> not too hard to use "pg_log_fatal" when there's an exit(1) right
> after it, but there are quite a lot of cases where a subroutine
> reports an error and returns a failure code to its caller, whereupon
> the caller exits. Either the subroutine has to make an unwarranted
> assumption about what its callers will do, or we need to make an API
> change to allow the subroutine itself to exit(), or we are going to
> present a user experience that is inconsistently different depending
> on internal implementation details.
Nice code cut.
> I conclude that we ought to drop the separate FATAL level and just
> use ERROR instead.
FWIW, I have found the uses of pg_log_error() and pg_log_fatal()
rather confusing in some of the src/bin/ tools, so I am in favor of
removing completely one or the other, and getting rid of FATAL is the
best choice.
> The attached revision does that, standardizes on pg_fatal() as the
> abbreviation for pg_log_error() + exit(1), and invents detail/hint
> features as per previous discussion.
+#define pg_log_warning_hint(...) do { \
+ if (likely(__pg_log_level <= PG_LOG_WARNING)) \
+ pg_log_generic(PG_LOG_WARNING, PG_LOG_HINT, __VA_ARGS__);
\
} while(0)
Hm. I am not sure to like much this abstraction by having so many
macros that understand the log level through their name. Wouldn't it
be cleaner to have only one pg_log_hint() and one pg_log_detail() with
the log level passed as argument of the macro?
--
Michael
signature.asc
Description: PGP signature
Re: Frontend error logging style
Peter Eisentraut writes: > This patch already illustrates a couple of things that are wrong with > this approach: All of these objections are a bit moot with my followup proposal, no? > - It doesn't allow any other way of exiting. For example, in pg_dump, > you have removed a few exit_nicely() calls. It's not clear why that is > valid or whether it would always be valid for all call sites. As the patch stood, I'd hacked it so that pg_log_fatal called exit_nicely() not exit() within pg_dump. I agree that's not a great solution, but I think that the correct fix is to get rid of exit_nicely in favor of doing the requisite cleanup in an atexit hook. pg_dump is already at great hazard of somebody calling exit() not exit_nicely(), either through failure to pay attention to that undocumented convention, or because some code it imports from someplace like src/common calls exit() directly. You need not look any further than pg_malloc() to see that there are live problems there. I figured this could be addressed in a separate patch, though, because to the extent that missing the exit-nicely callbacks is a real bug, it's already a bug. > My suggestion is to just get rid of pg_log_fatal() and replace them all > with pg_log_error(). I'm on board with dropping the separate FATAL log level if there's consensus to do so; I think it adds more confusion than anything else. I still want to have something like pg_fatal(), though, because it's impossible to deny the usefulness of such an abbreviation. It's already been reinvented three or four times independently. Independently of either of those points, I still want to make the changes I proposed w.r.t. making explicit concepts of "detail" and "hint" addendums. What we have right now in the frontend code is an impossible mishmash of three or four ways of filling that lack, all inconsistent. regards, tom lane
Re: Frontend error logging style
Hi, On 2022-02-24 14:06:18 +0100, Peter Eisentraut wrote: > My suggestion is to just get rid of pg_log_fatal() and replace them all with > pg_log_error(). -1. This ignores that already several places came up with their slightly different versions of fatal exit handlers. We don't gain anything by not standardizing on one notion of a fatal error wrapper. Greetings, Andres Freund
Re: Frontend error logging style
On 23.02.22 00:23, Tom Lane wrote: This conversation seems to have tailed off without full resolution, but I observe that pretty much everyone except Peter is on board with defining pg_log_fatal as pg_log_error + exit(1). So I think we should just do that, unless Peter wants to produce a finished alternative proposal. I've now gone through and fleshed out the patch I sketched upthread. This patch already illustrates a couple of things that are wrong with this approach: - It doesn't allow any other way of exiting. For example, in pg_dump, you have removed a few exit_nicely() calls. It's not clear why that is valid or whether it would always be valid for all call sites. - It doesn't allow other exit codes. For example, in psql, you have changed a pg_log_fatal() call to pg_log_error() because it needed another exit code. This slides us right back into that annoying situation where in the backend we have to log error messages using elog(LOG) because the flow control is tangled up with the log level. My suggestion is to just get rid of pg_log_fatal() and replace them all with pg_log_error().
Re: Frontend error logging style
On Wed, Feb 23, 2022, at 12:30 PM, Tom Lane wrote: > Updating the patch is going to be a bit tedious, so I'm not > going to do it without buy-in that this solution would be > okay to commit. Any objections? No. I was confused by the multiple log functions spread in the client programs while I was working on pg_subscriber [1]. Your proposal looks good to me. [1] https://postgr.es/m/5ac50071-f2ed-4ace-a8fd-b892cffd33eb%40www.fastmail.com -- Euler Taveira EDB https://www.enterprisedb.com/
Re: Frontend error logging style
Hi, On 2022-02-23 10:30:02 -0500, Tom Lane wrote: > So I now propose modifying yesterday's patch thus: > > * Reinstantiate the PG_LOG_FATAL enum value, add support macros > pg_log_fatal, pg_log_fatal_hint, pg_log_fatal_detail. > > * Define pg_fatal as pg_log_fatal + exit(1). (This would essentially > move pg_rewind's definition into logging.h. pg_upgrade will > define it slightly differently, but the semantics end up the same.) > > * Adjust call sites to match. +1 > I do like this idea because it would not break any existing code > that expects pg_log_fatal to return. There is likely to be some > of that in outstanding patches, and this approach would merely > render it less-than-idiomatic rather than outright broken. > > Updating the patch is going to be a bit tedious, so I'm not > going to do it without buy-in that this solution would be > okay to commit. Any objections? +1 Greetings, Andres Freund
Re: Frontend error logging style
I wrote: > Andres Freund writes: >> What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps >> pg_log_* stuff "log only", but adds something adjacent enough to hopefully >> reduce future misunderstandings? > I'd be okay with that, except that pg_upgrade already has a pg_fatal > (because it has its *own* logging system, just in case you thought > this wasn't enough of a mess yet). Wait a moment. After looking closer, I realize that pg_upgrade's pg_fatal could trivially be turned into a macro; and the other two existing definitions already are macros. That would remove the risk of link-time symbol collisions that I was worried about. As a bonus, it'd substantially reduce the number of changes needed to make pg_upgrade use logging.c, whenever somebody wants to make that happen. So I now propose modifying yesterday's patch thus: * Reinstantiate the PG_LOG_FATAL enum value, add support macros pg_log_fatal, pg_log_fatal_hint, pg_log_fatal_detail. * Define pg_fatal as pg_log_fatal + exit(1). (This would essentially move pg_rewind's definition into logging.h. pg_upgrade will define it slightly differently, but the semantics end up the same.) * Adjust call sites to match. I do like this idea because it would not break any existing code that expects pg_log_fatal to return. There is likely to be some of that in outstanding patches, and this approach would merely render it less-than-idiomatic rather than outright broken. Updating the patch is going to be a bit tedious, so I'm not going to do it without buy-in that this solution would be okay to commit. Any objections? regards, tom lane
Re: Frontend error logging style
On 2022-02-22 22:44:25 -0500, Tom Lane wrote: > Andres Freund writes: > > What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps > > pg_log_* stuff "log only", but adds something adjacent enough to hopefully > > reduce future misunderstandings? > > I'd be okay with that, except that pg_upgrade already has a pg_fatal > (because it has its *own* logging system, just in case you thought > this wasn't enough of a mess yet). I'm in favor of aligning > pg_upgrade's logging with the rest, but I'd hoped to leave that for > later. Making the names collide would be bad even as a short-term > thing, I fear. I guess we could name pg_upgrade's out of the way... > I'm not against choosing some name other than pg_log_fatal, but that > particular suggestion has got conflicts. Got any other ideas? Maybe pg_fatal_exit(), pg_exit_fatal() or pg_fatal_error()?
Re: Frontend error logging style
Andres Freund writes: > What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps > pg_log_* stuff "log only", but adds something adjacent enough to hopefully > reduce future misunderstandings? I'd be okay with that, except that pg_upgrade already has a pg_fatal (because it has its *own* logging system, just in case you thought this wasn't enough of a mess yet). I'm in favor of aligning pg_upgrade's logging with the rest, but I'd hoped to leave that for later. Making the names collide would be bad even as a short-term thing, I fear. Looks like libpq_pipeline.c has its own pg_fatal, too. I'm not against choosing some name other than pg_log_fatal, but that particular suggestion has got conflicts. Got any other ideas? regards, tom lane
Re: Frontend error logging style
Hi, On 2022-02-22 18:23:19 -0500, Tom Lane wrote: > Robert Haas writes: > > On Fri, Nov 19, 2021 at 5:17 AM Peter Eisentraut > > wrote: > >> If people want to do that kind of thing (I'm undecided whether the > >> complexity is worth it), then make it a different API. The pg_log_* > >> calls are for writing formatted output. They normalized existing > >> hand-coded patterns at the time. We can wrap another API on top of them > >> that does flow control and output. The pg_log_* stuff is more on the > >> level of syslog(), which also just outputs stuff. Nobody is suggesting > >> that syslog(LOG_EMERG) should exit the program automatically. But you > >> can wrap higher-level APIs such as ereport() on top of that that might > >> do that. That'd maybe be a convincing argument in a project that didn't have elog(FATAL). > > Yeah, that might be a way forward. > > This conversation seems to have tailed off without full resolution, > but I observe that pretty much everyone except Peter is on board > with defining pg_log_fatal as pg_log_error + exit(1). So I think > we should just do that, unless Peter wants to produce a finished > alternative proposal. What about adding a pg_fatal() that's pg_log_fatal() + exit()? That keeps pg_log_* stuff "log only", but adds something adjacent enough to hopefully reduce future misunderstandings? To further decrease the chance of such mistakes, we could rename pg_log_fatal() to something else. Or add a a pg_log_fatal() function that's marked pg_nodiscard(), so that each callsite explicitly has to be (void) pg_log_fatal(). > I've now gone through and fleshed out the patch I sketched upthread. > This exercise convinced me that we absolutely should do something > very like this, because > > (1) As it stands, this patch removes a net of just about 1000 lines > of code. So we clearly need *something*. > (2) The savings would be even more, except that people have invented > macros for pg_log_error + exit(1) in at least four places already. > (None of them quite the same of course.) Here I've just fixed those > macro definitions to use pg_log_fatal. In the name of consistency, we > should probably get rid of those macros in favor of using pg_log_fatal > directly; but I've not done so here, since this patch is eyewateringly > long and boring already. Agreed. I don't care that much about the naming here. For a moment I was wondering whether there'd be a benefit for having the "pure logging" stuff be in a different static library than the erroring variant. So that e.g. libpq's check for exit() doesn't run into trouble. But then I remembered that libpq doesn't link against common... Greetings, Andres Freund
Re: Frontend error logging style
On Fri, Nov 19, 2021 at 5:17 AM Peter Eisentraut wrote: > If people want to do that kind of thing (I'm undecided whether the > complexity is worth it), then make it a different API. The pg_log_* > calls are for writing formatted output. They normalized existing > hand-coded patterns at the time. We can wrap another API on top of them > that does flow control and output. The pg_log_* stuff is more on the > level of syslog(), which also just outputs stuff. Nobody is suggesting > that syslog(LOG_EMERG) should exit the program automatically. But you > can wrap higher-level APIs such as ereport() on top of that that might > do that. Yeah, that might be a way forward. -- Robert Haas EDB: http://www.enterprisedb.com
Re: Frontend error logging style
On 16.11.21 16:18, Robert Haas wrote: I think we need frontend facilities that look like the backend facilities, so try/catch blocks, on-exit callbacks, and whatever else there is. Otherwise code reuse is going to continue to be annoying. If people want to do that kind of thing (I'm undecided whether the complexity is worth it), then make it a different API. The pg_log_* calls are for writing formatted output. They normalized existing hand-coded patterns at the time. We can wrap another API on top of them that does flow control and output. The pg_log_* stuff is more on the level of syslog(), which also just outputs stuff. Nobody is suggesting that syslog(LOG_EMERG) should exit the program automatically. But you can wrap higher-level APIs such as ereport() on top of that that might do that.
Re: Frontend error logging style
On Mon, Nov 15, 2021 at 10:02 PM Michael Paquier wrote: > On Mon, Nov 15, 2021 at 02:40:10PM -0500, Robert Haas wrote: > > Having different frontend utilities each invent their own > > slightly-different way of doing this makes it hard to reuse code, and > > hard to understand code. We need to find ways to make it more uniform, > > not just observe that it isn't uniform today and give up. > > I agree with this sentiment, but this is a bit more complex than just > calling exit() with pg_log_fatal(), no? pg_dump likes playing a lot > with its exit_nicely(), meaning that we may want to allow frontends to > plug in callbacks. Yep. I think we need frontend facilities that look like the backend facilities, so try/catch blocks, on-exit callbacks, and whatever else there is. Otherwise code reuse is going to continue to be annoying. -- Robert Haas EDB: http://www.enterprisedb.com
Re: Frontend error logging style
On Mon, Nov 15, 2021 at 02:40:10PM -0500, Robert Haas wrote: > Having different frontend utilities each invent their own > slightly-different way of doing this makes it hard to reuse code, and > hard to understand code. We need to find ways to make it more uniform, > not just observe that it isn't uniform today and give up. I agree with this sentiment, but this is a bit more complex than just calling exit() with pg_log_fatal(), no? pg_dump likes playing a lot with its exit_nicely(), meaning that we may want to allow frontends to plug in callbacks. -- Michael signature.asc Description: PGP signature
Re: Frontend error logging style
Peter Eisentraut writes: > Several programs wrap, say, pg_log_fatal() into a pg_fatal(), that does > logging, cleanup, and exit, as the case may be. I think that's a good > solution. I agree, and my draft patch formalized that by turning pg_log_fatal into exactly that. The question that I think is relevant here is what is the point of labeling errors as "error:" or "fatal:" if we're not going to make any serious attempt to make that distinction meaningful. I'm not really buying your argument that it's fine as-is. Anybody who thinks that there's a difference is going to be very confused by the behavior they observe. But, if we all know there's no difference, why have the difference? regards, tom lane
Re: Frontend error logging style
On Mon, Nov 15, 2021 at 2:15 PM Peter Eisentraut
wrote:
> This is specifically designed not to do any flow control. In the
> backend, we have many instances, where log messages are issued with the
> wrong log level because the stronger log level would have flow control
> impact that is not appropriate at the call site. I don't think we want
> more of that, especially since the flow control requirements in the
> varied suite of frontend programs is quite diverse. Moreover, we also
> require control over the exit codes in some cases, which this kind of
> API wouldn't allow.
I agree that the system we use in the backend isn't problem free, but
making the frontend do something randomly different isn't an
improvement. I think that most people who are writing PostgreSQL
frontend code have also written a lot of backend code, and they are
used to the way things work in the backend. More importantly, there's
an increasing amount of code that wants to run in either environment.
And there have been suggestions that we want to make more things, like
memory contexts, work that way. The design decision that you've made
here makes that harder, and results in stuff like this:
[rhaas pgsql]$ git grep pg_log_fatal.*VA_ARGS
src/bin/pg_rewind/pg_rewind.h:#define pg_fatal(...) do {
pg_log_fatal(__VA_ARGS__); exit(1); } while(0)
src/bin/pg_waldump/pg_waldump.c:#define fatal_error(...) do {
pg_log_fatal(__VA_ARGS__); exit(EXIT_FAILURE); } while(0)
src/include/lib/simplehash.h:do { pg_log_fatal(__VA_ARGS__);
exit(1); } while(0)
Having different frontend utilities each invent their own
slightly-different way of doing this makes it hard to reuse code, and
hard to understand code. We need to find ways to make it more uniform,
not just observe that it isn't uniform today and give up.
IOW, I think the fact that it's not designed to do any flow control is
a bad thing.
--
Robert Haas
EDB: http://www.enterprisedb.com
Re: Frontend error logging style
On 10.11.21 16:28, Robert Haas wrote: What I think we ought to be driving towards is having pg_log_fatal() forcibly exit, and pg_log_error() do the same unless the error is somehow caught. This is specifically designed not to do any flow control. In the backend, we have many instances, where log messages are issued with the wrong log level because the stronger log level would have flow control impact that is not appropriate at the call site. I don't think we want more of that, especially since the flow control requirements in the varied suite of frontend programs is quite diverse. Moreover, we also require control over the exit codes in some cases, which this kind of API wouldn't allow. Several programs wrap, say, pg_log_fatal() into a pg_fatal(), that does logging, cleanup, and exit, as the case may be. I think that's a good solution. If someone wanted to write a more widely reusable pg_fatal(), why not, but in my previous attempts, this was quite complicated and didn't turn out to be useful.
Re: Frontend error logging style
On 09.11.21 23:20, Tom Lane wrote:
2. What is the preferred style for adding extra lines to log messages?
I see a lot of direct prints to stderr:
pg_log_error("missing required argument: database name");
fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
progname);
exit(1);
This is mainly used for those few messages that are sort of a "global
standard".
but a number of places have chosen to do this:
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error("query was: %s", todo);
and some places got creative and did this:
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_info("query was: %s", sql.data);
I can't decide between those two. It depends on how each program
handles the log level internally.
Some kind of "detail" system could be useful. But it would need to be
tied into the log level, layout, etc. I have not seen much inspiration
for this kind of thing in other logging libraries, so I didn't do
anything about it yet.
Re: Frontend error logging style
On 09.11.21 23:20, Tom Lane wrote: 1. The distinction between "error" and "fatal" levels seems squishy to the point of uselessness. I think we should either get rid of it entirely, or make an effort to use "fatal" exactly for the cases that are going to give up and exit right away. Of the approximately 830 pg_log_error calls in HEAD, I count at least 450 that are immediately followed by exit(1), and so should be pg_log_fatal if this distinction means anything at all. OTOH, if we decide it doesn't mean anything, there are only about 90 pg_log_fatal calls to convert. I lean slightly to the "get rid of the distinction" option, not only because it'd be a much smaller patch but also because I don't care to expend brain cells on the which-to-use question while reviewing future patches. This logging system has been designed more generally, drawing some inspiration from Python and Java libraries, for example. It's up to the program using this to make sensible use of it. I think there are programs such as pg_receivewal where there is a meaningful distinction between errors flowing by and a fatal exit. But with something like pg_basebackup, there is no real difference, so that code sort of uses pg_log_error by default, since any error is implicitly fatal. I see the apparent inconsistency, but I don't think it's a real problem. Each program by itself has arguably sensible behavior.
Re: Frontend error logging style
Kyotaro Horiguchi writes:
> Aren't DETAIL and HINT expected to be hidden at the targetted cutoff
> level? In other words, I suspect that people want to hide non-primary
> messages for a lower verbosity level. On the other hand I'm not sure
> it is a proper behavior that log_level = WARNING causes ERROR messages
> are accompanied by DETAIL/HINT submessages...
I abandoned that idea in the draft patch. We could maybe do something
about it further down the line, but I'm not sure there's really any
demand.
As the patch is set up, you could theoretically do something like
pg_log_error("blah blah");
pg_log_info_detail("Very boring detail goes here.");
(note the intentionally different log priorities). But that feels wrong
to me --- it doesn't seem like individual call sites should be setting
such policy. If we do arrange for a way to hide the optional message
parts, I'd rather that the control were centralized in logging.c.
It certainly wouldn't be hard for logging.c to make different decisions
about what to print; the thing that's not clear to me is what the
user-level knob for it should look like. We already used up the
option of more or fewer -v switches.
regards, tom lane
Re: Frontend error logging style
At Wed, 10 Nov 2021 14:25:08 -0500, Tom Lane wrote in
> I wrote:
> > Hmm, interesting. Taking up my point #2, I'd been thinking about
> > proposing that we convert
> > pg_log_error("query failed: %s", PQerrorMessage(conn));
> > pg_log_error("query was: %s", todo);
> > to
> > pg_log_error("query failed: %s", PQerrorMessage(conn));
> > pg_log_error_detail("Query was: %s", todo);
>
> After looking around a bit, I see that a lot of these add-on messages
> are more nearly hints than details, so we'd probably better support
> both those cases right off the bat.
Sounds reasonable.
> To move things along a bit, here's a draft patch to logging.h/.c only
> to implement what I'm envisioning. I don't think there's much point
> in doing the per-call-site gruntwork until we have agreement on what
> the API is, so this seems like enough for discussion.
>
> (As a fervent hater of colorization, I don't have an opinion about
> whether or how to colorize the "detail:" and "hint:" fragments.
> But I'll happily take somebody else's adjustment to add that.)
(:) I don't hate colorization so much, but I'm frequently annoyed by
needing to turn off colorization and I disgust when there's no easy
way to disable that in a simple steps..)
Aren't DETAIL and HINT expected to be hidden at the targetted cutoff
level? In other words, I suspect that people want to hide non-primary
messages for a lower verbosity level. On the other hand I'm not sure
it is a proper behavior that log_level = WARNING causes ERROR messages
are accompanied by DETAIL/HINT submessages...
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Re: Frontend error logging style
I wrote:
> Hmm, interesting. Taking up my point #2, I'd been thinking about
> proposing that we convert
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error("query was: %s", todo);
> to
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error_detail("Query was: %s", todo);
After looking around a bit, I see that a lot of these add-on messages
are more nearly hints than details, so we'd probably better support
both those cases right off the bat.
To move things along a bit, here's a draft patch to logging.h/.c only
to implement what I'm envisioning. I don't think there's much point
in doing the per-call-site gruntwork until we have agreement on what
the API is, so this seems like enough for discussion.
(As a fervent hater of colorization, I don't have an opinion about
whether or how to colorize the "detail:" and "hint:" fragments.
But I'll happily take somebody else's adjustment to add that.)
regards, tom lane
diff --git a/src/common/logging.c b/src/common/logging.c
index fb1a9b1f87..84a4cdfd1f 100644
--- a/src/common/logging.c
+++ b/src/common/logging.c
@@ -151,6 +151,9 @@ pg_logging_init(const char *argv0)
}
}
+/*
+ * Change the logging flags.
+ */
void
pg_logging_config(int new_flags)
{
@@ -194,17 +197,19 @@ pg_logging_set_locus_callback(void (*cb) (const char **filename, uint64 *lineno)
}
void
-pg_log_generic(enum pg_log_level level, const char *pg_restrict fmt,...)
+pg_log_generic(enum pg_log_level level, enum pg_log_part part,
+ const char *pg_restrict fmt,...)
{
va_list ap;
va_start(ap, fmt);
- pg_log_generic_v(level, fmt, ap);
+ pg_log_generic_v(level, part, fmt, ap);
va_end(ap);
}
void
-pg_log_generic_v(enum pg_log_level level, const char *pg_restrict fmt, va_list ap)
+pg_log_generic_v(enum pg_log_level level, enum pg_log_part part,
+ const char *pg_restrict fmt, va_list ap)
{
int save_errno = errno;
const char *filename = NULL;
@@ -232,7 +237,8 @@ pg_log_generic_v(enum pg_log_level level, const char *pg_restrict fmt, va_list a
fmt = _(fmt);
- if (!(log_flags & PG_LOG_FLAG_TERSE) || filename)
+ if (part == PG_LOG_PRIMARY &&
+ (!(log_flags & PG_LOG_FLAG_TERSE) || filename))
{
if (sgr_locus)
fprintf(stderr, ANSI_ESCAPE_FMT, sgr_locus);
@@ -251,30 +257,34 @@ pg_log_generic_v(enum pg_log_level level, const char *pg_restrict fmt, va_list a
if (!(log_flags & PG_LOG_FLAG_TERSE))
{
- switch (level)
+ switch (part)
{
- case PG_LOG_FATAL:
-if (sgr_error)
- fprintf(stderr, ANSI_ESCAPE_FMT, sgr_error);
-fprintf(stderr, _("fatal: "));
-if (sgr_error)
- fprintf(stderr, ANSI_ESCAPE_RESET);
-break;
- case PG_LOG_ERROR:
-if (sgr_error)
- fprintf(stderr, ANSI_ESCAPE_FMT, sgr_error);
-fprintf(stderr, _("error: "));
-if (sgr_error)
- fprintf(stderr, ANSI_ESCAPE_RESET);
+ case PG_LOG_PRIMARY:
+switch (level)
+{
+ case PG_LOG_ERROR:
+ if (sgr_error)
+ fprintf(stderr, ANSI_ESCAPE_FMT, sgr_error);
+ fprintf(stderr, _("error: "));
+ if (sgr_error)
+ fprintf(stderr, ANSI_ESCAPE_RESET);
+ break;
+ case PG_LOG_WARNING:
+ if (sgr_warning)
+ fprintf(stderr, ANSI_ESCAPE_FMT, sgr_warning);
+ fprintf(stderr, _("warning: "));
+ if (sgr_warning)
+ fprintf(stderr, ANSI_ESCAPE_RESET);
+ break;
+ default:
+ break;
+}
break;
- case PG_LOG_WARNING:
-if (sgr_warning)
- fprintf(stderr, ANSI_ESCAPE_FMT, sgr_warning);
-fprintf(stderr, _("warning: "));
-if (sgr_warning)
- fprintf(stderr, ANSI_ESCAPE_RESET);
+ case PG_LOG_DETAIL:
+fprintf(stderr, _("detail: "));
break;
- default:
+ case PG_LOG_HINT:
+fprintf(stderr, _("hint: "));
break;
}
}
diff --git a/src/include/common/logging.h b/src/include/common/logging.h
index a71cf84249..ec589ccd03 100644
--- a/src/include/common/logging.h
+++ b/src/include/common/logging.h
@@ -16,7 +16,7 @@
enum pg_log_level
{
/*
- * Not initialized yet
+ * Not initialized yet (not to be used as an actual message log level).
*/
PG_LOG_NOTSET = 0,
@@ -43,20 +43,42 @@ enum pg_log_level
PG_LOG_ERROR,
/*
- * Severe errors that cause program termination. (One-shot programs may
- * chose to label even fatal errors as merely "errors". The distinction
- * is up to the program.)
- */
- PG_LOG_FATAL,
-
- /*
- * Turn all logging off.
+ * Turn all logging off (not to be used as an actual message log level).
*/
PG_LOG_OFF,
};
+/*
+ * __pg_log_level is the minimum log level that will actually be shown.
+ */
extern enum pg_log_level __pg_log_level;
+/*
+ * A log message can have several parts. The primary message is required,
+ * others are optional. When emitting multiple parts, do so in the order of
+ * this enum, for consistency.
+ */
+enum pg_log_part
+{
+ /*
+ * The primary message. Try to keep it to
Re: Frontend error logging style
Robert Haas writes:
> I agree with this list of problems. I think that the end game here is
> getting to be able to use ereport() and friends in the frontend, which
> would require confronting both of these issues at a deep level. We
> don't necessarily have to do that now, though, but I think it's an
> argument against just nuking "fatal" from orbit. What I think we ought
> to be driving towards is having pg_log_fatal() forcibly exit, and
> pg_log_error() do the same unless the error is somehow caught.
Perhaps. The usage that I'm concerned about is exemplified by this
common pattern:
pg_log_error("%s", PQerrorMessage(conn));
PQfinish(conn);
exit(1);
ie there's some cleanup you want to do between emitting the error and
actually exiting. (I grant that maybe someday the PQfinish could be
done in an atexit handler or the like, but that's way more redesign
than I want to do right now.) In the case where you *don't* have
any cleanup to do, though, it'd be nice to just write one line not
two.
That leads me to think that we should redefine pg_log_fatal as
#define pg_log_fatal(...) (pg_log_error(__VA_ARGS__), exit(1))
We still want to get rid of the distinct PG_LOG_FATAL log level,
because whether you are using this form of pg_log_fatal or writing
exit() separately is a coding detail that should not manifest
as visibly distinct user output.
This proposal doesn't move us very far towards your endgame,
but I think it's a reasonable incremental step, and it makes
the difference between pg_log_error() and pg_log_fatal()
clear and useful.
> I have been wondering for some time about trying to make the frontend
> and backend facilities symmetric and using case to distinguish. That
> is, if you see:
> ERROR: this stinks
> DETAIL: It smells very bad.
> CONTEXT: garbage dump
> ...well then that's a backend message. And if you see:
> error: this stinks
> detail: It smells very bad.
> context: garbage dump
> ...well then that's a frontend message. I don't completely love that
> way of making a distinction, but I think we need something, and that's
> pretty nearly the present practice at least for the primary message.
> We don't really have a solid convention for detail/context/hint on the
> FE side; this is one idea.
Hmm, interesting. Taking up my point #2, I'd been thinking about
proposing that we convert
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error("query was: %s", todo);
to
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error_detail("Query was: %s", todo);
and similarly add a pg_log_info_detail() companion for pg_log_info(), etc.
With your point above, the prefix these'd print would be "detail:" not
"DETAIL:", but otherwise it seems to match up pretty well.
Also, if we are modeling this on backend conventions, we should say that
style rules for pg_log_error_detail match those for errdetail(), with
complete sentences and so forth. I wonder whether "detail:" followed
by a capitalized sentence would look weird ... but you did it above,
so maybe that's what people would expect.
Again, there's more that could be done later, but this seems to be
enough to address the cases that people have been inventing ad-hoc
solutions for.
regards, tom lane
Re: Frontend error logging style
On Tue, Nov 9, 2021 at 5:20 PM Tom Lane wrote: > 1. The distinction between "error" and "fatal" levels seems squishy > to the point of uselessness. > > 2. What is the preferred style for adding extra lines to log messages? I agree with this list of problems. I think that the end game here is getting to be able to use ereport() and friends in the frontend, which would require confronting both of these issues at a deep level. We don't necessarily have to do that now, though, but I think it's an argument against just nuking "fatal" from orbit. What I think we ought to be driving towards is having pg_log_fatal() forcibly exit, and pg_log_error() do the same unless the error is somehow caught. That might require more changes than you or whoever wants to do right now, so perhaps what we ought to do is just enforce the policy you suggested before: if we're going to exit immediately afterward, it's fatal; if not, it's an error. I have been wondering for some time about trying to make the frontend and backend facilities symmetric and using case to distinguish. That is, if you see: ERROR: this stinks DETAIL: It smells very bad. CONTEXT: garbage dump ...well then that's a backend message. And if you see: error: this stinks detail: It smells very bad. context: garbage dump ...well then that's a frontend message. I don't completely love that way of making a distinction, but I think we need something, and that's pretty nearly the present practice at least for the primary message. We don't really have a solid convention for detail/context/hint on the FE side; this is one idea. -- Robert Haas EDB: http://www.enterprisedb.com
Re: Frontend error logging style
At Tue, 09 Nov 2021 17:20:41 -0500, Tom Lane wrote in
> ISTM that the recently-introduced new frontend logging support
> (common/logging.h et al) could use a second pass now that we have
> some experience with it. There are two points that are bugging me:
>
> 1. The distinction between "error" and "fatal" levels seems squishy
> to the point of uselessness. I think we should either get rid of it
> entirely, or make an effort to use "fatal" exactly for the cases that
> are going to give up and exit right away. Of the approximately 830
> pg_log_error calls in HEAD, I count at least 450 that are immediately
> followed by exit(1), and so should be pg_log_fatal if this distinction
> means anything at all. OTOH, if we decide it doesn't mean anything,
> there are only about 90 pg_log_fatal calls to convert. I lean
> slightly to the "get rid of the distinction" option, not only because
> it'd be a much smaller patch but also because I don't care to expend
> brain cells on the which-to-use question while reviewing future
> patches.
Agreed. On backends, FATAL is bound to a behavior defferent from
ERROR. I doubt of the necessity of the difference between the two on
a console application (or frontend in PG-term). I would prefer to get
rid of the FATAL level.
I once thought ERROR should cause outoright end of an application, but
things don't seem so simple..
> 2. What is the preferred style for adding extra lines to log messages?
> I see a lot of direct prints to stderr:
>
> pg_log_error("missing required argument: database name");
> fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
> progname);
> exit(1);
>
> but a number of places have chosen to do this:
>
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error("query was: %s", todo);
>
> and some places got creative and did this:
>
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_info("query was: %s", sql.data);
In the first place the pg_log_info doesn't work at all since pgbench
doesn't make the log-level go below PG_LOG_INFO. (--quiet works the
different way..) In that case the pg_log_info can even be said to be
used just to avoid the message from being prepended by a severity tag.
I think we should fix that.
> I think this ought to be cleaned up so we have a more-or-less uniform
> approach. Aside from the randomly different source code, each of
> these choices has different implications for whether the extra line
> gets printed or not depending on verbosity level, and that seems bad.
>
> One plausible choice is to drop the first style (which surely has
> little to recommend it) and use either the second or third style
> depending on whether you think the addendum ought to appear at the
> same or higher verbosity level as the main message. But we'd
> still be at hazard of people making randomly different choices
> about that in identical cases, as indeed the second and third
> examples show.
>
> Another idea is to reduce such cases to one call:
>
> pg_log_error("query failed: %s\nquery was: %s",
>PQerrorMessage(conn), sql.data);
>
> but I don't much like that: it knows more than it should about
> the presentation format, and it can't support hiding the detail
> portion at lower verbosity levels.
>
> So I'm not totally satisfied with these ideas, but I don't
> immediately have a better one.
>
> Thoughts?
Honestly I don't like that:p
The cause of the confusion is we are using verbosity to hide *a part
of* a grouped messages. We make distinction beween the two concepts
in the backend code but not in frontend. At least in pgbench, it
seems to me as if the severity tag prepended by the pg_log_hoge
functions is mere a label just to be shown on console.
That being said it is a kind of impssible to expect users to specify
the two independent levels on command line.
Couldn't we have a function, say, named as "pg_log_error_detail",
which prints the message when __pg_log_level is *above* ERROR and
prepended by "detail:" tag? (or not showing the tag, keeping the
current behavior on surface.) We would have the same for
pg_log_warning. (pg_log_error_detail behaves a bit differetnly from
pg_log_info in this definition.)
> pg_log_error("query failed: %s", PQerrorMessage(conn));
> pg_log_error_detail("query was: %s", sql.data);
So pg_log_generic(_v) have an additional parameter, say, detailed bool.
pg_log_generic(enum pg_log_level level, bool detailed, const char *pg_restrict
fmt,...)
Considering that the level is used only to identify severity tag
string, it is somewhat strange that the detailed flag conflicts with
it. But I'm not sure it is sane to add instead an extra-and-hidden log
level to pg_log_level..
Or as a simpler way, we could just have aliases for pg_log_info().
#define pg_log_error_detail(...)
Frontend error logging style
ISTM that the recently-introduced new frontend logging support
(common/logging.h et al) could use a second pass now that we have
some experience with it. There are two points that are bugging me:
1. The distinction between "error" and "fatal" levels seems squishy
to the point of uselessness. I think we should either get rid of it
entirely, or make an effort to use "fatal" exactly for the cases that
are going to give up and exit right away. Of the approximately 830
pg_log_error calls in HEAD, I count at least 450 that are immediately
followed by exit(1), and so should be pg_log_fatal if this distinction
means anything at all. OTOH, if we decide it doesn't mean anything,
there are only about 90 pg_log_fatal calls to convert. I lean
slightly to the "get rid of the distinction" option, not only because
it'd be a much smaller patch but also because I don't care to expend
brain cells on the which-to-use question while reviewing future
patches.
2. What is the preferred style for adding extra lines to log messages?
I see a lot of direct prints to stderr:
pg_log_error("missing required argument: database name");
fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
progname);
exit(1);
but a number of places have chosen to do this:
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_error("query was: %s", todo);
and some places got creative and did this:
pg_log_error("query failed: %s", PQerrorMessage(conn));
pg_log_info("query was: %s", sql.data);
I think this ought to be cleaned up so we have a more-or-less uniform
approach. Aside from the randomly different source code, each of
these choices has different implications for whether the extra line
gets printed or not depending on verbosity level, and that seems bad.
One plausible choice is to drop the first style (which surely has
little to recommend it) and use either the second or third style
depending on whether you think the addendum ought to appear at the
same or higher verbosity level as the main message. But we'd
still be at hazard of people making randomly different choices
about that in identical cases, as indeed the second and third
examples show.
Another idea is to reduce such cases to one call:
pg_log_error("query failed: %s\nquery was: %s",
PQerrorMessage(conn), sql.data);
but I don't much like that: it knows more than it should about
the presentation format, and it can't support hiding the detail
portion at lower verbosity levels.
So I'm not totally satisfied with these ideas, but I don't
immediately have a better one.
Thoughts?
regards, tom lane
