Fixed an issue that prevented errors from being output to the console before the logging system was initialized.

That is, while parsing options. Error codes were still being returned accurately so this would not have made a process look like it succeeded when it did not.

doc/xml/release.xml

@@ -137,7 +137,11 @@
             <release-core-list>
                 <release-bug-list>
                     <release-item>
-                        <p>Fixed a bug where internal symlinks were not being created for tablespaces in the repository.  This issue was only apparent when trying to bring up clusters in-place manually using filesystem snapshots and did not affect normal backup and restore.</p>
+                        <p>Fixed an issue where internal symlinks were not being created for tablespaces in the repository.  This issue was only apparent when trying to bring up clusters in-place manually using filesystem snapshots and did not affect normal backup and restore.</p>
+                    </release-item>
+
+                    <release-item>
+                        <p>Fixed an issue that prevented errors from being output to the console before the logging system was initialized, i.e. while parsing options. Error codes were still being returned accurately so this would not have made a process look like it succeeded when it did not.</p>
                     </release-item>
                 </release-bug-list>
 
@@ -185,7 +189,7 @@
             <release-doc-list>
                 <release-bug-list>
                     <release-item>
-                        <p>Fixed and issue that suppressed exceptions in PDF builds.</p>
+                        <p>Fixed an issue that suppressed exceptions in PDF builds.</p>
                     </release-item>
 
                     <release-item>
@@ -245,7 +249,7 @@
                             <release-item-contributor id="shang.cynthia"/>
                         </release-item-contributor-list>
 
-                        <p>Update control and wal test files to <id>9.4</id> with matching system identifiers.</p>
+                        <p>Update control and WAL test files to <id>9.4</id> with matching system identifiers.</p>
                     </release-item>
 
                     <release-item>

lib/pgBackRest/Archive.pm

