workerd icon indicating copy to clipboard operation
workerd copied to clipboard
verified publisher icon cloudflare

🐛 Infinite loop crash under WSL - failed: connect(): Cannot assign requested address; address = 127.0.0.1:60743

Open MicroDroid opened this issue 1 year ago • 3 comments

Hello,

I have a Remix application that uses wrangler to launch in dev mode, and it's been working for me for quite some time, until it no longer did.

Environment

  • Arch Linux under latest WSL2 on latest Windows 11
  • Latest wrangler
  • Node 21

Bug Reproduction

The steps to reproduce the bug are:

  1. wrangler pages dev --compatibility-date=2023-06-21 ./public

  2. Load a page a few times with browser cache disabled (I'll explain why later)

  3. Watch workerd enter an infinite loop of printing this error:

    ✘ [ERROR] workerd/io/io-context.c++:353: error: e = kj/async-io-unix.c++:1509: failed: connect(): Cannot assign requested address; address = 127.0.0.1:60743

  stack:
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b95eee1
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b9560f1
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b955ea1
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b955c22
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b956a50
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b958dd0
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@48ca9f9
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b932130
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b937f00
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@55baa78
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@736f3ca
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8ec770
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8be930
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8fecf0
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@5a43838
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@5d24800
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@52c6f30
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@5a45356
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@5a4543e
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8b76b7
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8b766c
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8b76e3
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8ac096
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8c9c50
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8ae50c
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@b8aded8
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47c0257
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47d8da8
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47d870c
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47d86e8
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47d86be
  /home/REDACTED/REDACTED/REDACTED/node_modules/.pnpm/@[email protected]/node_modules/@cloudflare/workerd-linux-64/bin/workerd@47d85f3

    Note: The file path at the top of trace is sometimes workerd/io/io-context.c++:353 and other times workerd/jsg/util.c++:291, not sure why.

It's important to note that:

  • The error may start on first page load, or 10th. It doesn't after an exact step, it just occurs after using wrangler for "a while"
  • It seems like disabling browser cache causes a lot more HTTP requests to go towards wrangler which makes the bug much more likely to trigger
  • Once the bug starts wrangler is just virtually dead and spamming the console as CPU speed with this error

Things I know about this bug

  1. If I run netstat -ntlp | grep <port> I do see that a node process already reserved <port>, which makes sense why wrangler can't acquire it, but then if I Ctrl-C wrangler itself that node process disappears, so basically wrangler itself was allocating it to begin with anyways.
  2. If I run this same project on a cloud machine, this bug does not happen.

Things I suspect may be relevant

  1. I recently updated my WSL2 to latest. Now, I tried downgrading a bunch of versions, that did not fix the bug. I tried downgrading further then my WSL2 installation broke up so I re-upgraded to latest

Debugging

I did the following:

  1. Built workerd from source with -c dbg to preserve debug info in the output binary
  2. Replaced workerd in my project's file tree with the one with debug info
  3. Reproduced the bug but with LLVM_SYMBOLIZER=$(which llvm-symbolizer) and got the following: 
    kj::(anonymous namespace)::LowLevelAsyncIoProviderImpl::wrapConnectingSocketFd(int, sockaddr
const*, unsigned int, unsigned int) at external/capnp-cpp/src/kj/async-io-unix.c++:1509:11

kj::(anonymous namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()::operator()() const at
external/capnp-cpp/src/kj/async-io-unix.c++:1648:25

decltype(reducePromiseType((kj::_::ReturnType_<kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'(), void>::Type*)(nullptr), false))
kj::evalNow<kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()>(kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()&&)::'lambda'()::operator()() const at
external/capnp-cpp/src/kj/async-inl.h:1448:3

kj::Maybe<kj::Exception>
kj::runCatchingExceptions<decltype(reducePromiseType((kj::_::ReturnType_<kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'(), void>::Type*)(nullptr), false))
kj::evalNow<kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()>(kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()&&)::'lambda'()>(kj::(anonymous
namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'()&&) at
bazel-out/k8-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj/kj/exception.h:366:5

kj::(anonymous namespace)::NetworkAddressImpl::connectImpl(kj::LowLevelAsyncIoProvider&,
kj::LowLevelAsyncIoProvider::NetworkFilter&, kj::ArrayPtr<kj::(anonymous
namespace)::SocketAddress>, bool)::'lambda'(kj::Own<kj::AsyncIoStream,
std::nullptr_t>&&)::operator()(kj::Own<kj::AsyncIoStream, std::nullptr_t>&&) const at
external/capnp-cpp/src/kj/async-io-unix.c++:1652:0

kj::(anonymous
namespace)::NetworkAddressImpl::connect()::'lambda'(kj::AuthenticatedStream&&)::operator()(kj::AuthenticatedStream&&)
const at external/capnp-cpp/src/kj/async-io-unix.c++:1557:0

workerd::server::PromisedNetworkAddress::connect() (.resume) at
src/workerd/server/server.c++:440:17

kj::(anonymous
namespace)::PromisedAsyncIoStream::PromisedAsyncIoStream(kj::Promise<kj::Own<kj::AsyncIoStream,
std::nullptr_t>>)::'lambda'(kj::Own<kj::AsyncIoStream,
std::nullptr_t>)::operator()(kj::Own<kj::AsyncIoStream, std::nullptr_t>) const at
external/capnp-cpp/src/kj/async-io.c++:2376:0

kj::(anonymous namespace)::PromisedAsyncIoStream::write(void const*, unsigned
long)::'lambda'()::operator()() const at external/capnp-cpp/src/kj/async-io.c++:2422:0

kj::_::Coroutine<void>::ForkedPromiseAwaiter<void>::await_resume() at
bazel-out/k8-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj-async/kj/async-inl.h:2399:44

kj::(anonymous namespace)::HttpFixedLengthEntityWriter::write(void const*, unsigned long)
(.resume) at external/capnp-cpp/src/kj/compat/http.c++:2476:5

kj::(anonymous namespace)::AsyncPipe::BlockedPumpTo::write(void const*, unsigned
long)::'lambda'()::operator()() const at external/capnp-cpp/src/kj/async-io.c++:1250:0

kj::Canceler::AdapterImpl<void>::AdapterImpl(kj::PromiseFulfiller<void>&, kj::Canceler&,
kj::Promise<void>)::$_0::operator()() const at external/capnp-cpp/src/kj/async.c++:272:0

kj::(anonymous namespace)::AsyncPipe::BlockedWrite::pumpTo(kj::AsyncOutputStream&, unsigned
long)::'lambda1'()::operator()() const at external/capnp-cpp/src/kj/async-io.c++:639:0

workerd::api::(anonymous
namespace)::BodyBufferInputStream::pumpTo(workerd::api::WritableStreamSink&, bool) (.resume) at
src/workerd/api/http.c++:598:7

workerd::api::ReadableStreamInternalController::pumpTo(workerd::jsg::Lock&,
kj::Own<workerd::api::WritableStreamSink, std::nullptr_t>,
bool)::$_0::operator()(workerd::api::DeferredProxy<void>) at
src/workerd/api/streams/internal.c++:2079:0

kj::Promise<void>
workerd::IoContext::waitForDeferredProxy<void>(kj::Promise<workerd::api::DeferredProxy<void>>&&)::'lambda'(workerd::api::DeferredProxy<void>)::operator()(workerd::api::DeferredProxy<void>)
const at bazel-out/k8-dbg/bin/src/workerd/io/_virtual_includes/io/workerd/io/io-context.h:519:0

kj::Promise<void> workerd::api::(anonymous namespace)::fetchImplNoOutputLock(workerd::jsg::Lock&,
workerd::jsg::Ref<workerd::api::Fetcher>, workerd::jsg::Ref<workerd::api::Request>,
kj::Vector<kj::Url>)::$_1::operator()<workerd::jsg::Ref<workerd::api::ReadableStream>>(kj::Promise<void>,
workerd::jsg::Ref<workerd::api::ReadableStream>) const (.resume) at
src/workerd/api/http.c++:1818:11

kj::Promise<void> workerd::api::(anonymous namespace)::fetchImplNoOutputLock(workerd::jsg::Lock&,
workerd::jsg::Ref<workerd::api::Fetcher>, workerd::jsg::Ref<workerd::api::Request>,
kj::Vector<kj::Url>)::$_1::operator()<workerd::jsg::Ref<workerd::api::ReadableStream>>(kj::Promise<void>,
workerd::jsg::Ref<workerd::api::ReadableStream>) const (.resume) at
src/workerd/api/http.c++:1822:13

std::__1::coroutine_handle<void>::resume[abi:ue170006]() const at
/usr/bin/../include/c++/v1/__coroutine/coroutine_handle.h:78:9

kj::_::CoroutineBase::fire() at external/capnp-cpp/src/kj/async.c++:3043:13

non-virtual thunk to kj::_::CoroutineBase::fire() at external/capnp-cpp/src/kj/async.c++:0:0

kj::EventLoop::turn() at external/capnp-cpp/src/kj/async.c++:1828:31

kj::_::waitImpl(kj::Own<kj::_::PromiseNode, kj::_::PromiseDisposer>&&, kj::_::ExceptionOrValue&,
kj::WaitScope&, kj::SourceLocation)::$_2::operator()() const at
external/capnp-cpp/src/kj/async.c++:1988:21

void kj::WaitScope::runOnStackPool<kj::_::waitImpl(kj::Own<kj::_::PromiseNode,
kj::_::PromiseDisposer>&&, kj::_::ExceptionOrValue&, kj::WaitScope&,
kj::SourceLocation)::$_2>(kj::_::waitImpl(kj::Own<kj::_::PromiseNode, kj::_::PromiseDisposer>&&,
kj::_::ExceptionOrValue&, kj::WaitScope&, kj::SourceLocation)::$_2&&) at
external/capnp-cpp/src/kj/async.h:1320:7

kj::_::waitImpl(kj::Own<kj::_::PromiseNode, kj::_::PromiseDisposer>&&, kj::_::ExceptionOrValue&,
kj::WaitScope&, kj::SourceLocation) at external/capnp-cpp/src/kj/async.c++:1985:17

kj::Promise<void>::wait(kj::WaitScope&, kj::SourceLocation) at
bazel-out/k8-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj-async/kj/async-inl.h:1366:3

void
workerd::server::CliMain::serveImpl<workerd::server::CliMain::serve()::'lambda'(workerd::jsg::V8System&,
workerd::server::config::Config::Reader)>(workerd::server::CliMain::serve()::'lambda'(workerd::jsg::V8System&,
workerd::server::config::Config::Reader)&&) at src/workerd/server/workerd.c++:1209:15

workerd::server::CliMain::serve() at src/workerd/server/workerd.c++:1221:5

auto workerd::server::CliMain::addServeOptions(kj::MainBuilder&)::'lambda5'(auto&,
auto&&...)::operator()<workerd::server::CliMain>(auto&, auto&&...) at
src/workerd/server/workerd.c++:745:27

auto kj::_::BoundMethod<workerd::server::CliMain&,
workerd::server::CliMain::addServeOptions(kj::MainBuilder&)::'lambda5'(auto&, auto&&...),
workerd::server::CliMain::addServeOptions(kj::MainBuilder&)::'lambda6'(auto&,
auto&&...)>::operator()<>() at
bazel-out/k8-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj/kj/function.h:263:12

kj::MainBuilder::Validity auto
workerd::server::cliMethod<kj::_::BoundMethod<workerd::server::CliMain&,
workerd::server::CliMain::addServeOptions(kj::MainBuilder&)::'lambda5'(auto&, auto&&...),
workerd::server::CliMain::addServeOptions(kj::MainBuilder&)::'lambda6'(auto&,
auto&&...)>>(auto&&)::'lambda'(auto&&...)::operator()<>(auto&&...) at
src/workerd/server/workerd.c++:98:7

MicroDroid avatar Apr 14 '24 15:04 MicroDroid

I wanted to make an extremely stripped down version of the public directory so I can upload it here as a repro, but in the stripped down version it works for a few page loads and then throws literally a random error, such as one of:

✘ [ERROR] workerd/server/server.c++:3327: error: Uncaught exception: kj/async-io-unix.c++:778: disconnected: remote.worker_do_not_log; Request failed due to internal error

or

✘ [ERROR] Error in ProxyController: Error inside ProxyWorker

or

✘ [ERROR] *** Fatal uncaught kj::Exception: workerd/jsg/jsg.c++:130: failed: attempt to take recursive isolate lock

I don't even know what now

MicroDroid avatar Apr 14 '24 23:04 MicroDroid

Also why is wrangler try to allocate a port around 60000 anyways, like I don't get it why does it need to allocate anything other than 8788?

MicroDroid avatar Apr 14 '24 23:04 MicroDroid

I am seeing this as well. Its extremely annoying, and happens way too frequently. I have to spam CTRL-C for like 15 seconds to get it to finally stop, and then often times when I start it again it just immediately does it again. Restarting the computer usually fixes it at least for a little bit.

KyGuy2002 avatar Sep 01 '24 19:09 KyGuy2002