diff --git a/src/logging.cpp b/src/logging.cpp index 2d98525a3a2a..30cbeeba94f2 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -179,6 +179,8 @@ const CLogCategoryDesc LogCategories[] = #endif {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::TXRECONCILIATION, "txreconciliation"}, + {BCLog::SCAN, "scan"}, + {BCLog::TXPACKAGES, "txpackages"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, @@ -296,6 +298,10 @@ std::string LogCategoryToStr(BCLog::LogFlags category) return "blockstorage"; case BCLog::LogFlags::TXRECONCILIATION: return "txreconciliation"; + case BCLog::LogFlags::SCAN: + return "scan"; + case BCLog::LogFlags::TXPACKAGES: + return "txpackages"; /* Start Dash */ case BCLog::LogFlags::CHAINLOCKS: return "chainlocks"; diff --git a/src/logging.h b/src/logging.h index 2488d056cd79..c1fbb3694929 100644 --- a/src/logging.h +++ b/src/logging.h @@ -67,6 +67,8 @@ namespace BCLog { #endif BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), + SCAN = (uint64_t)1 << 28, + TXPACKAGES = (uint64_t)1 << 29, //Start Dash CHAINLOCKS = ((uint64_t)1 << 32), diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 1d634907c5bc..8aef35018636 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3221,6 +3221,7 @@ void PeerManagerImpl::ProcessOrphanTx(std::set& orphan_work_set) const TxValidationState& state = result.m_state; if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { + LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s\n", orphanHash.ToString()); LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s\n", orphanHash.ToString()); _RelayTransaction(porphanTx->GetHash()); m_orphanage.AddChildrenToWorkSet(*porphanTx, orphan_work_set); @@ -3228,7 +3229,11 @@ void PeerManagerImpl::ProcessOrphanTx(std::set& orphan_work_set) break; } 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::TXPACKAGES, " invalid orphan tx %s from peer=%d. %s\n", + orphanHash.ToString(), + from_peer, + state.ToString()); + LogPrint(BCLog::MEMPOOLREJ, "%s from peer=%d was not accepted: %s\n", orphanHash.ToString(), from_peer, state.ToString()); @@ -3237,6 +3242,7 @@ void PeerManagerImpl::ProcessOrphanTx(std::set& orphan_work_set) } // Has inputs but not accepted to mempool // Probably non-standard or insufficient fee + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s\n", orphanHash.ToString()); LogPrint(BCLog::MEMPOOL, " removed orphan tx %s\n", orphanHash.ToString()); m_recent_rejects.insert(orphanHash); m_orphanage.EraseTx(orphanHash); @@ -4478,12 +4484,29 @@ void PeerManagerImpl::ProcessMessage( // allowing the node to function as a gateway for // nodes hidden behind it. if (!m_mempool.exists(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 from forcerelay peer=%d\n", + tx.GetHash().ToString(), pfrom.GetId()); } else { - LogPrintf("Force relaying tx %s from peer=%d\n", tx.GetHash().ToString(), pfrom.GetId()); + LogPrintf("Force relaying tx %s from peer=%d\n", + tx.GetHash().ToString(), pfrom.GetId()); _RelayTransaction(tx.GetHash()); } } + // 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; } @@ -4555,7 +4578,8 @@ void PeerManagerImpl::ProcessMessage( LogPrint(BCLog::MEMPOOL, "orphanage overflow, removed %u tx\n", nEvicted); } } 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\n", + tx.GetHash().ToString()); // We will continue to reject this tx since it has rejected // parents so avoid re-requesting it from other peers. m_recent_rejects.insert(tx.GetHash()); @@ -4586,7 +4610,8 @@ void PeerManagerImpl::ProcessMessage( // 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 from peer=%d was not accepted: %s\n", + tx.GetHash().ToString(), pfrom.GetId(), state.ToString()); MaybePunishNodeForTx(pfrom.GetId(), state); diff --git a/src/txorphanage.cpp b/src/txorphanage.cpp index ce9d6435ce9f..85faeed55077 100644 --- a/src/txorphanage.cpp +++ b/src/txorphanage.cpp @@ -36,7 +36,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer) unsigned int sz = GetSerializeSize(*tx, CTransaction::CURRENT_VERSION); if (sz > MAX_STANDARD_TX_SIZE) { - LogPrint(BCLog::MEMPOOL, "ignoring large orphan tx (size: %u, hash: %s)\n", sz, hash.ToString()); + LogPrint(BCLog::TXPACKAGES, "ignoring large orphan tx (size: %u, txid: %s)\n", sz, hash.ToString()); return false; } @@ -49,7 +49,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer) m_orphan_tx_size += sz; - LogPrint(BCLog::MEMPOOL, "stored orphan tx %s (mapsz %u outsz %u)\n", hash.ToString(), + LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (mapsz %u outsz %u)\n", hash.ToString(), m_orphans.size(), m_outpoint_to_orphan_it.size()); ::g_stats_client->inc("transactions.orphans.add", 1.0f); ::g_stats_client->gauge("transactions.orphans", m_orphans.size()); @@ -82,6 +82,7 @@ int TxOrphanage::EraseTx(const uint256& 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(); assert(m_orphan_tx_size >= it->second.nTxSize); @@ -106,7 +107,7 @@ void TxOrphanage::EraseForPeer(NodeId peer) nErased += EraseTx(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); } unsigned int TxOrphanage::LimitOrphans(unsigned int max_orphans_size) @@ -132,7 +133,7 @@ unsigned int TxOrphanage::LimitOrphans(unsigned int max_orphans_size) } // 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.empty() && m_orphan_tx_size > max_orphans_size) @@ -142,6 +143,7 @@ unsigned int TxOrphanage::LimitOrphans(unsigned int max_orphans_size) EraseTx(m_orphan_list[randompos]->first); ++nEvicted; } + if (nEvicted > 0) LogPrint(BCLog::TXPACKAGES, "orphanage overflow, removed %u tx\n", nEvicted); return nEvicted; } @@ -153,6 +155,8 @@ void TxOrphanage::AddChildrenToWorkSet(const CTransaction& tx, std::set if (it_by_prev != m_outpoint_to_orphan_it.end()) { for (const auto& elem : it_by_prev->second) { orphan_work_set.insert(elem->first); + LogPrint(BCLog::TXPACKAGES, "added %s to peer %d workset\n", + elem->first.ToString(), elem->second.fromPeer); } } } @@ -222,6 +226,6 @@ void TxOrphanage::EraseForBlock(const CBlock& block) for (const uint256& orphanHash : vOrphanErase) { nErased += EraseTx(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); } } diff --git a/test/functional/p2p_permissions.py b/test/functional/p2p_permissions.py index 53bf2e4f8a58..8a2c3ec1eff2 100755 --- a/test/functional/p2p_permissions.py +++ b/test/functional/p2p_permissions.py @@ -112,7 +112,7 @@ def in_mempool(): self.bump_mocktime(1) return txid in self.nodes[0].getrawmempool() - with self.nodes[1].assert_debug_log(["Force relaying tx {} from peer=0".format(txid)]): + with self.nodes[1].assert_debug_log([f"Force relaying tx {txid} from peer=0"]): p2p_rebroadcast_wallet.send_txs_and_test([tx], self.nodes[1]) self.wait_until(in_mempool) @@ -125,14 +125,14 @@ def in_mempool(): [tx], self.nodes[1], success=False, - reject_reason='{} from peer=0 was not accepted: txn-mempool-conflict'.format(txid) + reject_reason=f"{txid} from peer=0 was not accepted: txn-mempool-conflict", ) 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=f"Not relaying non-mempool transaction {txid} from forcerelay peer=0", ) def checkpermission(self, args, expectedPermissions):