Add log levels and advertise them to users via logging callback

[theuni]

Fixes #215. Alternative to #216.

This is is implemented roughly as suggested here:

• Adds log levels.
• Adds an additional "Raise" log level.
• Uses the 'Trace' level by default, so existing behavior is unchanged.
• Remains backwards-compatible via a new (deprecated) EventLoop constructor.

Users should not observe any behavioral difference. However, they can now change the log level (using the EventLoop constructor which takes a LogOptions) to set a lower level.

Once merged, Core should take advantage of the new functionality:

• Update the callback function signature.
• Set the requested log level.
• Map mp log levels to Core ones inside the callback.

[DrahtBot]

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	ryanofsky

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #218 (Better error and log messages by ryanofsky)

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.

[ryanofsky]

Code review ACK 72ed9d9. Looks good in current form, but I do have a number of suggestions, which could be followups:

• Would be nice to have just a single MP_LOG macro instead of a collection of macros as suggested. The only thing we need macros for is conditional evaluation. Other logging features are better handled by C++ code. Practically speaking, I think we are going to want more log options beyond just levels to control what is logged, and we will probably want to allow log sink classes other than the event loop to provide more context. For example it'd be nice to pass a Connection object or possible Request object instead of an EventLoop object to MP_LOG as the log sink, and log extra connection & request information, or only conditionally log for certain connections or requests. And it'd be nice to allow logging directives in .capnp files so individual classes or methods could be annotated with logging categories or other information. Like if IPC is used by mining and gui clients, it would be nice to enable logging for just mining events, or a specific subset of GUI events, instead of all IPC calls. It could also be nice to have a log sink that logs the current source location (file/function/line number). I'd like it to be possible to make these changes by simply modifying the Logger class and not having to refactor a collection of macros. This is the reason for defining MP_LOG as a simple forwarding macro in the suggestion. I also think there can be other advantages to avoiding macros like providing clearer compile errors.

• I'm not sure why Logger class needs to be movable, or why it requires separate enabled state. I.e. is there a use-case for m_fn being null and enabled being true? These are implementation details that could be simplified later, though.

• Maybe prefer to call Exception level Raise or Throw. To me, MP_LOGEXCEPTION sounds like something that should be used to log an exception that has already happened, not like something that should be used to trigger one. MP_LOG(Log::Throw, loop) looks more like something that would throw an exception. (Also for background, it may not be clear why there is an exception-throwing feature. The reason is that I wanted applications using libmultiprocess like Bitcoin core to not need their application code to be compiled with libmultiprocess as a dependency. This means that when there are IPC errors like connections being broken, client exceptions need to be constructed by the application, so node/wallet/GUI code can be built just referencing local exception types not using libmultiprocess or capnproto type definitions.)

• Would be nice to rename LogLevel to just Log so log prints could be a little shorter like: MP_LOG(Log::Info, loop) << "something something". I also feel like the exception level is not really a level, and more of a behavior flag. And I could also imagine other flags like Log::RateLimit being defined for progress messages that should be rate limited. A simple Log:: prefix seems good enough whatever logging flag might be needed.

• Would be nice to not to break the API so it is easier to bump bitcoin subtree and not have to include bitcoin core changes in the libmultiprocess merge commit, or introduce a broken commit that doesn't compile. Seems like it should be possible to do this by keeping the EventLoop(std::function<void(bool, std::string)> log_fn) constructor unchanged, and setting options.log_fn = [log_fn](level, message) { log_fn(level == Exception, msesage); } when it is called.

[theuni]

Would be nice to have just a single MP_LOG macro instead of a collection of macros as suggested.

Sure, no preference here. Happy to do that.

I'm not sure why Logger class needs to be movable, or why it requires separate enabled state. I.e. is there a use-case for m_fn being null and enabled being true? These are implementation details that could be simplified later, though.

The constructor changes started as a bugfix, and I just finished them up for the sake of completion. Unless I'm misreading, currently in master, if moved, the moved-from logger will invoke the callback with an empty buffer.

I don't have a use-case in mind... I can just disable moving if you'd prefer.

As for the enabled variable, I agree it's unnecessary and awkward. I considered just setting m_fn to nullptr if disabled, but decided the intention of the code was more clear with a separate variable. Happy to change this if you'd prefer.

Maybe prefer to call Exception level Raise or Throw. To me, MP_LOGEXCEPTION sounds like something that should be used to log an exception that has already happened, not like something that should be used to trigger one. MP_LOG(Log::Throw, loop) looks more like something that would throw an exception. (Also for background, it may not be clear why there is an exception-throwing feature. The reason is that I wanted applications using libmultiprocess like Bitcoin core to not need their application code to be compiled with libmultiprocess as a dependency. This means that when there are IPC errors like connections being broken, client exceptions need to be constructed by the application, so node/wallet/GUI code can be built just referencing local exception types not using libmultiprocess or capnproto type definitions.)