@@ -1145,10 +1145,7 @@ sub check
         or do
         {
             # Confess unhandled errors
-            if (!isException($EVAL_ERROR))
+            confess $EVAL_ERROR if (!isException($EVAL_ERROR));
-            {
-                confess $EVAL_ERROR;
-            }
 
             # If this is a backrest error then capture the last code and message
             $iResult = $EVAL_ERROR->code();
@@ -1168,10 +1165,7 @@ sub check
         or do
         {
             # Confess unhandled errors
-            if (!isException($EVAL_ERROR))
+            confess $EVAL_ERROR if (!isException($EVAL_ERROR));
-            {
-                confess $EVAL_ERROR;
-            }
 
             # If this is a backrest error then capture the last code and message
             $iResult = $EVAL_ERROR->code();
@@ -1188,9 +1182,9 @@ sub check
             $self->getBackupInfoCheck($oFile);
             return true;
         }
-        # If there is an error but it is not that the file is missing then confess
         or do
         {
+            # If there is an error but it is not that the file is missing then confess
             if (!isException($EVAL_ERROR) || $EVAL_ERROR->code() != ERROR_PATH_MISSING)
             {
                 confess $EVAL_ERROR;

lib/pgBackRest/Common/Exception.pm

@@ -166,6 +166,7 @@ sub new
     my $iCode = shift;       # Error code
     my $strMessage = shift;  # ErrorMessage
     my $strTrace = shift;    # Stack trace
+    my $rExtra = shift;      # Extra info used exclusively by the logging system
 
     if ($iCode < ERROR_MINIMUM || $iCode > ERROR_MAXIMUM)
     {
@@ -181,6 +182,7 @@ sub new
     $self->{iCode} = $iCode;
     $self->{strMessage} = $strMessage;
     $self->{strTrace} = $strTrace;
+    $self->{rExtra} = $rExtra;
 
     return $self;
 }
@@ -205,6 +207,16 @@ sub code
     return $self->{iCode};
 }
 
+####################################################################################################################################
+# extra
+####################################################################################################################################
+sub extra
+{
+    my $self = shift;
+
+    return $self->{rExtra};
+}
+
 ####################################################################################################################################
 # MESSAGE
 ####################################################################################################################################

lib/pgBackRest/Common/Exit.pm

@@ -55,6 +55,10 @@ sub exitSafe
             {name => 'strSignal', required => false},
         );
 
+    # Reset logging in case it was disabled when the exception/signal occurred
+    configLogging();
+
+    # Log command stop
     commandStop();
 
     # Close the remote
@@ -74,6 +78,7 @@ sub exitSafe
         if (isException($oException))
         {
             $iExitCode = $oException->code();
+            logException($oException);
         }
         else
         {

lib/pgBackRest/Common/Log.pm

@@ -67,7 +67,7 @@ my $strLogFileCache = undef;
 
 my $strLogLevelFile = OFF;
 my $strLogLevelConsole = OFF;
-my $strLogLevelStdOut = OFF;
+my $strLogLevelStdErr = WARN;
 
 # Test globals
 my $bTest = false;
@@ -144,7 +144,7 @@ sub logLevelSet
 {
     my $strLevelFileParam = shift;
     my $strLevelConsoleParam = shift;
-    my $strLevelStdOutParam = shift;
+    my $strLevelStdErrParam = shift;
 
     # Load FileCommon module
     require pgBackRest::FileCommon;
@@ -170,14 +170,14 @@ sub logLevelSet
         $strLogLevelConsole = uc($strLevelConsoleParam);
     }
 
-    if (defined($strLevelStdOutParam))
+    if (defined($strLevelStdErrParam))
     {
-        if (!defined($oLogLevelRank{uc($strLevelStdOutParam)}{rank}))
+        if (!defined($oLogLevelRank{uc($strLevelStdErrParam)}{rank}))
         {
-            confess &log(ERROR, "stdout log level ${strLevelStdOutParam} does not exist");
+            confess &log(ERROR, "stdout log level ${strLevelStdErrParam} does not exist");
         }
 
-        $strLogLevelStdOut = uc($strLevelStdOutParam);
+        $strLogLevelStdErr = uc($strLevelStdErrParam);
     }
 }
 
@@ -367,7 +367,7 @@ sub logDebugOut
 
     if ($oLogLevelRank{$strLevel}{rank} <= $oLogLevelRank{$strLogLevelConsole}{rank} ||
         $oLogLevelRank{$strLevel}{rank} <= $oLogLevelRank{$strLogLevelFile}{rank} ||
-        $oLogLevelRank{$strLevel}{rank} <= $oLogLevelRank{$strLogLevelStdOut}{rank})
+        $oLogLevelRank{$strLevel}{rank} <= $oLogLevelRank{$strLogLevelStdErr}{rank})
     {
         if (defined($oParamHash))
         {
@@ -473,6 +473,18 @@ sub logDebugOut
     }
 }
 
+####################################################################################################################################
+# logException
+####################################################################################################################################
+sub logException
+{
+    my $oException = shift;
+
+    return &log($oException->level(), $oException->message(), $oException->code(), undef, undef, undef, $oException->extra());
+}
+
+push @EXPORT, qw(logException);
+
 ####################################################################################################################################
 # LOG - log messages
 ####################################################################################################################################
@@ -484,10 +496,21 @@ sub log
     my $bSuppressLog = shift;
     my $iIndent = shift;
     my $iProcessId = shift;
+    my $rExtra = shift;
 
     # Set defaults
     $bSuppressLog = defined($bSuppressLog) ? $bSuppressLog : false;
 
+    # Initialize rExtra
+    if (!defined($rExtra))
+    {
+        $rExtra =
+        {
+            bLogFile => false,
+            bLogConsole => false,
+        };
+    }
+
     # Set operational variables
     my $strMessageFormat = $strMessage;
     my $iLogLevelRank = $oLogLevelRank{"${strLevel}"}{rank};
@@ -562,12 +585,13 @@ sub log
         (' ' x (7 - length($strLevel))) . "${strLevel}: ${strMessageFormat}\n";
 
     # Output to stderr depending on log level
