log: mempool: log removal reason in validation interface #26419

jamesob commented at 12:12 AM on October 29, 2022: member

Currently the exact reason a transaction is removed from the mempool isn't logged. It is sometimes detectable from context, but adding the reason to the validation interface logs (where it is already passed) seems like an easy way to disambiguate.

For example in the case of mempool expiry, the logs look like this:

[validationinterface.cpp:220] [TransactionRemovedFromMempool] [validation] Enqueuing TransactionRemovedFromMempool: txid=<txid> wtxid=<wtxid>
[txmempool.cpp:1050] [RemoveUnbroadcastTx] [mempool] Removed <txid> from set of unbroadcast txns before confirmation that txn was sent out
[validationinterface.cpp:220] [operator()] [validation] TransactionRemovedFromMempool: txid=<txid> wtxid=<wtxid>
[validation.cpp:267] [LimitMempoolSize] [mempool] Expired 1 transactions from the memory pool

There is no context-free way to know $txid was evicted on the basis of expiry. This change will make that case (and probably others) clear.

DrahtBot added the label Utils/log/libs on Oct 29, 2022

0xB10C commented at 10:05 AM on October 30, 2022: contributor

Concept ACK!

jamesob force-pushed on Nov 3, 2022

in src/txmempool.cpp:1243 in d76405729d outdated

1237 | +        case MemPoolRemovalReason::REORG: return "reorg";
1238 | +        case MemPoolRemovalReason::BLOCK: return "block";
1239 | +        case MemPoolRemovalReason::CONFLICT: return "conflict";
1240 | +        case MemPoolRemovalReason::REPLACED: return "replaced";
1241 | +    }
1242 | +    return "unknown";

stickies-v commented at 4:37 PM on November 3, 2022:

Any downside to using Assert instead so we have better observability when this fn goes out of sync with MemPoolRemovalReason?

    Assert(false);

jamesob commented at 6:17 PM on November 3, 2022:

We have to add a return to avoid CI failures, but I think that assert is a great idea. Will add.

stickies-v commented at 6:02 PM on November 3, 2022: contributor

Approach ACK d76405729d2cc369437af798ff1962e7bd481dde

Better logging is always worthwhile.

jamesob force-pushed on Nov 3, 2022

in src/txmempool.cpp:1243 in f26105859f outdated

1238 | +        case MemPoolRemovalReason::BLOCK: return "block";
1239 | +        case MemPoolRemovalReason::CONFLICT: return "conflict";
1240 | +        case MemPoolRemovalReason::REPLACED: return "replaced";
1241 | +    }
1242 | +    Assert(false);
1243 | +    return "unknown";

maflcko commented at 6:27 PM on November 3, 2022:

    assert(false);

nit: This should be shorter and pass CI

jamesob commented at 6:39 PM on November 3, 2022:

Let's give it a whirl

jamesob force-pushed on Nov 3, 2022

stickies-v commented at 7:46 PM on November 3, 2022: contributor

