deno icon indicating copy to clipboard operation
deno copied to clipboard

node:http server doesn't handle read errors

Open ianbrault opened this issue 1 year ago • 8 comments

Version: Deno 1.40.3

Hit the following exception while my webserver was running:

[2024.3.5 07:21:08]: GET /
[2024.3.5 07:25:00]: GET /
[2024.3.5 07:25:00]: GET /
[2024.3.5 07:25:00]: GET /
[2024.3.5 07:25:00]: GET /
error: Uncaught BadResource: Bad resource ID
    at Object.pull (ext:deno_web/06_streams.js:946:38)
    at Module.invokeCallbackFunction (ext:deno_webidl/00_webidl.js:944:16)
    at ReadableByteStreamController.pullAlgorithm (ext:deno_web/06_streams.js:3559:14)  
    at readableByteStreamControllerCallPullIfNeeded (ext:deno_web/06_streams.js:1242:49)
    at ReadableByteStreamController.[[[PullSteps]]] (ext:deno_web/06_streams.js:5979:5) 
    at readableStreamDefaultReaderRead (ext:deno_web/06_streams.js:2509:36)
    at ReadableStreamDefaultReader.read (ext:deno_web/06_streams.js:5476:5)
    at IncomingMessageForServer.read [as _read] (node:http:1176:42)
    at IncomingMessageForServer.Readable.read (ext:deno_node/_stream.mjs:2999:16)
    at flow (ext:deno_node/_stream.mjs:3371:38)

The server is using express on top of Deno:

const app = express();
// ... configure middleware ...
await mongoose.connect("mongodb://localhost:27017");
app.listen(3030, () => info(`server running on https://127.0.0.1:${port}`));

and the home route does nothing outside of sending a file:

router.get("/", (_req, res) => {
    info("GET /");
    res.sendFile("home.html", {
        root: path.getViewsDirectory("home")
    });
});

I am suspicious that the exception is due to the 4 requests within the same second.

ianbrault avatar Mar 09 '24 00:03 ianbrault

@ianbrault do you know, by the way, if there's any way to catch this exception on a global level to prevent server restart? I tried both globalThis.addEventListener('error', ... and globalThis.addEventListener('unhandledrejection', ... but none seems to help.

punarinta avatar Apr 01 '24 13:04 punarinta

@punarinta I am not aware if there's a way to catch this but perhaps someone with more knowledge on the matter can chime in

ianbrault avatar Apr 01 '24 20:04 ianbrault

Thank you! @bartlomieju do you maybe know what should be the way catch such exceptions on the top level?

punarinta avatar Apr 02 '24 07:04 punarinta

@ianbrault, thanks for opening the issue. I created an example to reproduce the bug but it resulted in a different error. Is it possible for you to share an example that reproduces the error that you mentioned?

Example:

import express from 'express';

const app = express();

app.get("/", (_req, res) => {
  console.info("GET /");
  res.sendFile("home.html", {
    root: import.meta.dirname,
  });
});

const port = 3000;
app.listen(port, () => {
  console.log(`Server listening on port ${port}`);
});

The error I encountered is the following which is triggered after wrk finishes its testing:

GET /
error: Uncaught (in promise) TypeError: The stream controller cannot close or enqueue.
    at ReadableStreamDefaultController.enqueue (ext:deno_web/06_streams.js:6057:13)
    at Function.#enqueue (node:http:1352:18)
    at ServerResponse.write [as _write] (node:http:1391:32)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3947:16)
    at _write (ext:deno_node/_stream.mjs:3892:14)
    at ServerResponse.Writable.write (ext:deno_node/_stream.mjs:3895:14)
    at ReadStream.ondata (ext:deno_node/_stream.mjs:3179:26)
    at ReadStream.emit (ext:deno_node/_stream.mjs:1851:9)
    at addChunk (ext:deno_node/_stream.mjs:2873:16)
    at readableAddChunk (ext:deno_node/_stream.mjs:2852:13)