Thanks, that's helpful context. And indeed, I was confused about why this error was not a raise().

Would be nice to rename LogLevel to just Log so log prints could be a little shorter like: MP_LOG(Log::Info, loop) << "something something". I also feel like the exception level is not really a level, and more of a behavior flag. And I could also imagine other flags like Log::RateLimit being defined for progress messages that should be rate limited. A simple Log:: prefix seems good enough whatever logging flag might be needed.

No problem with renaming. And yeah, I went back and forth on the exception level question.

Would be nice to not to break the API so it is easier to bump bitcoin subtree and not have to include bitcoin core changes in the libmultiprocess merge commit, or introduce a broken commit that doesn't compile. Seems like it should be possible to do this by keeping the EventLoop(std::function<void(bool, std::string)> log_fn) constructor unchanged, and setting options.log_fn = [log_fn](level, message) { log_fn(level == Exception, msesage); } when it is called.

Clever, I can do that.

---

For the sake of getting this in more quickly, I'm going to punt on the implementation details for now and just focus on the API changes. I do agree (or at least, don't strongly disagree) with all of your suggestions, so I'd be happy to do them as a follow-up.

Thinking about this more, for future-proofing, I think it'd be good for the callback to simply take a LogData struct which could be extended in the future as needed, without having to change the function signature again. That would allow us to punt on some of the implementation details for now. Specifically, I'd propose:

namespace mp {
  struct LogData {
    std::string message;
    LogLevel level;
    // Future flags and stuff.
  };

  using LogFn = std::function<void(LogData)>;
}

Thoughts?

[ryanofsky]

The constructor changes started as a bugfix, and I just finished them up for the sake of completion. Unless I'm misreading, currently in master, if moved, the moved-from logger will invoke the callback with an empty buffer.

I don't have a use-case in mind... I can just disable moving if you'd prefer.

Makes sense, and nice to fix that bug. I think I'd want to disable moving unless there is a reason to have it, but fine either way.

As for the enabled variable, I agree it's unnecessary and awkward. I considered just setting m_fn to nullptr if disabled, but decided the intention of the code was more clear with a separate variable. Happy to change this if you'd prefer.

Yeah seems fine either way, but could be nice to get rid of. Especially if move & assignments functions go away and there is reduced boilerplate in general.

Thanks, that's helpful context. And indeed, I was confused about why this error was not a raise().

I think this one is not a raise because point of raising is to return individual exceptions to clients that they can handle and potentially recover from. If taskFailed raised an exception, because it is called from the event loop thread, I think that would end the whole event loop and break all IPC connections, which could be an overreaction. There may be a better way to make this customizable though.

Thinking about this more, for future-proofing, I think it'd be good for the callback to simply take a LogData struct which could be extended in the future as needed, without having to change the function signature again.

I like that idea. I think I might call the struct LogMessage instead of LogData just to be more descriptive, and because I"m a little allergic to suffixes like Info and Data that don't indicate anything specific.

PR looks good as is, but any of these changes would be welcome if you want to implement them. Thanks for finding the issue and providing this nice solution.

[theuni]

I just went ahead and implemented all of the feedback from above. Sorry for the substantial diff from the last push, just figured it'd be better to get it all knocked out in one go :)

Major changes:

• Logger now just takes a const reference to the loop's LogOptions. If necessary in the future (for other structures with different lifetimes), this can just be a copy.
• Renamed LogLevel to Log and Exception to Raise.
• Dropped the m_enabled variable, now calculated on-the-fly.
• Dropped level-specific macros.
• MP_LOG and MP_LOGPLAIN now just forward their parameters along.
• The logging callback now passes a lone mp::LogMessage parameter.
• Added a back-compat constructor as suggested.

[ryanofsky]

Code review ACK cd00f72. Looks very good.

Notes for possible followups, could:

• Remove deprecated Eventloop constructor
• Rename MP_LOGPLAIN to MP_LOG, have Logger constructor take log destination objects other than Eventloop
  • Different destination objects could prepend thread names, request numbers, etc
  • Destination variables could make serverInvoke and clientInvoke code more readable
