db/pgbackrest
1
0
Fork 0
mirror of https://github.com/pgbackrest/pgbackrest.git synced 2025-03-03 14:52:21 +02:00
Code Issues Releases Activity

Improve logging.

Browse Source 
Move command begin to C except when it must be called after another command in Perl (e.g. expire after backup). Command begin logs correctly for complex data types like hash and list. Specify which commands will log to file immediately and set the default log level for log messages that are common to all commands. File logging is initiated from C.
This commit is contained in:
David Steele 2018-03-12 10:55:58 -04:00
parent 94494a632f
commit 03f1082e86
34 changed files with 729 additions and 209 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
build/lib/pgBackRestBuild/Config/Build.pm
View File

@ -120,6 +120,7 @@ sub buildConfig
{
# Build command constants and data
#-------------------------------------------------------------------------------------------------------------------------------
my $rhCommandDefine = cfgDefineCommand();
my $rhEnum = $rhBuild->{&BLD_FILE}{&BLDLCL_FILE_CONFIG}{&BLD_ENUM}{&BLDLCL_ENUM_COMMAND};
my $iCommandTotal = 0;
@ -127,8 +128,10 @@ sub buildConfig
'static ConfigCommandData configCommandData[' . BLDLCL_CONSTANT_COMMAND_TOTAL . "] = CONFIG_COMMAND_LIST\n" .
"(";
foreach my $strCommand (cfgDefineCommandList())
foreach my $strCommand (sort(keys(%{$rhCommandDefine})))
{
my $rhCommand = $rhCommandDefine->{$strCommand};
# Build C enum
my $strCommandEnum = buildConfigCommandEnum($strCommand);
push(@{$rhEnum->{&BLD_LIST}}, $strCommandEnum);
@ -139,6 +142,9 @@ sub buildConfig
" CONFIG_COMMAND\n" .
" (\n" .
" CONFIG_COMMAND_NAME(\"${strCommand}\")\n" .
"\n" .
" CONFIG_COMMAND_LOG_FILE(" . ($rhCommand->{&CFGDEF_LOG_FILE} ? 'true' : 'false') . ")\n" .
" CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevel" . ucfirst(lc($rhCommand->{&CFGDEF_LOG_LEVEL_DEFAULT})) . ")\n" .
" )\n";
$iCommandTotal++;

151
build/lib/pgBackRestBuild/Config/Data.pm
View File

@ -435,6 +435,19 @@ use constant CFGDEF_DEFAULT_RETENTION_MAX => 9999999;
# Option definition constants - defines, types, sections, etc.
####################################################################################################################################
# Command defines
#-----------------------------------------------------------------------------------------------------------------------------------
# Does this command log to a file? This is the default behavior, but it can be overridden in code by calling logFileInit(). The
# default is true.
use constant CFGDEF_LOG_FILE => 'log-file';
push @EXPORT, qw(CFGDEF_LOG_FILE);
# Defines the log level to use for default messages that are output for every command. For example, the log message that lists all
# the options passed is usually output at the info level, but that might not be appropriate for some commands, such as info. Allow
# the log level to be lowered so these common messages will not be emmitted where they might be distracting.
use constant CFGDEF_LOG_LEVEL_DEFAULT => 'log-level-default';
push @EXPORT, qw(CFGDEF_LOG_LEVEL_DEFAULT);
# Option defines
#-----------------------------------------------------------------------------------------------------------------------------------
use constant CFGDEF_ALLOW_LIST => 'allow-list';
@ -498,6 +511,87 @@ use constant CFGDEF_SECTION_GLOBAL => 'global';
use constant CFGDEF_SECTION_STANZA => 'stanza';
push @EXPORT, qw(CFGDEF_SECTION_STANZA);
####################################################################################################################################
# Command definition data
####################################################################################################################################
my $rhCommandDefine =
{
&CFGCMD_ARCHIVE_GET =>
{
&CFGDEF_LOG_FILE => false,
},
&CFGCMD_ARCHIVE_PUSH =>
{
&CFGDEF_LOG_FILE => false,
},
&CFGCMD_BACKUP =>
{
},
&CFGCMD_CHECK =>
{
&CFGDEF_LOG_FILE => false,
},
&CFGCMD_EXPIRE =>
{
},
&CFGCMD_HELP =>
{
&CFGDEF_LOG_FILE => false,
&CFGDEF_LOG_LEVEL_DEFAULT => DEBUG,
},
&CFGCMD_INFO =>
{
&CFGDEF_LOG_FILE => false,
&CFGDEF_LOG_LEVEL_DEFAULT => DEBUG,
},
&CFGCMD_LOCAL =>
{
&CFGDEF_LOG_FILE => false,
},
&CFGCMD_REMOTE =>
{
&CFGDEF_LOG_FILE => false,
},
&CFGCMD_RESTORE =>
{
},
&CFGCMD_STANZA_CREATE =>
{
},
&CFGCMD_STANZA_DELETE =>
{
},
&CFGCMD_STANZA_UPGRADE =>
{
},
&CFGCMD_START =>
{
},
&CFGCMD_STOP =>
{
},
&CFGCMD_VERSION =>
{
&CFGDEF_LOG_FILE => false,
&CFGDEF_LOG_LEVEL_DEFAULT => DEBUG,
},
};
####################################################################################################################################
# Option definition data
####################################################################################################################################
@ -2085,7 +2179,25 @@ my %hConfigDefine =
);
####################################################################################################################################
# Process define defaults
# Process command define defaults
####################################################################################################################################
foreach my $strCommand (sort(keys(%{$rhCommandDefine})))
{
# Log files are created by default
if (!defined($rhCommandDefine->{$strCommand}{&CFGDEF_LOG_FILE}))
{
$rhCommandDefine->{$strCommand}{&CFGDEF_LOG_FILE} = true;
}
# Default log level is INFO
if (!defined($rhCommandDefine->{$strCommand}{&CFGDEF_LOG_LEVEL_DEFAULT}))
{
$rhCommandDefine->{$strCommand}{&CFGDEF_LOG_LEVEL_DEFAULT} = INFO;
}
}
####################################################################################################################################
# Process option define defaults
####################################################################################################################################
foreach my $strKey (sort(keys(%hConfigDefine)))
{
@ -2191,10 +2303,19 @@ foreach my $strKey (sort(keys(%hConfigDefine)))
{
confess &log(ASSERT, "int/float option '${strKey}' must have allow range or list");
}
# Ensure all commands are valid
foreach my $strCommand (sort(keys(%{$hConfigDefine{$strKey}{&CFGDEF_COMMAND}})))
{
if (!defined($rhCommandDefine->{$strCommand}))
{
confess &log(ASSERT, "invalid command '${strCommand}'");
}
}
}
####################################################################################################################################
# Get configuration definition
# Get option definition
####################################################################################################################################
sub cfgDefine
{
@ -2203,29 +2324,23 @@ sub cfgDefine
push @EXPORT, qw(cfgDefine);
####################################################################################################################################
# Get command definition
####################################################################################################################################
sub cfgDefineCommand
{
return dclone($rhCommandDefine);
}
push @EXPORT, qw(cfgDefineCommand);
####################################################################################################################################
# Get list of all commands
####################################################################################################################################
sub cfgDefineCommandList
{
my $rhCommandMap;
# Get unique list of commands
foreach my $strOption (sort(keys(%hConfigDefine)))
{
foreach my $strCommand (sort(keys(%{$hConfigDefine{$strOption}{&CFGDEF_COMMAND}})))
{
$rhCommandMap->{$strCommand} = true;
}
}
# Add special commands
$rhCommandMap->{&CFGCMD_HELP} = true;
$rhCommandMap->{&CFGCMD_VERSION} = true;
# Return sorted list
return (sort(keys(%{$rhCommandMap})));
return (sort(keys(%{$rhCommandDefine})));
}
push @EXPORT, qw(cfgDefineCommandList);

4
doc/xml/release.xml
View File

@ -55,6 +55,10 @@
<p>Improve Perl configuration. Set config before <code>Main::main()</code> call to avoid secrets being exposed in a stack trace. Move logic for setting defaults to C.</p>
</release-item>
<release-item>
<p>Improve logging. Move command begin to C except when it must be called after another command in Perl (e.g. <cmd>expire</cmd> after <cmd>backup</cmd>). Command begin logs correctly for complex data types like hash and list. Specify which commands will log to file immediately and set the default log level for log messages that are common to all commands. File logging is initiated from C.</p>
</release-item>
<release-item>
<release-item-contributor-list>
<release-item-ideator id="hunley.douglas"/>

2
lib/pgBackRest/Archive/Push/Async.pm
View File

@ -121,7 +121,7 @@ sub process
or confess &log(ERROR, "unable to create new session group: $OS_ERROR", ERROR_ASSERT);
# Open the log file
logFileSet(storageLocal(), cfgOption(CFGOPT_LOG_PATH) . '/' . cfgOption(CFGOPT_STANZA) . '-archive-async');
logFileSet(storageLocal(), cfgOption(CFGOPT_LOG_PATH) . '/' . cfgOption(CFGOPT_STANZA) . '-archive-async', true);
# Start processing
$self->processServer();

3
lib/pgBackRest/Common/Log.pm
View File

@ -122,6 +122,7 @@ sub logFileSet
{
my $oStorage = shift;
my $strFile = shift;
my $bLogFileFirstParam = shift;
# Only open the log file if file logging is enabled
if ($strLogLevelFile ne OFF)
@ -130,7 +131,7 @@ sub logFileSet
$strFile .= '.log';
$bLogFileExists = -e $strFile ? true : false;
$bLogFileFirst = true;
$bLogFileFirst = defined($bLogFileFirstParam) ? $bLogFileFirstParam : false;
if (!sysopen($hLogFile, $strFile, O_WRONLY | O_CREAT | O_APPEND, oct('0660')))
{

5
lib/pgBackRest/Config/Config.pm
View File

@ -133,9 +133,6 @@ sub configLoad
configLogging(true);
}
# Log the command begin
commandBegin();
# Neutralize the umask to make the repository file/path modes more consistent
if (cfgOptionValid(CFGOPT_NEUTRAL_UMASK) && cfgOption(CFGOPT_NEUTRAL_UMASK))
{
@ -435,6 +432,8 @@ sub commandBegin
cfgCommandWrite(cfgCommandId($strCommand), true, '', false, undef, true));
}
push @EXPORT, qw(commandBegin);
####################################################################################################################################
# commandEnd
#

6
lib/pgBackRest/Main.pm
View File

@ -64,6 +64,12 @@ sub main
############################################################################################################################
if (cfgCommandTest(CFGCMD_ARCHIVE_PUSH))
{
# If async then run command begin so that it gets output to the log file when it is opened
if (cfgOption(CFGOPT_ARCHIVE_ASYNC))
{
commandBegin();
}
# Load module dynamically
require pgBackRest::Archive::Push::Push;
pgBackRest::Archive::Push::Push->import();

1
libc/Makefile.PL
View File

@ -77,6 +77,7 @@ my @stryCFile =
'cipher/block.c',
'cipher/cipher.c',
'cipher/random.c',
'command/command.c',
'common/encode.c',
'common/encode/base64.c',
'common/error.c',

3
src/command/archive/push/push.c
View File

@ -143,9 +143,10 @@ cmdArchivePush()
if ((processId = fork()) == 0)
{
// Only want to see warnings and errors from async process
// Only want to see warnings and errors on the console from async process
cfgOptionSet(cfgOptLogLevelConsole, cfgSourceParam, varNewStrZ("warn"));
// Execute async process
perlExec();
}
// Wait for async process to exit (this should happen quickly) and report any errors

130
src/command/command.c
View File

@ -1,6 +1,7 @@
/***********************************************************************************************************************************
Common Command Routines
***********************************************************************************************************************************/
#include <assert.h>
#include <string.h>
#include "common/log.h"
@ -14,53 +15,95 @@ Begin the command
void
cmdBegin()
{
MEM_CONTEXT_TEMP_BEGIN()
// A command must be set
assert(cfgCommand() != cfgCmdNone);
// This is fairly expensive log message to generate so skip it if it won't be output
if (logWill(cfgLogLevelDefault()))
{
// Basic info on command start
String *info = strNewFmt("%s command begin %s:", cfgCommandName(cfgCommand()), PGBACKREST_VERSION);
// Loop though options and add the ones that are interesting
for (ConfigOption optionId = 0; optionId < CFG_OPTION_TOTAL; optionId++)
MEM_CONTEXT_TEMP_BEGIN()
{
const Variant *option = cfgOption(optionId);
// Basic info on command start
String *info = strNewFmt("%s command begin %s:", cfgCommandName(cfgCommand()), PGBACKREST_VERSION);
// Skip the option if it is not valid, or default, or not set
if (!cfgOptionValid(optionId) ||
cfgOptionSource(optionId) == cfgSourceDefault ||
(option == NULL && !cfgOptionNegate(optionId)))
// Loop though options and add the ones that are interesting
for (ConfigOption optionId = 0; optionId < CFG_OPTION_TOTAL; optionId++)
{
continue;
}
// Skip the option if it is not valid
if (!cfgOptionValid(optionId))
continue;
// If option was negated
if (cfgOptionNegate(optionId))
strCatFmt(info, " --no-%s", cfgOptionName(optionId));
// Else not negated
else
{
ConfigDefineOption optionDefId = cfgOptionDefIdFromId(optionId);
strCatFmt(info, " --%s", cfgOptionName(optionId));
if (cfgDefOptionType(optionDefId) != cfgDefOptTypeBoolean)
// If option was negated
if (cfgOptionNegate(optionId))
strCatFmt(info, " --no-%s", cfgOptionName(optionId));
// If option was reset
else if (cfgOptionReset(optionId))
strCatFmt(info, " --reset-%s", cfgOptionName(optionId));
// Else set and not default
else if (cfgOptionSource(optionId) != cfgSourceDefault && cfgOptionTest(optionId))
{
ConfigDefineOption optionDefId = cfgOptionDefIdFromId(optionId);
// Don't show redacted options
if (cfgDefOptionSecure(optionDefId))
strCat(info, "=<redacted>");
strCatFmt(info, " --%s=<redacted>", cfgOptionName(optionId));
// Output boolean option
else if (cfgDefOptionType(optionDefId) == cfgDefOptTypeBoolean)
strCatFmt(info, " --%s", cfgOptionName(optionId));
// Output other options
else
{
const String *optionStr = varStrForce(option);
StringList *valueList = NULL;
if (strchr(strPtr(optionStr), ' ') != NULL)
optionStr = strNewFmt("\"%s\"", strPtr(optionStr));
// Generate the values of hash options
if (cfgDefOptionType(optionDefId) == cfgDefOptTypeHash)
{
valueList = strLstNew();
strCatFmt(info, "=%s", strPtr(optionStr));
const KeyValue *optionKv = cfgOptionKv(optionId);
const VariantList *keyList = kvKeyList(optionKv);
for (unsigned int keyIdx = 0; keyIdx < varLstSize(keyList); keyIdx++)
{
strLstAdd(
valueList,
strNewFmt(
"%s=%s", strPtr(varStr(varLstGet(keyList, keyIdx))),
strPtr(varStrForce(kvGet(optionKv, varLstGet(keyList, keyIdx))))));
}
}
// Generate values for list options
else if (cfgDefOptionType(optionDefId) == cfgDefOptTypeList)
{
valueList = strLstNewVarLst(cfgOptionLst(optionId));
}
// Else only one value
else
{
valueList = strLstNew();
strLstAdd(valueList, varStrForce(cfgOption(optionId)));
}
// Output options and values
for (unsigned int valueListIdx = 0; valueListIdx < strLstSize(valueList); valueListIdx++)
{
const String *value = strLstGet(valueList, valueListIdx);
strCatFmt(info, " --%s", cfgOptionName(optionId));
if (strchr(strPtr(value), ' ') != NULL)
value = strNewFmt("\"%s\"", strPtr(value));
strCatFmt(info, "=%s", strPtr(value));
}
}
}
}
}
LOG_INFO(strPtr(info));
LOG_ANY(cfgLogLevelDefault(), 0, strPtr(info));
}
MEM_CONTEXT_TEMP_END();
}
MEM_CONTEXT_TEMP_END();
}
/***********************************************************************************************************************************
@ -69,17 +112,24 @@ End the command
void
cmdEnd(int code)
{
MEM_CONTEXT_TEMP_BEGIN()
// A command must be set
assert(cfgCommand() != cfgCmdNone);
// Skip this log message if it won't be output. It's not too expensive but since we skipped cmdBegin(), may as well.
if (logWill(cfgLogLevelDefault()))
{
// Basic info on command end
String *info = strNewFmt("%s command end: ", cfgCommandName(cfgCommand()));
MEM_CONTEXT_TEMP_BEGIN()
{
// Basic info on command end
String *info = strNewFmt("%s command end: ", cfgCommandName(cfgCommand()));
if (code == 0)
strCat(info, "completed successfully");
else
strCatFmt(info, "aborted with exception [%03d]", code);
if (code == 0)
strCat(info, "completed successfully");
else
strCatFmt(info, "aborted with exception [%03d]", code);
LOG_INFO(strPtr(info));
LOG_ANY(cfgLogLevelDefault(), 0, strPtr(info));
}
MEM_CONTEXT_TEMP_END();
}
MEM_CONTEXT_TEMP_END();
}

8
src/common/exit.c
View File

@ -4,6 +4,7 @@ Exit Routines
#include "command/command.h"
#include "common/exit.h"
#include "common/log.h"
#include "config/config.h"
/***********************************************************************************************************************************
Do cleanup and return result code
@ -16,12 +17,13 @@ exitSafe(bool error)
// Report error if one was thrown
if (error)
{
LOG_ERROR(errorCode(), errorMessage());
LOG_ANY(errorCode() == errorTypeCode(&AssertError) ? logLevelAssert : logLevelError, errorCode(), errorMessage());
result = errorCode();
}
// Log command end
cmdEnd(result);
// Log command end if a command is set
if (cfgCommand() != cfgCmdNone)
cmdEnd(result);
// Return result - caller should immediate pass this result to exit()
return result;

258
src/common/log.c
View File

@ -1,6 +1,9 @@
/***********************************************************************************************************************************
Log Handler
***********************************************************************************************************************************/
#include <assert.h>
#include <errno.h>
#include <fcntl.h>
#include <stdarg.h>
#include <string.h>
#include <strings.h>
@ -17,14 +20,27 @@ Module variables
// Log levels
LogLevel logLevelStdOut = logLevelError;
LogLevel logLevelStdErr = logLevelError;
LogLevel logLevelFile = logLevelOff;
// Log file handles
int logHandleStdOut = STDOUT_FILENO;
int logHandleStdErr = STDERR_FILENO;
int logHandleFile = -1;
// Has the log file banner been written yet?
bool logFileBanner = false;
// Is the timestamp printed in the log?
bool logTimestamp = false;
/***********************************************************************************************************************************
Debug Asserts
***********************************************************************************************************************************/
#define ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel) \
{ \
assert(logLevel > logLevelOff); \
}
/***********************************************************************************************************************************
Log buffer
***********************************************************************************************************************************/
@ -81,100 +97,194 @@ logLevelStr(LogLevel logLevel)
Initialize the log system
***********************************************************************************************************************************/
void
logInit(LogLevel logLevelStdOutParam, LogLevel logLevelStdErrParam, bool logTimestampParam)
logInit(LogLevel logLevelStdOutParam, LogLevel logLevelStdErrParam, LogLevel logLevelFileParam, bool logTimestampParam)
{
logLevelStdOut = logLevelStdOutParam;
logLevelStdErr = logLevelStdErrParam;
logLevelFile = logLevelFileParam;
logTimestamp = logTimestampParam;
}
/***********************************************************************************************************************************
Set the log file
***********************************************************************************************************************************/
void
logFileSet(const char *logFile)
{
// Close the file handle if it is already open
if (logHandleFile != -1)
{
close(logHandleFile);
logHandleFile = -1;
}
// Only open the file if there is a chance to log something
if (logLevelFile != logLevelOff)
{
// Open the file and handle errors
logHandleFile = open(logFile, O_CREAT | O_APPEND | O_WRONLY, 0750);
if (logHandleFile == -1)
{
int errNo = errno;
LOG_WARN("unable to open log file '%s': %s\nNOTE: process will continue without log file.", logFile, strerror(errNo));
};
// Output the banner on first log message
logFileBanner = false;
}
}
/***********************************************************************************************************************************
Check if a log level will be logged to any output
This is useful for log messages that are expensive to generate and should be skipped if they will be discarded.
***********************************************************************************************************************************/
static bool
logWillFile(LogLevel logLevel)
{
ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel)
return logLevel <= logLevelFile && logHandleFile != -1;
}
static bool
logWillStdErr(LogLevel logLevel)
{
ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel)
return logLevel <= logLevelStdErr;
}
static bool
logWillStdOut(LogLevel logLevel)
{
ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel)
return logLevel <= logLevelStdOut;
}
bool
logWill(LogLevel logLevel)
{
ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel)
return logWillStdOut(logLevel) || logWillStdErr(logLevel) || logWillFile(logLevel);
}
/***********************************************************************************************************************************
General log function
***********************************************************************************************************************************/
void
logInternal(LogLevel logLevel, const char *fileName, const char *functionName, int fileLine, int code, const char *format, ...)
logInternal(LogLevel logLevel, const char *fileName, const char *functionName, int code, const char *format, ...)
{
// Should this entry be logged?
if (logLevel <= logLevelStdOut || logLevel <= logLevelStdErr)
ASSERT_MESSAGE_LOG_LEVEL_VALID(logLevel)
size_t bufferPos = 0; // Current position in the buffer
// Add time
if (logTimestamp)
{
size_t bufferPos = 0;
TimeUSec logTimeUSec = timeUSec();
time_t logTime = (time_t)(logTimeUSec / USEC_PER_SEC);
// Add time
if (logTimestamp && logLevel > logLevelStdErr)
bufferPos += strftime(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "%Y-%m-%d %H:%M:%S", localtime(&logTime));
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, ".%03d ", (int)(logTimeUSec / 1000 % 1000));
}
// Add process and aligned log level
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "P00 %*s: ", 6, logLevelStr(logLevel));
// Position after the timestamp and process id for output to stderr
size_t messageStdErrPos = bufferPos - strlen(logLevelStr(logLevel)) - 2;
// Check that error code matches log level
assert(
code == 0 || (logLevel == logLevelError && code != errorTypeCode(&AssertError)) ||
(logLevel == logLevelAssert && code == errorTypeCode(&AssertError)));
// Add code
if (code != 0)
bufferPos += (size_t)snprintf(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "[%03d]: ", code);
// Add debug info
if (logLevel >= logLevelDebug)
{
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "%s:%s(): ", fileName, functionName);
}
// Format message
va_list argumentList;
va_start(argumentList, format);
if (logLevel <= logLevelStdErr || strchr(format, '\n') == NULL)
bufferPos += (size_t)vsnprintf(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, format, argumentList);
else
{
vsnprintf(logFormat, LOG_BUFFER_SIZE, format, argumentList);
// Indent all lines after the first
const char *formatPtr = logFormat;
const char *linefeedPtr = strchr(logFormat, '\n');
int indentSize = 12;
while (linefeedPtr != NULL)
{
TimeUSec logTimeUSec = timeUSec();
time_t logTime = (time_t)(logTimeUSec / USEC_PER_SEC);
strncpy(logBuffer + bufferPos, formatPtr, (size_t)(linefeedPtr - formatPtr + 1));
bufferPos += (size_t)(linefeedPtr - formatPtr + 1);
bufferPos += strftime(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "%Y-%m-%d %H:%M:%S", localtime(&logTime));
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, ".%03d ", (int)(logTimeUSec / 1000 % 1000));
formatPtr = linefeedPtr + 1;
linefeedPtr = strchr(formatPtr, '\n');
for (int indentIdx = 0; indentIdx < indentSize; indentIdx++)
logBuffer[bufferPos++] = ' ';
}
// Add process and aligned log level
if (logLevel > logLevelStdErr)
strcpy(logBuffer + bufferPos, formatPtr);
bufferPos += strlen(formatPtr);
}
va_end(argumentList);
// Add linefeed
logBuffer[bufferPos++] = '\n';
logBuffer[bufferPos] = 0;
// Determine where to log the message based on log-level-stderr
if (logWillStdErr(logLevel))
{
THROW_ON_SYS_ERROR(
write(
logHandleStdErr, logBuffer + messageStdErrPos, bufferPos - messageStdErrPos) != (int)(bufferPos - messageStdErrPos),
FileWriteError, "unable to write log to stderr");
}
else if (logWillStdOut(logLevel))
{
THROW_ON_SYS_ERROR(
write(logHandleStdOut, logBuffer, bufferPos) != (int)bufferPos, FileWriteError, "unable to write log to stdout");
}
// Log to file
if (logWillFile(logLevel))
{
// If the banner has not been written
if (!logFileBanner)
{
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "P00 %*s: ", 6, logLevelStr(logLevel));
// Add a blank line if the file already has content
if (lseek(logHandleFile, 0, SEEK_END) > 0)
THROW_ON_SYS_ERROR(write(logHandleFile, "\n", 1) != 1, FileWriteError, "unable to write banner spacing to file");
// Write process start banner
const char *banner = "-------------------PROCESS START-------------------\n";
THROW_ON_SYS_ERROR(
write(logHandleFile, banner, strlen(banner)) != (int)strlen(banner), FileWriteError,
"unable to write banner to file");
// Mark banner as written
logFileBanner = true;
}
// Else just the log level with no alignment
else
bufferPos += (size_t)snprintf(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "%s: ", logLevelStr(logLevel));
// Add error code
if (code != 0)
bufferPos += (size_t)snprintf(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "[%03d]: ", code);
// Add debug info
if (logLevelStdOut >= logLevelDebug)
{
bufferPos += (size_t)snprintf(
logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, "%s:%s():%d: ", fileName, functionName, fileLine);
}
// Format message
va_list argumentList;
va_start(argumentList, format);
if (logLevel <= logLevelStdErr || strchr(format, '\n') == NULL)
bufferPos += (size_t)vsnprintf(logBuffer + bufferPos, LOG_BUFFER_SIZE - bufferPos, format, argumentList);
else
{
vsnprintf(logFormat, LOG_BUFFER_SIZE, format, argumentList);
// Indent all lines after the first
const char *formatPtr = logFormat;
const char *linefeedPtr = strchr(logFormat, '\n');
int indentSize = 12;
while (linefeedPtr != NULL)
{
strncpy(logBuffer + bufferPos, formatPtr, (size_t)(linefeedPtr - formatPtr + 1));
bufferPos += (size_t)(linefeedPtr - formatPtr + 1);
formatPtr = linefeedPtr + 1;
linefeedPtr = strchr(formatPtr, '\n');
for (int indentIdx = 0; indentIdx < indentSize; indentIdx++)
logBuffer[bufferPos++] = ' ';
}
strcpy(logBuffer + bufferPos, formatPtr);
bufferPos += strlen(formatPtr);
}
va_end(argumentList);
// Add linefeed
logBuffer[bufferPos++] = '\n';
logBuffer[bufferPos] = 0;
// Determine where to log the message based on log-level-stderr
int stream = logHandleStdOut;
if (logLevel <= logLevelStdErr)
stream = logHandleStdErr;
THROW_ON_SYS_ERROR(
write(stream, logBuffer, bufferPos) != (int)bufferPos, FileWriteError, "unable to write log to console");
write(logHandleFile, logBuffer, bufferPos) != (int)bufferPos, FileWriteError, "unable to write log to file");
}
}

