log: Add validation interface logging #16688

pull jkczyz wants to merge 4 commits into bitcoin:master from jkczyz:2019-08-validation-logging changing 5 files +67 −16
  1. jkczyz commented at 10:08 pm on August 22, 2019: contributor

    Add logging of CValidationInterface callbacks using a new VALIDATION log flag (see #12994). A separate flag is desirable as the logging can be noisy and thus may need to be disabled without affecting other logging.

    This could help debug issues where there may be race conditions at play, such as #12978.

  2. fanquake added the label Utils/log/libs on Aug 22, 2019
  3. fanquake added the label Validation on Aug 22, 2019
  4. in src/validationinterface.cpp:12 in e13e0f85dc outdated
     4@@ -5,9 +5,13 @@
     5 
     6 #include <validationinterface.h>
     7 
     8+#include <chain.h>
     9+#include <logging.h>
    10 #include <primitives/block.h>
    11+#include <primitives/transaction.h>
    


    ariard commented at 0:21 am on August 23, 2019:
    Compiling without including transaction header (already included in txmempool.h)

    hebasto commented at 7:12 am on August 23, 2019:

    From the Developer Notes - Source code organization:

    • Every .cpp and .h file should #include every header file it directly uses classes, functions or other definitions from, even if those headers are already included indirectly through other headers.
      • Rationale: Excluding headers because they are already indirectly included results in compilation failures when those indirect dependencies change. Furthermore, it obscures what the real code dependencies are.

    ariard commented at 1:56 pm on August 23, 2019:
    Ah thanks, didn’t know it!
  5. DrahtBot commented at 0:52 am on August 23, 2019: member

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

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #17562 (WIP: Validation: Remove ConnectTrace and PerBlockConnectTrace by jnewbery)
    • #17477 (Remove the mempool’s NotifyEntryAdded and NotifyEntryRemoved signals by jnewbery)
    • #17399 (validation: Templatize ValidationState instead of subclassing by jkczyz)
    • #16365 (Log RPC parameters (arguments) if -debug=rpcparams by LarryRuane)

    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.

  6. in src/validationinterface.cpp:140 in e13e0f85dc outdated
    136@@ -133,47 +137,62 @@ void CMainSignals::UpdatedBlockTip(const CBlockIndex *pindexNew, const CBlockInd
    137     // the chain actually updates. One way to ensure this is for the caller to invoke this signal
    138     // in the same critical section where the chain is updated
    139 
    140-    m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
    141+    auto func = __func__;
    


    ariard commented at 0:56 am on August 23, 2019:
    What’s the rational defining func instead of directly as LogPrint arg ?

    jkczyz commented at 3:58 pm on August 26, 2019:

    Using it directly will give the name of the lambda, i.e. operator(), which is not desirable.

    Ideally, I could use __func__ in the lambda capture. However, this is not allowed because it has static storage duration. With C++14, we could use capture initializers instead.

  7. in src/validationinterface.cpp:142 in e13e0f85dc outdated
    136@@ -133,47 +137,62 @@ void CMainSignals::UpdatedBlockTip(const CBlockIndex *pindexNew, const CBlockInd
    137     // the chain actually updates. One way to ensure this is for the caller to invoke this signal
    138     // in the same critical section where the chain is updated
    139 
    140-    m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
    141+    auto func = __func__;
    142+    m_internals->m_schedulerClient.AddToProcessQueue([func, pindexNew, pindexFork, fInitialDownload, this] {
    143+        if (pindexFork) LogPrint(BCLog::VALIDATIONINTERFACE, "%s: fork block hash=%s\n", func, pindexFork->GetBlockHash().ToString());
    


    ariard commented at 0:59 am on August 23, 2019:
    Could you use a ternary to check pindexFork instead of two call to LogPrint? Also fInitialDownload could be logged

    jkczyz commented at 6:07 pm on September 3, 2019:
    Good call! I had misinterpreted the frequency of this being non-null. Fixed in 4bacb54.
  8. in src/validationinterface.cpp:169 in e13e0f85dc outdated
    168 
    169 void CMainSignals::BlockConnected(const std::shared_ptr<const CBlock> &pblock, const CBlockIndex *pindex, const std::shared_ptr<const std::vector<CTransactionRef>>& pvtxConflicted) {
    170-    m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, pvtxConflicted, this] {
    171+    auto func = __func__;
    172+    m_internals->m_schedulerClient.AddToProcessQueue([func, pblock, pindex, pvtxConflicted, this] {
    173+        LogPrint(BCLog::VALIDATIONINTERFACE, "%s: block hash=%s\n", func, pblock->GetHash().ToString());
    


    ariard commented at 1:03 am on August 23, 2019:
    Thanks to pindex, maybe log the height too

    jkczyz commented at 6:07 pm on September 3, 2019:
    Added in 4bacb54.
  9. in src/validationinterface.cpp:187 in e13e0f85dc outdated
    186 
    187 void CMainSignals::ChainStateFlushed(const CBlockLocator &locator) {
    188-    m_internals->m_schedulerClient.AddToProcessQueue([locator, this] {
    189+    auto func = __func__;
    190+    m_internals->m_schedulerClient.AddToProcessQueue([func, locator, this] {
    191+        LogPrint(BCLog::VALIDATIONINTERFACE, "%s: block hash=%s\n", func, locator.IsNull() ? "null" : locator.vHave.front().ToString());
    


    ariard commented at 1:09 am on August 23, 2019:
    nit: maybe “top block hash %s bottom block hash”

    jkczyz commented at 9:55 pm on August 28, 2019:
    I believe the bottom block hash will always be the genesis block hash, so logging it probably won’t be very useful. Plus it may be a little confusing given only the top block is being flushed.
  10. in src/validationinterface.cpp:160 in e13e0f85dc outdated
    158 void CMainSignals::TransactionRemovedFromMempool(CTransactionRef ptx, MemPoolRemovalReason reason) {
    159     if (reason != MemPoolRemovalReason::BLOCK && reason != MemPoolRemovalReason::CONFLICT) {
    160-        m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] {
    161+        auto func = __func__;
    162+        m_internals->m_schedulerClient.AddToProcessQueue([func, ptx, this] {
    163+            LogPrint(BCLog::VALIDATIONINTERFACE, "%s: tx hash=%s\n", func, ptx->GetHash().ToString());
    


    ariard commented at 1:11 am on August 23, 2019:
    You may add MemPoolRemovalReasonString somewhere, like TransactionErrorString in util/error.cp. IMO that’s an interesting info to log

    jkczyz commented at 6:07 pm on September 3, 2019:
    Done in 504d009.
  11. ariard commented at 1:21 am on August 23, 2019: member

    Tested validationinterface log flag with both cli option and logging RPC. Worked as expected.

    Nice to have more logging around the validation callbacks, order of events may be so confusing!

  12. jnewbery commented at 5:56 pm on August 24, 2019: member
    Concept ACK
  13. jkczyz force-pushed on Sep 3, 2019
  14. jkczyz commented at 6:14 pm on September 3, 2019: contributor

    Addressed all comments and add correct formatting for valid CValidationState in b303865.

    Also updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying. Although this means the references are only valid for the lifetime of the object, which should be okay.

  15. in src/validationinterface.cpp:142 in b303865bc6 outdated
    146     // in the same critical section where the chain is updated
    147 
    148-    m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
    149+    auto func = __func__;
    150+    m_internals->m_schedulerClient.AddToProcessQueue([func, pindexNew, pindexFork, fInitialDownload, this] {
    151+        LogPrint(BCLog::VALIDATIONINTERFACE, "%s: new block hash=%s fork block hash=%s initial download=%d\n", func,
    


    jnewbery commented at 8:59 pm on October 8, 2019:

    nit: Refer to this as “IBD” or “Initial Block Download” rather than “initial download”. I suggest: "%s: new block hash=%s fork block hash=%s (In IBD=%d)\n" or similar.

    (These are low-level logs. Anyone reading them should understand what IBD means.

  16. in src/validationinterface.cpp:153 in b303865bc6 outdated
    158 
    159 void CMainSignals::TransactionAddedToMempool(const CTransactionRef &ptx) {
    160-    m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] {
    161+    auto func = __func__;
    162+    m_internals->m_schedulerClient.AddToProcessQueue([func, ptx, this] {
    163+        LogPrint(BCLog::VALIDATIONINTERFACE, "%s: tx hash=%s\n", func, ptx->GetHash().ToString());
    


    jnewbery commented at 9:06 pm on October 8, 2019:
    nit: call this the ’txid’ instead of ’tx hash’, and also log the wtxid (use GetWitnessHash())
  17. in src/txmempool.cpp:1108 in b303865bc6 outdated
    1099@@ -1098,3 +1100,22 @@ void CTxMemPool::SetIsLoaded(bool loaded)
    1100 }
    1101 
    1102 SaltedTxidHasher::SaltedTxidHasher() : k0(GetRand(std::numeric_limits<uint64_t>::max())), k1(GetRand(std::numeric_limits<uint64_t>::max())) {}
    1103+
    1104+std::string MemPoolRemovalReasonString(const MemPoolRemovalReason reason)
    1105+{
    1106+    switch (reason) {
    1107+    case MemPoolRemovalReason::EXPIRY:
    1108+        return "Expired from mempool";
    


    jnewbery commented at 9:11 pm on October 8, 2019:

    nit: I think these strings could just be EXPIRY, SIZELIMIT, etc. These strings are for logs only, so will only be read by engineers.

    Trying to make these strings more generally accessible obscures some of the nuance. For example MemPoolRemovalReason::REORG means that a transaction was removed during a re-org because it spent a coinbase transaction that is no longer mature, or because it is no longer final, or because mempool policy changed since it first entered the mempool so it can no longer be added or because the re-org was too large and we dropped transactions to avoid memory exhaustion.

  18. in src/validationinterface.cpp:141 in b303865bc6 outdated
    145     // the chain actually updates. One way to ensure this is for the caller to invoke this signal
    146     // in the same critical section where the chain is updated
    147 
    148-    m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
    149+    auto func = __func__;
    150+    m_internals->m_schedulerClient.AddToProcessQueue([func, pindexNew, pindexFork, fInitialDownload, this] {
    


    jnewbery commented at 9:37 pm on October 8, 2019:
    For all of these async validationinterface callbacks, I think it’d be useful to log both when the event is enqueued and dequeued, with some kind of counter to correlate the two logs. Thoughts?

    jkczyz commented at 0:01 am on October 16, 2019:

    The scheduler client guarantees these callbacks are executed serially in the order in which they were enqueued. Unless there is a need to correlate the enqueuing with the execution of BlockChecked and NewPowValidBlock, I’m hesitant to add more complexity to the code.

    Is there a specific case where you think the additional logging would be useful? If so, would correlation using data from the log message be sufficient rather than adding a counter?


    jnewbery commented at 3:35 pm on October 16, 2019:

    I think this: #12978 (comment) would have been easier to spot with logging when the callbacks were enqueued, and it would have been easier to correlate those enqueue events with the thread that was running.

    You’re probably right that there’s no need for a counter and that the data from the log message is enough to correlate the enqueue/dequeue events.


    jkczyz commented at 7:11 pm on October 17, 2019:
    Done. In order to avoid duplicating the logging code, I added some private template methods declared in the header and defined in the implementation file. The linker seems ok with this though let me know if there is a better way. Defining the helpers in the header would have required moving MainSignalsInstance into the header.

    jkczyz commented at 10:11 pm on October 17, 2019:

    FYI, I had to make some minor changes to placate the linter. It was giving the following failures:

    0src/validationinterface.cpp: Expected 0 argument(s) after format string but found 1 argument(s): LogPrint(BCLog::VALIDATIONINTERFACE, fmt, args...)
    1^---- failure generated from test/lint/lint-format-strings.sh
    2All calls to LogPrintf() and LogPrint() should be terminated with \n
    3src/validationinterface.cpp:    LogPrint(BCLog::VALIDATIONINTERFACE, fmt, args...);
    4^---- failure generated from test/lint/lint-logs.sh
    

    https://travis-ci.org/bitcoin/bitcoin/jobs/599302990


    mzumsande commented at 11:06 pm on October 18, 2019:

    In order to avoid duplicating the logging code, I added some private template methods declared in the header and defined in the implementation file. The linker seems ok with this(…)

    This could lead to portability issues, see e.g. https://stackoverflow.com/questions/495021/why-can-templates-only-be-implemented-in-the-header-file. I tried something similar recently in another PR, and the linker in one of the Travis runs did complain, so I am also interested to know if there are better solutions than moving stuff into the header.


    jkczyz commented at 0:38 am on October 19, 2019:
    Yeah, that could very well be the case. That said, if we want to avoid argument evaluation when the logging category is not enabled, I would need to turn these into macros. See discussion starting in #16688 (comment). Then I could remove those template method declarations from the header.

    jnewbery commented at 6:02 pm on October 21, 2019:
    This does indeed seem to have caused a build failure: https://travis-ci.org/bitcoin/bitcoin/jobs/600461225

    jkczyz commented at 6:40 pm on October 21, 2019:
    Indeed. It seems variadic arguments within lambda captures are not supported by that compilation environment. At least that’s what I’ve gleaned from a similar issue (https://github.com/Ultimaker/CuraEngine/issues/426#issuecomment-269451925). However, this shouldn’t be a problem if I change it into a macro.

    jkczyz commented at 11:14 pm on October 30, 2019:

    Turns out changing EnqueueAndLogEvent into a macro has some implications that are making this infeasible. Consider:

     0#define ENQUEUE_AND_LOG_EVENT(event, fmt, ...)                                             \
     1    do {                                                                                   \
     2        LOG_EVENT("Enqueuing " fmt, __VA_ARGS__);                                          \
     3        m_internals->m_schedulerClient.AddToProcessQueue([event, fmt, __VA_ARGS__, this] { \
     4            LOG_EVENT(fmt, __VA_ARGS__);                                                   \
     5            event();                                                                       \
     6        });                                                                                \
     7    } while (0)
     8
     9#define LOG_EVENT(fmt, ...) \
    10    LogPrint(BCLog::VALIDATIONINTERFACE, fmt "\n", __VA_ARGS__);
    

    The problem is that the capture list is expecting variables but the call sites are providing expressions. So unfortunately this won’t compile. Presumably, if this did work, the expressions in the lambda would be evaluated thus defeating the purpose.

    Unless there is a creative solution that I’m unaware of, the only alternative I can think of is to forgo the macro and duplicate the LogPrint for the enqueuing in each method. Thoughts?


    jkczyz commented at 0:30 am on October 31, 2019:
    Actually, it looks like using a default capture instead of __VA_ARGS__ will do what I need!

    jkczyz commented at 6:23 pm on October 31, 2019:
    Implemented as a macro in 6ab424c.
  19. jnewbery commented at 9:39 pm on October 8, 2019: member
    I’ve partially reviewed and left a few comments inline. I intend to finish review and test this week.
  20. jnewbery commented at 10:03 pm on October 9, 2019: member

    I did some light testing and this looks good. If you wanted to add automated tests, take a look at assert_debug_log() in the TestNode object. That allows you to test that specific strings have been written to the debug log.

    updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying.

    Was this required for the PR? Those accessors aren’t used very much, so performance isn’t critical. I’d suggest not changing them in this PR.

  21. jkczyz force-pushed on Oct 17, 2019
  22. jkczyz force-pushed on Oct 17, 2019
  23. jkczyz commented at 7:40 pm on October 17, 2019: contributor

    I did some light testing and this looks good. If you wanted to add automated tests, take a look at assert_debug_log() in the TestNode object. That allows you to test that specific strings have been written to the debug log.

    I would be hesitant to add a functional test only to check for informational logging. Is there an existing a test where all these events are exercised? Not sure if it is worth adding regardless.

    updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying.

    Was this required for the PR? Those accessors aren’t used very much, so performance isn’t critical. I’d suggest not changing them in this PR.

    Yeah, commit 72c6e50 calls those methods in such a way that not returning references would have incurred excessive copies. Would it be better if the two commits were merged?

  24. jkczyz force-pushed on Oct 17, 2019
  25. jkczyz commented at 10:33 pm on October 17, 2019: contributor

    @jnewbery I have some concerns about this additional logging. Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category. This was not the case prior to that PR since a macro was used for logging.

    Given the heavy amount of logging added in this PR, should the function vs macro approach for logging be revisited? Typically, the use of macros in logging libraries is to avoid such argument evaluation if I understand correctly.

  26. MarcoFalke commented at 1:03 pm on October 18, 2019: member

    Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category.

    Huh? They were passed to strprintf before and after that change, but strprintf was only called when logging was enabled. I don’t see how that pull changed anything.

  27. jkczyz commented at 4:36 pm on October 18, 2019: contributor

    Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category.

    Huh? They were passed to strprintf before and after that change, but strprintf was only called when logging was enabled. I don’t see how that pull changed anything.

    By evaluation I mean at the call site of LogPrint. While this doesn’t make a difference when passing variables, it does matter when the arguments are calls to other functions. Prior to #14209, the latter would be textually included when used and thus not evaluated if logging was not enabled for the given category.

  28. MarcoFalke commented at 4:57 pm on October 18, 2019: member
    Ah, right
  29. in src/consensus/validation.h:141 in 515e3ee7fa outdated
    136@@ -137,8 +137,8 @@ class CValidationState {
    137     }
    138     ValidationInvalidReason GetReason() const { return m_reason; }
    139     unsigned int GetRejectCode() const { return chRejectCode; }
    140-    std::string GetRejectReason() const { return strRejectReason; }
    141-    std::string GetDebugMessage() const { return strDebugMessage; }
    142+    const std::string& GetRejectReason() const { return strRejectReason; }
    143+    const std::string& GetDebugMessage() const { return strDebugMessage; }
    


    practicalswift commented at 3:56 pm on October 19, 2019:
    Why this change? :)

    jkczyz commented at 6:08 pm on October 19, 2019:
    See #16688 (comment). @jnewbery Regarding my previous comment, I’m also happy to remove this commit if that’s preferred. Seems I had not read your comment closely enough about it not being performance critical. Though note my concerns about macro vs function logging.

    practicalswift commented at 6:34 pm on October 19, 2019:

    What is the object lifetime of strRejectReason and strDebugMessage?

    Are they guaranteed to outlive the callers of GetRejectReason or GetDebugMessage?


    jkczyz commented at 1:45 am on October 20, 2019:
    Their lifetimes are that of the corresponding CValidationState as mentioned in #16688 (comment). All current uses are guaranteed to outlive the callers as they either make a copy or are passed by const reference to other functions that do something similar. There’s no such guarantee for future callers though.

    practicalswift commented at 2:12 pm on October 20, 2019:

    I don’t think 6c730c3926d1871d8ce4c63eb6752808d7c3484a is a good idea: it introduces a very sharp edge in consensus critical code which is not offset by any measurable gain AFAICT.

    We should always err on the side of caution when touching consensus critical code: if there is a trade-off between safety (current or future) and speed, then safety is generally much more important. In the cases where speed is critical for some reasons we should always measure before optimising :)

    Somewhat related: https://www.youtube.com/watch?v=3MB2iiCkGxg&t=870


    jkczyz commented at 9:27 pm on October 20, 2019:
    Fair enough. I’ve removed 6c730c3.
  30. in src/txmempool.cpp:1121 in deb243ef87 outdated
    1114+        return "BLOCK";
    1115+    case MemPoolRemovalReason::CONFLICT:
    1116+        return "CONFLICT";
    1117+    case MemPoolRemovalReason::REPLACED:
    1118+        return "REPLACED";
    1119+    }
    


    hebasto commented at 4:40 pm on October 20, 2019:
    0    } // no default case, so the compiler can warn about missing cas
    

    See: Developer Notes - switch statement on an enumeration example


    jkczyz commented at 8:02 pm on November 22, 2019:
    No longer needed since rebasing removed the need for this code.
  31. in src/validationinterface.cpp:208 in b6bc83628f outdated
    215+    LogEvent("%s: block hash=%s", __func__, block->GetHash().ToString());
    216     m_internals->NewPoWValidBlock(pindex, block);
    217 }
    218+
    219+template <typename... Args>
    220+void CMainSignals::EnqueueAndLogEvent(std::function<void ()> event, const char* fmt, const Args&... args) {
    


    hebasto commented at 5:09 pm on October 20, 2019:
    Could event parameter be a const reference?

    jkczyz commented at 6:23 pm on October 31, 2019:
    No longer applicable as this is now a macros in 6ab424c.
  32. hebasto changes_requested
  33. hebasto commented at 5:25 pm on October 20, 2019: member
    IMO, 6c730c3926d1871d8ce4c63eb6752808d7c3484a commit is outside the original PR goal. Also string (i.e., basic_string<char>) offers move semantics; so it can be efficiently return by value.
  34. jkczyz force-pushed on Oct 20, 2019
  35. jkczyz force-pushed on Oct 20, 2019
  36. jkczyz commented at 9:35 pm on October 20, 2019: contributor

    IMO, 6c730c3 commit is outside the original PR goal. Also string (i.e., basic_string<char>) offers move semantics; so it can be efficiently return by value.

    I removed the commit. But I don’t believe move semantics apply here as the function is returning a member variable.

  37. jnewbery commented at 6:18 pm on October 21, 2019: member

    I removed the commit. (https://github.com/bitcoin/bitcoin/commit/6c730c3926d1871d8ce4c63eb6752808d7c3484a)

    Thanks!

    I’ve tested this and it works great. I think we need to resolve this question: #16688 (comment) before merging this PR. It seems reasonable to me to change logging back to using a macro for the reasons you suggest. Adding a GetHash() call to every validation interface call, even when logging is disabled, seems a shame. I’d be happy to review a PR that does that.

    Rename CMainSignals::MempoolEntryRemoved to TransactionRemovedFromMempool and Format CValidationState properly in all cases could be pulled out into their own PR while we’re waiting for that, although note that Format CValidationState properly in all cases conflicts with https://github.com/bitcoin/bitcoin/pull/17004/commits/0053e16714323c1694c834fdca74f064a1a33529.

  38. jkczyz commented at 0:01 am on October 22, 2019: contributor

    I’ve tested this and it works great. I think we need to resolve this question: #16688 (comment) before merging this PR. It seems reasonable to me to change logging back to using a macro for the reasons you suggest. Adding a GetHash() call to every validation interface call, even when logging is disabled, seems a shame. I’d be happy to review a PR that does that. @jnewbery Will do. @MarcoFalke I’m not sure I follow the part about “unnecessary branches are not analyzed” in #14209. If I were to make LogPrint (but not LogPrintf) a macro again, will I need to define it conditionally based on USE_COVERAGE as was done in c8914b9?

  39. MarcoFalke commented at 12:47 pm on October 22, 2019: member
    If you revert #14209, please make it as slim as possible (without the USE_COVERAGE guard, which mostly did only harm)
  40. jnewbery commented at 2:42 pm on October 22, 2019: member

    I would be hesitant to add a functional test only to check for informational logging. Is there an existing a test where all these events are exercised? Not sure if it is worth adding regardless.

    Yeah, I agree that this isn’t necessary.

  41. jkczyz referenced this in commit 93e8f7a833 on Oct 22, 2019
  42. jkczyz referenced this in commit 8734c856f8 on Oct 22, 2019
  43. DrahtBot added the label Needs rebase on Oct 24, 2019
  44. jkczyz force-pushed on Oct 31, 2019
  45. jkczyz force-pushed on Oct 31, 2019
  46. jkczyz force-pushed on Oct 31, 2019
  47. jkczyz force-pushed on Oct 31, 2019
  48. jkczyz force-pushed on Oct 31, 2019
  49. jkczyz force-pushed on Oct 31, 2019
  50. DrahtBot removed the label Needs rebase on Oct 31, 2019
  51. jkczyz commented at 6:29 pm on October 31, 2019: contributor

    Rename CMainSignals::MempoolEntryRemoved to TransactionRemovedFromMempool and Format CValidationState properly in all cases could be pulled out into their own PR while we’re waiting for that, although note that Format CValidationState properly in all cases conflicts with 0053e16.

    I’ve rebased and resolved the conflict now that your change has been merged. The PR should be ready for any last comments. Also, will need reviews of #17218. :)

  52. MarcoFalke referenced this in commit 90a2341713 on Nov 1, 2019
  53. sidhujag referenced this in commit 30e410619b on Nov 1, 2019
  54. jnewbery commented at 3:12 pm on November 1, 2019: member

    It appears that the function name isn’t being captured properly:

    02019-11-01T15:06:44.834237Z [loadblk] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0
    12019-11-01T15:06:44.834255Z [loadblk] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=1)
    22019-11-01T15:06:44.834276Z [init] block tree size = 1
    32019-11-01T15:06:44.834283Z [init] nBestHeight = 0
    42019-11-01T15:06:44.834338Z [init] Bound to 127.0.0.1:11625
    52019-11-01T15:06:44.834350Z [init] init message: Loading P2P addresses...
    62019-11-01T15:06:44.834367Z [init] ERROR: DeserializeFileDB: Failed to open file /tmp/user/1000/bitcoin_func_test_if8trhon/node0/regtest/peers.dat
    72019-11-01T15:06:44.834438Z [init] Invalid or missing peers.dat; recreating
    82019-11-01T15:06:44.834758Z [scheduler] operator(): block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0
    92019-11-01T15:06:44.834919Z [scheduler] operator(): new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=1)
    

    Those last two lines should show BlockConnected and UpdatedBlockTip

  55. jkczyz force-pushed on Nov 1, 2019
  56. jkczyz commented at 8:32 pm on November 1, 2019: contributor

    It appears that the function name isn’t being captured properly:

    Fixed in 9eb373c.

  57. in src/validationinterface.cpp:124 in 9eb373c07a outdated
    142+// evaluating arguments when logging is not enabled.
    143+//
    144+// NOTE: The lambda captures all local variables by value.
    145+#define ENQUEUE_AND_LOG_EVENT(event, fmt, name, ...)           \
    146+    do {                                                       \
    147+        auto local_name = (name);                              \
    


    jnewbery commented at 8:58 pm on November 1, 2019:
    At this point, it might just be easier to hard-code the function name into the log strings, or do you see a down-side to that?

    jkczyz commented at 10:09 pm on November 1, 2019:

    The downside is that the logging can go out of sync if the method is renamed (like in dd2855d) and that the format string is longer.

    Note this implementation was used in an earlier version of the PR: #16688#pullrequestreview-278747465 (see second outdated comment). It was no longer needed when I added a helper method but needed again once I switched to a macro.

  58. in src/validationinterface.cpp:146 in 9eb373c07a outdated
    166-    });
    167+    };
    168+    ENQUEUE_AND_LOG_EVENT(event, "%s: new block hash=%s fork block hash=%s (in IBD=%d)", __func__,
    169+                          pindexNew->GetBlockHash().ToString(),
    170+                          pindexFork ? pindexFork->GetBlockHash().ToString() : "null",
    171+                          fInitialDownload);
    


    jnewbery commented at 8:21 pm on November 4, 2019:
    nit: fInitialDownload ? 'true' : 'false'

    jkczyz commented at 6:37 pm on November 5, 2019:

    Done in f871e27 by changing %d to %s, as tinyformat does the conversion if using that specifier.

    https://github.com/c42f/tinyformat#special-cases-for-p-c-and-s

  59. in src/validationinterface.cpp:200 in 9eb373c07a outdated
    210+    auto event = [pblock, this] {
    211         m_internals->BlockDisconnected(pblock);
    212-    });
    213+    };
    214+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s", __func__,
    215+                          pblock->GetHash().ToString());
    


    jnewbery commented at 8:31 pm on November 4, 2019:
    Observation: This should be updated to also log the height when #15931 is merged (specifically commit https://github.com/bitcoin/bitcoin/pull/15931/commits/7d0f76a83e50328aaa8e7836b533ea0ea10d3c53)

    jkczyz commented at 6:39 pm on November 5, 2019:
    ACK. Happy to wait for that to be merged if you prefer.

    jnewbery commented at 11:36 am on November 8, 2019:
    #15931 is merged

    jkczyz commented at 10:52 pm on November 8, 2019:
    Updated in 741cab0.
  60. jnewbery commented at 8:49 pm on November 4, 2019: member

    Tested ACK 9eb373c07ad78448ea78eee97d1ee9b9b409b4b9

    One personal-style-preference nit, which you should feel free to ignore.

    I’ve run several functional tests with this and manually tested it with a regtest node. It’s really illuminating to see where the CValidationInterface callbacks are being enqueued and then called.

    Really great stuff @jkczyz . Thanks for persisting with this!

  61. jkczyz force-pushed on Nov 5, 2019
  62. jkczyz force-pushed on Nov 5, 2019
  63. jnewbery commented at 6:41 pm on November 5, 2019: member
    Tested ACK f871e272a1e4bd2b1c8b474416ee8eb065ef4e2c
  64. in src/txmempool.h:357 in 454caa12c2 outdated
    355@@ -356,6 +356,8 @@ enum class MemPoolRemovalReason {
    356     REPLACED,    //!< Removed for replacement
    357 };
    358 
    359+std::string MemPoolRemovalReasonString(const MemPoolRemovalReason reason);
    


    ariard commented at 10:14 pm on November 5, 2019:
    nit: const?

    jkczyz commented at 11:21 pm on November 5, 2019:
    Do you mean remove the const from the parameter?

    ariard commented at 1:14 am on November 6, 2019:
    Nevermind, that’s not a class method, useless to put const in function signature
  65. in src/validationinterface.cpp:118 in f871e272a1 outdated
    130@@ -126,52 +131,90 @@ void SyncWithValidationInterfaceQueue() {
    131     promise.get_future().wait();
    132 }
    133 
    134+// Use a macro instead of a function for conditional logging to prevent
    


    ariard commented at 10:20 pm on November 5, 2019:
    Not a C++ expert, could you explain or point to why macro prevent to evaluate argument there? I mean aren’t they replaced at preprocessing and we know flag only at runtime?

    sipa commented at 10:41 pm on November 5, 2019:

    compare the macro expansion:

    0if (debug_foo) {
    1    LogPrintf("Foobar %i", ExpensiveToComputeFunction());
    2}
    

    with

    0LogPrint(BCLog::FOO, "Foobar %i", ExpensiveToComputeFunction());
    

    In the first example, ExpensiveToComputeFunction is not invoked if debug_foo is false. In the second one it’s invoked, but then disregarded by LogPrint.


    ariard commented at 11:06 pm on November 5, 2019:

    Thanks but got it, LogPrint has been changed to a macro in #17218, was still thinking it was a function…

    That’s said shouldn’t we use the LOG_PRINT convention as for any other macro ?


    jkczyz commented at 4:57 am on November 7, 2019:
    I’m using the convention in this PR but did not change it in the referenced PR for LogPrint since it was simply partially reverting a commit. It would have been a much larger change to update all the call sites, and that’s something I’d be hesitant in undertaking without enough support for the change.
  66. ariard commented at 10:35 pm on November 5, 2019: member
    Tested with -debug=validationinterface set, print messages as expected. Holding my ACK on answer on the macro question.
  67. ariard commented at 11:09 pm on November 5, 2019: member
    Tested ACK f871e27
  68. DrahtBot added the label Needs rebase on Nov 8, 2019
  69. jnewbery commented at 8:47 pm on November 8, 2019: member
    Rebased on master and added height logging to BlockDisconnected here: https://github.com/jnewbery/bitcoin/tree/pr16688.1 . Feel free to take it!
  70. jkczyz force-pushed on Nov 8, 2019
  71. jnewbery commented at 11:25 pm on November 8, 2019: member

    Tested ACK 741cab0a7dcfe07860db8ad73678fbfde7eb6ada

    Your latest push has different emails for the Author and Committer in the commits. I’m not sure if that was intentional or you want to change it back.

  72. DrahtBot removed the label Needs rebase on Nov 8, 2019
  73. DrahtBot added the label Needs rebase on Nov 10, 2019
  74. jkczyz force-pushed on Nov 11, 2019
  75. jkczyz force-pushed on Nov 11, 2019
  76. jkczyz commented at 9:21 pm on November 11, 2019: contributor

    Tested ACK 741cab0

    Your latest push has different emails for the Author and Committer in the commits. I’m not sure if that was intentional or you want to change it back.

    Updated and rebased.

  77. DrahtBot removed the label Needs rebase on Nov 11, 2019
  78. jnewbery commented at 10:12 pm on November 11, 2019: member
    ACK cd6bf9970fdebc878cfc2d3b80bfc6cd4d39ffd7
  79. ariard commented at 4:42 pm on November 14, 2019: member
    ACK cd6bf99. Change since last time is block height in BlockDisconnected log.
  80. DrahtBot added the label Needs rebase on Nov 22, 2019
  81. jkczyz force-pushed on Nov 22, 2019
  82. DrahtBot removed the label Needs rebase on Nov 22, 2019
  83. jkczyz commented at 8:11 pm on November 22, 2019: contributor
    Rebased and resolved merge conflicts. The commits for formatting MemPoolRemovalReason and renaming CMainSignals::MempoolEntryRemoved have been removed since #14384 made them obsolete. But just realized @jnewbery asked to have the reason added in this PR if the #14384 was merged first.
  84. jnewbery commented at 8:40 pm on November 22, 2019: member

    @jnewbery asked to have the reason added in this PR

    It’s not essential but I think logging the reason is definitely a nice-to-have. None of the clients need access to the reason (yet) so it could just be logged and dropped in the validationinterface.

  85. jkczyz force-pushed on Nov 22, 2019
  86. jkczyz commented at 9:24 pm on November 22, 2019: contributor

    It’s not essential but I think logging the reason is definitely a nice-to-have. None of the clients need access to the reason (yet) so it could just be logged and dropped in the validationinterface.

    Done in 34d6486.

  87. jnewbery commented at 9:43 pm on November 22, 2019: member
    Tested ACK 34d6486de309d24d040a900fe3492582dc6bbb45
  88. jnewbery commented at 9:48 pm on November 22, 2019: member
    I’d love to see this merged soon. Once you’ve had validationinterface logging for test debugging, you don’t want to go back!
  89. jkczyz commented at 1:23 am on November 23, 2019: contributor

    The linter says 34d6486 introduced a circular dependency:

    0A new circular dependency in the form of "txmempool -> validationinterface -> txmempool" appears to have been introduced.
    

    To break this, I’d have to move both MemPoolRemovalReason and MemPoolRemovalReasonString elsewhere. Thoughts?

  90. jnewbery commented at 3:09 am on November 23, 2019: member

    To break this, I’d have to move both MemPoolRemovalReason and MemPoolRemovalReasonString elsewhere. Thoughts?

    Just remove that commit. No need to make this PR more complex just to log the removal reason. It can be done in a follow-up.

  91. jkczyz force-pushed on Nov 23, 2019
  92. jnewbery commented at 3:28 pm on November 25, 2019: member
    Tested ACK 0cadb123b
  93. ariard commented at 7:26 pm on November 25, 2019: member
    ACK 0cadb12, only changes are dropping commits/removing arg following #14384 merge
  94. hebasto commented at 9:10 pm on December 21, 2019: member
    Concept ACK. Will test.
  95. hebasto commented at 8:50 am on December 22, 2019: member

    There are some code organization concerns.

    I believe that headers and forward class declaration should not be touched in the “Format CValidationState properly in all cases” commit (ee4d66a38c5c09161f8a3e63047db6b6908687f4).

    Instead, <consensus/validation.h> should be included to validationinterface.cpp in the “Add logging for CValidationInterface events” commit (0cadb123bad37a2c224834a3d98bed474c661c21).

  96. hebasto changes_requested
  97. hebasto commented at 10:57 am on December 22, 2019: member

    Tested on Linux Mint 19.3. It works as expected.

    The only suggestion: #16688 (comment)

  98. in src/logging.cpp:165 in 389d423a25 outdated
    161@@ -162,6 +162,7 @@ const CLogCategoryDesc LogCategories[] =
    162     {BCLog::COINDB, "coindb"},
    163     {BCLog::QT, "qt"},
    164     {BCLog::LEVELDB, "leveldb"},
    165+    {BCLog::VALIDATIONINTERFACE, "validationinterface"},
    


    ryanofsky commented at 10:08 pm on December 26, 2019:

    In commit “Add VALIDATIONINTERFACE to BCLog::LogFlags” (389d423a252e43d0b08871f8ae5b66a84a8a217c)

    Would change names to VALIDATION, "validation". These are just validation events. Fact that they are printed in the validationinterface source file instead of the validation one is an implementation detail that could change and would be arcane to someone just trying to configure logging categories.

  99. in src/util/validation.h:11 in ee4d66a38c outdated
     5@@ -6,9 +6,9 @@
     6 #ifndef BITCOIN_UTIL_VALIDATION_H
     7 #define BITCOIN_UTIL_VALIDATION_H
     8 
     9-#include <string>
    10+#include <consensus/validation.h>
    11 
    12-class ValidationState;
    


    ryanofsky commented at 10:12 pm on December 26, 2019:

    In commit “Format CValidationState properly in all cases” (ee4d66a38c5c09161f8a3e63047db6b6908687f4)

    Replacing forward declaration with a full include seems unnecessary here, just making the diff bigger and perhaps unnecessarily slowing down compilation.

  100. in src/util/validation.cpp:20 in ee4d66a38c outdated
    19+    }
    20+
    21+    const std::string debug_message = state.GetDebugMessage();
    22+    if (!debug_message.empty()) {
    23+        return strprintf("%s, %s", state.GetRejectReason(), debug_message);
    24+    }
    


    ryanofsky commented at 10:22 pm on December 26, 2019:

    In commit “Format CValidationState properly in all cases” (ee4d66a38c5c09161f8a3e63047db6b6908687f4)

    I’m a little confused by all the changes in this commit. As far as I can tell the only change that affects behavior is adding if (state.IsValid()) return "Valid"; at the top of this function, and everything else is a rewrite / style cleanup. Not a big deal, but in the future it might be good to fully motivate changes in the commit description or do style changes in separate commits.

  101. in src/validationinterface.cpp:175 in 0cadb123ba outdated
    181 }
    182 
    183-void CMainSignals::BlockDisconnected(const std::shared_ptr<const CBlock>& pblock, const CBlockIndex* pindex)
    184-{
    185-    m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, this] {
    186+void CMainSignals::BlockDisconnected(const std::shared_ptr<const CBlock>& pblock, const CBlockIndex* pindex) {
    


    ryanofsky commented at 10:27 pm on December 26, 2019:

    In commit “Add logging for CValidationInterface events” (0cadb123bad37a2c224834a3d98bed474c661c21)

    Whitespace is changing unnecessarily (and format is nonstandard, brace should go on new line)


    jkczyz commented at 7:10 pm on January 3, 2020:

    I was largely trying to avoid style changes and conform with the local conventions in the file. However, in the interim the brace was moved in https://github.com/bitcoin/bitcoin/commit/10b4729e33f76092bd8cfa06d1a5e0a066436f76#diff-e8d9e22d9683f73a9fb8399be0dab640R159 to use the standard conventions.

    Not sure what is preferred, but I don’t mind changing it back to reduce the diff size.

  102. ryanofsky approved
  103. ryanofsky commented at 10:38 pm on December 26, 2019: member
    Code review ACK 0cadb123bad37a2c224834a3d98bed474c661c21. Nice change! I left some suggestions, but feel free to ignore them.
  104. Add VALIDATION to BCLog::LogFlags
    This flag is for logging from within CValidationInterface (see #12994).
    A separate flag is desirable as the logging can be noisy and thus may
    need to be disabled without affecting other logging.
    428ac70095
  105. Format CValidationState properly in all cases
    FormatStateMessage does not properly handle the case where
    CValidationState::IsValid() returns true. Use "Valid" for the state in
    this case.
    72f3227c83
  106. Refactor FormatStateMessage for clarity
    All cases of CValidationState were condensed into one strprintf call.
    This is no longer suitable as more cases are added (e.g., IsValid).
    6edebacb21
  107. Add logging for CValidationInterface events
    This could help debug issues where there may be race conditions at play,
    such as #12978.
    
    Fixes #12994.
    f9abf4ab6d
  108. jkczyz force-pushed on Jan 3, 2020
  109. jkczyz commented at 8:17 pm on January 3, 2020: contributor
    @hebasto @ryanofsky Thanks for the review! I’ve addressed all comments.
  110. jnewbery commented at 9:07 pm on January 3, 2020: member
    ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f
  111. hebasto commented at 10:06 pm on January 3, 2020: member
    ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f
  112. ariard commented at 11:10 pm on January 3, 2020: member
    ACK f9abf4a, only changes since 0cadb12 are replacing log indication VALIDATIONINTERFACE by VALIDATION and avoiding a forward declaration with a new include
  113. ryanofsky approved
  114. ryanofsky commented at 9:23 pm on January 8, 2020: member
    Code review ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f. Just suggested changes since last review (thanks!)
  115. laanwj referenced this in commit e7f8450357 on Jan 9, 2020
  116. laanwj merged this on Jan 9, 2020
  117. laanwj closed this on Jan 9, 2020

  118. sidhujag referenced this in commit 9d38d10d6e on Jan 9, 2020
  119. jonatack commented at 11:34 pm on January 9, 2020: member

    ACK e7f84503571c171a7e6728cd2d77dd4103bd7a6f posthumous code review and manual tests.

    Usage listed here for visitor convenience (the PR description was not updated from validationinterface to validation):

    • bitcoind -help | grep -B6 ", validation"
    0  -debug=<category>
    1       Output debugging information (default: -nodebug, supplying <category> is
    2       optional). If <category> is not supplied or if <category> = 1,
    3       output all debugging information. <category> can be: net, tor,
    4       mempool, http, bench, zmq, walletdb, rpc, estimatefee, addrman,
    5       selectcoins, reindex, cmpctblock, rand, prune, proxy, mempoolrej,
    6       libevent, coindb, qt, leveldb, validation.
    
    • bitcoind -debug=validation (launch bitcoind with validation logging)
    • bitcoin-cli help logging
    • bitcoin-cli logging [] '["validation"]' (toggle validation logging off)
    • bitcoin-cli logging '["validation"]' (toggle validation logging on)
  120. luke-jr referenced this in commit 4dd2f82dad on Jan 12, 2020
  121. luke-jr referenced this in commit 28a17585d4 on Feb 9, 2020
  122. deadalnix referenced this in commit 04394f92dc on Jun 19, 2020
  123. jasonbcox referenced this in commit c3bbc613c4 on Jul 14, 2020
  124. sidhujag referenced this in commit 98e750b015 on Nov 10, 2020
  125. sidhujag referenced this in commit 496411c6bc on Nov 10, 2020
  126. PastaPastaPasta referenced this in commit d15f179eeb on Sep 11, 2021
  127. PastaPastaPasta referenced this in commit 940ae481be on Sep 11, 2021
  128. PastaPastaPasta referenced this in commit 4055086f17 on Sep 12, 2021
  129. PastaPastaPasta referenced this in commit 0aff2b2c01 on Sep 12, 2021
  130. PastaPastaPasta referenced this in commit c511977b12 on Sep 12, 2021
  131. PastaPastaPasta referenced this in commit 8d3bee5e71 on Sep 14, 2021
  132. PastaPastaPasta referenced this in commit eb9c94185b on Sep 14, 2021
  133. PastaPastaPasta referenced this in commit 06583cc33b on Sep 15, 2021
  134. furszy referenced this in commit 2f16162010 on Sep 23, 2021
  135. DrahtBot locked this on Feb 15, 2022

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-11-17 12:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me