Thread: Emit extra debug message when executing extension script.
Patch attached. Helpful for debugging complex extension script problems.
Attachment
On 28.06.22 21:10, Jeff Davis wrote:
> + ereport(DEBUG1, errmsg("executing extension script: %s", filename));
This should either be elog or use errmsg_internal.
On Wed, Jun 29, 2022 at 9:26 AM Peter Eisentraut
<peter.eisentraut@enterprisedb.com> wrote:
> On 28.06.22 21:10, Jeff Davis wrote:
> > + ereport(DEBUG1, errmsg("executing extension script: %s", filename));
>
> This should either be elog or use errmsg_internal.
Why?
--
Robert Haas
EDB: http://www.enterprisedb.com
On Wed, 2022-06-29 at 21:39 -0400, Robert Haas wrote:
> > This should either be elog or use errmsg_internal.
>
> Why?
I didn't see a response, so I'm still using ereport(). I attached a new
version though that doesn't emit the actual script filename; instead
just the from/to version.
The output looks nicer and I don't have to worry about whether the user
should be able to know the share directory or not.
Regards,
Jeff Davis
Attachment
On Fri, Jul 01, 2022 at 03:24:27PM -0700, Jeff Davis wrote:
> + ereport(DEBUG1, errmsg("executing extension update script from version '%s' to '%s'", from_version,
version));
nitpick: I would suggest "executing extension script for update from
version X to Y."
I personally would rather this output the name of the file. If revealing
the directory is a concern, perhaps we could just trim everything but the
file name.
--
Nathan Bossart
Amazon Web Services: https://aws.amazon.com
On Fri, 2022-07-01 at 15:33 -0700, Nathan Bossart wrote:
> On Fri, Jul 01, 2022 at 03:24:27PM -0700, Jeff Davis wrote:
> > + ereport(DEBUG1, errmsg("executing extension update
> > script from version '%s' to '%s'", from_version, version));
>
> nitpick: I would suggest "executing extension script for update from
> version X to Y."
Thank you. Committed with minor modification to include the extension
name.
I did end up using Peter's suggestion. I reviewed other DEBUG messages
and it seems nearly all use elog() or errmsg_internal().
> I personally would rather this output the name of the file. If
> revealing
> the directory is a concern, perhaps we could just trim everything but
> the
> file name.
I could have slightly refactored the code to do this, but it didn't
quite seem worth it for a single debug message.
Regards,
Jeff Davis
On 2022-Jun-29, Robert Haas wrote:
> On Wed, Jun 29, 2022 at 9:26 AM Peter Eisentraut
> <peter.eisentraut@enterprisedb.com> wrote:
> > On 28.06.22 21:10, Jeff Davis wrote:
> > > + ereport(DEBUG1, errmsg("executing extension script: %s", filename));
> >
> > This should either be elog or use errmsg_internal.
>
> Why?
The reason is that errmsg() marks the message for translation, and we
don't want to burden translators with messages that are of little
interest to most users. Using either elog() or errmsg_internal()
avoids that.
--
Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/
"El sudor es la mejor cura para un pensamiento enfermo" (Bardia)
On Mon, Jul 4, 2022 at 5:27 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> On 2022-Jun-29, Robert Haas wrote:
> > On Wed, Jun 29, 2022 at 9:26 AM Peter Eisentraut
> > <peter.eisentraut@enterprisedb.com> wrote:
> > > On 28.06.22 21:10, Jeff Davis wrote:
> > > > + ereport(DEBUG1, errmsg("executing extension script: %s", filename));
> > >
> > > This should either be elog or use errmsg_internal.
> >
> > Why?
>
> The reason is that errmsg() marks the message for translation, and we
> don't want to burden translators with messages that are of little
> interest to most users. Using either elog() or errmsg_internal()
> avoids that.
Yeah, I'm aware of that in general, but I'm not quite clear on how we
decide that. Do we take the view that all debug-level messages need
not be translated?
--
Robert Haas
EDB: http://www.enterprisedb.com
On 2022-Jul-05, Robert Haas wrote:
> On Mon, Jul 4, 2022 at 5:27 AM Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> > On 2022-Jun-29, Robert Haas wrote:
> > > Why?
> >
> > The reason is that errmsg() marks the message for translation, and we
> > don't want to burden translators with messages that are of little
> > interest to most users. Using either elog() or errmsg_internal()
> > avoids that.
>
> Yeah, I'm aware of that in general, but I'm not quite clear on how we
> decide that. Do we take the view that all debug-level messages need
> not be translated?
Yes. I don't know about others, but I do.
I notice that we have a small number of other errmsg() uses in DEBUG
messages already. I don't think they're quite worth it. I mean, would
a user ever run amcheck with log level set to DEBUG, and care about
any of these messages? I think I wouldn't care.
contrib/amcheck/verify_heapam.c: ereport(DEBUG1,
contrib/amcheck/verify_heapam.c- (errcode(ERRCODE_READ_ONLY_SQL_TRANSACTION),
contrib/amcheck/verify_heapam.c- errmsg("cannot verify unlogged relation \"%s\" during recovery,
skipping",
contrib/amcheck/verify_nbtree.c: ereport(DEBUG1,
contrib/amcheck/verify_nbtree.c- (errcode(ERRCODE_READ_ONLY_SQL_TRANSACTION),
contrib/amcheck/verify_nbtree.c- errmsg("cannot verify unlogged index \"%s\" during recovery, skipping",
Why are these basic_archive messages translatable? Seems pointless.
contrib/basic_archive/basic_archive.c: ereport(DEBUG3,
contrib/basic_archive/basic_archive.c- (errmsg("archiving \"%s\" via basic_archive", file)));
contrib/basic_archive/basic_archive.c: ereport(DEBUG3,
contrib/basic_archive/basic_archive.c- (errmsg("archive file \"%s\" already exists with identical
contents",
contrib/basic_archive/basic_archive.c: ereport(DEBUG1,
contrib/basic_archive/basic_archive.c- (errmsg("archived \"%s\" via basic_archive", file)));
We also have a small number in the backend:
src/backend/access/heap/vacuumlazy.c: ereport(DEBUG2,
src/backend/access/heap/vacuumlazy.c- (errmsg("table \"%s\": removed %lld dead item identifiers in %u
pages",
src/backend/access/heap/vacuumlazy.c- vacrel->relname, (long long) index, vacuumed_pages)));
Why is this one unconditional DEBUG2 instead of depending on
LVRelState->message_level (ie. turn into INFO when VERBOSE is used),
like every other message from vacuum? It seems to me that if I say
VERBOSE, then I may be interested in this message also. While at it,
why are the index vacuuming routines not using LVRelState->message_level
either but instead hardcode DEBUG2? Aren't they all mistakes?
src/backend/replication/logical/worker.c: ereport(DEBUG1,
src/backend/replication/logical/worker.c- (errmsg("logical replication apply worker for subscription
\"%s\"two_phase is %s",
src/backend/replication/logical/worker.c- MySubscription->name,
Not sure why anybody cares about this. Why not remove the message?
src/backend/utils/activity/pgstat.c: ereport(DEBUG2,
src/backend/utils/activity/pgstat.c- (errcode_for_file_access(),
src/backend/utils/activity/pgstat.c- errmsg("unlinked permanent statistics file \"%s\"",
Hmm, why is there an errcode here, after the operation succeeds? ISTM
this could be an elog().
Then we have this one:
ereport(DEBUG1,
(errcode(ERRCODE_INTERNAL_ERROR),
errmsg("picksplit method for column %d of index \"%s\" failed",
attno + 1, RelationGetRelationName(r)),
errhint("The index is not optimal. To optimize it, contact a developer, or try to use the column as
thesecond one in the CREATE INDEX command.")));
I cannot understand how is DEBUG1 a useful log level for this message.
How is the user going to find out that there is a problem, when this
message is hidden from them? Do we tell people to run their insert
queries for tables with GiST indexes under DEBUG1, in case the picksplit
method fails, so that they can contact a developer? How many
user-defined picksplit methods have been improved to cope with this
problem, since commit 09368d23dbf4 added this bit in April 2009? How
many of them have been presenting the problem since then, and not been
fixed because nobody has noticed that there is a problem?
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/