db/pgbackrest
1
0
Fork 0
mirror of https://github.com/pgbackrest/pgbackrest.git synced 2024-12-12 10:04:14 +02:00
Code Issues Releases Activity

Improve error message when info files are missing/corrupt.

Browse Source 
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.
This commit is contained in:
David Steele 2018-11-28 18:41:21 -05:00
parent 47687dd13a
commit 74b72df9db
9 changed files with 125 additions and 126 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
doc/xml/release.xml
View File

@ -59,6 +59,10 @@
<p>Allow I/O read interface to explicitly request blocking reads.</p>
</release-item>
<release-item>
<p>Improve error message when info files are missing/corrupt.</p>
</release-item>
<release-item>
<p>Rename <code>PGBACKREST</code>/<code>BACKREST</code> constants to <code>PROJECT</code>.</p>
</release-item>

131
src/info/info.c
View File

@ -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));

10
src/info/infoArchive.c
View File

@ -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());

10
test/expect/mock-archive-001.log
View File

@ -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=<redacted> --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

8
test/expect/mock-archive-003.log
View File

@ -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.

5
test/lib/pgBackRestTest/Module/Mock/MockArchiveTest.pm
View File

@ -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(

24
test/src/module/archive/getTest.c
View File

@ -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)));
}
}

12
test/src/module/info/infoArchiveTest.c
View File

@ -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

47
test/src/module/info/infoTest.c
View File

@ -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);