util: Refactor logging code into a global object #12954

jimpo commented at 10:03 PM on April 11, 2018: contributor

This is purely a refactor with no behavior changes.

This creates a new class BCLog::Logger to encapsulate all global logging configuration and state.

fanquake added the label Utils/log/libs on Apr 11, 2018

fanquake added the label Refactoring on Apr 11, 2018

laanwj commented at 5:57 AM on April 12, 2018: member

Concept ACK, splitting the logging functionality out of util makes sense, util.cpp is large, haphazard and this is a clearly distinguishable concern from the rest.

MarcoFalke commented at 1:51 PM on April 13, 2018: member

Concept ACK. Needs rebase

jimpo force-pushed on Apr 16, 2018

in src/util.h:67 in 67cd23663c outdated

 150 | -    } \
 151 | -} while(0)
 152 | -#endif
 153 | -
 154 |  template<typename... Args>
 155 |  bool error(const char* fmt, const Args&... args)

sipa commented at 2:32 AM on April 16, 2018:

I think this should move to logging as well, so the cyclic dependency between logging and util can be avoided.

jimpo commented at 2:47 AM on April 16, 2018:

LogPrintf is also used in TraceThread, and I don't think either of them actually belong in logging (the whole point of this PR is to create a more cohesive separation). I can very easily imagine another method that gets added to util.h in the future requiring logging as well.

The dependency isn't really cyclic -- logging.cpp includes util.h, and util.h includes logging.h, but logging.h does not include util.h.

sipa commented at 6:04 AM on April 16, 2018:

My view is that you should always treat the .h and the .cpp file as one unit. While this may indeed not be a cyclic dependency for the compiler, it is certainly one between the two modules semantically: logging can't work without util, and util can't work without logging. Finding out why that is the case helps creating a cleaner separation.

You're right that util is going to depend on logging though, as it contains a number of higher level functions. However, It looks like logging only really needs util for finding the debug log path, though. All the rest is in utiltime. This seems easy to fix, by instead having init query the path and call a setter on logging for it for example. If other reviewers are fine with that, we can fix that up in another PR.

Empact commented at 3:03 AM on April 20, 2018:

Last I looked, when reviewing #13021, I saw another approach to solving the cyclic dependency is to include utiltime.h in logging.cpp and splitting out args and path handling from util.h. Didn’t go all the way to implementing that but would be happy to as a follow-on to #13021.

Empact commented at 3:08 AM on April 20, 2018:

Lol, didn’t finish reading your comment @sipa. Anyway I’m for it.

jimpo commented at 8:16 AM on April 20, 2018:

Fixed with d903273cf8e51d2789ba8a88c608a66e63dcdc14.

sipa commented at 2:34 AM on April 16, 2018: member

Concept ACK

jimpo force-pushed on Apr 16, 2018

MarcoFalke commented at 3:26 PM on April 17, 2018: member

Needs rebase again. (Since this has some Concept ACKs, but is somewhat largish, it might be easier to merge in two steps. First the move-only commit in a separate pull request and then the refactoring in this pull request)

sipa referenced this in commit 8b262eb2d8 on Apr 20, 2018

jimpo force-pushed on Apr 20, 2018

in src/logging.h:71 in d903273cf8 outdated

  67 | +        /**
  68 | +         * m_started_new_line is a state variable that will suppress printing of
  69 | +         * the timestamp when multiple calls are made that don't end in a
  70 | +         * newline.
  71 | +         */
  72 | +        std::atomic_bool m_started_new_line{true};

jnewbery commented at 2:29 PM on April 20, 2018:

Note that this maintains the old (broken) behaviour:

two threads are running. Thread A logs a line that doesn't terminate with a newline (ie a 'continuing' log)
thread B then logs a line. This is treated as a 'continuation' log of thread A's previous log, and is printed on the same line, without a timestamp
thread A's 'continuation' log is printed on a new line, with a timestamp

No need to fix that in this PR.

in src/logging.h:24 in d903273cf8 outdated

  20 | @@ -19,15 +21,7 @@ static const bool DEFAULT_LOGIPS        = false;
  21 |  static const bool DEFAULT_LOGTIMESTAMPS = true;
  22 |  extern const char * const DEFAULT_DEBUGLOGFILE;
  23 |  
  24 | -extern bool fPrintToConsole;
  25 | -extern bool fPrintToDebugLog;
  26 | -
  27 | -extern bool fLogTimestamps;
  28 | -extern bool fLogTimeMicros;
  29 |  extern bool fLogIPs;

jnewbery commented at 3:13 PM on April 20, 2018:

In commit util: Establish global logger object. : any reason to exclude fLogIPs from g_logger?

jimpo commented at 6:50 AM on April 23, 2018:

It's not actually used by the logger, it's just used in the net code. Arguably it should live there instead.

jnewbery commented at 3:16 PM on April 20, 2018: member

Tested ACK d903273cf8e51d2789ba8a88c608a66e63dcdc14. Couple of comments inline but nothing to prevent merge.

in src/logging.cpp:258 in d903273cf8 outdated

 258 | @@ -264,7 +259,7 @@ void BCLog::Logger::ShrinkDebugFile()
 259 |          int nBytes = fread(vch.data(), 1, vch.size(), file);

MarcoFalke commented at 9:17 PM on April 21, 2018:

Unrelated nit: Could change int to size_t here, so that it doesn't break when someone changes RECENT_DEBUG_HISTORY_SIZE to 5GB.

