gianzellweger commented 8 months ago

Which Cloudflare product(s) does this pertain to?

Workers Runtime, Wrangler core

What version(s) of the tool(s) are you using?

3.34.2 [Wrangler], 0.0.21 [workers-rs], 1.78.0-nightly [Rust]

What version of Node are you using?

21.7.1

What operating system and version are you using?

Linux (Fedora) (arm64)

Describe the Bug

Observed behavior

If a minimal delay (or some work) is introduced, the server throws an error. The log is the following:

✘ [ERROR] A hanging Promise was canceled. This happens when the worker runtime is waiting for a Promise from JavaScript to resolve, but has detected that the Promise cannot possibly ever resolve because all code and events related to the Promise's I/O context have already finished.

Expected behavior

I would expect the work to finish and to respond to the request.

Steps to reproduce

A minimal working subset of your worker code


use worker::{event, Env, Request, Response, Result};

[event(fetch)]

pub async fn main(_req: Request, _env: Env, _ctx: worker::Context) -> Result { std::thread::sleep(Duration::from_micros(200)); // Shorter delays/actual work also triggers this behavior return Response::from_html(""); }

- A minimal working subset of your `wrangler.toml`
```TOML
name = "function"
workers_dev = true
compatibility_date = "2022-01-20"
main = "build/worker/shim.mjs"

[vars]
WORKERS_RS_VERSION = "0.0.21"

[build]
command = "cargo install -q worker-build && worker-build --release" # required

Commands used to start your local dev server, including custom env and cli args
```
$ npx wrangler dev
```
I also tried using wrangler beta, but to avail.
Steps to be performed in the browser, curl commands, or a test we can run that reliably fails (at least a percent of the time) Nothing

Please provide a link to a minimal reproduction

No response

Please provide any relevant error logs

This is a log of starting the local server, opening the page, and then closing the server:

--- 2024-03-18T22:59:16.892Z debug
🪵  Writing logs to "/home/gian/.config/.wrangler/logs/wrangler-2024-03-18_22-59-16_813.log"
---

--- 2024-03-18T22:59:16.892Z debug
Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
    at Object.openSync (node:fs:580:18)
    at Object.readFileSync (node:fs:459:35)
    at tryLoadDotEnv (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:124353:72)
    at loadDotEnv (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:124362:12)
    at /home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:164011:20
    at /home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:131396:16
    at maybeAsyncResult (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:129617:44)
    at /home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:131395:14
    at /home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:129604:22
    at Array.reduce (<anonymous>) {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: '.env'
}
---

--- 2024-03-18T22:59:16.898Z log
 ⛅️ wrangler 3.34.2
[38;2;255;136;0m-------------------[39m
---

--- 2024-03-18T22:59:16.901Z log
Running custom build: cargo install -q worker-build && worker-build --release
---

--- 2024-03-18T22:59:17.262Z debug
Retrieving cached values for userId from node_modules/.cache/wrangler
---

--- 2024-03-18T22:59:17.262Z debug
Metrics dispatcher: Dispatching disabled - would have sent {"type":"event","name":"run dev","properties":{"local":true,"usesTypeScript":false}}.
---

--- 2024-03-18T22:59:17.263Z debug
Failed to load .env file "/home/gian/badlang/edge-function/.dev.vars": Error: ENOENT: no such file or directory, open '/home/gian/badlang/edge-function/.dev.vars'
    at Object.openSync (node:fs:580:18)
    at Object.readFileSync (node:fs:459:35)
    at tryLoadDotEnv (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:124353:72)
    at loadDotEnv (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:124362:12)
    at getVarsForDev (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:161686:18)
    at getBindings (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:169301:10)
    at getBindingsAndAssetPaths (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:169257:20)
    at getDevReactElement (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:168929:40)
    at startDev (/home/gian/.npm/_npx/32026684e21afda6/node_modules/wrangler/wrangler-dist/cli.js:168993:60)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: '/home/gian/badlang/edge-function/.dev.vars'
}
---

--- 2024-03-18T22:59:17.263Z log
Your worker has access to the following bindings:
- Vars:
  - WORKERS_RS_VERSION: "0.0.21"
---

--- 2024-03-18T22:59:17.326Z debug
Writing additional module to output /home/gian/badlang/edge-function/.wrangler/tmp/dev-74zf9U/cd2e406bcaef2dacc340db153b2c17b8a6c76684-index.wasm
---

--- 2024-03-18T22:59:17.328Z log
[2m⎔ Starting local server...[22m
---

--- 2024-03-18T22:59:17.424Z debug
[InspectorProxyWorker] handleProxyControllerIncomingMessage {"type":"reloadStart"}
---

--- 2024-03-18T22:59:17.504Z debug
[InspectorProxyWorker] handleProxyControllerIncomingMessage {"type":"reloadComplete","proxyData":{"userWorkerUrl":{"protocol":"http:","hostname":"127.0.0.1","port":"39449"},"userWorkerInspectorUrl":{"protocol":"ws:","hostname":"127.0.0.1","port":"37791","pathname":"/core:user:edge-function"},"userWorkerInnerUrlOverrides":{"protocol":"http"},"headers":{"MF-Proxy-Shared-Secret":"4464f6a7-e0de-4e1f-a254-48ff5cb6791a"},"liveReload":false,"proxyLogsToController":false,"internalDurableObjects":[]}}
---

--- 2024-03-18T22:59:17.505Z debug
[InspectorProxyWorker] reconnectRuntimeWebSocket
---

--- 2024-03-18T22:59:17.506Z debug
[InspectorProxyWorker] NEW RUNTIME WEBSOCKET http://127.0.0.1:37791/core:user:edge-function
---

--- 2024-03-18T22:59:17.507Z debug
[InspectorProxyWorker] SEND TO DEVTOOLS {"method":"Runtime.executionContextsCleared"}
---

--- 2024-03-18T22:59:17.508Z debug
[InspectorProxyWorker] RUNTIME WEBSOCKET OPENED
---

--- 2024-03-18T22:59:17.509Z debug
[InspectorProxyWorker] SEND TO RUNTIME {"method":"Runtime.enable","id":100000001}
---

--- 2024-03-18T22:59:17.510Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Runtime.executionContextCreated',
  params: {
    context: {
      id: 314525313,
      origin: '',
      name: 'Worker',
      uniqueId: '-6388031286083024090.3230764925894258461'
    }
  }
}
---

--- 2024-03-18T22:59:17.511Z debug
[InspectorProxyWorker] SEND TO RUNTIME {"method":"Debugger.enable","id":100000002}
---

--- 2024-03-18T22:59:17.511Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Debugger.scriptParsed',
  params: {
    scriptId: '3',
    url: 'file:///home/gian/badlang/edge-function/.wrangler/tmp/dev-74zf9U/shim.js',
    startLine: 0,
    startColumn: 0,
    endLine: 825,
    endColumn: 86,
    executionContextId: 314525313,
    hash: '995b8ac50fc4fd12e3b42a3d2b6c78cd5c89ba60dff0f8b26aad05aab19739db',
    isLiveEdit: false,
    sourceMapURL: 'shim.js.map',
    hasSourceURL: true,
    isModule: true,
    length: 24847,
    scriptLanguage: 'JavaScript',
    embedderName: 'shim.js'
  }
}
---

--- 2024-03-18T22:59:17.512Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Debugger.scriptParsed',
  params: {
    scriptId: '4',
    url: 'wasm://wasm/edge_function.wasm-001871c6',
    startLine: 0,
    startColumn: 0,
    endLine: 0,
    endColumn: 400497,
    executionContextId: 314525313,
    hash: 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855',
    isLiveEdit: false,
    sourceMapURL: '',
    hasSourceURL: false,
    isModule: false,
    length: 400497,
    codeOffset: 4678,
    scriptLanguage: 'WebAssembly',
    debugSymbols: { type: 'None' },
    embedderName: 'wasm://wasm/edge_function.wasm-001871c6'
  }
}
---

--- 2024-03-18T22:59:17.513Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  id: 100000002,
  result: { debuggerId: '-7095866075607620815.2873960517711552267' }
}
---

--- 2024-03-18T22:59:17.514Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE { id: 100000003, method: 'Network.enable', result: {} }
---

--- 2024-03-18T22:59:17.514Z debug
[InspectorProxyWorker] SEND TO RUNTIME {"method":"Network.enable","id":100000003}
---

--- 2024-03-18T22:59:17.515Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE { id: 100000001, result: {} }
---

--- 2024-03-18T22:59:19.766Z error
[31m✘ [41;31m[[41;97mERROR[41;31m][0m [1mA hanging Promise was canceled. This happens when the worker runtime is waiting for a Promise from JavaScript to resolve, but has detected that the Promise cannot possibly ever resolve because all code and events related to the Promise's I/O context have already finished.[0m

---

--- 2024-03-18T22:59:19.767Z error
[31m✘ [41;31m[[41;97mERROR[41;31m][0m [1mA hanging Promise was canceled. This happens when the worker runtime is waiting for a Promise from JavaScript to resolve, but has detected that the Promise cannot possibly ever resolve because all code and events related to the Promise's I/O context have already finished.[0m

---

--- 2024-03-18T22:59:19.768Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Runtime.consoleAPICalled',
  params: {
    type: 'warning',
    args: [ [Object] ],
    executionContextId: 314525313,
    timestamp: 1710802759730,
    stackTrace: { callFrames: [] }
  }
}
---

--- 2024-03-18T22:59:19.768Z error
[31m✘ [41;31m[[41;97mERROR[41;31m][0m [1mUncaught (in response) Error: The script will never generate a response.[0m

---

--- 2024-03-18T22:59:19.769Z error
[31m✘ [41;31m[[41;97mERROR[41;31m][0m [1mUncaught (in response) Error: The script will never generate a response.[0m

---

--- 2024-03-18T22:59:19.769Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Runtime.exceptionThrown',
  params: {
    timestamp: 1710802759730,
    exceptionDetails: {
      exceptionId: 1,
      text: 'Uncaught (in response)',
      lineNumber: 0,
      columnNumber: -2,
      url: 'undefined',
      exception: [Object],
      executionContextId: 314525313
    }
  }
}
---

--- 2024-03-18T22:59:19.770Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Runtime.consoleAPICalled',
  params: {
    type: 'warning',
    args: [ [Object] ],
    executionContextId: 314525313,
    timestamp: 1710802759750,
    stackTrace: { callFrames: [] }
  }
}
---

--- 2024-03-18T22:59:19.770Z debug
[InspectorProxyWorker] RUNTIME INCOMING MESSAGE {
  method: 'Runtime.exceptionThrown',
  params: {
    timestamp: 1710802759750,
    exceptionDetails: {
      exceptionId: 2,
      text: 'Uncaught (in response)',
      lineNumber: 0,
      columnNumber: -2,
      url: 'undefined',
      exception: [Object],
      executionContextId: 314525313
    }
  }
}
---

--- 2024-03-18T22:59:19.770Z debug
workerd/util/symbolizer.c++:96: warning: Not symbolizing stack traces because $LLVM_SYMBOLIZER is not set. To symbolize stack traces, set $LLVM_SYMBOLIZER to the location of the llvm-symbolizer binary. When running tests under bazel, use `--test_env=LLVM_SYMBOLIZER=<path>`.
workerd/server/server.c++:3088: error: Uncaught exception: kj/async-io-unix.c++:186: disconnected: remote.worker_do_not_log; Request failed due to internal error
stack: /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b8982b /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b5d55f /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b5dd97 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b519e3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37ee3c3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37ee7bf /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b6ee0c /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b6ee0c /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b6ee0c /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2863d50 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@286d210 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37e015b /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b519e3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37df6fc /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2863d50 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2ec2f68 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2ec337b /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b519e3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2d866a8 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@312dcf3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@286d210 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37e015b /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@37df6fc /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2863d50 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2ec2f68 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2ec337b /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b519e3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b51cb7 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@2d878ff /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b519e3 /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b52c1f /home/gian/.npm/_npx/32026684e21afda6/node_modules/@cloudflare/workerd-linux-arm64/bin/workerd@4b59077
---

--- 2024-03-18T22:59:21.593Z debug
Not Implemented Error: ConfigController#teardown
---

--- 2024-03-18T22:59:21.593Z debug
Not Implemented Error: BundlerController#teardown
---

--- 2024-03-18T22:59:21.594Z debug
Not Implemented Error: LocalRuntimeController#teardown
---

--- 2024-03-18T22:59:21.594Z debug
Not Implemented Error: RemoteRuntimeController#teardown
---

--- 2024-03-18T22:59:21.594Z debug
ProxyController teardown
---

--- 2024-03-18T22:59:21.603Z log
[2m⎔ Shutting down local server...[22m
---

gianzellweger commented 8 months ago

Update: Since updating to wrangler 3.36.0, there is now an error on the page, linking to this file and location:

/usr/local/lib/node_modules/wrangler/node_modules/miniflare/dist/src/workers/core/entry.worker.js:895:22

I believe this is the file on GitHub. https://github.com/cloudflare/workers-sdk/blob/c5135224f5e58391a26befbee3f389d69f50a71b/packages/miniflare/src/workers/core/entry.worker.ts#L272

The problem hasn't resolved yet.

penalosa commented 4 months ago

I'm going to transfer this to the workers-rs repo, as it looks like this is a bug specific to delays in Rust code compiled to WASM.

kflansburg commented 4 months ago

I'm not sure exactly how the runtime detects that futures arent making progress, but I suspect the blocking sleep here is the issue. Can you use an async sleep such as tokio::time::sleep?

zebp commented 4 months ago

We have a Delay type in the worker crate for this, it can be used like this:

use std::time::Duration;
use worker::Delay;

let duration = Duration::from_millis(1000);

// Waits a second
Delay::from(duration).await;

cloudflare / workers-rs

🐛 BUG: Any delay will cause the server to error #595