From 74b72df9dbfbfb00d5b729cb83bef35e77fd73c6 Mon Sep 17 00:00:00 2001 From: David Steele Date: Wed, 28 Nov 2018 18:41:21 -0500 Subject: [PATCH] Improve error message when info files are missing/corrupt. The previous error message only showed the last error. In addition, some errors were missed (such as directory permission errors) that could prevent the copy from being checked. Show both errors below a generic "unable to load" error. Details are now given explaining exactly why the primary and copy failed. Previously if one file could not be loaded a warning would be output. This has been removed because it is not clear what the user should do in this case. Should they do a stanza-create --force? Maybe the best idea is to automatically repair the corrupt file, but on the other hand that might just spread corruption if pgBackRest makes the wrong choice. --- doc/xml/release.xml | 4 + src/info/info.c | 131 +++++++----------- src/info/infoArchive.c | 10 +- test/expect/mock-archive-001.log | 10 +- test/expect/mock-archive-003.log | 8 +- .../Module/Mock/MockArchiveTest.pm | 5 +- test/src/module/archive/getTest.c | 24 ++-- test/src/module/info/infoArchiveTest.c | 12 +- test/src/module/info/infoTest.c | 47 ++++--- 9 files changed, 125 insertions(+), 126 deletions(-) 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);