Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

More granular debug #8484

Closed
wants to merge 1 commit into from
Closed

More granular debug #8484

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/init.cpp
View file
Open in desktop
Expand Up @@ -423,7 +423,7 @@ std::string HelpMessage(HelpMessageMode mode)
strUsage += HelpMessageOpt("-limitdescendantsize=<n>", strprintf("Do not accept transactions if any ancestor would have more than <n> kilobytes of in-mempool descendants (default: %u).", DEFAULT_DESCENDANT_SIZE_LIMIT));
strUsage += HelpMessageOpt("-bip9params=deployment:start:end", "Use given start/end times for specified BIP9 deployment (regtest-only)");
}
string debugCategories = "addrman, alert, bench, coindb, db, http, libevent, lock, mempool, mempoolrej, net, proxy, prune, rand, reindex, rpc, selectcoins, tor, zmq"; // Don't translate these and qt below
string debugCategories = "addrman, alert, bench, block, coindb, db, estimatefee, http, libevent, lock, mempool(,rej}, net{,2}, proxy, prune, rand, reindex, rpc, selectcoins, tx, tor, zmq"; // Don't translate these and qt below
if (mode == HMM_BITCOIN_QT)
debugCategories += ", qt";
strUsage += HelpMessageOpt("-debug=<category>", strprintf(_("Output debugging information (default: %u, supplying <category> is optional)"), 0) + ". " +
Expand Down
65 changes: 35 additions & 30 deletions src/main.cpp
View file
Open in desktop
Expand Up @@ -4805,7 +4805,7 @@ void static ProcessGetData(CNode* pfrom, const Consensus::Params& consensusParam
static const int nOneWeek = 7 * 24 * 60 * 60; // assume > 1 week = historical
if (send && connman.OutboundTargetReached(true) && ( ((pindexBestHeader != NULL) && (pindexBestHeader->GetBlockTime() - mi->second->GetBlockTime() > nOneWeek)) || inv.type == MSG_FILTERED_BLOCK) && !pfrom->fWhitelisted)
{
LogPrint("net", "historical block serving limit reached, disconnect peer=%d\n", pfrom->GetId());
LogPrint("block", "historical block serving limit reached, disconnect peer=%d\n", pfrom->GetId());

//disconnect node
pfrom->fDisconnect = true;
Expand Down Expand Up @@ -4931,7 +4931,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
{
unsigned int nMaxSendBufferSize = connman.GetSendBufferSize();

LogPrint("net", "received: %s (%u bytes) peer=%d\n", SanitizeString(strCommand), vRecv.size(), pfrom->id);
LogPrint("net2", "received: %s (%u bytes) peer=%d\n", SanitizeString(strCommand), vRecv.size(), pfrom->id);
if (mapArgs.count("-dropmessagestest") && GetRand(atoi(mapArgs["-dropmessagestest"])) == 0)
{
LogPrintf("dropmessagestest DROPPING RECV MESSAGE\n");
Expand Down Expand Up @@ -5234,7 +5234,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
boost::this_thread::interruption_point();

bool fAlreadyHave = AlreadyHave(inv);
LogPrint("net", "got inv: %s %s peer=%d\n", inv.ToString(), fAlreadyHave ? "have" : "new", pfrom->id);
LogPrint("net2", "got inv: %s %s peer=%d\n", inv.ToString(), fAlreadyHave ? "have" : "new", pfrom->id);

if (inv.type == MSG_TX) {
inv.type |= nFetchFlags;
Expand Down Expand Up @@ -5265,14 +5265,14 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
// later (within the same cs_main lock, though).
MarkBlockAsInFlight(pfrom->GetId(), inv.hash, chainparams.GetConsensus());
}
LogPrint("net", "getheaders (%d) %s to peer=%d\n", pindexBestHeader->nHeight, inv.hash.ToString(), pfrom->id);
LogPrint("block", "getheaders (%d) %s to peer=%d\n", pindexBestHeader->nHeight, inv.hash.ToString(), pfrom->id);
}
}
else
{
pfrom->AddInventoryKnown(inv);
if (fBlocksOnly)
LogPrint("net", "transaction (%s) inv sent in violation of protocol peer=%d\n", inv.hash.ToString(), pfrom->id);
LogPrint("tx", "transaction (%s) inv sent in violation of protocol peer=%d\n", inv.hash.ToString(), pfrom->id);
else if (!fAlreadyHave && !fImporting && !fReindex && !IsInitialBlockDownload())
pfrom->AskFor(inv);
}
Expand Down Expand Up @@ -5303,10 +5303,10 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
}

if (fDebug || (vInv.size() != 1))
LogPrint("net", "received getdata (%u invsz) peer=%d\n", vInv.size(), pfrom->id);
LogPrint("net2", "received getdata (%u invsz) peer=%d\n", vInv.size(), pfrom->id);

if ((fDebug && vInv.size() > 0) || (vInv.size() == 1))
LogPrint("net", "received getdata for: %s peer=%d\n", vInv[0].ToString(), pfrom->id);
LogPrint("net2", "received getdata for: %s peer=%d\n", vInv[0].ToString(), pfrom->id);

pfrom->vRecvGetData.insert(pfrom->vRecvGetData.end(), vInv.begin(), vInv.end());
ProcessGetData(pfrom, chainparams.GetConsensus(), connman);
Expand Down Expand Up @@ -5369,7 +5369,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
}

if (it->second->nHeight < chainActive.Height() - 15) {
LogPrint("net", "Peer %d sent us a getblocktxn for a block > 15 deep", pfrom->id);
LogPrint("block", "Peer %d sent us a getblocktxn for a block > 15 deep", pfrom->id);
return true;
}

Expand Down Expand Up @@ -5397,7 +5397,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,

LOCK(cs_main);
if (IsInitialBlockDownload() && !pfrom->fWhitelisted) {
LogPrint("net", "Ignoring getheaders from peer=%d because node is in initial block download\n", pfrom->id);
LogPrint("block", "Ignoring getheaders from peer=%d because node is in initial block download\n", pfrom->id);
return true;
}

Expand Down Expand Up @@ -5444,7 +5444,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
// We are in blocks only mode and peer is either not whitelisted or whitelistrelay is off
if (!fRelayTxes && (!pfrom->fWhitelisted || !GetBoolArg("-whitelistrelay", DEFAULT_WHITELISTRELAY)))
{
LogPrint("net", "transaction sent in violation of protocol peer=%d\n", pfrom->id);
LogPrint("tx", "transaction sent in violation of protocol peer=%d\n", pfrom->id);
return true;
}

Expand Down Expand Up @@ -5672,7 +5672,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
(*queuedBlockIt)->partialBlock.reset(new PartiallyDownloadedBlock(&mempool));
else {
// The block was already in flight using compact blocks from the same peer
LogPrint("net", "Peer sent us compact block we were already syncing!\n");
LogPrint("block", "Peer sent us compact block we were already syncing!\n");
return true;
}
}
Expand Down Expand Up @@ -5741,7 +5741,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
map<uint256, pair<NodeId, list<QueuedBlock>::iterator> >::iterator it = mapBlocksInFlight.find(resp.blockhash);
if (it == mapBlocksInFlight.end() || !it->second.second->partialBlock ||
it->second.first != pfrom->GetId()) {
LogPrint("net", "Peer %d sent us block transactions for block we weren't expecting\n", pfrom->id);
LogPrint("block", "Peer %d sent us block transactions for block we weren't expecting\n", pfrom->id);
return true;
}

