The logging facility of bitcoind writes debug and informational messages to debug.log
at the top level of the data directory. A brief description can be found in the
developer notes.
LogPrintf() writes to debug.log unconditionallly. These messages are considered important
enough to always be written.
LogPrint() takes a category as its first argument,
and only writes to debug.log if the specified category is enabled.
The list of categories is defined by
enum LogFlags.
The user can enable a logging category, for example NET (p2p messages) by specifing
the configuration option debug=net. The strings are defined by
[LogCategories](https://github.com/bitcoin/bitcoin/blob/0c2a1288a210916254c939d080ce12ffc5547841/src/logging.cpp#L150)
but the mapping from the enum category symbols to strings is trivial.
The logging categories can also be enabled and disabled at runtime using the
logging
RPC.
Multiple logging categories can be enabled simultaneously by specifying
multiple debug= config options.
PR #9424 changed the logging
categories from a set of strings (like "net") to a enumeration type (NET).
What does this PR do, and what is the problem it proposes to address?
What are the advantages of std::bitset compared with bit manipulations on integers?
An earlier attempt, PR #26619, was closed
in favor of the current PR. What are some advantages and disadvantages of each approach?
There are two special logging categories, ALL and NONE. Why are these needed?
Logger::m_categories
was wrapped by std::atomic. Why was that needed? Why is it no longer needed?
Following on to that question, some
concern was expressed
on the PR about performance, and the need for benchmarking. Why would this be important?
An unknown P2P message does not cause a LogPrintf() message. Why not?
Wouldn’t it be helpful to see if a peer is sending us a message we don’t
understand?
Does the same principle apply to RPC, REST, or ZMQ requests?
<roze_paul> I just read over the file changes and comments, going back to maxwell's PR in late 2016...but i didn't test...AFAIK all the testing added amounts to one in-line code (asserts)
<kouloumos> I haven't finish looking at the implementation yet, but what I started with is gathering context about how the change came to be, other related logging changes, other usages of bit operation in the codebase and looked a bit into the performance
<LarryRuane> did you notice that `std::bitset` has a fixed size (number of bits)? the fact that the number of bits is specified within angle brackets indicates that
<roze_paul> we get to get rid of the manual bitshifting code...which i don't understand why this is such a huge advantage, but it was stated in the notes as an advantage
<LarryRuane> lightlike: yes, there may be fewer code conflicts to resolve (like if two PRs allocate the same bit)... although those aren't too hard to resolve
<LarryRuane> on the other hand, `std::bitset` may reveal too much of the underlying representation... but I don't think so because could be _conceptual_ bits (flags)
<LarryRuane> we kind of covered this already, but Q4: An earlier attempt, PR #26619, was closed in favor of the current PR. What are some advantages and disadvantages of each approach?
<roze_paul> re. q4: the previous approach (26619) required less work, in that there was no approach change, just a change from 32 to 64 bit integers...in that sense it probably required less testing and review, which is an advantage
<LarryRuane> brunoerg: right, it's conceivable that we could need more than 64 logging categories in the future (new subsystems or make them more fine-grained)
<LarryRuane> I think another advantage of the closed 26619 is that we can still use std::atomic (I couldn't figure out how to wrap `std::bitset` with `std::atomic` but maybe there's a way)
<roze_paul> @larry do you use trace levels, to get all the data, and then filter the logging data yourself...just thinking of a way to work around using levels..
<roze_paul> Q5: not entirely sure, but i think calling all will turn on all logging topics, and none will turn of (bitset.reset) all topics...ALL also conveys the number of total number of topics, if one wants that info
<LarryRuane> the functional tests do this, because they assume that by default you would want to see all categories, AND, there's one other reason, anyone know why?
<LarryRuane> anyway, I think the other reason the functional tests enable all categories is to test the `LogPrint` calls! It would be bad if you enabled a category, and the `LogPrint` dereferenced a null pointer or something and crashed the process
<LarryRuane> we kind of touched on this already, but Q6 `Logger::m_categories` was wrapped by `std::atomic`. Why was that needed? Why is it no longer needed?
<kouloumos> interesting! I've seen that for functional tests there are some logging categories that we ignore, could this become be an issue if such regression occurs for those categories?
<kouloumos> I think it was needed because of concurrency due to different components wanting to access the logger. I was curious why it was now replaced with locks, but I think you already touched why.
<LarryRuane> good transition to Q7 Following on to that question, some concern was expressed on the PR about performance, and the need for benchmarking. Why would this be important?
<LarryRuane> but it's hard to say how important that difference is (is it a drop in the ocean compared with a half-drop in the ocean? Or is it a drop in the glass of water?) ... depends on the surrounding code
<LarryRuane> Q8 An unknown P2P message does not cause a LogPrintf() message. Why not? Wouldn’t it be helpful to see if a peer is sending us a message we don’t understand?
<kouloumos> Also looking into those benchmarks, I was wondering how significant are the results of such a logging benchmark. They are benchmarking the performance of a single invocation, is this actually a good metric?
<LarryRuane> we're at time, didn't get to Q10 The Logger::WillLogCategory is annotated with const; what does this mean? How is it possible to modify the object by locking m_cs?
<LarryRuane> b_101: both of you are on exactly the right track ... `const` means that calling this method won't change the state of the object (it's a "read-only" call)
<LarryRuane> but `mutable` does allow you to cheat, in that a const method can make changes that are actual functional changes! i.e. change the _logical_ state of the object
<LarryRuane> i.e. nothing in the language verifies that your use of `mutable` and `const` functions are non-functional ... there's probably no way to automatically check that
<LarryRuane> b_101: yes, I think `LOCK()` is the most common way to do locking (I don't know why the logging subsystem doesn't use `LOCK`), but what that macro does is actually declare a (local) variable with some constructed artificial name,
<LarryRuane> and that variable's constructor actually does the mutex lock, and its destructor does the unlock.. which is very clever! it's hard to make the mistake of forgetting to unlock a mutex (like it is if you're doing unlocking explicitly)
<LarryRuane> you may notice lots of places where there's an opening brace (`{`) then a call to `LOCK`, then a small amount of code, then the close brace ... that's to limit the duration of the mutex locking to just the block of code (not locked after the close brace)
<LarryRuane> `StdLockGuard scoped_lock(m_cs)` has that same property as `LOCK` where the unlock is automatic, but with `StdLockGuard` you're making the variable visible (you choose the name), instead of it being hidden within the `LOCK` macro
<LarryRuane> and as i said, i don't really know why it's done that way in the logging subsystem ... maybe historical? maybe `LOCK` didn't exist when the logging code was written? not sure