Cannot call write after a stream was destroyed #69

michelalbers · 2023-07-18T12:02:07Z

Screenshot

Expected Behaviour
Do not write to the stream after it is closed / destroyed

Actual Behaviour
Writes to stream after it was destroyed which results in an error.

Debug Information
This bug resulted when using the use/express handler created with a createHandler call. According to the code there is no check in place wether the stream was closed in the meantime.

Further Information
Maybe introduce a variable let cancelled = false; and set it to true once the stream was closed. Check for cancelled before trying to do a .write().

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

enisdenjo · 2023-07-19T13:25:31Z

Hmm, I thought that the close listener above the loop should suffice, but apparently not.

graphql-sse/src/use/express.ts

Lines 96 to 101 in f33ccc2

    
           res.once('close', body.return); 
        
           for await (const value of body) { 
        
             await new Promise<void>((resolve, reject) => 
        
               res.write(value, (err) => (err ? reject(err) : resolve())), 
        
             ); 
        
           }

I am trying to write a failing test now and then I'll proceed with fixing the bug.

Thanks for reporting!

enisdenjo · 2023-07-19T15:07:55Z

I am struggling a bit with the failing test, can you share more details on when this happens? Or even better, a repro?

enisdenjo · 2023-07-30T15:32:59Z

@michelalbers any luck with the repro?

enisdenjo · 2023-08-07T10:57:19Z

Unable to reproduce. Added some tests too.

groundmuffin · 2023-08-21T09:50:42Z

Same error:
Node version: 16.14.2

Error: Cannot call write after a stream was destroyed
at new NodeError (node:internal/errors:371:5)
at write_ (node:_http_outgoing:750:11)
at ServerResponse.write (node:_http_outgoing:707:15)
at /Users/john/Projects/graphql-api/node_modules/graphql-sse/lib/use/express.js:75:56
at new Promise ()
at handleRequest (/Users/john/Projects/graphql-api/node_modules/graphql-sse/lib/use/express.js:75:19)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
at /Users/john/Projects/graphql-api/src/express.js:162:5 {
code: 'ERR_STREAM_DESTROYED'
}
node:internal/errors:464
ErrorCaptureStackTrace(err);
^

Error: Cannot render headers after they are sent to the client
at new NodeError (node:internal/errors:371:5)
at ServerResponse.writeHead (node:_http_server:312:13)
at ServerResponse.writeHead (/Users/john/Projects/graphql-api/node_modules/on-headers/index.js:44:26)
at ServerResponse.writeHead (/Users/john/Projects/graphql-api/node_modules/on-headers/index.js:44:26)
at /Users/john/Projects/graphql-api/src/express.js:166:9
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5) {
code: 'ERR_HTTP_HEADERS_SENT'
}

Process finished with exit code 1

enisdenjo · 2023-08-21T13:54:13Z

A repro would be very helpful as I am unable to create one myself.

groundmuffin · 2023-08-21T14:30:00Z

I'm unable to reproduce it every time as well, but the following code seems unsafe in certain situation:
:node_modules/graphql-sse/lib/use/express.js:75:56

for await (const value of body) {
        await new Promise((resolve, reject) => res.write(value, (err) => (err ? reject(err) : resolve())));
}

Error: Cannot call write after a stream was destroyed

It looks like the response stream/object was destroyed (for whatever reason), but the promise callback is not canceled.

Also, I put the subscription handler in a try/catch block, as the docs specifies, but the node process crash with an unhandled exception :

app.use(
  GQL_SUBSCRIPTIONS_ENDPOINT,
  async (req, res) => {
	  try {
		  await subscriptionsHandler(req, res)
	  }
	  catch (err) {
		  console.error(err)
		  res.writeHead(500).end()
	  }
  }
)

enisdenjo · 2023-08-21T15:09:11Z

