From 3a3e8923273dbea3a772e3a6d7d65adf28cb6d4f Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Wed, 11 Jun 2025 15:01:47 -0400 Subject: [PATCH 1/2] logging: Add better logging on IPC server-side failures Motivation: when trying to add a new unit test ran into a confusing error "(remote):0: failed: remote exception: Called null capability" caused by forgetting to make a FooInterface.initThreadMap call during initialization and these logging prints would have made it easier to see where the error was coming from and debug. --- include/mp/proxy-types.h | 7 +++++++ include/mp/type-context.h | 34 ++++++++++++++++++++++++++++++++++ 2 files changed, 41 insertions(+) diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index 5d38048..1bc3459 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -753,6 +753,13 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) 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); + }, [&server, req](::kj::Exception&& e) { + // Call failed for some reason. Cap'n Proto will try to send + // this error to the client as well, but it is good to log the + // failure early here and include the request number. + MP_LOG(*server.m_context.loop, Log::Error) << "IPC server error request #" << req << " " << TypeName() + << " " << kj::str("kj::Exception: ", e).cStr(); + return kj::mv(e); }); } catch (const std::exception& e) { MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception: " << e.what(); diff --git a/include/mp/type-context.h b/include/mp/type-context.h index 3733d6b..039d204 100644 --- a/include/mp/type-context.h +++ b/include/mp/type-context.h @@ -205,6 +205,40 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn& << "IPC server error request #" << req << ", missing thread to execute request"; throw std::runtime_error("invalid thread handle"); } + }, [&server, req](::kj::Exception&& e) -> kj::Promise { + // If you see the error "(remote):0: failed: remote exception: + // Called null capability" here, it probably means your Init class + // is missing a declaration like: + // + // construct @0 (threadMap: Proxy.ThreadMap) -> (threadMap :Proxy.ThreadMap); + // + // which passes a ThreadMap reference from the client to the server, + // allowing the server to create threads to run IPC calls on the + // client, and also returns a ThreadMap reference from the server to + // the client, allowing the client to create threads on the server. + // (Typically the latter ThreadMap is used more often because there + // are more client-to-server calls.) + // + // If the other side of the connection did not previously get a + // ThreadMap reference from this side of the connection, when the + // other side calls `m_thread_map.makeThreadRequest()` in + // `BuildField` above, `m_thread_map` will be null, but that call + // will not fail immediately due to Cap'n Proto's request pipelining + // and delayed execution. Instead that call will return an invalid + // Thread reference, and when that reference is passed to this side + // of the connection as `thread_client` above, the + // `getLocalServer(thread_client)` call there will be the first + // thing to overtly fail, leading to an error here. + // + // Potentially there are also other things that could cause errors + // here, but this is the most likely cause. + // + // The log statement here is not strictly necessary since the same + // exception will also be logged in serverInvoke, but this logging + // may provide extra context that could be helpful for debugging. + MP_LOG(*server.m_context.loop, Log::Info) + << "IPC server error request #" << req << " CapabilityServerSet::getLocalServer call failed, did you forget to provide a ThreadMap to the client prior to this IPC call?"; + return kj::mv(e); }); // Use connection m_canceler object to cancel the result promise if the // connection is destroyed. (By default Cap'n Proto does not cancel requests From e62b8f681cc386f6403353044443e1768b062437 Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Mon, 30 Jun 2025 10:47:34 -0400 Subject: [PATCH 2/2] debug: Add TypeName() function and log statements for Proxy objects being created and destroyed --- include/mp/proxy-io.h | 7 +++++++ include/mp/proxy-types.h | 13 +++++++------ include/mp/util.h | 31 ++++++++++++++++++++++++++++++- src/mp/gen.cpp | 3 +++ 4 files changed, 47 insertions(+), 7 deletions(-) diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index c298257..04a7985 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -495,6 +495,8 @@ ProxyClientBase::ProxyClientBase(typename Interface::Client cli : m_client(std::move(client)), m_context(connection) { + MP_LOG(*m_context.loop, Log::Info) << "Creating " << CxxTypeName(*this) << " " << this; + // Handler for the connection getting destroyed before this client object. auto disconnect_cb = m_context.connection->addSyncCleanup([this]() { // Release client capability by move-assigning to temporary. @@ -551,13 +553,16 @@ ProxyClientBase::ProxyClientBase(typename Interface::Client cli template ProxyClientBase::~ProxyClientBase() noexcept { + MP_LOG(*m_context.loop, Log::Info) << "Cleaning up " << CxxTypeName(*this) << " " << this; CleanupRun(m_context.cleanup_fns); + MP_LOG(*m_context.loop, Log::Info) << "Destroying " << CxxTypeName(*this) << " " << this; } template ProxyServerBase::ProxyServerBase(std::shared_ptr impl, Connection& connection) : m_impl(std::move(impl)), m_context(&connection) { + MP_LOG(*m_context.loop, Log::Info) << "Creating " << CxxTypeName(*this) << " " << this; assert(m_impl); } @@ -576,6 +581,7 @@ ProxyServerBase::ProxyServerBase(std::shared_ptr impl, Co template ProxyServerBase::~ProxyServerBase() { + MP_LOG(*m_context.loop, Log::Info) << "Cleaning up " << CxxTypeName(*this) << " " << this; if (m_impl) { // If impl is non-null at this point, it means no client is waiting for // the m_impl server object to be destroyed synchronously. This can @@ -602,6 +608,7 @@ ProxyServerBase::~ProxyServerBase() }); } assert(m_context.cleanup_fns.empty()); + MP_LOG(*m_context.loop, Log::Info) << "Destroying " << CxxTypeName(*this) << " " << this; } //! If the capnp interface defined a special "destroy" method, as described the diff --git a/include/mp/proxy-types.h b/include/mp/proxy-types.h index 1bc3459..d3cb35d 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -595,16 +595,16 @@ template void clientDestroy(Client& client) { if (client.m_context.connection) { - MP_LOG(*client.m_context.loop, Log::Info) << "IPC client destroy " << typeid(client).name(); + MP_LOG(*client.m_context.loop, Log::Info) << "IPC client destroy " << CxxTypeName(client); } else { - KJ_LOG(INFO, "IPC interrupted client destroy", typeid(client).name()); + KJ_LOG(INFO, "IPC interrupted client destroy", CxxTypeName(client)); } } template void serverDestroy(Server& server) { - MP_LOG(*server.m_context.loop, Log::Info) << "IPC server destroy " << typeid(server).name(); + MP_LOG(*server.m_context.loop, Log::Info) << "IPC server destroy " << CxxTypeName(server); } //! Entry point called by generated client code that looks like: @@ -740,6 +740,7 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) using ServerContext = ServerInvokeContext; using ArgList = typename ProxyClientMethodTraits::Params; ServerContext server_context{server, call_context, req}; + auto self = server.thisCap(); // ReplaceVoid is used to support fn.invoke implementations that // execute asynchronously and return promises, as well as // implementations that execute synchronously and return void. The @@ -749,16 +750,16 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) // and waiting for it to complete. return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); }, [&]() { return kj::Promise(kj::mv(call_context)); }) - .then([&server, req](CallContext call_context) { + .then([&server, req, self](CallContext call_context) { 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); - }, [&server, req](::kj::Exception&& e) { + }).catch_([&server, req, self](::kj::Exception&& e) -> kj::Promise { // Call failed for some reason. Cap'n Proto will try to send // this error to the client as well, but it is good to log the // failure early here and include the request number. MP_LOG(*server.m_context.loop, Log::Error) << "IPC server error request #" << req << " " << TypeName() - << " " << kj::str("kj::Exception: ", e).cStr(); + << " " << kj::str("kj::Exception: ", e.getDescription()).cStr(); return kj::mv(e); }); } catch (const std::exception& e) { diff --git a/include/mp/util.h b/include/mp/util.h index 80791bd..51a46b7 100644 --- a/include/mp/util.h +++ b/include/mp/util.h @@ -7,7 +7,7 @@ #include #include -#include +#include #include #include #include @@ -15,11 +15,17 @@ #include #include #include +#include #include #include #include #include +#if __has_include() +#include +#include +#endif + namespace mp { //! Generic utility functions used by capnp code. @@ -274,6 +280,28 @@ inline char* CharCast(unsigned char* c) { return (char*)c; } inline const char* CharCast(const char* c) { return c; } inline const char* CharCast(const unsigned char* c) { return (const char*)c; } +#if __has_include() // GCC & Clang ─ use to demangle +inline std::string _demangle(const char* m) +{ + int status = 0; + std::unique_ptr p{ + abi::__cxa_demangle(m, nullptr, nullptr, &status), std::free}; + return (status == 0 && p) ? p.get() : m; // fall back on mangled if needed +} +#else // MSVC or other ─ no demangling available +inline std::string _demangle(const char* m) { return m; } +#endif + +template +std::string CxxTypeName(const T& /*unused*/) +{ +#ifdef __cpp_rtti + return _demangle(typeid(std::decay_t).name()); +#else + return ""; +#endif +} + //! Exception thrown from code executing an IPC call that is interrupted. struct InterruptException final : std::exception { explicit InterruptException(std::string message) : m_message(std::move(message)) {} @@ -337,6 +365,7 @@ void CancelMonitor::promiseDestroyed(CancelProbe& probe) if (m_on_cancel) m_on_cancel(); m_probe = nullptr; } + } // namespace mp #endif // MP_UTIL_H diff --git a/src/mp/gen.cpp b/src/mp/gen.cpp index 53d3fd3..db552b1 100644 --- a/src/mp/gen.cpp +++ b/src/mp/gen.cpp @@ -239,8 +239,11 @@ static void Generate(kj::StringPtr src_prefix, cpp_types << "// Generated by " PROXY_BIN " from " << src_file << "\n\n"; cpp_types << "// IWYU pragma: no_include \"mp/proxy.h\"\n"; cpp_types << "// IWYU pragma: no_include \"mp/proxy-io.h\"\n"; + cpp_types << "#include <" << include_path << ".h> // IWYU pragma: keep\n"; cpp_types << "#include <" << include_path << ".proxy.h>\n"; cpp_types << "#include <" << include_path << ".proxy-types.h> // IWYU pragma: keep\n"; + cpp_types << "#include \n"; + cpp_types << "#include \n"; cpp_types << "#include <" << PROXY_TYPES << ">\n\n"; cpp_types << "namespace mp {\n";