From 83a2e10c0b03c0e7b20316babeaf6700caa6a1e8 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Fri, 26 Sep 2025 16:01:51 +0000 Subject: [PATCH 1/8] Logging: Add an EventLoop constructor to allow for user-specified log options --- include/mp/proxy-io.h | 9 +++++++-- src/mp/proxy.cpp | 4 ++-- 2 files changed, 9 insertions(+), 4 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index 9be80625..3673151e 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -168,8 +168,13 @@ std::string LongThreadName(const char* exe_name); class EventLoop { public: - //! Construct event loop object. - EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr); + //! Construct event loop object with default logging options. + EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr) + : EventLoop(exe_name, LogOptions{std::move(log_fn)}, context){} + + //! Construct event loop object with specified logging options. + EventLoop(const char* exe_name, LogOptions log_opts, void* context = nullptr); + ~EventLoop(); //! Run event loop. Does not return until shutdown. This should only be diff --git a/src/mp/proxy.cpp b/src/mp/proxy.cpp index 06825c99..271682c8 100644 --- a/src/mp/proxy.cpp +++ b/src/mp/proxy.cpp @@ -191,13 +191,13 @@ void EventLoop::addAsyncCleanup(std::function fn) startAsyncThread(); } -EventLoop::EventLoop(const char* exe_name, LogFn log_fn, void* context) +EventLoop::EventLoop(const char* exe_name, LogOptions log_opts, void* context) : m_exe_name(exe_name), m_io_context(kj::setupAsyncIo()), m_task_set(new kj::TaskSet(m_error_handler)), + m_log_opts(std::move(log_opts)), m_context(context) { - m_log_opts.log_fn = log_fn; int fds[2]; KJ_SYSCALL(socketpair(AF_UNIX, SOCK_STREAM, 0, fds)); m_wait_fd = fds[0]; From 463a8296d188afc7ca89a783a09757bab91d6f1f Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Mon, 29 Sep 2025 20:09:25 +0000 Subject: [PATCH 2/8] Logging: Disable moving or copying Logger --- include/mp/proxy-io.h | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index 3673151e..f4442b85 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -104,7 +104,12 @@ class Logger { public: Logger(bool raise, LogFn& fn) : m_raise(raise), m_fn(fn) {} - Logger(Logger&& logger) : m_raise(logger.m_raise), m_fn(logger.m_fn), m_buffer(std::move(logger.m_buffer)) {} + + Logger(Logger&&) = delete; + Logger& operator=(Logger&&) = delete; + Logger(const Logger&) = delete; + Logger& operator=(const Logger&) = delete; + ~Logger() noexcept(false) { if (m_fn) m_fn(m_raise, m_buffer.str()); From d0a1ba7ebf21ef612089cb4f1b1cb9e45467dd13 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Thu, 25 Sep 2025 20:52:17 +0000 Subject: [PATCH 3/8] Logging: add log levels to mirror Core's For now, all messages are reported at Log::Info. --- include/mp/proxy-io.h | 49 +++++++++++++++++++++++++++---------------- 1 file changed, 31 insertions(+), 18 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index f4442b85..e4c5f9f7 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -98,12 +98,35 @@ class LoggingErrorHandler : public kj::TaskSet::ErrorHandler EventLoop& m_loop; }; +enum class Log { + Trace = 0, + Debug, + Info, + Warning, + Error, + Raise, +}; + using LogFn = std::function; +struct LogOptions { + + //! External logging callback. + LogFn log_fn; + + //! Maximum number of characters to use when representing + //! request and response structs as strings. + size_t max_chars{200}; + + //! Messages with a severity level less than log_level will not be + //! reported. + Log log_level{Log::Trace}; +}; + class Logger { public: - Logger(bool raise, LogFn& fn) : m_raise(raise), m_fn(fn) {} + Logger(const LogOptions& options, Log log_level) : m_options(options), m_log_level(log_level) {} Logger(Logger&&) = delete; Logger& operator=(Logger&&) = delete; @@ -112,13 +135,13 @@ class Logger ~Logger() noexcept(false) { - if (m_fn) m_fn(m_raise, m_buffer.str()); + if (m_options.log_fn) m_options.log_fn(m_log_level == Log::Raise, m_buffer.str()); } template friend Logger& operator<<(Logger& logger, T&& value) { - if (logger.m_fn) logger.m_buffer << std::forward(value); + if (logger.m_options.log_fn) logger.m_buffer << std::forward(value); return logger; } @@ -128,21 +151,11 @@ class Logger return logger << std::forward(value); } - bool m_raise; - LogFn& m_fn; + const LogOptions& m_options; + Log m_log_level; std::ostringstream m_buffer; }; -struct LogOptions { - - //! External logging callback. - LogFn log_fn; - - //! Maximum number of characters to use when representing - //! request and response structs as strings. - size_t max_chars{200}; -}; - std::string LongThreadName(const char* exe_name); //! Event loop implementation. @@ -222,12 +235,12 @@ class EventLoop Logger log() { - Logger logger(false, m_log_opts.log_fn); + Logger logger(m_log_opts, Log::Info); logger << "{" << LongThreadName(m_exe_name) << "} "; return logger; } - Logger logPlain() { return {false, m_log_opts.log_fn}; } - Logger raise() { return {true, m_log_opts.log_fn}; } + Logger logPlain() { return {m_log_opts, Log::Info}; } + Logger raise() { return {m_log_opts, Log::Raise}; } //! Process name included in thread names so combined debug output from //! multiple processes is easier to understand. From 67b092d835cd9ff9721da66cd5f718292665b659 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Mon, 29 Sep 2025 20:16:52 +0000 Subject: [PATCH 4/8] Logging: Disable logging if messsage level is less than the requested level --- include/mp/proxy-io.h | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index e4c5f9f7..e28adc2b 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -135,13 +135,13 @@ class Logger ~Logger() noexcept(false) { - if (m_options.log_fn) m_options.log_fn(m_log_level == Log::Raise, m_buffer.str()); + if (enabled()) m_options.log_fn(m_log_level == Log::Raise, m_buffer.str()); } template friend Logger& operator<<(Logger& logger, T&& value) { - if (logger.m_options.log_fn) logger.m_buffer << std::forward(value); + if (logger.enabled()) logger.m_buffer << std::forward(value); return logger; } @@ -151,6 +151,17 @@ class Logger return logger << std::forward(value); } + explicit operator bool() const + { + return enabled(); + } + +private: + bool enabled() const + { + return m_options.log_fn && m_log_level >= m_options.log_level; + } + const LogOptions& m_options; Log m_log_level; std::ostringstream m_buffer; From 408874a78fdc4ba83eb1a3adef51c447399a0319 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Mon, 29 Sep 2025 20:17:31 +0000 Subject: [PATCH 5/8] Logging: Use new logging macros The Info log level is still used for all messages other than exceptions. Also remove now-unused log functions. --- include/mp/proxy-io.h | 17 ++++++----------- include/mp/proxy-types.h | 24 ++++++++++++------------ include/mp/type-context.h | 6 +++--- src/mp/proxy.cpp | 6 +++--- 4 files changed, 24 insertions(+), 29 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index e28adc2b..458b32d6 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -167,6 +167,10 @@ class Logger std::ostringstream m_buffer; }; +#define MP_LOGPLAIN(loop, ...) if (mp::Logger logger{(loop).m_log_opts, __VA_ARGS__}; logger) logger + +#define MP_LOG(loop, ...) MP_LOGPLAIN(loop, __VA_ARGS__) << "{" << LongThreadName((loop).m_exe_name) << "} " + std::string LongThreadName(const char* exe_name); //! Event loop implementation. @@ -244,15 +248,6 @@ class EventLoop //! Check if loop should exit. bool done() const MP_REQUIRES(m_mutex); - Logger log() - { - Logger logger(m_log_opts, Log::Info); - logger << "{" << LongThreadName(m_exe_name) << "} "; - return logger; - } - Logger logPlain() { return {m_log_opts, Log::Info}; } - Logger raise() { return {m_log_opts, Log::Raise}; } - //! Process name included in thread names so combined debug output from //! multiple processes is easier to understand. const char* m_exe_name; @@ -677,7 +672,7 @@ std::unique_ptr> ConnectStream(EventLoop& loop, int f init_client = connection->m_rpc_system->bootstrap(ServerVatId().vat_id).castAs(); Connection* connection_ptr = connection.get(); connection->onDisconnect([&loop, connection_ptr] { - loop.log() << "IPC client: unexpected network disconnect."; + MP_LOG(loop, Log::Info) << "IPC client: unexpected network disconnect."; delete connection_ptr; }); }); @@ -700,7 +695,7 @@ void _Serve(EventLoop& loop, kj::Own&& stream, InitImpl& init }); auto it = loop.m_incoming_connections.begin(); it->onDisconnect([&loop, it] { - loop.log() << "IPC server: socket disconnected."; + MP_LOG(loop, Log::Info) << "IPC server: socket disconnected."; loop.m_incoming_connections.erase(it); }); } diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index 222defd9..dfa88efe 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -568,7 +568,7 @@ template void clientDestroy(Client& client) { if (client.m_context.connection) { - client.m_context.loop->log() << "IPC client destroy " << typeid(client).name(); + MP_LOG(*client.m_context.loop, Log::Info) << "IPC client destroy " << typeid(client).name(); } else { KJ_LOG(INFO, "IPC interrupted client destroy", typeid(client).name()); } @@ -577,7 +577,7 @@ void clientDestroy(Client& client) template void serverDestroy(Server& server) { - server.m_context.loop->log() << "IPC server destroy " << typeid(server).name(); + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server destroy " << typeid(server).name(); } //! Entry point called by generated client code that looks like: @@ -605,7 +605,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel // declaration so the server method runs in a dedicated thread. assert(!g_thread_context.loop_thread); g_thread_context.waiter = std::make_unique(); - proxy_client.m_context.loop->logPlain() + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << g_thread_context.thread_name << "} IPC client first request from current thread, constructing waiter"; } @@ -629,13 +629,13 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel using FieldList = typename ProxyClientMethodTraits::Fields; invoke_context.emplace(*proxy_client.m_context.connection, thread_context); IterateFields().handleChain(*invoke_context, request, FieldList(), typename FieldObjs::BuildParams{&fields}...); - proxy_client.m_context.loop->logPlain() + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << thread_context.thread_name << "} IPC client send " << TypeName() << " " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); proxy_client.m_context.loop->m_task_set->add(request.send().then( [&](::capnp::Response&& response) { - proxy_client.m_context.loop->logPlain() + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << thread_context.thread_name << "} IPC client recv " << TypeName() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); try { @@ -653,7 +653,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel disconnected = "IPC client method call interrupted by disconnect."; } else { kj_exception = kj::str("kj::Exception: ", e).cStr(); - proxy_client.m_context.loop->logPlain() + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << thread_context.thread_name << "} IPC client exception " << kj_exception; } const Lock lock(thread_context.waiter->m_mutex); @@ -665,8 +665,8 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel Lock lock(thread_context.waiter->m_mutex); thread_context.waiter->wait(lock, [&done]() { return done; }); if (exception) std::rethrow_exception(exception); - if (!kj_exception.empty()) proxy_client.m_context.loop->raise() << kj_exception; - if (disconnected) proxy_client.m_context.loop->raise() << disconnected; + if (!kj_exception.empty()) MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Raise) << kj_exception; + if (disconnected) MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Raise) << disconnected; } //! Invoke callable `fn()` that may return void. If it does return void, replace @@ -700,7 +700,7 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) using Results = typename decltype(call_context.getResults())::Builds; int req = ++server_reqs; - server.m_context.loop->log() << "IPC server recv request #" << req << " " + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server recv request #" << req << " " << TypeName() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); try { @@ -717,14 +717,14 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); }, [&]() { return kj::Promise(kj::mv(call_context)); }) .then([&server, req](CallContext call_context) { - server.m_context.loop->log() << "IPC server send response #" << req << " " << TypeName() + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server send response #" << req << " " << TypeName() << " " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars); }); } catch (const std::exception& e) { - server.m_context.loop->log() << "IPC server unhandled exception: " << e.what(); + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server unhandled exception: " << e.what(); throw; } catch (...) { - server.m_context.loop->log() << "IPC server unhandled exception"; + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server unhandled exception"; throw; } } diff --git a/include/mp/type-context.h b/include/mp/type-context.h index 9bd939e4..8ff3b938 100644 --- a/include/mp/type-context.h +++ b/include/mp/type-context.h @@ -150,16 +150,16 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn& // thread. KJ_IF_MAYBE (thread_server, perhaps) { const auto& thread = static_cast&>(*thread_server); - server.m_context.loop->log() + MP_LOG(*server.m_context.loop, Log::Info) << "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::Info) << "IPC server error request #" << req << " {" << thread.m_thread_context.thread_name << "}" << ", thread busy"; throw std::runtime_error("thread busy"); } } else { - server.m_context.loop->log() + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server error request #" << req << ", missing thread to execute request"; throw std::runtime_error("invalid thread handle"); } diff --git a/src/mp/proxy.cpp b/src/mp/proxy.cpp index 271682c8..e57ba9ec 100644 --- a/src/mp/proxy.cpp +++ b/src/mp/proxy.cpp @@ -42,7 +42,7 @@ thread_local ThreadContext g_thread_context; void LoggingErrorHandler::taskFailed(kj::Exception&& exception) { KJ_LOG(ERROR, "Uncaught exception in daemonized task.", exception); - m_loop.log() << "Uncaught exception in daemonized task."; + MP_LOG(m_loop, Log::Info) << "Uncaught exception in daemonized task."; } EventLoopRef::EventLoopRef(EventLoop& loop, Lock* lock) : m_loop(&loop), m_lock(lock) @@ -251,9 +251,9 @@ void EventLoop::loop() break; } } - log() << "EventLoop::loop done, cancelling event listeners."; + MP_LOG(*this, Log::Info) << "EventLoop::loop done, cancelling event listeners."; m_task_set.reset(); - log() << "EventLoop::loop bye."; + MP_LOG(*this, Log::Info) << "EventLoop::loop bye."; wait_stream = nullptr; KJ_SYSCALL(::close(post_fd)); const Lock lock(m_mutex); From e4de0412b4308ef636ac0ee31562db0140b12801 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Fri, 26 Sep 2025 00:00:45 +0000 Subject: [PATCH 6/8] Logging: Break out expensive log messages and classify them as Trace --- include/mp/proxy-types.h | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index dfa88efe..054c1dd8 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -631,13 +631,17 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel IterateFields().handleChain(*invoke_context, request, FieldList(), typename FieldObjs::BuildParams{&fields}...); MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << thread_context.thread_name << "} IPC client send " - << TypeName() << " " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); + << TypeName(); + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace) + << "send data: " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); proxy_client.m_context.loop->m_task_set->add(request.send().then( [&](::capnp::Response&& response) { MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) << "{" << thread_context.thread_name << "} IPC client recv " - << TypeName() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); + << TypeName(); + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace) + << "recv data: " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars); try { IterateFields().handleChain( *invoke_context, response, FieldList(), typename FieldObjs::ReadResults{&fields}...); @@ -701,7 +705,9 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) int req = ++server_reqs; MP_LOG(*server.m_context.loop, Log::Info) << "IPC server recv request #" << req << " " - << TypeName() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); + << TypeName(); + MP_LOG(*server.m_context.loop, Log::Trace) << "request data: " + << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); try { using ServerContext = ServerInvokeContext; @@ -717,8 +723,9 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); }, [&]() { return kj::Promise(kj::mv(call_context)); }) .then([&server, req](CallContext call_context) { - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server send response #" << req << " " << TypeName() - << " " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars); + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server send response #" << req << " " << TypeName(); + MP_LOG(*server.m_context.loop, Log::Trace) << "response data: " + << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars); }); } catch (const std::exception& e) { MP_LOG(*server.m_context.loop, Log::Info) << "IPC server unhandled exception: " << e.what(); From 213574ccc43d6b644a67de7144b16907388f42ae Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Fri, 26 Sep 2025 00:07:59 +0000 Subject: [PATCH 7/8] Logging: reclassify remaining log messages --- include/mp/proxy-io.h | 2 +- include/mp/proxy-types.h | 12 ++++++------ include/mp/type-context.h | 6 +++--- src/mp/proxy.cpp | 2 +- 4 files changed, 11 insertions(+), 11 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index 458b32d6..ce1c4bf8 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -672,7 +672,7 @@ std::unique_ptr> ConnectStream(EventLoop& loop, int f init_client = connection->m_rpc_system->bootstrap(ServerVatId().vat_id).castAs(); Connection* connection_ptr = connection.get(); connection->onDisconnect([&loop, connection_ptr] { - MP_LOG(loop, Log::Info) << "IPC client: unexpected network disconnect."; + MP_LOG(loop, Log::Warning) << "IPC client: unexpected network disconnect."; delete connection_ptr; }); }); diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index 054c1dd8..22468b15 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -629,7 +629,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel using FieldList = typename ProxyClientMethodTraits::Fields; invoke_context.emplace(*proxy_client.m_context.connection, thread_context); IterateFields().handleChain(*invoke_context, request, FieldList(), typename FieldObjs::BuildParams{&fields}...); - MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Debug) << "{" << thread_context.thread_name << "} IPC client send " << TypeName(); MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace) @@ -637,7 +637,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel proxy_client.m_context.loop->m_task_set->add(request.send().then( [&](::capnp::Response&& response) { - MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info) + MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Debug) << "{" << thread_context.thread_name << "} IPC client recv " << TypeName(); MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace) @@ -704,7 +704,7 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) using Results = typename decltype(call_context.getResults())::Builds; int req = ++server_reqs; - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server recv request #" << req << " " + MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server recv request #" << req << " " << TypeName(); MP_LOG(*server.m_context.loop, Log::Trace) << "request data: " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); @@ -723,15 +723,15 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); }, [&]() { return kj::Promise(kj::mv(call_context)); }) .then([&server, req](CallContext call_context) { - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server send response #" << req << " " << TypeName(); + MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName(); MP_LOG(*server.m_context.loop, Log::Trace) << "response data: " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars); }); } catch (const std::exception& e) { - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server unhandled exception: " << e.what(); + MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception: " << e.what(); throw; } catch (...) { - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server unhandled exception"; + MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception"; throw; } } diff --git a/include/mp/type-context.h b/include/mp/type-context.h index 8ff3b938..09ac1790 100644 --- a/include/mp/type-context.h +++ b/include/mp/type-context.h @@ -150,16 +150,16 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn& // thread. KJ_IF_MAYBE (thread_server, perhaps) { const auto& thread = static_cast&>(*thread_server); - MP_LOG(*server.m_context.loop, Log::Info) + 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))) { - MP_LOG(*server.m_context.loop, Log::Info) + 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"); } } else { - MP_LOG(*server.m_context.loop, Log::Info) + MP_LOG(*server.m_context.loop, Log::Error) << "IPC server error request #" << req << ", missing thread to execute request"; throw std::runtime_error("invalid thread handle"); } diff --git a/src/mp/proxy.cpp b/src/mp/proxy.cpp index e57ba9ec..95da96b5 100644 --- a/src/mp/proxy.cpp +++ b/src/mp/proxy.cpp @@ -42,7 +42,7 @@ thread_local ThreadContext g_thread_context; void LoggingErrorHandler::taskFailed(kj::Exception&& exception) { KJ_LOG(ERROR, "Uncaught exception in daemonized task.", exception); - MP_LOG(m_loop, Log::Info) << "Uncaught exception in daemonized task."; + MP_LOG(m_loop, Log::Error) << "Uncaught exception in daemonized task."; } EventLoopRef::EventLoopRef(EventLoop& loop, Lock* lock) : m_loop(&loop), m_lock(lock) From 515ce93ad349380ff44e2141009d4aa7c9545654 Mon Sep 17 00:00:00 2001 From: Cory Fields Date: Mon, 29 Sep 2025 20:49:49 +0000 Subject: [PATCH 8/8] Logging: Pass LogData struct to logging callback The previous logging callback signature is deprecated and support will be removed in a future release. Also adds a include to calculator example to make IWYU happy. --- example/calculator.cpp | 2 ++ example/example.cpp | 6 +++--- example/printer.cpp | 6 +++--- include/mp/proxy-io.h | 19 +++++++++++++++++-- test/mp/test/test.cpp | 6 +++--- 5 files changed, 28 insertions(+), 11 deletions(-) diff --git a/example/calculator.cpp b/example/calculator.cpp index 016a0486..86ce388b 100644 --- a/example/calculator.cpp +++ b/example/calculator.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -37,6 +38,7 @@ class InitImpl : public Init } }; +// Exercises deprecated log callback signature static void LogPrint(bool raise, const std::string& message) { if (raise) throw std::runtime_error(message); diff --git a/example/example.cpp b/example/example.cpp index 5088f796..38313977 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -35,10 +35,10 @@ static auto Spawn(mp::EventLoop& loop, const std::string& process_argv0, const s return std::make_tuple(mp::ConnectStream(loop, fd), pid); } -static void LogPrint(bool raise, const std::string& message) +static void LogPrint(mp::LogMessage log_data) { - if (raise) throw std::runtime_error(message); - std::ofstream("debug.log", std::ios_base::app) << message << std::endl; + if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message); + std::ofstream("debug.log", std::ios_base::app) << log_data.message << std::endl; } int main(int argc, char** argv) diff --git a/example/printer.cpp b/example/printer.cpp index eb384018..9150d59b 100644 --- a/example/printer.cpp +++ b/example/printer.cpp @@ -32,10 +32,10 @@ class InitImpl : public Init std::unique_ptr makePrinter() override { return std::make_unique(); } }; -static void LogPrint(bool raise, const std::string& message) +static void LogPrint(mp::LogMessage log_data) { - if (raise) throw std::runtime_error(message); - std::ofstream("debug.log", std::ios_base::app) << message << std::endl; + if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message); + std::ofstream("debug.log", std::ios_base::app) << log_data.message << std::endl; } int main(int argc, char** argv) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index ce1c4bf8..0abef89d 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -107,7 +107,16 @@ enum class Log { Raise, }; -using LogFn = std::function; +struct LogMessage { + + //! Message to be logged + std::string message; + + //! The severity level of this message + Log level; +}; + +using LogFn = std::function; struct LogOptions { @@ -135,7 +144,7 @@ class Logger ~Logger() noexcept(false) { - if (enabled()) m_options.log_fn(m_log_level == Log::Raise, m_buffer.str()); + if (enabled()) m_options.log_fn({std::move(m_buffer).str(), m_log_level}); } template @@ -208,6 +217,12 @@ class EventLoop //! Construct event loop object with specified logging options. EventLoop(const char* exe_name, LogOptions log_opts, void* context = nullptr); + //! Backwards-compatible constructor for previous (deprecated) logging callback signature + EventLoop(const char* exe_name, std::function old_callback, void* context = nullptr) + : EventLoop(exe_name, + LogFn{[old_callback = std::move(old_callback)](LogMessage log_data) {old_callback(log_data.level == Log::Raise, std::move(log_data.message));}}, + context){} + ~EventLoop(); //! Run event loop. Does not return until shutdown. This should only be diff --git a/test/mp/test/test.cpp b/test/mp/test/test.cpp index c9f9b51d..79b440f8 100644 --- a/test/mp/test/test.cpp +++ b/test/mp/test/test.cpp @@ -67,9 +67,9 @@ class TestSetup TestSetup(bool client_owns_connection = true) : thread{[&] { - EventLoop loop("mptest", [](bool raise, const std::string& log) { - std::cout << "LOG" << raise << ": " << log << "\n"; - if (raise) throw std::runtime_error(log); + EventLoop loop("mptest", [](mp::LogMessage log_data) { + std::cout << "LOG" << (int)log_data.level << ": " << log_data.message << "\n"; + if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message); }); auto pipe = loop.m_io_context.provider->newTwoWayPipe();