From a33dde1e41d8923a46db84b50550175fa6149c48 Mon Sep 17 00:00:00 2001 From: glozow Date: Wed, 9 Aug 2023 15:25:34 +0200 Subject: [PATCH 1/4] [log] include wtxid in tx {relay,validation,orphanage} logging --- src/net_processing.cpp | 25 +++++++++++++++++-------- src/txorphanage.cpp | 5 +++-- src/validation.cpp | 4 +++- test/functional/p2p_permissions.py | 6 +++--- 4 files changed, 26 insertions(+), 14 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 8189d6c9f3b..64103b28806 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2919,9 +2919,10 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) const MempoolAcceptResult result = m_chainman.ProcessTransaction(porphanTx); const TxValidationState& state = result.m_state; const uint256& orphanHash = porphanTx->GetHash(); + const uint256& orphan_wtxid = porphanTx->GetWitnessHash(); if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { - LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s\n", orphanHash.ToString()); + LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); RelayTransaction(orphanHash, porphanTx->GetWitnessHash()); m_orphanage.AddChildrenToWorkSet(*porphanTx); m_orphanage.EraseTx(orphanHash); @@ -2931,8 +2932,9 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) return true; } else if (state.GetResult() != TxValidationResult::TX_MISSING_INPUTS) { if (state.IsInvalid()) { - LogPrint(BCLog::MEMPOOL, " invalid orphan tx %s from peer=%d. %s\n", + LogPrint(BCLog::MEMPOOL, " invalid orphan tx %s (wtxid=%s) from peer=%d. %s\n", orphanHash.ToString(), + orphan_wtxid.ToString(), peer.m_id, state.ToString()); // Maybe punish peer that gave us an invalid orphan tx @@ -2940,7 +2942,7 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) } // Has inputs but not accepted to mempool // Probably non-standard or insufficient fee - LogPrint(BCLog::MEMPOOL, " removed orphan tx %s\n", orphanHash.ToString()); + LogPrint(BCLog::MEMPOOL, " removed orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); if (state.GetResult() != TxValidationResult::TX_WITNESS_STRIPPED) { // We can add the wtxid of this transaction to our reject filter. // Do not add txids of witness transactions or witness-stripped @@ -4115,9 +4117,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // permission, even if they were already in the mempool, allowing // the node to function as a gateway for nodes hidden behind it. if (!m_mempool.exists(GenTxid::Txid(tx.GetHash()))) { - LogPrintf("Not relaying non-mempool transaction %s from forcerelay peer=%d\n", tx.GetHash().ToString(), pfrom.GetId()); + LogPrintf("Not relaying non-mempool transaction %s (wtxid=%s) from forcerelay peer=%d\n", + tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), pfrom.GetId()); } else { - LogPrintf("Force relaying tx %s from peer=%d\n", tx.GetHash().ToString(), pfrom.GetId()); + LogPrintf("Force relaying tx %s (wtxid=%s) from peer=%d\n", + tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), pfrom.GetId()); RelayTransaction(tx.GetHash(), tx.GetWitnessHash()); } } @@ -4137,9 +4141,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, pfrom.m_last_tx_time = GetTime(); - LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (poolsz %u txn, %u kB)\n", + LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (wtxid=%s) (poolsz %u txn, %u kB)\n", pfrom.GetId(), tx.GetHash().ToString(), + tx.GetWitnessHash().ToString(), m_mempool.size(), m_mempool.DynamicMemoryUsage() / 1000); for (const CTransactionRef& removedTx : result.m_replaced_transactions.value()) { @@ -4191,7 +4196,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // DoS prevention: do not allow m_orphanage to grow unbounded (see CVE-2012-3789) m_orphanage.LimitOrphans(m_opts.max_orphan_txs); } else { - LogPrint(BCLog::MEMPOOL, "not keeping orphan with rejected parents %s\n",tx.GetHash().ToString()); + LogPrint(BCLog::MEMPOOL, "not keeping orphan with rejected parents %s (wtxid=%s)\n", + tx.GetHash().ToString(), + tx.GetWitnessHash().ToString()); // We will continue to reject this tx since it has rejected // parents so avoid re-requesting it from other peers. // Here we add both the txid and the wtxid, as we know that @@ -4256,7 +4263,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // regardless of false positives. if (state.IsInvalid()) { - LogPrint(BCLog::MEMPOOLREJ, "%s from peer=%d was not accepted: %s\n", tx.GetHash().ToString(), + LogPrint(BCLog::MEMPOOLREJ, "%s (wtxid=%s) from peer=%d was not accepted: %s\n", + tx.GetHash().ToString(), + tx.GetWitnessHash().ToString(), pfrom.GetId(), state.ToString()); MaybePunishNodeForTx(pfrom.GetId(), state); diff --git a/src/txorphanage.cpp b/src/txorphanage.cpp index af86baa8ac2..de84ca59566 100644 --- a/src/txorphanage.cpp +++ b/src/txorphanage.cpp @@ -21,6 +21,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer) LOCK(m_mutex); const uint256& hash = tx->GetHash(); + const uint256& wtxid = tx->GetWitnessHash(); if (m_orphans.count(hash)) return false; @@ -34,7 +35,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer) unsigned int sz = GetTransactionWeight(*tx); if (sz > MAX_STANDARD_TX_WEIGHT) { - LogPrint(BCLog::MEMPOOL, "ignoring large orphan tx (size: %u, hash: %s)\n", sz, hash.ToString()); + LogPrint(BCLog::MEMPOOL, "ignoring large orphan tx (size: %u, txid: %s, wtxid: %s)\n", sz, hash.ToString(), wtxid.ToString()); return false; } @@ -47,7 +48,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", hash.ToString(), + LogPrint(BCLog::MEMPOOL, "stored orphan tx %s (wtxid=%s) (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(), m_orphans.size(), m_outpoint_to_orphan_it.size()); return true; } diff --git a/src/validation.cpp b/src/validation.cpp index ed9889d9dd3..0b6327ec558 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1079,9 +1079,11 @@ bool MemPoolAccept::Finalize(const ATMPArgs& args, Workspace& ws) // Remove conflicting transactions from the mempool for (CTxMemPool::txiter it : ws.m_all_conflicting) { - LogPrint(BCLog::MEMPOOL, "replacing tx %s with %s for %s additional fees, %d delta bytes\n", + LogPrint(BCLog::MEMPOOL, "replacing tx %s (wtxid=%s) with %s (wtxid=%s) for %s additional fees, %d delta bytes\n", it->GetTx().GetHash().ToString(), + it->GetTx().GetWitnessHash().ToString(), hash.ToString(), + tx.GetWitnessHash().ToString(), FormatMoney(ws.m_modified_fees - ws.m_conflicting_fees), (int)entry->GetTxSize() - (int)ws.m_conflicting_size); TRACE7(mempool, replaced, diff --git a/test/functional/p2p_permissions.py b/test/functional/p2p_permissions.py index f84bbf67e63..6153e4a1566 100755 --- a/test/functional/p2p_permissions.py +++ b/test/functional/p2p_permissions.py @@ -106,7 +106,7 @@ class P2PPermissionsTests(BitcoinTestFramework): self.log.debug("Check that node[1] will send the tx to node[0] even though it is already in the mempool") self.connect_nodes(1, 0) - with self.nodes[1].assert_debug_log(["Force relaying tx {} from peer=0".format(txid)]): + with self.nodes[1].assert_debug_log(["Force relaying tx {} (wtxid={}) from peer=0".format(txid, tx.getwtxid())]): p2p_rebroadcast_wallet.send_txs_and_test([tx], self.nodes[1]) self.wait_until(lambda: txid in self.nodes[0].getrawmempool()) @@ -119,14 +119,14 @@ class P2PPermissionsTests(BitcoinTestFramework): [tx], self.nodes[1], success=False, - reject_reason='{} from peer=0 was not accepted: txn-mempool-conflict'.format(txid) + reject_reason='{} (wtxid={}) from peer=0 was not accepted: txn-mempool-conflict'.format(txid, tx.getwtxid()) ) p2p_rebroadcast_wallet.send_txs_and_test( [tx], self.nodes[1], success=False, - reject_reason='Not relaying non-mempool transaction {} from forcerelay peer=0'.format(txid) + reject_reason='Not relaying non-mempool transaction {} (wtxid={}) from forcerelay peer=0'.format(txid, tx.getwtxid()) ) def checkpermission(self, args, expectedPermissions): From 51b3275cd1de467933f13d8b71286bf5ebd12b4b Mon Sep 17 00:00:00 2001 From: glozow Date: Mon, 6 Mar 2023 16:46:18 +0000 Subject: [PATCH 2/4] [log] add category TXPACKAGES for orphanage and package relay --- src/logging.cpp | 3 +++ src/logging.h | 1 + src/net_processing.cpp | 6 +++--- src/txorphanage.cpp | 12 ++++++------ 4 files changed, 13 insertions(+), 9 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index a5cfb0d28e3..08bfa1f7a49 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -182,6 +182,7 @@ const CLogCategoryDesc LogCategories[] = {BCLog::BLOCKSTORAGE, "blockstorage"}, {BCLog::TXRECONCILIATION, "txreconciliation"}, {BCLog::SCAN, "scan"}, + {BCLog::TXPACKAGES, "txpackages"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, }; @@ -286,6 +287,8 @@ std::string LogCategoryToStr(BCLog::LogFlags category) return "txreconciliation"; case BCLog::LogFlags::SCAN: return "scan"; + case BCLog::LogFlags::TXPACKAGES: + return "txpackages"; case BCLog::LogFlags::ALL: return "all"; } diff --git a/src/logging.h b/src/logging.h index fc03c8eac38..f7380d89283 100644 --- a/src/logging.h +++ b/src/logging.h @@ -68,6 +68,7 @@ namespace BCLog { BLOCKSTORAGE = (1 << 26), TXRECONCILIATION = (1 << 27), SCAN = (1 << 28), + TXPACKAGES = (1 << 29), ALL = ~(uint32_t)0, }; enum class Level { diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 64103b28806..a0946754a0b 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2922,7 +2922,7 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) const uint256& orphan_wtxid = porphanTx->GetWitnessHash(); if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { - LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); + LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); RelayTransaction(orphanHash, porphanTx->GetWitnessHash()); m_orphanage.AddChildrenToWorkSet(*porphanTx); m_orphanage.EraseTx(orphanHash); @@ -2932,7 +2932,7 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) return true; } else if (state.GetResult() != TxValidationResult::TX_MISSING_INPUTS) { if (state.IsInvalid()) { - LogPrint(BCLog::MEMPOOL, " invalid orphan tx %s (wtxid=%s) from peer=%d. %s\n", + LogPrint(BCLog::TXPACKAGES, " invalid orphan tx %s (wtxid=%s) from peer=%d. %s\n", orphanHash.ToString(), orphan_wtxid.ToString(), peer.m_id, @@ -2942,7 +2942,7 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) } // Has inputs but not accepted to mempool // Probably non-standard or insufficient fee - LogPrint(BCLog::MEMPOOL, " removed orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); if (state.GetResult() != TxValidationResult::TX_WITNESS_STRIPPED) { // We can add the wtxid of this transaction to our reject filter. // Do not add txids of witness transactions or witness-stripped diff --git a/src/txorphanage.cpp b/src/txorphanage.cpp index de84ca59566..4fed6a60ed6 100644 --- a/src/txorphanage.cpp +++ b/src/txorphanage.cpp @@ -35,7 +35,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer) unsigned int sz = GetTransactionWeight(*tx); if (sz > MAX_STANDARD_TX_WEIGHT) { - LogPrint(BCLog::MEMPOOL, "ignoring large orphan tx (size: %u, txid: %s, wtxid: %s)\n", sz, hash.ToString(), wtxid.ToString()); + LogPrint(BCLog::TXPACKAGES, "ignoring large orphan tx (size: %u, txid: %s, wtxid: %s)\n", sz, hash.ToString(), wtxid.ToString()); return false; } @@ -48,7 +48,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 (wtxid=%s) (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(), + LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (wtxid=%s) (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(), m_orphans.size(), m_outpoint_to_orphan_it.size()); return true; } @@ -107,7 +107,7 @@ void TxOrphanage::EraseForPeer(NodeId peer) nErased += EraseTxNoLock(maybeErase->second.tx->GetHash()); } } - if (nErased > 0) LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx from peer=%d\n", nErased, peer); + if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx from peer=%d\n", nErased, peer); } void TxOrphanage::LimitOrphans(unsigned int max_orphans) @@ -133,7 +133,7 @@ void TxOrphanage::LimitOrphans(unsigned int max_orphans) } // Sweep again 5 minutes after the next entry that expires in order to 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); + if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx due to expiration\n", nErased); } FastRandomContext rng; while (m_orphans.size() > max_orphans) @@ -143,7 +143,7 @@ void TxOrphanage::LimitOrphans(unsigned int max_orphans) EraseTxNoLock(m_orphan_list[randompos]->first); ++nEvicted; } - if (nEvicted > 0) LogPrint(BCLog::MEMPOOL, "orphanage overflow, removed %u tx\n", nEvicted); + if (nEvicted > 0) LogPrint(BCLog::TXPACKAGES, "orphanage overflow, removed %u tx\n", nEvicted); } void TxOrphanage::AddChildrenToWorkSet(const CTransaction& tx) @@ -234,6 +234,6 @@ void TxOrphanage::EraseForBlock(const CBlock& block) for (const uint256& orphanHash : vOrphanErase) { nErased += EraseTxNoLock(orphanHash); } - LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx included or conflicted by block\n", nErased); + LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx included or conflicted by block\n", nErased); } } From 3b8c17838a561616fd7c933753c7b98b6c6c7c99 Mon Sep 17 00:00:00 2001 From: glozow Date: Mon, 24 Jul 2023 16:09:50 +0100 Subject: [PATCH 3/4] [log] add more logs related to orphan handling - Whenever a tx is erased. Allows somebody to see which transactions have been erased due to expiry/overflow, not just how many. - Whenever a tx is added to a peer's workset. - AcceptToMemoryPool when a tx is accepted, mirroring the one logged for a tx received from a peer. This allows someone to see all of the transactions that are accepted to mempool just by looking for ATMP logs. - MEMPOOLREJ when a tx is rejected, mirroring the one logged for a tx received from a peer. This allows someone to see all of the transaction rejections by looking at MEMPOOLREJ logs. --- src/net_processing.cpp | 10 ++++++++++ src/txorphanage.cpp | 4 ++++ 2 files changed, 14 insertions(+) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index a0946754a0b..ec8230fd688 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2923,6 +2923,11 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); + LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (wtxid=%s) (poolsz %u txn, %u kB)\n", + peer.m_id, + orphanHash.ToString(), + orphan_wtxid.ToString(), + m_mempool.size(), m_mempool.DynamicMemoryUsage() / 1000); RelayTransaction(orphanHash, porphanTx->GetWitnessHash()); m_orphanage.AddChildrenToWorkSet(*porphanTx); m_orphanage.EraseTx(orphanHash); @@ -2937,6 +2942,11 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) orphan_wtxid.ToString(), peer.m_id, state.ToString()); + LogPrint(BCLog::MEMPOOLREJ, "%s (wtxid=%s) from peer=%d was not accepted: %s\n", + orphanHash.ToString(), + orphan_wtxid.ToString(), + peer.m_id, + state.ToString()); // Maybe punish peer that gave us an invalid orphan tx MaybePunishNodeForTx(peer.m_id, state); } diff --git a/src/txorphanage.cpp b/src/txorphanage.cpp index 4fed6a60ed6..7455d914e80 100644 --- a/src/txorphanage.cpp +++ b/src/txorphanage.cpp @@ -84,6 +84,8 @@ int TxOrphanage::EraseTxNoLock(const uint256& txid) m_orphan_list[old_pos] = it_last; it_last->second.list_pos = old_pos; } + const auto& wtxid = it->second.tx->GetWitnessHash(); + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s (wtxid=%s)\n", txid.ToString(), wtxid.ToString()); m_orphan_list.pop_back(); m_wtxid_to_orphan_it.erase(it->second.tx->GetWitnessHash()); @@ -160,6 +162,8 @@ void TxOrphanage::AddChildrenToWorkSet(const CTransaction& tx) std::set& orphan_work_set = m_peer_work_set.try_emplace(elem->second.fromPeer).first->second; // Add this tx to the work set orphan_work_set.insert(elem->first); + LogPrint(BCLog::TXPACKAGES, "added %s (wtxid=%s) to peer %d workset\n", + tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), elem->second.fromPeer); } } } From a3b55c94b9ffde07386aa887149ddca91b364967 Mon Sep 17 00:00:00 2001 From: glozow Date: Mon, 14 Aug 2023 14:05:34 +0100 Subject: [PATCH 4/4] [doc] move comment about AlreadyHaveTx DoS score to the right place This comment isn't in the right place, as detection of a tx in recent_rejects would cause the function to exit much earlier. Move the comment to the right place and tweak the first sentence for accuracy. --- src/net_processing.cpp | 32 +++++++++++++++----------------- 1 file changed, 15 insertions(+), 17 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index ec8230fd688..c5a22f258a4 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -4135,6 +4135,21 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, RelayTransaction(tx.GetHash(), tx.GetWitnessHash()); } } + // 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; } @@ -4255,23 +4270,6 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, } } - // 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 (wtxid=%s) from peer=%d was not accepted: %s\n", tx.GetHash().ToString(),