[log] updates in TxOrphanage

- Add elapsed time in "remove orphan" log
- Add size in "stored orphan" log
- grammar edit

Author: glozow

src/txorphanage.cpp

@@ -47,7 +47,7 @@ bool TxOrphanage::AddTx(const CTransactionRef& tx, NodeId peer)
         m_outpoint_to_orphan_it[txin.prevout].insert(ret.first);
     }
 
-    LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (wtxid=%s) (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(),
+    LogPrint(BCLog::TXPACKAGES, "stored orphan tx %s (wtxid=%s), weight: %u (mapsz %u outsz %u)\n", hash.ToString(), wtxid.ToString(), sz,
              m_orphans.size(), m_outpoint_to_orphan_it.size());
     return true;
 }
@@ -84,7 +84,10 @@ int TxOrphanage::EraseTxNoLock(const Wtxid& wtxid)
         it_last->second.list_pos = old_pos;
     }
     const auto& txid = it->second.tx->GetHash();
-    LogPrint(BCLog::TXPACKAGES, "   removed orphan tx %s (wtxid=%s)\n", txid.ToString(), wtxid.ToString());
+    // Time spent in orphanage = difference between current and entry time.
+    // Entry time is equal to ORPHAN_TX_EXPIRE_TIME earlier than entry's expiry.
+    LogPrint(BCLog::TXPACKAGES, "   removed orphan tx %s (wtxid=%s) after %ds\n", txid.ToString(), wtxid.ToString(),
+             GetTime() + ORPHAN_TX_EXPIRE_TIME - it->second.nTimeExpire);
     m_orphan_list.pop_back();
 
     m_orphans.erase(it);
@@ -107,7 +110,7 @@ void TxOrphanage::EraseForPeer(NodeId peer)
             nErased += EraseTxNoLock(wtxid);
         }
     }
-    if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx from peer=%d\n", nErased, peer);
+    if (nErased > 0) LogPrint(BCLog::TXPACKAGES, "Erased %d orphan transaction(s) from peer=%d\n", nErased, peer);
 }
 
 void TxOrphanage::LimitOrphans(unsigned int max_orphans, FastRandomContext& rng)
@@ -230,7 +233,7 @@ void TxOrphanage::EraseForBlock(const CBlock& block)
         for (const auto& orphanHash : vOrphanErase) {
             nErased += EraseTxNoLock(orphanHash);
         }
-        LogPrint(BCLog::TXPACKAGES, "Erased %d orphan tx included or conflicted by block\n", nErased);
+        LogPrint(BCLog::TXPACKAGES, "Erased %d orphan transaction(s) included or conflicted by block\n", nErased);
     }
 }
 

test/functional/p2p_invalid_tx.py

@@ -165,7 +165,7 @@ def run_test(self):
             node.p2ps[0].send_txs_and_test([rejected_parent], node, success=False)
 
         self.log.info('Test that a peer disconnection causes erase its transactions from the orphan pool')
-        with node.assert_debug_log(['Erased 100 orphan tx from peer=25']):
+        with node.assert_debug_log(['Erased 100 orphan transaction(s) from peer=25']):
             self.reconnect_p2p(num_connections=1)
 
         self.log.info('Test that a transaction in the orphan pool is included in a new tip block causes erase this transaction from the orphan pool')
@@ -190,7 +190,7 @@ def run_test(self):
         block_A.solve()
 
         self.log.info('Send the block that includes the previous orphan ... ')
-        with node.assert_debug_log(["Erased 1 orphan tx included or conflicted by block"]):
+        with node.assert_debug_log(["Erased 1 orphan transaction(s) included or conflicted by block"]):
             node.p2ps[0].send_blocks_and_test([block_A], node, success=True)
 
         self.log.info('Test that a transaction in the orphan pool conflicts with a new tip block causes erase this transaction from the orphan pool')
@@ -219,7 +219,7 @@ def run_test(self):
         block_B.solve()
 
         self.log.info('Send the block that includes a transaction which conflicts with the previous orphan ... ')
-        with node.assert_debug_log(["Erased 1 orphan tx included or conflicted by block"]):
+        with node.assert_debug_log(["Erased 1 orphan transaction(s) included or conflicted by block"]):
             node.p2ps[0].send_blocks_and_test([block_B], node, success=True)