17
src/common/log.h
View File

@ -28,9 +28,11 @@ Expose internal data for debugging/testing
#ifndef NDEBUG
extern LogLevel logLevelStdOut;
extern LogLevel logLevelStdErr;
extern LogLevel logLevelFile;
extern int logHandleStdOut;
extern int logHandleStdErr;
extern int logHandleFile;
extern bool logTimestamp;
#endif
@ -38,16 +40,25 @@ Expose internal data for debugging/testing
/***********************************************************************************************************************************
Functions
***********************************************************************************************************************************/
void logInit(LogLevel logLevelStdOut, LogLevel logLevelStdErr, bool logTimestamp);
void logInit(LogLevel logLevelStdOut, LogLevel logLevelStdErr, LogLevel logLevelFile, bool logTimestamp);
void logFileSet(const char *logFile);
bool logWill(LogLevel logLevel);
LogLevel logLevelEnum(const char *logLevel);
const char *logLevelStr(LogLevel logLevel);
/***********************************************************************************************************************************
Macros
Only call logInternal() if the message will be logged to one of the available outputs.
***********************************************************************************************************************************/
#define LOG_ANY(logLevel, code, ...) \
logInternal(logLevel, __FILE__, __func__, __LINE__, code, __VA_ARGS__)
{ \
if (logWill(logLevel)) \
logInternal(logLevel, __FILE__, __func__, code, __VA_ARGS__); \
}
#define LOG_ERROR(code, ...) \
LOG_ANY(logLevelError, code, __VA_ARGS__)
#define LOG_INFO(...) \
@ -59,6 +70,6 @@ Macros
Internal Functions
***********************************************************************************************************************************/
void logInternal(
LogLevel logLevel, const char *fileName, const char *functionName, int fileLine, int code, const char *format, ...);
LogLevel logLevel, const char *fileName, const char *functionName, int code, const char *format, ...);
#endif

