Skip to content

Commit 5666966

Browse files
achow101achow101
committed
Merge #28364: log: log wtxids when possible, add TXPACKAGES category
a3b55c9 [doc] move comment about AlreadyHaveTx DoS score to the right place (glozow) 3b8c178 [log] add more logs related to orphan handling (glozow) 51b3275 [log] add category TXPACKAGES for orphanage and package relay (glozow) a33dde1 [log] include wtxid in tx {relay,validation,orphanage} logging (glozow) Pull request description: This was taken from #28031 (see #27463 for project tracking). - Log wtxids in addition to txids when possible. This allows us to track the fate of a transaction from inv to mempool accept/reject through logs. - Additional orphan-related logging to make testing and debugging easier. Suggested in #28031 (review) and #28031 (comment) - Add `TXPACKAGES` category for logging. - Move a nearby comment block that was in the wrong place. ACKs for top commit: instagibbs: reACK a3b55c9 achow101: ACK a3b55c9 brunoerg: crACK a3b55c9 mzumsande: Code review ACK a3b55c9 Tree-SHA512: 21884ef7c2ea2fd006e715574a9dd3e6cbbe8f82d62c6187fe1d39aad5a834051203fda5f355a06ca40c3e2b9561aec50d7c922a662b1edc96f7b552c9f4b24d
2 parents a4e0bcb + a3b55c9 commit 5666966

File tree

6 files changed

+63
-35
lines changed

6 files changed

+63
-35
lines changed

‎src/logging.cpp‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -182,6 +182,7 @@ const CLogCategoryDesc LogCategories[] =
182182
{BCLog::BLOCKSTORAGE, "blockstorage"},
183183
{BCLog::TXRECONCILIATION, "txreconciliation"},
184184
{BCLog::SCAN, "scan"},
185+
{BCLog::TXPACKAGES, "txpackages"},
185186
{BCLog::ALL, "1"},
186187
{BCLog::ALL, "all"},
187188
};
@@ -286,6 +287,8 @@ std::string LogCategoryToStr(BCLog::LogFlags category)
286287
return "txreconciliation";
287288
case BCLog::LogFlags::SCAN:
288289
return "scan";
290+
case BCLog::LogFlags::TXPACKAGES:
291+
return "txpackages";
289292
case BCLog::LogFlags::ALL:
290293
return "all";
291294
}

‎src/logging.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -68,6 +68,7 @@ namespace BCLog {
6868
BLOCKSTORAGE = (1 << 26),
6969
TXRECONCILIATION = (1 << 27),
7070
SCAN = (1 << 28),
71+
TXPACKAGES = (1 << 29),
7172
ALL = ~(uint32_t)0,
7273
};
7374
enum class Level {

‎src/net_processing.cpp‎

Lines changed: 42 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -2919,9 +2919,15 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer)
29192919
const MempoolAcceptResult result = m_chainman.ProcessTransaction(porphanTx);
29202920
const TxValidationState& state = result.m_state;
29212921
const uint256& orphanHash = porphanTx->GetHash();
2922+
const uint256& orphan_wtxid = porphanTx->GetWitnessHash();
29222923

