"Unified logging system" breaks access to pg_dump debug outputs

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

"Unified logging system" breaks access to pg_dump debug outputs

Tom Lane-2
pg_dump et al have some low-level debug log messages that commit
cc8d41511 converted to pg_log_debug() calls, replacing the previous
one-off logging verbosity system that was there.  However, these
calls are dead code as things stand, because there is no way to set
__pg_log_level high enough to get them to print.

I propose the attached minimal patch to restore the previous
functionality.

Alternatively, we might consider inventing an additional logging.c
function pg_logging_increase_level() with the obvious semantics, and
make the various programs just call that when they see a -v switch.
That would be a slightly bigger patch, but it would more easily support
programs with a range of useful verbosities, so maybe that's a better
idea.

In a quick look around, I could not find any other unreachable
pg_log_debug calls.

(Note: it seems possible that the theoretical multiple verbosity
levels in pg_dump were already broken before cc8d41511, because
right offhand I do not see any code that that removed that would
have allowed invoking the higher levels either.  Nonetheless, there
is no point in carrying dead code --- and these messages *are*
of some interest.  I discovered this problem while trying to
debug parallel pg_restore behavior just now, and wondering
why "-v -v" didn't produce the messages I saw in the source code.)

                        regards, tom lane


diff --git a/src/bin/pg_dump/pg_dump.c b/src/bin/pg_dump/pg_dump.c
index 784bceaec3..08a2976a6b 100644
--- a/src/bin/pg_dump/pg_dump.c
+++ b/src/bin/pg_dump/pg_dump.c
@@ -511,8 +511,11 @@ main(int argc, char **argv)
  break;
 
  case 'v': /* verbose */
+ if (g_verbose)
+ pg_logging_set_level(PG_LOG_DEBUG); /* -v -v */
+ else
+ pg_logging_set_level(PG_LOG_INFO);
  g_verbose = true;
- pg_logging_set_level(PG_LOG_INFO);
  break;
 
  case 'w':
diff --git a/src/bin/pg_dump/pg_dumpall.c b/src/bin/pg_dump/pg_dumpall.c
index 97d2b8dac1..11eeb36aa1 100644
--- a/src/bin/pg_dump/pg_dumpall.c
+++ b/src/bin/pg_dump/pg_dumpall.c
@@ -282,8 +282,11 @@ main(int argc, char *argv[])
  break;
 
  case 'v':
+ if (verbose)
+ pg_logging_set_level(PG_LOG_DEBUG); /* -v -v */
+ else
+ pg_logging_set_level(PG_LOG_INFO);
  verbose = true;
- pg_logging_set_level(PG_LOG_INFO);
  appendPQExpBufferStr(pgdumpopts, " -v");
  break;
 
diff --git a/src/bin/pg_dump/pg_restore.c b/src/bin/pg_dump/pg_restore.c
index 544ae3bc5c..af04aa0787 100644
--- a/src/bin/pg_dump/pg_restore.c
+++ b/src/bin/pg_dump/pg_restore.c
@@ -244,8 +244,11 @@ main(int argc, char **argv)
  break;
 
  case 'v': /* verbose */
+ if (opts->verbose)
+ pg_logging_set_level(PG_LOG_DEBUG); /* -v -v */
+ else
+ pg_logging_set_level(PG_LOG_INFO);
  opts->verbose = 1;
- pg_logging_set_level(PG_LOG_INFO);
  break;
 
  case 'w':
Reply | Threaded
Open this post in threaded view
|

Re: "Unified logging system" breaks access to pg_dump debug outputs

Tom Lane-2
I wrote:
> Alternatively, we might consider inventing an additional logging.c
> function pg_logging_increase_level() with the obvious semantics, and
> make the various programs just call that when they see a -v switch.
> That would be a slightly bigger patch, but it would more easily support
> programs with a range of useful verbosities, so maybe that's a better
> idea.

After further thought, I concluded that's a clearly superior solution,
so 0001 attached does it like that.  After noting that the enum values
are in the opposite direction from how I thought they went, I realized
that "increase_level" might be a bit ambiguous, so I now propose to
call it pg_logging_increase_verbosity.

> (Note: it seems possible that the theoretical multiple verbosity
> levels in pg_dump were already broken before cc8d41511, because
> right offhand I do not see any code that that removed that would
> have allowed invoking the higher levels either.

Closer inspection says this was almost certainly true, because
I discovered that pg_dump -v -v crashes if you don't specify
an output filename :-(.  So this has probably been unreachable
at least since we went over to using our own snprintf always;
before that, depending on platform, it might've been fine.
So we also need 0002 attached to fix that.

                        regards, tom lane


diff --git a/src/bin/pg_archivecleanup/pg_archivecleanup.c b/src/bin/pg_archivecleanup/pg_archivecleanup.c
index e454bae767..12338e3bb2 100644
--- a/src/bin/pg_archivecleanup/pg_archivecleanup.c
+++ b/src/bin/pg_archivecleanup/pg_archivecleanup.c
@@ -302,7 +302,7 @@ main(int argc, char **argv)
  switch (c)
  {
  case 'd': /* Debug mode */
- pg_logging_set_level(PG_LOG_DEBUG);
+ pg_logging_increase_verbosity();
  break;
  case 'n': /* Dry-Run mode */
  dryrun = true;
diff --git a/src/bin/pg_dump/pg_dump.c b/src/bin/pg_dump/pg_dump.c
index 784bceaec3..53432acefc 100644
--- a/src/bin/pg_dump/pg_dump.c
+++ b/src/bin/pg_dump/pg_dump.c
@@ -512,7 +512,7 @@ main(int argc, char **argv)
 
  case 'v': /* verbose */
  g_verbose = true;
- pg_logging_set_level(PG_LOG_INFO);
+ pg_logging_increase_verbosity();
  break;
 
  case 'w':
diff --git a/src/bin/pg_dump/pg_dumpall.c b/src/bin/pg_dump/pg_dumpall.c
index 97d2b8dac1..219ca963c3 100644
--- a/src/bin/pg_dump/pg_dumpall.c
+++ b/src/bin/pg_dump/pg_dumpall.c
@@ -283,7 +283,7 @@ main(int argc, char *argv[])
 
  case 'v':
  verbose = true;
- pg_logging_set_level(PG_LOG_INFO);
+ pg_logging_increase_verbosity();
  appendPQExpBufferStr(pgdumpopts, " -v");
  break;
 
diff --git a/src/bin/pg_dump/pg_restore.c b/src/bin/pg_dump/pg_restore.c
index 544ae3bc5c..eebf0d300b 100644
--- a/src/bin/pg_dump/pg_restore.c
+++ b/src/bin/pg_dump/pg_restore.c
@@ -245,7 +245,7 @@ main(int argc, char **argv)
 
  case 'v': /* verbose */
  opts->verbose = 1;
- pg_logging_set_level(PG_LOG_INFO);
+ pg_logging_increase_verbosity();
  break;
 
  case 'w':
diff --git a/src/bin/pg_rewind/pg_rewind.c b/src/bin/pg_rewind/pg_rewind.c
index 23fc749e44..0ec52cb032 100644
--- a/src/bin/pg_rewind/pg_rewind.c
+++ b/src/bin/pg_rewind/pg_rewind.c
@@ -181,7 +181,7 @@ main(int argc, char **argv)
 
  case 3:
  debug = true;
- pg_logging_set_level(PG_LOG_DEBUG);
+ pg_logging_increase_verbosity();
  break;
 
  case 'D': /* -D or --target-pgdata */
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 332eabf637..663d7d292a 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -5522,7 +5522,7 @@ main(int argc, char **argv)
  pgport = pg_strdup(optarg);
  break;
  case 'd':
- pg_logging_set_level(PG_LOG_DEBUG);
+ pg_logging_increase_verbosity();
  break;
  case 'c':
  benchmarking_option_set = true;
diff --git a/src/common/logging.c b/src/common/logging.c
index 6a3a437a34..d9632fffc8 100644
--- a/src/common/logging.c
+++ b/src/common/logging.c
@@ -157,12 +157,30 @@ pg_logging_config(int new_flags)
  log_flags = new_flags;
 }
 
+/*
+ * pg_logging_init sets the default log level to INFO.  Programs that prefer
+ * a different default should use this to set it, immediately afterward.
+ */
 void
 pg_logging_set_level(enum pg_log_level new_level)
 {
  __pg_log_level = new_level;
 }
 
+/*
+ * Command line switches such as --verbose should invoke this.
+ */
+void
+pg_logging_increase_verbosity(void)
+{
+ /*
+ * The enum values are chosen such that we have to decrease __pg_log_level
+ * in order to become more verbose.
+ */
+ if (__pg_log_level > PG_LOG_NOTSET + 1)
+ __pg_log_level--;
+}
+
 void
 pg_logging_set_pre_callback(void (*cb) (void))
 {
diff --git a/src/include/common/logging.h b/src/include/common/logging.h
index 028149c7a1..3205b8fef9 100644
--- a/src/include/common/logging.h
+++ b/src/include/common/logging.h
@@ -66,6 +66,7 @@ extern enum pg_log_level __pg_log_level;
 void pg_logging_init(const char *argv0);
 void pg_logging_config(int new_flags);
 void pg_logging_set_level(enum pg_log_level new_level);
+void pg_logging_increase_verbosity(void);
 void pg_logging_set_pre_callback(void (*cb) (void));
 void pg_logging_set_locus_callback(void (*cb) (const char **filename, uint64 *lineno));
 

diff --git a/src/bin/pg_dump/pg_backup_archiver.c b/src/bin/pg_dump/pg_backup_archiver.c
index c05a1fd6af..178b61d6cb 100644
--- a/src/bin/pg_dump/pg_backup_archiver.c
+++ b/src/bin/pg_dump/pg_backup_archiver.c
@@ -2278,7 +2278,8 @@ _allocAH(const char *FileSpec, const ArchiveFormat fmt,
 {
  ArchiveHandle *AH;
 
- pg_log_debug("allocating AH for %s, format %d", FileSpec, fmt);
+ pg_log_debug("allocating AH for %s, format %d",
+ FileSpec ? FileSpec : "(stdio)", fmt);
 
  AH = (ArchiveHandle *) pg_malloc0(sizeof(ArchiveHandle));
 
Reply | Threaded
Open this post in threaded view
|

Re: "Unified logging system" breaks access to pg_dump debug outputs

Alvaro Herrera-9
On 2020-Sep-15, Tom Lane wrote:

> I wrote:
> > Alternatively, we might consider inventing an additional logging.c
> > function pg_logging_increase_level() with the obvious semantics, and
> > make the various programs just call that when they see a -v switch.
> > That would be a slightly bigger patch, but it would more easily support
> > programs with a range of useful verbosities, so maybe that's a better
> > idea.
>
> After further thought, I concluded that's a clearly superior solution,
> so 0001 attached does it like that.  After noting that the enum values
> are in the opposite direction from how I thought they went, I realized
> that "increase_level" might be a bit ambiguous, so I now propose to
> call it pg_logging_increase_verbosity.

I like this better too ... I've wished for extra-verbose messages from
pg_dump in the past, and this now allows me to add something should I
want them again.

> > (Note: it seems possible that the theoretical multiple verbosity
> > levels in pg_dump were already broken before cc8d41511, because
> > right offhand I do not see any code that that removed that would
> > have allowed invoking the higher levels either.
>
> Closer inspection says this was almost certainly true, because
> I discovered that pg_dump -v -v crashes if you don't specify
> an output filename :-(.  So this has probably been unreachable
> at least since we went over to using our own snprintf always;
> before that, depending on platform, it might've been fine.
> So we also need 0002 attached to fix that.

Ugh.

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


Reply | Threaded
Open this post in threaded view
|

Re: "Unified logging system" breaks access to pg_dump debug outputs

Tom Lane-2
Alvaro Herrera <[hidden email]> writes:
> On 2020-Sep-15, Tom Lane wrote:
>> After further thought, I concluded that's a clearly superior solution,
>> so 0001 attached does it like that.  After noting that the enum values
>> are in the opposite direction from how I thought they went, I realized
>> that "increase_level" might be a bit ambiguous, so I now propose to
>> call it pg_logging_increase_verbosity.

> I like this better too ... I've wished for extra-verbose messages from
> pg_dump in the past, and this now allows me to add something should I
> want them again.

Pushed, thanks for reviewing.

                        regards, tom lane