48
src/config/config.auto.c
View File

@ -12,81 +12,129 @@ static ConfigCommandData configCommandData[CFG_COMMAND_TOTAL] = CONFIG_COMMAND_L
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("archive-get")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("archive-push")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("backup")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("check")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("expire")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("help")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelDebug)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("info")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelDebug)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("local")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("remote")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("restore")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("stanza-create")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("stanza-delete")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("stanza-upgrade")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("start")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("stop")
CONFIG_COMMAND_LOG_FILE(true)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelInfo)
)
CONFIG_COMMAND
(
CONFIG_COMMAND_NAME("version")
CONFIG_COMMAND_LOG_FILE(false)
CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelDebug)
)
)

27
src/config/config.c
View File

@ -1,6 +1,7 @@
/***********************************************************************************************************************************
Command and Option Configuration
***********************************************************************************************************************************/
#include <assert.h>
#include <string.h>
#include "common/error.h"
@ -13,6 +14,8 @@ Map command names to ids and vice versa.
typedef struct ConfigCommandData
{
const char *name;
bool logFile:1;
unsigned int logLevelDefault:4;
} ConfigCommandData;
#define CONFIG_COMMAND_LIST(...) \
@ -21,6 +24,10 @@ typedef struct ConfigCommandData
#define CONFIG_COMMAND(...) \
{__VA_ARGS__},
#define CONFIG_COMMAND_LOG_FILE(logFileParam) \
.logFile = logFileParam,
#define CONFIG_COMMAND_LOG_LEVEL_DEFAULT(logLevelDefaultParam) \
.logLevelDefault = logLevelDefaultParam,
#define CONFIG_COMMAND_NAME(nameParam) \
.name = nameParam,
@ -260,6 +267,26 @@ cfgExeSet(const String *exeParam)
MEM_CONTEXT_END();
}
/***********************************************************************************************************************************
Does this command log to a file?
***********************************************************************************************************************************/
bool
cfgLogFile()
{
assert(cfgCommand() != cfgCmdNone);
return configCommandData[cfgCommand()].logFile;
}
/***********************************************************************************************************************************
Get default log level -- used for log messages that are common to all commands
***********************************************************************************************************************************/
LogLevel
cfgLogLevelDefault()
{
assert(cfgCommand() != cfgCmdNone);
return (LogLevel)configCommandData[cfgCommand()].logLevelDefault;
}
/***********************************************************************************************************************************
Ensure that option id is valid
***********************************************************************************************************************************/

