diff --git a/include/mp/proxy-io.h b/include/mp/proxy-io.h index d7b9f0e..ee25bfe 100644 --- a/include/mp/proxy-io.h +++ b/include/mp/proxy-io.h @@ -511,6 +511,7 @@ ProxyClientBase::ProxyClientBase(typename Interface::Client cli : m_client(std::move(client)), m_context(connection) { + MP_LOG(*m_context.loop, Log::Debug) << "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. @@ -567,13 +568,16 @@ ProxyClientBase::ProxyClientBase(typename Interface::Client cli template ProxyClientBase::~ProxyClientBase() noexcept { + MP_LOG(*m_context.loop, Log::Debug) << "Cleaning up " << CxxTypeName(*this) << " " << this; CleanupRun(m_context.cleanup_fns); + MP_LOG(*m_context.loop, Log::Debug) << "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::Debug) << "Creating " << CxxTypeName(*this) << " " << this; assert(m_impl); } @@ -592,6 +596,7 @@ ProxyServerBase::ProxyServerBase(std::shared_ptr impl, Co template ProxyServerBase::~ProxyServerBase() { + MP_LOG(*m_context.loop, Log::Debug) << "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 @@ -618,6 +623,7 @@ ProxyServerBase::~ProxyServerBase() }); } assert(m_context.cleanup_fns.empty()); + MP_LOG(*m_context.loop, Log::Debug) << "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 c13debf..70b0538 100644 --- a/include/mp/proxy-types.h +++ b/include/mp/proxy-types.h @@ -645,16 +645,16 @@ template void clientDestroy(Client& client) { if (client.m_context.connection) { - MP_LOG(*client.m_context.loop, Log::Debug) << "IPC client destroy " << typeid(client).name(); + MP_LOG(*client.m_context.loop, Log::Debug) << "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::Debug) << "IPC server destroy " << typeid(server).name(); + MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server destroy " << CxxTypeName(server); } //! Entry point called by generated client code that looks like: @@ -780,10 +780,11 @@ kj::Promise serverInvoke(Server& server, CallContext& call_context, Fn fn) using Params = decltype(params); using Results = typename decltype(call_context.getResults())::Builds; + EventLoop& loop = *server.m_context.loop; int req = ++server_reqs; - MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server recv request #" << req << " " - << TypeName(); - MP_LOG(*server.m_context.loop, Log::Trace) << "request data: " + MP_LOG(loop, Log::Debug) << "IPC server recv request #" << req << " " + << TypeName(); + MP_LOG(loop, Log::Trace) << "request data: " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars); try { @@ -799,16 +800,23 @@ 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) { - 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); + .then([&loop, req](CallContext call_context) { + MP_LOG(loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName(); + MP_LOG(loop, Log::Trace) << "response data: " + << LogEscape(call_context.getResults().toString(), loop.m_log_opts.max_chars); + }).catch_([&loop, req](::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(loop, Log::Error) << "IPC server error request #" << req << " " << TypeName() + << " " << kj::str("kj::Exception: ", e.getDescription()).cStr(); + return kj::mv(e); }); } catch (const std::exception& e) { - MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception: " << e.what(); + MP_LOG(loop, Log::Error) << "IPC server unhandled exception: " << e.what(); throw; } catch (...) { - MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception"; + MP_LOG(loop, Log::Error) << "IPC server unhandled exception"; throw; } } diff --git a/include/mp/type-context.h b/include/mp/type-context.h index 8efd4fa..03eab03 100644 --- a/include/mp/type-context.h +++ b/include/mp/type-context.h @@ -216,6 +216,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"); } + }, [&loop, 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(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 diff --git a/include/mp/util.h b/include/mp/util.h index a3db128..380a142 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, /*output_buffer=*/nullptr, /*length=*/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)) {} diff --git a/src/mp/gen.cpp b/src/mp/gen.cpp index 603f9cc..18e4ee0 100644 --- a/src/mp/gen.cpp +++ b/src/mp/gen.cpp @@ -240,8 +240,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";