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

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':

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));

Alvaro Herrera <alvherre@2ndquadrant.com> 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