4
src/config/config.h
View File

@ -7,6 +7,7 @@ config/parse.c sets the command and options and determines which options are val
#ifndef CONFIG_H
#define CONFIG_H
#include "common/log.h"
#include "common/type.h"
#include "config/define.h"
@ -20,6 +21,9 @@ Access the current command and command parameters.
ConfigCommand cfgCommand();
const char *cfgCommandName(ConfigCommand commandId);
bool cfgLogFile();
LogLevel cfgLogLevelDefault();
const StringList *cfgCommandParam();
/***********************************************************************************************************************************

2
src/config/define.c
View File

@ -231,7 +231,7 @@ cfgDefDataFind(
bool dataDefFound = false; \
int dataDef = 0; \
int dataDefListSize = 0; \
const void **dataDefList = NULL; \
const void **dataDefList = NULL; \
\
cfgDefDataFind( \
type, commandDefId, configDefineOptionData[optionDefId].data, &dataDefFound, &dataDef, &dataDefList, &dataDefListSize);

54
src/config/load.c
View File

@ -3,6 +3,7 @@ Configuration Load
***********************************************************************************************************************************/
#include <string.h>
#include "command/command.h"
#include "common/memContext.h"
#include "common/log.h"
#include "config/config.h"
@ -31,6 +32,7 @@ cfgLoadParam(unsigned int argListSize, const char *argList[], String *exe)
{
LogLevel logLevelConsole = logLevelOff;
LogLevel logLevelStdErr = logLevelOff;
LogLevel logLevelFile = logLevelOff;
bool logTimestamp = true;
if (cfgOptionValid(cfgOptLogLevelConsole))
@ -39,30 +41,48 @@ cfgLoadParam(unsigned int argListSize, const char *argList[], String *exe)
if (cfgOptionValid(cfgOptLogLevelStderr))
logLevelStdErr = logLevelEnum(strPtr(cfgOptionStr(cfgOptLogLevelStderr)));
if (cfgOptionValid(cfgOptLogLevelFile))
logLevelFile = logLevelEnum(strPtr(cfgOptionStr(cfgOptLogLevelFile)));
if (cfgOptionValid(cfgOptLogTimestamp))
logTimestamp = cfgOptionBool(cfgOptLogTimestamp);
logInit(logLevelConsole, logLevelStdErr, logTimestamp);
logInit(logLevelConsole, logLevelStdErr, logLevelFile, logTimestamp);
}
// If an exe was passed in the use that
if (exe != NULL)
cfgExeSet(exe);
// Set default for repo-host-cmd
if (cfgOptionValid(cfgOptRepoHost) && cfgOptionTest(cfgOptRepoHost) &&
cfgOptionSource(cfgOptRepoHostCmd) == cfgSourceDefault)
// Only continue if a command was set. If no command is set then help will be displayed
if (cfgCommand() != cfgCmdNone)
{
cfgOptionDefaultSet(cfgOptRepoHostCmd, varNewStr(cfgExe()));
}
// Set default for pg-host-cmd
if (cfgOptionValid(cfgOptPgHostCmd))
{
for (unsigned int optionIdx = 0; optionIdx < cfgOptionIndexTotal(cfgOptPgHost); optionIdx++)
// Open the log file if this command logs to a file
if (cfgLogFile())
{
if (cfgOptionTest(cfgOptPgHost + optionIdx) && cfgOptionSource(cfgOptPgHostCmd + optionIdx) == cfgSourceDefault)
cfgOptionDefaultSet(cfgOptPgHostCmd + optionIdx, varNewStr(cfgExe()));
logFileSet(
strPtr(strNewFmt("%s/%s-%s.log", strPtr(cfgOptionStr(cfgOptLogPath)), strPtr(cfgOptionStr(cfgOptStanza)),
cfgCommandName(cfgCommand()))));
}
// Begin the command
cmdBegin();
// If an exe was passed in the use that
if (exe != NULL)
cfgExeSet(exe);
// Set default for repo-host-cmd
if (cfgOptionValid(cfgOptRepoHost) && cfgOptionTest(cfgOptRepoHost) &&
cfgOptionSource(cfgOptRepoHostCmd) == cfgSourceDefault)
{
cfgOptionDefaultSet(cfgOptRepoHostCmd, varNewStr(cfgExe()));
}
// Set default for pg-host-cmd
if (cfgOptionValid(cfgOptPgHostCmd))
{
for (unsigned int optionIdx = 0; optionIdx < cfgOptionIndexTotal(cfgOptPgHost); optionIdx++)
{
if (cfgOptionTest(cfgOptPgHost + optionIdx) && cfgOptionSource(cfgOptPgHostCmd + optionIdx) == cfgSourceDefault)
cfgOptionDefaultSet(cfgOptPgHostCmd + optionIdx, varNewStr(cfgExe()));
}
}
}
}

