From cbf514e191783937de63b5a276fcefc426e6f430 Mon Sep 17 00:00:00 2001 From: Cynthia Shang Date: Mon, 10 Dec 2018 16:32:41 -0500 Subject: [PATCH] Improve info error messages introduced in 74b72df9. - Add detail to errors when info files are loaded with incorrect encryption settings. - Throw FileMissingError rather than FileOpenError when both copies of the info file are missing. - If one file is present (but errors) and the other is missing, then return the error for the file that was present. Contributed by Cynthia Shang. --- doc/xml/release.xml | 7 ++- src/info/info.c | 29 ++++++++++-- test/expect/mock-archive-001.log | 4 +- test/expect/mock-archive-003.log | 2 +- .../Module/Mock/MockArchiveTest.pm | 5 +-- test/src/module/archive/getTest.c | 4 +- test/src/module/info/infoArchiveTest.c | 2 +- test/src/module/info/infoTest.c | 44 ++++++++++++++++--- 8 files changed, 77 insertions(+), 20 deletions(-) diff --git a/doc/xml/release.xml b/doc/xml/release.xml index 89abb5408..8f69071f7 100644 --- a/doc/xml/release.xml +++ b/doc/xml/release.xml @@ -104,7 +104,12 @@ -

Improve error message when info files are missing/corrupt.

+ + + + + +

