#16688 log: Add validation interface logging (logging)
- 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 (
- Clients can subscribe to updates from the validation layer using the
- The validation layer notifies
CValidationInterfacesubscribers 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)
- 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?
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.