2
src/config/parse.c
View File

@ -230,7 +230,7 @@ configParse(unsigned int argListSize, const char *argList[])
// Enable logging (except for local and remote commands) so config file warnings will be output
if (cfgCommand() != cfgCmdLocal && cfgCommand() != cfgCmdRemote)
logInit(logLevelWarn, logLevelWarn, false);
logInit(logLevelWarn, logLevelWarn, logLevelOff, false);
// Phase 2: parse config file unless --no-config passed
// ---------------------------------------------------------------------------------------------------------------------

2
src/main.c
View File

@ -6,7 +6,6 @@ Main
#include "command/archive/push/push.h"
#include "command/help/help.h"
#include "command/command.h"
#include "common/error.h"
#include "common/exit.h"
#include "config/config.h"
@ -44,7 +43,6 @@ main(int argListSize, const char *argList[])
// -------------------------------------------------------------------------------------------------------------------------
else if (cfgCommand() == cfgCmdArchivePush && cfgOptionBool(cfgOptArchiveAsync))
{
cmdBegin();
cmdArchivePush();
}

4
test/expect/mock-all-001.log
View File

@ -4332,7 +4332,7 @@ db-version="9.4"
restore delta, remap - selective restore 16384 (db-master host)
> [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --delta --log-level-console=detail --db-include=16384 --stanza=db restore
------------------------------------------------------------------------------------------------------------------------------------
P00 INFO: restore command begin [BACKREST-VERSION]: --compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=16384=1 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore command begin [BACKREST-VERSION]: --compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=16384 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore backup set [BACKUP-DIFF-5]
P00 INFO: remap tablespace pg_tblspc/2 directory to [TEST_PATH]/db-master/db/tablespace/ts2-2
P00 DETAIL: check [TEST_PATH]/db-master/db/base-2 exists
@ -4369,7 +4369,7 @@ restore_command = '[BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf
restore delta, remap - selective restore 32768 (db-master host)
> [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --delta --log-level-console=detail --db-include=32768 --stanza=db restore
------------------------------------------------------------------------------------------------------------------------------------
P00 INFO: restore command begin [BACKREST-VERSION]: --compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=32768=1 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore command begin [BACKREST-VERSION]: --compress --compress-level=3 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=32768 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-path=[TEST_PATH]/db-master/repo --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore backup set [BACKUP-DIFF-5]
P00 INFO: remap tablespace pg_tblspc/2 directory to [TEST_PATH]/db-master/db/tablespace/ts2-2
P00 DETAIL: check [TEST_PATH]/db-master/db/base-2 exists

4
test/expect/mock-all-002.log
View File

@ -4613,7 +4613,7 @@ db-version="9.4"
restore delta, remap - selective restore 16384 (db-master host)
> [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --delta --log-level-console=detail --db-include=16384 --stanza=db restore
------------------------------------------------------------------------------------------------------------------------------------
P00 INFO: restore command begin [BACKREST-VERSION]: --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=16384=1 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-2] --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore command begin [BACKREST-VERSION]: --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=16384 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-2] --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore backup set [BACKUP-DIFF-5]
P00 INFO: remap tablespace pg_tblspc/2 directory to [TEST_PATH]/db-master/db/tablespace/ts2-2
P00 DETAIL: check [TEST_PATH]/db-master/db/base-2 exists
@ -4650,7 +4650,7 @@ restore_command = '[BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf
restore delta, remap - selective restore 32768 (db-master host)
> [CONTAINER-EXEC] db-master [BACKREST-BIN] --config=[TEST_PATH]/db-master/pgbackrest.conf --delta --log-level-console=detail --db-include=32768 --stanza=db restore
------------------------------------------------------------------------------------------------------------------------------------
P00 INFO: restore command begin [BACKREST-VERSION]: --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=32768=1 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-2] --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore command begin [BACKREST-VERSION]: --no-compress --compress-level=3 --compress-level-network=1 --config=[TEST_PATH]/db-master/pgbackrest.conf --db-include=32768 --delta --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 --pg1-path=[TEST_PATH]/db-master/db/base-2 --protocol-timeout=60 --repo1-host=backup --repo1-host-cmd=[BACKREST-BIN] --repo1-host-config=[TEST_PATH]/backup/pgbackrest.conf --repo1-host-user=[USER-2] --stanza=db --tablespace-map=2=[TEST_PATH]/db-master/db/tablespace/ts2-2
P00 INFO: restore backup set [BACKUP-DIFF-5]
P00 INFO: remap tablespace pg_tblspc/2 directory to [TEST_PATH]/db-master/db/tablespace/ts2-2
P00 DETAIL: check [TEST_PATH]/db-master/db/base-2 exists

