Add validation interface logging (
logging) Sep 11, 2019
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
CValidationInterface subscribers whenever the mempool or chainstate is updated. Some interface methods are (see
validationinterface.cpp for the full list of interface methods):
(fired once when the block chain is extended with one or more new blocks)
(fired once for every block added to the block chain. The notification includes the serialized block with transactions)
(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
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?
2 13:00 <sosthene> nah it certainly comes from my side, happens all the time
6 13:00 <udiWertheimer> jnewbery: that’s dedication!
8 13:01 <jkczyz> As jnewbery noted, I'm guest hosting today. He may be around to help with the finer points :)
9 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
10 13:01 <jkczyz> Today we’re reviewing PR #16688, which adds logging to validation layer’s event notification
11 13:01 <jkczyz> The validation layer processes blocks and transactions from the net processing layer and updates the validated chain state and mempool
12 13:02 <jkczyz> Any initial thoughts on this PR?
13 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
14 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
15 13:05 <jkczyz> Alright, let's jump into the questions
16 13:05 <jkczyz> What’s the reason for adding logging to event notification?
17 13:06 <sosthene> I guess it helps debugging?
18 13:07 <jkczyz> sosthene: correct, what sort of issues can it help debug?
19 13:07 <jnewbery> specifically, since the CValidationInterface is asynchronous, it can help with debugging threading issues and race conditions
20 13:07 <lightlike> it helps with error analysis, especially in case of race conditions, which appear in functional tests sometimes.
21 13:07 <emzy> There was a race condition where it would had helpd to debug.
22 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.
23 13:08 <jkczyz> jnewbery, emzy: correct! Specifically it could have helped with issue #12978
25 13:08 <lightlike> ironically, there is a is a race condition in the TSAN Travis build of this PR (which seems unrelated though)
26 13:08 <jkczyz> Here there was a race condition resulting in UpdatedBlockTip() signals delivered out of order
27 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)
28 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
29 13:10 <jkczyz> lightlike: Yes, appears to be so. I thought about force pushing to see if there was some flakiness to the test
30 13:10 <jnewbery> I've got to head out now. Bye!
31 13:11 <jkczyz> jnewbery: Bye! Thanks for stopping in
32 13:11 <jkczyz> ok, next question: What mechanism is used to notify listeners of validation events?
34 13:12 <jkczyz> lightlike: cool, thanks for investigating! I'll have to look at that issue
35 13:13 <jkczyz> Hint: it uses a third-party library
36 13:15 <lightlike> don't know about it in depth, but via callback functions
37 13:16 <sosthene> I'm not even sure to quite get the question
38 13:16 <jkczyz> lightlike: yes, it uses callbacks, specifically with the boost:signals2 library
40 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!
42 13:17 <jkczyz> Ok, let's move on to some more interesting questions
43 13:18 <jkczyz> What code implements CValidationInterface? What does it use event notifications for?
44 13:18 <jkczyz> There are many correct answers to this one
45 13:19 <lightlike> the wallet does, for tracking the status of wallet transactions
46 13:21 <jkczyz> lightlike: yes, though this interface is adapted by NotificationsHandlerImpl for use by the wallet
48 13:22 <sosthene> what about the networking part? I guess you need to know if a peer is feeding you invalid blocks or tx?
49 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 :)
50 13:25 <jkczyz> On the wallet-side, using event notification helps with separation betweeen node and wallet functionality
51 13:25 <jkczyz> anything else?
52 13:25 <sosthene> I see it implemented in the BaseIndex class too, but I'm not too sure about what it does
54 13:26 <jkczyz> sosthene: Good find! It uses BlockConnected and ChainStateFlushed to write to on-disk indexes
56 13:28 <jkczyz> The remaining uses are not as important as these, but they are still interesting to look at
57 13:28 <sosthene> I see it also mentioned in the transaction.h file
59 13:28 <jkczyz> submitblock RPC, ZMQ notificaitons, withing tests.
60 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.
61 13:30 <sosthene> lightlike: I don't quite understand sorry, how do we know we have been sent something invalid without involving validationinterface?
62 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
63 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.
64 13:34 <jkczyz> lightlike: yes, put more eloquently :)
65 13:34 <sosthene> lightlike: ok, it makes more sense, thanks!
66 13:34 <jkczyz> Alright, let's move on
67 13:34 <jkczyz> What is a CBlockLocator? How is it used in this PR? How else is it used?
68 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).
70 13:39 <jkczyz> lightlike: yes, also in getheaders
73 13:40 <jkczyz> lightlike: great! I was just about to ask how it was constructed
74 13:40 <jkczyz> Any insight into why it is constructed in that manner?
75 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.
76 13:43 <jkczyz> lightlike: good observation! This is a nice way to limit the amount of data exchanged between peers.
77 13:43 <lightlike> jkczyz: do you know if satoshi came up with it?
78 13:44 <jkczyz> The locators are also used when writing to the on-disk block index
79 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
80 13:46 <jkczyz> Back to one of the original questions: How is CBlockLocator used in this PR?
81 13:47 <lightlike> just to get the first element (which is the tip)
82 13:48 <sosthene> I see it in ChainStateFlushed, but I don't understand what it does
83 13:48 <jkczyz> lightlike: yup, this is logged as part of ChainStateFlushed.
84 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!
85 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
86 13:50 <lightlike> looks like everyone is at Scaling Bitcoin today :-)
87 13:51 <jkczyz> sosthene: thanks for joining!
88 13:51 <jkczyz> lightlike: indeed :)
89 13:51 <jkczyz> Hopefully there are some lurkers following along, too
90 13:52 <jkczyz> ok, let's finish up the last couple questions
91 13:52 <jkczyz> What refactorings are included in this PR?
92 13:53 <jkczyz> Hint: see the commits from the PR
93 13:54 <lightlike> MempoolEntryRemoved is renamed to TransactionRemovedFromMempool, some String functions are changed to return a const ref
94 13:54 <jkczyz> yep, fairly trivial changes but good for code hygiene
95 13:55 <jkczyz> Lastly, as we are running out of time: How can this PR be tested? Could any other tests have been added?
96 13:56 <lightlike> not sure about that one. I think there is some mechanism to check for log messages in functional tests.
97 13:57 <jkczyz> lightlike: yeah, I remember seeing that in the PR that logged bitcoind's args
98 13:58 <jkczyz> Here, I manually verified the logging through the p2p_compactblocks.py functional test
99 13:59 <lightlike> though i am not sure if testing log messages is a bit overkill.
100 13:59 <jkczyz> This was the flaky test from issue
101 13:59 <jkczyz> issue #12978
103 13:59 <jkczyz> lightlike: agreed
104 14:00 <jkczyz> Other testing may be unit tests for newly added code
105 14:00 <jkczyz> And that's the bell!
106 14:00 <jkczyz> Thanks lightlike and sosthene for participating today!
107 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.
108 14:00 <lightlike> thanks jkczyz!
110 14:01 <jkczyz> So they can be covered in future weeks
111 14:01 <jkczyz> lightlike: Thanks! This was fun :)
112 14:02 <lightlike> jkczyz: gonna review/ack on github in the next days.