From 2de0e104d3f2fd8f041b8e39e3561b5c1be2441c Mon Sep 17 00:00:00 2001 From: glozow Date: Mon, 6 Mar 2023 16:46:18 +0000 Subject: [PATCH] log: add orphanage logs, add TXPACKAGES category Summary: ``` - Additional orphan-related logging to make testing and debugging easier. - Add TXPACKAGES category for logging. - Move a nearby comment block that was in the wrong place. ``` Backport of [[https://github.com/bitcoin/bitcoin/pull/28364 | core#28364]]. Test Plan: ninja all check-all Reviewers: #bitcoin_abc, PiRK Reviewed By: #bitcoin_abc, PiRK Differential Revision: https://reviews.bitcoinabc.org/D16318 --- src/logging.cpp | 1 + src/logging.h | 1 + src/net_processing.cpp | 50 ++++++++++++++++++++++++------------------ src/txorphanage.cpp | 17 ++++++++------ 4 files changed, 41 insertions(+), 28 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 2186854ff4..ea5f763b41 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -134,6 +134,7 @@ const CLogCategoryDesc LogCategories[] = { #endif {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::NETDEBUG, "netdebug"}, + {BCLog::TXPACKAGES, "txpackages"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, }; diff --git a/src/logging.h b/src/logging.h index 08e9a93101..23eda62cd4 100644 --- a/src/logging.h +++ b/src/logging.h @@ -67,6 +67,7 @@ enum LogFlags : uint32_t { #endif BLOCKSTORE = (1 << 26), NETDEBUG = (1 << 27), + TXPACKAGES = (1 << 28), ALL = ~uint32_t(0), }; diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 180f758ad2..f172ec31de 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3997,23 +3997,31 @@ bool PeerManagerImpl::ProcessOrphanTx(const Config &config, Peer &peer) { const TxId &orphanTxId = porphanTx->GetId(); if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { - LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s\n", + LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s\n", orphanTxId.ToString()); + LogPrint(BCLog::MEMPOOL, + "AcceptToMemoryPool: peer=%d: accepted %s (poolsz %u txn, " + "%u kB)\n", + peer.m_id, orphanTxId.ToString(), m_mempool.size(), + m_mempool.DynamicMemoryUsage() / 1000); RelayTransaction(orphanTxId); m_orphanage.AddChildrenToWorkSet(*porphanTx); m_orphanage.EraseTx(orphanTxId); return true; } else if (state.GetResult() != TxValidationResult::TX_MISSING_INPUTS) { if (state.IsInvalid()) { - LogPrint(BCLog::MEMPOOL, + LogPrint(BCLog::TXPACKAGES, " invalid orphan tx %s from peer=%d. %s\n", orphanTxId.ToString(), peer.m_id, state.ToString()); + LogPrint(BCLog::MEMPOOLREJ, + "%s from peer=%d was not accepted: %s\n", + orphanTxId.ToString(), peer.m_id, state.ToString()); // Punish peer that gave us an invalid orphan tx MaybePunishNodeForTx(peer.m_id, state); } // Has inputs but not accepted to mempool // Probably non-standard or insufficient fee - LogPrint(BCLog::MEMPOOL, " removed orphan tx %s\n", + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s\n", orphanTxId.ToString()); m_recent_rejects.insert(orphanTxId); @@ -5300,6 +5308,23 @@ void PeerManagerImpl::ProcessMessage( RelayTransaction(tx.GetId()); } } + + // If a tx is detected by m_recent_rejects it is ignored. Because we + // haven't submitted the tx to our mempool, we won't have computed a + // DoS score for it or determined exactly why we consider it + // invalid. + // + // This means we won't penalize any peer subsequently relaying a + // DoSy tx (even if we penalized the first peer who gave it to us) + // because we have to account for m_recent_rejects showing false + // positives. In other words, we shouldn't penalize a peer if we + // aren't *sure* they submitted a DoSy tx. + // + // Note that m_recent_rejects doesn't just record DoSy or invalid + // transactions, but any tx not accepted by the mempool, which may + // be due to node policy (vs. consensus). So we can't blanket + // penalize a peer simply for relaying a tx that our + // m_recent_rejects has caught, regardless of false positives. return; } @@ -5370,7 +5395,7 @@ void PeerManagerImpl::ProcessMessage( DEFAULT_MAX_ORPHAN_TRANSACTIONS)); unsigned int nEvicted = m_orphanage.LimitOrphans(nMaxOrphanTx); if (nEvicted > 0) { - LogPrint(BCLog::MEMPOOL, + LogPrint(BCLog::TXPACKAGES, "orphanage overflow, removed %u tx\n", nEvicted); } } else { @@ -5391,23 +5416,6 @@ void PeerManagerImpl::ProcessMessage( } } - // If a tx has been detected by m_recent_rejects, we will have reached - // this point and the tx will have been ignored. Because we haven't - // submitted the tx to our mempool, we won't have computed a DoS - // score for it or determined exactly why we consider it invalid. - // - // This means we won't penalize any peer subsequently relaying a DoSy - // tx (even if we penalized the first peer who gave it to us) because - // we have to account for m_recent_rejects showing false positives. In - // other words, we shouldn't penalize a peer if we aren't *sure* they - // submitted a DoSy tx. - // - // Note that m_recent_rejects doesn't just record DoSy or invalid - // transactions, but any tx not accepted by the mempool, which may be - // due to node policy (vs. consensus). So we can't blanket penalize a - // peer simply for relaying a tx that our m_recent_rejects has caught, - // regardless of false positives. - if (state.IsInvalid()) { LogPrint(BCLog::MEMPOOLREJ, "%s from peer=%d was not accepted: %s\n", diff --git a/src/txorphanage.cpp b/src/txorphanage.cpp index b25f128476..59bd7fc329 100644 --- a/src/txorphanage.cpp +++ b/src/txorphanage.cpp @@ -31,7 +31,7 @@ bool TxOrphanage::AddTx(const CTransactionRef &tx, NodeId peer) { // megabytes of orphans and somewhat more byprev index (in the worst case): unsigned int sz = tx->GetTotalSize(); if (sz > MAX_STANDARD_TX_SIZE) { - LogPrint(BCLog::MEMPOOL, + LogPrint(BCLog::TXPACKAGES, "ignoring large orphan tx (size: %u, hash: %s)\n", sz, txid.ToString()); return false; @@ -46,7 +46,7 @@ bool TxOrphanage::AddTx(const CTransactionRef &tx, NodeId peer) { m_outpoint_to_orphan_it[txin.prevout].insert(ret.first); } - LogPrint(BCLog::MEMPOOL, "stored orphan tx %s (mapsz %u outsz %u)\n", + LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (mapsz %u outsz %u)\n", txid.ToString(), m_orphans.size(), m_outpoint_to_orphan_it.size()); return true; } @@ -82,6 +82,7 @@ int TxOrphanage::EraseTxNoLock(const TxId &txid) { m_orphan_list[old_pos] = it_last; it_last->second.list_pos = old_pos; } + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s \n", txid.ToString()); m_orphan_list.pop_back(); m_orphans.erase(it); @@ -103,8 +104,8 @@ void TxOrphanage::EraseForPeer(NodeId peer) { } } if (nErased > 0) { - LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx from peer=%d\n", nErased, - peer); + LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx from peer=%d\n", + nErased, peer); } } @@ -133,8 +134,8 @@ unsigned int TxOrphanage::LimitOrphans(unsigned int max_orphans) { // batch the linear scan. nNextSweep = nMinExpTime + ORPHAN_TX_EXPIRE_INTERVAL; if (nErased > 0) { - LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx due to expiration\n", - nErased); + LogPrint(BCLog::TXPACKAGES, + "Erased %d orphan tx due to expiration\n", nErased); } } FastRandomContext rng; @@ -162,6 +163,8 @@ void TxOrphanage::AddChildrenToWorkSet(const CTransaction &tx) { .first->second; // Add this tx to the work set orphan_work_set.insert(elem->first); + LogPrint(BCLog::TXPACKAGES, "added %s to peer %d workset\n", + tx.GetId().ToString(), elem->second.fromPeer); } } } @@ -232,7 +235,7 @@ void TxOrphanage::EraseForBlock(const CBlock &block) { for (const auto &orphanId : vOrphanErase) { nErased += EraseTxNoLock(orphanId); } - LogPrint(BCLog::MEMPOOL, + LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx included or conflicted by block\n", nErased); }