Merge #218: Better error and log messages

4eae445 debug: Add TypeName() function and log statements for Proxy objects being created and destroyed (Ryan Ofsky)
f326c5b logging: Add better logging on IPC server-side failures (Ryan Ofsky)

Pull request description:

  This PR contains some logging and error message improvements I made locally in recent months that seem useful to upstream. Details are in commit messages

ACKs for top commit:
  sedited:
    ACK 4eae445

Tree-SHA512: 8eaa83df2d9181de56fea315b4cdbf04d5f714862d8c74394b16cd9e8f74cd1bba4846794ae1e29abc0d9df0e7503276a7196cf1d10d49a79bc897264b17906f

Author: ryanofsky

include/mp/proxy-io.h

@@ -511,6 +511,7 @@ ProxyClientBase<Interface, Impl>::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<Interface, Impl>::ProxyClientBase(typename Interface::Client cli
 template <typename Interface, typename Impl>
 ProxyClientBase<Interface, Impl>::~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 <typename Interface, typename Impl>
 ProxyServerBase<Interface, Impl>::ProxyServerBase(std::shared_ptr<Impl> 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<Interface, Impl>::ProxyServerBase(std::shared_ptr<Impl> impl, Co
 template <typename Interface, typename Impl>
 ProxyServerBase<Interface, Impl>::~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<Interface, Impl>::~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

include/mp/proxy-types.h

@@ -645,16 +645,16 @@ template <typename Client>
 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 <typename Server>
 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<void> 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<typename Params::Reads>();
-    MP_LOG(*server.m_context.loop, Log::Trace) << "request data: "
+    MP_LOG(loop, Log::Debug) << "IPC server recv request  #" << req << " "
+        << TypeName<typename Params::Reads>();
+    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<void> 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<CallContext>(kj::mv(call_context)); })
-            .then([&server, req](CallContext call_context) {
-                MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName<Results>();
-                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<Results>();
+                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<void> {
+                // 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<Results>()
+                    << " " << 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;
     }
 }

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<typename ServerContext::CallContext> {
+            // 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<Thread>::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

include/mp/util.h

@@ -7,19 +7,25 @@
 
 #include <capnp/schema.h>
 #include <cassert>
-#include <cstddef>
+#include <cstdlib>
 #include <cstring>
 #include <exception>
 #include <functional>
 #include <kj/string-tree.h>
 #include <mutex>
 #include <string>
 #include <tuple>
+#include <typeinfo>
 #include <type_traits>
 #include <utility>
 #include <variant>
 #include <vector>
 
+#if __has_include(<cxxabi.h>)
+#include <cxxabi.h>
+#include <memory>
+#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(<cxxabi.h>)   // GCC & Clang ─ use <cxxabi.h> to demangle
+inline std::string _demangle(const char* m)
+{
+    int status = 0;
+    std::unique_ptr<char, void(*)(void*)> 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<class T>
+std::string CxxTypeName(const T& /*unused*/)
+{
+#ifdef __cpp_rtti
+    return _demangle(typeid(std::decay_t<T>).name());
+#else
+    return "<type information unavailable without rtti>";
+#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)) {}

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 <kj/common.h>\n";
+    cpp_types << "#include <mp/util.h>\n";
     cpp_types << "#include <" << PROXY_TYPES << ">\n\n";
     cpp_types << "namespace mp {\n";