Make archive-get info messages consistent between C and Perl implementations.

The info messages were spread around and logged differently based on the execution path and in some cases logged nothing at all.

Temporarily track the async server status with a flag so that info messages are not output in the async process.  The async process will be refactored as a separate command to be exec'd in a future commit.

doc/xml/release.xml

@@ -67,6 +67,10 @@
                     <release-item>
                         <p>Migrate control functions to detect stop files to C from Perl.</p>
                     </release-item>
+
+                    <release-item>
+                        <p>Make archive-get info messages consistent between C and Perl implementations.</p>
+                    </release-item>
                 </release-development-list>
             </release-core-list>
 

lib/pgBackRest/Archive/Get/Get.pm

@@ -75,7 +75,7 @@ sub process
 
         if (!defined($strSourceArchive))
         {
-            confess &log(ERROR, 'WAL segment not provided', ERROR_PARAM_REQUIRED);
+            confess &log(ERROR, 'WAL segment not provided', ERROR_ASSERT);
         }
 
         # Make sure the destination file is defined
@@ -83,20 +83,10 @@ sub process
 
         if (!defined($strDestinationFile))
         {
-            confess &log(ERROR, 'WAL segment destination not provided', ERROR_PARAM_REQUIRED);
+            confess &log(ERROR, 'WAL segment destination not provided', ERROR_ASSERT);
         }
 
         $iResult = archiveGetFile($strSourceArchive, $strDestinationFile, false);
-
-        # Info for the Postgres log
-        if ($iResult == 0)
-        {
-            &log(INFO, 'got WAL segment ' . $strSourceArchive);
-        }
-        else
-        {
-            &log(INFO, "unable to find ${strSourceArchive} in the archive");
-        }
     }
 
     # Return from function and log return values if any

src/command/archive/get/get.c

@@ -99,6 +99,7 @@ cmdArchiveGet(void)
 {
     FUNCTION_DEBUG_VOID(logLevelDebug);
 
+    // Set the result assuming the archive file will not be found
     int result = 1;
 
     MEM_CONTEXT_TEMP_BEGIN()
@@ -128,7 +129,9 @@ cmdArchiveGet(void)
             walDestination = strNewFmt("%s/%s", strPtr(cfgOptionStr(cfgOptPgPath)), strPtr(walDestination));
 
         // Async get can only be performed on WAL segments, history or other files must use synchronous mode
-        if (cfgOptionBool(cfgOptArchiveAsync) && regExpMatchOne(strNew(WAL_SEGMENT_REGEXP), walSegment))
+        bool asyncServer = false;
+
+        if (cfgOptionBool(cfgOptArchiveAsync) && walIsSegment(walSegment))
         {
             bool found = false;                                         // Has the WAL segment been found yet?
             bool queueFull = false;                                     // Is the queue half or more full?
@@ -146,8 +149,6 @@ cmdArchiveGet(void)
                 {
                     storageRemoveP(
                         storageSpool(), strNewFmt(STORAGE_SPOOL_ARCHIVE_IN "/%s.ok", strPtr(walSegment)), .errorOnMissing = true);
-
-                    LOG_INFO("unable to find WAL segment %s", strPtr(walSegment));
                     break;
                 }
 
@@ -175,8 +176,7 @@ cmdArchiveGet(void)
                     // Move (or copy if required) the file
                     storageMoveNP(source, destination);
 
-                    // Log success
+                    // Return success
-                    LOG_INFO("got WAL segment %s asynchronously", strPtr(walSegment));
                     result = 0;
 
                     // Get a list of WAL segments left in the queue
@@ -203,12 +203,13 @@ cmdArchiveGet(void)
                     // Fork off the async process
                     if (fork() == 0)
                     {
-                        // Async process returns 0 unless there is an error
-                        result = 0;
-
                         // Execute async process and catch exceptions
                         TRY_BEGIN()
                         {
+                            // In the async server
+                            asyncServer = true;
+                            result = 0;
+
                             // Get the version of PostgreSQL
                             unsigned int pgVersion = pgControlInfo(cfgOptionStr(cfgOptPgPath)).version;
 
@@ -254,7 +255,7 @@ cmdArchiveGet(void)
                         }
                         TRY_END();
 
-                        break;
+                        break;                                          // {uncovered - async calls always return errors for now}
                     }
                     // Else mark async process as forked
                     else
@@ -273,6 +274,7 @@ cmdArchiveGet(void)
             }
             while (waitMore(wait));
         }