satyarohith avatar May 21 '24 07:05 satyarohith

From @lucacasonato the issue should be fixable by wrapping Controller.enqueue function and checking if the stream has been closed.

bartlomieju avatar May 21 '24 14:05 bartlomieju

@satyarohith I have not been able to reproduce using wrk locally but for an example with some additional detail:

import express from "npm:[email protected]";
import mongoose from "npm:mongoose@^6.7";

import * as path from "$std/path/mod.ts";

function getViewsDirectory(app: string): string {
    const filePath = path.fromFileUrl(import.meta.url);
    const dirPath = path.dirname(filePath)
    return path.join(dirPath, app, "views");
}

const router = express.Router();

router.get("/", (_req, res) => {
    info("GET /");
    res.sendFile("home.html", {
        root: path.getViewsDirectory("home")
    });
});

const app = express();
app.use(express.json());
app.use(express.urlencoded({extended: true}));
app.use(router);

await mongoose.connect("mongodb://localhost:27017");

const port = 3030;
app.listen(port, () => console.log(`server running on https://127.0.0.1:${port}`));

ianbrault avatar Jun 02 '24 02:06 ianbrault

I got here from #15203, I have similar problem with server sent events.

import express from "express";
const app = express();


app.get('/sse', async (req, res) => {
  res.header('Content-Type', 'text/event-stream')
  req.once('close', () => {
    if (req.aborted) {
      console.log('request closed')
    }
  })
  while(true) {
    res.write('data: hello\n\n')
    await new Promise(resolve => setTimeout(resolve, 1000))
  }
});

app.listen(8000, () => console.log('Server listening on port 8000'))

After closing connection "request closed" should be displayed (this works in node) Instead I get following error:

error: Uncaught (in promise) TypeError: The stream controller cannot close or enqueue.
    at ReadableStreamDefaultController.enqueue (ext:deno_web/06_streams.js:6064:13)
    at Function.#enqueue (node:http:1042:18)
    at ServerResponse.write [as _write] (node:http:1075:32)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3956:16)
    at _write (ext:deno_node/_stream.mjs:3901:14)
    at ServerResponse.Writable.write (ext:deno_node/_stream.mjs:3904:14)
    at file:///.../test.js:13:9
    at eventLoopTick (ext:core/01_core.js:207:9)

raaymax avatar Jun 15 '24 10:06 raaymax

@satyarohith

We've been seeing a similar issue in our production environment for a while now:

error: Uncaught (in promise) BadResource: Bad resource ID
    at Object.pull (ext:deno_web/06_streams.js:937:38)
    at Module.invokeCallbackFunction (ext:deno_webidl/00_webidl.js:981:16)
    at ReadableByteStreamController.pullAlgorithm (ext:deno_web/06_streams.js:3558:14)
    at readableByteStreamControllerCallPullIfNeeded (ext:deno_web/06_streams.js:1233:49)
    at ReadableByteStreamController.[[[PullSteps]]] (ext:deno_web/06_streams.js:5985:5)
    at readableStreamDefaultReaderRead (ext:deno_web/06_streams.js:2508:36)
    at ReadableStreamDefaultReader.read (ext:deno_web/06_streams.js:5482:5)
    at IncomingMessageForServer.read [as _read] (node:http:1284:42)
    at IncomingMessageForServer.Readable.read (ext:deno_node/_stream.mjs:2996:16)
    at resume_ (ext:deno_node/_stream.mjs:3346:16)

I found this issue an prayed that upgrading Deno would solve it. Unfortunately it didn't - I've just seen it again on 1.45.2.

We are using Apollo server with express middleware. It seems to happen (in some cases 🤷) when our frontend sends a GraphQL request, cancels it shortly after and then sends another request: Screenshot 2024-07-15 at 16 59 32

Unfortunately I've been unable to make a minimal reproducible example.

It would be greatly appreciated if someone could help investigate this. I'd be happy to provide more details if needed.

bageren avatar Jul 15 '24 15:07 bageren