Skip to content

Commit 698fedb

Browse files
committed
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.
1 parent 70f632b commit 698fedb

2 files changed

Lines changed: 51 additions & 8 deletions

File tree

include/mp/proxy-types.h

Lines changed: 17 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -776,14 +776,16 @@ extern std::atomic<int> server_reqs;
776776
template <typename Server, typename CallContext, typename Fn>
777777
kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
778778
{
779+
auto server_cap = server.thisCap();
779780
auto params = call_context.getParams();
780781
using Params = decltype(params);
781782
using Results = typename decltype(call_context.getResults())::Builds;
782783

784+
EventLoop& loop = *server.m_context.loop;
783785
int req = ++server_reqs;
784-
MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server recv request #" << req << " "
785-
<< TypeName<typename Params::Reads>();
786-
MP_LOG(*server.m_context.loop, Log::Trace) << "request data: "
786+
MP_LOG(loop, Log::Debug) << "IPC server recv request #" << req << " "
787+
<< TypeName<typename Params::Reads>();
788+
MP_LOG(loop, Log::Trace) << "request data: "
787789
<< LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars);
788790

789791
try {
@@ -799,16 +801,23 @@ kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
799801
// and waiting for it to complete.
800802
return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); },
801803
[&]() { return kj::Promise<CallContext>(kj::mv(call_context)); })
802-
.then([&server, req](CallContext call_context) {
803-
MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName<Results>();
804-
MP_LOG(*server.m_context.loop, Log::Trace) << "response data: "
804+
.then([&server, &loop, server_cap, req](CallContext call_context) {
805+
MP_LOG(loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName<Results>();
806+
MP_LOG(loop, Log::Trace) << "response data: "
805807
<< LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars);
808+
}).catch_([&loop, server_cap, req](::kj::Exception&& e) -> kj::Promise<void> {
809+
// Call failed for some reason. Cap'n Proto will try to send
810+
// this error to the client as well, but it is good to log the
811+
// failure early here and include the request number.
812+
MP_LOG(loop, Log::Error) << "IPC server error request #" << req << " " << TypeName<Results>()
813+
<< " " << kj::str("kj::Exception: ", e.getDescription()).cStr();
814+
return kj::mv(e);
806815
});
807816
} catch (const std::exception& e) {
808-
MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception: " << e.what();
817+
MP_LOG(loop, Log::Error) << "IPC server unhandled exception: " << e.what();
809818
throw;
810819
} catch (...) {
811-
MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception";
820+
MP_LOG(loop, Log::Error) << "IPC server unhandled exception";
812821
throw;
813822
}
814823
}

include/mp/type-context.h

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -216,6 +216,40 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn&
216216
<< "IPC server error request #" << req << ", missing thread to execute request";
217217
throw std::runtime_error("invalid thread handle");
218218
}
219+
}, [&loop, req](::kj::Exception&& e) -> kj::Promise<typename ServerContext::CallContext> {
220+
// If you see the error "(remote):0: failed: remote exception:
221+
// Called null capability" here, it probably means your Init class
222+
// is missing a declaration like:
223+
//
224+
// construct @0 (threadMap: Proxy.ThreadMap) -> (threadMap :Proxy.ThreadMap);
225+
//
226+
// which passes a ThreadMap reference from the client to the server,
227+
// allowing the server to create threads to run IPC calls on the
228+
// client, and also returns a ThreadMap reference from the server to
229+
// the client, allowing the client to create threads on the server.
230+
// (Typically the latter ThreadMap is used more often because there
231+
// are more client-to-server calls.)
232+
//
233+
// If the other side of the connection did not previously get a
234+
// ThreadMap reference from this side of the connection, when the
235+
// other side calls `m_thread_map.makeThreadRequest()` in
236+
// `BuildField` above, `m_thread_map` will be null, but that call
237+
// will not fail immediately due to Cap'n Proto's request pipelining
238+
// and delayed execution. Instead that call will return an invalid
239+
// Thread reference, and when that reference is passed to this side
240+
// of the connection as `thread_client` above, the
241+
// `getLocalServer(thread_client)` call there will be the first
242+
// thing to overtly fail, leading to an error here.
243+
//
244+
// Potentially there are also other things that could cause errors
245+
// here, but this is the most likely cause.
246+
//
247+
// The log statement here is not strictly necessary since the same
248+
// exception will also be logged in serverInvoke, but this logging
249+
// may provide extra context that could be helpful for debugging.
250+
MP_LOG(loop, Log::Info)
251+
<< "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?";
252+
return kj::mv(e);
219253
});
220254
// Use connection m_canceler object to cancel the result promise if the
221255
// connection is destroyed. (By default Cap'n Proto does not cancel requests

0 commit comments

Comments
 (0)