Expand Down Expand Up @@ -5813,7 +5813,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
if (mapBlockIndex.find(headers[0].hashPrevBlock) == mapBlockIndex.end() && nCount < MAX_BLOCKS_TO_ANNOUNCE) {
nodestate->nUnconnectingHeaders++;
pfrom->PushMessage(NetMsgType::GETHEADERS, chainActive.GetLocator(pindexBestHeader), uint256());
LogPrint("net", "received header %s: missing prev block %s, sending getheaders (%d) to end (peer=%d, nUnconnectingHeaders=%d)\n",
LogPrint("block", "received header %s: missing prev block %s, sending getheaders (%d) to end (peer=%d, nUnconnectingHeaders=%d)\n",
headers[0].GetHash().ToString(),
headers[0].hashPrevBlock.ToString(),
pindexBestHeader->nHeight,
Expand Down Expand Up @@ -5847,7 +5847,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
}

if (nodestate->nUnconnectingHeaders > 0) {
LogPrint("net", "peer=%d: resetting nUnconnectingHeaders (%d -> 0)\n", pfrom->id, nodestate->nUnconnectingHeaders);
LogPrint("block", "peer=%d: resetting nUnconnectingHeaders (%d -> 0)\n", pfrom->id, nodestate->nUnconnectingHeaders);
}
nodestate->nUnconnectingHeaders = 0;

Expand All @@ -5858,7 +5858,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
// Headers message had its maximum size; the peer may have more headers.
// TODO: optimize: if pindexLast is an ancestor of chainActive.Tip or pindexBestHeader, continue
// from there instead.
LogPrint("net", "more getheaders (%d) to end to peer=%d (startheight:%d)\n", pindexLast->nHeight, pfrom->id, pfrom->nStartingHeight);
LogPrint("block", "more getheaders (%d) to end to peer=%d (startheight:%d)\n", pindexLast->nHeight, pfrom->id, pfrom->nStartingHeight);
pfrom->PushMessage(NetMsgType::GETHEADERS, chainActive.GetLocator(pindexLast), uint256());
}

Expand All @@ -5883,7 +5883,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
// the main chain -- this shouldn't really happen. Bail out on the
// direct fetch and rely on parallel download instead.
if (!chainActive.Contains(pindexWalk)) {
LogPrint("net", "Large reorg, won't direct fetch to %s (%d)\n",
LogPrint("block", "Large reorg, won't direct fetch to %s (%d)\n",
pindexLast->GetBlockHash().ToString(),
pindexLast->nHeight);
} else {
Expand All @@ -5897,11 +5897,11 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
uint32_t nFetchFlags = GetFetchFlags(pfrom, pindex->pprev, chainparams.GetConsensus());
vGetData.push_back(CInv(MSG_BLOCK | nFetchFlags, pindex->GetBlockHash()));
MarkBlockAsInFlight(pfrom->GetId(), pindex->GetBlockHash(), chainparams.GetConsensus(), pindex);
LogPrint("net", "Requesting block %s from peer=%d\n",
LogPrint("block", "Requesting block %s from peer=%d\n",
pindex->GetBlockHash().ToString(), pfrom->id);
}
if (vGetData.size() > 1) {
LogPrint("net", "Downloading blocks toward %s (%d) via headers direct fetch\n",
LogPrint("block", "Downloading blocks toward %s (%d) via headers direct fetch\n",
pindexLast->GetBlockHash().ToString(), pindexLast->nHeight);
}
if (vGetData.size() > 0) {
Expand All @@ -5928,7 +5928,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
CBlock block;
vRecv >> block;

LogPrint("net", "received block %s peer=%d\n", block.GetHash().ToString(), pfrom->id);
LogPrint("block", "received block %s peer=%d\n", block.GetHash().ToString(), pfrom->id);

CValidationState state;
// Process all blocks from whitelisted peers, even if not requested,
Expand Down Expand Up @@ -5966,7 +5966,7 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
// Only send one GetAddr response per connection to reduce resource waste
// and discourage addr stamping of INV announcements.
if (pfrom->fSentAddr) {
LogPrint("net", "Ignoring repeated \"getaddr\". peer=%d\n", pfrom->id);
LogPrint("net2", "Ignoring repeated \"getaddr\". peer=%d\n", pfrom->id);
return true;
}
pfrom->fSentAddr = true;
Expand Down Expand Up @@ -6150,7 +6150,12 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
vRecv >> hash;
ss << ": hash " << hash.ToString();
}
LogPrint("net", "Reject %s\n", SanitizeString(ss.str()));
if (strMsg == NetMsgType::BLOCK)
LogPrint("block", "Reject from peer=%d %s\n", pfrom->id, SanitizeString(ss.str()));
else if (strMsg == NetMsgType::TX)
LogPrint("tx", "Reject from peer=%d %s\n", pfrom->id, SanitizeString(ss.str()));
else
LogPrint("net", "Reject from peer=%d %s\n", pfrom->id, SanitizeString(ss.str()));
} catch (const std::ios_base::failure&) {
// Avoid feedback loops by preventing reject messages from triggering a new reject message.
LogPrint("net", "Unparseable reject message received\n");
Expand Down Expand Up @@ -6445,7 +6450,7 @@ bool SendMessages(CNode* pto, CConnman& connman)
got back an empty response. */
if (pindexStart->pprev)
pindexStart = pindexStart->pprev;
LogPrint("net", "initial getheaders (%d) to peer=%d (startheight:%d)\n", pindexStart->nHeight, pto->id, pto->nStartingHeight);
LogPrint("block", "initial getheaders (%d) to peer=%d (startheight:%d)\n", pindexStart->nHeight, pto->id, pto->nStartingHeight);
pto->PushMessage(NetMsgType::GETHEADERS, chainActive.GetLocator(pindexStart), uint256());
}
}
Expand Down Expand Up @@ -6529,7 +6534,7 @@ bool SendMessages(CNode* pto, CConnman& connman)
if (vHeaders.size() == 1 && state.fPreferHeaderAndIDs) {
// We only send up to 1 block as header-and-ids, as otherwise
// probably means we're doing an initial-ish-sync or they're slow
LogPrint("net", "%s sending header-and-ids %s to peer %d\n", __func__,
LogPrint("block", "%s sending header-and-ids %s to peer %d\n", __func__,
vHeaders.front().GetHash().ToString(), pto->id);
//TODO: Shouldn't need to reload block from disk, but requires refactor
CBlock block;
Expand All @@ -6539,12 +6544,12 @@ bool SendMessages(CNode* pto, CConnman& connman)
state.pindexBestHeaderSent = pBestIndex;
} else if (state.fPreferHeaders) {
if (vHeaders.size() > 1) {
LogPrint("net", "%s: %u headers, range (%s, %s), to peer=%d\n", __func__,
LogPrint("block", "%s: %u headers, range (%s, %s), to peer=%d\n", __func__,
vHeaders.size(),
vHeaders.front().GetHash().ToString(),
vHeaders.back().GetHash().ToString(), pto->id);
} else {
LogPrint("net", "%s: sending header %s to peer=%d\n", __func__,
LogPrint("block", "%s: sending header %s to peer=%d\n", __func__,
vHeaders.front().GetHash().ToString(), pto->id);
}
pto->PushMessage(NetMsgType::HEADERS, vHeaders);
Expand All @@ -6566,14 +6571,14 @@ bool SendMessages(CNode* pto, CConnman& connman)
// This should be very rare and could be optimized out.
// Just log for now.
if (chainActive[pindex->nHeight] != pindex) {
LogPrint("net", "Announcing block %s not on main chain (tip=%s)\n",
LogPrint("block", "Announcing block %s not on main chain (tip=%s)\n",
hashToAnnounce.ToString(), chainActive.Tip()->GetBlockHash().ToString());
}

// If the peer's chain has this block, don't inv it back.
if (!PeerHasHeader(&state, pindex)) {
pto->PushInventory(CInv(MSG_BLOCK, hashToAnnounce));
LogPrint("net", "%s: sending inv peer=%d hash=%s\n", __func__,
LogPrint("block", "%s: sending inv peer=%d hash=%s\n", __func__,
pto->id, hashToAnnounce.ToString());
}
}
Expand Down Expand Up @@ -6750,13 +6755,13 @@ bool SendMessages(CNode* pto, CConnman& connman)
uint32_t nFetchFlags = GetFetchFlags(pto, pindex->pprev, consensusParams);
vGetData.push_back(CInv(MSG_BLOCK | nFetchFlags, pindex->GetBlockHash()));
MarkBlockAsInFlight(pto->GetId(), pindex->GetBlockHash(), consensusParams, pindex);
LogPrint("net", "Requesting block %s (%d) peer=%d\n", pindex->GetBlockHash().ToString(),
LogPrint("block", "Requesting block %s (%d) peer=%d\n", pindex->GetBlockHash().ToString(),
pindex->nHeight, pto->id);
}
if (state.nBlocksInFlight == 0 && staller != -1) {
if (State(staller)->nStallingSince == 0) {
State(staller)->nStallingSince = nNow;
LogPrint("net", "Stall started peer=%d\n", staller);
LogPrint("block", "Stall started peer=%d\n", staller);
}
}
}
Expand All @@ -6770,7 +6775,7 @@ bool SendMessages(CNode* pto, CConnman& connman)
if (!AlreadyHave(inv))
{
if (fDebug)
LogPrint("net", "Requesting %s peer=%d\n", inv.ToString(), pto->id);
LogPrint("tx2", "Requesting %s peer=%d\n", inv.ToString(), pto->id);
vGetData.push_back(inv);
if (vGetData.size() >= 1000)
{
Expand Down