log: Consolidate timedata logging #23057

mzumsande commented at 9:35 PM on September 21, 2021: member

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)

mzumsande force-pushed on Sep 21, 2021

in src/timedata.cpp:107 in 0a0e966dbf outdated

 105 | +                logMessage += strprintf("%+d  ", n);
 106 |              }
 107 | -            LogPrint(BCLog::NET, "|  "); /* Continued */
 108 | -            LogPrint(BCLog::NET, "nTimeOffset = %+d  (%+d minutes)\n", nTimeOffset, nTimeOffset / 60);
 109 | +            logMessage += strprintf("|  median offset = %+d  (%+d minutes)", nTimeOffset, nTimeOffset / 60);
 110 | +            LogPrint(BCLog::NET, "%s\n", logMessage);

jonatack commented at 9:59 PM on September 21, 2021:

Inside the if (LogAcceptCategory(BCLog::NET)) conditional, the check is already done so can just use LogPrintf (see src/logging.h#L191 where the same check is run if a log category is passed)

jnewbery commented at 8:47 AM on September 22, 2021:

I think it's still better to use LogPrint(BCLog::NET, ...), since that makes it easier to grep for lines that log to a specific category. If we have more structured logging in future, then it'd be better if logs were logging to the correct category.

mzumsande commented at 8:52 PM on September 22, 2021:

that makes sense to me - e.g. at some point we might decide to include the log category in the log entry in some form - so I'll keep it.

jonatack commented at 12:39 PM on September 23, 2021:

I think it's still better to use LogPrint(BCLog::NET, ...), since that makes it easier to grep for lines that log to a specific category.

Grep-ability (grepness?) is essential but a comment on the same line can do that too. In any case just an observation, it doesn't need to be done in this pach.

jonatack commented at 9:59 PM on September 21, 2021: member

Concept ACK

DrahtBot added the label Utils/log/libs on Sep 21, 2021

in src/timedata.cpp:102 in 0a0e966dbf outdated

  98 | @@ -98,11 +99,12 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample)
  99 |          }
 100 |  
 101 |          if (LogAcceptCategory(BCLog::NET)) {
 102 | +            std::string logMessage{"time data samples: "};

jnewbery commented at 8:47 AM on September 22, 2021:

nit: current project style would be:

            std::string log_message{"time data samples: "};

mzumsande commented at 8:52 PM on September 22, 2021:

renamed the variable.

in src/timedata.cpp:104 in 0a0e966dbf outdated

  98 | @@ -98,11 +99,12 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample)
  99 |          }
 100 |  
 101 |          if (LogAcceptCategory(BCLog::NET)) {
 102 | +            std::string logMessage{"time data samples: "};
 103 |              for (const int64_t n : vSorted) {
 104 | -                LogPrint(BCLog::NET, "%+d  ", n); /* Continued */
 105 | +                logMessage += strprintf("%+d  ", n);

jnewbery commented at 8:49 AM on September 22, 2021:

Note that concatenating to a std::string can be inefficient, since it may need to reallocate multiple times if the buffer isn't large enough. You could use str::string::reserve to avoid reallocations, but I don't think it's worth it here, since this log is built only a few times during each run of the application.

mzumsande commented at 8:58 PM on September 22, 2021:

I agree - will keep this in mind, thanks!

laanwj commented at 12:28 PM on September 23, 2021:

tinyformat also isn't really optimized for speed, and using it this way it returns a temporary string, which is copied then deallocated, every time it's called

but yeah it's for optional debug logging, not building a 500MB XML document, i don't think performance at this level is any concern here

jnewbery commented at 8:49 AM on September 22, 2021: member

Concept ACK

log: call LogPrint only once with time data samples

This prevents malformed log entries caused by other threads
logging concurrently.

64e1ddd255

mzumsande force-pushed on Sep 22, 2021

jnewbery commented at 9:55 AM on September 23, 2021: member

Tested ACK 64e1ddd255

MarcoFalke commented at 11:46 AM on September 23, 2021: member

Concept ACK. I guess any log statement that is /*Continued*/ is affected by this.

mzumsande commented at 12:53 PM on September 23, 2021: member

Concept ACK. I guess any log statement that is /*Continued*/ is affected by this.

Not all are affected - in some places /*Continued*/ is used to appease the linter when the string for a single LogPrintf is spread over multiple lines. I did have a short look before opening this PR, and while there are other spots, this one seemed by far the worst offender because of the number of potential LogPrint() calls

jonatack commented at 12:59 PM on September 23, 2021: member

TIL about lint-logs.sh. Looks like some of the continued annotations can be removed (not necessarily in this patch). Though they may be useful as documentation of intent.

laanwj commented at 1:34 PM on September 23, 2021: member

Also the intentional, relevant uses of Continued seem to be for progress percentages, and run during Init when most threads haven't been spun up yet (so very little chance of concurrency confusion).

laanwj commented at 2:54 PM on September 23, 2021: member

Tested ACK 64e1ddd255771e57a88a20f07dbde04a83bf0c75, new message lgtm

2021-09-23T14:41:15Z time data samples: -44  -41  -39  -37  -36  -28  -25  -23  -21  -20  -20  -18  -17  -16  -16  -15  -12  -11  -11  -10  -10  -10  -10  -8  -6  -4  -4  -4  -3  -3  -3  -3  -3  -2  +0  |  median offset = -11  (+0 minutes)

laanwj merged this on Sep 23, 2021

laanwj closed this on Sep 23, 2021

sidhujag referenced this in commit 180c576fd4 on Sep 24, 2021

MarcoFalke commented at 11:50 AM on September 27, 2021: member

Fixed the others in #23104

DrahtBot locked this on Oct 30, 2022

mzumsande deleted the branch on Jun 23, 2023