logging: better use of log::Entry internally #34865

In commit "logging: pass log::Entry through to logging functions" (05a89da0d41b28d8ede51f8252f14b099ae8afe2)

Since this commit is changing signatures of LogPrintStr / LogPrintStr_ methods and updating all call sites already, it seems like it would be to good choose a better name for them. When LogPrintStr was originally written it just took a single string argument so the name made sense. But over time more parameters were added and now it takes an entry struct instead of a string argument. Would suggest just calling these methods Log / Log_ but I think anything without Str would be an improvement.

Updated, thanks. I opted for LogPrint{_} to disambiguate from util::log::Log() and keep the name familiar.

In commit "logging: pass log::Entry through to logging functions" (05a89da0d41b28d8ede51f8252f14b099ae8afe2)

It's a little atypical for c++ functions to require their arguments to be rvalues like this. Would suggest just util::log::Entry entry so this can be called naturally and callers can decide whether to move or copy.

You're right, changed to passing by value. I thought for an internal function it makes sense to make it more explicit that no copies can happen here, but it's probably not worth the awkwardness.

In commit "logging: replace FormatLogStrInPlace with Format" (b94475aecd75414f61a2a3a7f0302fcad907d12e)

Note (in case it helps other reviewers): I was trying to figure out why FormatLogStrInPlace was written in this unusual way, taking a mutable string parameter, and building the string in reverse, adding prefixes instead of appending.

It seems like there wasn't a real reason for this other than trying to minimize differences with the previous code when this method was introduced in 558df5c733d31456faf856d44f7037f41981d797 from #30386

In commit "logging: make BufferedLog a log::Entry wrapper" (ebb0a14acee83a719d640002d7461938979e4342)

One drawback of this change is that BufferedLog now contains an entry.should_ratelimit field that is unused and ignored.

This is a minor issue and could be fixed in a pretty clean way with #34778 by passing the util::log::Options struct added in that PR alongside util::log::Entry to logging functions and then dropping the util::log::Entry::should_ratelimit field.

In commit "logging: replace FormatLogStrInPlace with Format" (b94475aecd75414f61a2a3a7f0302fcad907d12e)

Diff would be a little smaller without renaming str_prefixed to log_msg, and new name does not seem obviously better to me than the old one, but no strong opinion.

I don't think str_prefixed is clear, but perhaps log_msg doesn't sufficiently differentiate from Entry::message, so perhaps e.g. fmt_log_line would be best. That said, I agree it's touching a lot of new lines, so I've reverted it to str_prefixed.

nit in 984206585f9f1e27897e3e55b3ddbf7bdf30b5c1: This is my fault for not making SourceLocation explicit, but I think this should remain SourceLocation{__func__}, like it was before. This way, it is clear that this is not just a single string literal pointer, but a more complex struct that captures the current source location.

Maybe add the explicit in the prior commit? https://isocpp.github.io/CppCoreGuidelines/CppCoreGuidelines#rc-explicit

Will include in next force push, thanks.

nit in 9842065: Would be nice to mark entry as moved? (void)std::move(entry) in the next line, because clang-tidy does not track partial moves, IIUC? https://godbolt.org/z/fEr4Y59vd

Also, it still seems confusing to have two almost identical structs here and copy them field-by-field.

Why not just keep it a single blob?

diff --git a/src/logging.cpp b/src/logging.cpp
index abccc03abf..0de1f6030b 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -87,4 +87,4 @@ bool BCLog::Logger::StartLogging()
         const auto& buflog = m_msgs_before_open.front();
-        std::string s{buflog.str};
-        FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime);
+        std::string s{buflog.message};
+        FormatLogStrInPlace(s, static_cast<LogFlags>(buflog.category), buflog.level, buflog.source_loc, buflog.thread_name, buflog.timestamp, buflog.mocktime);
         m_msgs_before_open.pop_front();
@@ -374,7 +374,7 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
 
-static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
+static size_t MemUsage(const util::log::Entry& buflog)
 {
-    return memusage::DynamicUsage(buflog.str) +
-           memusage::DynamicUsage(buflog.threadname) +
-           memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
+    return memusage::DynamicUsage(buflog.message) +
+           memusage::DynamicUsage(buflog.thread_name) +
+           memusage::MallocUsage(sizeof(memusage::list_node<util::log::Entry>));
 }
