merge bitcoin#25202: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order

Co-authored-by: UdjinM6 <UdjinM6@users.noreply.github.com>
This commit is contained in:
Kittywhiskers Van Gogh 2024-11-20 16:31:08 +00:00
parent 7697b73257
commit b046e091c9
No known key found for this signature in database
GPG Key ID: 30CD0C065E5C4AAD
17 changed files with 95 additions and 66 deletions

View File

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

View File

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

View File

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

View File

@ -375,10 +375,22 @@ static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
/** libevent event log callback */
static void libevent_log_cb(int severity, const char *msg)
{
if (severity >= EVENT_LOG_WARN) // Log warn messages and higher without debug category
LogPrintf("libevent: %s\n", msg);
else
LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg);
BCLog::Level level;
switch (severity) {
case EVENT_LOG_DEBUG:
level = BCLog::Level::Debug;
break;
case EVENT_LOG_MSG:
level = BCLog::Level::Info;
break;
case EVENT_LOG_WARN:
level = BCLog::Level::Warning;
break;
default: // EVENT_LOG_ERR and others are mapped to error
level = BCLog::Level::Error;
break;
}
LogPrintLevel(BCLog::LIBEVENT, level, "%s\n", msg);
}
bool InitHTTPServer()

View File

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

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@ -481,7 +481,7 @@ static CAddress GetBindAddress(const Sock& sock)
if (!sock.GetSockName((struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) {
addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind);
} else {
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> 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;
}

View File

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

View File

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

View File

@ -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<std::string> log_lines;
for (std::string log; std::getline(file, log);) {

View File

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

View File

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

View File

@ -152,7 +152,7 @@ extern const std::map<uint64_t,std::string> WALLET_FLAG_CAVEATS;
// evaluating arguments when logging for the category is not enabled.
#define WalletCJLogPrint(wallet, ...) \
do { \
if (LogAcceptCategory(BCLog::COINJOIN)) { \
if (LogAcceptCategory(BCLog::COINJOIN, BCLog::Level::Debug)) { \
wallet.WalletLogPrintf(__VA_ARGS__); \
} \
} while (0)