This was taken from #28031 (see #27463 for project tracking).
TXPACKAGES category for logging.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--021abf342d371248e50ceaed478a90ca-->
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | instagibbs, brunoerg, mzumsande, achow101 |
| Concept ACK | jonatack |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
<!--174a7506f384e20aa4161008e828411d-->
Reviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.
2918 | @@ -2919,9 +2919,10 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer)
2919 | const MempoolAcceptResult result = m_chainman.ProcessTransaction(porphanTx);
in [log] include wtxid in tx {relay,validation,orphanage} logging
looks like we're missing one wtxid logging event here:
https://github.com/glozow/bitcoin/blob/2023-08-log-wtxids/src/net_processing.cpp#L4224
thanks, added wtxid to that log :+1:
Oops, I added it with wtxid before txid :scream: . Fixed. Good thing we added tests eh
4134 | @@ -4135,6 +4135,21 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, 4135 | RelayTransaction(tx.GetHash(), tx.GetWitnessHash()); 4136 | } 4137 | } 4138 | + // If a tx has been detected by m_recent_rejects, it is ignored. Because we haven't
Ok I finally understand what this comment is saying, yay. In my words:
We stop processing a transaction if we currently have it in mempool or it is detected in m_recent_rejects.
Recall that m_recent_rejects can have false positives, so in this case we cannot safely
punish the peer without further processing, which we are explicitly avoiding with this cache.
:+1:
ACK 17e327d95ae9e55353f94acee126b227cf906c3f
modulo that one missing log, for completeness
- 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.
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.
118 | @@ -119,14 +119,14 @@ def check_tx_relay(self): 119 | [tx], 120 | self.nodes[1], 121 | success=False, 122 | - reject_reason='{} from peer=0 was not accepted: txn-mempool-conflict'.format(txid) 123 | + reject_reason='{} (wtxid={}) from peer=0 was not accepted: txn-mempool-conflict'.format(txid, tx.getwtxid())
nit: we could also change it to use f-strings instead of format given it touches this line.
Will keep this in mind for the future. I'm just sticking with how this string was formatted previously.
crACK a3b55c94b9ffde07386aa887149ddca91b364967
Code looks great and m_recent_rejects check is done into AlreadyHaveTx so the local change makes sense for me. I just was in doubt if this comment could be in AlreadyHaveTx but seems ok to leave it in net_processing side.
83 | @@ -84,6 +84,8 @@ int TxOrphanage::EraseTxNoLock(const uint256& txid) 84 | m_orphan_list[old_pos] = it_last; 85 | it_last->second.list_pos = old_pos; 86 | } 87 | + const auto& wtxid = it->second.tx->GetWitnessHash(); 88 | + LogPrint(BCLog::TXPACKAGES, " removed orphan tx %s (wtxid=%s)\n", txid.ToString(), wtxid.ToString()); 89 | m_orphan_list.pop_back(); 90 | m_wtxid_to_orphan_it.erase(it->second.tx->GetWitnessHash());
nit: could use the newly introduced wtxid in this line too.
Will do in the next PR, as it touches this line :+1:
Code review ACK a3b55c94b9ffde07386aa887149ddca91b364967
2918 | @@ -2919,9 +2919,15 @@ bool PeerManagerImpl::ProcessOrphanTx(Peer& peer) 2919 | const MempoolAcceptResult result = m_chainman.ProcessTransaction(porphanTx); 2920 | const TxValidationState& state = result.m_state; 2921 | const uint256& orphanHash = porphanTx->GetHash(); 2922 | + const uint256& orphan_wtxid = porphanTx->GetWitnessHash(); 2923 | 2924 | if (result.m_result_type == MempoolAcceptResult::ResultType::VALID) { 2925 | - LogPrint(BCLog::MEMPOOL, " accepted orphan tx %s\n", orphanHash.ToString()); 2926 | + LogPrint(BCLog::TXPACKAGES, " accepted orphan tx %s (wtxid=%s)\n", orphanHash.ToString(), orphan_wtxid.ToString()); 2927 | + LogPrint(BCLog::MEMPOOL, "AcceptToMemoryPool: peer=%d: accepted %s (wtxid=%s) (poolsz %u txn, %u kB)\n",
For added or updated logging, it would help the migration to severity level logging if LogPrintLevel instead of LogPrint was used, either with debug or trace levels depending on e.g. log frequency.
For more context, LogPrintLevel may eventually become the principal or only logging macro, and at some point could be renamed to just Log, so using it for new logging would make the transition easier.
I'm not familiar with the migration you're referring to, could you link a PR/issue where I can see the changes and motivation? It's not clear to me why I should change this PR for it.
#25203 has been ongoing since a year and a half and several initial steps have been merged. The blocker since March has been #27231, though given how long it has remained open I'll probably begin to work around it.
By using the new macros, there is less to update later on, and you are able to decide now the log level per message of your added logging.
67 | @@ -68,6 +68,7 @@ namespace BCLog { 68 | BLOCKSTORAGE = (1 << 26), 69 | TXRECONCILIATION = (1 << 27), 70 | SCAN = (1 << 28), 71 | + TXPACKAGES = (1 << 29),
A possible alternative to adding a category would be to distinguish these from the other mempool logs via debug vs trace levels, if applicable.
User-facing naming suggestion, here and for "txpackages" in logging.cpp, categories tend to be named in the singular.
TXPACKAGE = (1 << 29),
I prefer txpackages. There's plenty of places where a log pertains to multiple packages.
Concept ACK, happy to see improved or more useful logging.
ACK a3b55c94b9ffde07386aa887149ddca91b364967