From 55d74630b43058b51f22d3ac9da6f3d1295416a8 Mon Sep 17 00:00:00 2001 From: UdjinM6 Date: Fri, 15 Nov 2024 12:38:04 +0300 Subject: [PATCH 01/24] docs: mention building for some HOSTs only in `release-process.md` --- doc/release-process.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/doc/release-process.md b/doc/release-process.md index 221da92d0d..70f2b79a69 100644 --- a/doc/release-process.md +++ b/doc/release-process.md @@ -97,6 +97,8 @@ Follow the relevant Guix README.md sections: - [Building](/contrib/guix/README.md#building) - [Attesting to build outputs](/contrib/guix/README.md#attesting-to-build-outputs) +_Note: we build releases for some supported HOSTs only so either provide correct `HOSTS` variable or run `./contrib/containers/guix/scripts/guix-start` instead of `./contrib/guix/guix-build` when building binaries_ + ### Verify other builders' signatures to your own. (Optional) Add other builders keys to your gpg keyring, and/or refresh keys: See `../dash/contrib/builder-keys/README.md`. From 479ae82ecc1b2714de81c2d28e86515f7c9fab04 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 18 Nov 2024 10:45:27 +0000 Subject: [PATCH 02/24] merge bitcoin#23235: Reduce unnecessary default logging --- src/logging.cpp | 1 + src/logging.h | 1 + src/node/blockstorage.cpp | 4 ++-- src/validation.cpp | 17 +++++++++-------- test/functional/rpc_misc.py | 2 +- 5 files changed, 14 insertions(+), 11 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index dbbff8b92f..ddb6c57fbd 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -161,6 +161,7 @@ const CLogCategoryDesc LogCategories[] = {BCLog::I2P, "i2p"}, {BCLog::IPC, "ipc"}, {BCLog::LOCK, "lock"}, + {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::TXRECONCILIATION, "txreconciliation"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, diff --git a/src/logging.h b/src/logging.h index a534512049..b12a22cb63 100644 --- a/src/logging.h +++ b/src/logging.h @@ -62,6 +62,7 @@ namespace BCLog { I2P = (1 << 22), IPC = (1 << 23), LOCK = (1 << 24), + BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), //Start Dash diff --git a/src/node/blockstorage.cpp b/src/node/blockstorage.cpp index 3c13592e8a..ed1e8005e8 100644 --- a/src/node/blockstorage.cpp +++ b/src/node/blockstorage.cpp @@ -585,7 +585,7 @@ void UnlinkPrunedFiles(const std::set& 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; diff --git a/src/validation.cpp b/src/validation.cpp index fda0a2b1f7..1074bb065f 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -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"); } } diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index ca3901dd6d..1d141d8e1c 100755 --- a/test/functional/rpc_misc.py +++ b/test/functional/rpc_misc.py @@ -57,7 +57,7 @@ def run_test(self): self.log.info("test logging rpc and help") # Test logging RPC returns the expected number of logging categories. - assert_equal(len(node.logging()), 39) + assert_equal(len(node.logging()), 40) # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True) From d9cc2ea17824a9b0667f2091819b51a90eca8093 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 17:26:32 +0000 Subject: [PATCH 03/24] merge bitcoin#23104: Avoid breaking single log lines over multiple lines in the log file --- src/sync.cpp | 24 +++++++++++++----------- src/wallet/coinselection.cpp | 6 +++--- 2 files changed, 16 insertions(+), 14 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index 7540819262..c0a3314765 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -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()); diff --git a/src/wallet/coinselection.cpp b/src/wallet/coinselection.cpp index be9fdbb1c2..6bd9044da8 100644 --- a/src/wallet/coinselection.cpp +++ b/src/wallet/coinselection.cpp @@ -340,15 +340,15 @@ bool KnapsackSolver(const CAmount& nTargetValue, std::vector& 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, From f331cbe8c84c69f0be023b7d13eceb4728b0d02a Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 18 Nov 2024 10:47:10 +0000 Subject: [PATCH 04/24] merge bitcoin#24770: Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive --- doc/developer-notes.md | 14 ++++++++++++++ src/evo/creditpool.h | 1 + src/llmq/quorums.h | 1 + src/logging.cpp | 2 ++ src/logging.h | 2 ++ src/net.h | 2 ++ src/stats/rawsender.cpp | 1 + src/sync.h | 5 +++++ src/test/checkqueue_tests.cpp | 10 +++++++--- test/functional/rpc_misc.py | 3 --- 10 files changed, 35 insertions(+), 6 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 5d81f32d21..f4a7095392 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -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) @@ -412,6 +413,19 @@ 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. + +To enable it, run configure with `-DDEBUG_LOCKCONTENTION` added to your +CPPFLAGS, e.g. `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 diff --git a/src/evo/creditpool.h b/src/evo/creditpool.h index 5da980df65..4d4169974d 100644 --- a/src/evo/creditpool.h +++ b/src/evo/creditpool.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include diff --git a/src/llmq/quorums.h b/src/llmq/quorums.h index fac31afb02..415b4c60fd 100644 --- a/src/llmq/quorums.h +++ b/src/llmq/quorums.h @@ -15,6 +15,7 @@ #include #include #include +#include #include #include diff --git a/src/logging.cpp b/src/logging.cpp index ddb6c57fbd..5ac21e344b 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -160,7 +160,9 @@ 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"}, diff --git a/src/logging.h b/src/logging.h index b12a22cb63..c88bae4957 100644 --- a/src/logging.h +++ b/src/logging.h @@ -61,7 +61,9 @@ namespace BCLog { VALIDATION = (1 << 21), I2P = (1 << 22), IPC = (1 << 23), +#ifdef DEBUG_LOCKCONTENTION LOCK = (1 << 24), +#endif BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), diff --git a/src/net.h b/src/net.h index 89ea78a4b9..3ac5523e21 100644 --- a/src/net.h +++ b/src/net.h @@ -16,6 +16,7 @@ #include #include #include +#include #include #include #include @@ -42,6 +43,7 @@ #include #include #include +#include #include #include #include diff --git a/src/stats/rawsender.cpp b/src/stats/rawsender.cpp index eb423e37d5..8b56875f2f 100644 --- a/src/stats/rawsender.cpp +++ b/src/stats/rawsender.cpp @@ -5,6 +5,7 @@ #include +#include #include #include #include diff --git a/src/sync.h b/src/sync.h index 7206ac387a..dfe5846d7c 100644 --- a/src/sync.h +++ b/src/sync.h @@ -6,8 +6,11 @@ #ifndef BITCOIN_SYNC_H #define BITCOIN_SYNC_H +#ifdef DEBUG_LOCKCONTENTION #include #include +#endif + #include #include @@ -161,8 +164,10 @@ class SCOPED_LOCKABLE UniqueLock : public Base 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(); } diff --git a/src/test/checkqueue_tests.cpp b/src/test/checkqueue_tests.cpp index d0e5404057..b7ccc71cdc 100644 --- a/src/test/checkqueue_tests.cpp +++ b/src/test/checkqueue_tests.cpp @@ -18,13 +18,17 @@ #include /** - * 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) diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index 1d141d8e1c..cd69f65ddb 100755 --- a/test/functional/rpc_misc.py +++ b/test/functional/rpc_misc.py @@ -56,9 +56,6 @@ def run_test(self): self.log.info("test logging rpc and help") - # Test logging RPC returns the expected number of logging categories. - assert_equal(len(node.logging()), 40) - # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True) node.logging(exclude=['qt']) From a9cfbd1048f79796d4835cb88412ebcdc19d8a5c Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 16:04:28 +0000 Subject: [PATCH 05/24] fix: don't use non-existent `PrintLockContention` in `SharedEnter` `PrintLockContention` hasn't existed since dash#6046 --- src/sync.h | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/src/sync.h b/src/sync.h index dfe5846d7c..6f4ffcc680 100644 --- a/src/sync.h +++ b/src/sync.h @@ -256,13 +256,10 @@ class SCOPED_LOCKABLE SharedLock : public Base { 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) From 3d67771f89c28f7ffc344f0948f8bc552047343e Mon Sep 17 00:00:00 2001 From: pasta Date: Thu, 21 Nov 2024 11:43:40 -0600 Subject: [PATCH 06/24] refactor: add in quorumBaseBlockIndexCache to reduce cs_main contention --- src/llmq/quorums.cpp | 15 ++++++++++++++- src/llmq/quorums.h | 4 ++++ 2 files changed, 18 insertions(+), 1 deletion(-) diff --git a/src/llmq/quorums.cpp b/src/llmq/quorums.cpp index 87aef8e791..1b9902a5a8 100644 --- a/src/llmq/quorums.cpp +++ b/src/llmq/quorums.cpp @@ -633,7 +633,20 @@ std::vector CQuorumManager::ScanQuorums(Consensus::LLMQType llmqTyp CQuorumCPtr CQuorumManager::GetQuorum(Consensus::LLMQType llmqType, const uint256& quorumHash) const { - const CBlockIndex* pQuorumBaseBlockIndex = WITH_LOCK(cs_main, return m_chainstate.m_blockman.LookupBlockIndex(quorumHash)); + const CBlockIndex* pQuorumBaseBlockIndex = [&]() { + // Lock contention may still be high here; consider using a shared lock + // We cannot hold cs_quorumBaseBlockIndexCache the whole time as that creates lock-order inversion with cs_main; + // We cannot aquire cs_main if we have cs_quorumBaseBlockIndexCache held + const CBlockIndex* pindex; + if (!WITH_LOCK(cs_quorumBaseBlockIndexCache, return quorumBaseBlockIndexCache.get(quorumHash, pindex))) { + pindex = WITH_LOCK(cs_main, return m_chainstate.m_blockman.LookupBlockIndex(quorumHash)); + if (pindex) { + LOCK(cs_quorumBaseBlockIndexCache); + quorumBaseBlockIndexCache.insert(quorumHash, pindex); + } + } + return pindex; + }(); if (!pQuorumBaseBlockIndex) { LogPrint(BCLog::LLMQ, "CQuorumManager::%s -- block %s not found\n", __func__, quorumHash.ToString()); return nullptr; diff --git a/src/llmq/quorums.h b/src/llmq/quorums.h index fac31afb02..4700bd6fc1 100644 --- a/src/llmq/quorums.h +++ b/src/llmq/quorums.h @@ -252,6 +252,10 @@ class CQuorumManager mutable Mutex cs_cleanup; mutable std::map> cleanupQuorumsCache GUARDED_BY(cs_cleanup); + mutable Mutex cs_quorumBaseBlockIndexCache; + // On mainnet, we have around 62 quorums active at any point; let's cache a little more than double that to be safe. + mutable unordered_lru_cache quorumBaseBlockIndexCache; + mutable ctpl::thread_pool workerPool; mutable CThreadInterrupt quorumThreadInterrupt; From b65f0bab7f55f8cc27e72828d0f9045c1e6181d7 Mon Sep 17 00:00:00 2001 From: pasta Date: Thu, 21 Nov 2024 13:54:37 -0600 Subject: [PATCH 07/24] refactor: move expensive CInv initialization out of hot loop --- src/net_processing.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index b6f75dfa00..19bd7de3f5 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2328,13 +2328,13 @@ void PeerManagerImpl::RelayInvFiltered(CInv &inv, const uint256& relatedTxHash, void PeerManagerImpl::RelayTransaction(const uint256& txid) { + const CInv inv{m_cj_ctx->dstxman->GetDSTX(txid) ? MSG_DSTX : MSG_TX, txid}; LOCK(m_peer_mutex); for(auto& it : m_peer_map) { Peer& peer = *it.second; auto tx_relay = peer.GetTxRelay(); if (!tx_relay) continue; - const CInv inv{m_cj_ctx->dstxman->GetDSTX(txid) ? MSG_DSTX : MSG_TX, txid}; PushInv(peer, inv); }; } From 4668db60a2c6abbf138f4d7ce4fd1dd10ec6a98f Mon Sep 17 00:00:00 2001 From: pasta Date: Thu, 21 Nov 2024 13:43:59 -0600 Subject: [PATCH 08/24] refactor: create helper function RelayRecoveredSig inside peerman this commit should have a few benefits: 1. previous logic using ForEachNode results in locking m_nodes_mutex, a highly contended RecursiveMutex, AND m_peer_mutex(in GetPeerRef) 2. prior also resulted in calling .find over the m_peer_map for each node. Basically old logic was (probably) O(n(nlogn) the new logic results in acquiring m_peer_mutex once and looping over the list of peers, (probably) O(n) 3. Moves networking logic out of llmq/ and into actual net_processing.cpp --- src/llmq/signing.cpp | 7 +------ src/net.h | 2 -- src/net_processing.cpp | 16 +++++++++++++++- src/net_processing.h | 3 +++ 4 files changed, 19 insertions(+), 9 deletions(-) diff --git a/src/llmq/signing.cpp b/src/llmq/signing.cpp index 68b4949438..4258eecc83 100644 --- a/src/llmq/signing.cpp +++ b/src/llmq/signing.cpp @@ -633,12 +633,7 @@ void CSigningManager::ProcessRecoveredSig(const std::shared_ptrGetHash())); if (m_mn_activeman != nullptr) { - CInv inv(MSG_QUORUM_RECOVERED_SIG, recoveredSig->GetHash()); - connman.ForEachNode([&](const CNode* pnode) { - if (pnode->fSendRecSigs) { - Assert(m_peerman)->PushInventory(pnode->GetId(), inv); - } - }); + Assert(m_peerman)->RelayRecoveredSig(recoveredSig->GetHash()); } auto listeners = WITH_LOCK(cs_listeners, return recoveredSigsListeners); diff --git a/src/net.h b/src/net.h index 89ea78a4b9..22fcc827b0 100644 --- a/src/net.h +++ b/src/net.h @@ -976,8 +976,6 @@ class CNode // If true, we will send him CoinJoin queue messages std::atomic fSendDSQueue{false}; - // If true, we will announce/send him plain recovered sigs (usually true for full nodes) - std::atomic fSendRecSigs{false}; // If true, we will send him all quorum related messages, even if he is not a member of our quorums std::atomic qwatch{false}; diff --git a/src/net_processing.cpp b/src/net_processing.cpp index b6f75dfa00..3c10f519f4 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -271,6 +271,8 @@ struct Peer { std::atomic m_ping_start{0us}; /** Whether a ping has been requested by the user */ std::atomic m_ping_queued{false}; + /** Whether the peer has requested to receive llmq recovered signatures */ + std::atomic m_wants_recsigs{false}; struct TxRelay { mutable RecursiveMutex m_bloom_filter_mutex; @@ -607,6 +609,7 @@ class PeerManagerImpl final : public PeerManager void RelayInvFiltered(CInv &inv, const CTransaction &relatedTx, const int minProtoVersion) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void RelayInvFiltered(CInv &inv, const uint256 &relatedTxHash, const int minProtoVersion) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void RelayTransaction(const uint256& txid) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); + void RelayRecoveredSig(const uint256& sigHash) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void SetBestHeight(int height) override { m_best_height = height; }; void Misbehaving(const NodeId pnode, const int howmuch, const std::string& message = "") override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void ProcessMessage(CNode& pfrom, const std::string& msg_type, CDataStream& vRecv, @@ -2339,6 +2342,17 @@ void PeerManagerImpl::RelayTransaction(const uint256& txid) }; } +void PeerManagerImpl::RelayRecoveredSig(const uint256& sigHash) +{ + const CInv inv{MSG_QUORUM_RECOVERED_SIG, sigHash}; + LOCK(m_peer_mutex); + for (const auto& [_, peer] : m_peer_map) { + if (peer->m_wants_recsigs) { + PushInv(*peer, inv); + } + } +} + void PeerManagerImpl::RelayAddress(NodeId originator, const CAddress& addr, bool fReachable) @@ -3948,7 +3962,7 @@ void PeerManagerImpl::ProcessMessage( if (msg_type == NetMsgType::QSENDRECSIGS) { bool b; vRecv >> b; - pfrom.fSendRecSigs = b; + peer->m_wants_recsigs = b; return; } diff --git a/src/net_processing.h b/src/net_processing.h index a857201516..99144d2335 100644 --- a/src/net_processing.h +++ b/src/net_processing.h @@ -109,6 +109,9 @@ class PeerManager : public CValidationInterface, public NetEventsInterface virtual void RelayTransaction(const uint256& txid) EXCLUSIVE_LOCKS_REQUIRED(cs_main) = 0; + /** Relay recovered sigs to all interested peers */ + virtual void RelayRecoveredSig(const uint256& sigHash) = 0; + /** Set the best height */ virtual void SetBestHeight(int height) = 0; From 3ba602672c422c335fe7de708f009b5ef86c4f5e Mon Sep 17 00:00:00 2001 From: pasta Date: Tue, 19 Nov 2024 22:41:07 -0600 Subject: [PATCH 09/24] refactor: use self.wait_until in all the dash specific "wait_until_x" logic in order to actually apply the timeout scaling settings --- test/functional/feature_governance.py | 12 +++---- test/functional/feature_llmq_signing.py | 4 +-- .../test_framework/test_framework.py | 34 +++++++++---------- 3 files changed, 25 insertions(+), 25 deletions(-) diff --git a/test/functional/feature_governance.py b/test/functional/feature_governance.py index 43c49784d2..670048735f 100755 --- a/test/functional/feature_governance.py +++ b/test/functional/feature_governance.py @@ -9,7 +9,7 @@ from test_framework.messages import uint256_to_string from test_framework.test_framework import DashTestFramework from test_framework.governance import have_trigger_for_height, prepare_object -from test_framework.util import assert_equal, satoshi_round, wait_until_helper +from test_framework.util import assert_equal, satoshi_round GOVERNANCE_UPDATE_MIN = 60 * 60 # src/governance/object.h @@ -195,7 +195,7 @@ def run_test(self): self.wait_until(lambda: len(isolated.gobject("list", "valid", "triggers")) == 1, timeout=5) isolated_trigger_hash = list(isolated.gobject("list", "valid", "triggers").keys())[0] self.wait_until(lambda: list(isolated.gobject("list", "valid", "triggers").values())[0]['YesCount'] == 1, timeout=5) - more_votes = wait_until_helper(lambda: list(isolated.gobject("list", "valid", "triggers").values())[0]['YesCount'] > 1, timeout=5, do_assert=False) + more_votes = self.wait_until(lambda: list(isolated.gobject("list", "valid", "triggers").values())[0]['YesCount'] > 1, timeout=5, do_assert=False) assert_equal(more_votes, False) self.log.info("Move 1 block enabling the Superblock maturity window on non-isolated nodes") @@ -206,7 +206,7 @@ def run_test(self): self.check_superblockbudget(False) self.log.info("The 'winner' should submit new trigger and vote for it, but it's isolated so no triggers should be found") - has_trigger = wait_until_helper(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) >= 1, timeout=5, do_assert=False) + has_trigger = self.wait_until(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) >= 1, timeout=5, do_assert=False) assert_equal(has_trigger, False) self.log.info("Move 1 block inside the Superblock maturity window on non-isolated nodes") @@ -217,7 +217,7 @@ def run_test(self): self.wait_until(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) == 1, timeout=5) winning_trigger_hash = list(self.nodes[0].gobject("list", "valid", "triggers").keys())[0] self.wait_until(lambda: list(self.nodes[0].gobject("list", "valid", "triggers").values())[0]['YesCount'] == 1, timeout=5) - more_votes = wait_until_helper(lambda: list(self.nodes[0].gobject("list", "valid", "triggers").values())[0]['YesCount'] > 1, timeout=5, do_assert=False) + more_votes = self.wait_until(lambda: list(self.nodes[0].gobject("list", "valid", "triggers").values())[0]['YesCount'] > 1, timeout=5, do_assert=False) assert_equal(more_votes, False) self.log.info("Make sure amounts aren't trimmed") @@ -233,7 +233,7 @@ def run_test(self): self.log.info("Every non-isolated MN should vote for the same trigger now, no new triggers should be created") self.wait_until(lambda: list(self.nodes[0].gobject("list", "valid", "triggers").values())[0]['YesCount'] == self.mn_count - 1, timeout=5) - more_triggers = wait_until_helper(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) > 1, timeout=5, do_assert=False) + more_triggers = self.wait_until(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) > 1, timeout=5, do_assert=False) assert_equal(more_triggers, False) self.reconnect_isolated_node(payee_idx, 0) @@ -260,7 +260,7 @@ def sync_gov(node): self.log.info("Should see two triggers now") self.wait_until(lambda: len(isolated.gobject("list", "valid", "triggers")) == 2, timeout=5) self.wait_until(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) == 2, timeout=5) - more_triggers = wait_until_helper(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) > 2, timeout=5, do_assert=False) + more_triggers = self.wait_until(lambda: len(self.nodes[0].gobject("list", "valid", "triggers")) > 2, timeout=5, do_assert=False) assert_equal(more_triggers, False) self.log.info("Move another block inside the Superblock maturity window") diff --git a/test/functional/feature_llmq_signing.py b/test/functional/feature_llmq_signing.py index 8206e7dde4..082bfe7e83 100755 --- a/test/functional/feature_llmq_signing.py +++ b/test/functional/feature_llmq_signing.py @@ -13,7 +13,7 @@ from test_framework.messages import CSigShare, msg_qsigshare, uint256_to_string from test_framework.p2p import P2PInterface from test_framework.test_framework import DashTestFramework -from test_framework.util import assert_equal, assert_raises_rpc_error, force_finish_mnsync, wait_until_helper +from test_framework.util import assert_equal, assert_raises_rpc_error, force_finish_mnsync class LLMQSigningTest(DashTestFramework): @@ -55,7 +55,7 @@ def wait_for_sigs(hasrecsigs, isconflicting1, isconflicting2, timeout): self.wait_until(lambda: check_sigs(hasrecsigs, isconflicting1, isconflicting2), timeout = timeout) def assert_sigs_nochange(hasrecsigs, isconflicting1, isconflicting2, timeout): - assert not wait_until_helper(lambda: not check_sigs(hasrecsigs, isconflicting1, isconflicting2), timeout = timeout, do_assert = False) + assert not self.wait_until(lambda: not check_sigs(hasrecsigs, isconflicting1, isconflicting2), timeout = timeout, do_assert = False) # Initial state wait_for_sigs(False, False, False, 1) diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index a9a063b593..973ab48a9e 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -768,7 +768,7 @@ def get_peer_ids(from_connection, node_num): def isolate_node(self, node_num, timeout=5): self.nodes[node_num].setnetworkactive(False) - wait_until_helper(lambda: self.nodes[node_num].getconnectioncount() == 0, timeout=timeout) + self.wait_until(lambda: self.nodes[node_num].getconnectioncount() == 0, timeout=timeout) def reconnect_isolated_node(self, a, b): self.nodes[a].setnetworkactive(True) @@ -893,8 +893,8 @@ def _initialize_mocktime(self, is_genesis): for node in self.nodes: node.mocktime = self.mocktime - def wait_until(self, test_function, timeout=60, lock=None): - return wait_until_helper(test_function, timeout=timeout, lock=lock, timeout_factor=self.options.timeout_factor) + def wait_until(self, test_function, timeout=60, lock=None, sleep=0.5, do_assert=True): + return wait_until_helper(test_function, timeout=timeout, lock=lock, timeout_factor=self.options.timeout_factor, sleep=sleep, do_assert=do_assert) # Private helper methods. These should not be accessed by the subclass test scripts. @@ -1620,7 +1620,7 @@ def check_tx(): return node.getrawtransaction(txid) except: return False - if wait_until_helper(check_tx, timeout=timeout, sleep=1, do_assert=expected) and not expected: + if self.wait_until(check_tx, timeout=timeout, sleep=1, do_assert=expected) and not expected: raise AssertionError("waiting unexpectedly succeeded") def create_isdlock(self, hextx): @@ -1652,7 +1652,7 @@ def check_instantlock(): return node.getrawtransaction(txid, True)["instantlock"] except: return False - if wait_until_helper(check_instantlock, timeout=timeout, sleep=1, do_assert=expected) and not expected: + if self.wait_until(check_instantlock, timeout=timeout, sleep=1, do_assert=expected) and not expected: raise AssertionError("waiting unexpectedly succeeded") def wait_for_chainlocked_block(self, node, block_hash, expected=True, timeout=15): @@ -1662,7 +1662,7 @@ def check_chainlocked_block(): return block["confirmations"] > 0 and block["chainlock"] except: return False - if wait_until_helper(check_chainlocked_block, timeout=timeout, sleep=0.1, do_assert=expected) and not expected: + if self.wait_until(check_chainlocked_block, timeout=timeout, sleep=0.1, do_assert=expected) and not expected: raise AssertionError("waiting unexpectedly succeeded") def wait_for_chainlocked_block_all_nodes(self, block_hash, timeout=15, expected=True): @@ -1670,14 +1670,14 @@ def wait_for_chainlocked_block_all_nodes(self, block_hash, timeout=15, expected= self.wait_for_chainlocked_block(node, block_hash, expected=expected, timeout=timeout) def wait_for_best_chainlock(self, node, block_hash, timeout=15): - wait_until_helper(lambda: node.getbestchainlock()["blockhash"] == block_hash, timeout=timeout, sleep=0.1) + self.wait_until(lambda: node.getbestchainlock()["blockhash"] == block_hash, timeout=timeout, sleep=0.1) def wait_for_sporks_same(self, timeout=30): def check_sporks_same(): self.bump_mocktime(1) sporks = self.nodes[0].spork('show') return all(node.spork('show') == sporks for node in self.nodes[1:]) - wait_until_helper(check_sporks_same, timeout=timeout, sleep=0.5) + self.wait_until(check_sporks_same, timeout=timeout, sleep=0.5) def wait_for_quorum_connections(self, quorum_hash, expected_connections, mninfos, llmq_type_name="llmq_test", timeout = 60, wait_proc=None): def check_quorum_connections(): @@ -1716,7 +1716,7 @@ def ret(): # no sessions at all - not ok return ret() - wait_until_helper(check_quorum_connections, timeout=timeout, sleep=1) + self.wait_until(check_quorum_connections, timeout=timeout, sleep=1) def wait_for_masternode_probes(self, quorum_hash, mninfos, timeout = 30, wait_proc=None, llmq_type_name="llmq_test"): def check_probes(): @@ -1754,7 +1754,7 @@ def ret(): return ret() return True - wait_until_helper(check_probes, timeout=timeout, sleep=1) + self.wait_until(check_probes, timeout=timeout, sleep=1) def wait_for_quorum_phase(self, quorum_hash, phase, expected_member_count, check_received_messages, check_received_messages_count, mninfos, llmq_type_name="llmq_test", timeout=30, sleep=0.5): def check_dkg_session(): @@ -1776,7 +1776,7 @@ def check_dkg_session(): break return member_count >= expected_member_count - wait_until_helper(check_dkg_session, timeout=timeout, sleep=sleep) + self.wait_until(check_dkg_session, timeout=timeout, sleep=sleep) def wait_for_quorum_commitment(self, quorum_hash, nodes, llmq_type=100, timeout=15): def check_dkg_comitments(): @@ -1797,7 +1797,7 @@ def check_dkg_comitments(): return False return True - wait_until_helper(check_dkg_comitments, timeout=timeout, sleep=1) + self.wait_until(check_dkg_comitments, timeout=timeout, sleep=1) def wait_for_quorum_list(self, quorum_hash, nodes, timeout=15, sleep=2, llmq_type_name="llmq_test"): def wait_func(): @@ -1807,7 +1807,7 @@ def wait_func(): self.bump_mocktime(sleep, nodes=nodes) self.generate(self.nodes[0], 1, sync_fun=lambda: self.sync_blocks(nodes)) return False - wait_until_helper(wait_func, timeout=timeout, sleep=sleep) + self.wait_until(wait_func, timeout=timeout, sleep=sleep) def wait_for_quorums_list(self, quorum_hash_0, quorum_hash_1, nodes, llmq_type_name="llmq_test", timeout=15, sleep=2): def wait_func(): @@ -1818,7 +1818,7 @@ def wait_func(): self.bump_mocktime(sleep, nodes=nodes) self.generate(self.nodes[0], 1, sync_fun=lambda: self.sync_blocks(nodes)) return False - wait_until_helper(wait_func, timeout=timeout, sleep=sleep) + self.wait_until(wait_func, timeout=timeout, sleep=sleep) def move_blocks(self, nodes, num_blocks): self.bump_mocktime(1, nodes=nodes) @@ -2055,7 +2055,7 @@ def check_recovered_sig(): if not mn.node.quorum("hasrecsig", llmq_type, rec_sig_id, rec_sig_msg_hash): return False return True - wait_until_helper(check_recovered_sig, timeout=timeout, sleep=1) + self.wait_until(check_recovered_sig, timeout=timeout, sleep=1) def get_recovered_sig(self, rec_sig_id, rec_sig_msg_hash, llmq_type=100, use_platformsign=False): # Note: recsigs aren't relayed to regular nodes by default, @@ -2116,7 +2116,7 @@ def test_mns(): (valid, len(mns), quorum_type_in, quorum_hash_in)) return valid == len(mns) - wait_until_helper(test_mns, timeout=timeout, sleep=0.5) + self.wait_until(test_mns, timeout=timeout, sleep=0.5) def wait_for_mnauth(self, node, count, timeout=10): def test(): @@ -2126,4 +2126,4 @@ def test(): if "verified_proregtx_hash" in p and p["verified_proregtx_hash"] != "": c += 1 return c >= count - wait_until_helper(test, timeout=timeout) + self.wait_until(test, timeout=timeout) From 86e92c376a71c5cf5b061c0e7c178990c5d61c9f Mon Sep 17 00:00:00 2001 From: Konstantin Akimov Date: Sat, 23 Nov 2024 01:54:18 +0700 Subject: [PATCH 10/24] refactor: drop unused CConnman from CSigningManager --- src/llmq/context.cpp | 2 +- src/llmq/instantsend.h | 1 + src/llmq/signing.cpp | 4 ++-- src/llmq/signing.h | 4 +--- 4 files changed, 5 insertions(+), 6 deletions(-) diff --git a/src/llmq/context.cpp b/src/llmq/context.cpp index 94da64087c..31857000d5 100644 --- a/src/llmq/context.cpp +++ b/src/llmq/context.cpp @@ -33,7 +33,7 @@ LLMQContext::LLMQContext(ChainstateManager& chainman, CConnman& connman, CDeterm qman{std::make_unique(*bls_worker, chainman.ActiveChainstate(), connman, dmnman, *qdkgsman, evo_db, *quorum_block_processor, mn_activeman, mn_sync, sporkman, unit_tests, wipe)}, - sigman{std::make_unique(connman, mn_activeman, chainman.ActiveChainstate(), *qman, peerman, + sigman{std::make_unique(mn_activeman, chainman.ActiveChainstate(), *qman, peerman, unit_tests, wipe)}, shareman{std::make_unique(connman, *sigman, mn_activeman, *qman, sporkman, peerman)}, clhandler{[&]() -> llmq::CChainLocksHandler* const { diff --git a/src/llmq/instantsend.h b/src/llmq/instantsend.h index 5f8f9e18bd..c0a27d7494 100644 --- a/src/llmq/instantsend.h +++ b/src/llmq/instantsend.h @@ -22,6 +22,7 @@ class CBlockIndex; class CChainState; +class CConnman; class CDBWrapper; class CMasternodeSync; class CSporkManager; diff --git a/src/llmq/signing.cpp b/src/llmq/signing.cpp index 4258eecc83..9aa5a72ec8 100644 --- a/src/llmq/signing.cpp +++ b/src/llmq/signing.cpp @@ -348,9 +348,9 @@ void CRecoveredSigsDb::CleanupOldVotes(int64_t maxAge) ////////////////// -CSigningManager::CSigningManager(CConnman& _connman, const CActiveMasternodeManager* const mn_activeman, const CChainState& chainstate, +CSigningManager::CSigningManager(const CActiveMasternodeManager* const mn_activeman, const CChainState& chainstate, const CQuorumManager& _qman, const std::unique_ptr& peerman, bool fMemory, bool fWipe) : - db(fMemory, fWipe), connman(_connman), m_mn_activeman(mn_activeman), m_chainstate(chainstate), qman(_qman), m_peerman(peerman) + db(fMemory, fWipe), m_mn_activeman(mn_activeman), m_chainstate(chainstate), qman(_qman), m_peerman(peerman) { } diff --git a/src/llmq/signing.h b/src/llmq/signing.h index e3519cb3ab..e044c51bf6 100644 --- a/src/llmq/signing.h +++ b/src/llmq/signing.h @@ -19,7 +19,6 @@ class CActiveMasternodeManager; class CChainState; -class CConnman; class CDataStream; class CDBBatch; class CDBWrapper; @@ -160,7 +159,6 @@ class CSigningManager private: CRecoveredSigsDb db; - CConnman& connman; const CActiveMasternodeManager* const m_mn_activeman; const CChainState& m_chainstate; const CQuorumManager& qman; @@ -179,7 +177,7 @@ class CSigningManager std::vector recoveredSigsListeners GUARDED_BY(cs_listeners); public: - CSigningManager(CConnman& _connman, const CActiveMasternodeManager* const mn_activeman, const CChainState& chainstate, + CSigningManager(const CActiveMasternodeManager* const mn_activeman, const CChainState& chainstate, const CQuorumManager& _qman, const std::unique_ptr& peerman, bool fMemory, bool fWipe); bool AlreadyHave(const CInv& inv) const; From 87c31ad67a92f738e317f81ef9873a8fb80028f7 Mon Sep 17 00:00:00 2001 From: UdjinM6 Date: Sat, 23 Nov 2024 01:27:04 +0300 Subject: [PATCH 11/24] Update doc/release-process.md Co-authored-by: PastaPastaPasta <6443210+PastaPastaPasta@users.noreply.github.com> --- doc/release-process.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/doc/release-process.md b/doc/release-process.md index 70f2b79a69..6089e43eab 100644 --- a/doc/release-process.md +++ b/doc/release-process.md @@ -97,7 +97,7 @@ Follow the relevant Guix README.md sections: - [Building](/contrib/guix/README.md#building) - [Attesting to build outputs](/contrib/guix/README.md#attesting-to-build-outputs) -_Note: we build releases for some supported HOSTs only so either provide correct `HOSTS` variable or run `./contrib/containers/guix/scripts/guix-start` instead of `./contrib/guix/guix-build` when building binaries_ +_Note: we ship releases for only some supported HOSTs so consider providing limited `HOSTS` variable or run `./contrib/containers/guix/scripts/guix-start` instead of `./contrib/guix/guix-build` when building binaries for quicker builds that exclude the supported but not shipped HOSTs_ ### Verify other builders' signatures to your own. (Optional) From dafa7363a38f6ebe445461ff7d8a707f867bbc82 Mon Sep 17 00:00:00 2001 From: pasta Date: Fri, 22 Nov 2024 15:45:16 -0600 Subject: [PATCH 12/24] fix: respect SENDDSQUEUE message, move DSQ relay into net processing / peerman in 6148, I broke the functionality where a peer must opt in / opt out of DSQUEUE messages. This was mostly ok, and not immediately detected, as with this bug, simply everyone would receive DSQ messages over inventory (or classically, old proto versions were not affected by this bug). But this still would result in quite a bit of wasted bandwidth for peers which may not care about DSQ at all. This commit should restore the prior functionality, where a node should send the SENDDSQUEUE message if they wish to receive DSQs. Once they've sent that, depending on their protocol version, they will either have the messages pushed to them as available, or on modern protocols, they will thereafter receive DSQs over the inventory system. NOTE: I also refactor the code in this commit, moving some network proccessing into.... wait for it... net_processing.cpp! This allowed us to remove some dependencies in coinjoin.h. DSQ messages are now relayed to peers by calling peer_manager.RelayDSQ --- src/coinjoin/client.cpp | 2 +- src/coinjoin/client.h | 1 + src/coinjoin/coinjoin.cpp | 14 ------------ src/coinjoin/coinjoin.h | 4 ---- src/coinjoin/server.cpp | 6 ++--- src/coinjoin/server.h | 1 + src/net_processing.cpp | 46 ++++++++++++++++++++++++++++++++++++++- src/net_processing.h | 4 ++++ 8 files changed, 55 insertions(+), 23 deletions(-) diff --git a/src/coinjoin/client.cpp b/src/coinjoin/client.cpp index 4c15f98f4a..9804b1be5b 100644 --- a/src/coinjoin/client.cpp +++ b/src/coinjoin/client.cpp @@ -132,7 +132,7 @@ PeerMsgRet CCoinJoinClientQueueManager::ProcessDSQueue(const CNode& peer, CDataS WITH_LOCK(cs_vecqueue, vecCoinJoinQueue.push_back(dsq)); } } // cs_ProcessDSQueue - dsq.Relay(connman, *peerman); + peerman->RelayDSQ(dsq); return {}; } diff --git a/src/coinjoin/client.h b/src/coinjoin/client.h index c4e22b7123..17239b9a71 100644 --- a/src/coinjoin/client.h +++ b/src/coinjoin/client.h @@ -28,6 +28,7 @@ class CMasternodeSync; class CNode; class CoinJoinWalletManager; class CTxMemPool; +class PeerManager; class UniValue; diff --git a/src/coinjoin/coinjoin.cpp b/src/coinjoin/coinjoin.cpp index 338b4cf054..74fc644a70 100644 --- a/src/coinjoin/coinjoin.cpp +++ b/src/coinjoin/coinjoin.cpp @@ -14,7 +14,6 @@ #include #include #include -#include #include #include #include @@ -71,19 +70,6 @@ bool CCoinJoinQueue::CheckSignature(const CBLSPublicKey& blsPubKey) const return true; } -bool CCoinJoinQueue::Relay(CConnman& connman, PeerManager& peerman) -{ - CInv inv(MSG_DSQ, GetHash()); - peerman.RelayInv(inv, DSQ_INV_VERSION); - connman.ForEachNode([&connman, this](CNode* pnode) { - CNetMsgMaker msgMaker(pnode->GetCommonVersion()); - if (pnode->fSendDSQueue && pnode->nVersion < DSQ_INV_VERSION) { - connman.PushMessage(pnode, msgMaker.Make(NetMsgType::DSQUEUE, (*this))); - } - }); - return true; -} - bool CCoinJoinQueue::IsTimeOutOfBounds(int64_t current_time) const { return current_time - nTime > COINJOIN_QUEUE_TIMEOUT || diff --git a/src/coinjoin/coinjoin.h b/src/coinjoin/coinjoin.h index 5680b8abc2..68e2f40c05 100644 --- a/src/coinjoin/coinjoin.h +++ b/src/coinjoin/coinjoin.h @@ -24,14 +24,12 @@ class CActiveMasternodeManager; class CChainState; -class CConnman; class CBLSPublicKey; class CBlockIndex; class ChainstateManager; class CMasternodeSync; class CTxMemPool; class TxValidationState; -class PeerManager; namespace llmq { class CChainLocksHandler; @@ -221,8 +219,6 @@ class CCoinJoinQueue /// Check if we have a valid Masternode address [[nodiscard]] bool CheckSignature(const CBLSPublicKey& blsPubKey) const; - bool Relay(CConnman& connman, PeerManager& peerman); - /// Check if a queue is too old or too far into the future [[nodiscard]] bool IsTimeOutOfBounds(int64_t current_time = GetAdjustedTime()) const; diff --git a/src/coinjoin/server.cpp b/src/coinjoin/server.cpp index 856cf5fc7e..bb65990dd9 100644 --- a/src/coinjoin/server.cpp +++ b/src/coinjoin/server.cpp @@ -186,7 +186,7 @@ PeerMsgRet CCoinJoinServer::ProcessDSQUEUE(const CNode& peer, CDataStream& vRecv TRY_LOCK(cs_vecqueue, lockRecv); if (!lockRecv) return {}; vecCoinJoinQueue.push_back(dsq); - dsq.Relay(connman, *m_peerman); + m_peerman->RelayDSQ(dsq); } return {}; } @@ -519,7 +519,7 @@ void CCoinJoinServer::CheckForCompleteQueue() LogPrint(BCLog::COINJOIN, "CCoinJoinServer::CheckForCompleteQueue -- queue is ready, signing and relaying (%s) " /* Continued */ "with %d participants\n", dsq.ToString(), vecSessionCollaterals.size()); dsq.Sign(*m_mn_activeman); - dsq.Relay(connman, *m_peerman); + m_peerman->RelayDSQ(dsq); } } @@ -732,7 +732,7 @@ bool CCoinJoinServer::CreateNewSession(const CCoinJoinAccept& dsa, PoolMessage& GetAdjustedTime(), false); LogPrint(BCLog::COINJOIN, "CCoinJoinServer::CreateNewSession -- signing and relaying new queue: %s\n", dsq.ToString()); dsq.Sign(*m_mn_activeman); - dsq.Relay(connman, *m_peerman); + m_peerman->RelayDSQ(dsq); LOCK(cs_vecqueue); vecCoinJoinQueue.push_back(dsq); } diff --git a/src/coinjoin/server.h b/src/coinjoin/server.h index e7f3a2340b..c33e98fbf8 100644 --- a/src/coinjoin/server.h +++ b/src/coinjoin/server.h @@ -11,6 +11,7 @@ class CActiveMasternodeManager; class CCoinJoinServer; +class CConnman; class CDataStream; class CDeterministicMNManager; class CDSTXManager; diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 7a8677e0e0..d6ebc6bed7 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -368,6 +368,15 @@ struct Peer { /** Whether the peer has signaled support for receiving ADDRv2 (BIP155) * messages, indicating a preference to receive ADDRv2 instead of ADDR ones. */ std::atomic_bool m_wants_addrv2{false}; + + enum class WantsDSQ { + NONE, // Peer doesn't want DSQs + INV, // Peer will be notified of DSQs over Inventory System (see: DSQ_INV_VERSION) + ALL, // Peer will be notified of all DSQs, by simply sending them the DSQ + }; + + std::atomic m_wants_dsq{WantsDSQ::NONE}; + /** Whether this peer has already sent us a getaddr message. */ bool m_getaddr_recvd GUARDED_BY(NetEventsInterface::g_msgproc_mutex){false}; /** Number of addresses that can be processed from this peer. Start at 1 to @@ -610,6 +619,7 @@ class PeerManagerImpl final : public PeerManager void RelayInvFiltered(CInv &inv, const uint256 &relatedTxHash, const int minProtoVersion) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void RelayTransaction(const uint256& txid) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void RelayRecoveredSig(const uint256& sigHash) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); + void RelayDSQ(const CCoinJoinQueue& queue) override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void SetBestHeight(int height) override { m_best_height = height; }; void Misbehaving(const NodeId pnode, const int howmuch, const std::string& message = "") override EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex); void ProcessMessage(CNode& pfrom, const std::string& msg_type, CDataStream& vRecv, @@ -2279,6 +2289,34 @@ void PeerManagerImpl::RelayInv(CInv &inv, const int minProtoVersion) }); } +void PeerManagerImpl::RelayDSQ(const CCoinJoinQueue& queue) +{ + CInv inv{MSG_DSQ, queue.GetHash()}; + std::vector nodes_send_all; + { + LOCK(m_peer_mutex); + for (const auto& [nodeid, peer] : m_peer_map) { + switch (peer->m_wants_dsq) { + case Peer::WantsDSQ::NONE: + break; + case Peer::WantsDSQ::INV: + PushInv(*peer, inv); + break; + case Peer::WantsDSQ::ALL: + nodes_send_all.push_back(nodeid); + break; + } + } + } + for (auto nodeId : nodes_send_all) { + m_connman.ForNode(nodeId, [&](CNode* pnode) -> bool { + CNetMsgMaker msgMaker(pnode->GetCommonVersion()); + m_connman.PushMessage(pnode, msgMaker.Make(NetMsgType::DSQUEUE, queue)); + return true; + }); + } +} + void PeerManagerImpl::RelayInvFiltered(CInv &inv, const CTransaction& relatedTx, const int minProtoVersion) { // TODO: Migrate to iteration through m_peer_map @@ -3954,7 +3992,13 @@ void PeerManagerImpl::ProcessMessage( { bool b; vRecv >> b; - pfrom.fSendDSQueue = b; + if (!b) { + peer->m_wants_dsq = Peer::WantsDSQ::NONE; + } else if (pfrom.GetCommonVersion() < DSQ_INV_VERSION) { + peer->m_wants_dsq = Peer::WantsDSQ::ALL; + } else { + peer->m_wants_dsq = Peer::WantsDSQ::INV; + } return; } diff --git a/src/net_processing.h b/src/net_processing.h index 99144d2335..93506873d7 100644 --- a/src/net_processing.h +++ b/src/net_processing.h @@ -16,6 +16,7 @@ class CActiveMasternodeManager; class AddrMan; class CTxMemPool; +class CCoinJoinQueue; class CDeterministicMNManager; class CMasternodeMetaMan; class CMasternodeSync; @@ -93,6 +94,9 @@ class PeerManager : public CValidationInterface, public NetEventsInterface /** Broadcast inventory message to a specific peer. */ virtual void PushInventory(NodeId nodeid, const CInv& inv) = 0; + /** Relay DSQ based on peer preference */ + virtual void RelayDSQ(const CCoinJoinQueue& queue) = 0; + /** Relay inventories to all peers */ virtual void RelayInv(CInv &inv, const int minProtoVersion = MIN_PEER_PROTO_VERSION) = 0; virtual void RelayInvFiltered(CInv &inv, const CTransaction &relatedTx, From 0e01d5b5f38104f1db3c9a1e2aca87c209c35a85 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 15:11:52 +0000 Subject: [PATCH 13/24] partial bitcoin#22766: Clarify and disable unused ArgsManager flags excludes: - c5d7e34bd9a4ad752c5ec88032420e2e90ab17ab --- src/util/system.cpp | 102 +++++++++++++++++++++++--------------------- src/util/system.h | 16 ++++--- 2 files changed, 64 insertions(+), 54 deletions(-) diff --git a/src/util/system.cpp b/src/util/system.cpp index 6834189aa6..112dbb9e09 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -79,6 +79,7 @@ #include #include #include +#include #include #include #include @@ -205,60 +206,65 @@ 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. - * - * 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. + * Parse "name", "section.name", "noname", "section.noname" settings keys. * - * 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); - // Double negatives like -nofoo=0 are supported (but discouraged) - if (!InterpretBool(value)) { - LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key, value); - return true; - } - return false; + result.negated = true; } - return value; + result.name = key; + return result; } /** - * Check settings value validity according to flags. + * 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 * - * 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 + * @return parsed settings value if it is valid, otherwise nullopt accompanied + * by a descriptive error string */ -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); +static std::optional 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.name, value); + return true; + } return false; } - return true; + return value; } // Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to @@ -366,21 +372,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 flags = GetArgFlags('-' + key); + KeyInfo keyinfo = InterpretKey(key); + std::optional 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 value = InterpretValue(keyinfo, val, *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 @@ -580,10 +586,8 @@ bool ArgsManager::ReadSettingsFile(std::vector* 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); } } @@ -680,6 +684,7 @@ void ArgsManager::AddArg(const std::string& name, const std::string& help, unsig LOCK(cs_args); std::map& 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 @@ -926,15 +931,14 @@ bool ArgsManager::ReadConfigStream(std::istream& stream, const std::string& file return false; } for (const std::pair& option : options) { - std::string section; - std::string key = option.first; - util::SettingsValue value = InterpretOption(section, key, option.second); - std::optional flags = GetArgFlags('-' + key); + KeyInfo key = InterpretKey(option.first); + std::optional flags = GetArgFlags('-' + key.name); if (flags) { - if (!CheckValid(key, value, *flags, error)) { + std::optional 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); diff --git a/src/util/system.h b/src/util/system.h index b99a5f9a1e..376b6ca90b 100644 --- a/src/util/system.h +++ b/src/util/system.h @@ -178,12 +178,18 @@ 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 + DEBUG_ONLY = 0x100, /* Some options would cause cross-contamination if values for * mainnet were used while running on regtest/testnet (or vice-versa). From d3e837ad22db389da3f57da1f63e7df74a5f1184 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Tue, 12 Apr 2022 03:00:28 -0400 Subject: [PATCH 14/24] merge bitcoin#24830: Allow -proxy="" setting values --- src/init.cpp | 6 +----- src/util/system.cpp | 18 +++++++++++------- src/util/system.h | 1 + test/functional/feature_config_args.py | 2 +- 4 files changed, 14 insertions(+), 13 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index efb29eae5d..f82252d439 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -583,7 +583,7 @@ void SetupServerArgs(ArgsManager& argsman) argsman.AddArg("-peertimeout=", 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=", strprintf("Listen for connections on . 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=", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION); + argsman.AddArg("-proxy=", "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=", "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=", "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); @@ -1337,10 +1337,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= or -proxy=.")); - } - if (args.GetBoolArg("-reindex-chainstate", false)) { // indexes that must be deactivated to prevent index corruption, see #24630 if (args.GetBoolArg("-coinstatsindex", DEFAULT_COINSTATSINDEX)) { diff --git a/src/util/system.cpp b/src/util/system.cpp index 112dbb9e09..3277d52b41 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -248,7 +248,7 @@ KeyInfo InterpretKey(std::string key) * @return parsed settings value if it is valid, otherwise nullopt accompanied * by a descriptive error string */ -static std::optional InterpretValue(const KeyInfo& key, const std::string& value, +static std::optional InterpretValue(const KeyInfo& key, const std::string* value, unsigned int flags, std::string& error) { // Return negated settings as false values. @@ -258,13 +258,17 @@ static std::optional InterpretValue(const KeyInfo& key, con 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.name, value); + if (value && !InterpretBool(*value)) { + LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key.name, *value); return true; } return false; } - return value; + 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 value ? *value : ""; } // Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to @@ -337,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 val; size_t is_index = key.find('='); if (is_index != std::string::npos) { val = key.substr(is_index + 1); @@ -383,7 +387,7 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin return false; } - std::optional value = InterpretValue(keyinfo, val, *flags, error); + std::optional value = InterpretValue(keyinfo, val ? &*val : nullptr, *flags, error); if (!value) return false; m_settings.command_line_options[keyinfo.name].push_back(*value); @@ -934,7 +938,7 @@ bool ArgsManager::ReadConfigStream(std::istream& stream, const std::string& file KeyInfo key = InterpretKey(option.first); std::optional flags = GetArgFlags('-' + key.name); if (flags) { - std::optional value = InterpretValue(key, option.second, *flags, error); + std::optional value = InterpretValue(key, &option.second, *flags, error); if (!value) { return false; } diff --git a/src/util/system.h b/src/util/system.h index 376b6ca90b..f4e17d9195 100644 --- a/src/util/system.h +++ b/src/util/system.h @@ -189,6 +189,7 @@ class ArgsManager 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 diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index 666aee897e..cba1d17cb5 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -84,7 +84,7 @@ def test_config_file_parser(self): def test_invalid_command_line_options(self): self.nodes[0].assert_start_raises_init_error( - expected_msg='Error: No proxy server specified. Use -proxy= or -proxy=.', + expected_msg='Error: Error parsing command line arguments: Can not set -proxy with no value. Please specify value with -proxy=value.', extra_args=['-proxy'], ) From 88592f30a30658908b954f0a182dbbd1bb5c7cf3 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 17:14:18 +0000 Subject: [PATCH 15/24] merge bitcoin#24464: Add severity level to logs --- src/logging.cpp | 141 ++++++++++++++++++++++++++++++++++++- src/logging.h | 35 ++++++--- src/net.cpp | 30 ++++---- src/test/logging_tests.cpp | 120 +++++++++++++++++++++++++++++++ 4 files changed, 300 insertions(+), 26 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 5ac21e344b..68516b20f9 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -188,7 +188,7 @@ const CLogCategoryDesc LogCategories[] = bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (str == "") { + if (str.empty()) { flag = BCLog::ALL; return true; } @@ -201,6 +201,123 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } +std::string LogLevelToStr(BCLog::Level level) +{ + switch (level) { + case BCLog::Level::None: + return "none"; + case BCLog::Level::Debug: + return "debug"; + case BCLog::Level::Info: + return "info"; + case BCLog::Level::Warning: + return "warning"; + case BCLog::Level::Error: + return "error"; + } + assert(false); +} + +std::string LogCategoryToStr(BCLog::LogFlags category) +{ + // Each log category string representation should sync with LogCategories + switch (category) { + case BCLog::LogFlags::NONE: + return "none"; + 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); +} + std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) const { // Sort log categories by alphabetical order. @@ -268,11 +385,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, const int source_line, const BCLog::LogFlags category, const 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 + "] "); } diff --git a/src/logging.h b/src/logging.h index c88bae4957..3e085db5fb 100644 --- a/src/logging.h +++ b/src/logging.h @@ -91,6 +91,13 @@ namespace BCLog { ALL = ~(uint64_t)0, }; + enum class Level { + Debug = 0, + None = 1, + Info = 2, + Warning = 3, + Error = 4, + }; class Logger { @@ -130,7 +137,7 @@ namespace BCLog { std::atomic 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, const int source_line, const BCLog::LogFlags category, const BCLog::Level level); /** Returns whether logs will be written to any output */ bool Enabled() const @@ -211,7 +218,7 @@ std::string SafeStringFormat(const std::string& fmt, const Args&... args) // peer can fill up a user's disk with debug.log entries. template -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; @@ -221,19 +228,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))) { \ + LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ + } \ + } while (0) + +#define LogPrintLevel(level, category, ...) \ + do { \ + if (LogAcceptCategory((category))) { \ + LogPrintLevel_(category, level, __VA_ARGS__); \ + } \ } while (0) #endif // BITCOIN_LOGGING_H diff --git a/src/net.cpp b/src/net.cpp index 3b54c7422c..49fa69941d 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -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::Level::Warning, BCLog::NET, "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::Level::Debug, 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); } 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::Level::Debug, BCLog::NET, "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::Level::Warning, BCLog::NET, "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::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } std::unique_ptr 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::Level::Error, BCLog::NET, "%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::Level::Error, BCLog::NET, "%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::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 84ddbc50c6..2ce9060074 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,13 +5,55 @@ #include #include #include +#include #include +#include +#include +#include +#include #include BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) +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; + + 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} + { + 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; + LogInstance().m_log_sourcelocations = true; + } + + ~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; + } +}; + BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); @@ -30,4 +72,82 @@ 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) +{ + 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 log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector 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) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + + LogPrintf("foo5: %s\n", "bar5"); + LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7"); + LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8"); + LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9"); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "foo10: %s\n", "bar10"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector 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) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + const auto concated_categery_names = LogInstance().LogCategoriesString(); + std::vector> expected_category_names; + const auto category_names = SplitString(concated_categery_names, ','); + for (const auto& category_name : category_names) { + BCLog::LogFlags category = BCLog::NONE; + const auto trimmed_category_name = TrimString(category_name); + BOOST_TEST(GetLogCategory(category, trimmed_category_name)); + expected_category_names.emplace_back(category, trimmed_category_name); + } + + std::vector 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 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_AUTO_TEST_SUITE_END() From ff6304f5f3a439de12d3c0d25cc10de63286e05f Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 4 Apr 2022 13:10:10 +0200 Subject: [PATCH 16/24] merge bitcoin#24757: add `DEBUG_LOCKCONTENTION` to `--enable-debug` and CI --- ci/test/00_setup_env_native_tsan.sh | 2 +- configure.ac | 1 + doc/developer-notes.md | 6 ++++-- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/ci/test/00_setup_env_native_tsan.sh b/ci/test/00_setup_env_native_tsan.sh index 633304580f..add809a28c 100755 --- a/ci/test/00_setup_env_native_tsan.sh +++ b/ci/test/00_setup_env_native_tsan.sh @@ -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 diff --git a/configure.ac b/configure.ac index 55fae0a021..816dc964e9 100644 --- a/configure.ac +++ b/configure.ac @@ -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 diff --git a/doc/developer-notes.md b/doc/developer-notes.md index f4a7095392..7226447c51 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -419,8 +419,10 @@ 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. -To enable it, run configure with `-DDEBUG_LOCKCONTENTION` added to your -CPPFLAGS, e.g. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run dashd. +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. From 7697b73257c4a8f4e92e224538347fd32f565834 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 11 Nov 2024 19:22:46 +0000 Subject: [PATCH 17/24] revert dash#2794: Disable logging of libevent debug messages reverts: - a1e4ac21fd3a97332c5d270a01babd4e278fc300 --- src/httpserver.cpp | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index 951e99f999..081c6898e4 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -377,9 +377,8 @@ 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); + else + LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg); } bool InitHTTPServer() From b046e091c91c8b90f7f1370203d4f1d2f85c4537 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 16:31:08 +0000 Subject: [PATCH 18/24] merge bitcoin#25202: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order Co-authored-by: UdjinM6 --- src/batchedlogger.cpp | 19 +++++++++++-------- src/batchedlogger.h | 16 ++++++++++------ src/dbwrapper.cpp | 6 +++--- src/httpserver.cpp | 20 ++++++++++++++++---- src/llmq/commitment.cpp | 6 +++--- src/llmq/dkgsession.cpp | 6 +++--- src/llmq/instantsend.cpp | 4 ++-- src/llmq/signing_shares.cpp | 14 +++++++++----- src/llmq/utils.cpp | 13 +++++++------ src/logging.h | 15 ++++++++++----- src/net.cpp | 16 ++++++++-------- src/net_processing.cpp | 2 +- src/qt/coincontroldialog.cpp | 2 +- src/test/logging_tests.cpp | 8 ++++---- src/timedata.cpp | 2 +- src/wallet/wallet.cpp | 2 +- src/wallet/wallet.h | 10 +++++----- 17 files changed, 95 insertions(+), 66 deletions(-) diff --git a/src/batchedlogger.cpp b/src/batchedlogger.cpp index a4204e86f4..0006ac51da 100644 --- a/src/batchedlogger.cpp +++ b/src/batchedlogger.cpp @@ -4,11 +4,14 @@ #include -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(); } diff --git a/src/batchedlogger.h b/src/batchedlogger.h index c24ca84fe5..6f2b13bf9b 100644 --- a/src/batchedlogger.h +++ b/src/batchedlogger.h @@ -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 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(); diff --git a/src/dbwrapper.cpp b/src/dbwrapper.cpp index 1c6efe7595..193f5f9258 100644 --- a/src/dbwrapper.cpp +++ b/src/dbwrapper.cpp @@ -20,7 +20,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger { // 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 @@ class CBitcoinLevelDBLogger : public leveldb::Logger { 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; diff --git a/src/httpserver.cpp b/src/httpserver.cpp index 081c6898e4..504f3cf642 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -375,10 +375,22 @@ static void HTTPWorkQueueRun(WorkQueue* 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); - 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() diff --git a/src/llmq/commitment.cpp b/src/llmq/commitment.cpp index ea131b113c..05607c34a6 100644 --- a/src/llmq/commitment.cpp +++ b/src/llmq/commitment.cpp @@ -82,7 +82,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_nullproTxHash.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]; diff --git a/src/llmq/dkgsession.cpp b/src/llmq/dkgsession.cpp index d59e7defee..1c95881efe 100644 --- a/src/llmq/dkgsession.cpp +++ b/src/llmq/dkgsession.cpp @@ -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) << " | "; diff --git a/src/llmq/instantsend.cpp b/src/llmq/instantsend.cpp index c50fa939e0..e175009bb8 100644 --- a/src/llmq/instantsend.cpp +++ b/src/llmq/instantsend.cpp @@ -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; } diff --git a/src/llmq/signing_shares.cpp b/src/llmq/signing_shares.cpp index baa31593d2..f3e53442e3 100644 --- a/src/llmq/signing_shares.cpp +++ b/src/llmq/signing_shares.cpp @@ -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); } diff --git a/src/llmq/utils.cpp b/src/llmq/utils.cpp index e3cc8ac240..59147750ee 100644 --- a/src/llmq/utils.cpp +++ b/src/llmq/utils.cpp @@ -216,7 +216,7 @@ std::vector> 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> 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> 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> 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); diff --git a/src/logging.h b/src/logging.h index 3e085db5fb..69d07b5e09 100644 --- a/src/logging.h +++ b/src/logging.h @@ -191,9 +191,14 @@ 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) { + // Log messages at Warning and Error level unconditionally, so that + // important troubleshooting information doesn't get lost. + if (level >= BCLog::Level::Warning) { + return true; + } return LogInstance().WillLogCategory(category); } @@ -241,14 +246,14 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st // evaluating arguments when logging for the category is not enabled. #define LogPrint(category, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), BCLog::Level::Debug)) { \ LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ } \ } while (0) -#define LogPrintLevel(level, category, ...) \ +#define LogPrintLevel(category, level, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), (level))) { \ LogPrintLevel_(category, level, __VA_ARGS__); \ } \ } while (0) diff --git a/src/net.cpp b/src/net.cpp index 49fa69941d..ce10298659 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -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 { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n"); } } return addr_bind; @@ -509,12 +509,12 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo /// debug print if (fLogIPs) { - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n", + 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 { - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection lastseen=%.1fhrs\n", + 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); } @@ -1963,7 +1963,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket, CMasternodeSy } if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "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()); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } std::unique_ptr sock = CreateSock(addrBind); if (!sock) { strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + 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)); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } LogPrintf("Bound to %s\n", addrBind.ToStringAddrPort()); @@ -4119,7 +4119,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (sock->Listen(SOMAXCONN) == SOCKET_ERROR) { strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 8676ad3371..e66e7e11ee 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3662,7 +3662,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), diff --git a/src/qt/coincontroldialog.cpp b/src/qt/coincontroldialog.cpp index 4ada490a7a..4c89d8314e 100644 --- a/src/qt/coincontroldialog.cpp +++ b/src/qt/coincontroldialog.cpp @@ -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")); diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 2ce9060074..1f86cc33fd 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -99,10 +99,10 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) LogPrintf("foo5: %s\n", "bar5"); LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7"); - LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8"); - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9"); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "foo10: %s\n", "bar10"); + 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 log_lines; for (std::string log; std::getline(file, log);) { diff --git a/src/timedata.cpp b/src/timedata.cpp index bf0427cb95..a0b8c33e7a 100644 --- a/src/timedata.cpp +++ b/src/timedata.cpp @@ -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); diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 3449332970..346a2ec199 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -3432,7 +3432,7 @@ std::vector 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); diff --git a/src/wallet/wallet.h b/src/wallet/wallet.h index dd0238595b..7b41966216 100644 --- a/src/wallet/wallet.h +++ b/src/wallet/wallet.h @@ -150,11 +150,11 @@ extern const std::map 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 From 026409e4ffcc82b16f0c7f6d96ebf8b7ef1f5ab9 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 12:39:12 +0000 Subject: [PATCH 19/24] merge bitcoin#25217: update lint-logs.py to detect LogPrintLevel, mention WalletLogPrintf --- test/lint/lint-logs.sh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/lint/lint-logs.sh b/test/lint/lint-logs.sh index 7972aa9fe8..85f94a1cdf 100755 --- a/test/lint/lint-logs.sh +++ b/test/lint/lint-logs.sh @@ -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 From 21470fdeb383ba4ce1691049417ae49be1f2b66b Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Tue, 7 Jun 2022 15:39:29 +0200 Subject: [PATCH 20/24] merge bitcoin#25292: Add LogPrintLevel to lint-format-strings, drop LogPrint-vs-LogPrintf section in dev notes --- doc/developer-notes.md | 5 ----- test/lint/lint-format-strings.sh | 1 + 2 files changed, 1 insertion(+), 5 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 7226447c51..8fe61e0f31 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -862,11 +862,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 diff --git a/test/lint/lint-format-strings.sh b/test/lint/lint-format-strings.sh index ca4bc89258..21586d1cee 100755 --- a/test/lint/lint-format-strings.sh +++ b/test/lint/lint-format-strings.sh @@ -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" From 52a12639892de407ee8895d8c2c017dd4ebc3d77 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 16:28:40 +0000 Subject: [PATCH 21/24] merge bitcoin#25614: Severity-based logging, step 2 --- doc/developer-notes.md | 6 +- src/init.cpp | 1 + src/init/common.cpp | 28 ++++- src/init/common.h | 1 + src/logging.cpp | 83 +++++++++++-- src/logging.h | 55 +++++++-- src/test/i2p_tests.cpp | 4 + src/test/logging_tests.cpp | 125 ++++++++++++++++++-- src/test/util/setup_common.cpp | 1 + test/functional/test_framework/test_node.py | 2 + 10 files changed, 270 insertions(+), 36 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 8fe61e0f31..1f3aef04a6 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -390,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. diff --git a/src/init.cpp b/src/init.cpp index f82252d439..002818135b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -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); diff --git a/src/init/common.cpp b/src/init/common.cpp index 8be70f7caf..ecf1095b90 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -13,6 +13,7 @@ #include #include #include +#include #include #include #include @@ -57,11 +58,12 @@ bool SanityChecks() void AddLoggingArgs(ArgsManager& argsman) { argsman.AddArg("-debuglogfile=", 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=", "Output debugging information (default: -nodebug, supplying is optional). " - "If is not supplied or if = 1, output all debugging information. can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.", + argsman.AddArg("-debug=", "Output debug and trace logging (default: -nodebug, supplying is optional). " + "If is not supplied or if = 1, output all debug and trace logging. can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); - argsman.AddArg("-debugexclude=", "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=", "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=|:", 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 : is supplied, the setting will override the global one and may be specified multiple times to set multiple category-specific levels. 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= + 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=: + 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=:. Valid categories: %s. Valid loglevels: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString())); + } + } + } + } +} + void SetLoggingCategories(const ArgsManager& args) { if (args.IsArgSet("-debug")) { diff --git a/src/init/common.h b/src/init/common.h index fc4bc1b280..bcd46f41d3 100644 --- a/src/init/common.h +++ b/src/init/common.h @@ -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 diff --git a/src/logging.cpp b/src/logging.cpp index 68516b20f9..ab59bd5599 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -5,15 +5,17 @@ #include #include +#include #include #include -#include #include #include #include +#include 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"}, @@ -201,11 +216,11 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } -std::string LogLevelToStr(BCLog::Level level) +std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const { switch (level) { - case BCLog::Level::None: - return "none"; + case BCLog::Level::Trace: + return "trace"; case BCLog::Level::Debug: return "debug"; case BCLog::Level::Info: @@ -214,6 +229,8 @@ std::string LogLevelToStr(BCLog::Level level) return "warning"; case BCLog::Level::Error: return "error"; + case BCLog::Level::None: + return ""; } assert(false); } @@ -223,7 +240,7 @@ std::string LogCategoryToStr(BCLog::LogFlags category) // Each log category string representation should sync with LogCategories switch (category) { case BCLog::LogFlags::NONE: - return "none"; + return ""; case BCLog::LogFlags::NET: return "net"; case BCLog::LogFlags::TOR: @@ -318,6 +335,25 @@ std::string LogCategoryToStr(BCLog::LogFlags category) assert(false); } +static std::optional 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 BCLog::Logger::LogCategoriesList(bool enabled_only) const { // Sort log categories by alphabetical order. @@ -338,6 +374,18 @@ std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) con return ret; } +/** Log severity levels that can be selected by the user. */ +static constexpr std::array 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{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); }); +} + std::string BCLog::Logger::LogTimestampStr(const std::string& str) { std::string strStamped; @@ -385,7 +433,7 @@ 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, const BCLog::LogFlags category, const BCLog::Level level) +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); @@ -494,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; +} diff --git a/src/logging.h b/src/logging.h index 69d07b5e09..a8d5453047 100644 --- a/src/logging.h +++ b/src/logging.h @@ -7,8 +7,8 @@ #define BITCOIN_LOGGING_H #include -#include #include +#include #include #include @@ -17,6 +17,7 @@ #include #include #include +#include #include static const bool DEFAULT_LOGTIMEMICROS = false; @@ -92,12 +93,14 @@ namespace BCLog { ALL = ~(uint64_t)0, }; enum class Level { - Debug = 0, - None = 1, - Info = 2, - Warning = 3, - Error = 4, + 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 { @@ -115,6 +118,13 @@ namespace BCLog { */ std::atomic_bool m_started_new_line{true}; + //! Category-specific log level. Overrides `m_log_level`. + std::unordered_map 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 m_log_level{DEFAULT_LOG_LEVEL}; + /** Log categories bitfield. */ std::atomic m_categories{0}; @@ -137,7 +147,7 @@ namespace BCLog { std::atomic 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, const BCLog::LogFlags category, const BCLog::Level level); + 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 @@ -168,6 +178,22 @@ namespace BCLog { void ShrinkDebugFile(); + std::unordered_map CategoryLevels() const + { + StdLockGuard scoped_lock(m_cs); + return m_category_log_levels; + } + void SetCategoryLogLevel(const std::unordered_map& 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); @@ -176,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 LogCategoriesList(bool enabled_only = false) const; /** Returns a string with the log categories in alphabetical order. */ @@ -184,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; }; @@ -194,12 +228,7 @@ BCLog::Logger& LogInstance(); /** Return true if log accepts specified category, at the specified level. */ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) { - // Log messages at Warning and Error level unconditionally, so that - // important troubleshooting information doesn't get lost. - if (level >= BCLog::Level::Warning) { - return true; - } - return LogInstance().WillLogCategory(category); + return LogInstance().WillLogCategoryLevel(category, level); } /** Return true if str parses as a log category and set the flag */ diff --git a/src/test/i2p_tests.cpp b/src/test/i2p_tests.cpp index 79b34931d3..95a0fb6a04 100644 --- a/src/test/i2p_tests.cpp +++ b/src/test/i2p_tests.cpp @@ -3,6 +3,7 @@ // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include +#include #include #include #include @@ -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() diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 1f86cc33fd..69257af721 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -2,6 +2,7 @@ // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. +#include #include #include #include @@ -10,6 +11,7 @@ #include #include #include +#include #include #include @@ -17,6 +19,12 @@ 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; @@ -25,6 +33,8 @@ struct LogSetup : public BasicTestingSetup { bool prev_log_timestamps; bool prev_log_threadnames; bool prev_log_sourcelocations; + std::unordered_map 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"}, @@ -32,14 +42,21 @@ struct LogSetup : public BasicTestingSetup { 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_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; - LogInstance().m_log_sourcelocations = true; + + // 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() @@ -51,6 +68,8 @@ struct LogSetup : public BasicTestingSetup { 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); } }; @@ -74,6 +93,7 @@ BOOST_AUTO_TEST_CASE(logging_timer) 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"); @@ -94,9 +114,6 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) { - // Prevent tests from failing when the line number of the following log calls changes. - LogInstance().m_log_sourcelocations = false; - LogPrintf("foo5: %s\n", "bar5"); LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7"); @@ -120,16 +137,14 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) { - // Prevent tests from failing when the line number of the following log calls changes. - LogInstance().m_log_sourcelocations = false; LogInstance().EnableCategory(BCLog::LogFlags::ALL); - const auto concated_categery_names = LogInstance().LogCategoriesString(); + const auto concatenated_category_names = LogInstance().LogCategoriesString(); std::vector> expected_category_names; - const auto category_names = SplitString(concated_categery_names, ','); + const auto category_names = SplitString(concatenated_category_names, ','); for (const auto& category_name : category_names) { - BCLog::LogFlags category = BCLog::NONE; + BCLog::LogFlags category; const auto trimmed_category_name = TrimString(category_name); - BOOST_TEST(GetLogCategory(category, trimmed_category_name)); + BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name)); expected_category_names.emplace_back(category, trimmed_category_name); } @@ -150,4 +165,92 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) 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 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 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() diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp index 487bb1bb56..25b355ef71 100644 --- a/src/test/util/setup_common.cpp +++ b/src/test/util/setup_common.cpp @@ -149,6 +149,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve "-logsourcelocations", "-logtimemicros", "-logthreadnames", + "-loglevel=trace", "-debug", "-debugexclude=libevent", "-debugexclude=leveldb", diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 0f2bd413eb..6863e72b40 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -125,6 +125,8 @@ def __init__(self, i, datadir, extra_args_from_options, *, chain, rpchost, timew 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. From 1621696a6f6b59fb584e9203e6806e935f507b80 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 13:26:16 +0000 Subject: [PATCH 22/24] log: restore `LogPrintLevel` messages from prior backports --- src/net_processing.cpp | 14 +++++++------- src/node/txreconciliation.cpp | 7 ++++--- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index e66e7e11ee..187d70c79c 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3763,19 +3763,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; } @@ -3784,7 +3784,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; } @@ -3797,16 +3797,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; } diff --git a/src/node/txreconciliation.cpp b/src/node/txreconciliation.cpp index 8d23c85a9a..03d4258a84 100644 --- a/src/node/txreconciliation.cpp +++ b/src/node/txreconciliation.cpp @@ -83,7 +83,7 @@ class TxReconciliationTracker::Impl 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 @@ class TxReconciliationTracker::Impl // 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 @@ class TxReconciliationTracker::Impl 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); } } From 5187ec0b690e3d1db23a76bd1a1a24d3bd65468b Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Fri, 1 Oct 2021 10:54:20 +0200 Subject: [PATCH 23/24] Merge bitcoin/bitcoin#23136: test: update fee rate assertion helper in the functional test framework b658d7d5c5339739dc19bf961d84186469a818d5 test: update assert_fee_amount() in test_framework/util.py (Jon Atack) Pull request description: Follow-up to 42e1b5d9797b65 (#12486). - update call to `round()` with our utility function `satoshi_round()` to avoid intermittent test failures - rename `fee_per_kB` to `feerate_BTC_kvB` for precision - store division result in `feerate_BTC_vB` Possibly resolves #19418. ACKs for top commit: meshcollider: utACK b658d7d5c5339739dc19bf961d84186469a818d5 Tree-SHA512: f124ded98c913f98782dc047a85a05d3fdf5f0585041fa81129be562138f6261ec1bd9ee2af89729028277e75b591b0a7ad50244016c2b2fa935c6e400523183 --- test/functional/test_framework/util.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py index 59a4d663cc..1d730feb8c 100644 --- a/test/functional/test_framework/util.py +++ b/test/functional/test_framework/util.py @@ -36,13 +36,14 @@ def assert_approx(v, vexp, vspan=0.00001): raise AssertionError("%s > [%s..%s]" % (str(v), str(vexp - vspan), str(vexp + vspan))) -def assert_fee_amount(fee, tx_size, fee_per_kB): - """Assert the fee was in range""" - target_fee = round(tx_size * fee_per_kB / 1000, 8) +def assert_fee_amount(fee, tx_size, feerate_DASH_kvB): + """Assert the fee is in range.""" + feerate_DASH_vB = feerate_DASH_kvB / 1000 + target_fee = satoshi_round(tx_size * feerate_DASH_vB) if fee < target_fee: raise AssertionError("Fee of %s DASH too low! (Should be %s DASH)" % (str(fee), str(target_fee))) # allow the wallet's estimation to be at most 2 bytes off - if fee > (tx_size + 2) * fee_per_kB / 1000: + if fee > (tx_size + 2) * feerate_DASH_vB: raise AssertionError("Fee of %s DASH too high! (Should be %s DASH)" % (str(fee), str(target_fee))) From 379aefab10f487676daec41d3871583b408bb166 Mon Sep 17 00:00:00 2001 From: laanwj <126646+laanwj@users.noreply.github.com> Date: Thu, 24 Feb 2022 12:34:33 +0100 Subject: [PATCH 24/24] Merge bitcoin/bitcoin#24434: Add missed word to error message ff33c5ae633191df94759a5f3deead43863cd8fd Add missed word to error message (Hennadii Stepanov) Pull request description: Reported by Transifex translator [mmazi](https://www.transifex.com/user/profile/mmazi/). ACKs for top commit: laanwj: ACK ff33c5ae633191df94759a5f3deead43863cd8fd Tree-SHA512: 487512956dbaa42a33057362fc438f45ded211493221646b23101784902e75e6d72ef5b5184f175362e0d821a8409badc58abab4e06e86d4934b064dc5bb7050 --- src/net.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/net.cpp b/src/net.cpp index 3b54c7422c..8d2f8746c1 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -4353,7 +4353,7 @@ bool CConnman::Start(CDeterministicMNManager& dmnman, CMasternodeMetaMan& mn_met if (connOptions.m_use_addrman_outgoing && !connOptions.m_specified_outgoing.empty()) { if (clientInterface) { clientInterface->ThreadSafeMessageBox( - _("Cannot provide specific connections and have addrman find outgoing connections at the same."), + _("Cannot provide specific connections and have addrman find outgoing connections at the same time."), "", CClientUIInterface::MSG_ERROR); } return false;