Move log messages: tx enqueue to mempool, allocation to blockstorage

Sjors commented at 1:04 pm on March 19, 2023: member

When running with -debug=validation the log is filled with:

02023-03-19T12:46:01Z [validation] Enqueuing TransactionAddedToMempool: txid=37c8e1ef87d75a67fbaf44e116018fbc70d9c4ef0e27e2ae56861395101f9b8e wtxid=24e2d76012f9cde451d085ead4feab136feddae6cb55d37221a81aac6c0eaf42
12023-03-19T12:46:01Z [validation] TransactionAddedToMempool: txid=37c8e1ef87d75a67fbaf44e116018fbc70d9c4ef0e27e2ae56861395101f9b8e wtxid=24e2d76012f9cde451d085ead4feab136feddae6cb55d37221a81aac6c0eaf42

These log entries are more appropriate for -debug=mempool.

This change limits -debug=validation to messages that are related to blocks and headers. It also downgrades Enqueuing messages to the Trace level.

It makes it easier to run for a long time without excessive log file growth. This debug category is particularly useful for keeping track of problematic headers that were seen, the timing of reorgs, see also #27276.

Since this PR touches validationinterface.cpp anyway, it also includes a commit to drop function names from log messages, since we now have -logsourcelocations.

Similarly, though less important, I moved [validation] Pre-allocating up to position 0x… in rev….dat messages to blockstorage. This reduces the number of [validation] log messages further. ~~to 3 per (normal) block.~~

The volume of log messages could also have been reduced by changing the log level of these messages to trace. Doing so would prevent a whack-a-mole game of moving log messages to different categories. However in this case I think the change in log category would be justified even if it didn’t have a big impact on noise. I.e. someone running with -debug=mempool would expect to see the TransactionAddedToMempool messages and someone running with -debug=blockstorage would perhaps be surprised to not see the Pre-allocating message.

DrahtBot commented at 1:04 pm on March 19, 2023: contributor

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

Code Coverage

For detailed information about the code coverage, see the test coverage report.

Reviews

See the guideline for information on the review process.

Type	Reviewers
Approach ACK	ajtowns

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#29538 (refactor: Improve naming of CBlock::GetHash() -> GetHeaderHash() by fjahr)
#29256 (Improve new LogDebug/Trace/Info/Warning/Error Macros by ryanofsky)
#28960 (kernel: Remove dependency on CScheduler by TheCharlatan)

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.

Sjors force-pushed on Mar 19, 2023

Sjors commented at 1:43 pm on March 19, 2023: member

Still investigating the linter issue… (update: figured it out)

0src/validationinterface.cpp: Expected 0 argument(s) after format string but found 1 argument(s): LogPrint(category, fmt "\n", __VA_ARGS__)

Sjors force-pushed on Mar 19, 2023

in src/validationinterface.cpp:180 in ab69eafe7c outdated

183-        LOG_EVENT("Enqueuing " fmt, local_name, __VA_ARGS__);  \
184-        m_internals->m_schedulerClient.AddToProcessQueue([=] { \
185-            LOG_EVENT(fmt, local_name, __VA_ARGS__);           \
186-            event();                                           \
187-        });                                                    \
188+#define ENQUEUE_AND_LOG_EVENT(category, event, fmt, name, ...)          \

Sjors commented at 1:47 pm on March 19, 2023:

