Premature close

[gajus]

Prerequisites

• I have written a descriptive issue title
• I have searched existing issues to ensure the bug has not already been reported

Fastify version

3.27.4

Plugin version

4.0.1

Node.js version

16.13.1

Operating system

macOS

Operating system version (i.e. 20.04, 11.3, 10)

12.0.1

Description

Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
  at new NodeError (node:internal/errors:371:5)
  at Duplexify.onclose (node:internal/streams/end-of-stream:135:30)
  at Duplexify.emit (node:events:402:35)
  at Duplexify.emit (node:domain:475:12)
  at Duplexify._destroy (/Users/gajus/Documents/dev/contra/contra-web-app/node_modules/duplexify/index.js:199:8)
  at /Users/gajus/Documents/dev/contra/contra-web-app/node_modules/duplexify/index.js:182:10
  at processTicksAndRejections (node:internal/process/task_queues:78:11)

Steps to Reproduce

This appears to happen when request is aborted while still serving the file.

Expected Behavior

Should produce a warning, but not an uncaught error.

[mcollina]

Could you upload an example to reproduce? Even better, would you like to send a PR to fix?

[gajus]

Not an issue I will champion since my use case was addressed without using fastify-compress (by serving pre-compressed files). Feel free to re-open if this an issue for anyone else.

[SimenB]

I got the same today. Having issues reproducing it, tho.

Essentially same stack, but

Error: Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at new NodeError (node:internal/errors:371:5)
    at Duplexify.onclose (node:internal/streams/end-of-stream:135:30)
    at Duplexify.emit (node:events:538:35)
    at Duplexify.emit (node:domain:475:12)
    at Duplexify._destroy (/app/node_modules/peek-stream/node_modules/duplexify/index.js:199:8)
    at /app/node_modules/peek-stream/node_modules/duplexify/index.js:182:10
    at processTicksAndRejections (node:internal/process/task_queues:78:11)

[mcollina]

Lmk if you can repro.

[gajus]

@SimenB The way to reproduce is to start downloading a file and cancel the request while it is still buffering. Tip: using "3g slow" throttling in DevTools helps to replicate it.

[SimenB]

Thanks @gajus!

I've put together https://github.com/SimenB/fastify-premature-close.

However, the only way I get the error is if I use https://chrome.google.com/webstore/detail/imagus/immpkjjlgappgfkkfieppnmlhakdmaab?hl=en and hover the link to trigger a download, then move the cursor away. I recorded a quick screen capture to illustrate

Screen.Recording.2022-03-25.at.16.25.06.mov

Clicking the link and then aborting the download when it starts doesn't trigger the error, so it seems to be an issue when you abort before getting headers back, and not while the response is streaming? Not 100% sure.

[SimenB]

@mcollina are you able to reproduce? Might make sense to reopen the issue 🙂

[mcollina]

The fix this would be to add an 'error' event handler to these:

fastify-compress/index.js

Lines 517 to 518 in 05811f9

	case 1: return swap(null, pumpify(inflate.gzip(), unzipStream(inflate, maxRecursion - 1)))
	case 2: return swap(null, pumpify(inflate.deflate(), unzipStream(inflate, maxRecursion - 1)))

There seem to be a very tight race condition. I would really like to have a unit test for this, I think we could test using proxyquire and overriding the dependency.

Would you like to send a PR?

[SimenB]

Not sure I'm the correct person to fix this, streams are still somewhat magical to me 😅

What would the error handler do? Just swallow?

[mcollina]

I think just swallowing would be fine in this case.

[SimenB]

Seems to be zipStream that's called, not unzipStream. isCompressed(data) is 0 so switch doesn't do anything and doing return swap(null, deflate[encoding]().on('error', () => {})) for

fastify-compress/index.js

Line 506 in 05811f9

return swap(null, deflate[encoding]())

still errors. Adding no-op error handler to the peek call also makes no difference

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[SimenB]

@mcollina thoughts on how to move forward here? I've suppressed the error from our logging now, but that means we might miss actual cases of bad stream handling, and not just these false positives.

[mcollina]

I'm currently focusing on shipping Fastify v4 and I don't have much time to dig deep into this problem. I'd be happy to take a PR that fixes it but it probably requires a couple of days of research to fix.

[SimenB]

Exciting! I don't know streams enough to properly debug this, so I'll wait for somebody else to have time. But no immediate rush 👍

[temsa]

I've put together https://github.com/SimenB/fastify-premature-close.

Hey, I've forked your repo in order to reproduce the error directly with an http client ( after failing making a unit test showing the actual problem in the library):
SimenB/fastify-premature-close#2

Yet, I've realized later that maybe it is not linked to the fastify-compress library, and actually I was having the same error without it:
SimenB/fastify-premature-close#3

So, it seems to me more like a won't fix kind of issue: if there is an issue, it seems to me that it is in fastify rather than in fastify-compress

[TimotejR]

