workers-sdk icon indicating copy to clipboard operation
workers-sdk copied to clipboard
verified publisher icon cloudflare

🐛 BUG: `POST` with body to a Worker in local dev throws an error

Open threepointone opened this issue 1 year ago • 5 comments

Which Cloudflare product(s) does this pertain to?

Wrangler

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

[email protected]

What version of Node are you using?

v20.14.0

What operating system and version are you using?

Mac OS

Describe the Bug

Observed behavior

Making a POST request to a durable object (or a Worker) without a content-type header throws a weird error in local dev.

Expected behavior

It shouldn't throw the error.

Steps to reproduce

Full repro and instructions at https://github.com/threepointone/durable-post-error

Please provide a link to a minimal reproduction

https://github.com/threepointone/durable-post-error

Please provide any relevant error logs

--- 2024-08-16T18:14:52.620Z debug
🪵  Writing logs to "[redacted]/.wrangler/logs/wrangler-2024-08-16_18-14-52_550.log"
---

--- 2024-08-16T18:14:52.620Z debug
Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
at Object.openSync (node:fs:573:18)
at Object.readFileSync (node:fs:452:35)
at tryLoadDotEnv ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:158723:72)
at loadDotEnv ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:158732:12)
at [redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:200869:20
at [redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:165685:16
at maybeAsyncResult ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:163906:44)
at [redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:165684:14
at [redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:163893:22
at Array.reduce () {
errno: -2,
code: 'ENOENT',
syscall: 'open',
path: '.env'
}


--- 2024-08-16T18:14:52.627Z log


⛅️ wrangler 3.61.0 (update available [32m3.72.0[39m)
[38;5;214m-------------------------------------------------------[39m




--- 2024-08-16T18:14:52.652Z warn
[33m▲ [43;33m[[43;30mWARNING[43;33m][0m [1mProcessing wrangler.toml configuration:[0m


- "assets" fields are experimental and may change or break at any time.





--- 2024-08-16T18:14:52.663Z debug
Retrieving cached values for userId from node_modules/.cache/wrangler


--- 2024-08-16T18:14:52.663Z debug
Metrics dispatcher: Dispatching disabled - would have sent {"type":"event","name":"run dev","properties":{"local":true,"usesTypeScript":true}}.


--- 2024-08-16T18:14:52.664Z debug
Failed to load .env file "[redacted]/code/durable-post-error/.dev.vars": Error: ENOENT: no such file or directory, open '[redacted]/code/durable-post-error/.dev.vars'
at Object.openSync (node:fs:573:18)
at Object.readFileSync (node:fs:452:35)
at tryLoadDotEnv ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:158723:72)
at loadDotEnv ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:158732:12)
at getVarsForDev ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:198228:18)
at getBindings ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:206571:10)
at getBindingsAndAssetPaths ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:206452:20)
at getDevReactElement ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:206136:40)
at startDev ([redacted]/code/durable-post-error/node_modules/wrangler/wrangler-dist/cli.js:206200:60)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {
errno: -2,
code: 'ENOENT',
syscall: 'open',
path: '[redacted]/code/durable-post-error/.dev.vars'
}


--- 2024-08-16T18:14:52.664Z log
Your worker has access to the following bindings:
  • Durable Objects:
    • thing: Thing

--- 2024-08-16T18:14:52.711Z log [2m⎔ Starting local server...[22m

--- 2024-08-16T18:14:57.236Z debug [InspectorProxyWorker] handleProxyControllerIncomingMessage {"type":"reloadStart"}

--- 2024-08-16T18:14:57.242Z debug [InspectorProxyWorker] handleProxyControllerIncomingMessage {"type":"reloadComplete","proxyData":{"userWorkerUrl":{"protocol":"http:","hostname":"127.0.0.1","port":"57796"},"userWorkerInspectorUrl":{"protocol":"ws:","hostname":"127.0.0.1","port":"57786","pathname":"/core:user:durable-post-error"},"userWorkerInnerUrlOverrides":{"protocol":"http"},"headers":{"MF-Proxy-Shared-Secret":"47226542-9427-4b6b-a101-17378e8b9bb1"},"liveReload":false,"proxyLogsToController":false,"internalDurableObjects":[{"name":"thing","class_name":"Thing"}],"entrypointAddresses":{"Thing":{"host":"127.0.0.1","port":57797},"INTERNAL_WRANGLER_MIDDLEWARE":{"host":"127.0.0.1","port":57798},"default":{"host":"127.0.0.1","port":57799}}}}

--- 2024-08-16T18:15:00.697Z 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/jsg/util.c++:278: error: e = kj/compat/http.c++:1989: failed: expected clean; can't read more data after a previous read didn't complete stack: 101a82afb 102f2853c 100aeb83c 1011ee3d8 100ae253c 101221a6f 101221b03; sentryErrorContext = jsgInternalError

--- 2024-08-16T18:15:00.748Z debug [InspectorProxyWorker] SEND TO DEVTOOLS {"method":"Runtime.executionContextsCleared"}

--- 2024-08-16T18:15:00.748Z debug [InspectorProxyWorker] NEW RUNTIME WEBSOCKET http://127.0.0.1:57786/core:user:durable-post-error

--- 2024-08-16T18:15:00.749Z debug [InspectorProxyWorker] RUNTIME WEBSOCKET OPENED

--- 2024-08-16T18:15:00.749Z debug [InspectorProxyWorker] SEND TO RUNTIME {"method":"Runtime.enable","id":100000001}

--- 2024-08-16T18:15:00.749Z debug [InspectorProxyWorker] reconnectRuntimeWebSocket

--- 2024-08-16T18:15:00.750Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { method: 'Runtime.executionContextCreated', params: { context: { id: 31225345, origin: '', name: 'Worker', uniqueId: '-8680546262951044072.2674101883297242401' } } }

--- 2024-08-16T18:15:00.751Z error [31m✘ [41;31m[[41;97mERROR[41;31m][0m [1mUncaught (async) TypeError: Can't read from request stream after response has been sent.[0m

--- 2024-08-16T18:15:00.751Z debug [InspectorProxyWorker] SEND TO RUNTIME {"method":"Debugger.enable","id":100000002}

--- 2024-08-16T18:15:00.752Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { method: 'Debugger.scriptParsed', params: { scriptId: '3', url: 'file://[redacted]/code/durable-post-error/.wrangler/tmp/dev-ptvoTq/index.js', startLine: 0, startColumn: 0, endLine: 666, endColumn: 94, executionContextId: 31225345, hash: '51381fa33db140701f7856697a22a1d48c886719d6af04bd5a8893b0e8fe80b2', isLiveEdit: false, sourceMapURL: 'index.js.map', hasSourceURL: true, isModule: true, length: 61440, scriptLanguage: 'JavaScript', embedderName: 'index.js' } }

--- 2024-08-16T18:15:00.752Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { method: 'Debugger.scriptParsed', params: { scriptId: '4', url: 'cloudflare:workers', startLine: 0, startColumn: 0, endLine: 10, endColumn: 0, executionContextId: 31225345, hash: '95b000c8168afc603c2f855cc510cdd1d9e89180fe6367ddb1665f390ef1561e', isLiveEdit: false, sourceMapURL: '', hasSourceURL: false, isModule: true, length: 605, scriptLanguage: 'JavaScript', embedderName: 'cloudflare:workers' } }

--- 2024-08-16T18:15:00.752Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { id: 100000002, result: { debuggerId: '-207011184714484215.761388423425182187' } }

--- 2024-08-16T18:15:00.753Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { id: 100000003, method: 'Network.enable', result: {} }

--- 2024-08-16T18:15:00.753Z debug [InspectorProxyWorker] SEND TO RUNTIME {"method":"Network.enable","id":100000003}

--- 2024-08-16T18:15:00.753Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { method: 'Runtime.exceptionThrown', params: { timestamp: 1723832100697, exceptionDetails: { exceptionId: 1, text: 'Uncaught (async)', lineNumber: 0, columnNumber: -2, url: 'undefined', exception: [Object], executionContextId: 31225345 } } }

--- 2024-08-16T18:15:00.753Z debug [InspectorProxyWorker] RUNTIME INCOMING MESSAGE { id: 100000001, result: {} }

--- 2024-08-16T18:15:07.206Z debug Not Implemented Error: ConfigController#teardown

--- 2024-08-16T18:15:07.206Z debug ProxyController teardown

--- 2024-08-16T18:15:07.209Z log [2m⎔ Shutting down local server...[22m

threepointone avatar Aug 16 '24 18:08 threepointone

I also note that wrangler is extremely fragile, with a very simple benchmark I was getting about a 30% failure on all requests.

threepointone avatar Aug 16 '24 19:08 threepointone

So it's that if you POST without a content-type header, Wrangler throws this error.

irvinebroque avatar Aug 16 '24 21:08 irvinebroque

Unfortunately I get the error even with a Content-Type header

curl -X POST http://localhost:8787 -d \"some body\" -H \"Content-Type: text/plain\"

or

fetch("http://localhost:8787/parties/thing/123", {
  method: "POST",
  body: "abc",
  headers: {
    "Content-Type": "text/plain",
  },
})
  .then((response) => {
    console.log(response);
  })
  .catch((error) => {
    console.log(error);
  });

threepointone avatar Aug 16 '24 22:08 threepointone

Escape character makes a difference? 🤔

> curl -X POST http://localhost:8787 \
     -H "Content-Type: text/html" \
     -d "some body" 
Hello World!%            
                                                                                                                                                                                                                         
> curl -X POST http://localhost:8787 \
     -H "Content-Type: text/html" \
     -d \"some body\"
Hello World!curl: (3) URL rejected: Bad hostname

irvinebroque avatar Aug 17 '24 00:08 irvinebroque

with the escape characters, the body doesn't get sent fully, sigh "some . I'm bad at bash fu.

Instead of the curl, now using this script to experiment:

fetch("http://localhost:8787/parties/thing/123", {
  method: "POST",
  body: "abc",
  headers: {
    "Content-Type": "text/plain",
  },
})
  .then((response) => {
    console.log(response);
  })
  .catch((error) => {
    console.log(error);
  });

The error shows up with or without the content-type header The error doesn't come if I drain the body before sending the response (say, with await request.text())

I'll leave this for oncall for next week. I think I have to file another issue for the brittleness (sending a few requests locks up the server badly atm)

what is happening lol

threepointone avatar Aug 17 '24 08:08 threepointone