Warnings "EventLoop destroyed with events still in the queue. Memory leak?"

[Jens Alfke]

I’m in the midst of improving the error handling in my code, but there’s a warning logged by KJ that I can’t figure out. I’d appreciate any advice or insight.

It happens when my client code fails to connect because server-side auth fails, so it gets an abrupt "Connection reset by peer” error that’s thrown from the first Promise::wait() call. That exception causes my client object to get destructed, and during its destructor the warning gets logged (with a bunch of backtrace.)

The message as logged from my onRecoverableException handler looks like:

expected head == nullptr [10bf07390 == nullptr]; EventLoop destroyed with events still in the queue.  Memory leak?; head->traceEvent() = 10152fc4c 101548a28

    kj::_::ImmediatePromiseNode<kj::Own<capnp::ClientHook> >::get(kj::_::ExceptionOrValue&) (in myapp) + 0: returning here

The call stack is pretty long, so I’ve tried to clean it up a bit. “myapp” is app code. “snej::shs” is my implementation of the SecretHandshake secure-socket protocol, including CapnP glue code adapted from ez-rpc.c++.

myapp::KJExceptionCallback::onRecoverableException() at Logging.cc:80:28

kj::_::Debug::Fault::~Fault() + 172

kj::EventLoop::~EventLoop() + 432

kj::_::HeapDisposer<kj::() const + 56

kj::Disposer::Dispose_<kj::LowLevelAsyncIoProvider, true>::dispose() at memory.h:522:14

void kj::Disposer::dispose<kj::LowLevelAsyncIoProvider>() const at memory.h:534:3

kj::Own<kj::LowLevelAsyncIoProvider>::dispose() at memory.h:278:17

kj::Own<kj::LowLevelAsyncIoProvider>::~Own() at memory.h:204:28

kj::Own<kj::LowLevelAsyncIoProvider>::~Own() at memory.h:204:26

kj::AsyncIoContext::~AsyncIoContext() at async-io.h:876:8

kj::AsyncIoContext::~AsyncIoContext() at async-io.h:876:8

snej::shs::SecretRPCContext::~SecretRPCContext() at SecretRPC.cc:56:9

snej::shs::SecretRPCContext::~SecretRPCContext() at SecretRPC.cc:50:45

snej::shs::SecretRPCContext::~SecretRPCContext() at SecretRPC.cc:50:45

kj::Disposer::Dispose_<snej::shs::SecretRPCContext, true>::dispose() at memory.h:522:14

void kj::Disposer::dispose<snej::shs::SecretRPCContext>() const at memory.h:534:3

kj::Own<snej::shs::SecretRPCContext>::dispose() at memory.h:278:17

kj::Own<snej::shs::SecretRPCContext>::~Own() at memory.h:204:28

kj::Own<snej::shs::SecretRPCContext>::~Own() at memory.h:204:26

snej::shs::SecretRPCClient::Impl::~Impl() at SecretRPC.cc:283:29

snej::shs::SecretRPCClient::Impl::~Impl() at SecretRPC.cc:283:29

kj::_::HeapDisposer<snej::shs::SecretRPCClient::Impl>::disposeImpl() const at memory.h:433:60

kj::Disposer::Dispose_<snej::shs::SecretRPCClient::Impl, false>::dispose() at memory.h:528:14

void kj::Disposer::dispose<snej::shs::SecretRPCClient::Impl>() const at memory.h:534:3

kj::Own<snej::shs::SecretRPCClient::Impl>::dispose() at memory.h:278:17

kj::Own<snej::shs::SecretRPCClient::Impl>::~Own() at memory.h:204:28

kj::Own<snej::shs::SecretRPCClient::Impl>::~Own() at memory.h:204:26

snej::shs::SecretRPCClient::~SecretRPCClient() at SecretRPC.cc:383:59

snej::shs::SecretRPCClient::~SecretRPCClient() at SecretRPC.cc:383:57

kj::_::HeapDisposer<snej::shs::SecretRPCClient>::disposeImpl() const at memory.h:433:60

kj::Disposer::Dispose_<snej::shs::SecretRPCClient, false>::dispose() at memory.h:528:14

void kj::Disposer::dispose<snej::shs::SecretRPCClient>() const at memory.h:534:3

kj::Own<snej::shs::SecretRPCClient>::dispose() at memory.h:278:17

kj::Own<snej::shs::SecretRPCClient>::~Own() at memory.h:204:28