-    if ($iLogLevelRank <= $oLogLevelRank{$strLogLevelStdOut}{rank})
+    if (!$rExtra->{bLogConsole} && $iLogLevelRank <= $oLogLevelRank{$strLogLevelStdErr}{rank})
     {
         syswrite(*STDERR, $strLevel . (defined($iCode) ? " [${iCode}]" : '') . ": $strMessage\n");
+        $rExtra->{bLogConsole} = true;
     }
     # Else output to stdout depending on log level and test flag
-    elsif ($iLogLevelRank <= $oLogLevelRank{$strLogLevelConsole}{rank} || $bTest && $strLevel eq TEST)
+    elsif (!$rExtra->{bLogConsole} && $iLogLevelRank <= $oLogLevelRank{$strLogLevelConsole}{rank} || $bTest && $strLevel eq TEST)
     {
         if (!$bSuppressLog)
         {
@@ -579,10 +603,12 @@ sub log
         {
             usleep($fTestDelay * 1000000);
         }
+
+        $rExtra->{bLogConsole} = true;
     }
 
     # Output to file depending on log level and test flag
-    if ($iLogLevelRank <= $oLogLevelRank{$strLogLevelFile}{rank})
+    if (!$rExtra->{bLogLogFile} && $iLogLevelRank <= $oLogLevelRank{$strLogLevelFile}{rank})
     {
         if (defined($hLogFile) || (defined($strLogLevelFile) && $strLogLevelFile ne OFF))
         {
@@ -614,12 +640,14 @@ sub log
                 }
             }
         }
+
+        $rExtra->{bLogFile} = true;
     }
 
     # Throw a typed exception if code is defined
     if (defined($iCode))
     {
-        return new pgBackRest::Common::Exception($strLevel, $iCode, $strMessage, longmess());
+        return new pgBackRest::Common::Exception($strLevel, $iCode, $strMessage, longmess(), $rExtra);
     }
 
     # Return the message test so it can be used in a confess

lib/pgBackRest/Config/Config.pm

@@ -1867,6 +1867,29 @@ my %oOptionRule =
 ####################################################################################################################################
 my %oOption;                # Option hash
 my $strCommand;             # Command (backup, archive-get, ...)
+my $bInitLog = false;       # Has logging been initialized yet?
+
+####################################################################################################################################
+# configLogging
+#
+# Configure logging based on options.
+####################################################################################################################################
+sub configLogging
+{
+    my $bLogInitForce = shift;
+
+    if (($bInitLog || (defined($bLogInitForce) && $bLogInitForce)) && !commandTest(CMD_REMOTE) && !commandTest(CMD_LOCAL))
+    {
+        logLevelSet(
+            optionValid(OPTION_LOG_LEVEL_FILE) ? optionGet(OPTION_LOG_LEVEL_FILE) : OFF,
+            optionValid(OPTION_LOG_LEVEL_CONSOLE) ? optionGet(OPTION_LOG_LEVEL_CONSOLE) : OFF,
+            optionValid(OPTION_LOG_LEVEL_STDERR) ? optionGet(OPTION_LOG_LEVEL_STDERR) : OFF);
+
+        $bInitLog = true;
+    }
+}
+
+push @EXPORT, qw(configLogging);
 
 ####################################################################################################################################
 # configLoad
@@ -1877,9 +1900,6 @@ sub configLoad
 {
     my $bInitLogging = shift;
 
-    # Determine if logging should be initialized
-    $bInitLogging = (!defined($bInitLogging) ? true : $bInitLogging);
-
     # Clear option in case it was loaded before
     %oOption = ();
 
@@ -2003,13 +2023,11 @@ sub configLoad
     }
 
     # If this is not the remote and logging is allowed (to not overwrite log levels for tests) then set the log level so that
