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 [[bitcoin/bitcoin#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

@@ -134,6 +134,7 @@ const CLogCategoryDesc LogCategories[] = {
 #endif
  {BCLog::BLOCKSTORE, "blockstorage"},
  {BCLog::NETDEBUG, "netdebug"},
+ {BCLog::TXPACKAGES, "txpackages"},
  {BCLog::ALL, "1"},
  {BCLog::ALL, "all"},
 };

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),
 };
 

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",

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);
  }