kj::Own<snej::shs::SecretRPCClient>::~Own() at memory.h:204:26

myapp::net::Client::ConnectionImpl::~ConnectionImpl() at Client.cc:281:19

myapp::net::Client::ConnectionImpl::~ConnectionImpl() at Client.cc:281:19

myapp::net::Client::ConnectionImpl::~ConnectionImpl() at Client.cc:281:19

std::__1::default_delete<myapp::net::Client::Impl>::operator() const at unique_ptr.h:57:5

std::__1::unique_ptr<myapp::net::Client::Impl, std::__1::default_delete<myapp::net::Client::Impl> >::reset() at unique_ptr.h:318:7

std::__1::unique_ptr<myapp::net::Client::Impl, std::__1::default_delete<myapp::net::Client::Impl> >::~unique_ptr() at unique_ptr.h:272:19

std::__1::unique_ptr<myapp::net::Client::Impl, std::__1::default_delete<myapp::net::Client::Impl> >::~unique_ptr() at unique_ptr.h:272:17

myapp::net::Client::~Client() at Client.cc:314:21

myapp::net::Client::~Client() at Client.cc:314:21

myapp::SyncTask::_run() at SyncTask.cc:166:5

myapp::SyncTask::run() const at SyncTask.cc:82:9

kj::_::RunnableImpl<myapp::SyncTask::run() at exception.h:319:5

kj::_::runCatchingExceptions() + 36

kj::Maybe<kj::Exception> kj::runCatchingExceptions<myapp::SyncTask::run() at exception.h:332:10

myapp::SyncTask::run() at SyncTask.cc:82:9

SyncCommand::runSubcommand() at ClientMain.cc:842:24

InteractiveTool::runSubcommand() at InteractiveTool.cc:72:29

myappClient::run() at ClientMain.cc:178:13

Tool::main() at Tool.hh:63:20

main() at ClientMain.cc:188:28

[Kenton Varda]

Hi Jens,

Sorry for the slow reply.

This error indicates that the KJ EventLoop (which is part of the objects returned by kj::setupAsyncIo()) was destroyed while some kj::Promise objects still existed.

Ideally, you should set things up so that when the stack unwinds, all Promise objects are destroyed before the EventLoop is destroyed. Alternatively, make sure to catch all exceptions at the top level such that the EventLoop is never destroyed.

-Kenton

--
You received this message because you are subscribed to the Google Groups "Cap'n Proto" group.
To unsubscribe from this group and stop receiving emails from it, send an email to capnproto+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/capnproto/59C02C00-95D1-4357-8F26-9E3F8A1C35DC%40mooseyard.com.

[Jens Alfke]

On Jun 7, 2022, at 9:53 AM, 'Kenton Varda' via Cap'n Proto <capn...@googlegroups.com> wrote:

Ideally, you should set things up so that when the stack unwinds, all Promise objects are destroyed before the EventLoop is destroyed. 

Thanks! I actually figured this out shortly after posting, but forgot to send a follow-up. I had to inspect some classes' member declarations carefully to find the two that were in the wrong order; swapping them fixed it.

But maybe you can help me with a less-annoying warning that I’m still getting. When either the client or the server connection closes, I always get an Info-level log:

returning failure over rpc; exception = capnp/rpc.c++:3107: failed: RpcSystem was destroyed.

It appears harmless, and no exception is actually thrown, but I’d rather not be logging this. Any idea what I might still be doing wrong?

—Jens

[Kenton Varda]

Hi Jens,

Info-level logs are generally meant to be enabled only for debugging, so the idea here is you normally shouldn't see this log. All exceptions that are transmitted over RPC are info-logged but normally you would only want to log them in production if some actual operation you care about fails with this exception.

-Kenton

[Jens Alfke]

On Jun 7, 2022, at 3:07 PM, Kenton Varda <ken...@cloudflare.com> wrote:

Info-level logs are generally meant to be enabled only for debugging, so the idea here is you normally shouldn't see this log.

But I am debugging :) I’m debugging my code, using KJ logging. So I do see this somewhat scary-looking message mixed in with my own logs.

All exceptions that are transmitted over RPC are info-logged 

So it's normal for this exception to be created & transmitted when a client connection closes? If so I’ll just ignore it from now on.

—Jens

[Kenton Varda]

Yes, it's normal. I agree it's kind of spammy but I haven't figured out what to do about it.