-    # INFO/WARN messages can be displayed (the user may still disable them).
+    # INFO/WARN messages can be displayed (the user may still disable them).  This should be run before any WARN logging is
-    if (!commandTest(CMD_REMOTE) && !commandTest(CMD_LOCAL) && $bInitLogging)
+    # generated.
+    if (!defined($bInitLogging) || $bInitLogging)
     {
-        logLevelSet(
+        configLogging(true);
-            optionValid(OPTION_LOG_LEVEL_FILE) ? optionGet(OPTION_LOG_LEVEL_FILE) : OFF,
-            optionValid(OPTION_LOG_LEVEL_CONSOLE) ? optionGet(OPTION_LOG_LEVEL_CONSOLE) : OFF,
-            optionValid(OPTION_LOG_LEVEL_STDERR) ? optionGet(OPTION_LOG_LEVEL_STDERR) : OFF);
     }
 
     # Neutralize the umask to make the repository file/path modes more consistent

test/expect/backup-synthetic-001.log

@@ -330,6 +330,13 @@ db-version="9.4"
 [db:history]
 1={"db-catalog-version":201409291,"db-control-version":942,"db-system-id":6353949018581704918,"db-version":"9.4"}
 
+full backup - invalid cmd line (db-master host)
+> [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --no-online --type=full --stanza=bogus backup
+------------------------------------------------------------------------------------------------------------------------------------
+STDERR:
+ERROR [112]: backup command requires option: db-path
+HINT: does this stanza exist?
+
 stop all stanzas (db-master host)
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --force stop
 ------------------------------------------------------------------------------------------------------------------------------------

test/lib/pgBackRestTest/Backup/BackupTest.pm

@@ -967,6 +967,15 @@ sub backupTestRun
                  strTest => $strTestPoint,
                  fTestDelay => 0});
 
+            # Error on backup option to check logging
+            #-----------------------------------------------------------------------------------------------------------------------
+            if ($bNeutralTest && !$bRemote)
+            {
+                $oHostBackup->backup(
+                    $strType, 'invalid cmd line',
+                    {oExpectedManifest => \%oManifest, strStanza => 'bogus', iExpectedExitStatus => ERROR_OPTION_REQUIRED});
+            }
+
             # Test protocol timeout
             #-----------------------------------------------------------------------------------------------------------------------
             if ($bNeutralTest && $bRemote)

test/lib/pgBackRestTest/Backup/Common/HostBackupTest.pm

@@ -215,7 +215,7 @@ sub backupBegin
         (defined($$oParam{bStandby}) && $$oParam{bStandby} ? " --backup-standby" : '') .
         (defined($oParam->{bRepoLink}) && !$oParam->{bRepoLink} ? ' --no-repo-link' : '') .
         ($strType ne 'incr' ? " --type=${strType}" : '') .
-        ' --stanza=' . $self->stanza() . ' backup' .
+        ' --stanza=' . (defined($oParam->{strStanza}) ? $oParam->{strStanza} : $self->stanza()) . ' backup' .
         (defined($strTest) ? " --test --test-delay=${fTestDelay} --test-point=" . lc($strTest) . '=y' : ''),
         {strComment => $strComment, iExpectedExitStatus => $$oParam{iExpectedExitStatus},
          oLogTest => $self->{oLogTest}, bLogOutput => $self->synthetic()});
@@ -266,6 +266,13 @@ sub backupEnd
 
     return if ($oExecuteBackup->{iExpectedExitStatus} != 0);
 
+    # If an alternate stanza was specified
+    if (defined($oParam->{strStanza}))
+    {
+        confess &log(ASSERT,
+            'if an alternate stanza is specified it must generate an error - the remaining code will not be aware of the stanza');
+    }
+
     my $strBackup = $self->backupLast();
 
     # If a real backup then load the expected manifest from the actual manifest.  An expected manifest can't be generated perfectly

test/lib/pgBackRestTest/Common/ExecuteTest.pm

@@ -195,6 +195,11 @@ sub endRetry
     # Pass the log to the LogTest object
     if (defined($self->{oLogTest}))
     {
+        if (defined($self->{strErrorLog}) && $self->{strErrorLog} ne '')
+        {
+            $self->{strOutLog} .= "STDERR:\n" . $self->{strErrorLog};
+        }
+
         $self->{oLogTest}->logAdd($self->{strCommand}, $self->{strComment}, $self->{bLogOutput} ? $self->{strOutLog} : undef);
     }