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

Sjors · 2023-03-19T13:04:39Z

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

2023-03-19T12:46:01Z [validation] Enqueuing TransactionAddedToMempool: txid=37c8e1ef87d75a67fbaf44e116018fbc70d9c4ef0e27e2ae56861395101f9b8e wtxid=24e2d76012f9cde451d085ead4feab136feddae6cb55d37221a81aac6c0eaf42
2023-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 · 2023-03-19T13:04:41Z

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 · 2023-03-19T13:43:27Z

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

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

Sjors · 2023-03-19T13:47:54Z

src/validationinterface.cpp

-            LOG_EVENT(fmt, local_name, __VA_ARGS__);           \
-            event();                                           \
-        });                                                    \
+#define ENQUEUE_AND_LOG_EVENT(category, event, fmt, name, ...)          \


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

jonatack · 2023-03-19T14:28:52Z

src/flatfile.cpp

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


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.

Suggested change

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

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

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

(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).

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

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.

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

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.

(added a note to the PR description)

I'll look into switching to the LogPrintLevel function.

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

maflcko · 2023-03-20T09:46:15Z

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

TimeoutError: [Errno 110] Connection timed out

0xB10C · 2023-04-01T13:01:43Z

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).

ajtowns · 2023-08-21T05:33:09Z

Approach ACK

Sjors · 2023-08-21T09:39:35Z

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

ajtowns · 2023-08-22T03:04:13Z

src/flatfile.cpp

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


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

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 .

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)

I changed it to Debug

ajtowns · 2023-08-29T11:49:11Z

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...

ajtowns · 2023-08-29T11:02:22Z

src/validationinterface.cpp

-#define LOG_EVENT(fmt, ...) \
-    LogPrint(BCLog::VALIDATION, fmt "\n", __VA_ARGS__)
+#define LOG_EVENT(category, level, fmt, ...) \
+    LogPrintLevel(category, level, fmt "\n", __VA_ARGS__)


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

Got rid of it.

ajtowns · 2023-08-29T11:03:33Z

src/validationinterface.cpp

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


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

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

ajtowns · 2023-08-29T11:51:02Z

src/validationinterface.cpp

-            LOG_EVENT(fmt, local_name, __VA_ARGS__);           \
-            event();                                           \
-        });                                                    \
+#define ENQUEUE_AND_LOG_EVENT(category, level, event, fmt, ...)    \


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

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 · 2023-08-30T15:55:57Z

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

Sjors · 2023-08-31T07:02:00Z

src/validationinterface.cpp

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


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

Sjors · 2023-12-04T12:17:27Z

Rebased after #28368.

Sjors · 2024-02-13T13:02:57Z

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

The Enqueuing wrapper uses level Trace.

Use -logsourcelocations instead.

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

maflcko · 2024-02-13T15:07:24Z

src/validationinterface.cpp