We get a lot of these two errors in production and are not able to reproduce it:

Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
 at new NodeError (node:internal/errors:371:5)
 at Duplexify.onclose (node:internal/streams/end-of-stream:135:30)
 at Duplexify.emit (node:events:402:35)
 at Duplexify._destroy (/app/node_modules/peek-stream/node_modules/duplexify/index.js:199:8)
 at /app/node_modules/peek-stream/node_modules/duplexify/index.js:182:10
 at processTicksAndRejections (node:internal/process/task_queues:78:11)

Error: premature close
 at onclosenexttick (/app/node_modules/end-of-stream/index.js:54:86)
 at processTicksAndRejections (node:internal/process/task_queues:78:11)

Since we use peek-stream only via fastify-compress, we believe they are caused by fastify-compress. We use its version 4.0.0.

[TimotejR]

Yet, I've realized later that maybe it is not linked to the fastify-compress library, and actually I was having the same error without it:
SimenB/fastify-premature-close#3
So, it seems to me more like a won't fix kind of issue: if there is an issue, it seems to me that it is in fastify rather than in fastify-compress

You are using fastify-compress in this code.

[mcollina]

I've tried using the reproduction from @SimenB with all the latest module versions and I can't reproduce. Could you verify?

If the problem still appears, could you check if https://github.com/fastify/fastify-compress/tree/something solves it? I still need to finish this one but there should be enough features for you to verify.

[TimotejR]

Thank you!

I do not understand why hovering above the link should trigger a download. I could reproduce the error (with the versions used by @SimenB) by opening the link in a new tab and closing that tab.

With fastify@4.2.0, @fastify/compress@6.1.0, and @fastify/static@6.4.0, I get the following error when opening the link:

TypeError: reply.header(...).compress is not a function
    at Object.<anonymous> (file:///C:/Users/trose/Documents/fastify-premature-close/index.js:24:6)
    at preHandlerCallback (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\handleRequest.js:126:28)     
    at preValidationCallback (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\handleRequest.js:110:5)   
    at handler (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\handleRequest.js:74:7)
    at handleRequest (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\handleRequest.js:22:5)
    at runPreParsing (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\route.js:487:5)
    at Object.routeHandler [as handler] (C:\Users\trose\Documents\fastify-premature-close\node_modules\fastify\lib\route.js:434:7)
    at Router.lookup (C:\Users\trose\Documents\fastify-premature-close\node_modules\find-my-way\index.js:359:14)
    at Server.emit (node:events:527:28)
    at parserOnIncoming (node:_http_server:956:12)

Edit: OK, I now installed the extension. But with the new versions, I still get the same TypeError by hovering.

[SimenB]

You possibly need an await when registering the plugin? It's been added to the readme at least

[SimenB]

I pushed 2 commits to my reproduction now - one upgrading to the latest versions of deps for fastify@3 (so moving to scoped packages, but not latest) and the error was still reproducable. However, when I upgrade to fastify@4 I don't get any errors. So it seems to have been fixed somehow?

Note that if I use fastify@3 with the latest packages (manually editing 4.x to 3.x in node_modules) the error still reproduces. So this seems like something inside fastify itself changed. 4.0.0-alpha.1 reprduces the error, but not 4.0.0-alpha.2.

From looking at https://github.com/fastify/fastify/releases/tag/v4.0.0-alpha.2, fastify/fastify#3651 seems like the obvious change which fixed this 🙂

[SimenB]

Can confirm fastify/fastify#3651 fixed the issue - applying the reply.request.raw.aborted === true check to fastify 3 also fixes (or at least silences) the error

[mcollina]

Do you think we should backport that fix to v3.x?

[TimotejR]

We would be glad since we use apollo-server-fastify which is not compatible with fastify@4. The error indeed vanishes when using await.

[mcollina]

@TimotejR would you like to send a backport PR of fastify/fastify#3651 against https://github.com/fastify/fastify/tree/3.x?

[TimotejR]

Yes! :)

[SimenB]

https://github.com/fastify/fastify/releases/tag/v3.29.1 has the backport 🎉

[TimotejR]