29232924
if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) {
2924-
LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s\n", orphanHash.ToString());
2925+
LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString());
2926+
LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (wtxid=%s) (poolsz %u txn, %u kB)\n",
2927+
peer.m_id,
2928+
orphanHash.ToString(),
2929+
orphan_wtxid.ToString(),
2930+
m_mempool.size(), m_mempool.DynamicMemoryUsage() / 1000);
29252931
RelayTransaction(orphanHash, porphanTx->GetWitnessHash());
29262932
m_orphanage.AddChildrenToWorkSet(*porphanTx);
29272933
m_orphanage.EraseTx(orphanHash);
@@ -2931,16 +2937,22 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer)
29312937
return true;
29322938
} else if (state.GetResult() != TxValidationResult::TX_MISSING_INPUTS) {
29332939
if (state.IsInvalid()) {
2934-
LogPrint(BCLog::MEMPOOL, " invalid orphan tx %s from peer=%d. %s\n",
2940+
LogPrint(BCLog::TXPACKAGES, " invalid orphan tx %s (wtxid=%s) from peer=%d. %s\n",
29352941
orphanHash.ToString(),
2942+
orphan_wtxid.ToString(),
2943+
peer.m_id,
2944+
state.ToString());
2945+
LogPrint(BCLog::MEMPOOLREJ, "%s (wtxid=%s) from peer=%d was not accepted: %s\n",
2946+
orphanHash.ToString(),
2947+
orphan_wtxid.ToString(),
29362948
peer.m_id,
29372949
state.ToString());
29382950
// Maybe punish peer that gave us an invalid orphan tx
29392951
MaybePunishNodeForTx(peer.m_id, state);
29402952
}
29412953
// Has inputs but not accepted to mempool
29422954
// Probably non-standard or insufficient fee
2943-
LogPrint(BCLog::MEMPOOL, " removed orphan tx %s\n", orphanHash.ToString());
2955+
LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString());
29442956
if (state.GetResult() != TxValidationResult::TX_WITNESS_STRIPPED) {
29452957
// We can add the wtxid of this transaction to our reject filter.
29462958
// Do not add txids of witness transactions or witness-stripped
@@ -4115,12 +4127,29 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
41154127
// permission, even if they were already in the mempool, allowing
41164128
// the node to function as a gateway for nodes hidden behind it.
41174129
if (!m_mempool.exists(GenTxid::Txid(tx.GetHash()))) {
4118-
LogPrintf("Not relaying non-mempool transaction %s from forcerelay peer=%d\n", tx.GetHash().ToString(), pfrom.GetId());
4130+
LogPrintf("Not relaying non-mempool transaction %s (wtxid=%s) from forcerelay peer=%d\n",
4131+
tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), pfrom.GetId());
41194132
} else {
4120-
LogPrintf("Force relaying tx %s from peer=%d\n", tx.GetHash().ToString(), pfrom.GetId());
4133+
LogPrintf("Force relaying tx %s (wtxid=%s) from peer=%d\n",
4134+
tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), pfrom.GetId());
41214135
RelayTransaction(tx.GetHash(), tx.GetWitnessHash());
41224136
}
41234137
}
4138+
// If a tx is detected by m_recent_rejects it is ignored. Because we haven't
4139+
// submitted the tx to our mempool, we won't have computed a DoS
4140+
// score for it or determined exactly why we consider it invalid.
4141+
//
4142+
// This means we won't penalize any peer subsequently relaying a DoSy
4143+
// tx (even if we penalized the first peer who gave it to us) because
4144+
// we have to account for m_recent_rejects showing false positives. In
4145+
// other words, we shouldn't penalize a peer if we aren't *sure* they
4146+
// submitted a DoSy tx.
4147+
//
4148+
// Note that m_recent_rejects doesn't just record DoSy or invalid
4149+
// transactions, but any tx not accepted by the mempool, which may be
4150+
// due to node policy (vs. consensus). So we can't blanket penalize a
4151+
// peer simply for relaying a tx that our m_recent_rejects has caught,
4152+
// regardless of false positives.
41244153
return;
41254154
}
41264155

@@ -4137,9 +4166,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
41374166

41384167
pfrom.m_last_tx_time = GetTime<std::chrono::seconds>();
41394168

4140-
LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (poolsz %u txn, %u kB)\n",
4169+
LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (wtxid=%s) (poolsz %u txn, %u kB)\n",
41414170
pfrom.GetId(),
41424171
tx.GetHash().ToString(),
4172+
tx.GetWitnessHash().ToString(),
41434173
m_mempool.size(), m_mempool.DynamicMemoryUsage() / 1000);
41444174

41454175
for (const CTransactionRef& removedTx : result.m_replaced_transactions.value()) {
@@ -4191,7 +4221,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
41914221
// DoS prevention: do not allow m_orphanage to grow unbounded (see CVE-2012-3789)
41924222
m_orphanage.LimitOrphans(m_opts.max_orphan_txs);
41934223
} else {
4194-
LogPrint(BCLog::MEMPOOL, "not keeping orphan with rejected parents %s\n",tx.GetHash().ToString());
4224+
LogPrint(BCLog::MEMPOOL, "not keeping orphan with rejected parents %s (wtxid=%s)\n",
4225+
tx.GetHash().ToString(),
4226+
tx.GetWitnessHash().ToString());
41954227
// We will continue to reject this tx since it has rejected
41964228
// parents so avoid re-requesting it from other peers.
41974229
// Here we add both the txid and the wtxid, as we know that
@@ -4238,25 +4270,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
42384270
}
42394271
}
42404272