+        // Else perform synchronous get
         else
         {
             // Disable async if it was enabled
@@ -281,6 +283,15 @@ cmdArchiveGet(void)
             // Call synchronous get
             result = perlExec();
         }
+
+        // Log whether or not the file was found
+        if (!asyncServer)                                               // {uncovered - async calls always return errors for now}
+        {
+            if (result == 0)
+                LOG_INFO("found %s in the archive", strPtr(walSegment));
+            else
+                LOG_INFO("unable to find %s in the archive", strPtr(walSegment));
+        }
     }
     MEM_CONTEXT_TEMP_END();
 

src/perl/embed.auto.c

@@ -891,26 +891,17 @@ static const EmbeddedModule embeddedModule[] =
             "\n"
             "if (!defined($strSourceArchive))\n"
             "{\n"
-            "confess &log(ERROR, 'WAL segment not provided', ERROR_PARAM_REQUIRED);\n"
+            "confess &log(ERROR, 'WAL segment not provided', ERROR_ASSERT);\n"
             "}\n"
             "\n\n"
             "my $strDestinationFile = ${$rstryCommandArg}[1];\n"
             "\n"
             "if (!defined($strDestinationFile))\n"
             "{\n"
-            "confess &log(ERROR, 'WAL segment destination not provided', ERROR_PARAM_REQUIRED);\n"
+            "confess &log(ERROR, 'WAL segment destination not provided', ERROR_ASSERT);\n"
             "}\n"
             "\n"
             "$iResult = archiveGetFile($strSourceArchive, $strDestinationFile, false);\n"
-            "\n\n"
-            "if ($iResult == 0)\n"
-            "{\n"
-            "&log(INFO, 'got WAL segment ' . $strSourceArchive);\n"
-            "}\n"
-            "else\n"
-            "{\n"
-            "&log(INFO, \"unable to find ${strSourceArchive} in the archive\");\n"
-            "}\n"
             "}\n"
             "\n\n"
             "return logDebugReturn\n"

test/expect/mock-archive-001.log

@@ -148,8 +148,8 @@ P00  DEBUG:     Storage::Local->list=>: stryFileList = ()
 P00  DEBUG:     Archive::Common::walSegmentFind=>: strWalFileName = [undef]
 P00  DEBUG:     Archive::Get::File::archiveGetCheck=>: strArchiveFile = [undef], strArchiveId = 9.4-1, strCipherPass = [undef]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 1
-P00   INFO: unable to find 700000007000000070000000 in the archive
 P00  DEBUG:     perl/exec::perlExec: => 1
+P00   INFO: unable to find 700000007000000070000000 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 1
 P00  DEBUG:     common/exit::exitSafe: (result: 1, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)
