Early logging improvements

ajtowns commented at 4:33 pm on July 3, 2024: contributor

In order to cope gracefully with Log*() calls that are invoked prior to logging being fully configured (indicated by calling StartLogging() we buffer early log messages in m_msgs_before_open. This has a couple of minor issues:

if there are many such log messages the buffer can become arbitrarily large; this can be a problem for users of libkernel that might not wish to worry about logging at all, and as a result never invoke StartLogging()
early log messages are formatted before the formatting options are configured, leading to inconsistent output

Fix those issues by buffering the log info prior to formatting it, and setting a limit on the size of the buffer (dropping the oldest lines, and reporting the number of lines skipped).

Also adds some thread safety annotations, and the ability to invoke LogInstance().DisableLogging() if you want to disable logging entirely, for a minor efficiency improvement.

logging: Add thread safety annotations 6bbc2dd6c5

DrahtBot commented at 4:33 pm on July 3, 2024: 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
ACK	maflcko, ryanofsky, TheCharlatan

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:

#30343 (wallet, logging: Replace WalletLogPrintf() with LogInfo() by ryanofsky)
#30342 (kernel, logging: Pass Logger instances to kernel objects by ryanofsky)
#29798 (Logging cleanup by vasild)
#29256 (Improve new LogDebug/Trace/Info/Warning/Error Macros by ryanofsky)
#26697 (logging: use bitset for categories 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.

ajtowns force-pushed on Jul 3, 2024

ajtowns commented at 5:25 pm on July 3, 2024: contributor

Easiest way to test is to add some log lines into init.cpp InitLogging(), eg:

0    for (int i = 0; i < 10000; ++i) {
1        LogInfo("log spam %d...\n", i);
2    }
3    LogWarning("awoogah\n");
4    LogError("internal bug not detected\nhello, world!\nwas that fun?\n");

Running bitcoind -regtest -logtimemicros should give a decent indication of the differences.

If you want to modify bitcoin-chainstate to see what the logs would look like, remove the DisableLogging call and add:

0LogInstance().m_print_to_console = true;
1LogInstance().StartLogging()

somewhere.

ajtowns force-pushed on Jul 3, 2024

DrahtBot commented at 5:58 pm on July 3, 2024: contributor

🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the documentation.

Possibly this is due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.

Leave a comment here, if you need help tracking down a confusing failure.

Debug: https://github.com/bitcoin/bitcoin/runs/27006383028

DrahtBot added the label CI failed on Jul 3, 2024

maflcko removed the label CI failed on Jul 4, 2024

in src/bitcoin-chainstate.cpp:50 in ce34ad42c7 outdated

42@@ -42,6 +43,8 @@
43 
44 int main(int argc, char* argv[])
45 {
46+    LogInstance().DisableLogging();

ryanofsky commented at 6:58 pm on July 10, 2024:

In commit “logging: Add DisableLogging()” (ce34ad42c7c19edf726a31551ec3780733147db9)

Could there be a comment here explaining why logging is disabled here? Is it needed because this bitcoin-chainstate is not calling StartLogging(), so the log buffer could fill up?

ajtowns commented at 4:34 am on July 15, 2024:

It’s mostly added so that DisableLogging() isn’t dead code; all it really achieves is a minor performance improvement. Added some comments that maybe clarifies things.

in src/logging.cpp:75 in 3d4b1f4af4 outdated

71@@ -71,6 +72,9 @@ bool BCLog::Logger::StartLogging()
72 
73     // dump buffered messages from before we opened the log
74     m_buffering = false;
75+    if (m_buffer_lines_skipped > 0) {

ryanofsky commented at 7:09 pm on July 10, 2024:

In commit “logging: Limit early logging buffer” (3d4b1f4af406276671b5d0115574dea6b4a64340)

Since the log limit discards old log prints instead of skipping new prints, I think it would be a little clearer if “skipped” was replaced with “discarded” throughout this commit.

ajtowns commented at 4:34 am on July 15, 2024:

Changed

in src/logging.cpp:373 in 3d4b1f4af4 outdated

401@@ -382,11 +402,20 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi
402 
403     str_prefixed = LogTimestampStr(str_prefixed);
404 
405-    m_started_new_line = !str.empty() && str[str.size()-1] == '\n';

ryanofsky commented at 7:11 pm on July 10, 2024:

In commit “logging: Limit early logging buffer” (3d4b1f4af406276671b5d0115574dea6b4a64340)

It seems like a mistake to drop this as it is not being set otherwise.

(EDIT: The line is added back in the next commit, but it shouldn’t be deleted in this one.)

ajtowns commented at 4:52 am on July 18, 2024:

Should be fixed (line is no longer touched)

in src/logging.cpp:376 in 0456828a50 outdated

372+static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
373+{
374+    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
375+}
376+
377+void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string source_file, int source_line, std::string logging_function, std::string threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const

ryanofsky commented at 7:28 pm on July 10, 2024:

In commit “logging: Apply formatting to early log messages” (0456828a50b86fd9185b7428e9012b7c18e970f9)

Maybe something to consider for a followup but some of the arguments to FormatLogStrInPlace and the two LogPrintStr functions could be string_views instead of strings (logging_function, source_file, threadname).

ajtowns commented at 4:34 am on July 15, 2024:

Added a followup commit to switch to string_view

ryanofsky approved

ryanofsky commented at 7:29 pm on July 10, 2024: contributor

Code review ACK 0456828a50b86fd9185b7428e9012b7c18e970f9. Left some suggestions, but they are not important

logging: Add DisableLogging() 0b1960f1b2

ajtowns force-pushed on Jul 15, 2024

in src/logging.cpp:104 in 0b1960f1b2 outdated

 95@@ -96,6 +96,18 @@ void BCLog::Logger::DisconnectTestLogger()
 96     m_print_callbacks.clear();
 97 }
 98 
 99+void BCLog::Logger::DisableLogging()
100+{
101+    {
102+        StdLockGuard scoped_lock(m_cs);
103+        assert(m_buffering);
104+        assert(m_print_callbacks.empty());

maflcko commented at 12:39 pm on July 18, 2024:

q in 0b1960f1b29cfe5209ac68102c8643fc9553f247: Any reason to assert this but not the that the other m_print_to_* fields are false? What is the difference of a developer writing PushBackCallback(...); DisableLogging() to crash the program vs a developer writing m_print_to_console=true;DisableLogging() to achieve the same?

ajtowns commented at 1:50 am on July 19, 2024:

The other things can be safely set to false, so we can be sure they’re false without an assertion. But if you’ve set a callback you’ve also gotten an iterator that you might intend to pass to DeleteCallback later, which would then crash if we had cleared m_print_callbacks here.

maflcko commented at 5:23 am on July 19, 2024:

Fair enough, but I am mostly thinking what would be the use case for possibly confusing code like m_print_to_console=true;DisableLogging()? Given that this function also assert(m_buffering), the code can only be called when logging was never active, I’d still say it makes sense to at least Assume(!m_print_to*).

in src/logging.h:82 in 3854484b98 outdated

78@@ -79,6 +79,7 @@ namespace BCLog {
79         Error,
80     };
81     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
82+    constexpr size_t DEFAULT_MAX_LOG_BUFFER{1000000}; // buffer up to 1MB of log data prior to StartLogging

maflcko commented at 12:52 pm on July 18, 2024:

style nit in 3854484b988dfc7144e3ed3ca09de563e435cc34:

1'000'000

in src/logging.h:166 in 0b1960f1b2 outdated

161+         * This offers a slight speedup and slightly smaller memory usage
162+         * compared to leaving the logging system in its default state.
163+         * Mostly intended for libbitcoin-kernel apps that don't want any logging.
164+         * Should be used instead of StartLogging().
165+         */
166+        void DisableLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);

ryanofsky commented at 2:12 pm on July 18, 2024:

In commit “logging: Add DisableLogging()” (0b1960f1b29cfe5209ac68102c8643fc9553f247)

I think it’s a good idea to add this DisableLogging() method for clarity, even though in practice it’s equivalent to just calling StartLogging() without setting any logging options.

But I think in the future it would be nice to simplify the log interface and replace StartLogging() DisableLogging() and DisconnectTestLogger() methods with a single SetOptions() method:

 0struct BufferOptions {
 1   size_t max_bytes{1000000};
 2};
 3
 4struct OutputOptions {
 5    fs::path print_to_file{};
 6    bool print_to_console{false};
 7    bool log_timestamps{true};
 8    bool log_time_micros{false};
 9    bool log_threadnames{false};
10    bool log_sourcelocations{false};
11    bool always_print_category_level{false};
12};
13
14using Options = std::variant<BufferOptions, OutputOptions>;
15
16Options m_options{};
17
18void SetOptions(Options options);

The default behavior, as currently, would be to buffer log messages, but it would be easy to set default output options to disable logging, or set custom output options to enable it.

ajtowns commented at 3:44 am on July 19, 2024:

I’d like to change Enabled() and WillLogCategoryLevel() functions to be lockless so that calls to Log*() don’t block when they have nothing to do. I think the above changes would mesh well with that.

in src/logging.cpp:405 in a67baea866 outdated

423-        m_cur_buffer_memusage += MemUsage(str_prefixed);
424-        while (m_cur_buffer_memusage > m_max_buffer_memusage) {
425-            if (m_msgs_before_open.empty()) {
426-                m_cur_buffer_memusage = 0;
427-                break;
428+        if (!starts_new_line && !m_msgs_before_open.empty()) {

ryanofsky commented at 2:34 pm on July 18, 2024:

In commit “logging: Apply formatting to early log messages” (a67baea866719837865864a5eb56a47a9f132de1)

I think it might make sense to explicitly handle the case where starts_new_line is false and m_msgs_before_open is empty. Right now the code will cut off the first part of the log line but include the rest of the message, which could lead to confusing or misleading output. Better options might be to add a ... [truncated] prefix to the line, or to discard the whole message.

ajtowns commented at 3:37 am on July 19, 2024:

Added a [...] marker, since it was easy.

In order to trigger it you’d need to have 1MB of log message on a single, incomplete line, which seems a bit ridiculous. Long-term, I think it would make more sense to stop intentionally doing incomplete lines (since that introduces a race condition if other threads are also logging), and just add a newline if it’s missing… shrug

maflcko commented at 1:23 pm on July 19, 2024:

Long-term, I think it would make more sense to stop intentionally doing incomplete lines (since that introduces a race condition if other threads are also logging), and just add a newline if it’s missing… shrug

Fixed in #30485 (but not yet removing the m_started_new_line to avoid a merge conflict here). I’ll do it in a follow-up, after this one is merged, or if I get the OK to do it before this one is merged.

In any case, according to the coverage report, all of this is dead code, so shrug . Shouldn’t matter much either way.

in src/logging.cpp:390 in f3632d53a5 outdated

387 {
388     str.insert(0, GetLogPrefix(category, level));
389 
390     if (m_log_sourcelocations) {
391-        str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
392+        insert_many(str, 0, "[", RemovePrefix(source_file, "./"), ":", ToString(source_line), "] [", logging_function, "] ");

ryanofsky commented at 2:44 pm on July 18, 2024:

In commit “logging: use std::string_view” (f3632d53a5be7efe61be8181ff481d30f7313bd4)

I wonder if using insert_many is actually more efficient than strprinf:

0str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefix(source_file, "./"), source_line, logging_function);

Using strprintf seems more readable, and I suspect if we really wanted to optimize this code we probably would build up a new string rather than repeatedly inserting at the beginning of an existing string.

ajtowns commented at 3:38 am on July 19, 2024:

Changed to strprintf. Got a bit target fixated there…

ryanofsky approved

ryanofsky commented at 2:52 pm on July 18, 2024: contributor

Code review ACK f3632d53a5be7efe61be8181ff481d30f7313bd4. I left some suggestions, but feel free to ignore them. Overall I think this PR makes early logging behavior a lot better by making the log format consistent, and it also makes nice API improvements like avoiding runaway memory usage, and switching to std::string_view.

in src/logging.cpp:407 in a67baea866 outdated

425-            if (m_msgs_before_open.empty()) {
426-                m_cur_buffer_memusage = 0;
427-                break;
428+        if (!starts_new_line && !m_msgs_before_open.empty()) {
429+            m_msgs_before_open.back().str += str;
430+            m_cur_buffer_memusage += str.size();

maflcko commented at 4:44 pm on July 18, 2024:

q in a67baea866719837865864a5eb56a47a9f132de1: Why use str here? Seems odd to possibly leak terminal control codes into the log?

ajtowns commented at 3:38 am on July 19, 2024:

That’s a bug, changed.

in src/logging.cpp:427 in a67baea866 outdated

439+                .source_line=source_line,
440+                .category=category,
441+                .level=level,
442+            };
443+            m_msgs_before_open.push_back(buf);
444+            m_cur_buffer_memusage += MemUsage(buf);

maflcko commented at 4:50 pm on July 18, 2024:

nit in a67baea866719837865864a5eb56a47a9f132de1: Could switch the two lines and use std::move?

ajtowns commented at 3:38 am on July 19, 2024:

Done

maflcko approved

maflcko commented at 5:06 pm on July 18, 2024: member

ACK f3632d53a5be7efe61be8181ff481d30f7313bd4 🚲

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: ACK f3632d53a5be7efe61be8181ff481d30f7313bd4 🚲
3Npt3Z0ZvZ7d1vkjP+I6WoSxmYlnR8J954hzJEEVA5Y1ogrEp3GDcMINyxhP04yvRf/5iWhedn+y9a9jxwtHmAw==

logging: Limit early logging buffer

Log messages created prior to StartLogging() being called go into a
buffer. Enforce a limit on the size of this buffer.

6cf9b34440

logging: Apply formatting to early log messages

The formatting of log messages isn't defined until StartLogging() is
called; so can't be correctly applied to early log messages from prior
to that call. Instead of saving the output log message, save the inputs
to the logging invocation (including time, mocktime and thread name),
and format those inputs into a log message when StartLogging() is called.

558df5c733

ajtowns force-pushed on Jul 19, 2024

DrahtBot added the label CI failed on Jul 19, 2024

DrahtBot commented at 4:50 am on July 19, 2024: contributor

🚧 At least one of the CI tasks failed. Debug: https://github.com/bitcoin/bitcoin/runs/27646993578

Make sure to run all tests locally, according to the documentation.

The failure may happen due to a number of reasons, for example:

Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

in src/logging.cpp:381 in 1cd8386a18 outdated

377+void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
378 {
379     str.insert(0, GetLogPrefix(category, level));
380 
381     if (m_log_sourcelocations) {
382-        str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");

maflcko commented at 5:30 am on July 19, 2024:

nit in 1cd8386a18db0ced6da0c5f42e952e81fa02867c:

 0clang-tidy-18 -p=/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu -quiet -load=/tidy-build/libbitcoin-tidy.so /ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src/logging.cpp
 1logging.cpp:19:13: error: using decl 'ToString' is unused [misc-unused-using-decls,-warnings-as-errors]
 2   19 | using util::ToString;
 3      |             ^
 4logging.cpp:19:13: note: remove the using
 5   19 | using util::ToString;
 6      | ~~~~~~~~~~~~^~~~~~~~~
 7^^^ ⚠️ Failure generated from clang-tidy
 8+ echo '^^^ ⚠️ Failure generated from clang-tidy'
 9+ false
10��������

in src/logging.cpp:381 in 1cd8386a18 outdated

378 {
379     str.insert(0, GetLogPrefix(category, level));
380 
381     if (m_log_sourcelocations) {
382-        str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
383+        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefix(source_file, "./"), source_line, logging_function));

maflcko commented at 5:31 am on July 19, 2024:

nit in https://github.com/bitcoin/bitcoin/commit/1cd8386a18db0ced6da0c5f42e952e81fa02867c:

Could use RemovePrefixView for consistency and to avoid a useless string constructor?

maflcko commented at 5:36 am on July 19, 2024: member

lgtm, after a CI fix.

re-ACK 1cd8386a18db0ced6da0c5f42e952e81fa02867c 🏡

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: re-ACK 1cd8386a18db0ced6da0c5f42e952e81fa02867c  🏡
38ysDmnHpYk3ulyRBsxRoXiqBgPnKiwl54SZM1p6EqcYvQ0Pl39Qmk3M0fuBdFyBflutT4xSMMavOyAe9wX4FCQ==

DrahtBot requested review from ryanofsky on Jul 19, 2024

logging: use std::string_view b4dd7ab43e

ajtowns force-pushed on Jul 19, 2024

DrahtBot removed the label CI failed on Jul 19, 2024

maflcko commented at 7:38 am on July 19, 2024: member

re-ACK b4dd7ab43e8cfc2c171f67588e4e1ec2705393c2 🕴

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: re-ACK b4dd7ab43e8cfc2c171f67588e4e1ec2705393c2 🕴
3jM/rPHAaIwZvm8W2wJGcZTGYV/m+3AI+tcbtSXChUzTig/qQoVfzFh/aNMuy08785DW+EVKwt5nlRn3W2mrOAw==

in src/logging.cpp:412 in 558df5c733 outdated

424+                m_msgs_before_open.back().str += str_prefixed;
425+                m_cur_buffer_memusage += str_prefixed.size();
426+                return;
427+            } else {
428+                // unlikely edge case; add a marker that something was trimmed
429+                str_prefixed.insert(0, "[...] ");

ryanofsky commented at 10:44 pm on July 22, 2024:

In commit “logging: Apply formatting to early log messages” (558df5c733d31456faf856d44f7037f41981d797)

Probably better to leave alone since this affects an edge case of an edge case, but just observing that this code could increment m_cur_buffer_memusage to count the usage more accurately.

ajtowns commented at 4:35 am on July 23, 2024:

The memusage is incremented later when str_prefixed is included in buf, so afaics this should already be accurate.

ryanofsky approved

ryanofsky commented at 10:54 pm on July 22, 2024: contributor

Code review ACK b4dd7ab43e8cfc2c171f67588e4e1ec2705393c2

Main change since last review is fixing an escaping bug #30386 (review), but also includes a few other review suggestions

in src/logging.cpp:106 in 6cf9b34440 outdated

 98@@ -94,6 +99,11 @@ void BCLog::Logger::DisconnectTestLogger()
 99     if (m_fileout != nullptr) fclose(m_fileout);
100     m_fileout = nullptr;
101     m_print_callbacks.clear();
102+    m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
103+    m_cur_buffer_memusage = 0;
104+    m_buffer_lines_discarded = 0;
105+    m_msgs_before_open.clear();
106+

TheCharlatan commented at 10:20 am on July 24, 2024:

Nit: Unneeded newline.

in src/logging.cpp:102 in 6cf9b34440 outdated

 98@@ -94,6 +99,11 @@ void BCLog::Logger::DisconnectTestLogger()
 99     if (m_fileout != nullptr) fclose(m_fileout);
100     m_fileout = nullptr;
101     m_print_callbacks.clear();
102+    m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;

TheCharlatan commented at 11:46 am on July 24, 2024:

Nit: Why is this being set again? I’m guessing it is not declared as const to future-proof it against introducing an option controlling its size, but it is not clear why disconnecting should clear such a value again.

maflcko commented at 8:24 am on July 26, 2024:

This is for tests only, where each unit test uses the same global logger, so resetting the global state before each unit test is useful.

TheCharlatan approved

TheCharlatan commented at 12:40 pm on July 24, 2024: contributor

Nice, ACK b4dd7ab43e8cfc2c171f67588e4e1ec2705393c2

maflcko commented at 8:25 am on July 26, 2024: member

Should be good to merge with 3 acks, or is it waiting on more review, or something else?

ryanofsky merged this on Jul 26, 2024

ryanofsky closed this on Jul 26, 2024

Early logging improvements #30386

Code Coverage

Reviews

Conflicts