4241-
// If a tx has been detected by m_recent_rejects, we will have reached
4242-
// this point and the tx will have been ignored. Because we haven't
4243-
// submitted the tx to our mempool, we won't have computed a DoS
4244-
// score for it or determined exactly why we consider it invalid.
4245-
//
4246-
// This means we won't penalize any peer subsequently relaying a DoSy
4247-
// tx (even if we penalized the first peer who gave it to us) because
4248-
// we have to account for m_recent_rejects showing false positives. In
4249-
// other words, we shouldn't penalize a peer if we aren't *sure* they
4250-
// submitted a DoSy tx.
4251-
//
4252-
// Note that m_recent_rejects doesn't just record DoSy or invalid
4253-
// transactions, but any tx not accepted by the mempool, which may be
4254-
// due to node policy (vs. consensus). So we can't blanket penalize a
4255-
// peer simply for relaying a tx that our m_recent_rejects has caught,
4256-
// regardless of false positives.
4257-
42584273
if (state.IsInvalid()) {
4259-
LogPrint(BCLog::MEMPOOLREJ, "%s from peer=%d was not accepted: %s\n", tx.GetHash().ToString(),
4274+
LogPrint(BCLog::MEMPOOLREJ, "%s (wtxid=%s) from peer=%d was not accepted: %s\n",
4275+
tx.GetHash().ToString(),
4276+
tx.GetWitnessHash().ToString(),
42604277
pfrom.GetId(),
42614278
state.ToString());
42624279
MaybePunishNodeForTx(pfrom.GetId(), state);

‎src/txorphanage.cpp‎

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer)
2121
LOCK(m_mutex);
2222

2323
const uint256& hash = tx->GetHash();
24+
const uint256& wtxid = tx->GetWitnessHash();
2425
if (m_orphans.count(hash))
2526
return false;
2627

@@ -34,7 +35,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer)
3435
unsigned int sz = GetTransactionWeight(*tx);
3536
if (sz > MAX_STANDARD_TX_WEIGHT)
3637
{
37-
LogPrint(BCLog::MEMPOOL, "ignoring large orphan tx (size: %u, hash: %s)\n", sz, hash.ToString());
38+
LogPrint(BCLog::TXPACKAGES, "ignoring large orphan tx (size: %u, txid: %s, wtxid: %s)\n", sz, hash.ToString(), wtxid.ToString());
3839
return false;
3940
}
4041

@@ -47,7 +48,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer)
4748
m_outpoint_to_orphan_it[txin.prevout].insert(ret.first);
4849
}
4950

50-
LogPrint(BCLog::MEMPOOL, "stored orphan tx %s (mapsz %u outsz %u)\n", hash.ToString(),
51+
LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (wtxid=%s) (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(),
5152
m_orphans.size(), m_outpoint_to_orphan_it.size());
5253
return true;
5354
}
@@ -83,6 +84,8 @@ int TxOrphanage::EraseTxNoLock(const uint256& txid)
8384
m_orphan_list[old_pos] = it_last;
8485
it_last->second.list_pos = old_pos;
8586
}
87+
const auto& wtxid = it->second.tx->GetWitnessHash();
88+
LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s (wtxid=%s)\n", txid.ToString(), wtxid.ToString());
8689
m_orphan_list.pop_back();
8790
m_wtxid_to_orphan_it.erase(it->second.tx->GetWitnessHash());
8891

@@ -106,7 +109,7 @@ void TxOrphanage::EraseForPeer(NodeId peer)
106109
nErased += EraseTxNoLock(maybeErase->second.tx->GetHash());
107110
}
108111
}
109-
if (nErased > 0) LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx from peer=%d\n", nErased, peer);
112+
if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx from peer=%d\n", nErased, peer);
110113
}
111114