2
test/lib/pgBackRestTest/Common/DefineTest.pm
View File

@ -146,7 +146,7 @@ my $oTestDef =
},
{
&TESTDEF_NAME => 'log',
&TESTDEF_TOTAL => 3,
&TESTDEF_TOTAL => 4,
&TESTDEF_C => true,
&TESTDEF_CDEF => '-DNO_LOG',

25
test/lib/pgBackRestTest/Common/JobTest.pm
View File

@ -31,6 +31,11 @@ use pgBackRestTest::Common::ListTest;
use pgBackRestTest::Common::RunTest;
use pgBackRestTest::Common::VmTest;
####################################################################################################################################
# Build flags from the last build. When the build flags change test files must be rebuilt
####################################################################################################################################
my $rhBuildFlags = undef;
####################################################################################################################################
# new
####################################################################################################################################
@ -172,11 +177,21 @@ sub run
{bSuppressStdErr => true});
# If testing C code copy source files to the test directory
if ($self->{oTest}->{&TEST_C} && !$bGCovExists)
if ($self->{oTest}->{&TEST_C})
{
executeTest(
"cp -r $self->{strBackRestBase}/src/* $self->{strGCovPath} &&" .
"cp -r $self->{strBackRestBase}/test/src/* $self->{strGCovPath}");
if (!$bGCovExists)
{
executeTest("cp -r $self->{strBackRestBase}/src/* $self->{strGCovPath}");
}
if (!$bGCovExists || defined($rhBuildFlags->{$self->{iVmIdx}}) != defined($self->{oTest}->{&TEST_CDEF}) ||
defined($rhBuildFlags->{$self->{iVmIdx}}) &&
$rhBuildFlags->{$self->{iVmIdx}} ne $self->{oTest}->{&TEST_CDEF})
{
executeTest("cp -r $self->{strBackRestBase}/test/src/* $self->{strGCovPath}");
}
$rhBuildFlags->{$self->{iVmIdx}} = $self->{oTest}->{&TEST_CDEF};
}
# If testing Perl code (or C code that calls Perl code) install bin and Perl C Library
@ -343,7 +358,7 @@ sub run
" -c test.c\n" .
"\n" .
".c.o:\n" .
"\t\$(CC) \$(CFLAGS) -O2 -c \$< -o \$@\n";
"\t\$(CC) \$(CFLAGS) \$(TESTFLAGS) -O2 -c \$< -o \$@\n";
$self->{oStorageTest}->put($self->{strGCovPath} . "/Makefile", $strMakefile);

1
test/lib/pgBackRestTest/Env/Host/HostBackupTest.pm
View File

@ -110,6 +110,7 @@ sub new
# Set log/lock paths
$self->{strLogPath} = $self->testPath() . '/' . HOST_PATH_LOG;
storageTest()->pathCreate($self->{strLogPath}, {strMode => '0770'});
$self->{strLockPath} = $self->testPath() . '/' . HOST_PATH_LOCK;
# Set conf file

20
test/src/common/harnessTest.c
View File