Rebase to master should fix the CI issue (https://github.com/bitcoin/bitcoin/commit/fa590cfaae887c927ffb4af92a15516332428d69)

jamesob force-pushed on Nov 3, 2022

stickies-v approved

stickies-v commented at 10:14 PM on November 3, 2022: contributor

ACK f58c3a4

DrahtBot commented at 11:36 AM on November 4, 2022: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#26152 (Bump unconfirmed ancestor transactions to target feerate by Xekyo)

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.

log: mempool: log removal reason in validation interface

Currently the exact reason a transaction is removed from the mempool isn't
logged. It is sometimes detectable from context, but adding the `reason` to
the validation interface logs (where it is already passed) seems like an easy
way to disambiguate.

For example, in the case of mempool expiry, the logs look like this:

```
[validationinterface.cpp:220] [TransactionRemovedFromMempool] [validation] Enqueuing TransactionRemovedFromMempool: txid=<txid> wtxid=<wtxid>
[txmempool.cpp:1050] [RemoveUnbroadcastTx] [mempool] Removed <txid> from set of unbroadcast txns before confirmation that txn was sent out
[validationinterface.cpp:220] [operator()] [validation] TransactionRemovedFromMempool: txid=<txid> wtxid=<wtxid>
[validation.cpp:267] [LimitMempoolSize] [mempool] Expired 1 transactions from the memory pool
```

There is no context-free way to know $txid was evicted on the basis of expiry.
This change will make that case (and probably others) clear.

25ef049d60

in src/validationinterface.h:23 in f58c3a47f8 outdated

  19 | @@ -20,6 +20,7 @@ struct CBlockLocator;
  20 |  class CValidationInterface;
  21 |  class CScheduler;
  22 |  enum class MemPoolRemovalReason;
  23 | +const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;

0xB10C commented at 12:50 PM on November 4, 2022:

This spews a bunch of redundant-decls warnings when compiling for me. I tried dropping it, but that doesn't work.

In file included from ./validation.h:28,
                 from ./rpc/blockchain.h:13,
                 from rest.cpp:19:
./txmempool.h:358:19: warning: redundant redeclaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’ in same scope [-Wredundant-decls]
  358 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
In file included from ./index/base.h:11,
                 from ./index/blockfilterindex.h:12,
                 from rest.cpp:13:
./validationinterface.h:23:19: note: previous declaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’
   23 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
  CXX      rpc/libbitcoin_node_a-net.o
In file included from ./index/base.h:11,
                 from ./index/blockfilterindex.h:12,
                 from rpc/blockchain.cpp:20:
./validationinterface.h:23:19: warning: redundant redeclaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’ in same scope [-Wredundant-decls]
   23 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
In file included from ./validation.h:28,
                 from ./rpc/blockchain.h:13,
                 from rpc/blockchain.cpp:6:
./txmempool.h:358:19: note: previous declaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’
  358 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
  CXX      rpc/libbitcoin_node_a-node.o
In file included from rpc/mining.cpp:38:
./validationinterface.h:23:19: warning: redundant redeclaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’ in same scope [-Wredundant-decls]
   23 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
In file included from ./node/miner.h:10,
                 from rpc/mining.cpp:19:
./txmempool.h:358:19: note: previous declaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’
  358 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
  CXX      rpc/libbitcoin_node_a-output_script.o
In file included from ./validation.h:28,
                 from ./rpc/blockchain.h:13,
                 from rpc/net.cpp:18:
./txmempool.h:358:19: warning: redundant redeclaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’ in same scope [-Wredundant-decls]
  358 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
In file included from ./net_processing.h:10,
                 from rpc/net.cpp:13:
./validationinterface.h:23:19: note: previous declaration of ‘const string RemovalReasonToString(const MemPoolRemovalReason&)’
   23 | const std::string RemovalReasonToString(const MemPoolRemovalReason& r) noexcept;
      |                   ^~~~~~~~~~~~~~~~~~~~~
  CXX      rpc/libbitcoin_node_a-rawtransaction.o
  CXX      rpc/libbitcoin_node_a-server.o
...

0xB10C commented at 1:02 PM on November 4, 2022:

with gcc 11.3.0 and -Wredundant-decls in CXXFLAGS

0xB10C commented at 1:10 PM on November 4, 2022:

~no warnings with gcc 10.3.0~ nvm warnings with gcc 10.3.0 too

jamesob force-pushed on Nov 4, 2022

jamesob commented at 1:39 PM on November 4, 2022: member

@0xB10C ah, thanks for testing with gcc. Pushed a fix.

0xB10C commented at 2:55 PM on November 4, 2022: contributor

ACK 25ef049d60535ac02508ba71ef60f17d8349f120

Reviewed changes, built, and manually tested that the correct reason appears in the debug.logs of the regtest nodes spawned by the mempool_expiry.py and mempool_limit.py functional tests.

josibake commented at 2:58 PM on November 4, 2022: member

Concept ACK

will review in depth later today!

maflcko merged this on Nov 5, 2022

maflcko closed this on Nov 5, 2022

sidhujag referenced this in commit c9ab68b078 on Nov 6, 2022

bitcoin locked this on Nov 5, 2023