Improve error messages when info files are missing/corrupt.

 diff --git a/src/info/info.c b/src/info/info.c index d0b52b220..a13586757 100644 --- a/src/info/info.c +++ b/src/info/info.c @@ -146,7 +146,20 @@ infoLoad(Info *this, const Storage *storage, bool copyFile, CipherType cipherTyp } // Load and parse the info file - Buffer *buffer = storageGetNP(infoRead); + Buffer *buffer = NULL; + + TRY_BEGIN() + { + buffer = storageGetNP(infoRead); + } + CATCH(CryptoError) + { + THROW_FMT( + CryptoError, "'%s' %s\nHINT: Is or was the repo encrypted?", strPtr(storagePathNP(storage, fileName)), + errorMessage()); + } + TRY_END(); + iniParse(this->ini, strNewBuf(buffer)); // Make sure the ini is valid by testing the checksum @@ -161,7 +174,7 @@ infoLoad(Info *this, const Storage *storage, bool copyFile, CipherType cipherTyp bool checksumMissing = strSize(infoChecksum) < 3; THROW_FMT( - ChecksumError, "invalid checksum in '%s', expected '%s' but %s%s%s", strPtr(fileName), + ChecksumError, "invalid checksum in '%s', expected '%s' but %s%s%s", strPtr(storagePathNP(storage, 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)), @@ -219,6 +232,8 @@ infoNew(const Storage *storage, const String *fileName, CipherType cipherType, c { // On error store the error and try to load the copy String *primaryError = strNewFmt("%s: %s", errorTypeName(errorType()), errorMessage()); + bool primaryMissing = errorType() == &FileMissingError; + const ErrorType *primaryErrorType = errorType(); TRY_BEGIN() { @@ -226,8 +241,14 @@ infoNew(const Storage *storage, const String *fileName, CipherType cipherType, c } CATCH_ANY() { - THROW_FMT( - FileOpenError, "unable to load info file '%s' or '%s" INI_COPY_EXT "':\n%s\n%s: %s", + // If both copies of the file have the same error then throw that error, + // else if one file is missing but the other is in error and it is not missing, throw that error + // else throw an open error + THROWP_FMT( + errorType() == primaryErrorType ? errorType() : + (errorType() == &FileMissingError ? primaryErrorType : + (primaryMissing ? errorType() : &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()); } diff --git a/test/expect/mock-archive-001.log b/test/expect/mock-archive-001.log index 23d785d12..b4de9b418 100644 --- a/test/expect/mock-archive-001.log +++ b/test/expect/mock-archive-001.log @@ -14,14 +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: [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': +P00 ERROR: [055]: 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 [041] +P00 INFO: archive-get command end: aborted with exception [055] 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 b00ac996b..13aab84e2 100644 --- a/test/expect/mock-archive-003.log +++ b/test/expect/mock-archive-003.log @@ -11,7 +11,7 @@ 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: [041]: unable to load info file '/archive/db/archive.info' or '/archive/db/archive.info.copy': +P00 ERROR: [055]: 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. diff --git a/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm b/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm index 00037839e..0bb56ae64 100644 --- a/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm +++ b/test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm @@ -135,12 +135,9 @@ 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 => $iExpectedError, oLogTest => $self->expect()}); + {iExpectedExitStatus => ERROR_FILE_MISSING, oLogTest => $self->expect()}); #--------------------------------------------------------------------------------------------------------------------------- $oHostBackup->stanzaCreate( diff --git a/test/src/module/archive/getTest.c b/test/src/module/archive/getTest.c index da251a8f6..f93b53ca9 100644 --- a/test/src/module/archive/getTest.c +++ b/test/src/module/archive/getTest.c @@ -345,7 +345,7 @@ testRun(void) HARNESS_FORK_CHILD() { TEST_ERROR_FMT( - cmdArchiveGet(), FileOpenError, + cmdArchiveGet(), FileMissingError, "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" @@ -375,7 +375,7 @@ testRun(void) HARNESS_FORK_CHILD() { TEST_ERROR_FMT( - cmdArchiveGet(), FileOpenError, + cmdArchiveGet(), FileMissingError, "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" diff --git a/test/src/module/info/infoArchiveTest.c b/test/src/module/info/infoArchiveTest.c index 4dcdb8511..dbdb236ad 100644 --- a/test/src/module/info/infoArchiveTest.c +++ b/test/src/module/info/infoArchiveTest.c @@ -17,7 +17,7 @@ testRun(void) String *fileName = strNewFmt("%s/test.ini", testPath()); TEST_ERROR_FMT( - infoArchiveNew(storageLocal(), fileName, true, cipherTypeNone, NULL), FileOpenError, + infoArchiveNew(storageLocal(), fileName, true, cipherTypeNone, NULL), FileMissingError, "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" diff --git a/test/src/module/info/infoTest.c b/test/src/module/info/infoTest.c index 18a505a56..746df93ff 100644 --- a/test/src/module/info/infoTest.c +++ b/test/src/module/info/infoTest.c @@ -37,7 +37,7 @@ testRun(void) // Info files missing and at least one is required //-------------------------------------------------------------------------------------------------------------------------- TEST_ERROR( - infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileMissingError, strPtr( strNewFmt( "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" @@ -121,7 +121,7 @@ testRun(void) storagePutNP(storageNewWriteNP(storageLocalWrite(), fileName), bufNewStr(content)), "put invalid br format to file"); TEST_ERROR( - infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FormatError, strPtr( strNewFmt( "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" @@ -129,7 +129,28 @@ testRun(void) "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)); + content = strNew + ( + "[backrest]\n" + "backrest-checksum=\"14617b089cb5c9b3224e739bb794e865b9bcdf4b\"\n" + "backrest-format=4\n" + "backrest-version=\"2.05\"\n" + "\n" + "[db]\n" + "db-catalog-version=201409291\n" + "db-control-version=942\n" + "db-id=1\n" + "db-system-id=6569239123849665679\n" + "db-version=\"9.4\"\n" + "\n" + "[db:history]\n" + "1={\"db-catalog-version\":201409291,\"db-control-version\":942,\"db-system-id\":6569239123849665679," + "\"db-version\":\"9.4\"}\n" + ); + + TEST_RESULT_VOID( + storagePutNP( + storageNewWriteNP(storageLocalWrite(), fileNameCopy), bufNewStr(content)), "put invalid info to copy file"); TEST_ERROR( infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, @@ -137,7 +158,8 @@ testRun(void) 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", + "ChecksumError: invalid checksum in '%s/test.ini.copy', expected 'af92308095d6141bcda6b2df6d574f98d1115163'" + " but found '14617b089cb5c9b3224e739bb794e865b9bcdf4b'", testPath(), testPath(), testPath(), testPath()))); // Invalid checksum @@ -189,7 +211,7 @@ testRun(void) // Copy file error TEST_ERROR( - infoNew(storageLocal(), fileName, cipherTypeNone, NULL), FileOpenError, + infoNew(storageLocal(), fileName, cipherTypeNone, NULL), ChecksumError, strPtr( strNewFmt( "unable to load info file '%s/test.ini' or '%s/test.ini.copy':\n" @@ -199,7 +221,19 @@ testRun(void) " but found '4306ec205f71417c301e403c4714090e61c8a999'", testPath(), testPath(), testPath(), testPath()))); + // Encryption error + //-------------------------------------------------------------------------------------------------------------------------- storageRemoveNP(storageLocalWrite(), fileName); + TEST_ERROR( + infoNew(storageLocal(), fileName, cipherTypeAes256Cbc, strNew("12345678")), CryptoError, + 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" + "CryptoError: '%s/test.ini.copy' cipher header invalid\n" + "HINT: Is or was the repo encrypted?", + testPath(), testPath(), testPath(), testPath()))); + storageRemoveNP(storageLocalWrite(), fileNameCopy); // infoFree()