@@ -442,13 +442,4 @@ void BCLog::Logger::LogPrint_(util::log::Entry entry)
         {
-            BufferedLog buf{
-                .now = entry.timestamp,
-                .mocktime = GetMockTime(),
-                .str = std::move(str_prefixed),
-                .threadname = std::move(entry.thread_name),
-                .source_loc = entry.source_loc,
-                .category = static_cast<LogFlags>(entry.category),
-                .level = entry.level,
-            };
-            m_cur_buffer_memusage += MemUsage(buf);
-            m_msgs_before_open.push_back(std::move(buf));
+            m_cur_buffer_memusage += MemUsage(entry);
+            m_msgs_before_open.push_back(std::move(entry));
         }
diff --git a/src/logging.h b/src/logging.h
index b7d4a5f43b..bcd620d8ba 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -130,12 +130,2 @@ namespace BCLog {
     {
-    public:
-        struct BufferedLog {
-            SystemClock::time_point now;
-            std::chrono::seconds mocktime;
-            std::string str, threadname;
-            SourceLocation source_loc;
-            LogFlags category;
-            Level level;
-        };
-
     private:
@@ -144,3 +134,3 @@ namespace BCLog {
         FILE* m_fileout GUARDED_BY(m_cs) = nullptr;
-        std::list<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs);
+        std::list<util::log::Entry> m_msgs_before_open GUARDED_BY(m_cs);
         bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started.
diff --git a/src/util/log.h b/src/util/log.h
index edf387e98b..c05751bf76 100644
--- a/src/util/log.h
+++ b/src/util/log.h
@@ -57,2 +57,3 @@ struct Entry {
     SystemClock::time_point timestamp{SystemClock::now()};
+    std::chrono::seconds mocktime{GetMockTime()};
     std::string thread_name{util::ThreadGetInternalName()};

And then going further and passing it to FormatLogStrInPlace?

nit in 9842065: Would be nice to mark entry as moved?

Included in next force push, thanks. (note: it's removed again in the next commit, which already marked all of entry as moved)

Also, it still seems confusing to have two almost identical structs here and copy them field-by-field. Why not just keep it a single blob?

Did you see commit 23fd3690be8d0d6c6b6a0c12bd32958030d82b93? It does almost exactly what you propose, except for keeping mocktime separate as I think that's a node concern. I'm not vehemently opposed to wholesale combining both structs (and initially implemented it that way), but I do think the separation makes sense?

And then going further and passing it to FormatLogStrInPlace?

That's done in commit e9123b39d4ae8f35bc8ae526122db2390633fe05

ok, I guess I should have looked at all the commits 😅

Maybe add to the commit message. "This will copy the entry fields to BufferedLog, but the next commit cleans this up." (or so). But up to you.

Left the message as-is, I try to minimize references to other (future) commits because it makes rebasing/reordering a lot more painful and is easy to miss resulting in stale messages.

nit/question: This seems a bit arbitrary, why take the time here, but not the mocktime?

diff --git a/src/util/log.h b/src/util/log.h
index edf387e98b..c05751bf76 100644
--- a/src/util/log.h
+++ b/src/util/log.h
@@ -57,2 +57,3 @@ struct Entry {
     SystemClock::time_point timestamp{SystemClock::now()};
+    std::chrono::seconds mocktime{GetMockTime()};
     std::string thread_name{util::ThreadGetInternalName()};

I kept mocktime separate as I think that's a node concern rather than util (e.g. not relevant for kernel iiuc)?

re: #34865 (review)

I kept mocktime separate as I think that's a node concern rather than util (e.g. not relevant for kernel iiuc)?

No strong opinion, but I agree with Marco it would seem simpler to treat time and mock time the same, and I don't think I see a downside to the suggestion since this struct is not exposed by the kernel API. Anything seems fine, though

Alright I've moved everything in util::log::Entry as it simplifies things and it seems there's preference for that approach. Thanks for the feedback!