• Maybe add streaming helpers to support automatically formatting structs and applying max_chars, and maybe support conditional output like << LogAt(Log::Trace, [&](auto& logger) { logger << response; }

[theuni]

Notes for possible followups, could:

Agree with all of these.

Here's a branch ready for PR'ing into Core to take advantage of the changes here: https://github.com/theuni/bitcoin/commits/libmultiprocess-logging-bump/

[ryanofsky]

Thanks, I'll go ahead and merge this today and open a subtree bump PR for bitcoin. If we want these changes to be in v30 (which is sounds like you do?) I believe I will also need to open up a separate subtree bump PR for the 30.x branch, assuming marco's comment in bitcoin/bitcoin#33439 (comment) is right.

I could add your commits from https://github.com/theuni/bitcoin/commits/libmultiprocess-logging-bump/ to the subtree bump PR too, though it seems like it might be less confusing if that was a separate PR. Happy to do whatever you prefer,

Would still welcome more reviews here if anyone wants to look. Looking around at other changes that could be merged: #213 and #214 seem ready and #212, #218, and #221 could also be ready if reviewed.

[sipa]

Do we want to pass LogMessage by value? It's 40 bytes here, while I think the normal advice is max 2 pointers worth for objects passed by value.

[ryanofsky]

const LogMessage& could make sense semantically. Only disadvantage might be that if log handler wanted to move the string or message into another data structure, it would no longer be able to do that, and would need to copy it instead. Probably a log handler would not do that, but it's not inconceivable. Maybe LogMessage&& would make more sense?

I'm guessing choice doesn't matter too much since cost of moving the struct should be small compared to cost of invoking the function through a pointer and actually formatting the log message. And it should be possible to change the type without breaking compatibility later, so anything here seems fine.

[theuni]

Only disadvantage might be that if log handler wanted to move the string or message into another data structure, it would no longer be able to do that, and would need to copy it instead. Probably a log handler would not do that, but it's not inconceivable. Maybe LogMessage&& would make more sense?

This was my thinking as well. And since libmultiprocess always calls this function from Logger's dtor (just before the string is erased), it will always be move constructed. LogMessage&& would be fine too, but I don't see much upside there, and tend to reserve that for universal references unless there's some meaningful difference.

[theuni]

Thanks, I'll go ahead and merge this today and open a subtree bump PR for bitcoin. If we want these changes to be in v30 (which is sounds like you do?) I believe I will also need to open up a separate subtree bump PR for the 30.x branch, assuming marco's comment in bitcoin/bitcoin#33439 (comment) is right.

I agree in principle, seems like having a branch for v30 makes sense just generally speaking.

But for now at least, looking at libmultiprocess master, I don't see the harm in just bumping to everything in master + this pr? Everything since the last bump seems pretty straightforward, unless there's some potential for a regression that I'm not seeing?

I could add your commits from https://github.com/theuni/bitcoin/commits/libmultiprocess-logging-bump/ to the subtree bump PR too, though it seems like it might be less confusing if that was a separate PR. Happy to do whatever you prefer,

I could go ahead and open a PR for my branch, then rebase after the bump. That way we can get parallel review with a separation of concerns.

Would still welcome more reviews here if anyone wants to look. Looking around at other changes that could be merged: #213 and #214 seem ready and #212, #218, and #221 could also be ready if reviewed.

Thanks, will have a look.

[ryanofsky]

But for now at least, looking at libmultiprocess master, I don't see the harm in just bumping to everything in master + this pr? Everything since the last bump seems pretty straightforward, unless there's some potential for a regression that I'm not seeing?

Yes I think we want to backport all libmultiprocess changes into the 30.x release branch, or none of them as discussed in #33439, and avoid doing something more complicated like cherry-picking.

So far no libmultiprocess changes have been backported since the branch was created, but it should not be a problem to do that. I just need to create two bitcoin PRs instead of one.

I could go ahead and open a PR for my branch, then rebase after the bump. That way we can get parallel review with a separation of concerns.

Sounds good, that'd be helpful

[ryanofsky]

Hmm, I was about to merge this but didn't realize there was a silent merge conflict with #214. Do you think you could rebase?

Will close and reopen to trigger CI. Sorry for not noticing this before.

[theuni]

Done. Fixed the silent conflict. Diff from the rebase is just:

diff --git a/include/mp/type-context.h b/include/mp/type-context.h
index 0ca3579..09ac179 100644
--- a/include/mp/type-context.h
+++ b/include/mp/type-context.h
@@ -153,7 +153,7 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn&
                 MP_LOG(*server.m_context.loop, Log::Debug)
                     << "IPC server post request  #" << req << " {" << thread.m_thread_context.thread_name << "}";
                 if (!thread.m_thread_context.waiter->post(std::move(invoke))) {
-                    server.m_context.loop->log()
+                    MP_LOG(*server.m_context.loop, Log::Error)
                         << "IPC server error request #" << req
                         << " {" << thread.m_thread_context.thread_name << "}" << ", thread busy";
                     throw std::runtime_error("thread busy");

[ryanofsky]

Code review ACK 515ce93. Just rebased and fixed compile error caused by new log print since last review