We still get the same errors. :(

[mcollina]

We would need a reproduction.

[mariusa]

Got this too. Solved by removing fastify-compress, thanks to the discussion here.

Error appeared after upgrading

"@fastify/compress": "5.x.x" to 6.x.x
"fastify": "3.x.x" to 4.x.x

and all current fastify components ("fastify-plugin" etc). No other code changes, so it worked fine with previous versions.

Strange, the error never shown in production (on Heroku). Added a log just before the error, that shows, but then nothing on that request (which didn't complete).

Only on development it was showing:

[1659947213897] ERROR (3648759 on fedora): premature close
    reqId: "req-1"
    err: {
      "type": "Error",
      "message": "premature close",
      "stack":
          Error: premature close
              at onclosenexttick ( .../node_modules/end-of-stream/index.js:54:86)
              at processTicksAndRejections (node:internal/process/task_queues:78:11)
    }

Trying to build a reproduction.

[mcollina]

Note that a logged error is the expected behavior as a connection was truncated. This issue was about an uncaught exception.

[mariusa]

Right. Saying that there was no logged error in production, just on development. It was hard to debug without a logged error.

Reproduction:
test.html (works fine with a simple html page, error appears only with this content). Even removing some of the comments solves the error (!)

<!--
  test testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest testtest test

  https://community.shopify.com/c/shopify-apis-and-sdks/shopify-app-gem-or-shopify-koa-shopify-auth-error/m-p/1505650#M77895
-->

<body>
    <script src="https://unpkg.com/@shopify/app-bridge@2"></script>
    <script>
        // If the current window is the 'parent', change the URL by setting location.href
        if (window.top === window.self) {
            window.top.location.href = "{{redirectURL}}"

            // If the current window is the 'child', change the parent's URL with App Bridge Redirect
        } else {
            var AppBridge = window['app-bridge']
            var app = AppBridge.default({
                apiKey: "{{SHOPIFY_API_KEY}}",
                shopOrigin: "{{shopDomain}}",
            })

            var normalizedLink = document.createElement('a')
            normalizedLink.href = "{{redirectURL}}"

            var Redirect = AppBridge.actions.Redirect
            Redirect.create(app).dispatch(Redirect.Action.REMOTE, normalizedLink.href)
        }
    </script>
</body>

misc.js

'use strict'

// eslint-disable-next-line require-await
export default async (fastify, opts) => {


    fastify.get('/test', async (req, reply) => {
        let page = fs.readFileSync(`./tpl/test.html`, 'utf8')
        console.log('page', page)
        reply.type('text/html') //otherwise it's plain text, instead of being interpreted as html
        reply.send(page)
        return
    })

}

[ilya-adnymics]

Too late to the party, but Google sent me here, so I'll post a comment in case someone else would end up here as well.
Got the same error after migrating to fastify 4 and @fastify/compress 6. I didn't want to remove @fastify/compress as I find it super nice (although the error was gone after I tried commenting it out 🤷‍♂️). What fixed it for me is following this instructions from fastify Migration guide:

In some situations, like when a response is sent asynchronously or when you're just not explicitly returning a response, you'll need to return the reply argument from your router handler.

So basically repace

  ...
  reply.send(page)
  return

with

  return reply.send(page)

After this, my requests started working, compression is working as well.

[TimotejR]

We could finally reproduce the "error" by reloading the client during fetching a lot of data. I suggest to log a warning instead of an error.

[matthiasg]

Its actually pretty easy to reproduce

import Fastify from 'fastify'
import FastifyCompress from '@fastify/compress'

const fastify = Fastify({
  logger: true
})

await fastify.register(FastifyCompress, { global: true, threshold: 1, encodings: ['gzip', 'deflate'] })

const docA = { id: 'testA' }
const docB = { id: 'testB' }

fastify.get('/', 
  async (request, reply) => {
   reply.send([docA, docB])
  })

fastify.listen({ port: 8000 }, (err) => {
  if (err) {
    fastify.log.error(err)
    process.exit(1)
  }
})

Changing to return reply.send like @ilya-adnymics said fixes it

[danielecr]

I am using reply.compress() directly, and I meet this error too. I can not explain why on the client side I got 'ERR_PADDING_2', I search for it, I found reference on nodejs on windows
But really on server side the error was "premature close". So I did some tests, I found that

return reply;

at the end of the handler, fixed the problem.
For some reason I thought that return null; was a good choice, but no.
I am just wondering if not returning the reply object cause some dispose/gc made too soon.

But really this happens only when using compress.

Some combination I tried:

1. reply.send(content); return null;: FST_ERR_REP_ALREADY_SENT","name":"FastifyError","statusCode":500
2. reply.compress(content); return null;: ERR_STREAM_PREMATURE_CLOSE
3. reply.compress(content); return;: ERR_STREAM_PREMATURE_CLOSE
4. reply.compress(content); return reply;: ok
5. reply.send(content); return reply;: ok

So, at the end I adopted the practice to return reply, that is ok every time.

NOTE: my handler is async

[alexcroox]

I can confirm returning even a basic JSON object will create this error unless you do as danielecr said above:

reply.compress({ test: true })
return reply

return reply.compress will not work as a 1 liner in an async handler

[Uzlopak]

This is documented behaviour:

https://fastify.dev/docs/latest/Reference/Routes/#promise-resolution

[jack-bliss]

i'm also getting this error with the direct JSON return pattern. i think it would be really nice if we could register an error handler for this case at the point that we register the plugin - that way we could choose to log it or ignore it ourselves. for now, we're going to change to use reply.send instead of direct returns.

[Eomm]

Please open a new detailed issue adding a Minimal, Reproducible Example or a feature request.