112115
void TxOrphanage::LimitOrphans(unsigned int max_orphans)
@@ -132,7 +135,7 @@ void TxOrphanage::LimitOrphans(unsigned int max_orphans)
132135
}
133136
// Sweep again 5 minutes after the next entry that expires in order to batch the linear scan.
134137
nNextSweep = nMinExpTime + ORPHAN_TX_EXPIRE_INTERVAL;
135-
if (nErased > 0) LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx due to expiration\n", nErased);
138+
if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx due to expiration\n", nErased);
136139
}
137140
FastRandomContext rng;
138141
while (m_orphans.size() > max_orphans)
@@ -142,7 +145,7 @@ void TxOrphanage::LimitOrphans(unsigned int max_orphans)
142145
EraseTxNoLock(m_orphan_list[randompos]->first);
143146
++nEvicted;
144147
}
145-
if (nEvicted > 0) LogPrint(BCLog::MEMPOOL, "orphanage overflow, removed %u tx\n", nEvicted);
148+
if (nEvicted > 0) LogPrint(BCLog::TXPACKAGES, "orphanage overflow, removed %u tx\n", nEvicted);
146149
}
147150

148151
void TxOrphanage::AddChildrenToWorkSet(const CTransaction& tx)
@@ -159,6 +162,8 @@ void TxOrphanage::AddChildrenToWorkSet(const CTransaction& tx)
159162
std::set<uint256>& orphan_work_set = m_peer_work_set.try_emplace(elem->second.fromPeer).first->second;
160163
// Add this tx to the work set
161164
orphan_work_set.insert(elem->first);
165+
LogPrint(BCLog::TXPACKAGES, "added %s (wtxid=%s) to peer %d workset\n",
166+
tx.GetHash().ToString(), tx.GetWitnessHash().ToString(), elem->second.fromPeer);
162167
}
163168
}
164169
}
@@ -233,6 +238,6 @@ void TxOrphanage::EraseForBlock(const CBlock& block)
233238
for (const uint256& orphanHash : vOrphanErase) {
234239
nErased += EraseTxNoLock(orphanHash);
235240
}
236-
LogPrint(BCLog::MEMPOOL, "Erased %d orphan tx included or conflicted by block\n", nErased);
241+
LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx included or conflicted by block\n", nErased);
237242
}
238243
}

‎src/validation.cpp‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1079,9 +1079,11 @@ bool MemPoolAccept::Finalize(const ATMPArgs& args, Workspace& ws)
10791079
// Remove conflicting transactions from the mempool
10801080
for (CTxMemPool::txiter it : ws.m_all_conflicting)
10811081
{
1082-
LogPrint(BCLog::MEMPOOL, "replacing tx %s with %s for %s additional fees, %d delta bytes\n",
1082+
LogPrint(BCLog::MEMPOOL, "replacing tx %s (wtxid=%s) with %s (wtxid=%s) for %s additional fees, %d delta bytes\n",
10831083
it->GetTx().GetHash().ToString(),
1084+
it->GetTx().GetWitnessHash().ToString(),
10841085
hash.ToString(),
1086+
tx.GetWitnessHash().ToString(),
10851087
FormatMoney(ws.m_modified_fees - ws.m_conflicting_fees),
10861088
(int)entry->GetTxSize() - (int)ws.m_conflicting_size);
10871089
TRACE7(mempool, replaced,

‎test/functional/p2p_permissions.py‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ def check_tx_relay(self):
106106

107107
self.log.debug("Check that node[1] will send the tx to node[0] even though it is already in the mempool")
108108
self.connect_nodes(1, 0)
109-
with self.nodes[1].assert_debug_log(["Force relaying tx {} from peer=0".format(txid)]):
109+
with self.nodes[1].assert_debug_log(["Force relaying tx {} (wtxid={}) from peer=0".format(txid, tx.getwtxid())]):
110110
p2p_rebroadcast_wallet.send_txs_and_test([tx], self.nodes[1])
111111
self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
112112

@@ -119,14 +119,14 @@ def check_tx_relay(self):
119119
[tx],
120120
self.nodes[1],
121121
success=False,
122-
reject_reason='{} from peer=0 was not accepted: txn-mempool-conflict'.format(txid)
122+
reject_reason='{} (wtxid={}) from peer=0 was not accepted: txn-mempool-conflict'.format(txid, tx.getwtxid())
123123
)
124124

125125
p2p_rebroadcast_wallet.send_txs_and_test(
126126
[tx],
127127
self.nodes[1],
128128
success=False,
129-
reject_reason='Not relaying non-mempool transaction {} from forcerelay peer=0'.format(txid)
129+
reject_reason='Not relaying non-mempool transaction {} (wtxid={}) from forcerelay peer=0'.format(txid, tx.getwtxid())
130130
)
131131

132132
def checkpermission(self, args, expectedPermissions):

0 commit comments

Comments
 (0)