RFC: Instanced logs #30338
RFC: Instanced logs #30338
Conversation
THIS COMMIT DOES NOT COMPILE! Add an instance param to every logging macro/function. The next commit will add the global LogInstance() to each callsite. This will allow us to use an instantiated logger rather than assuming a static global, which will be especially useful for the kernel.
-BEGIN VERIFY SCRIPT- sed -i -e 's/LogInfo(/LogInfo(LogInstance(), /g' $(git grep -l LogInfo\( ./src | grep -v logging.h) && \ sed -i -e 's/LogWarning(/LogWarning(LogInstance(), /g' $(git grep -l LogWarning\( ./src | grep -v logging.h) && \ sed -i -e 's/LogError(/LogError(LogInstance(), /g' $(git grep -l LogError\( ./src | grep -v logging.h) && \ sed -i -e 's/LogDebug(/LogDebug(LogInstance(), /g' $(git grep -l LogDebug\( ./src | grep -v logging.h) && \ sed -i -e 's/LogTrace(/LogTrace(LogInstance(), /g' $(git grep -l LogTrace\( ./src | grep -v logging.h) && \ sed -i -e 's/LogPrintfCategory(/LogPrintfCategory(LogInstance(), /g' $(git grep -l LogPrintfCategory\( ./src | grep -v logging.h) && \ sed -i -e '/WalletLogPrintf(/!s/LogPrintf(/LogPrintf(LogInstance(), /g' $(git grep -l LogPrintf\( ./src | grep -v logging.h) && \ sed -i -e 's/LogPrintLevel(/LogPrintLevel(LogInstance(), /g' $(git grep -l LogPrintLevel\( ./src | grep -v logging.h) && \ sed -i -e 's/LogPrint(/LogPrint(LogInstance(), /g' $(git grep -l LogPrint\( ./src | grep -v logging.h) && \ sed -i -e 's/LogAcceptCategory(/LogAcceptCategory(LogInstance(), /g' $(git grep -l LogAcceptCategory\( ./src | grep -v logging.h) && \ sed -i -e 's/ LogPrintf_(/ LogInstance().LogPrintf_(/g' src/test/logging_tests.cpp -END VERIFY SCRIPT-
|
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. Code CoverageFor detailed information about the code coverage, see the test coverage report. ReviewsSee the guideline for information on the review process. ConflictsReviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first. |
|
Ping @TheCharlatan @ajtowns @maflcko for Concept (N)ACKs |
|
🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the Possibly this is due to a silent merge conflict (the changes in this pull request being Leave a comment here, if you need help tracking down a confusing failure. |
| assert(p <= limit); | ||
| base[std::min(bufsize - 1, (int)(p - base))] = '\0'; | ||
| LogPrintLevel(BCLog::LEVELDB, BCLog::Level::Debug, "%s", base); // NOLINT(bitcoin-unterminated-logprintf) | ||
| LogPrintLevel(LogInstance(), BCLog::LEVELDB, BCLog::Level::Debug, "%s", base); // NOLINT(bitcoin-unterminated-logprintf) |
There was a problem hiding this comment.
This makes the call sites even more verbose and LogInstance(), is repeated everywhere. In this case one improvement could be to use a default argument for that parameter which defaults to LogInstance() but I can see that this may not play well with the ... arguments.
Maybe introduce another function that takes (category, level, instance, ...)? Or check if the first of ... arguments in (category, level, ...) is a log instance and if not, then default the instance to LogInstance()? Something like:
class Logger
{
};
template <typename... Args>
void Log(int, const Logger&, const Args&...)
{
}
template <typename... Args>
void f(int a, const Args&... args)
{
auto CallLog = [&](const auto& first, const auto&... rest) {
if constexpr (std::is_same<decltype(first), Logger>::value) {
Log(a, first, rest...);
} else {
Log(a, Logger{}, first, rest...);
}
};
CallLog(args...);
}
int main(int, char**)
{
f(5, 6);
f(8, Logger{}, 9);
return 0;
}There was a problem hiding this comment.
re: #30338 (comment)
This makes the call sites even more verbose and
LogInstance(), is repeated everywhere
See #30342 for an alternative which should make everything less verbose. For example, this line changes to LogDebug(m_log, "%s", base);
|
🐙 This pull request conflicts with the target branch and needs rebase. |
I don't understand where this is coming from. Libraries can export globals, eg |
Being forced to eliminate all globals doesn't seem to be the claim here? As long as the globals don't carry over annoying state from previous usage, require annoying initialization, or aren't mostly safe from user misuse, their usage is fine. Next to what was brought up before about having the ability to distinguish between between the logged lines from multiple instances, there are a few other problems with the existing implementation that make its usage as a global annoying at the moment. If an instantiated logger is a red line here, we might be able to find other solutions though. The current implementation buffers without a limit until I also noticed that any logs buffered before the user applies their own user-defined options will be printed in the default format and with default categories. Re-starting logging is also awkward to do at the moment. Logging is workable for the kernel library as is, but it would be nice to address the remaining pain points. I think having instantiated logging would be the best way to solve these issues, making it clear to the user when something will be logged, as well as giving guarantees on its format. |
The opposite of instanced parameters is globals; if instanced parameters are necessary, then globals aren't possible. The claim in the OP is that the "instanced logs" proposed here are "necessary for the kernel".
I assume that's referring to the concept of rewriting
Limiting the buffer could make sense. We could also tweak the defaults to be more suitable for the kernel (eg, no buffering of logs prior to // logging.h
class LoggingLaunchSettings
{
public:
template<typename Fn>
LoggingLaunchSettings(Fn&& fn) { Logger logger = LogInstance(); fn(logger); }
};
// init.cpp
static BCLog::LoggingLaunchSettings bitcoind_logging_control{
[](auto& logger) { logger.m_early_buffer = true; }
};Other users of libkernel who wanted buffering could then do the same thing.
Buffering debug/trace logging prior to Fixing the formatting of buffered logs is a bit of work, but not very complicated. It doesn't seem particularly related to the kernel, though. Would you review a PR to do that?
I'm not sure what you mean? There's
Touching every single line of logging code for a "nice to have" doesn't make much sense to me. It's nice to be able to just shove a |
AJ I know we are disagreeing about a lot of things, and I do not fault you in any way for this, but your reactions seem very strong relative the actual scope of changes we would like to make. We should set aside Cory's big scripted diff commit here, which I think is a proof of concept and an illustrative change, not an actual change being proposed to merge. I think the actual changes being considered would look a lot more like:
Which come from #30342 and yes, I can understand, probably you do not love. But I don't understand how they would have a discernible negative impact or why you would want to spend time arguing against them? These seem like basically trivial changes. I am sincerely asking about this, because I do not understand what you see as being at stake here. |
|
Yes, @ryanofsky. This was a POC (FWIW I am actually very ok with the scripted-diff approach which touches every line, but I didn't expect it to be popular). At this point I'd prefer to throw my weight behind #30342 as it accomplishes what I want without being so invasive. I won't add to the arguing here as I think you and @TheCharlatan have said what I would've anyway. |
|
Thanks for going through this. Having something like
yes :)
Besides the incoherent naming between the two, it also starts buffering again when calling |
Have a look at ajtowns#9 and see what you think; obviously needs a little cleaning up before PRing properly. It also has a commit to add
Not really sure what else you'd expect it to do? I don't really see why you'd ever "restart" logging rather than "reconfiguring" it while it's still running though, at least outside of tests. |
I don't know what you want me to say here? I didn't say "THAT'S CRAZY YOU SHOULD ALL BE PUT IN AN ASYLUM"; I said "it doesn't make much sense to me". The only way to be less strong about my opinion is to be entirely silent... Your patches are roughly how I imagine Cory's would eventually look, and they still touch every single line of logging code (*in the kernel, anyway). That just seems completely unnecessary to me. The kernel library already works; I don't think logging needs major changes in order for it to not only work but work well with the kernel.
For instance, once we have |
|
Thanks AJ, it's great to get specific and find out what actual problems you are concerned about, before coming to the conclusion that it is too difficult to remove one hard dependency on global shared state, and therefore we should resort to workarounds such as running code in multiple processes, or finding ways to reset the state and coordinate access to it.
The same way you add temporary logging now. With #30342, if you are modifying bitcoind or bitcoin-qt, you can continue to write The goal is to allow (and probably require) external applications using the kernel library to specify log instances. The goal is not to get rid of global state in bitcoind and bitcoin-qt. The idea is to let applications using the kernel library work with multiple data directories and simulate actions of multiple nodes, while collecting output from each separately, not mixed in a single stream. (Also, more speculatively, being able to specify log instances could make it easier to use the kernel library to write software that connects multiple networks, or to use kernel library as a dependency of another library that allows having separate instances of its own state.) Obviously, we can have a debate about how important these features are, or discuss a myriad of workarounds to implement them in different ways, but we should also evaluate what a straightforward approach of just declaring logger variables and using them looks like, and what the advantages and disadvantages of this approach are. Having implemented e9b91f5 and facc2d0 I don't see real disadvantages, as - LogPrintf("Wiping LevelDB in %s\n", fs::PathToString(params.path));
+ LogInfo(m_log, "Wiping LevelDB in %s\n", fs::PathToString(params.path));seems like a boring and straightforward change to me.
Right, In bitcoind and bitcoin-qt, if a log statement does not specify a logger, it should just go to the global log instance. By contrast, libbitcoinkernel probably would be more flexible if it didn't come with a default log instance, so any instance could be the default instance. A straightforward approach would be to a have a |
What I'm concerned about is making logging unnecessarily complicated to use -- it should be easy to use, and it should be easy to understand what's going on without needing any context from the rest of the module where the logging is happening, or from debates about how logging should work. You asked about specific problems this change could cause; and I'm happy to give examples, but they're not my fundamental concern.
To me, the logic goes: okay, there's going to be global shared state anyway, how can we make it as simple as possible to deal with? And having multiple references to the same object that we pass around, even though there's a global anyway, doesn't make things simpler.
I don't think it makes sense to do that within a single process / address space, personally. I really don't think it makes sense to make it more complicated to maintain bitcoind/bitcoin-qt in order to optimise speculative simulation software.
I don't think this change is straightforward: if it were, this PR wouldn't need to be a WIP that still needs a bunch of other changes in a followup to work.
The idea, as I understand it, would be that you'd invoke: at which point chainman could initialise But that approach breaks if you're initialising the logger based on a conf file that you manage with It also breaks for the various global mutexes that are still in the kernel (just
That's begging the question... The goal, the important thing, should be to have some observable benefit, that is achieved by that change, not to make the change itself. I believe the important thing this PR is attempting to resolve is more along the lines of "it should be easy to use libbitcoinkernel from a quick and dirty C++ program (along the lines of bitcoin-chainstate), without having to worry about doing anything with logging at all -- at most creating a dummy logger because it's a mandatory argument to some constructors. That should then work fine without potentially leaking memory or any other problems. Preferably, adding a simple one-liner should be enough to enable outputting all the logging information so that you can debug your program just like in bitcoind". I think "being able to use two (or more) different BlockManager objects in the same program at the same time and distinguish their logs" isn't important, though it might be nice. Likewise "if I write a libbitcoinkernel program and haven't added a one-liner to enable logging, logging is a no-op and it should be optimised as such and execute as quick as possible". |
This looks good to me, thank you for implementing. Regarding disabling the buffering, I'm not sure if defaulting to off in our code is a good idea. How about this as an alternative: sedited@86fed95 ? The library would always be configured to not buffer. The user could choose at compile time to leave this initialization out, or override it at runtime. |
I don't think anything is broken here, or maybe we have different ideas of what broken means. In any case, I don't understand what problem you see here, and think it would be helpful if you could describe whatever the issue is more fully. I appreciate you acknowledging the benefits of applications being able to declare their own loggers that are "fully initialised (on construction) before potentially being used anywhere" and even saying "might be nice" to be able to use different log instances for different purposes. I think, at this point, we both understand the benefits of not hardcoding logging macros to use a single global leaked log instance, even while we disagree about the magnitude of the benefits. I am trying to focus discussion on the costs, not the benefits, because we seem to disagree about not just the magnitude of the costs, but whether they exist at all. For example you are mentioning complexity without pointing to complicated changes or complicated code, and you are saying certain things are broken when they don't seem to be obviously broken. It would be good to clear these things up so neither of us have misconceptions. |
Not really convinced explaining things is getting anywhere? Sometimes you have to try fully implementing your idea before you realise it doesn't work... As I understand it, your proposal is (a) that the kernel will not have a global logger instance; but since mutexes do logging, they will need a logger instance, and since we use mutexes in the kernel they cannot use the global logger instance; therefore (b) you suggest that the each Mutex class can just have a logger instance of its own; however this doesn't work for two reasons:
I really wish you'd do likewise at some point... It feels like I'm saying "just treat everything as orbiting the sun, it's simpler" and just getting "no, we're here on earth, and we can make the maths work if we just ..." in response.
The point of looking at the benefits is you can see whether there might be some other way of achieving the same benefits. "I'd like to get from point A to B, and a Lambo will get me there, and I know it's expensive, but I just want to focus on if whether we can afford it". I'm not sure what you think the benefits actually are (eg, if we keep a global logger for mutexes around, then there's still a global logger in the kernel) -- and they seem to keep changing while the solution remains the same...
The PR that we're commenting on is +1000 -1000 and isn't even remotely complete. You're coming up with random extra ideas to perhaps fix edge cases, though you don't think they're necessary. Things look broken to me, but not to you. You keep saying things that suggest you don't think I'm an idiot, but if that's the case, then all of that is evidence that this isn't just a simple tweak. Passing a logger through constructors and keep tracking of it in member variables is already more complex than just having a global; additionally having a global that is automatically initialised and cleared would be much more complicated when you start taking thread-safety into account. |
I think #30342 is a full implementation of making it possible the specify log instances kernel code should use. If you are looking for an implementation of a change to remove the hardcoded global logger instance from the kernel (replacing it as described with a global pointer to a default fallback log instance), see ecadc8f. (EDIT: added link to implementation)
Thank you for clarifying. This is not what I'm proposing. Mutexes don't normally log anything except lock contention prints and inconsistent lock order warnings when certain debug options are turned on. I don' t think there is a need for libbitcoinkernel users to be able specify which specific logger instance these are logged to. Allowing kernel users to create multiple logger instances but warning them that if (1) they create multiple instances simultaneously and (2) they enable very low-level log prints, the prints might be sent to the first instance seems fine. If it is not fine, with a small amount of extra work we can also allow them to specify which instance even kernel lock order warnings get sent to. I just don't see a need to do this.
I am sorry, but the situation where we heap-allocate a global logger and leak it and hardcode all log prints in the codebase to use a shared logger does not seem simpler than the approach I am proposing where a log instance is just a normal object, and if you want code control where log output goes, you just pass it the log instance you want to use, and do not worry about global initialization order and heaving a memory leak, and coordinating shared access to the logger with reset functions, and buffering etc. I understand the current situation works well for bitcoind and bitcoin-qt code, but I think it will hamstring potential uses of libbitcoinkernel, and I think there is a way to have the best of both worlds that will reduce rather than increase complexity. I understand the previous statements are subjective, that passing the variable you want to use to the function you want to call may be simpler to some people, and making the variable a global accessed from everywhere may be simpler to other people. I just think if you look specifically at kernel logging, the two approaches are just not very different from each other and #30342 is a small, straightforward change that not does not have other objectively negative effects. I also want to apologize if this discussion is frustrating and I am sorry for only responding the technical parts of your posts and not responding to "meta" comments about lambos and +1000-1000 changes. I just think right now you are thinking about a different change than what I am proposing and it is important to clear up technical, objective disagreements before focusing on more subjective ones. |
Okay, see #30386 for the more serious take. I have another patch that I could add on top that would also buffer early debug/trace logs, but that seemed a bit unnecessary (LMK if it would be useful).
With the PR above, the behaviour is:
That feels fine to me, but ymmv. I think having the same "default" between the kernel code as used by bitcoind and the kernel code as exposed in a library is better than having it be different; not too fussed on what that default is. |
|
⌛ There hasn't been much activity lately and the patch still needs rebase. What is the status here?
|
PR'ing this early as an RFC because it's a lot of work that will require constant rebasing. This is the first logical step and is mostly mechanical.
This PR adds an "instance" param to each log function and callsite. As is, there should be no functional change here.
The intention is to allow for a specific instance to be passed in each time we use the logger, rather than the implicit global as we have it now. Eventually (one subsystem/chunk at a time), this will allow us to instantiate a per-context logger, which is necessary for the kernel.
This is my second iteration. The first approach can be seen here: theuni@533e75e. It was much cleaner and used c++20's
std::source_location, however it proved to be impossible to do lazy variadic parameter evaluation that way. The approach here is rather dumb, but it should incur no performance penalty.If there's a rough consensus on this approach, I'd like to go ahead and get this PR cleaned up and merged so that I can begin the work of converting global
LogInstance()s to real instances. The first major goal would be to allow the kernel/bitcoin-chainstate to be used without the static global instance.Note that the first commit will not compile. The second is a massive scripted-diff. If that's a problem, I can add a commit which introduces dummy macros, then switch them back after the scripted-diff.