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

gianzellweger · 2024-03-18T23:00:59Z

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<Response> {
    std::thread::sleep(Duration::from_micros(200)); // Shorter delays/actual work also triggers this behavior
    return Response::from_html("<html></html>");
}

A minimal working subset of your wrangler.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
---

The text was updated successfully, but these errors were encountered:

gianzellweger · 2024-03-20T22:51:21Z

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 · 2024-07-08T13:43:54Z

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 · 2024-07-08T14:02:11Z

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 · 2024-07-09T22:58:13Z

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;

gianzellweger added the bug Something isn't working label Mar 18, 2024

penalosa transferred this issue from cloudflare/workers-sdk Jul 8, 2024

penalosa removed this from workers-sdk Jul 8, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

gianzellweger commented Mar 18, 2024

gianzellweger commented Mar 20, 2024

penalosa commented Jul 8, 2024

kflansburg commented Jul 8, 2024

zebp commented Jul 9, 2024

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

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

Comments

gianzellweger commented Mar 18, 2024

Which Cloudflare product(s) does this pertain to?

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

What version of Node are you using?

What operating system and version are you using?

Describe the Bug

Observed behavior

Expected behavior

Steps to reproduce

Please provide a link to a minimal reproduction

Please provide any relevant error logs

gianzellweger commented Mar 20, 2024

penalosa commented Jul 8, 2024

kflansburg commented Jul 8, 2024

zebp commented Jul 9, 2024