diff --git a/doc/xml/release.xml b/doc/xml/release.xml index 709e5c612..31f0dfa83 100644 --- a/doc/xml/release.xml +++ b/doc/xml/release.xml @@ -59,6 +59,10 @@

Allow I/O read interface to explicitly request blocking reads.

+ +

Improve error message when info files are missing/corrupt.

+
+

Rename PGBACKREST/BACKREST constants to PROJECT.

diff --git a/src/info/info.c b/src/info/info.c index 54d73e617..d0b52b220 100644 --- a/src/info/info.c +++ b/src/info/info.c @@ -112,80 +112,13 @@ infoHash(const Ini *ini) } /*********************************************************************************************************************************** -Internal function to check if the information is valid or not +Load and validate the info file (or copy) ***********************************************************************************************************************************/ static bool -infoValidInternal( - const Info *this, // Info object to validate - bool ignoreError) // ignore errors found? -{ - FUNCTION_TEST_BEGIN(); - FUNCTION_TEST_PARAM(INFO, this); - FUNCTION_TEST_PARAM(BOOL, ignoreError); - - FUNCTION_TEST_ASSERT(this != NULL); - FUNCTION_TEST_END(); - - bool result = true; - - MEM_CONTEXT_TEMP_BEGIN() - { - // Make sure the ini is valid by testing the checksum - String *infoChecksum = varStr(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_CHECKSUM_STR)); - - CryptoHash *hash = infoHash(this->ini); - - // ??? Temporary hack until get json parser: add quotes around hash before comparing - if (!strEq(infoChecksum, strQuoteZ(bufHex(cryptoHash(hash)), "\""))) - { - // ??? Temporary hack until get json parser: remove quotes around hash before displaying in messsage & check < 3 - String *chksumMsg = strNewFmt("invalid checksum in '%s', expected '%s' but found '%s'", - strPtr(this->fileName), strPtr(bufHex(cryptoHash(hash))), (strSize(infoChecksum) < 3) ? - "[undef]" : strPtr(strSubN(infoChecksum, 1, strSize(infoChecksum) - 2))); - - if (!ignoreError) - { - THROW(ChecksumError, strPtr(chksumMsg)); - } - else - { - LOG_WARN(strPtr(chksumMsg)); - result = false; - } - } - - // Make sure that the format is current, otherwise error - if (varIntForce(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_FORMAT_STR)) != REPOSITORY_FORMAT) - { - String *fmtMsg = strNewFmt( - "invalid format in '%s', expected %d but found %d", - strPtr(this->fileName), REPOSITORY_FORMAT, - varIntForce(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_FORMAT_STR))); - - if (!ignoreError) - { - THROW(FormatError, strPtr(fmtMsg)); - } - else - { - LOG_WARN(strPtr(fmtMsg)); - result = false; - } - } - } - MEM_CONTEXT_TEMP_END(); - - FUNCTION_TEST_RESULT(BOOL, result); -} - -/*********************************************************************************************************************************** -Internal function to load the copy and check validity -***********************************************************************************************************************************/ -static bool -loadInternal(Info *this, const Storage *storage, bool copyFile, CipherType cipherType, const String *cipherPass) +infoLoad(Info *this, const Storage *storage, bool copyFile, CipherType cipherType, const String *cipherPass) { FUNCTION_DEBUG_BEGIN(logLevelTrace) - FUNCTION_DEBUG_PARAM(INFO, this); // Info object to load parsed buffer into + FUNCTION_DEBUG_PARAM(INFO, this); FUNCTION_DEBUG_PARAM(STORAGE, storage); FUNCTION_DEBUG_PARAM(BOOL, copyFile); // Is this the copy file? FUNCTION_DEBUG_PARAM(ENUM, cipherType); @@ -201,7 +134,7 @@ loadInternal(Info *this, const Storage *storage, bool copyFile, CipherType ciphe String *fileName = copyFile ? strCat(strDup(this->fileName), INI_COPY_EXT) : this->fileName; // Attempt to load the file - StorageFileRead *infoRead = storageNewReadP(storage, fileName, .ignoreMissing = true); + StorageFileRead *infoRead = storageNewReadNP(storage, fileName); if (cipherType != cipherTypeNone) { @@ -212,16 +145,35 @@ loadInternal(Info *this, const Storage *storage, bool copyFile, CipherType ciphe NULL)))); } + // Load and parse the info file Buffer *buffer = storageGetNP(infoRead); + iniParse(this->ini, strNewBuf(buffer)); - // If the file exists, parse and validate it - if (buffer != NULL) + // Make sure the ini is valid by testing the checksum + String *infoChecksum = varStr(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_CHECKSUM_STR)); + + CryptoHash *hash = infoHash(this->ini); + + // ??? Temporary hack until get json parser: add quotes around hash before comparing + if (!strEq(infoChecksum, strQuoteZ(bufHex(cryptoHash(hash)), "\""))) { - iniParse(this->ini, strNewBuf(buffer)); + // Is the checksum present? + bool checksumMissing = strSize(infoChecksum) < 3; - // Do not ignore errors if the copy file is invalid - if (infoValidInternal(this, (copyFile ? false : true))) - result = true; + THROW_FMT( + ChecksumError, "invalid checksum in '%s', expected '%s' but %s%s%s", strPtr(fileName), + strPtr(bufHex(cryptoHash(hash))), checksumMissing ? "no checksum found" : "found '", + // ??? Temporary hack until get json parser: remove quotes around hash before displaying in messsage + checksumMissing ? "" : strPtr(strSubN(infoChecksum, 1, strSize(infoChecksum) - 2)), + checksumMissing ? "" : "'"); + } + + // Make sure that the format is current, otherwise error + if (varIntForce(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_FORMAT_STR)) != REPOSITORY_FORMAT) + { + THROW_FMT( + FormatError, "invalid format in '%s', expected %d but found %d", strPtr(fileName), REPOSITORY_FORMAT, + varIntForce(iniGet(this->ini, INI_SECTION_BACKREST_STR, INI_KEY_FORMAT_STR))); } } MEM_CONTEXT_TEMP_END(); @@ -258,17 +210,30 @@ infoNew(const Storage *storage, const String *fileName, CipherType cipherType, c this->ini = iniNew(); this->fileName = strDup(fileName); - // Attempt to load the main file. If it does not exist or is invalid, try to load the copy. - if (!loadInternal(this, storage, false, cipherType, cipherPass)) + // Attempt to load the primary file + TRY_BEGIN() { - if (!loadInternal(this, storage, true, cipherType, cipherPass)) + infoLoad(this, storage, false, cipherType, cipherPass); + } + CATCH_ANY() + { + // On error store the error and try to load the copy + String *primaryError = strNewFmt("%s: %s", errorTypeName(errorType()), errorMessage()); + + TRY_BEGIN() + { + infoLoad(this, storage, true, cipherType, cipherPass); + } + CATCH_ANY() { THROW_FMT( - FileMissingError, "unable to open %s or %s", - strPtr(storagePathNP(storage, this->fileName)), - strPtr(strCat(storagePathNP(storage, this->fileName), INI_COPY_EXT))); + FileOpenError, "unable to load info file '%s' or '%s" INI_COPY_EXT "':\n%s\n%s: %s", + strPtr(storagePathNP(storage, this->fileName)), strPtr(storagePathNP(storage, this->fileName)), + strPtr(primaryError), errorTypeName(errorType()), errorMessage()); } + TRY_END(); } + TRY_END(); // Load the cipher passphrase if it exists String *cipherPass = varStr(iniGetDefault(this->ini, INI_SECTION_CIPHER_STR, INI_KEY_CIPHER_PASS_STR, NULL)); diff --git a/src/info/infoArchive.c b/src/info/infoArchive.c index ec42f5bad..efb2f1bd2 100644 --- a/src/info/infoArchive.c +++ b/src/info/infoArchive.c @@ -55,13 +55,13 @@ infoArchiveNew(const Storage *storage, const String *fileName, bool ignoreMissin { this->infoPg = infoPgNew(storage, fileName, infoPgArchive, cipherType, cipherPass); } - CATCH(FileMissingError) + CATCH_ANY() { - THROW_FMT( - FileMissingError, + THROWP_FMT( + errorType(), "%s\n" - "HINT: archive.info does not exist but is required to push/get WAL segments.\n" - "HINT: is archive_command configured in postgresql.conf?\n" + "HINT: archive.info cannot be opened but is required to push/get WAL segments.\n" + "HINT: is archive_command configured correctly in postgresql.conf?\n" "HINT: has a stanza-create been performed?\n" "HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.", errorMessage()); diff --git a/test/expect/mock-archive-001.log b/test/expect/mock-archive-001.log index 8164c4a34..23d785d12 100644 --- a/test/expect/mock-archive-001.log +++ b/test/expect/mock-archive-001.log @@ -14,12 +14,14 @@ P00 INFO: archive-push command end: aborted with exception [055] > [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-cipher-pass= --repo1-cipher-type=aes-256-cbc --repo1-path=[TEST_PATH]/db-master/repo --stanza=db -P00 ERROR: [055]: unable to open [TEST_PATH]/db-master/repo/archive/db/archive.info or [TEST_PATH]/db-master/repo/archive/db/archive.info.copy - HINT: archive.info does not exist but is required to push/get WAL segments. - HINT: is archive_command configured in postgresql.conf? +P00 ERROR: [041]: unable to load info file '[TEST_PATH]/db-master/repo/archive/db/archive.info' or '[TEST_PATH]/db-master/repo/archive/db/archive.info.copy': + FileMissingError: unable to open '[TEST_PATH]/db-master/repo/archive/db/archive.info' for read: [2] No such file or directory + FileMissingError: unable to open '[TEST_PATH]/db-master/repo/archive/db/archive.info.copy' for read: [2] No such file or directory + HINT: archive.info cannot be opened but is required to push/get WAL segments. + HINT: is archive_command configured correctly in postgresql.conf? HINT: has a stanza-create been performed? HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme. -P00 INFO: archive-get command end: aborted with exception [055] +P00 INFO: archive-get command end: aborted with exception [041] stanza-create db - stanza create (db-master host) > [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --stanza=db --log-level-console=detail --no-online --force stanza-create diff --git a/test/expect/mock-archive-003.log b/test/expect/mock-archive-003.log index 67e2e78cd..b00ac996b 100644 --- a/test/expect/mock-archive-003.log +++ b/test/expect/mock-archive-003.log @@ -11,9 +11,11 @@ P00 ERROR: [055]: archive.info does not exist but is required to push/get WAL s > [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 ERROR: [055]: unable to open /archive/db/archive.info or /archive/db/archive.info.copy - HINT: archive.info does not exist but is required to push/get WAL segments. - HINT: is archive_command configured in postgresql.conf? +P00 ERROR: [041]: unable to load info file '/archive/db/archive.info' or '/archive/db/archive.info.copy': + FileMissingError: unable to open '/archive/db/archive.info': No such file or directory + FileMissingError: unable to open '/archive/db/archive.info.copy': No such file or directory + HINT: archive.info cannot be opened but is required to push/get WAL segments. + HINT: is archive_command configured correctly in postgresql.conf? HINT: has a stanza-create been performed? HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme. diff --git a/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm b/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm index 0bb56ae64..00037839e 100644 --- a/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm +++ b/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm @@ -135,9 +135,12 @@ sub run $strCommandPush . " ${strWalPath}/${strSourceFile1}", {iExpectedExitStatus => ERROR_FILE_MISSING, oLogTest => $self->expect()}); + # ??? C and Perl currently return different errors for info open failures -- this can be removed when Perl is gone + my $iExpectedError = !$bRemote ? ERROR_FILE_OPEN : ERROR_FILE_MISSING; + $oHostDbMaster->executeSimple( $strCommandGet . " ${strSourceFile1} ${strWalPath}/RECOVERYXLOG", - {iExpectedExitStatus => ERROR_FILE_MISSING, oLogTest => $self->expect()}); + {iExpectedExitStatus => $iExpectedError, oLogTest => $self->expect()}); #--------------------------------------------------------------------------------------------------------------------------- $oHostBackup->stanzaCreate( diff --git a/test/src/module/archive/getTest.c b/test/src/module/archive/getTest.c index b81c8cb1f..da251a8f6 100644 --- a/test/src/module/archive/getTest.c +++ b/test/src/module/archive/getTest.c @@ -345,13 +345,17 @@ testRun(void) HARNESS_FORK_CHILD() { TEST_ERROR_FMT( - cmdArchiveGet(), FileMissingError, - "unable to open %s/archive/test1/archive.info or %s/archive/test1/archive.info.copy\n" - "HINT: archive.info does not exist but is required to push/get WAL segments.\n" - "HINT: is archive_command configured in postgresql.conf?\n" + cmdArchiveGet(), FileOpenError, + "unable to load info file '%s/archive/test1/archive.info' or '%s/archive/test1/archive.info.copy':\n" + "FileMissingError: unable to open '%s/archive/test1/archive.info' for read: [2] No such file or directory\n" + "FileMissingError: unable to open '%s/archive/test1/archive.info.copy' for read: [2] No such file or" + " directory\n" + "HINT: archive.info cannot be opened but is required to push/get WAL segments.\n" + "HINT: is archive_command configured correctly in postgresql.conf?\n" "HINT: has a stanza-create been performed?\n" "HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving" " scheme.", + strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath))); } } @@ -371,13 +375,17 @@ testRun(void) HARNESS_FORK_CHILD() { TEST_ERROR_FMT( - cmdArchiveGet(), FileMissingError, - "unable to open %s/archive/test1/archive.info or %s/archive/test1/archive.info.copy\n" - "HINT: archive.info does not exist but is required to push/get WAL segments.\n" - "HINT: is archive_command configured in postgresql.conf?\n" + cmdArchiveGet(), FileOpenError, + "unable to load info file '%s/archive/test1/archive.info' or '%s/archive/test1/archive.info.copy':\n" + "FileMissingError: unable to open '%s/archive/test1/archive.info' for read: [2] No such file or directory\n" + "FileMissingError: unable to open '%s/archive/test1/archive.info.copy' for read: [2] No such file or" + " directory\n" + "HINT: archive.info cannot be opened but is required to push/get WAL segments.\n" + "HINT: is archive_command configured correctly in postgresql.conf?\n" "HINT: has a stanza-create been performed?\n" "HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving" " scheme.", + strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath)), strPtr(cfgOptionStr(cfgOptRepoPath))); } } diff --git a/test/src/module/info/infoArchiveTest.c b/test/src/module/info/infoArchiveTest.c index 411a62c76..4dcdb8511 100644 --- a/test/src/module/info/infoArchiveTest.c +++ b/test/src/module/info/infoArchiveTest.c @@ -17,13 +17,15 @@ testRun(void) String *fileName = strNewFmt("%s/test.ini", testPath()); TEST_ERROR_FMT( - infoArchiveNew(storageLocal(), fileName, true, cipherTypeNone, NULL), FileMissingError, - "unable to open %s/test.ini or %s/test.ini.copy\n" - "HINT: archive.info does not exist but is required to push/get WAL segments.\n" - "HINT: is archive_command configured in postgresql.conf?\n" + infoArchiveNew(storageLocal(), fileName, true, cipherTypeNone, NULL), FileOpenError, + "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" + "FileMissingError: unable to open '%s/test.ini' for read: [2] No such file or directory\n" + "FileMissingError: unable to open '%s/test.ini.copy' for read: [2] No such file or directory\n" + "HINT: archive.info cannot be opened but is required to push/get WAL segments.\n" + "HINT: is archive_command configured correctly in postgresql.conf?\n" "HINT: has a stanza-create been performed?\n" "HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.", - testPath(), testPath()); + testPath(), testPath(), testPath(), testPath()); //-------------------------------------------------------------------------------------------------------------------------- content = strNew diff --git a/test/src/module/info/infoTest.c b/test/src/module/info/infoTest.c index 50a2f7e50..18a505a56 100644 --- a/test/src/module/info/infoTest.c +++ b/test/src/module/info/infoTest.c @@ -36,9 +36,14 @@ testRun(void) // Info files missing and at least one is required //-------------------------------------------------------------------------------------------------------------------------- - String *missingInfoError = strNewFmt("unable to open %s or %s", strPtr(fileName), strPtr(fileNameCopy)); - - TEST_ERROR(infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileMissingError, strPtr(missingInfoError)); + TEST_ERROR( + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, + strPtr( + strNewFmt( + "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" + "FileMissingError: unable to open '%s/test.ini' for read: [2] No such file or directory\n" + "FileMissingError: unable to open '%s/test.ini.copy' for read: [2] No such file or directory", + testPath(), testPath(), testPath(), testPath()))); // Only copy exists and one is required //-------------------------------------------------------------------------------------------------------------------------- @@ -115,19 +120,25 @@ testRun(void) TEST_RESULT_VOID( storagePutNP(storageNewWriteNP(storageLocalWrite(), fileName), bufNewStr(content)), "put invalid br format to file"); - TEST_ERROR(infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileMissingError, strPtr(missingInfoError)); - harnessLogResult( + TEST_ERROR( + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, strPtr( - strNewFmt("P00 WARN: invalid format in '%s', expected %d but found %d", strPtr(fileName), REPOSITORY_FORMAT, 4))); + strNewFmt( + "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" + "FormatError: invalid format in '%s/test.ini', expected 5 but found 4\n" + "FileMissingError: unable to open '%s/test.ini.copy' for read: [2] No such file or directory", + testPath(), testPath(), testPath(), testPath()))); storageCopyNP(storageNewReadNP(storageLocal(), fileName), storageNewWriteNP(storageLocalWrite(), fileNameCopy)); TEST_ERROR( - infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FormatError, - strPtr(strNewFmt("invalid format in '%s', expected %d but found %d", strPtr(fileName), REPOSITORY_FORMAT, 4))); - harnessLogResult( + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, strPtr( - strNewFmt("P00 WARN: invalid format in '%s', expected %d but found %d", strPtr(fileName), REPOSITORY_FORMAT, 4))); + strNewFmt( + "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" + "FormatError: invalid format in '%s/test.ini', expected 5 but found 4\n" + "FormatError: invalid format in '%s/test.ini.copy', expected 5 but found 4", + testPath(), testPath(), testPath(), testPath()))); // Invalid checksum //-------------------------------------------------------------------------------------------------------------------------- @@ -178,13 +189,15 @@ testRun(void) // Copy file error TEST_ERROR( - infoNew(storageLocal(), fileName, cipherTypeNone, NULL), ChecksumError, - strPtr(strNewFmt("invalid checksum in '%s', expected '%s' but found '%s'", strPtr(fileName), - "4306ec205f71417c301e403c4714090e61c8a736", "4306ec205f71417c301e403c4714090e61c8a999"))); - - // Main file warning - harnessLogResult(strPtr(strNewFmt("P00 WARN: invalid checksum in '%s', expected '%s' but found '%s'", strPtr(fileName), - "4306ec205f71417c301e403c4714090e61c8a736", "[undef]"))); + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, + strPtr( + strNewFmt( + "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" + "ChecksumError: invalid checksum in '%s/test.ini', expected '4306ec205f71417c301e403c4714090e61c8a736' but" + " no checksum found\n" + "ChecksumError: invalid checksum in '%s/test.ini.copy', expected '4306ec205f71417c301e403c4714090e61c8a736'" + " but found '4306ec205f71417c301e403c4714090e61c8a999'", + testPath(), testPath(), testPath(), testPath()))); storageRemoveNP(storageLocalWrite(), fileName); storageRemoveNP(storageLocalWrite(), fileNameCopy);