Skip to content

Commit

Permalink
Make net debug more granular (move some into net2, block, tx)
Browse files Browse the repository at this point in the history
  • Loading branch information
@rebroad
rebroad committed Sep 14, 2016
1 parent a82e5d8 commit 168df73
Show file tree
Hide file tree
Showing 2 changed files with 36 additions and 31 deletions.
2 changes: 1 addition & 1 deletion src/init.cpp
View file
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
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

0 comments on commit 168df73

Please sign in to comment.