@@ -202,8 +202,8 @@ P00  DEBUG:     Storage::Local->new(): bAllowTemp = <true>, hRule = [undef], lBu
 P00  DEBUG:     Storage::Local->openWrite(): bAtomic = false, bPathCreate = <false>, lTimestamp = [undef], rhyFilter = ({rxyParam => ({strCompressType => decompress}), strClass => pgBackRest::Storage::Filter::Gzip}), strCipherPass = [undef], strGroup = [undef], strMode = <0640>, strUser = [undef], xFileExp = [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 P00  DEBUG:     Storage::Base->copy(): xDestinationFile = [object], xSourceFile = [object]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 0
-P00   INFO: got WAL segment 000000010000000100000001
 P00  DEBUG:     perl/exec::perlExec: => 0
+P00   INFO: found 000000010000000100000001 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 0
 P00  DEBUG:     common/exit::exitSafe: (result: 0, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)
@@ -231,7 +231,7 @@ P00   INFO: archive-push command end: aborted with exception [044]
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get 000000010000000100000001 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 ------------------------------------------------------------------------------------------------------------------------------------
 P00   INFO: archive-get command begin [BACKREST-VERSION]: [000000010000000100000001, [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG] --no-compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-timeout=45 --lock-path=[TEST_PATH]/db-master/lock --log-level-console=detail --log-level-file=trace --log-level-stderr=off --log-path=[TEST_PATH]/db-master/log --log-subprocess --no-log-timestamp --pg1-path=[TEST_PATH]/db-master/db/base --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --stanza=db
-P00   INFO: got WAL segment 000000010000000100000001
+P00   INFO: found 000000010000000100000001 in the archive
 P00   INFO: archive-get command end: completed successfully
 
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get 000000010000000100000001 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
@@ -294,7 +294,7 @@ P00   INFO: archive-push command end: aborted with exception [045]
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get --archive-async --archive-timeout=5 000000010000000100000002 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 ------------------------------------------------------------------------------------------------------------------------------------
 P00   INFO: archive-get command begin [BACKREST-VERSION]: [000000010000000100000002, [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG] --archive-async --archive-timeout=5 --no-compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-timeout=45 --lock-path=[TEST_PATH]/db-master/lock --log-level-console=detail --log-level-file=trace --log-level-stderr=off --log-path=[TEST_PATH]/db-master/log --log-subprocess --no-log-timestamp --pg1-path=[TEST_PATH]/db-master/db/base --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --spool-path=[TEST_PATH]/db-master/spool --stanza=db
-P00   INFO: got WAL segment 000000010000000100000002 asynchronously
+P00   INFO: found 000000010000000100000002 in the archive
 P00   INFO: archive-get command end: completed successfully
 
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-push [TEST_PATH]/db-master/db/base/pg_xlog/000000010000000100000002.partial

test/expect/mock-archive-002.log

@@ -135,8 +135,8 @@ P00  DEBUG:     Protocol::Helper::protocolGet(): bCache = <true>, iProcessIdx =
 P00  DEBUG:     Protocol::Helper::protocolGet: found cached protocol
 P00  DEBUG:     Archive::Get::File::archiveGetCheck=>: strArchiveFile = [undef], strArchiveId = 9.4-1, strCipherPass = <redacted>
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 1
-P00   INFO: unable to find 700000007000000070000000 in the archive
 P00  DEBUG:     perl/exec::perlExec: => 1
+P00   INFO: unable to find 700000007000000070000000 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 1
 P00  DEBUG:     common/exit::exitSafe: (result: 1, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)
@@ -182,8 +182,8 @@ P00  DEBUG:     Storage::Local->new(): bAllowTemp = <true>, hRule = [undef], lBu
 P00  DEBUG:     Storage::Local->openWrite(): bAtomic = false, bPathCreate = <false>, lTimestamp = [undef], rhyFilter = ({rxyParam => ({strCompressType => decompress}), strClass => pgBackRest::Storage::Filter::Gzip}), strCipherPass = [undef], strGroup = [undef], strMode = <0640>, strUser = [undef], xFileExp = [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 P00  DEBUG:     Storage::Base->copy(): xDestinationFile = [object], xSourceFile = [object]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 0
-P00   INFO: got WAL segment 000000010000000100000001
 P00  DEBUG:     perl/exec::perlExec: => 0
+P00   INFO: found 000000010000000100000001 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 0
 P00  DEBUG:     common/exit::exitSafe: (result: 0, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)
@@ -213,7 +213,7 @@ P00   INFO: archive-push command end: aborted with exception [044]
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get 000000010000000100000001 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 ------------------------------------------------------------------------------------------------------------------------------------
 P00   INFO: archive-get command begin [BACKREST-VERSION]: [000000010000000100000001, [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG] --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-timeout=45 --lock-path=[TEST_PATH]/db-master/lock --log-level-console=detail --log-level-file=trace --log-level-stderr=off --log-path=[TEST_PATH]/db-master/log --log-subprocess --no-log-timestamp --pg1-path=[TEST_PATH]/db-master/db/base --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-1] --stanza=db
-P00   INFO: got WAL segment 000000010000000100000001
+P00   INFO: found 000000010000000100000001 in the archive
 P00   INFO: archive-get command end: completed successfully
 
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get 000000010000000100000001 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
@@ -276,7 +276,7 @@ P00   INFO: archive-push command end: aborted with exception [045]
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-get --cmd-ssh=/usr/bin/ssh --archive-async --archive-timeout=5 000000010000000100000002 [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 ------------------------------------------------------------------------------------------------------------------------------------
 P00   INFO: archive-get command begin [BACKREST-VERSION]: [000000010000000100000002, [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG] --archive-async --archive-timeout=5 --cmd-ssh=/usr/bin/ssh --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-timeout=45 --lock-path=[TEST_PATH]/db-master/lock --log-level-console=detail --log-level-file=trace --log-level-stderr=off --log-path=[TEST_PATH]/db-master/log --log-subprocess --no-log-timestamp --pg1-path=[TEST_PATH]/db-master/db/base --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-1] --spool-path=[TEST_PATH]/db-master/spool --stanza=db
-P00   INFO: got WAL segment 000000010000000100000002 asynchronously
+P00   INFO: found 000000010000000100000002 in the archive
 P00   INFO: archive-get command end: completed successfully
 
 > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db archive-push [TEST_PATH]/db-master/db/base/pg_xlog/000000010000000100000002.partial

test/expect/mock-stanza-001.log

@@ -570,8 +570,8 @@ P00  DEBUG:     Storage::Local->new(): bAllowTemp = <true>, hRule = [undef], lBu
 P00  DEBUG:     Storage::Local->openWrite(): bAtomic = false, bPathCreate = <false>, lTimestamp = [undef], rhyFilter = ({rxyParam => ({strCompressType => decompress}), strClass => pgBackRest::Storage::Filter::Gzip}), strCipherPass = [undef], strGroup = [undef], strMode = <0640>, strUser = [undef], xFileExp = [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 P00  DEBUG:     Storage::Base->copy(): xDestinationFile = [object], xSourceFile = [object]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 0
-P00   INFO: got WAL segment 000000010000000100000002
 P00  DEBUG:     perl/exec::perlExec: => 0
+P00   INFO: found 000000010000000100000002 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 0
 P00  DEBUG:     common/exit::exitSafe: (result: 0, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)

test/expect/mock-stanza-002.log

@@ -427,8 +427,8 @@ P00  DEBUG:     Storage::Local->new(): bAllowTemp = <true>, hRule = [undef], lBu
 P00  DEBUG:     Storage::Local->openWrite(): bAtomic = false, bPathCreate = <false>, lTimestamp = [undef], rhyFilter = ({rxyParam => ({strCompressType => decompress}), strClass => pgBackRest::Storage::Filter::Gzip}), strCipherPass = [undef], strGroup = [undef], strMode = <0640>, strUser = [undef], xFileExp = [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 P00  DEBUG:     Storage::Base->copy(): xDestinationFile = [object], xSourceFile = [object]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 0
-P00   INFO: got WAL segment 000000010000000100000002
 P00  DEBUG:     perl/exec::perlExec: => 0
+P00   INFO: found 000000010000000100000002 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 0
 P00  DEBUG:     common/exit::exitSafe: (result: 0, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)

test/expect/mock-stanza-003.log

@@ -545,8 +545,8 @@ P00  DEBUG:     Storage::Local->new(): bAllowTemp = <true>, hRule = [undef], lBu
 P00  DEBUG:     Storage::Local->openWrite(): bAtomic = false, bPathCreate = <false>, lTimestamp = [undef], rhyFilter = ({rxyParam => ({strCompressType => decompress}), strClass => pgBackRest::Storage::Filter::Gzip}), strCipherPass = [undef], strGroup = [undef], strMode = <0640>, strUser = [undef], xFileExp = [TEST_PATH]/db-master/db/base/pg_xlog/RECOVERYXLOG
 P00  DEBUG:     Storage::Base->copy(): xDestinationFile = [object], xSourceFile = [object]
 P00  DEBUG:     Archive::Get::File::archiveGetFile=>: iResult = 0
-P00   INFO: got WAL segment 000000010000000100000002
 P00  DEBUG:     perl/exec::perlExec: => 0
+P00   INFO: found 000000010000000100000002 in the archive
 P00  DEBUG:     command/archive/get/get::cmdArchiveGet: => 0
 P00  DEBUG:     common/exit::exitSafe: (result: 0, error: false, signalType: 0)
 P00  DEBUG:     common/lock::lockRelease: (failOnNoLock: false)

test/src/module/archive/getTest.c

@@ -166,18 +166,7 @@ testRun(void)
         harnessCfgLoad(strLstSize(argList), strLstPtr(argList));
 
         TEST_RESULT_INT(cmdArchiveGet(), 1, "timeout getting WAL segment");
-
+        harnessLogResult("P00   INFO: unable to find 000000010000000100000001 in the archive");
-        // Write out a bogus .error file to make sure it is ignored on the first loop
-        // -------------------------------------------------------------------------------------------------------------------------
-        // String *errorFile = storagePathNP(storageSpool(), strNew(STORAGE_SPOOL_ARCHIVE_IN "/000000010000000100000001.error"));
-        // storagePutNP(storageNewWriteNP(storageSpool(), errorFile), bufNewStr(strNew("25\n" BOGUS_STR)));
-        //
-        // TEST_ERROR(cmdArchiveGet(), AssertError, BOGUS_STR);
-        // unlink(strPtr(errorFile));
-        //
-        // // Wait for the lock to be released
-        // lockAcquire(cfgOptionStr(cfgOptLockPath), cfgOptionStr(cfgOptStanza), cfgLockType(), 30, true);
-        // lockRelease(true);
 
         // Check for missing WAL
         // -------------------------------------------------------------------------------------------------------------------------
@@ -188,7 +177,7 @@ testRun(void)
             storageNewWriteNP(storageSpool(), strNewFmt(STORAGE_SPOOL_ARCHIVE_IN "/%s.ok", strPtr(walSegment))), NULL);
 
         TEST_RESULT_VOID(cmdArchiveGet(), "successful get of missing WAL");
-        harnessLogResult("P00   INFO: unable to find WAL segment 000000010000000100000001");
+        harnessLogResult("P00   INFO: unable to find 000000010000000100000001 in the archive");
 
         TEST_RESULT_BOOL(
             storageExistsNP(storageSpool(), strNewFmt(STORAGE_SPOOL_ARCHIVE_IN "/%s.ok", strPtr(walSegment))), false,
@@ -205,7 +194,7 @@ testRun(void)
             bufNewStr(strNew("SHOULD-BE-A-REAL-WAL-FILE")));
 
         TEST_RESULT_VOID(cmdArchiveGet(), "successful get");
-        harnessLogResult("P00   INFO: got WAL segment 000000010000000100000001 asynchronously");
+        harnessLogResult("P00   INFO: found 000000010000000100000001 in the archive");
 
         TEST_RESULT_BOOL(storageExistsNP(storageTest, walFile), true, "check WAL segment was moved");
         storageRemoveP(storageTest, walFile, .errorOnMissing = true);
@@ -229,7 +218,7 @@ testRun(void)
             bufNewStr(strNew("SHOULD-BE-A-REAL-WAL-FILE")));
 
         TEST_RESULT_VOID(cmdArchiveGet(), "successful get");
-        harnessLogResult("P00   INFO: got WAL segment 000000010000000100000001 asynchronously");
+        harnessLogResult("P00   INFO: found 000000010000000100000001 in the archive");
 
         TEST_RESULT_BOOL(storageExistsNP(storageTest, walFile), true, "check WAL segment was moved");
 
@@ -244,6 +233,7 @@ testRun(void)
         TEST_RESULT_VOID(lockClear(true), "clear lock");
 
         TEST_RESULT_INT(cmdArchiveGet(), 1, "timeout waiting for lock");
+        harnessLogResult("P00   INFO: unable to find 000000010000000100000001 in the archive");
 
         // -------------------------------------------------------------------------------------------------------------------------
         strLstAddZ(argList, BOGUS_STR);