Add validation interface logging (logging)

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

Host: jkczyz  -  PR author: 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

  113:00 <jkczyz> hi
  213:00 <sosthene> nah it certainly comes from my side, happens all the time
  313:00 <lightlike> hi
  413:00 <jnewbery> hi
  513:00 <b10c> hi
  613:00 <udiWertheimer> jnewbery: that’s dedication!
  713:00 <emzy> Hi
  813:01 <jkczyz> As jnewbery noted, I'm guest hosting today. He may be around to help with the finer points :)
  913: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
 1013:01 <jkczyz> Today we’re reviewing PR #16688, which adds logging to validation layer’s event notification
 1113:01 <jkczyz> The validation layer processes blocks and transactions from the net processing layer and updates the validated chain state and mempool
 1213:02 <jkczyz> Any initial thoughts on this PR?
 1313:03 <jnewbery> I think it's great, and definitely going to be helpful for debugging issues as we move towards a more modular architecture
 1413: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
 1513:05 <jkczyz> Alright, let's jump into the questions
 1613:05 <jkczyz> What’s the reason for adding logging to event notification?
 1713:06 <sosthene> I guess it helps debugging?
 1813:07 <jkczyz> sosthene: correct, what sort of issues can it help debug?
 1913:07 <jnewbery> specifically, since the CValidationInterface is asynchronous, it can help with debugging threading issues and race conditions
 2013:07 <lightlike> it helps with error analysis, especially in case of race conditions, which appear in functional tests sometimes.
 2113:07 <emzy> There was a race condition where it would had helpd to debug.
 2213: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.
 2313:08 <jkczyz> jnewbery, emzy: correct! Specifically it could have helped with issue #12978
 2413:08 <jkczyz> https://github.com/bitcoin/bitcoin/issues/12978
 2513:08 <lightlike> ironically, there is a is a race condition in the TSAN Travis build of this PR (which seems unrelated though)
 2613:08 <jkczyz> Here there was a race condition resulting in UpdatedBlockTip() signals delivered out of order
 2713: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)
 2813: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
 2913:10 <jkczyz> lightlike: Yes, appears to be so. I thought about force pushing to see if there was some flakiness to the test
 3013:10 <jnewbery> I've got to head out now. Bye!
 3113:11 <jkczyz> jnewbery: Bye! Thanks for stopping in
 3213:11 <jkczyz> ok, next question: What mechanism is used to notify listeners of validation events?
 3313:11 <lightlike> jkczyz: i looked at it a little. seems related to https://github.com/bitcoin/bitcoin/issues/16133
 3413:12 <jkczyz> lightlike: cool, thanks for investigating! I'll have to look at that issue
 3513:13 <jkczyz> Hint: it uses a third-party library
 3613:15 <lightlike> don't know about it in depth, but via callback functions
 3713:16 <sosthene> I'm not even sure to quite get the question
 3813:16 <jkczyz> lightlike: yes, it uses callbacks, specifically with the boost:signals2 library
 3913:16 <jkczyz> https://www.boost.org/doc/libs/1_71_0/doc/html/signals2.html
 4013:17 <jkczyz> sosthene: The code in question is a bit tricky to reason through. I had to draw out a diagram to be honest!
 4113:17 <jkczyz> https://github.com/bitcoin/bitcoin/blob/d0f81a96d9c158a9226dc946bdd61d48c4d42959/src/validationinterface.cpp
 4213:17 <jkczyz> Ok, let's move on to some more interesting questions
 4313:18 <jkczyz> What code implements CValidationInterface? What does it use event notifications for?
 4413:18 <jkczyz> There are many correct answers to this one
 4513:19 <lightlike> the wallet does, for tracking the status of wallet transactions
 4613:21 <jkczyz> lightlike: yes, though this interface is adapted by NotificationsHandlerImpl for use by the wallet
 4713:21 <jkczyz> https://github.com/bitcoin/bitcoin/blob/9ab9d6356938ffe069ffc005a371d5405976823e/src/interfaces/chain.cpp#L158
 4813:22 <sosthene> what about the networking part? I guess you need to know if a peer is feeding you invalid blocks or tx?
 4913:24 <jkczyz> sosthene: correct, PeerLogicValidation (net processing layer) makes use of notificaitons to send peers new data and to validate peer messages (I believe :)
 5013:25 <jkczyz> On the wallet-side, using event notification helps with separation betweeen node and wallet functionality
 5113:25 <jkczyz> anything else?
 5213:25 <sosthene> I see it implemented in the BaseIndex class too, but I'm not too sure about what it does
 5313:25 <sosthene> https://github.com/bitcoin/bitcoin/blob/e4beef611a423e9f836fa210a51634e94f14d830/src/index/base.h
 5413:26 <jkczyz> sosthene: Good find! It uses BlockConnected and ChainStateFlushed to write to on-disk indexes
 5513:27 <sosthene> I see
 5613:28 <jkczyz> The remaining uses are not as important as these, but they are still interesting to look at
 5713:28 <sosthene> I see it also mentioned in the transaction.h file
 5813:28 <sosthene> https://github.com/bitcoin/bitcoin/blob/be0e8b4bff88b421128239e7140fc6bfdb654806/src/node/transaction.h
 5913:28 <jkczyz> submitblock RPC, ZMQ notificaitons, withing tests.
 6013: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.
 6113:30 <sosthene> lightlike: I don't quite understand sorry, how do we know we have been sent something invalid without involving validationinterface?
 6213: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
 6313: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.
 6413:34 <jkczyz> lightlike: yes, put more eloquently :)
 6513:34 <sosthene> lightlike: ok, it makes more sense, thanks!
 6613:34 <jkczyz> Alright, let's move on
 6713:34 <jkczyz> What is a CBlockLocator? How is it used in this PR? How else is it used?
 6813: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).
 6913:38 <sosthene> I found this, it makes sense with what lightlike says https://github.com/bitcoin/bitcoin/blob/78dae8caccd82cfbfd76557f1fb7d7557c7b5edb/src/primitives/block.h
 7013:39 <jkczyz> lightlike: yes, also in getheaders
 7113: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
 7213:39 <jkczyz> See details: https://en.bitcoin.it/wiki/Protocol_documentation#getblocks
 7313:40 <jkczyz> lightlike: great! I was just about to ask how it was constructed
 7413:40 <jkczyz> Any insight into why it is constructed in that manner?
 7513: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.
 7613:43 <jkczyz> lightlike: good observation! This is a nice way to limit the amount of data exchanged between peers.
 7713:43 <lightlike> jkczyz: do you know if satoshi came up with it?
 7813:44 <jkczyz> The locators are also used when writing to the on-disk block index
 7913: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
 8013:46 <jkczyz> Back to one of the original questions: How is CBlockLocator used in this PR?
 8113:47 <lightlike> just to get the first element (which is the tip)
 8213:48 <sosthene> I see it in ChainStateFlushed, but I don't understand what it does
 8313:48 <jkczyz> lightlike: yup, this is logged as part of ChainStateFlushed.
 8413:50 <sosthene> jkczyz: I got to go, I'll read the transcript to get the end of the story, thank you and see you!
 8513: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
 8613:50 <lightlike> looks like everyone is at Scaling Bitcoin today :-)
 8713:51 <jkczyz> sosthene: thanks for joining!
 8813:51 <jkczyz> lightlike: indeed :)
 8913:51 <jkczyz> Hopefully there are some lurkers following along, too
 9013:52 <jkczyz> ok, let's finish up the last couple questions
 9113:52 <jkczyz> What refactorings are included in this PR?
 9213:53 <jkczyz> Hint: see the commits from the PR
 9313:54 <lightlike> MempoolEntryRemoved is renamed to TransactionRemovedFromMempool, some String functions are changed to return a const ref
 9413:54 <jkczyz> yep, fairly trivial changes but good for code hygiene
 9513:55 <jkczyz> Lastly, as we are running out of time: How can this PR be tested? Could any other tests have been added?
 9613:56 <lightlike> not sure about that one. I think there is some mechanism to check for log messages in functional tests.
 9713:57 <jkczyz> lightlike: yeah, I remember seeing that in the PR that logged bitcoind's args
 9813:58 <jkczyz> Here, I manually verified the logging through the p2p_compactblocks.py functional test
 9913:59 <lightlike> though i am not sure if testing log messages is a bit overkill.
10013:59 <jkczyz> This was the flaky test from issue
10113:59 <jkczyz> issue #12978
10213:59 <jkczyz> https://github.com/bitcoin/bitcoin/issues/12978
10313:59 <jkczyz> lightlike: agreed
10414:00 <jkczyz> Other testing may be unit tests for newly added code
10514:00 <jkczyz> And that's the bell!
10614:00 <jkczyz> Thanks lightlike and sosthene for participating today!
10714: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.
10814:00 <lightlike> thanks jkczyz!
10914: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
11014:01 <jkczyz> So they can be covered in future weeks
11114:01 <jkczyz> lightlike: Thanks! This was fun :)
11214:02 <lightlike> jkczyz: gonna review/ack on github in the next days.