Merge bitcoin#23057: log: Consolidate timedata logging

laanwj · laanwj · commit d8b4b3077fd2 · 2021-09-23T16:55:47.000+02:00
64e1ddd log: call LogPrint only once with time data samples (Martin Zumsande) Pull request description: When timedata samples are logged, `LogPrint()` is currently invoked multiple times on the same log entry. This can lead to chaos in the log when other threads log concurrently, as in this example which motivated this PR: ``` 2021-09-20T00:28:57Z -48 -26 -11 -8 -6 Addrman checks started: new 37053, tried 83, total 37136 2021-09-20T00:28:57Z -3 -1 -1 -1 -1 +0 | nTimeOffset = -3 (+0 minutes) ``` Fix this by building the log message in a string and logging it one `LogPrint()` call. I also changed the wording slightly so that it becomes understandable what is being logged, example: ``` 2021-09-21T21:03:24Z time data samples: -43 -18 -12 -4 -1 -1 +0 +0 +268 | median offset = -1 (+0 minutes) ``` ACKs for top commit: jnewbery: Tested ACK 64e1ddd laanwj: Tested ACK 64e1ddd, new message lgtm Tree-SHA512: ffb7a93166cc8fd6a39200b9e03a9d1e8e975b7ded822ccddd015f553258b991162a5cb867501f426d3ebcfef4f32f0e06e17b18e6b01486b967595d102f8379
diff --git a/src/timedata.cpp b/src/timedata.cpp
@@ -11,6 +11,7 @@
 #include <netaddress.h>
 #include <node/ui_interface.h>
 #include <sync.h>
+#include <tinyformat.h>
 #include <util/system.h>
 #include <util/translation.h>
 #include <warnings.h>
@@ -98,11 +99,12 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample)
         }
 
         if (LogAcceptCategory(BCLog::NET)) {
+            std::string log_message{"time data samples: "};
             for (const int64_t n : vSorted) {
-                LogPrint(BCLog::NET, "%+d  ", n); /* Continued */
+                log_message += strprintf("%+d  ", n);
             }
-            LogPrint(BCLog::NET, "|  "); /* Continued */
-            LogPrint(BCLog::NET, "nTimeOffset = %+d  (%+d minutes)\n", nTimeOffset, nTimeOffset / 60);
+            log_message += strprintf("|  median offset = %+d  (%+d minutes)", nTimeOffset, nTimeOffset / 60);
+            LogPrint(BCLog::NET, "%s\n", log_message);
         }
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -11,6 +11,7 @@`
`11`	`11`	`#include <netaddress.h>`
`12`	`12`	`#include <node/ui_interface.h>`
`13`	`13`	`#include <sync.h>`
	`14`	`+#include <tinyformat.h>`
`14`	`15`	`#include <util/system.h>`
`15`	`16`	`#include <util/translation.h>`
`16`	`17`	`#include <warnings.h>`
`@@ -98,11 +99,12 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample)`
`98`	`99`	`}`
`99`	`100`
`100`	`101`	`if (LogAcceptCategory(BCLog::NET)) {`
	`102`	`+ std::string log_message{"time data samples: "};`
`101`	`103`	`for (const int64_t n : vSorted) {`
`102`		`- LogPrint(BCLog::NET, "%+d ", n); /* Continued */`
	`104`	`+ log_message += strprintf("%+d ", n);`
`103`	`105`	`}`
`104`		`- LogPrint(BCLog::NET, "\| "); /* Continued */`
`105`		`- LogPrint(BCLog::NET, "nTimeOffset = %+d (%+d minutes)\n", nTimeOffset, nTimeOffset / 60);`
	`106`	`+ log_message += strprintf("\| median offset = %+d (%+d minutes)", nTimeOffset, nTimeOffset / 60);`
	`107`	`+ LogPrint(BCLog::NET, "%s\n", log_message);`
`106`	`108`	`}`
`107`	`109`	`}`
`108`	`110`	`}`