+#define ENQUEUE_AND_LOG_EVENT(category, level, event, fmt, name, ...)                                 \
+    do {                                                                                              \
+        auto local_name = (name);                                                                     \
+        LogTrace(category, "Enqueuing " fmt "\n", local_name, __VA_ARGS__); \


e67ccf0: 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.

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.

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

DrahtBot · 2024-03-09T02:14:46Z

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

DrahtBot · 2024-05-29T13:19:30Z

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 force-pushed the 2022/03/log-tx-validation branch from cb37465 to f2c7d95 Compare March 19, 2023 13:41

Sjors force-pushed the 2022/03/log-tx-validation branch from f2c7d95 to 8de17cd Compare March 19, 2023 13:45

Sjors commented Mar 19, 2023

View reviewed changes

Sjors force-pushed the 2022/03/log-tx-validation branch from 8de17cd to 4eff439 Compare March 19, 2023 13:57

Sjors mentioned this pull request Mar 19, 2023

Log successful AcceptBlockHeader() #27276

Closed

Sjors changed the title ~~Move tx enqueue messages to mempool log~~ Move log messages: tx enqueue to mempool, allocation to blockstorage Mar 19, 2023

jonatack reviewed Mar 19, 2023

View reviewed changes

Sjors force-pushed the 2022/03/log-tx-validation branch from d562077 to 7417743 Compare March 19, 2023 15:21

maflcko mentioned this pull request Mar 20, 2023

ci: Cache more stuff in the ci images: msan, iwyu, pip, sdks #27028

Merged

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

DrahtBot mentioned this pull request Apr 20, 2023

assumeutxo #15606

Closed

18 tasks

DrahtBot mentioned this pull request May 8, 2023

assumeutxo (2) #27596

Merged

DrahtBot mentioned this pull request Aug 9, 2023

refactor: Enforce C-str fmt strings in WalletLogPrintf() #28237

Merged

DrahtBot added the Needs rebase label Aug 18, 2023

Sjors force-pushed the 2022/03/log-tx-validation branch from 7417743 to 55792a5 Compare August 21, 2023 09:39

Sjors mentioned this pull request Aug 21, 2023

Raise on invalid -debug and -loglevel config options #27632

Merged

Sjors force-pushed the 2022/03/log-tx-validation branch from 55792a5 to 81269d6 Compare August 21, 2023 09:47

DrahtBot added CI failed and removed CI failed Needs rebase labels Aug 21, 2023

ajtowns reviewed Aug 22, 2023

View reviewed changes

Sjors force-pushed the 2022/03/log-tx-validation branch from 81269d6 to f6429cc Compare August 23, 2023 08:46

ajtowns reviewed Aug 29, 2023

View reviewed changes

Sjors force-pushed the 2022/03/log-tx-validation branch from 330269f to 3d40916 Compare August 30, 2023 15:55

Sjors force-pushed the 2022/03/log-tx-validation branch from 3d40916 to a0f6b39 Compare August 30, 2023 16:03

Sjors commented Aug 31, 2023

View reviewed changes

Sjors mentioned this pull request Aug 31, 2023

validation: log which peer sent us a header #27826

Open

ajtowns mentioned this pull request Sep 1, 2023

logging: Simplify API for level based logging #28318

Merged

DrahtBot mentioned this pull request Nov 28, 2023

kernel: Remove dependency on CScheduler #28960

Merged

DrahtBot added the Needs rebase label Dec 1, 2023

Sjors force-pushed the 2022/03/log-tx-validation branch from a0f6b39 to 6f14178 Compare December 4, 2023 12:17

DrahtBot removed the Needs rebase label Dec 4, 2023

DrahtBot mentioned this pull request Dec 15, 2023

refactor: C++20: Use std::rotl #29085

Merged

DrahtBot added the CI failed label Jan 13, 2024

DrahtBot mentioned this pull request Jan 17, 2024

Improve new LogDebug/Trace/Info/Warning/Error Macros #29256

Open

Sjors force-pushed the 2022/03/log-tx-validation branch from 6f14178 to f42c98e Compare February 13, 2024 13:02

Sjors added 5 commits February 13, 2024 14:15

refactor: add category and level args to ENQUEUE_AND_LOG_EVENT

e67ccf0

The Enqueuing wrapper uses level Trace.

Don't log function names in ValidationInterface

628a1d4

Use -logsourcelocations instead.

Move tx enqueue messages to mempool log

bd3c44c

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

Move pre-allocating message to blockstorage log

e45103c

Update validationinterface.cpp format strings

17568b1

Sjors force-pushed the 2022/03/log-tx-validation branch from f42c98e to 17568b1 Compare February 13, 2024 13:17

maflcko reviewed Feb 13, 2024

View reviewed changes

DrahtBot removed the CI failed label Feb 13, 2024

Sjors marked this pull request as draft February 15, 2024 10:24

DrahtBot mentioned this pull request Mar 3, 2024

refactor: Improve naming of CBlock::GetHash() -> GetHeaderHash() #29538

Closed

Sjors mentioned this pull request Mar 5, 2024

p2p: log mutated blocks when unknown & valid PoW #29549

Closed

DrahtBot added the Needs rebase label Mar 9, 2024

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

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

Are you sure you want to change the base?

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

Conversation

Sjors commented Mar 19, 2023 • edited

DrahtBot commented Mar 19, 2023 • edited

Code Coverage

Reviews

Conflicts

Sjors commented Mar 19, 2023 • edited

Sjors Mar 19, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sjors Mar 19, 2023 • edited

Choose a reason for hiding this comment

jonatack Mar 19, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maflcko commented Mar 20, 2023

0xB10C commented Apr 1, 2023

ajtowns commented Aug 21, 2023

Sjors commented Aug 21, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ajtowns commented Aug 29, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sjors commented Aug 30, 2023 • edited

Choose a reason for hiding this comment

Sjors commented Dec 4, 2023

Sjors commented Feb 13, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

DrahtBot commented Mar 9, 2024

DrahtBot commented May 29, 2024

Sjors commented Mar 19, 2023 •

edited

DrahtBot commented Mar 19, 2023 •

edited

Sjors commented Mar 19, 2023 •

edited

Sjors Mar 19, 2023 •

edited

Sjors Mar 19, 2023 •

edited

jonatack Mar 19, 2023 •

edited

Sjors commented Aug 21, 2023 •

edited

Sjors commented Aug 30, 2023 •

edited