Note: I don’t know if there was any particular reason why the endline characters are vertically aligned (in #16688). If there’s no reason, then it would be easier to move them all to the left.

cc @kczyz

Sjors force-pushed on Mar 19, 2023

Sjors renamed this:
~~Move tx enqueue messages to mempool log~~
Move log messages: tx enqueue to mempool, allocation to blockstorage
on Mar 19, 2023

in src/flatfile.cpp:69 in d56207751f outdated

65@@ -66,7 +66,7 @@ size_t FlatFileSeq::Allocate(const FlatFilePos& pos, size_t add_size, bool& out_
66         if (CheckDiskSpace(m_dir, inc_size)) {
67             FILE *file = Open(pos);
68             if (file) {
69-                LogPrint(BCLog::VALIDATION, "Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);
70+                LogPrint(BCLog::BLOCKSTORE, "Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);

jonatack commented at 2:28 pm on March 19, 2023:

An alternative you could consider would be to use the trace log level, so this would be logged only if the trace loglevel is set with -loglevel, either globally or for this category.

0                LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Trace, "Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);

 0$ ./src/bitcoind -help-debug | grep -A10 loglevel
 1  -loglevel=<level>|<category>:<level>
 2       Set the global or per-category severity level for logging categories
 3       enabled with the -debug configuration option or the logging RPC:
 4       info, debug, trace (default=debug); warning and error levels are
 5       always logged. If <category>:<level> is supplied, the setting
 6       will override the global one and may be specified multiple times
 7       to set multiple category-specific levels. <category> can be:
 8       addrman, bench, blockstorage, cmpctblock, coindb, estimatefee,
 9       http, i2p, ipc, leveldb, libevent, lock, mempool, mempoolrej,
10       net, proxy, prune, qt, rand, reindex, rpc, scan, selectcoins,
11       tor, txreconciliation, util, validation, walletdb, zmq.

jonatack commented at 2:33 pm on March 19, 2023:

(Just changing the category might only shift verbose logging from one place to another. The idea of the log levels is to allow more granular control over detail).

0from src/logging.h
1
2    enum class Level {
3        Trace = 0, // High-volume or detailed logging for development/debugging
4        Debug,     // Reasonably noisy logging, but still usable in production
5        Info,      // Default
6        Warning,
7        Error,

Sjors commented at 2:36 pm on March 19, 2023:

I think blockstorage is correct place for this in any case. E.g. it also logs Leaving block file. I don’t know if it makes sense to reduce the log level.

Sjors commented at 2:47 pm on March 19, 2023:

Looking at the history of the BLOCKSTORE category, it was introduced as part of a larger change in #23235 to reduce the default log noise. There was no discussion about this particular line, and my guess is that it was overlooked. cc @ajtowns

jonatack commented at 2:52 pm on March 19, 2023:

The info level is logged by default if -debug=on for the category (as well as the debug level, for now during the transition period) and it would ease the review burden to use the new macros instead of the ones that will have to be updated. You may be right about BLOCKSTORE being a better place.

Sjors commented at 2:53 pm on March 19, 2023:

(added a note to the PR description)

Sjors commented at 2:54 pm on March 19, 2023:

I’ll look into switching to the LogPrintLevel function.

Sjors commented at 3:21 pm on March 19, 2023:

Done

ajtowns commented at 5:42 am on March 20, 2023:

Looking at the history of the BLOCKSTORE category, it was introduced as part of a larger change in #23235 to reduce the default log noise. There was no discussion about this particular line, and my guess is that it was overlooked. cc @ajtowns

That sounds right

Sjors force-pushed on Mar 19, 2023

maflcko commented at 9:46 am on March 20, 2023: member

CI network error https://cirrus-ci.com/task/4864754720702464?logs=ci#L61:

TimeoutError: [Errno 110] Connection timed out

glozow added the label Utils/log/libs on Mar 23, 2023

0xB10C commented at 1:01 pm on April 1, 2023: contributor

CI network error https://cirrus-ci.com/task/4864754720702464?logs=ci#L61:

TimeoutError: [Errno 110] Connection timed out

Note: The failed connections seems to be to the launchpad.net PPA with a newer bpfcc. Not using this newer PPA to install an up-to-date bpfcc causes warnings printed to stderr which means interface_usdt_coinselection.py is treated as failed. (The up-coming Ubuntu lunar seems to include an up-to-date bpfcc).

DrahtBot added the label Needs rebase on Aug 18, 2023

ajtowns commented at 5:33 am on August 21, 2023: contributor

Approach ACK

Sjors commented at 9:39 am on August 21, 2023: member

Rebased after #27632 (a trivial, but silent, conflict, I noticed it while trying to rebase when @DrahtBot asked).

Sjors force-pushed on Aug 21, 2023

DrahtBot added the label CI failed on Aug 21, 2023

DrahtBot removed the label CI failed on Aug 21, 2023

DrahtBot removed the label Needs rebase on Aug 21, 2023

in src/flatfile.cpp:69 in 81269d69d2 outdated

65@@ -66,7 +66,7 @@ size_t FlatFileSeq::Allocate(const FlatFilePos& pos, size_t add_size, bool& out_
66         if (CheckDiskSpace(m_dir, inc_size)) {
67             FILE *file = Open(pos);
68             if (file) {
69-                LogPrint(BCLog::VALIDATION, "Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);
70+                LogPrintLevel(BCLog::BLOCKSTORAGE, BCLog::Level::Info, "Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);

ajtowns commented at 3:04 am on August 22, 2023:

Why is this upgraded from Level::Debug to Level::Info ? That makes this logging unconditional?

Sjors commented at 2:40 pm on August 22, 2023:

It’s more complicated. WillLogCategoryLevel logs >= BCLog::Level::Warning for any category. For Info it first checks if the category is selected, which is only the case if the user set -debug=blockstorage.

Only if the category is set, it looks at category-specific log levels (-loglevel), and defaults to DEFAULT_LOG_LEVEL, which is currently Debug (but I vaguely recall the idea was the raise that to Info).

So this should not cause logging by default. I could still set the level to Debug but perhaps that’s better reserver for even lower level block storage stuff, if we ever add that. And indeed it didn’t when I briefly tested it .

ajtowns commented at 3:36 am on August 23, 2023:

We have Trace available for “even lower level” stuff (currently used by the wallet for sql logging). The only Info logging we currently do with a category is for libevent EVENT_LOG_MSG, which I don’t think is even used in the parts of libevent we actually use. I don’t think this change makes sense, but that’s probably mostly thinking that the logging api we have at the moment is confusing… (cf #28318)

Sjors commented at 8:46 am on August 23, 2023:

I changed it to Debug

Sjors force-pushed on Aug 23, 2023

in src/validationinterface.cpp:190 in f6429cc395 outdated

195     } while (0)
196 
197-#define LOG_EVENT(fmt, ...) \
198-    LogPrint(BCLog::VALIDATION, fmt "\n", __VA_ARGS__)
199+#define LOG_EVENT(category, level, fmt, ...) \
200+    LogPrintLevel(category, level, fmt "\n", __VA_ARGS__)

ajtowns commented at 11:02 am on August 29, 2023:

There’s not really any need for a separate LOG_EVENT macro anymore – all it saves now is adding a newline.

Sjors commented at 10:47 am on August 30, 2023:

Got rid of it.

in src/validationinterface.cpp:200 in f6429cc395 outdated

196@@ -198,7 +197,7 @@ void CMainSignals::UpdatedBlockTip(const CBlockIndex *pindexNew, const CBlockInd
197     auto event = [pindexNew, pindexFork, fInitialDownload, this] {
198         m_internals->Iterate([&](CValidationInterface& callbacks) { callbacks.UpdatedBlockTip(pindexNew, pindexFork, fInitialDownload); });
199     };
200-    ENQUEUE_AND_LOG_EVENT(event, "%s: new block hash=%s fork block hash=%s (in IBD=%s)", __func__,
201+    ENQUEUE_AND_LOG_EVENT(BCLog::VALIDATION, BCLog::Level::Info, event, "new block hash=%s fork block hash=%s (in IBD=%s)",

ajtowns commented at 11:03 am on August 29, 2023:

Also seems pointless to upgrade these to Info… If anything, these seem more appropriate to downgrade to Trace logging (the “Enqueuing” particularly).

Sjors commented at 10:56 am on August 30, 2023:

I’ll switch these to Debug and downgrade the Enqueuing wrapper to trace.

ajtowns commented at 11:49 am on August 29, 2023: contributor

This reduces the number of [validation] log messages to 3 per (normal) block.

I’m seeing 6 validation logs via validationinterface.cpp: NewPoWValidBlock, BlockChecked, BlockConnected (enqueued and executed), UpdatedBlockTip (enqueued and executed). I think that’s with default settings.

There’s also “Saw new header”, “Saw new cmpctblock header” and “UpdateTip”, but those aren’t [validation] log messages (they’re not categorised and don’t require -debug=validation), but if you’re only seeing those, you already weren’t seeing the “Pre-allocating…” messages…

in src/validationinterface.cpp:180 in f6429cc395 outdated

183-        LOG_EVENT("Enqueuing " fmt, local_name, __VA_ARGS__);  \
184-        m_internals->m_schedulerClient.AddToProcessQueue([=] { \
185-            LOG_EVENT(fmt, local_name, __VA_ARGS__);           \
186-            event();                                           \
187-        });                                                    \
188+#define ENQUEUE_AND_LOG_EVENT(category, level, event, fmt, ...)    \

ajtowns commented at 11:51 am on August 29, 2023:

No real need to include the level as a param, I think. Hardcoding it would make things a bit less noisy.

Sjors commented at 11:04 am on August 30, 2023:

This PR always sets level to Debug, so we don’t need it here. But then any later tweak in log levels would have to edit this macro again.

Sjors force-pushed on Aug 30, 2023

Sjors commented at 11:08 am on August 30, 2023: member

Rebased and addressed feedback.

I’m seeing 6 validation logs via validationinterface.cpp:

I don’t recall how I came up with 3. It’s indeed more, sometimes many more (when receiving the same header from multiple peers?). I may have gotten confused with #27826. Updated the description.

Sjors force-pushed on Aug 30, 2023

DrahtBot added the label CI failed on Aug 30, 2023

DrahtBot removed the label CI failed on Aug 30, 2023

Sjors commented at 1:32 pm on August 30, 2023: member

Oops…

0Error "tinyformat: Not enough conversion specifiers in format string" while formatting log message: block hash=%s

Will push fix.

Sjors force-pushed on Aug 30, 2023

Sjors commented at 3:55 pm on August 30, 2023: member

Dropping the function name (by default) made some of these messages ambiguous so I clarified them a bit in the second commit.

Sjors force-pushed on Aug 30, 2023

in src/validationinterface.cpp:258 in a0f6b3956a outdated

241@@ -246,17 +242,17 @@ void CMainSignals::ChainStateFlushed(const CBlockLocator &locator) {
242     auto event = [locator, this] {
243         m_internals->Iterate([&](CValidationInterface& callbacks) { callbacks.ChainStateFlushed(locator); });
244     };
245-    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s", __func__,
246+    ENQUEUE_AND_LOG_EVENT(BCLog::VALIDATION, BCLog::Level::Debug, event, "chainstate flushed block hash=%s",

Sjors commented at 7:02 am on August 31, 2023:

As an aside, this gets called 5-10 times for some blocks, zero times for most blocks.

DrahtBot added the label Needs rebase on Dec 1, 2023

Sjors commented at 12:17 pm on December 4, 2023: member

Rebased after #28368.

Sjors force-pushed on Dec 4, 2023

DrahtBot removed the label Needs rebase on Dec 4, 2023

DrahtBot added the label CI failed on Jan 13, 2024

Sjors force-pushed on Feb 13, 2024

Sjors commented at 1:02 pm on February 13, 2024: member

Rebased and switched LogPrintLevel(...Debug) to LogDebug(...)

refactor: add category and level args to ENQUEUE_AND_LOG_EVENT

The Enqueuing wrapper uses level Trace.

e67ccf09ff

Don't log function names in ValidationInterface

Use -logsourcelocations instead.

628a1d41a3

Move tx enqueue messages to mempool log

This limits -debug=validation to messages related to blocks and headers.

bd3c44c501

Move pre-allocating message to blockstorage log e45103cd85

Update validationinterface.cpp format strings 17568b1cc6

Sjors force-pushed on Feb 13, 2024

in src/validationinterface.cpp:185 in e67ccf09ff outdated

188-            event();                                           \
189-        });                                                    \
190+#define ENQUEUE_AND_LOG_EVENT(category, level, event, fmt, name, ...)                                 \
191+    do {                                                                                              \
192+        auto local_name = (name);                                                                     \
193+        LogTrace(category, "Enqueuing " fmt "\n", local_name, __VA_ARGS__); \

maflcko commented at 3:07 pm on February 13, 2024:

e67ccf09ff3df3810e08d278739fa25335785767: How is this a refactor? You are changing the behavior from debug to trace, no?

Also, I am not sure about this change. This makes intermittent test failures harder to debug, since trace is disabled. Also, below Debug is still used, so this drops only one of two log lines.

Sjors commented at 10:24 am on February 15, 2024:

Indeed this should be LogDebug() in order to not change behavior.

The downgrade to trace should be in a different commit. Will look into this again.

This makes intermittent test failures harder to debug, since trace is disabled.

I’ll look into what level to use. Lots of things have changed over the past few rebases.

maflcko commented at 10:40 am on February 15, 2024:

I think the trace level was always disabled, unless explicitly enabled? But I haven’t double checked this.

DrahtBot removed the label CI failed on Feb 13, 2024

Sjors marked this as a draft on Feb 15, 2024

DrahtBot added the label Needs rebase on Mar 9, 2024

DrahtBot commented at 2:14 am on March 9, 2024: contributor

🐙 This pull request conflicts with the target branch and needs rebase.

DrahtBot commented at 1:19 pm on May 29, 2024: contributor

There hasn’t been much activity lately and the patch still needs rebase. What is the status here?

Is it still relevant? ➡️ Please solve the conflicts to make it ready for review and to ensure the CI passes.
Is it no longer relevant? ➡️ Please close.
Did the author lose interest or time to work on this? ➡️ Please close it and mark it ‘Up for grabs’ with the label, so that it can be picked up in the future.

DrahtBot commented at 1:15 am on August 26, 2024: contributor

⌛ There hasn’t been much activity lately and the patch still needs rebase. What is the status here?

Is it still relevant? ➡️ Please solve the conflicts to make it ready for review and to ensure the CI passes.
Is it no longer relevant? ➡️ Please close.
Did the author lose interest or time to work on this? ➡️ Please close it and mark it ‘Up for grabs’ with the label, so that it can be picked up in the future.

Sjors commented at 8:47 am on August 26, 2024: member

Let’s mark this up for grabs. Though I might eventually grab it.

Sjors closed this on Aug 26, 2024

Move log messages: tx enqueue to mempool, allocation to blockstorage #27277

Code Coverage

Reviews

Conflicts