@ -7,6 +7,7 @@ C Test Harness
#include <string.h>
#include "common/harnessTest.h"
#include "common/logTest.h"
#define TEST_LIST_SIZE 64
@ -19,6 +20,7 @@ static TestData testList[TEST_LIST_SIZE];
static int testRun = 0;
static int testTotal = 0;
static bool testFirst = true;
static const char *testPathData = NULL;
@ -64,12 +66,25 @@ testBegin(const char *name)
if (testList[testRun - 1].selected)
{
#ifndef NO_LOG
// Make sure there is nothing untested left in the log
if (!testFirst)
testLogFinal();
#endif
// No longer the first test
testFirst = false;
if (testRun != 1)
printf("\n");
printf("run %03d - %s\n", testRun, name);
fflush(stdout);
#ifndef NO_LOG
// Initialize logging
testLogInit();
#endif
return true;
}
@ -82,6 +97,11 @@ testComplete - make sure all expected tests ran
void
testComplete()
{
#ifndef NO_LOG
// Make sure there is nothing untested left in the log
testLogFinal();
#endif
// Check that all tests ran
if (testRun != testTotal)
{

2
test/src/common/logTest.c
View File

@ -22,7 +22,7 @@ Initialize log for testing
void
testLogInit()
{
logInit(logLevelInfo, logLevelOff, false);
logInit(logLevelInfo, logLevelOff, logLevelOff, false);
stdoutFile = strNewFmt("%s/stdout.log", testPath());
logHandleStdOut = open(strPtr(stdoutFile), O_WRONLY | O_CREAT | O_TRUNC, 0640);

7
test/src/module/archive/pushTest.c
View File

@ -4,6 +4,7 @@ Test Archive Push Command
#include <stdlib.h>
#include "config/load.h"
#include "version.h"
/***********************************************************************************************************************************
Test Run
@ -22,7 +23,7 @@ testRun()
strLstAddZ(argList, "--stanza=db");
strLstAddZ(argList, "archive-push");
cfgLoad(strLstSize(argList), strLstPtr(argList));
logInit(logLevelInfo, logLevelOff, false);
logInit(logLevelInfo, logLevelOff, logLevelOff, false);
// -------------------------------------------------------------------------------------------------------------------------
String *segment = strNew("000000010000000100000001");
@ -107,7 +108,7 @@ testRun()
strLstAddZ(argList, "--log-level-console=off");
strLstAddZ(argList, "--log-level-stderr=off");
cfgLoad(strLstSize(argList), strLstPtr(argList));
logInit(logLevelInfo, logLevelOff, false);
logInit(logLevelInfo, logLevelOff, logLevelOff, false);
TRY_BEGIN()
{
@ -127,7 +128,7 @@ testRun()
// -------------------------------------------------------------------------------------------------------------------------
strLstAdd(argList, strNewFmt("--pg1-path=%s/db", testPath()));
cfgLoad(strLstSize(argList), strLstPtr(argList));
logInit(logLevelInfo, logLevelOff, false);
logInit(logLevelInfo, logLevelOff, logLevelOff, false);
TEST_ERROR(
cmdArchivePush(), ArchiveTimeoutError,

21
test/src/module/command/commandTest.c
View File

@ -31,7 +31,7 @@ testRun()
cfgOptionSet(cfgOptPgHost, cfgSourceConfig, NULL);
cfgOptionValidSet(cfgOptRepoHost, true);
cfgOptionSet(cfgOptRepoHost, cfgSourceConfig, varNewStr(strNew("backup1")));
cfgOptionResetSet(cfgOptRepoHost, true);
cfgOptionValidSet(cfgOptRepoPath, true);
cfgOptionSet(cfgOptRepoPath, cfgSourceConfig, varNewStr(strNew("/path/to the/repo")));
@ -39,10 +39,25 @@ testRun()
cfgOptionValidSet(cfgOptRepoS3Key, true);
cfgOptionSet(cfgOptRepoS3Key, cfgSourceConfig, varNewStr(strNew("SECRET-STUFF")));
cfgOptionValidSet(cfgOptDbInclude, true);
StringList *list = strLstNew();
strLstAddZ(list, "db1");
strLstAddZ(list, "db2");
cfgOptionSet(cfgOptDbInclude, cfgSourceParam, varNewVarLst(varLstNewStrLst(list)));
// !!! WHY DO WE STILL NEED TO CREATE THE VAR KV EMPTY?
cfgOptionValidSet(cfgOptRecoveryOption, true);
Variant *recoveryVar = varNewKv();
KeyValue *recoveryKv = varKv(recoveryVar);
kvPut(recoveryKv, varNewStr(strNew("standby_mode")), varNewStr(strNew("on")));
kvPut(recoveryKv, varNewStr(strNew("primary_conn_info")), varNewStr(strNew("blah")));
cfgOptionSet(cfgOptRecoveryOption, cfgSourceParam, recoveryVar);
cmdBegin();
testLogResult(
"P00 INFO: archive-get command begin " PGBACKREST_VERSION ": --compress --no-config --repo1-host=backup1 "
"--repo1-path=\"/path/to the/repo\" --repo1-s3-key=<redacted>");
"P00 INFO: archive-get command begin " PGBACKREST_VERSION ": --compress --no-config --db-include=db1"
" --db-include=db2 --recovery-option=standby_mode=on --recovery-option=primary_conn_info=blah --reset-repo1-host"
" --repo1-path=\"/path/to the/repo\" --repo1-s3-key=<redacted>");
// -------------------------------------------------------------------------------------------------------------------------
cmdEnd(0);

2
test/src/module/common/exitTest.c
View File

@ -15,7 +15,7 @@ testRun()
cfgInit();
cfgCommandSet(cfgCmdArchivePush);
TEST_RESULT_INT(exitSafe(NULL), 0, "exit with no error")
TEST_RESULT_INT(exitSafe(false), 0, "exit with no error")
testLogResult("P00 INFO: archive-push command end: completed successfully");
// -------------------------------------------------------------------------------------------------------------------------

91
test/src/module/common/logTest.c
View File

@ -32,16 +32,50 @@ testRun()
{
TEST_RESULT_INT(logLevelStdOut, logLevelError, "console logging is error");
TEST_RESULT_INT(logLevelStdErr, logLevelError, "stderr logging is error");
TEST_RESULT_VOID(logInit(logLevelInfo, logLevelWarn, true), "init logging");
TEST_RESULT_INT(logLevelFile, logLevelOff, "file logging is off");
TEST_RESULT_VOID(logInit(logLevelInfo, logLevelWarn, logLevelError, true), "init logging");
TEST_RESULT_INT(logLevelStdOut, logLevelInfo, "console logging is info");
TEST_RESULT_INT(logLevelStdErr, logLevelWarn, "stderr logging is warn");
TEST_RESULT_INT(logLevelFile, logLevelError, "file logging is error");
}
// *****************************************************************************************************************************
if (testBegin("logWill*()"))
{
logLevelStdOut = logLevelOff;
logLevelStdErr = logLevelOff;
logLevelFile = logLevelOff;
logHandleFile = -1;
TEST_RESULT_BOOL(logWill(logLevelError), false, "will not log");
TEST_RESULT_BOOL(logWillFile(logLevelError), false, "will not log file");
TEST_RESULT_BOOL(logWillStdErr(logLevelError), false, "will not log stderr");
TEST_RESULT_BOOL(logWillStdOut(logLevelError), false, "will not log stdout");
logLevelStdOut = logLevelError;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log");
TEST_RESULT_BOOL(logWillStdOut(logLevelError), true, "will log stdout");
logLevelStdOut = logLevelOff;
logLevelStdErr = logLevelError;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log");
TEST_RESULT_BOOL(logWillStdErr(logLevelError), true, "will log stderr");
logLevelStdErr = logLevelOff;
logLevelFile = logLevelError;
TEST_RESULT_BOOL(logWill(logLevelError), false, "will not log");
TEST_RESULT_BOOL(logWillFile(logLevelError), false, "will not log file");
logHandleFile = 1;
TEST_RESULT_BOOL(logWill(logLevelError), true, "will log");
TEST_RESULT_BOOL(logWillFile(logLevelError), true, "will log file");
logHandleFile = -1;
}
// *****************************************************************************************************************************
if (testBegin("logInternal()"))
{
TEST_RESULT_VOID(logInit(logLevelWarn, logLevelOff, true), "init logging to warn (timestamp on)");
TEST_RESULT_VOID(logInternal(logLevelWarn, NULL, NULL, 0, 0, "TEST"), "log timestamp");
TEST_RESULT_VOID(logInit(logLevelWarn, logLevelOff, logLevelOff, true), "init logging to warn (timestamp on)");
TEST_RESULT_VOID(logInternal(logLevelWarn, NULL, NULL, 0, "TEST"), "log timestamp");
String *logTime = strNewN(logBuffer, 23);
TEST_RESULT_BOOL(
@ -50,31 +84,45 @@ testRun()
true, "check timestamp format: %s", strPtr(logTime));
// Redirect output to files
TEST_RESULT_VOID(logInit(logLevelWarn, logLevelOff, false), "init logging to warn (timestamp off)");
TEST_RESULT_VOID(logInit(logLevelWarn, logLevelOff, logLevelOff, false), "init logging to warn (timestamp off)");
String *stdoutFile = strNewFmt("%s/stdout.log", testPath());
String *stderrFile = strNewFmt("%s/stderr.log", testPath());
String *fileFile = strNewFmt("%s/file.log", testPath());
logHandleStdOut = open(strPtr(stdoutFile), O_WRONLY | O_CREAT | O_TRUNC, 0640);
logHandleStdErr = open(strPtr(stderrFile), O_WRONLY | O_CREAT | O_TRUNC, 0640);
logBuffer[0] = 0;
TEST_RESULT_VOID(logInternal(logLevelWarn, NULL, NULL, 0, 0, "format %d", 99), "log warn");
TEST_RESULT_VOID(logInternal(logLevelWarn, NULL, NULL, 0, "format %d", 99), "log warn");
TEST_RESULT_STR(logBuffer, "P00 WARN: format 99\n", " check log");
logBuffer[0] = 0;
TEST_RESULT_VOID(logInternal(logLevelError, NULL, NULL, 0, 25, "message"), "log error");
TEST_RESULT_STR(logBuffer, "P00 ERROR: [025]: message\n", " check log");
TEST_RESULT_VOID(logInternal(logLevelError, NULL, NULL, 26, "message"), "log error");
TEST_RESULT_STR(logBuffer, "P00 ERROR: [026]: message\n", " check log");
logBuffer[0] = 0;
TEST_RESULT_VOID(logInternal(logLevelError, NULL, NULL, 0, 25, "message1\nmessage2"), "log error with multiple lines");
TEST_RESULT_STR(logBuffer, "P00 ERROR: [025]: message1\n message2\n", " check log");
TEST_RESULT_VOID(logInternal(logLevelError, NULL, NULL, 26, "message1\nmessage2"), "log error with multiple lines");
TEST_RESULT_STR(logBuffer, "P00 ERROR: [026]: message1\n message2\n", " check log");
TEST_RESULT_VOID(logInit(logLevelDebug, logLevelDebug, false), "init logging to debug");
TEST_RESULT_VOID(logInit(logLevelDebug, logLevelDebug, logLevelDebug, false), "init logging to debug");
// Log to file
logFileSet(strPtr(fileFile));
logBuffer[0] = 0;
TEST_RESULT_VOID(logInternal(logLevelError, "test.c", "test_func", 33, 25, "message"), "log error");
TEST_RESULT_STR(logBuffer, "ERROR: [025]: test.c:test_func():33: message\n", " check log");
TEST_RESULT_VOID(logInternal(logLevelDebug, "test.c", "test_func", 0, "message"), "log debug");
TEST_RESULT_STR(logBuffer, "P00 DEBUG: test.c:test_func(): message\n", " check log");
// Reopen the log file
logFileSet(strPtr(fileFile));
logBuffer[0] = 0;
TEST_RESULT_VOID(logInternal(logLevelInfo, "test.c", "test_func", 0, "info message"), "log info");
TEST_RESULT_STR(logBuffer, "P00 INFO: info message\n", " check log");
// Reopen invalid log file
logFileSet("/" BOGUS_STR);
// Check stdout
Storage *storage = storageNew(strNew(testPath()), 0750, 65536, NULL);
@ -82,15 +130,28 @@ testRun()
TEST_RESULT_STR(
strPtr(strNewBuf(storageGet(storage, stdoutFile, false))),
"P00 WARN: format 99\n"
"P00 ERROR: [025]: message\n"
"P00 ERROR: [025]: message1\n"
"P00 ERROR: [026]: message\n"
"P00 ERROR: [026]: message1\n"
" message2\n",
"checkout stdout output");
// Check stderr
TEST_RESULT_STR(
strPtr(strNewBuf(storageGet(storage, stderrFile, false))),
"ERROR: [025]: test.c:test_func():33: message\n",
"DEBUG: test.c:test_func(): message\n"
"INFO: info message\n"
"WARN: unable to open log file '/BOGUS': Permission denied\n"
"NOTE: process will continue without log file.\n",
"checkout stderr output");
// Check file
TEST_RESULT_STR(
strPtr(strNewBuf(storageGet(storage, fileFile, false))),
"-------------------PROCESS START-------------------\n"
"P00 DEBUG: test.c:test_func(): message\n"
"\n"
"-------------------PROCESS START-------------------\n"
"P00 INFO: info message\n",
"checkout file output");
}
}

8
test/src/module/config/configTest.c
View File

@ -79,6 +79,14 @@ testRun()
TEST_RESULT_VOID(cfgCommandSet(cfgCmdBackup), "command set to backup");
TEST_RESULT_INT(cfgCommand(), cfgCmdBackup, "command is backup");
// -------------------------------------------------------------------------------------------------------------------------
TEST_RESULT_VOID(cfgCommandSet(cfgCmdBackup), "command set to backup");
TEST_RESULT_INT(cfgLogLevelDefault(), logLevelInfo, "default log level is info");
TEST_RESULT_BOOL(cfgLogFile(), true, "log file is on");
TEST_RESULT_VOID(cfgCommandSet(cfgCmdInfo), "command set to archive-push");
TEST_RESULT_INT(cfgLogLevelDefault(), logLevelDebug, "default log level is debug");
TEST_RESULT_BOOL(cfgLogFile(), false, "log file is off");
// -------------------------------------------------------------------------------------------------------------------------
TEST_RESULT_BOOL(cfgCommandHelp(), false, "command help defaults to false");
TEST_RESULT_VOID(cfgCommandHelpSet(true), "set command help");

6
test/src/module/config/loadTest.c
View File

@ -93,5 +93,11 @@ testRun()
TEST_RESULT_STR(
strPtr(varStr(cfgOptionDefault(cfgOptPgHostCmd + 2))), strPtr(cfgExe()),
" command backup, option pg3-host-cmd default");
testLogErrResult(
"WARN: unable to open log file '/var/log/pgbackrest/db-backup.log': No such file or directory\n"
"NOTE: process will continue without log file.\n"
"WARN: unable to open log file '/var/log/pgbackrest/db-backup.log': No such file or directory\n"
"NOTE: process will continue without log file.");
}
}

10
test/src/test.c
View File

@ -48,11 +48,6 @@ main(void)
// Set globals
testPathSet("{[C_TEST_PATH]}");
#ifndef NO_LOG
// Initialize logging
testLogInit();
#endif
// Initialize tests
// run, selected
{[C_TEST_LIST]}
@ -64,11 +59,6 @@ main(void)
// Run the tests
testRun();
#ifndef NO_LOG
// Make sure there is nothing untested left in the log
testLogFinal();
#endif
// End test run and make sure all tests completed
testComplete();