Merge #6399: backport: merge bitcoin#23235, #23104, #24770, #24830, #24464, #24757, #25202, #25217, #25292, #25614, partial bitcoin#22766 (logging backports)

1621696a6f log: restore `LogPrintLevel` messages from prior backports (Kittywhiskers Van Gogh)
52a1263989 merge bitcoin#25614: Severity-based logging, step 2 (Kittywhiskers Van Gogh)
21470fdeb3 merge bitcoin#25292: Add LogPrintLevel to lint-format-strings, drop LogPrint-vs-LogPrintf section in dev notes (Kittywhiskers Van Gogh)
026409e4ff merge bitcoin#25217: update lint-logs.py to detect LogPrintLevel, mention WalletLogPrintf (Kittywhiskers Van Gogh)
b046e091c9 merge bitcoin#25202: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order (Kittywhiskers Van Gogh)
7697b73257 revert dash#2794: Disable logging of libevent debug messages (Kittywhiskers Van Gogh)
ff6304f5f3 merge bitcoin#24757: add `DEBUG_LOCKCONTENTION` to `--enable-debug` and CI (Kittywhiskers Van Gogh)
88592f30a3 merge bitcoin#24464: Add severity level to logs (Kittywhiskers Van Gogh)
d3e837ad22 merge bitcoin#24830: Allow -proxy="" setting values (Kittywhiskers Van Gogh)
0e01d5b5f3 partial bitcoin#22766: Clarify and disable unused ArgsManager flags (Kittywhiskers Van Gogh)
a9cfbd1048 fix: don't use non-existent `PrintLockContention` in `SharedEnter` (Kittywhiskers Van Gogh)
f331cbe8c8 merge bitcoin#24770: Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive (Kittywhiskers Van Gogh)
d9cc2ea178 merge bitcoin#23104: Avoid breaking single log lines over multiple lines in the log file (Kittywhiskers Van Gogh)
479ae82ecc merge bitcoin#23235: Reduce unnecessary default logging (Kittywhiskers Van Gogh)