The write loop should break as soon as the connection closes (see #69 (comment)).

This line takes care of it:

graphql-sse/src/use/express.ts

Line 96 in 256b590

res.once('close', body.return);

I am suspicious that express itself is late in reporting the closed connection event.

groundmuffin · 2023-08-22T14:59:13Z

Lets assume express actually is late in reporting the closed connection event. Isn't that enough reason to check the res availability before calling .write on it?

groundmuffin · 2023-08-22T15:14:18Z

Also I suppose that setting a handler on a 'close' event put it on a Macrotask queue (Node Event Loop), while setting a promise callback put it on a Microtask queue. Because of the fact that Microtask queue is consulted more frequently by design, we can meet a situation when the "for loop" handler is called before the "once" one.

enisdenjo · 2023-08-22T15:34:52Z

Both of your points make perfect sense @groundmuffin, I'll make the adjustments. Thanks!

…esponse's `close` event is late (#75) Closes #69

## [2.2.2](v2.2.1...v2.2.2) (2023-08-22) ### Bug Fixes * **use/http,use/http2,use/express,use/fastify:** Handle cases where response's `close` event is late ([#75](#75)) ([4457cba](4457cba)), closes [#69](#69)

enisdenjo · 2023-08-22T15:58:06Z

🎉 This issue has been resolved in version 2.2.2 🎉

The release is available on:

Your semantic-release bot 📦🚀

enisdenjo · 2023-08-22T15:59:55Z

@michelalbers, @groundmuffin the v2.2.2 includes a fix, would be great if you can test it out and report if the issue persists. Thank you for reporting and advising!

groundmuffin · 2023-08-23T11:43:36Z

It's still happening

Error: Cannot call write after a stream was destroyed
    at new NodeError (node:internal/errors:371:5)
    at write_ (node:_http_outgoing:750:11)
    at ServerResponse.write (node:_http_outgoing:707:15)
    at closed (/Users/john/Projects/graphql-api/node_modules/graphql-sse/lib/use/express.js:81:25)
    at new Promise (<anonymous>)
    at handleRequest (/Users/john/Projects/graphql-api/node_modules/graphql-sse/lib/use/express.js:75:34)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at /Users/john/Projects/graphql-api/src/express.js:162:5 {
  code: 'ERR_STREAM_DESTROYED'
}
node:internal/errors:464
    ErrorCaptureStackTrace(err);
    ^

Error: Cannot render headers after they are sent to the client
    at new NodeError (node:internal/errors:371:5)
    at ServerResponse.writeHead (node:_http_server:312:13)
    at ServerResponse.writeHead (/Users/john/Projects/graphql-api/node_modules/on-headers/index.js:44:26)
    at ServerResponse.writeHead (/Users/john/Projects/graphql-api/node_modules/on-headers/index.js:44:26)
    at /Users/john/Projects/graphql-api/src/express.js:166:9
    at processTicksAndRejections (node:internal/process/task_queues:96:5) {
  code: 'ERR_HTTP_HEADERS_SENT'
}

enisdenjo · 2023-08-23T11:49:28Z

Wow, then the .closed flag is wrong too. 🤔

…tead of `closed` before writing to response Closes #69

## [2.2.3](v2.2.2...v2.2.3) (2023-08-23) ### Bug Fixes * **use/http,use/http2,use/express,use/fastify:** Check `writable` instead of `closed` before writing to response ([3c71f69](3c71f69)), closes [#69](#69)

enisdenjo · 2023-08-23T12:03:48Z

🎉 This issue has been resolved in version 2.2.3 🎉

The release is available on:

Your semantic-release bot 📦🚀

enisdenjo · 2023-08-23T12:11:33Z

@groundmuffin, @michelalbers can you try out v2.2.3? I use the .writable flag there instead.

enisdenjo added the bug Something isn't working label Jul 19, 2023

enisdenjo self-assigned this Jul 20, 2023

enisdenjo closed this as not planned Won't fix, can't repro, duplicate, stale Aug 7, 2023

enisdenjo reopened this Aug 22, 2023

enisdenjo mentioned this issue Aug 22, 2023

fix(use/http,use/http2,use/express,use/fastify): Handle cases where response's close event is late #75

Merged

1 task

enisdenjo closed this as completed in #75 Aug 22, 2023

enisdenjo added a commit that referenced this issue Aug 22, 2023

fix(use/http,use/http2,use/express,use/fastify): Handle cases where r…

4457cba

…esponse's `close` event is late (#75) Closes #69

enisdenjo added the released Has been released and published label Aug 22, 2023

enisdenjo added a commit that referenced this issue Aug 23, 2023

fix(use/http,use/http2,use/express,use/fastify): Check writable ins…

3c71f69

…tead of `closed` before writing to response Closes #69

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cannot call write after a stream was destroyed #69

Cannot call write after a stream was destroyed #69

michelalbers commented Jul 18, 2023

enisdenjo commented Jul 19, 2023 •

edited

enisdenjo commented Jul 19, 2023

enisdenjo commented Jul 30, 2023

enisdenjo commented Aug 7, 2023

groundmuffin commented Aug 21, 2023 •

edited

enisdenjo commented Aug 21, 2023

groundmuffin commented Aug 21, 2023 •

edited

enisdenjo commented Aug 21, 2023

groundmuffin commented Aug 22, 2023

groundmuffin commented Aug 22, 2023 •

edited

enisdenjo commented Aug 22, 2023

enisdenjo commented Aug 22, 2023

enisdenjo commented Aug 22, 2023

groundmuffin commented Aug 23, 2023 •

edited

enisdenjo commented Aug 23, 2023

enisdenjo commented Aug 23, 2023

enisdenjo commented Aug 23, 2023

Cannot call write after a stream was destroyed #69

Cannot call write after a stream was destroyed #69

Comments

michelalbers commented Jul 18, 2023

enisdenjo commented Jul 19, 2023 • edited

enisdenjo commented Jul 19, 2023

enisdenjo commented Jul 30, 2023

enisdenjo commented Aug 7, 2023

groundmuffin commented Aug 21, 2023 • edited

enisdenjo commented Aug 21, 2023

groundmuffin commented Aug 21, 2023 • edited

enisdenjo commented Aug 21, 2023

groundmuffin commented Aug 22, 2023

groundmuffin commented Aug 22, 2023 • edited

enisdenjo commented Aug 22, 2023

enisdenjo commented Aug 22, 2023

enisdenjo commented Aug 22, 2023

groundmuffin commented Aug 23, 2023 • edited

enisdenjo commented Aug 23, 2023

enisdenjo commented Aug 23, 2023

enisdenjo commented Aug 23, 2023

enisdenjo commented Jul 19, 2023 •

edited

groundmuffin commented Aug 21, 2023 •

edited

groundmuffin commented Aug 21, 2023 •

edited

groundmuffin commented Aug 22, 2023 •

edited

groundmuffin commented Aug 23, 2023 •

edited