in src/logging.cpp:133 in d903273cf8 outdated

 132 | -            *f = BCLog::ALL;
 133 | +    if (str == "") {
 134 | +        flag = BCLog::ALL;
 135 | +        return true;
 136 | +    }
 137 | +    for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) {

jamesob commented at 6:31 PM on April 25, 2018:

nit: seems like you could phrase this more simply as

for (CLogCategoryDesc& cat : LogCategories) { ... }

There doesn't seem to be a need to have the index on hand.

jimpo commented at 3:58 AM on April 30, 2018:

Nice, fixed. Also gets rid of the dependency of logging on utilstrencodings.

jamesob approved

jamesob commented at 7:34 PM on April 25, 2018: member

Tested ACK https://github.com/bitcoin/bitcoin/pull/12954/commits/d903273cf8e51d2789ba8a88c608a66e63dcdc14

./src/qt/bitcoin-qt -regtest -conf="$(pwd)/bitcoin.conf" -debug=1
- Displays all available logs.
./src/qt/bitcoin-qt -testnet -conf="$(pwd)/bitcoin.conf" -debug=0
- Displays only uncategorized logs.
./src/qt/bitcoin-qt -testnet -conf="$(pwd)/bitcoin.conf" -debug=1
- Displays all available logs.
./src/qt/bitcoin-qt -testnet -conf="$(pwd)/bitcoin.conf" -help
- Displays available logging categories for -debug.
./src/bitcoind -debug=foobar
- Warns of invalid logging category.
./src/bitcoind -debug=1 -debugexclude=net,addrman,rand,leveldb
- Displays all available logs (confusing, but this matches behavior on master).
./src/bitcoind -debugexclude=net,addrman,rand,leveldb
- Excludes specified log categories.
./src/bitcoind -testnet -config="$(pwd)/bitcoin.conf" -debug=reindex -reindex
- Shows reindex-related log messages.
./src/bitcoind -testnet -config="$(pwd)/bitcoin.conf" -debug=net -reindex
- Shows no reindex-related log messages, but plenty of net-related ones.

Nice change. The one nit I had definitely shouldn't hold this up.

jimpo force-pushed on Apr 27, 2018

util: Establish global logger object.

The object encapsulates logging configuration, and in a later commit,
set up routines will also be moved into the class.

f55f4fcf05

util: Move debug file management functions into Logger. 6a6d764ca5

util: Encapsulate logCategories within BCLog::Logger. 3316a9ebb6

jimpo force-pushed on Apr 27, 2018

util: Refactor GetLogCategory.

Changing parameter types from pointers to references and uint32_t to
BCLog::LogFlags simplies calling code.

1eac317f25

scripted-diff: Rename BCLog::Logger member variables.

-BEGIN VERIFY SCRIPT-
sed -i "s/fileout/m_fileout/" src/logging.h src/logging.cpp
sed -i "s/mutexDebugLog/m_file_mutex/" src/logging.h src/logging.cpp
sed -i "s/vMsgsBeforeOpenLog/m_msgs_before_open/" src/logging.h src/logging.cpp
sed -i "s/logCategories/m_categories/" src/logging.h src/logging.cpp
sed -i "s/fPrintToConsole/m_print_to_console/" src/logging.h src/logging.cpp src/init.cpp
sed -i "s/fPrintToDebugLog/m_print_to_file/" src/logging.h src/logging.cpp src/init.cpp src/test/test_bitcoin.cpp src/bench/bench_bitcoin.cpp
sed -i "s/fLogTimestamps/m_log_timestamps/" src/logging.h src/logging.cpp src/init.cpp
sed -i "s/fLogTimeMicros/m_log_time_micros/" src/logging.h src/logging.cpp src/init.cpp
sed -i "s/fReopenDebugLog/m_reopen_file/" src/logging.h src/logging.cpp src/init.cpp
sed -i "s/fStartedNewLine/m_started_new_line/" src/logging.h src/logging.cpp
-END VERIFY SCRIPT-

8e7b961388

util: Store debug log file path in BCLog::Logger member.

This breaks the cyclic between logging and util.

8c2d695c4a

jimpo force-pushed on Apr 29, 2018

jnewbery commented at 1:17 PM on April 30, 2018: member

utACK 8c2d695c4. Only difference is changing to range based for loops per #12954 (review)

sipa commented at 2:10 AM on May 1, 2018: member

utACK 8c2d695c4a45bdd9378c7970b0fcba6e1efc01f9. Nice to see this encapsulated.

sipa merged this on May 1, 2018

sipa closed this on May 1, 2018

sipa referenced this in commit 5a666428b0 on May 1, 2018

jimpo deleted the branch on May 1, 2018

jasonbcox referenced this in commit a1f767f4b1 on Oct 25, 2019

Fuzzbawls referenced this in commit c94f2412af on Apr 14, 2020

PastaPastaPasta referenced this in commit 12309092de on Jul 18, 2020

PastaPastaPasta referenced this in commit fb21ce6d7e on Jul 19, 2020

jonspock referenced this in commit d1d90548d8 on Oct 1, 2020

jonspock referenced this in commit 54b62ff4b4 on Oct 5, 2020

jonspock referenced this in commit 219a16e9e6 on Oct 10, 2020

UdjinM6 referenced this in commit ab6a5238c2 on May 21, 2021

UdjinM6 referenced this in commit 671f1f8943 on May 25, 2021

TheArbitrator referenced this in commit b0565b3691 on Jun 4, 2021

gades referenced this in commit dcf9b6220e on Jun 30, 2021

MarcoFalke locked this on Sep 8, 2021