Pull request description:

  ## Additional Information

  * This pull request's primary purpose is to restore `LogPrintLevel`s from backports in [dash#6333](https://github.com/dashpay/dash/pull/6333) that were changed to `LogPrint`s as they were backported before `LogPrintLevel` was backported.
  * ~~`clang-format` suggestions for `LogPrintLevel` have to be ignored in order to prevent the linter from tripping due to a "missing newline" ([build](https://gitlab.com/dashpay/dash/-/jobs/8398818860#L54)).~~ Resolved by applying diff ([source](https://github.com/dashpay/dash/pull/6399#issuecomment-2488992710)).
  * `SharedLock` was introduced in [dash#5961](https://github.com/dashpay/dash/pull/5961) and `PrintLockContention` was removed in [dash#6046](https://github.com/dashpay/dash/pull/6046) but the changes in the latter were not extended to the former. This has been corrected as part of this pull request.

  ## Breaking Changes

  None expected.

  ## Checklist

  - [x] I have performed a self-review of my own code
  - [x] I have commented my code, particularly in hard-to-understand areas **(note: N/A)**
  - [x] I have added or updated relevant unit/integration/functional/e2e tests
  - [x] I have made corresponding changes to the documentation
  - [x] I have assigned this pull request to a milestone _(for repository code-owners and collaborators only)_

Top commit has no ACKs.

Tree-SHA512: f2d0ef8ce5cb1091c714a2169e89deb33fa71ff174ce4e6147b3ad421f57a84183d2a9e76736c0b064b2cc70fb3f2e545c42b8562cf36fdce18c3fb61307c364
This commit is contained in:
pasta 2024-11-26 10:27:00 -06:00
commit 1155ff2ccf
No known key found for this signature in database
GPG Key ID: E2F3D7916E722D38
44 changed files with 782 additions and 204 deletions

View File

@ -13,5 +13,5 @@ export TEST_RUNNER_EXTRA="--extended --exclude feature_pruning,feature_dbcrash,w
export TEST_RUNNER_EXTRA="${TEST_RUNNER_EXTRA} --timeout-factor=4" # Increase timeout because sanitizers slow down
export GOAL="install"
export BITCOIN_CONFIG="--enable-zmq --with-gui=no --with-sanitizers=thread CC=clang-16 CXX=clang++-16 CXXFLAGS='-g' --with-boost-process"
export CPPFLAGS="-DDEBUG_LOCKORDER -DARENA_DEBUG"
export CPPFLAGS="-DARENA_DEBUG -DDEBUG_LOCKORDER -DDEBUG_LOCKCONTENTION"
export PYZMQ=true

View File

@ -389,6 +389,7 @@ if test "x$enable_debug" = xyes; then
AX_CHECK_PREPROC_FLAG([-DDEBUG_CORE],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_CORE"]],,[[$CXXFLAG_WERROR]])
AX_CHECK_PREPROC_FLAG([-DDEBUG_LOCKORDER],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_LOCKORDER"]],,[[$CXXFLAG_WERROR]])
AX_CHECK_PREPROC_FLAG([-DDEBUG_LOCKCONTENTION], [DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_LOCKCONTENTION"], [], [$CXXFLAG_WERROR])
AX_CHECK_PREPROC_FLAG([-DABORT_ON_FAILED_ASSUME],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DABORT_ON_FAILED_ASSUME"]],,[[$CXXFLAG_WERROR]])
AX_CHECK_COMPILE_FLAG([-ftrapv],[DEBUG_CXXFLAGS="$DEBUG_CXXFLAGS -ftrapv"],,[[$CXXFLAG_WERROR]])
else

View File

@ -17,6 +17,7 @@ Developer Notes
- [`debug.log`](#debuglog)
- [Testnet and Regtest modes](#testnet-and-regtest-modes)
- [DEBUG_LOCKORDER](#debug_lockorder)
- [DEBUG_LOCKCONTENTION](#debug_lockcontention)
- [Valgrind suppressions file](#valgrind-suppressions-file)
- [Compiling for test coverage](#compiling-for-test-coverage)
- [Performance profiling with perf](#performance-profiling-with-perf)
@ -389,8 +390,10 @@ Run configure with the `--enable-gprof` option, then make.
If the code is behaving strangely, take a look in the `debug.log` file in the data directory;
error and debugging messages are written there.
The `-debug=...` command-line option controls debugging; running with just `-debug` or `-debug=1` will turn
on all categories (and give you a very large `debug.log` file).
Debug logging can be enabled on startup with the `-debug` and `-loglevel`
configuration options and toggled while dashd is running with the `logging`
RPC. For instance, launching dashd with `-debug` or `-debug=1` will turn on
all log categories and `-loglevel=trace` will turn on all log severity levels.
The Qt code routes `qDebug()` output to `debug.log` under category "qt": run with `-debug=qt`
to see it.
@ -412,6 +415,21 @@ configure option adds `-DDEBUG_LOCKORDER` to the compiler flags. This inserts
run-time checks to keep track of which locks are held and adds warnings to the
`debug.log` file if inconsistencies are detected.
### DEBUG_LOCKCONTENTION
Defining `DEBUG_LOCKCONTENTION` adds a "lock" logging category to the logging
RPC that, when enabled, logs the location and duration of each lock contention
to the `debug.log` file.
The `--enable-debug` configure option adds `-DDEBUG_LOCKCONTENTION` to the
compiler flags. You may also enable it manually for a non-debug build by running
configure with `-DDEBUG_LOCKCONTENTION` added to your CPPFLAGS,
i.e. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run dashd.
You can then use the `-debug=lock` configuration option at dashd startup or
`dash-cli logging '["lock"]'` at runtime to turn on lock contention logging.
It can be toggled off again with `dash-cli logging [] '["lock"]'`.
### Assertions and Checks
The util file `src/util/check.h` offers helpers to protect against coding and
@ -846,11 +864,6 @@ int GetInt(Tabs tab)
Strings and formatting
------------------------
- Be careful of `LogPrint` versus `LogPrintf`. `LogPrint` takes a `category` argument, `LogPrintf` does not.
- *Rationale*: Confusion of these can result in runtime exceptions due to
formatting mismatch, and it is easy to get wrong because of subtly similar naming.
- Use `std::string`, avoid C string manipulation functions.
- *Rationale*: C++ string handling is marginally safer, less scope for

View File

@ -4,11 +4,14 @@
#include <batchedlogger.h>
CBatchedLogger::CBatchedLogger(BCLog::LogFlags _category, const std::string& logging_function, const std::string& source_file, int source_line) :
accept(LogAcceptCategory(_category)),
m_logging_function(logging_function),
m_source_file(source_file),
m_source_line(source_line)
CBatchedLogger::CBatchedLogger(BCLog::LogFlags category, BCLog::Level level, const std::string& logging_function,
const std::string& source_file, int source_line) :
m_accept{LogAcceptCategory(category, level)},
m_category{category},
m_level{level},
m_logging_function{logging_function},
m_source_file{source_file},
m_source_line{source_line}
{
}
@ -19,9 +22,9 @@ CBatchedLogger::~CBatchedLogger()
void CBatchedLogger::Flush()
{
if (!accept || msg.empty()) {
if (!m_accept || m_msg.empty()) {
return;
}
LogInstance().LogPrintStr(msg, m_logging_function, m_source_file, m_source_line);
msg.clear();
LogInstance().LogPrintStr(m_msg, m_logging_function, m_source_file, m_source_line, m_category, m_level);
m_msg.clear();
}

View File

@ -10,22 +10,26 @@
class CBatchedLogger
{
private:
bool accept;
std::string m_logging_function;;
bool m_accept;
BCLog::LogFlags m_category;
BCLog::Level m_level;
std::string m_logging_function;
std::string m_source_file;
const int m_source_line;
std::string msg;
std::string m_msg;
public:
CBatchedLogger(BCLog::LogFlags _category, const std::string& logging_function, const std::string& m_source_file, int m_source_line);
CBatchedLogger(BCLog::LogFlags category, BCLog::Level level, const std::string& logging_function,
const std::string& m_source_file, int m_source_line);
virtual ~CBatchedLogger();
template<typename... Args>
void Batch(const std::string& fmt, const Args&... args)
{
if (!accept) {
if (!m_accept) {
return;
}
msg += " " + strprintf(fmt, args...) + "\n";
m_msg += " " + strprintf(fmt, args...) + "\n";
}
void Flush();

View File

@ -20,7 +20,7 @@ public:
// This code is adapted from posix_logger.h, which is why it is using vsprintf.
// Please do not do this in normal code
void Logv(const char * format, va_list ap) override {
if (!LogAcceptCategory(BCLog::LEVELDB)) {
if (!LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug)) {
return;
}
char buffer[500];
@ -64,7 +64,7 @@ public:
assert(p <= limit);
base[std::min(bufsize - 1, (int)(p - base))] = '\0';
LogPrintf("leveldb: %s", base); /* Continued */
LogPrintLevel(BCLog::LEVELDB, BCLog::Level::Debug, "%s", base); /* Continued */
if (base != buffer) {
delete[] base;
}
@ -187,7 +187,7 @@ CDBWrapper::~CDBWrapper()
bool CDBWrapper::WriteBatch(CDBBatch& batch, bool fSync)
{
const bool log_memory = LogAcceptCategory(BCLog::LEVELDB);
const bool log_memory = LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug);
double mem_before = 0;
if (log_memory) {
mem_before = DynamicMemoryUsage() / 1024.0 / 1024;

View File

@ -10,6 +10,7 @@
#include <serialize.h>
#include <sync.h>
#include <threadsafety.h>
#include <tinyformat.h>
#include <unordered_lru_cache.h>
#include <util/ranges_set.h>

View File

@ -375,11 +375,22 @@ static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
/** libevent event log callback */
static void libevent_log_cb(int severity, const char *msg)
{
if (severity >= EVENT_LOG_WARN) // Log warn messages and higher without debug category
LogPrintf("libevent: %s\n", msg);
// The below code causes log spam on Travis and the output of these logs has never been of any use so far
//else
// LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg);
BCLog::Level level;
switch (severity) {
case EVENT_LOG_DEBUG:
level = BCLog::Level::Debug;
break;
case EVENT_LOG_MSG:
level = BCLog::Level::Info;
break;
case EVENT_LOG_WARN:
level = BCLog::Level::Warning;
break;
default: // EVENT_LOG_ERR and others are mapped to error
level = BCLog::Level::Error;
break;
}
LogPrintLevel(BCLog::LIBEVENT, level, "%s\n", msg);
}
bool InitHTTPServer()

View File

@ -583,7 +583,7 @@ void SetupServerArgs(ArgsManager& argsman)
argsman.AddArg("-peertimeout=<n>", strprintf("Specify a p2p connection timeout delay in seconds. After connecting to a peer, wait this amount of time before considering disconnection based on inactivity (minimum: 1, default: %d)", DEFAULT_PEER_CONNECT_TIMEOUT), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
argsman.AddArg("-permitbaremultisig", strprintf("Relay non-P2SH multisig (default: %u)", DEFAULT_PERMIT_BAREMULTISIG), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
argsman.AddArg("-port=<port>", strprintf("Listen for connections on <port>. Nodes not using the default ports (default: %u, testnet: %u, regtest: %u) are unlikely to get incoming connections. Not relevant for I2P (see doc/i2p.md).", defaultChainParams->GetDefaultPort(), testnetChainParams->GetDefaultPort(), regtestChainParams->GetDefaultPort()), ArgsManager::ALLOW_ANY | ArgsManager::NETWORK_ONLY, OptionsCategory::CONNECTION);
argsman.AddArg("-proxy=<ip:port>", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
argsman.AddArg("-proxy=<ip:port>", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY | ArgsManager::DISALLOW_ELISION, OptionsCategory::CONNECTION);
argsman.AddArg("-proxyrandomize", strprintf("Randomize credentials for every proxy connection. This enables Tor stream isolation (default: %u)", DEFAULT_PROXYRANDOMIZE), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
argsman.AddArg("-seednode=<ip>", "Connect to a node to retrieve peer addresses, and disconnect. This option can be specified multiple times to connect to multiple nodes.", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
argsman.AddArg("-socketevents=<mode>", "Socket events mode, which must be one of 'select', 'poll', 'epoll' or 'kqueue', depending on your system (default: Linux - 'epoll', FreeBSD/Apple - 'kqueue', Windows - 'select')", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
@ -1212,6 +1212,7 @@ bool AppInitParameterInteraction(const ArgsManager& args)
// ********************************************************* Step 3: parameter-to-internal-flags
init::SetLoggingCategories(args);
init::SetLoggingLevel(args);
fCheckBlockIndex = args.GetBoolArg("-checkblockindex", chainparams.DefaultConsistencyChecks());
fCheckpointsEnabled = args.GetBoolArg("-checkpoints", DEFAULT_CHECKPOINTS_ENABLED);
@ -1337,10 +1338,6 @@ bool AppInitParameterInteraction(const ArgsManager& args)
nMaxTipAge = args.GetArg("-maxtipage", DEFAULT_MAX_TIP_AGE);
if (args.IsArgSet("-proxy") && args.GetArg("-proxy", "").empty()) {
return InitError(_("No proxy server specified. Use -proxy=<ip> or -proxy=<ip:port>."));
}
if (args.GetBoolArg("-reindex-chainstate", false)) {
// indexes that must be deactivated to prevent index corruption, see #24630
if (args.GetBoolArg("-coinstatsindex", DEFAULT_COINSTATSINDEX)) {

View File

@ -13,6 +13,7 @@
#include <logging.h>
#include <node/ui_interface.h>
#include <random.h>
#include <util/string.h>
#include <util/system.h>
#include <util/time.h>
#include <util/translation.h>
@ -57,11 +58,12 @@ bool SanityChecks()
void AddLoggingArgs(ArgsManager& argsman)
{
argsman.AddArg("-debuglogfile=<file>", strprintf("Specify location of debug log file. Relative paths will be prefixed by a net-specific datadir location. (-nodebuglogfile to disable; default: %s)", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
argsman.AddArg("-debug=<category>", "Output debugging information (default: -nodebug, supplying <category> is optional). "
"If <category> is not supplied or if <category> = 1, output all debugging information. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
argsman.AddArg("-debug=<category>", "Output debug and trace logging (default: -nodebug, supplying <category> is optional). "
"If <category> is not supplied or if <category> = 1, output all debug and trace logging. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-debugexclude=<category>", "Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-debugexclude=<category>", "Exclude debug and trace logging for a category. Can be used in conjunction with -debug=1 to output debug and trace logging for all categories except the specified category. This option can be specified multiple times to exclude multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: %s (default=%s); warning and error levels are always logged. If <category>:<level> is supplied, the setting will override the global one and may be specified multiple times to set multiple category-specific levels. <category> can be: %s.", LogInstance().LogLevelsString(), LogInstance().LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
#ifdef HAVE_THREAD_LOCAL
argsman.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (only available on platforms supporting thread_local) (default: %u)", DEFAULT_LOGTHREADNAMES), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
@ -89,6 +91,26 @@ void SetLoggingOptions(const ArgsManager& args)
fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
}
void SetLoggingLevel(const ArgsManager& args)
{
if (args.IsArgSet("-loglevel")) {
for (const std::string& level_str : args.GetArgs("-loglevel")) {
if (level_str.find_first_of(':', 3) == std::string::npos) {
// user passed a global log level, i.e. -loglevel=<level>
if (!LogInstance().SetLogLevel(level_str)) {
InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s."), level_str, LogInstance().LogLevelsString()));
}
} else {
// user passed a category-specific log level, i.e. -loglevel=<category>:<level>
const auto& toks = SplitString(level_str, ':');
if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid categories: %s. Valid loglevels: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()));
}
}
}
}
}
void SetLoggingCategories(const ArgsManager& args)
{
if (args.IsArgSet("-debug")) {

View File

@ -21,6 +21,7 @@ bool SanityChecks();
void AddLoggingArgs(ArgsManager& args);
void SetLoggingOptions(const ArgsManager& args);
void SetLoggingCategories(const ArgsManager& args);
void SetLoggingLevel(const ArgsManager& args);
bool StartLogging(const ArgsManager& args);
void LogPackageVersion();
} // namespace init

View File

@ -82,7 +82,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
return false;
}
auto members = utils::GetAllQuorumMembers(llmqType, dmnman, pQuorumBaseBlockIndex);
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
std::stringstream ss2;
for (const auto i: irange::range(llmq_params.size)) {
@ -106,7 +106,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
// sigs are only checked when the block is processed
if (checkSigs) {
uint256 commitmentHash = BuildCommitmentHash(llmq_params.type, quorumHash, validMembers, quorumPublicKey, quorumVvecHash);
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss3;
for (const auto &mn: members) {
ss3 << mn->proTxHash.ToString().substr(0, 4) << " | ";
@ -181,7 +181,7 @@ bool CheckLLMQCommitment(CDeterministicMNManager& dmnman, const ChainstateManage
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-commitment-type");
}
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
for (const auto i: irange::range(llmq_params_opt->size)) {
ss << "v[" << i << "]=" << qcTx.commitment.validMembers[i];

View File

@ -33,7 +33,7 @@ namespace llmq
{
CDKGLogger::CDKGLogger(const CDKGSession& _quorumDkg, std::string_view _func, int source_line) :
CBatchedLogger(BCLog::LLMQ_DKG,
CBatchedLogger(BCLog::LLMQ_DKG, BCLog::Level::Debug,
strprintf("QuorumDKG(type=%s, qIndex=%d, h=%d, member=%d)", _quorumDkg.params.name, _quorumDkg.quorumIndex,
_quorumDkg.m_quorum_base_block_index->nHeight, _quorumDkg.AreWeMember()),
__FILE__, source_line)
@ -120,7 +120,7 @@ bool CDKGSession::Init(const uint256& _myProTxHash, int _quorumIndex)
CDKGLogger logger(*this, __func__, __LINE__);
if (LogAcceptCategory(BCLog::LLMQ) && IsQuorumRotationEnabled(params, m_quorum_base_block_index)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug) && IsQuorumRotationEnabled(params, m_quorum_base_block_index)) {
int cycleQuorumBaseHeight = m_quorum_base_block_index->nHeight - quorumIndex;
const CBlockIndex* pCycleQuorumBaseBlockIndex = m_quorum_base_block_index->GetAncestor(cycleQuorumBaseHeight);
std::stringstream ss;
@ -138,7 +138,7 @@ bool CDKGSession::Init(const uint256& _myProTxHash, int _quorumIndex)
if (!myProTxHash.IsNull()) {
dkgDebugManager.InitLocalSessionStatus(params, quorumIndex, m_quorum_base_block_index->GetBlockHash(), m_quorum_base_block_index->nHeight);
relayMembers = utils::GetQuorumRelayMembers(params, m_dmnman, m_quorum_base_block_index, myProTxHash, true);
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
for (const auto& r : relayMembers) {
ss << r.ToString().substr(0, 4) << " | ";

View File

@ -639,7 +639,7 @@ void CInstantSendManager::HandleNewInputLockRecoveredSig(const CRecoveredSig& re
return;
}
if (LogAcceptCategory(BCLog::INSTANTSEND)) {
if (LogAcceptCategory(BCLog::INSTANTSEND, BCLog::Level::Debug)) {
for (const auto& in : tx->vin) {
auto id = ::SerializeHash(std::make_pair(INPUTLOCK_REQUESTID_PREFIX, in.prevout));
if (id == recoveredSig.getId()) {
@ -1509,7 +1509,7 @@ void CInstantSendManager::ProcessPendingRetryLockTxs()
// CheckCanLock is already called by ProcessTx, so we should avoid calling it twice. But we also shouldn't spam
// the logs when retrying TXs that are not ready yet.
if (LogAcceptCategory(BCLog::INSTANTSEND)) {
if (LogAcceptCategory(BCLog::INSTANTSEND, BCLog::Level::Debug)) {
if (!CheckCanLock(*tx, false, Params().GetConsensus())) {
continue;
}

View File

@ -15,6 +15,7 @@
#include <saltedhasher.h>
#include <threadinterrupt.h>
#include <unordered_lru_cache.h>
#include <util/time.h>
#include <atomic>
#include <map>

View File

@ -1334,7 +1334,7 @@ void CSigSharesManager::Cleanup()
const auto& oneSigShare = m->begin()->second;
std::string strMissingMembers;
if (LogAcceptCategory(BCLog::LLMQ_SIGS)) {
if (LogAcceptCategory(BCLog::LLMQ_SIGS, BCLog::Level::Debug)) {
if (const auto quorumIt = quorums.find(std::make_pair(oneSigShare.getLlmqType(), oneSigShare.getQuorumHash())); quorumIt != quorums.end()) {
const auto& quorum = quorumIt->second;
for (const auto i : irange::range(quorum->members.size())) {
@ -1346,11 +1346,15 @@ void CSigSharesManager::Cleanup()
}
}
LogPrint(BCLog::LLMQ_SIGS, "CSigSharesManager::%s -- signing session timed out. signHash=%s, id=%s, msgHash=%s, sigShareCount=%d, missingMembers=%s\n", __func__,
signHash.ToString(), oneSigShare.getId().ToString(), oneSigShare.getMsgHash().ToString(), count, strMissingMembers);
LogPrintLevel(BCLog::LLMQ_SIGS, BCLog::Level::Info, /* Continued */
"CSigSharesManager::%s -- signing session timed out. signHash=%s, id=%s, msgHash=%s, "
"sigShareCount=%d, missingMembers=%s\n",
__func__, signHash.ToString(), oneSigShare.getId().ToString(),
oneSigShare.getMsgHash().ToString(), count, strMissingMembers);
} else {
LogPrint(BCLog::LLMQ_SIGS, "CSigSharesManager::%s -- signing session timed out. signHash=%s, sigShareCount=%d\n", __func__,
signHash.ToString(), count);
LogPrintLevel(BCLog::LLMQ_SIGS, BCLog::Level::Info, /* Continued */
"CSigSharesManager::%s -- signing session timed out. signHash=%s, sigShareCount=%d\n",
__func__, signHash.ToString(), count);
}
RemoveSigSharesForSession(signHash);
}

View File

@ -216,7 +216,7 @@ std::vector<std::vector<CDeterministicMNCPtr>> ComputeQuorumMembersByQuarterRota
//TODO Check if it is triggered from outside (P2P, block validation). Throwing an exception is probably a wiser choice
//assert (!newQuarterMembers.empty());
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
for (const size_t i : irange::range(nQuorums)) {
std::stringstream ss;
@ -249,7 +249,7 @@ std::vector<std::vector<CDeterministicMNCPtr>> ComputeQuorumMembersByQuarterRota
std::move(previousQuarters.quarterHMinusC[i].begin(), previousQuarters.quarterHMinusC[i].end(), std::back_inserter(quorumMembers[i]));
std::move(newQuarterMembers[i].begin(), newQuarterMembers[i].end(), std::back_inserter(quorumMembers[i]));
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
ss << " [";
for (const auto &m: quorumMembers[i]) {
@ -397,7 +397,7 @@ std::vector<std::vector<CDeterministicMNCPtr>> BuildNewQuorumQuarterMembers(cons
sortedCombinedMnsList.push_back(std::move(m));
}
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
ss << " [";
for (const auto &m: sortedCombinedMnsList) {
@ -517,7 +517,7 @@ std::vector<std::vector<CDeterministicMNCPtr>> GetQuorumQuarterMembersBySnapshot
std::move(sortedMnsUsedAtH.begin(), sortedMnsUsedAtH.end(), std::back_inserter(sortedCombinedMns));
}
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::stringstream ss;
ss << " [";
for (const auto &m: sortedCombinedMns) {
@ -788,7 +788,8 @@ bool EnsureQuorumConnections(const Consensus::LLMQParams& llmqParams, CConnman&
relayMembers = connections;
}
if (!connections.empty()) {
if (!connman.HasMasternodeQuorumNodes(llmqParams.type, pQuorumBaseBlockIndex->GetBlockHash()) && LogAcceptCategory(BCLog::LLMQ)) {
if (!connman.HasMasternodeQuorumNodes(llmqParams.type, pQuorumBaseBlockIndex->GetBlockHash()) &&
LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::string debugMsg = strprintf("%s -- adding masternodes quorum connections for quorum %s:\n", __func__, pQuorumBaseBlockIndex->GetBlockHash().ToString());
for (const auto& c : connections) {
auto dmn = tip_mn_list.GetValidMN(c);
@ -835,7 +836,7 @@ void AddQuorumProbeConnections(const Consensus::LLMQParams& llmqParams, CConnman
}
if (!probeConnections.empty()) {
if (LogAcceptCategory(BCLog::LLMQ)) {
if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
std::string debugMsg = strprintf("%s -- adding masternodes probes for quorum %s:\n", __func__, pQuorumBaseBlockIndex->GetBlockHash().ToString());
for (const auto& c : probeConnections) {
auto dmn = tip_mn_list.GetValidMN(c);

View File

@ -5,15 +5,17 @@
#include <fs.h>
#include <logging.h>
#include <util/string.h>
#include <util/system.h>
#include <util/threadnames.h>
#include <util/string.h>
#include <util/time.h>
#include <algorithm>
#include <array>
#include <optional>
const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
BCLog::Logger& LogInstance()
{
@ -122,6 +124,19 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
return (m_categories.load(std::memory_order_relaxed) & category) != 0;
}
bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
{
// Log messages at Warning and Error level unconditionally, so that
// important troubleshooting information doesn't get lost.
if (level >= BCLog::Level::Warning) return true;
if (!WillLogCategory(category)) return false;
StdLockGuard scoped_lock(m_cs);
const auto it{m_category_log_levels.find(category)};
return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
}
bool BCLog::Logger::DefaultShrinkDebugFile() const
{
return m_categories == BCLog::NONE;
@ -135,7 +150,7 @@ struct CLogCategoryDesc {
const CLogCategoryDesc LogCategories[] =
{
{BCLog::NONE, "0"},
{BCLog::NONE, "none"},
{BCLog::NONE, ""},
{BCLog::NET, "net"},
{BCLog::TOR, "tor"},
{BCLog::MEMPOOL, "mempool"},
@ -160,7 +175,10 @@ const CLogCategoryDesc LogCategories[] =
{BCLog::VALIDATION, "validation"},
{BCLog::I2P, "i2p"},
{BCLog::IPC, "ipc"},
#ifdef DEBUG_LOCKCONTENTION
{BCLog::LOCK, "lock"},
#endif
{BCLog::BLOCKSTORE, "blockstorage"},
{BCLog::TXRECONCILIATION, "txreconciliation"},
{BCLog::ALL, "1"},
{BCLog::ALL, "all"},
@ -185,7 +203,7 @@ const CLogCategoryDesc LogCategories[] =
bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
{
if (str == "") {
if (str.empty()) {
flag = BCLog::ALL;
return true;
}
@ -198,6 +216,144 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
return false;
}
std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const
{
switch (level) {
case BCLog::Level::Trace:
return "trace";
case BCLog::Level::Debug:
return "debug";
case BCLog::Level::Info:
return "info";
case BCLog::Level::Warning:
return "warning";
case BCLog::Level::Error:
return "error";
case BCLog::Level::None:
return "";
}
assert(false);
}
std::string LogCategoryToStr(BCLog::LogFlags category)
{
// Each log category string representation should sync with LogCategories
switch (category) {
case BCLog::LogFlags::NONE:
return "";
case BCLog::LogFlags::NET:
return "net";
case BCLog::LogFlags::TOR:
return "tor";
case BCLog::LogFlags::MEMPOOL:
return "mempool";
case BCLog::LogFlags::HTTP:
return "http";
case BCLog::LogFlags::BENCHMARK:
return "bench";
case BCLog::LogFlags::ZMQ:
return "zmq";
case BCLog::LogFlags::WALLETDB:
return "walletdb";
case BCLog::LogFlags::RPC:
return "rpc";
case BCLog::LogFlags::ESTIMATEFEE:
return "estimatefee";
case BCLog::LogFlags::ADDRMAN:
return "addrman";
case BCLog::LogFlags::SELECTCOINS:
return "selectcoins";
case BCLog::LogFlags::REINDEX:
return "reindex";
case BCLog::LogFlags::CMPCTBLOCK:
return "cmpctblock";
case BCLog::LogFlags::RANDOM:
return "rand";
case BCLog::LogFlags::PRUNE:
return "prune";
case BCLog::LogFlags::PROXY:
return "proxy";
case BCLog::LogFlags::MEMPOOLREJ:
return "mempoolrej";
case BCLog::LogFlags::LIBEVENT:
return "libevent";
case BCLog::LogFlags::COINDB:
return "coindb";
case BCLog::LogFlags::QT:
return "qt";
case BCLog::LogFlags::LEVELDB:
return "leveldb";
case BCLog::LogFlags::VALIDATION:
return "validation";
case BCLog::LogFlags::I2P:
return "i2p";
case BCLog::LogFlags::IPC:
return "ipc";
#ifdef DEBUG_LOCKCONTENTION
case BCLog::LogFlags::LOCK:
return "lock";
#endif
case BCLog::LogFlags::BLOCKSTORE:
return "blockstorage";
case BCLog::LogFlags::TXRECONCILIATION:
return "txreconciliation";
/* Start Dash */
case BCLog::LogFlags::CHAINLOCKS:
return "chainlocks";
case BCLog::LogFlags::GOBJECT:
return "gobject";
case BCLog::LogFlags::INSTANTSEND:
return "instantsend";
case BCLog::LogFlags::LLMQ:
return "llmq";
case BCLog::LogFlags::LLMQ_DKG:
return "llmq-dkg";
case BCLog::LogFlags::LLMQ_SIGS:
return "llmq-sigs";
case BCLog::LogFlags::MNPAYMENTS:
return "mnpayments";
case BCLog::LogFlags::MNSYNC:
return "mnsync";
case BCLog::LogFlags::COINJOIN:
return "coinjoin";
case BCLog::LogFlags::SPORK:
return "spork";
case BCLog::LogFlags::NETCONN:
return "netconn";
case BCLog::LogFlags::CREDITPOOL:
return "creditpool";
case BCLog::LogFlags::EHF:
return "ehf";
case BCLog::LogFlags::DASH:
return "dash";
case BCLog::LogFlags::NET_NETCONN:
return "net|netconn";
/* End Dash */
case BCLog::LogFlags::ALL:
return "all";
}
assert(false);
}
static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
{
if (level_str == "trace") {
return BCLog::Level::Trace;
} else if (level_str == "debug") {
return BCLog::Level::Debug;
} else if (level_str == "info") {
return BCLog::Level::Info;
} else if (level_str == "warning") {
return BCLog::Level::Warning;
} else if (level_str == "error") {
return BCLog::Level::Error;
} else if (level_str == "none") {
return BCLog::Level::None;
} else {
return std::nullopt;
}
}
std::vector<LogCategory> BCLog::Logger::LogCategoriesList(bool enabled_only) const
{
// Sort log categories by alphabetical order.
@ -218,6 +374,18 @@ std::vector<LogCategory> BCLog::Logger::LogCategoriesList(bool enabled_only) con
return ret;
}
/** Log severity levels that can be selected by the user. */
static constexpr std::array<BCLog::Level, 3> LogLevelsList()
{
return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
}
std::string BCLog::Logger::LogLevelsString() const
{
const auto& levels = LogLevelsList();
return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });
}
std::string BCLog::Logger::LogTimestampStr(const std::string& str)
{
std::string strStamped;
@ -265,11 +433,31 @@ namespace BCLog {
}
} // namespace BCLog
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line)
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
{
StdLockGuard scoped_lock(m_cs);
std::string str_prefixed = LogEscapeMessage(str);
if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
std::string s{"["};
if (category != LogFlags::NONE) {
s += LogCategoryToStr(category);
}
if (category != LogFlags::NONE && level != Level::None) {
// Only add separator if both flag and level are not NONE
s += ":";
}
if (level != Level::None) {
s += LogLevelToStr(level);
}
s += "] ";
str_prefixed.insert(0, s);
}
if (m_log_sourcelocations && m_started_new_line) {
str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
}
@ -354,3 +542,24 @@ void BCLog::Logger::ShrinkDebugFile()
else if (file != nullptr)
fclose(file);
}
bool BCLog::Logger::SetLogLevel(const std::string& level_str)
{
const auto level = GetLogLevel(level_str);
if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
m_log_level = level.value();
return true;
}
bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
{
BCLog::LogFlags flag;
if (!GetLogCategory(flag, category_str)) return false;
const auto level = GetLogLevel(level_str);
if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
StdLockGuard scoped_lock(m_cs);
m_category_log_levels[flag] = level.value();
return true;
}

View File

@ -7,8 +7,8 @@
#define BITCOIN_LOGGING_H
#include <fs.h>
#include <tinyformat.h>
#include <threadsafety.h>
#include <tinyformat.h>
#include <util/string.h>
#include <atomic>
@ -17,6 +17,7 @@
#include <list>
#include <mutex>
#include <string>
#include <unordered_map>
#include <vector>
static const bool DEFAULT_LOGTIMEMICROS = false;
@ -61,7 +62,10 @@ namespace BCLog {
VALIDATION = (1 << 21),
I2P = (1 << 22),
IPC = (1 << 23),
#ifdef DEBUG_LOCKCONTENTION
LOCK = (1 << 24),
#endif
BLOCKSTORE = (1 << 26),
TXRECONCILIATION = (1 << 27),
//Start Dash
@ -88,6 +92,15 @@ namespace BCLog {
ALL = ~(uint64_t)0,
};
enum class Level {
Trace = 0, // High-volume or detailed logging for development/debugging
Debug, // Reasonably noisy logging, but still usable in production
Info, // Default
Warning,
Error,
None, // Internal use only
};
constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
class Logger
{
@ -105,6 +118,13 @@ namespace BCLog {
*/
std::atomic_bool m_started_new_line{true};
//! Category-specific log level. Overrides `m_log_level`.
std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
//! If there is no category-specific log level, all logs with a severity
//! level lower than `m_log_level` will be ignored.
std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL};
/** Log categories bitfield. */
std::atomic<uint64_t> m_categories{0};
@ -127,7 +147,7 @@ namespace BCLog {
std::atomic<bool> m_reopen_file{false};
/** Send a string to the log output */
void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line);
void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level);
/** Returns whether logs will be written to any output */
bool Enabled() const
@ -158,6 +178,22 @@ namespace BCLog {
void ShrinkDebugFile();
std::unordered_map<LogFlags, Level> CategoryLevels() const
{
StdLockGuard scoped_lock(m_cs);
return m_category_log_levels;
}
void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level>& levels)
{
StdLockGuard scoped_lock(m_cs);
m_category_log_levels = levels;
}
bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str);
Level LogLevel() const { return m_log_level.load(); }
void SetLogLevel(Level level) { m_log_level = level; }
bool SetLogLevel(const std::string& level);
uint64_t GetCategoryMask() const { return m_categories.load(); }
void EnableCategory(LogFlags flag);
@ -166,6 +202,8 @@ namespace BCLog {
bool DisableCategory(const std::string& str);
bool WillLogCategory(LogFlags category) const;
bool WillLogCategoryLevel(LogFlags category, Level level) const;
/** Returns a vector of the log categories in alphabetical order. */
std::vector<LogCategory> LogCategoriesList(bool enabled_only = false) const;
/** Returns a string with the log categories in alphabetical order. */
@ -174,6 +212,12 @@ namespace BCLog {
return Join(LogCategoriesList(enabled_only), ", ", [&](const LogCategory& i) { return i.category; });
};
//! Returns a string with all user-selectable log levels.
std::string LogLevelsString() const;
//! Returns the string representation of a log level.
std::string LogLevelToStr(BCLog::Level level) const;
bool DefaultShrinkDebugFile() const;
};
@ -181,10 +225,10 @@ namespace BCLog {
BCLog::Logger& LogInstance();
/** Return true if log accepts specified category */
static inline bool LogAcceptCategory(BCLog::LogFlags category)
/** Return true if log accepts specified category, at the specified level. */
static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level)
{
return LogInstance().WillLogCategory(category);
return LogInstance().WillLogCategoryLevel(category, level);
}
/** Return true if str parses as a log category and set the flag */
@ -208,7 +252,7 @@ std::string SafeStringFormat(const std::string& fmt, const Args&... args)
// peer can fill up a user's disk with debug.log entries.
template <typename... Args>
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const char* fmt, const Args&... args)
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, const char* fmt, const Args&... args)
{
if (LogInstance().Enabled()) {
std::string log_msg;
@ -218,19 +262,29 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
/* Original format string will have newline so don't add one here */
log_msg = "Error \"" + std::string(fmterr.what()) + "\" while formatting log message: " + fmt;
}
LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line);
LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level);
}
}
#define LogPrintf(...) LogPrintf_(__func__, __FILE__, __LINE__, __VA_ARGS__)
#define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::None, __VA_ARGS__)
// Use a macro instead of a function for conditional logging to prevent
// evaluating arguments when logging for the category is not enabled.
#define LogPrint(category, ...) \
do { \
if (LogAcceptCategory((category))) { \
LogPrintf(__VA_ARGS__); \
} \
#define LogPrint(category, ...) \
do { \
if (LogAcceptCategory((category), BCLog::Level::Debug)) { \
LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \
} \
} while (0)
#define LogPrintLevel(category, level, ...) \
do { \
if (LogAcceptCategory((category), (level))) { \
LogPrintLevel_(category, level, __VA_ARGS__); \
} \
} while (0)
#endif // BITCOIN_LOGGING_H

View File

@ -481,7 +481,7 @@ static CAddress GetBindAddress(const Sock& sock)
if (!sock.GetSockName((struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) {
addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind);
} else {
LogPrint(BCLog::NET, "Warning: getsockname failed\n");
LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n");
}
}
return addr_bind;
@ -509,14 +509,14 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo
/// debug print
if (fLogIPs) {
LogPrint(BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n",
use_v2transport ? "v2" : "v1",
pszDest ? pszDest : addrConnect.ToStringAddrPort(),
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "trying %s connection %s lastseen=%.1fhrs\n",
use_v2transport ? "v2" : "v1",
pszDest ? pszDest : addrConnect.ToStringAddrPort(),
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
} else {
LogPrint(BCLog::NET, "trying %s connection lastseen=%.1fhrs\n",
use_v2transport ? "v2" : "v1",
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "trying %s connection lastseen=%.1fhrs\n",
use_v2transport ? "v2" : "v1",
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
}
// Resolve
@ -1963,7 +1963,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket, CMasternodeSy
}
if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) {
LogPrintf("Warning: Unknown socket family\n");
LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "Unknown socket family\n");
} else {
addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE};
}
@ -4068,14 +4068,14 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len))
{
strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToStringAddrPort());
LogPrintf("%s\n", strError.original);
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original);
return false;
}
std::unique_ptr<Sock> sock = CreateSock(addrBind);
if (!sock) {
strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintf("%s\n", strError.original);
strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original);
return false;
}
@ -4110,7 +4110,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
strError = strprintf(_("Unable to bind to %s on this computer. %s is probably already running."), addrBind.ToStringAddrPort(), PACKAGE_NAME);
else
strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToStringAddrPort(), NetworkErrorString(nErr));
LogPrintf("%s\n", strError.original);
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original);
return false;
}
LogPrintf("Bound to %s\n", addrBind.ToStringAddrPort());
@ -4118,8 +4118,8 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
// Listen for incoming connections
if (sock->Listen(SOMAXCONN) == SOCKET_ERROR)
{
strError = strprintf(_("Error: Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintf("%s\n", strError.original);
strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original);
return false;
}

View File

@ -16,6 +16,7 @@
#include <hash.h>
#include <i2p.h>
#include <limitedmap.h>
#include <logging.h>
#include <net_permissions.h>
#include <netaddress.h>
#include <netbase.h>
@ -42,6 +43,7 @@
#include <cstdint>
#include <deque>
#include <functional>
#include <list>
#include <map>
#include <memory>
#include <optional>

View File

@ -3716,7 +3716,7 @@ void PeerManagerImpl::ProcessMessage(
// Log succesful connections unconditionally for outbound, but not for inbound as those
// can be triggered by an attacker at high rate.
if (!pfrom.IsInboundConn() || LogAcceptCategory(BCLog::NET)) {
if (!pfrom.IsInboundConn() || LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) {
LogPrintf("New %s %s peer connected: version: %d, blocks=%d, peer=%d%s\n",
pfrom.ConnectionTypeAsString(),
TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
@ -3817,19 +3817,19 @@ void PeerManagerImpl::ProcessMessage(
// from switching announcement protocols after the connection is up.
if (msg_type == NetMsgType::SENDTXRCNCL) {
if (!m_txreconciliation) {
LogPrint(BCLog::NET, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId());
return;
}
if (pfrom.fSuccessfullyConnected) {
LogPrint(BCLog::NET, "sendtxrcncl received after verack from peer=%d; disconnecting\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received after verack from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
// Peer must not offer us reconciliations if we specified no tx relay support in VERSION.
if (RejectIncomingTxs(pfrom)) {
LogPrint(BCLog::NET, "sendtxrcncl received from peer=%d to which we indicated no tx relay; disconnecting\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d to which we indicated no tx relay; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -3838,7 +3838,7 @@ void PeerManagerImpl::ProcessMessage(
// This flag might also be false in other cases, but the RejectIncomingTxs check above
// eliminates them, so that this flag fully represents what we are looking for.
if (!pfrom.m_relays_txs) {
LogPrint(BCLog::NET, "sendtxrcncl received from peer=%d which indicated no tx relay to us; disconnecting\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d which indicated no tx relay to us; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -3851,16 +3851,16 @@ void PeerManagerImpl::ProcessMessage(
peer_txreconcl_version, remote_salt);
switch (result) {
case ReconciliationRegisterResult::NOT_FOUND:
LogPrint(BCLog::NET, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId());
break;
case ReconciliationRegisterResult::SUCCESS:
break;
case ReconciliationRegisterResult::ALREADY_REGISTERED:
LogPrint(BCLog::NET, "txreconciliation protocol violation from peer=%d (sendtxrcncl received from already registered peer); disconnecting\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d (sendtxrcncl received from already registered peer); disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
case ReconciliationRegisterResult::PROTOCOL_VIOLATION:
LogPrint(BCLog::NET, "txreconciliation protocol violation from peer=%d; disconnecting\n", pfrom.GetId());
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}

View File

@ -585,7 +585,7 @@ void UnlinkPrunedFiles(const std::set<int>& setFilesToPrune)
FlatFilePos pos(*it, 0);
fs::remove(BlockFileSeq().FileName(pos));
fs::remove(UndoFileSeq().FileName(pos));
LogPrintf("Prune: %s deleted blk/rev (%05u)\n", __func__, *it);
LogPrint(BCLog::BLOCKSTORE, "Prune: %s deleted blk/rev (%05u)\n", __func__, *it);
}
}
@ -642,7 +642,7 @@ bool BlockManager::FindBlockPos(FlatFilePos& pos, unsigned int nAddSize, unsigne
if ((int)nFile != m_last_blockfile) {
if (!fKnown) {
LogPrint(BCLog::VALIDATION, "Leaving block file %i: %s\n", m_last_blockfile, m_blockfile_info[m_last_blockfile].ToString());
LogPrint(BCLog::BLOCKSTORE, "Leaving block file %i: %s\n", m_last_blockfile, m_blockfile_info[m_last_blockfile].ToString());
}
FlushBlockFile(!fKnown, finalize_undo);
m_last_blockfile = nFile;

View File

@ -83,7 +83,7 @@ public:
AssertLockNotHeld(m_txreconciliation_mutex);
LOCK(m_txreconciliation_mutex);
LogPrint(BCLog::TXRECONCILIATION, "Pre-register peer=%d\n", peer_id);
LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Pre-register peer=%d\n", peer_id);
const uint64_t local_salt{GetRand(UINT64_MAX)};
// We do this exactly once per peer (which are unique by NodeId, see GetNewNodeId) so it's
@ -116,7 +116,8 @@ public:
// v1 is the lowest version, so suggesting something below must be a protocol violation.
if (recon_version < 1) return ReconciliationRegisterResult::PROTOCOL_VIOLATION;
LogPrint(BCLog::TXRECONCILIATION, "Register peer=%d (inbound=%i)\n", peer_id, is_peer_inbound);
LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Register peer=%d (inbound=%i)\n",
peer_id, is_peer_inbound);
const uint256 full_salt{ComputeSalt(local_salt, remote_salt)};
recon_state->second = TxReconciliationState(!is_peer_inbound, full_salt.GetUint64(0), full_salt.GetUint64(1));
@ -128,7 +129,7 @@ public:
AssertLockNotHeld(m_txreconciliation_mutex);
LOCK(m_txreconciliation_mutex);
if (m_states.erase(peer_id)) {
LogPrint(BCLog::TXRECONCILIATION, "Forget txreconciliation state of peer=%d\n", peer_id);
LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Forget txreconciliation state of peer=%d\n", peer_id);
}
}

View File

@ -770,7 +770,7 @@ void CoinControlDialog::updateView()
// CoinJoin rounds
int nRounds = model->getRealOutpointCoinJoinRounds(output);
if (nRounds >= 0 || LogAcceptCategory(BCLog::COINJOIN)) {
if (nRounds >= 0 || LogAcceptCategory(BCLog::COINJOIN, BCLog::Level::Debug)) {
itemOutput->setText(COLUMN_COINJOIN_ROUNDS, QString::number(nRounds));
} else {
itemOutput->setText(COLUMN_COINJOIN_ROUNDS, tr("n/a"));

View File

@ -5,6 +5,7 @@
#include <stats/rawsender.h>
#include <logging.h>
#include <netaddress.h>
#include <netbase.h>
#include <util/sock.h>

View File

@ -94,34 +94,36 @@ LockData& GetLockData() {
static void potential_deadlock_detected(const LockPair& mismatch, const LockStack& s1, const LockStack& s2)
{
std::string strOutput = "";
strOutput += "POTENTIAL DEADLOCK DETECTED\n";
strOutput += "Previous lock order was:\n";
std::string log_message{};
log_message += "POTENTIAL DEADLOCK DETECTED\n";
log_message += "Previous lock order was:\n";
for (const LockStackItem& i : s1) {
std::string prefix{};
if (i.first == mismatch.first) {
strOutput += " (1)";
prefix = " (1)";
}
if (i.first == mismatch.second) {
strOutput += " (2)";
prefix = " (2)";
}
strOutput += strprintf(" %s\n", i.second.ToString());
log_message += strprintf("%s %s\n", prefix, i.second.ToString());
}
std::string mutex_a, mutex_b;
strOutput += "Current lock order is:\n";
log_message += "Current lock order is:\n";
for (const LockStackItem& i : s2) {
std::string prefix{};
if (i.first == mismatch.first) {
strOutput += " (1)";
prefix = " (1)";
mutex_a = i.second.Name();
}
if (i.first == mismatch.second) {
strOutput += " (2)";
prefix = " (2)";
mutex_b = i.second.Name();
}
strOutput += strprintf(" %s\n", i.second.ToString());
log_message += strprintf("%s %s\n", prefix, i.second.ToString());
}
LogPrintf("%s\n", strOutput);
LogPrintf("%s\n", log_message);
if (g_debug_lockorder_abort) {
tfm::format(std::cerr, "Assertion failed: detected inconsistent lock order for %s, details in debug log.\n", s2.back().second.ToString());

View File

@ -6,8 +6,11 @@
#ifndef BITCOIN_SYNC_H
#define BITCOIN_SYNC_H
#ifdef DEBUG_LOCKCONTENTION
#include <logging.h>
#include <logging/timer.h>
#endif
#include <threadsafety.h>
#include <util/macros.h>
@ -161,8 +164,10 @@ private:
void Enter(const char* pszName, const char* pszFile, int nLine)
{
EnterCritical(pszName, pszFile, nLine, Base::mutex());
#ifdef DEBUG_LOCKCONTENTION
if (Base::try_lock()) return;
LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
#endif
Base::lock();
}
@ -251,13 +256,10 @@ private:
{
EnterCritical(pszName, pszFile, nLine, Base::mutex());
#ifdef DEBUG_LOCKCONTENTION
if (!Base::try_lock()) {
PrintLockContention(pszName, pszFile, nLine);
#endif
Base::lock();
#ifdef DEBUG_LOCKCONTENTION
}
if (Base::try_lock()) return;
LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK);
#endif
Base::lock();
}
bool TrySharedEnter(const char* pszName, const char* pszFile, int nLine)

View File

@ -18,13 +18,17 @@
#include <vector>
/**
* Identical to TestingSetup but excludes lock contention logging, as some of
* these tests are designed to be heavily contested to trigger race conditions
* or other issues.
* Identical to TestingSetup but excludes lock contention logging if
* `DEBUG_LOCKCONTENTION` is defined, as some of these tests are designed to be
* heavily contested to trigger race conditions or other issues.
*/
struct NoLockLoggingTestingSetup : public TestingSetup {
NoLockLoggingTestingSetup()
#ifdef DEBUG_LOCKCONTENTION
: TestingSetup{CBaseChainParams::MAIN, /*extra_args=*/{"-debugexclude=lock"}} {}
#else
: TestingSetup{CBaseChainParams::MAIN} {}
#endif
};
BOOST_FIXTURE_TEST_SUITE(checkqueue_tests, NoLockLoggingTestingSetup)

View File

@ -3,6 +3,7 @@
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
#include <i2p.h>
#include <logging.h>
#include <netaddress.h>
#include <netbase.h>
#include <test/util/logging.h>
@ -20,6 +21,8 @@ BOOST_FIXTURE_TEST_SUITE(i2p_tests, BasicTestingSetup)
BOOST_AUTO_TEST_CASE(unlimited_recv)
{
const auto prev_log_level{LogInstance().LogLevel()};
LogInstance().SetLogLevel(BCLog::Level::Trace);
auto CreateSockOrig = CreateSock;
// Mock CreateSock() to create MockSock.
@ -40,6 +43,7 @@ BOOST_AUTO_TEST_CASE(unlimited_recv)
}
CreateSock = CreateSockOrig;
LogInstance().SetLogLevel(prev_log_level);
}
BOOST_AUTO_TEST_SUITE_END()

View File

@ -2,16 +2,77 @@
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
#include <init/common.h>
#include <logging.h>
#include <logging/timer.h>
#include <test/util/setup_common.h>
#include <util/string.h>
#include <chrono>
#include <fstream>
#include <iostream>
#include <unordered_map>
#include <utility>
#include <vector>
#include <boost/test/unit_test.hpp>
BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
static void ResetLogger()
{
LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL);
LogInstance().SetCategoryLogLevel({});
}
struct LogSetup : public BasicTestingSetup {
fs::path prev_log_path;
fs::path tmp_log_path;
bool prev_reopen_file;
bool prev_print_to_file;
bool prev_log_timestamps;
bool prev_log_threadnames;
bool prev_log_sourcelocations;
std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
BCLog::Level prev_log_level;
LogSetup() : prev_log_path{LogInstance().m_file_path},
tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
prev_reopen_file{LogInstance().m_reopen_file},
prev_print_to_file{LogInstance().m_print_to_file},
prev_log_timestamps{LogInstance().m_log_timestamps},
prev_log_threadnames{LogInstance().m_log_threadnames},
prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
prev_category_levels{LogInstance().CategoryLevels()},
prev_log_level{LogInstance().LogLevel()}
{
LogInstance().m_file_path = tmp_log_path;
LogInstance().m_reopen_file = true;
LogInstance().m_print_to_file = true;
LogInstance().m_log_timestamps = false;
LogInstance().m_log_threadnames = false;
// Prevent tests from failing when the line number of the logs changes.
LogInstance().m_log_sourcelocations = false;
LogInstance().SetLogLevel(BCLog::Level::Debug);
LogInstance().SetCategoryLogLevel({});
}
~LogSetup()
{
LogInstance().m_file_path = prev_log_path;
LogPrintf("Sentinel log to reopen log file\n");
LogInstance().m_print_to_file = prev_print_to_file;
LogInstance().m_reopen_file = prev_reopen_file;
LogInstance().m_log_timestamps = prev_log_timestamps;
LogInstance().m_log_threadnames = prev_log_threadnames;
LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
LogInstance().SetLogLevel(prev_log_level);
LogInstance().SetCategoryLogLevel(prev_category_levels);
}
};
BOOST_AUTO_TEST_CASE(logging_timer)
{
SetMockTime(1);
@ -30,4 +91,166 @@ BOOST_AUTO_TEST_CASE(logging_timer)
BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)");
}
BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
{
LogInstance().m_log_sourcelocations = true;
LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s", "bar1\n");
LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n");
LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n");
LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n");
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> expected = {
"[src1:1] [fn1] [net:debug] foo1: bar1",
"[src2:2] [fn2] [net] foo2: bar2",
"[src3:3] [fn3] [debug] foo3: bar3",
"[src4:4] [fn4] foo4: bar4",
};
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
{
LogPrintf("foo5: %s\n", "bar5");
LogPrint(BCLog::NET, "foo6: %s\n", "bar6");
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10");
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
std::vector<std::string> expected = {
"foo5: bar5",
"[net] foo6: bar6",
"[net:debug] foo7: bar7",
"[net:info] foo8: bar8",
"[net:warning] foo9: bar9",
"[net:error] foo10: bar10"};
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
{
LogInstance().EnableCategory(BCLog::LogFlags::ALL);
const auto concatenated_category_names = LogInstance().LogCategoriesString();
std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
const auto category_names = SplitString(concatenated_category_names, ',');
for (const auto& category_name : category_names) {
BCLog::LogFlags category;
const auto trimmed_category_name = TrimString(category_name);
BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
expected_category_names.emplace_back(category, trimmed_category_name);
}
std::vector<std::string> expected;
for (const auto& [category, name] : expected_category_names) {
LogPrint(category, "foo: %s\n", "bar");
std::string expected_log = "[";
expected_log += name;
expected_log += "] foo: bar";
expected.push_back(expected_log);
}
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
{
LogInstance().EnableCategory(BCLog::LogFlags::ALL);
LogInstance().SetLogLevel(BCLog::Level::Debug);
LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
// Global log level
LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
// Category-specific log level
LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6");
LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
std::vector<std::string> expected = {
"[http:info] foo1: bar1",
"[validation:warning] foo3: bar3",
"[rpc:error] foo4: bar4",
"[net:warning] foo5: bar5",
"[net:error] foo7: bar7",
};
std::ifstream file{tmp_log_path};
std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) {
log_lines.push_back(log);
}
BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}
BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
{
// Set global log level
{
ResetLogger();
ArgsManager args;
args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
const char* argv_test[] = {"dashd", "-loglevel=debug"};
std::string err;
BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
init::SetLoggingLevel(args);
BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
}
// Set category-specific log level
{
ResetLogger();
ArgsManager args;
args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
const char* argv_test[] = {"dashd", "-loglevel=net:trace"};
std::string err;
BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
init::SetLoggingLevel(args);
BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
const auto& category_levels{LogInstance().CategoryLevels()};
const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
BOOST_REQUIRE(net_it != category_levels.end());
BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
}
// Set both global log level and category-specific log level
{
ResetLogger();
ArgsManager args;
args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
const char* argv_test[] = {"dashd", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
std::string err;
BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
init::SetLoggingLevel(args);
BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
const auto& category_levels{LogInstance().CategoryLevels()};
BOOST_CHECK_EQUAL(category_levels.size(), 2);
const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
BOOST_CHECK(net_it != category_levels.end());
BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
BOOST_CHECK(http_it != category_levels.end());
BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
}
}
BOOST_AUTO_TEST_SUITE_END()

View File

@ -149,6 +149,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve
"-logsourcelocations",
"-logtimemicros",
"-logthreadnames",
"-loglevel=trace",
"-debug",
"-debugexclude=libevent",
"-debugexclude=leveldb",

View File

@ -99,7 +99,7 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample)
}
}
if (LogAcceptCategory(BCLog::NET)) {
if (LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) {
std::string log_message{"time data samples: "};
for (const int64_t n : vSorted) {
log_message += strprintf("%+d ", n);

View File

@ -79,6 +79,7 @@
#include <fstream>
#include <map>
#include <memory>
#include <optional>
#include <string>
#include <system_error>
#include <thread>
@ -205,60 +206,69 @@ static std::string SettingName(const std::string& arg)
return arg.size() > 0 && arg[0] == '-' ? arg.substr(1) : arg;
}
struct KeyInfo {
std::string name;
std::string section;
bool negated{false};
};
/**
* Interpret -nofoo as if the user supplied -foo=0.
* Parse "name", "section.name", "noname", "section.noname" settings keys.
*
* This method also tracks when the -no form was supplied, and if so,
* checks whether there was a double-negative (-nofoo=0 -> -foo=1).
*
* If there was not a double negative, it removes the "no" from the key
* and returns false.
*
* If there was a double negative, it removes "no" from the key, and
* returns true.
*
* If there was no "no", it returns the string value untouched.
*
* Where an option was negated can be later checked using the
* @note Where an option was negated can be later checked using the
* IsArgNegated() method. One use case for this is to have a way to disable
* options that are not normally boolean (e.g. using -nodebuglogfile to request
* that debug log output is not sent to any file at all).
*/
static util::SettingsValue InterpretOption(std::string& section, std::string& key, const std::string& value)
KeyInfo InterpretKey(std::string key)
{
KeyInfo result;
// Split section name from key name for keys like "testnet.foo" or "regtest.bar"
size_t option_index = key.find('.');
if (option_index != std::string::npos) {
section = key.substr(0, option_index);
result.section = key.substr(0, option_index);
key.erase(0, option_index + 1);
}
if (key.substr(0, 2) == "no") {
key.erase(0, 2);
result.negated = true;
}
result.name = key;
return result;
}
/**
* Interpret settings value based on registered flags.
*
* @param[in] key key information to know if key was negated
* @param[in] value string value of setting to be parsed
* @param[in] flags ArgsManager registered argument flags
* @param[out] error Error description if settings value is not valid
*
* @return parsed settings value if it is valid, otherwise nullopt accompanied
* by a descriptive error string
*/
static std::optional<util::SettingsValue> InterpretValue(const KeyInfo& key, const std::string* value,
unsigned int flags, std::string& error)
{
// Return negated settings as false values.
if (key.negated) {
if (flags & ArgsManager::DISALLOW_NEGATION) {
error = strprintf("Negating of -%s is meaningless and therefore forbidden", key.name);
return std::nullopt;
}
// Double negatives like -nofoo=0 are supported (but discouraged)
if (!InterpretBool(value)) {
LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key, value);
if (value && !InterpretBool(*value)) {
LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key.name, *value);
return true;
}
return false;
}
return value;
}
/**
* Check settings value validity according to flags.
*
* TODO: Add more meaningful error checks here in the future
* See "here's how the flags are meant to behave" in
* https://github.com/bitcoin/bitcoin/pull/16097#issuecomment-514627823
*/
static bool CheckValid(const std::string& key, const util::SettingsValue& val, unsigned int flags, std::string& error)
{
if (val.isBool() && !(flags & ArgsManager::ALLOW_BOOL)) {
error = strprintf("Negating of -%s is meaningless and therefore forbidden", key);
return false;
if (!value && (flags & ArgsManager::DISALLOW_ELISION)) {
error = strprintf("Can not set -%s with no value. Please specify value with -%s=value.", key.name, key.name);
return std::nullopt;
}
return true;
return value ? *value : "";
}
// Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to
@ -331,7 +341,7 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin
if (key.substr(0, 5) == "-psn_") continue;
#endif
std::string val;
std::optional<std::string> val;
size_t is_index = key.find('=');
if (is_index != std::string::npos) {
val = key.substr(is_index + 1);
@ -366,21 +376,21 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin
// Transform -foo to foo
key.erase(0, 1);
std::string section;
util::SettingsValue value = InterpretOption(section, key, val);
std::optional<unsigned int> flags = GetArgFlags('-' + key);
KeyInfo keyinfo = InterpretKey(key);
std::optional<unsigned int> flags = GetArgFlags('-' + keyinfo.name);
// Unknown command line options and command line options with dot
// characters (which are returned from InterpretOption with nonempty
// characters (which are returned from InterpretKey with nonempty
// section strings) are not valid.
if (!flags || !section.empty()) {
if (!flags || !keyinfo.section.empty()) {
error = strprintf("Invalid parameter %s", argv[i]);
return false;
}
if (!CheckValid(key, value, *flags, error)) return false;
std::optional<util::SettingsValue> value = InterpretValue(keyinfo, val ? &*val : nullptr, *flags, error);
if (!value) return false;
m_settings.command_line_options[key].push_back(value);
m_settings.command_line_options[keyinfo.name].push_back(*value);
}
// we do not allow -includeconf from command line, only -noincludeconf
@ -583,10 +593,8 @@ bool ArgsManager::ReadSettingsFile(std::vector<std::string>* errors)
return false;
}
for (const auto& setting : m_settings.rw_settings) {
std::string section;
std::string key = setting.first;
(void)InterpretOption(section, key, /* value */ {}); // Split setting key into section and argname
if (!GetArgFlags('-' + key)) {
KeyInfo key = InterpretKey(setting.first); // Split setting key into section and argname
if (!GetArgFlags('-' + key.name)) {
LogPrintf("Ignoring unknown rw_settings value %s\n", setting.first);
}
}
@ -683,6 +691,7 @@ void ArgsManager::AddArg(const std::string& name, const std::string& help, unsig
LOCK(cs_args);
std::map<std::string, Arg>& arg_map = m_available_args[cat];
if ((flags & (ALLOW_ANY | ALLOW_BOOL)) == 0) flags |= DISALLOW_NEGATION; // Temporary, removed in next scripted-diff
auto ret = arg_map.emplace(arg_name, Arg{name.substr(eq_index, name.size() - eq_index), help, flags});
assert(ret.second); // Make sure an insertion actually happened
@ -929,15 +938,14 @@ bool ArgsManager::ReadConfigStream(std::istream& stream, const std::string& file
return false;
}
for (const std::pair<std::string, std::string>& option : options) {
std::string section;
std::string key = option.first;
util::SettingsValue value = InterpretOption(section, key, option.second);
std::optional<unsigned int> flags = GetArgFlags('-' + key);
KeyInfo key = InterpretKey(option.first);
std::optional<unsigned int> flags = GetArgFlags('-' + key.name);
if (flags) {
if (!CheckValid(key, value, *flags, error)) {
std::optional<util::SettingsValue> value = InterpretValue(key, &option.second, *flags, error);
if (!value) {
return false;
}
m_settings.ro_config[section][key].push_back(value);
m_settings.ro_config[key.section][key.name].push_back(*value);
} else {
if (ignore_invalid_keys) {
LogPrintf("Ignoring unknown configuration value %s\n", option.first);

View File

@ -178,12 +178,19 @@ struct SectionInfo
class ArgsManager
{
public:
/**
* Flags controlling how config and command line arguments are validated and
* interpreted.
*/
enum Flags : uint32_t {
// Boolean options can accept negation syntax -noOPTION or -noOPTION=1
ALLOW_BOOL = 0x01,
ALLOW_INT = 0x02,
ALLOW_STRING = 0x04,
ALLOW_ANY = ALLOW_BOOL | ALLOW_INT | ALLOW_STRING,
ALLOW_ANY = 0x01, //!< disable validation
ALLOW_BOOL = 0x02, //!< unimplemented, draft implementation in #16545
ALLOW_INT = 0x04, //!< unimplemented, draft implementation in #16545
ALLOW_STRING = 0x08, //!< unimplemented, draft implementation in #16545
ALLOW_LIST = 0x10, //!< unimplemented, draft implementation in #16545
DISALLOW_NEGATION = 0x20, //!< disallow -nofoo syntax
DISALLOW_ELISION = 0x40, //!< disallow -foo syntax that doesn't assign any value
DEBUG_ONLY = 0x100,
/* Some options would cause cross-contamination if values for
* mainnet were used while running on regtest/testnet (or vice-versa).

View File

@ -2463,8 +2463,8 @@ bool CChainState::FlushStateToDisk(
// Flush best chain related state. This can only be done if the blocks / block index write was also done.
if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) {
{
LOG_TIME_SECONDS(strprintf("write coins cache to disk (%d coins, %.2fkB)",
coins_count, coins_mem_usage / 1000));
LOG_TIME_MILLIS_WITH_CATEGORY(strprintf("write coins cache to disk (%d coins, %.2fkB)",
coins_count, coins_mem_usage / 1000), BCLog::BENCHMARK);
// Typical Coin structures on disk are around 48 bytes in size.
// Pushing a new one to the database can cause it to be written
@ -3756,7 +3756,7 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
if (ppindex)
*ppindex = pindex;
if (pindex->nStatus & BLOCK_FAILED_MASK) {
LogPrintf("ERROR: %s: block %s is marked invalid\n", __func__, hash.ToString());
LogPrint(BCLog::VALIDATION, "%s: block %s is marked invalid\n", __func__, hash.ToString());
return state.Invalid(BlockValidationResult::BLOCK_CACHED_INVALID, "duplicate");
}
if (pindex->nStatus & BLOCK_CONFLICT_CHAINLOCK) {
@ -3775,25 +3775,26 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
CBlockIndex* pindexPrev = nullptr;
BlockMap::iterator mi{m_blockman.m_block_index.find(block.hashPrevBlock)};
if (mi == m_blockman.m_block_index.end()) {
LogPrintf("ERROR: %s: prev block not found\n", __func__);
LogPrint(BCLog::VALIDATION, "%s: %s prev block not found\n", __func__, hash.ToString());
return state.Invalid(BlockValidationResult::BLOCK_MISSING_PREV, "prev-blk-not-found");
}
pindexPrev = &((*mi).second);
assert(pindexPrev);
if (pindexPrev->nStatus & BLOCK_FAILED_MASK) {
LogPrintf("ERROR: %s: prev block invalid\n", __func__);
LogPrint(BCLog::VALIDATION, "%s: %s prev block invalid\n", __func__, hash.ToString());
return state.Invalid(BlockValidationResult::BLOCK_INVALID_PREV, "bad-prevblk");
}
if (pindexPrev->nStatus & BLOCK_CONFLICT_CHAINLOCK) {
// it's ok-ish, the other node is probably missing the latest chainlock
LogPrintf("ERROR: %s: prev block %s conflicts with chainlock\n", __func__, block.hashPrevBlock.ToString());
LogPrint(BCLog::VALIDATION, "%s: prev block %s conflicts with chainlock\n", __func__, block.hashPrevBlock.ToString());
return state.Invalid(BlockValidationResult::BLOCK_CHAINLOCK, "bad-prevblk-chainlock");
}
if (!ContextualCheckBlockHeader(block, state, m_blockman, chainparams, pindexPrev, GetAdjustedTime())) {
return error("%s: Consensus::ContextualCheckBlockHeader: %s, %s", __func__, hash.ToString(), state.ToString());
LogPrint(BCLog::VALIDATION, "%s: Consensus::ContextualCheckBlockHeader: %s, %s\n", __func__, hash.ToString(), state.ToString());
return false;
}
/* Determine if this block descends from any block which has been found
@ -3829,7 +3830,7 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
m_blockman.m_dirty_blockindex.insert(invalid_walk);
invalid_walk = invalid_walk->pprev;
}
LogPrintf("ERROR: %s: prev block invalid\n", __func__);
LogPrint(BCLog::VALIDATION, "%s: %s prev block invalid\n", __func__, hash.ToString());
return state.Invalid(BlockValidationResult::BLOCK_INVALID_PREV, "bad-prevblk");
}
}

View File

@ -340,15 +340,15 @@ bool KnapsackSolver(const CAmount& nTargetValue, std::vector<OutputGroup>& group
util::insert(setCoinsRet, lowest_larger->m_outputs);
nValueRet += lowest_larger->m_value;
} else {
std::string s = "CWallet::SelectCoinsMinConf best subset: ";
std::string log_message{"Coin selection best subset: "};
for (unsigned int i = 0; i < applicable_groups.size(); i++) {
if (vfBest[i]) {
util::insert(setCoinsRet, applicable_groups[i].m_outputs);
nValueRet += applicable_groups[i].m_value;
s += FormatMoney(applicable_groups[i].m_value) + " ";
log_message += strprintf("%s ", FormatMoney(applicable_groups[i].m_value));
}
}
LogPrint(BCLog::SELECTCOINS, "%s - total %s\n", s, FormatMoney(nBest));
LogPrint(BCLog::SELECTCOINS, "%stotal %s\n", log_message, FormatMoney(nBest));
}
// There is no change in PS, so we know the fee beforehand,

View File

@ -3432,7 +3432,7 @@ std::vector<CompactTallyItem> CWallet::SelectCoinsGroupedByAddresses(bool fSkipD
}
// debug
if (LogAcceptCategory(BCLog::SELECTCOINS)) {
if (LogAcceptCategory(BCLog::SELECTCOINS, BCLog::Level::Debug)) {
std::string strMessage = "SelectCoinsGroupedByAddresses - vecTallyRet:\n";
for (const auto& item : vecTallyRet)
strMessage += strprintf(" %s %f\n", EncodeDestination(item.txdest), float(item.nAmount)/COIN);

View File

@ -150,11 +150,11 @@ extern const std::map<uint64_t,std::string> WALLET_FLAG_CAVEATS;
// Use a macro instead of a function for conditional logging to prevent
// evaluating arguments when logging for the category is not enabled.
#define WalletCJLogPrint(wallet, ...) \
do { \
if (LogAcceptCategory(BCLog::COINJOIN)) { \
wallet.WalletLogPrintf(__VA_ARGS__); \
} \
#define WalletCJLogPrint(wallet, ...) \
do { \
if (LogAcceptCategory(BCLog::COINJOIN, BCLog::Level::Debug)) { \
wallet.WalletLogPrintf(__VA_ARGS__); \
} \
} while (0)
/** A wrapper to reserve an address from a wallet

View File

@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework):
def test_invalid_command_line_options(self):
self.nodes[0].assert_start_raises_init_error(
expected_msg='Error: No proxy server specified. Use -proxy=<ip> or -proxy=<ip:port>.',
expected_msg='Error: Error parsing command line arguments: Can not set -proxy with no value. Please specify value with -proxy=value.',
extra_args=['-proxy'],
)

View File

@ -56,9 +56,6 @@ class RpcMiscTest(BitcoinTestFramework):
self.log.info("test logging rpc and help")
# Test logging RPC returns the expected number of logging categories.
assert_equal(len(node.logging()), 39)
# Test toggling a logging category on/off/on with the logging RPC.
assert_equal(node.logging()['qt'], True)
node.logging(exclude=['qt'])

View File

@ -125,6 +125,8 @@ class TestNode():
self.args.append("-logthreadnames")
if self.version_is_at_least(21000000):
self.args.append("-logsourcelocations")
if self.version_is_at_least(22010000):
self.args.append("-loglevel=trace")
# Default behavior from global -v2transport flag is added to args to persist it over restarts.
# May be overwritten in individual tests, using extra_args.

View File

@ -17,6 +17,7 @@ FUNCTION_NAMES_AND_NUMBER_OF_LEADING_ARGUMENTS=(
"LogConnectFailure,1"
"LogPrint,1"
"LogPrintf,0"
"LogPrintLevel,2"
"printf,0"
"snprintf,2"
"sprintf,1"

View File

@ -14,7 +14,7 @@
export LC_ALL=C
UNTERMINATED_LOGS=$(git grep --extended-regexp "LogPrintf?\(" -- "*.cpp" | \
UNTERMINATED_LOGS=$(git grep --extended-regexp "(LogPrintLevel|LogPrintf?)\(" -- "*.cpp" | \
grep -v '\\n"' | \
grep -v '\.\.\.' | \
grep -v "/\* Continued \*/" | \
@ -22,7 +22,7 @@ UNTERMINATED_LOGS=$(git grep --extended-regexp "LogPrintf?\(" -- "*.cpp" | \
grep -v "LogPrintf()")
if [[ ${UNTERMINATED_LOGS} != "" ]]; then
# shellcheck disable=SC2028
echo "All calls to LogPrintf() and LogPrint() should be terminated with \\n"
echo "All calls to LogPrintf(), LogPrint(), LogPrintLevel(), and WalletLogPrintf() should be terminated with \\n"
echo
echo "${UNTERMINATED_LOGS}"
exit 1