#16688 log: Add validation interface logging (logging)

https://github.com/bitcoin/bitcoin/16688

Host: jkczyz

Notes

  • The validation layer enforces Bitcoin’s consensus rules.
  • It processes blocks and transactions from the net processing layer and updates the validated chain state (CChainState) and mempool (CTxMemPool).
  • Clients can subscribe to updates from the validation layer using the CValidationInterface.
  • The validation layer notifies CValidationInterface subscribers whenever the mempool or chainstate is updated. Some interface methods are (see validationinterface.cpp for the full list of interface methods):
    • UpdatedBlockTip (fired once when the block chain is extended with one or more new blocks)
    • BlockConnected (fired once for every block added to the block chain. The notification includes the serialized block with transactions)
    • TransactionAddedToMempool (fired whenever a new transaction is accepted into the mempool. The notification includes the serialized transaction)

Questions

  • What’s the reason for adding logging to event notification?
  • What mechanism is used to notify listeners of validation events?
  • What code implements CValidationInterface? What does it use event notifications for?
  • What is a CBlockLocator? How is it used in this PR? How else is it used?
  • What refactorings are included in this PR?
  • How can this PR be tested? Could any other tests have been added?

Meeting Log

13:00 < jkczyz> hi
13:00 < sosthene> nah it certainly comes from my side, happens all the time
13:00 < lightlike> hi
13:00 < jnewbery> hi
13:00 < b10c> hi
13:00 < udiWertheimer> jnewbery: that’s dedication!
13:00 < emzy> Hi
13:01 < jkczyz> As jnewbery noted, I'm guest hosting today. He may be around to help with the finer points :)
13:01 < jnewbery> udiWertheimer: haha. I'm going to duck out in a few minutes. Just wanted to make sure jkczyz has everything he needs to get started
13:01 < jkczyz> Today we’re reviewing PR #16688, which adds logging to validation layer’s event notification
13:01 < jkczyz> The validation layer processes blocks and transactions from the net processing layer and updates the validated chain state and mempool
13:02 < jkczyz> Any initial thoughts on this PR?
13:03 < jnewbery> I think it's great, and definitely going to be helpful for debugging issues as we move towards a more modular architecture
13:04 < jkczyz> jnewbery: Glad I can help in even a small way! While this is a fairly simple change, there are some lessons we can learn about the code through it
13:05 < jkczyz> Alright, let's jump into the questions
13:05 < jkczyz> What’s the reason for adding logging to event notification?
13:06 < sosthene> I guess it helps debugging?
13:07 < jkczyz> sosthene: correct, what sort of issues can it help debug?
13:07 < jnewbery> specifically, since the CValidationInterface is asynchronous, it can help with debugging threading issues and race conditions
13:07 < lightlike> it helps with error analysis, especially in case of race conditions, which appear in functional tests sometimes.
13:07 < emzy> There was a race condition where it would had helpd to debug.
13:07 < sosthene> In fact I wonder why there wasn't any log to begin with, as it seems a pretty critical part of Bitcoin to me.
13:08 < jkczyz> jnewbery, emzy: correct! Specifically it could have helped with issue #12978
13:08 < jkczyz> https://github.com/bitcoin/bitcoin/issues/12978
13:08 < lightlike> ironically, there is a is a race condition in the TSAN Travis build of this PR (which seems unrelated though)
13:08 < jkczyz> Here there was a race condition resulting in UpdatedBlockTip() signals delivered out of order
13:08 < jnewbery> sosthene: I agree this is critical, but for historic context, the CValidationInterface was updated about a year ago by Matt. Before then, I think it wasn't asynchronous (I may be wrong)
13:09 < jnewbery> bitcoind is (mostly) single threaded on the Message Handler thread. As we try to make it more multi-threaded, better logging at the interfaces is going to be more important
13:10 < jkczyz> lightlike: Yes, appears to be so. I thought about force pushing to see if there was some flakiness to the test
13:10 < jnewbery> I've got to head out now. Bye!
13:11 < jkczyz> jnewbery: Bye! Thanks for stopping in
13:11 < jkczyz> ok, next question: What mechanism is used to notify listeners of validation events?
13:11 < lightlike> jkczyz: i looked at it a little. seems related to https://github.com/bitcoin/bitcoin/issues/16133
13:12 < jkczyz> lightlike: cool, thanks for investigating! I'll have to look at that issue
13:13 < jkczyz> Hint: it uses a third-party library
13:15 < lightlike> don't know about it in depth, but via callback functions
13:16 < sosthene> I'm not even sure to quite get the question
13:16 < jkczyz> lightlike: yes, it uses callbacks, specifically with the boost:signals2 library
13:16 < jkczyz> https://www.boost.org/doc/libs/1_71_0/doc/html/signals2.html
13:17 < jkczyz> sosthene: The code in question is a bit tricky to reason through. I had to draw out a diagram to be honest!
13:17 < jkczyz> https://github.com/bitcoin/bitcoin/blob/d0f81a96d9c158a9226dc946bdd61d48c4d42959/src/validationinterface.cpp
13:17 < jkczyz> Ok, let's move on to some more interesting questions
13:18 < jkczyz> What code implements CValidationInterface? What does it use event notifications for?
13:18 < jkczyz> There are many correct answers to this one
13:19 < lightlike> the wallet does, for tracking the status of wallet transactions
13:21 < jkczyz> lightlike: yes, though this interface is adapted by NotificationsHandlerImpl for use by the wallet
13:21 < jkczyz> https://github.com/bitcoin/bitcoin/blob/9ab9d6356938ffe069ffc005a371d5405976823e/src/interfaces/chain.cpp#L158
13:22 < sosthene> what about the networking part? I guess you need to know if a peer is feeding you invalid blocks or tx?
13:24 < jkczyz> sosthene: correct, PeerLogicValidation (net processing layer) makes use of notificaitons to send peers new data and to validate peer messages (I believe :)
13:25 < jkczyz> On the wallet-side, using event notification helps with separation betweeen node and wallet functionality
13:25 < jkczyz> anything else?
13:25 < sosthene> I see it implemented in the BaseIndex class too, but I'm not too sure about what it does
13:25 < sosthene> https://github.com/bitcoin/bitcoin/blob/e4beef611a423e9f836fa210a51634e94f14d830/src/index/base.h
13:26 < jkczyz> sosthene: Good find! It uses BlockConnected and ChainStateFlushed to write to on-disk indexes
13:27 < sosthene> I see
13:28 < jkczyz> The remaining uses are not as important as these, but they are still interesting to look at
13:28 < sosthene> I see it also mentioned in the transaction.h file
13:28 < sosthene> https://github.com/bitcoin/bitcoin/blob/be0e8b4bff88b421128239e7140fc6bfdb654806/src/node/transaction.h
13:28 < jkczyz> submitblock RPC, ZMQ notificaitons, withing tests.
13:29 < lightlike> sosthene: my understanding is that the validation routines are called from the networking part (net_processing.cpp), and if we are sent something invalid, validationinterface will never be involved.
13:30 < sosthene> lightlike: I don't quite understand sorry, how do we know we have been sent something invalid without involving validationinterface?
13:33 < jkczyz> I may have been mistaken earlier about validating peer messages. Net processing will call the validation layer. Then only if the validation succeeds do subscrivers get notified
13:33 < lightlike> sosthene: we have a network thread that receives the messages. net_processing deals with the logic around these, and if we get a new block or tx, calls procedures in validation. Only if these procedures pass, validation will create signals for validationinterface that are passed on to the wallet etc.
13:34 < jkczyz> lightlike: yes, put more eloquently :)
13:34 < sosthene> lightlike: ok, it makes more sense, thanks!
13:34 < jkczyz> Alright, let's move on
13:34 < jkczyz> What is a CBlockLocator? How is it used in this PR? How else is it used?
13:37 < lightlike> jkczyz: i have encountered it in networking/getblocks messages, where it is used to determine the point up to which the chains of two peers are identical (for example in IBD when one peer has only part of the chain).
13:38 < sosthene> I found this, it makes sense with what lightlike says https://github.com/bitcoin/bitcoin/blob/78dae8caccd82cfbfd76557f1fb7d7557c7b5edb/src/primitives/block.h
13:39 < jkczyz> lightlike: yes, also in getheaders
13:39 < lightlike> https://github.com/bitcoin/bitcoin/blob/78dae8caccd82cfbfd76557f1fb7d7557c7b5edb/src/chain.cpp#L23 shows the logic behind it, how the internal vector of block hashes is filled
13:39 < jkczyz> See details: https://en.bitcoin.it/wiki/Protocol_documentation#getblocks
13:40 < jkczyz> lightlike: great! I was just about to ask how it was constructed
13:40 < jkczyz> Any insight into why it is constructed in that manner?
13:42 < lightlike> i think it's quite elegant, with the exponential thinning out: most of the time, two peers are just a few blocks away, so all the recent blocks are there. in rarer cases, where the chains differ strongly, multiple locators need to be exchanged to get the highest common block.
13:43 < jkczyz> lightlike: good observation! This is a nice way to limit the amount of data exchanged between peers.
13:43 < lightlike> jkczyz: do you know if satoshi came up with it?
13:44 < jkczyz> The locators are also used when writing to the on-disk block index
13:45 < jkczyz> lightlike: I'm afraid that predates my involvement. :) Checking out Github's blame layer might help determine the origin, though you may have to do some code archeology as the code has probably been moved from other files
13:46 < jkczyz> Back to one of the original questions: How is CBlockLocator used in this PR?
13:47 < lightlike> just to get the first element (which is the tip)
13:48 < sosthene> I see it in ChainStateFlushed, but I don't understand what it does
13:48 < jkczyz> lightlike: yup, this is logged as part of ChainStateFlushed.
13:50 < sosthene> jkczyz: I got to go, I'll read the transcript to get the end of the story, thank you and see you!
13:50 < jkczyz> sosthene: My understanding is that this is written to the on-disk index. I may be mistaken so others may correct me, but I believe this will give a compact path of block back to the genessis block
13:50 < lightlike> looks like everyone is at Scaling Bitcoin today :-)
13:51 < jkczyz> sosthene: thanks for joining!
13:51 < jkczyz> lightlike: indeed :)
13:51 < jkczyz> Hopefully there are some lurkers following along, too
13:52 < jkczyz> ok, let's finish up the last couple questions
13:52 < jkczyz> What refactorings are included in this PR?
13:53 < jkczyz> Hint: see the commits from the PR
13:54 < lightlike> MempoolEntryRemoved is renamed to TransactionRemovedFromMempool, some String functions are changed to return a const ref
13:54 < jkczyz> yep, fairly trivial changes but good for code hygiene
13:55 < jkczyz> Lastly, as we are running out of time: How can this PR be tested? Could any other tests have been added?
13:56 < lightlike> not sure about that one. I think there is some mechanism to check for log messages in functional tests.
13:57 < jkczyz> lightlike: yeah, I remember seeing that in the PR that logged bitcoind's args
13:58 < jkczyz> Here, I manually verified the logging through the p2p_compactblocks.py functional test
13:59 < lightlike> though i am not sure if testing log messages is a bit overkill.
13:59 < jkczyz> This was the flaky test from issue
13:59 < jkczyz> issue #12978
13:59 < jkczyz> https://github.com/bitcoin/bitcoin/issues/12978
13:59 < jkczyz> lightlike: agreed
14:00 < jkczyz> Other testing may be unit tests for newly added code
14:00 < jkczyz> And that's the bell!
14:00 < jkczyz> Thanks lightlike and sosthene for participating today!
14:00 < lightlike> by the way you don't have to force push for a new travis run. you could ask in #bitcoin-core-dev, several people can restart it.
14:00 < lightlike> thanks jkczyz!
14:01 < jkczyz> As jnewbery would want, please added any interesting PR's to https://github.com/bitcoin-core-review-club/bitcoin-core-review-club.github.io/issues/14
14:01 < jkczyz> So they can be covered in future weeks
14:01 < jkczyz> lightlike: Thanks! This was fun :)
14:02 < lightlike> jkczyz: gonna review/ack on github in the next days.