Sporadic ERR_STREAM_PREMATURE_CLOSE

[tigt]

🐛 Bug Report

Seemingly at random, fastify-static will fail to serve a static file.

• Refreshing/re-requesting the file usually fixes it
• Happens for text responses and binary files such as PNGs
• Happens with or without fastify-compress

Stack trace:

Error: Premature close
    at PassThrough.onclose ([redacted]/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)
    at PassThrough.emit (events.js:215:7)
    at emitCloseNT ([redacted]/node_modules/fastify-static/node_modules/readable-stream/lib/internal/streams/destroy.js:56:8)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)

Error log in console:

{
  "level": 50,
  "time": 1574780438858,
  "pid": 12747,
  "hostname": "[redacted]",
  "reqId": 12,
  "req": {
    "method": "GET",
    "url": "/sa/Home_qVN1-2b1b950.js",
    "remotePort": 52715
   },
   "res": { "statusCode": 500 },
   "err" :{
     "type": "NodeError",
     "message": "Premature close",
     "stack": "Error: Premature close\n    at PassThrough.onclose ([redacted]/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)\n    at PassThrough.emit (events.js:215:7)\n    at emitCloseNT ([redacted]/node_modules/fastify-static/node_modules/readable-stream/lib/internal/streams/destroy.js:56:8)\n    at processTicksAndRejections (internal/process/task_queues.js:79:21)",
     "name": "Error",
     "code": "ERR_STREAM_PREMATURE_CLOSE"
    },
  "msg": "Premature close",
  "v": 1
}

To Reproduce

Steps to reproduce the behavior:

1. Serve some static files with fastify-static
2. Seemingly randomly, the above will happen for page assets
3. The file indeed never makes it to the browser

Paste your code here:

import path from 'path'
import serveStatic from 'fastify-static'
import fp from 'fastify-plugin'

function staticAssets (server, opts, next) {
  server.register(serveStatic, {
    root: path.join(__dirname, '../browser'),
    prefix: '/sa/',
    maxAge: 9999999,
    immutable: true,
    dotfiles: 'ignore',
    index: false,
    decorateReply: false
  })

  server.register(serveStatic, {
    root: path.join(__dirname, '../server/magic-urls'),
    maxAge: 24 * 60 * 60, // 1 day
    dotfiles: 'ignore',
    index: false,
    decorateReply: false
  })
  next()
}

export default fp(staticAssets, {
  fastify: '2.10',
  name: '[redacted]-static-assets'
})

This plugin is then registered like so:

import staticAssets from './static-assets'

fastify.register(staticAssets)

Expected behavior

A clear and concise description of what you expected to happen.

Paste the results here:

Your Environment

• node version: 12.13.0
• fastify version: 2.10.0
• os: MacOS Mojave 10.14.6
• Requesting assets with MacOS Firefox 71, but it doesn’t appear to be doing anything special in its devtools

[tigt]

What makes this issue worse is that it combines with fastify-compress to bring down the server whenever it happens, with:

{"level":50,"time":1574781671276,"pid":13189,"hostname":"OF060VL35UHTD6R","reqId":12,"req":{"method":"GET","url":"/apple-touch-icon.png","remotePort":52883},"res":{"statusCode":500},"err":{"type":"NodeError","message":"Premature close","stack":"Error: Premature close\n    at Duplexify.onclose ([redacted]/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)\n    at Duplexify.emit (events.js:215:7)\n    at Duplexify._destroy ([redacted]/node_modules/duplexify/index.js:199:8)\n    at [redacted]/node_modules/duplexify/index.js:182:10\n    at processTicksAndRejections (internal/process/task_queues.js:75:11)","name":"Error","code":"ERR_STREAM_PREMATURE_CLOSE"},"msg":"Premature close","v":1}

[redacted]/node_modules/fastify-compress/index.js:153
  if (err) this.res.log.error(err)
                        ^
TypeError: Cannot read property 'error' of undefined
    at _Reply.onEnd ([redacted]/node_modules/fastify-compress/index.js:153:25)
    at [redacted]/node_modules/pump/index.js:75:7
    at f ([redacted]/node_modules/once/once.js:25:25)
    at Duplexify.<anonymous> ([redacted]/node_modules/pump/index.js:31:21)
    at Duplexify.f ([redacted]/node_modules/once/once.js:25:25)
    at onclosenexttick ([redacted]/node_modules/end-of-stream/index.js:54:73)
    at processTicksAndRejections (internal/process/task_queues.js:75:11)

[mcollina]

Are you able to reproduce this reliably?

Would you mind adding sending a PR that fixes it?

[tigt]

I wish I could reproduce it reliably. I'd love to PR it, but I'm completely stumped to what's going on. After about 3 days of fruitless debugging, I've got no leads and am considering switching servers to koa or something.

…

On Wed, Nov 27, 2019, 4:11 AM Matteo Collina ***@***.***> wrote: Are you able to reproduce this reliably? Would you mind adding sending a PR that fixes it? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#116?email_source=notifications&email_token=AB5S2SRM7BWQ5O3C77UA3ITQVY2UZA5CNFSM4JRZSIMKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEFI2E3Y#issuecomment-558998127>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB5S2STCRNFUA2UQTGE4WPDQVY2UZANCNFSM4JRZSIMA> .

[mcollina]

I wish I could reproduce it reliably. I'd love to PR it, but I'm completely
stumped to what's going on.

Same here, I have used those extensively and I have never experienced this. Is this limited to Firefox / Mac OS X?
What does the config of your fastify server look like?

After about 3 days of fruitless debugging, I've got no leads and am
considering switching servers to koa or something.

Passive-aggressive comments like this are not tolerated. Fastify is an open community, and we develop this framework together. I'm sorry this is frustrating for you, but we have no obligation in supporting you.

[tigt]

I’m sorry, I didn’t mean to slight the quality. I’m sure this is something I’m doing wrong, but I made the mistake of thinking out loud for how I’m going to hit my demo deadline.

This does indeed seem to be restricted to MacOS. I’ll try reproducing on Ubuntu to see if I can eliminate that variable.

[tigt]

I haven't run it on *nix yet, but I can confirm it doesn't seem to be related to the filesystem: the same errors happen with a final production build, or with Webpack's in-memory development mode.

[Eomm]

Are you using http2?

[tigt]

No, it's HTTP/1.1. I'll see if I can repro on HTTP/2 though for more data.

…

On Tue, Dec 10, 2019, 5:51 PM Manuel Spigolon ***@***.***> wrote: Are you using http2? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#116?email_source=notifications&email_token=AB5S2SVBYD77QVQET4QXZ5LQYAMQ7A5CNFSM4JRZSIMKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEGRHT6Q#issuecomment-564296186>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB5S2SWIWAA6LAFI7NZVLGLQYAMQ7ANCNFSM4JRZSIMA> .

[mcollina]

There is no need for that as it's not an http2 bug

[tigt]

You’re correct, as the same error happened when using Node’s http2.

I’m still trying to run it on another OS — the proxy at work is draconian.

[tigt]

Sorry about the radio silence — holidays.

I couldn’t reproduce the bug on Ubuntu.

When running ImageOptim on some of my referenced image assets while fastify was running, it caused this exact same error message. Looking around in the send module that fastify-static uses under the hood, it has the open bug Open file with fs.open and use fs.fstat and createWriteStream(null, { fd }):

Open file with fs.open and use fs.fstat and fs.createReadStream(null, { fd }) otherwise we might have a race where the file at the specified path is replaced in the time between fs.stat and fs.createReadStream and wrong header data is provided.

This seems like it might be related. Do you have any ideas on how I might experiment to confirm or deny this hypothesis?

[tigt]

As for what would be modifying the files, I’m not sure, but it could explain why I was never able to find a pattern to the sporadic errors. Some possible sources:

• Open Finder window modifying .DS_Store inside the same directory?
• VS Code doing polling of the directory for its tree/console views?
• MacOS FileVault encryption getting around to a newly modified file?
• Something else my job has installed on my machine in the background?

[mxvincent]

I have the same issue.
To reproduce, open in the brother (i.e. chrome) a large video file. Then during video playing call refresh from your brother, this error appear.
Video is served as Partial-Content and it seem to produce this error.

[markrzen]

I am seeing a similar error that seems to only happen to Safari interacting with fastify-static.

It seems to happen most often on iPhone Safari 604.1.

Error: Premature close
at PassThrough.onclose (/home/node/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)
at PassThrough.emit (events.js:323:22)
at emitCloseNT (/home/node/node_modules/readable-stream/lib/internal/streams/destroy.js:64:8)
at processTicksAndRejections (internal/process/task_queues.js:83:21)

I will investigate some more to see if I can figure out the cause for my products.

[markrzen]

I was able to reproduce it via refreshing Safari repetitively and closing it during one of those refreshes. It doesn't always happen, anyone know better way to abruptly close a connection?

[Eomm]

anyone know better way to abruptly close a connection?

Send back a big file and close the socket, I think it could be done with any client at this point

[thomheymann]

I'm able to reproduce this as advised by playing a big video file in Safari and pausing playback / refreshing the page.

The error message in the logs seems to be a red herring as closing the socket is entirely expected behaviour caused by browsers trying to save bandwidth and stopping unnecessary data transfers.

[Eomm]

I'm not sure it is "expected" since the error should be thrown when the client doesn't close the stream. Is the browser cutting the connections?

It would be good if you could share the example to understand better the case and if it is a browser-dependand issue

[mcollina]

I'm not sure it is "expected" since the error should be thrown when the client doesn't close the stream. Is the browser cutting the connections?

Yes

[tigt]

For anyone currently with this issue: I was able to fix it by taking the README’s advice and using a local copy of NGiNX to serve static files instead, proxying to the Fastify server for everything else.

[admataz]

I have been investigating this to round it off - and have found the following:

It's easy to reproduce the reported warning and error by interrupting a stream in an open connection with the client (I did this using autocannon - see details below).

I think the behaviour is expected.

I tried the same with fastify-compress - to try replicate the server crash mentioned above - but had the same results

autocannon -m GET 'http://127.0.0.1:3000/public/world.geo.json' -d 10 runs for 10 seconds - produces the error at the end when the connections close

[1594213861934] WARN  (76360 on dev.local): response terminated with an error with headers already sent
    reqId: 69657
    err: {
      "type": "NodeError",
      "message": "Premature close",
      "stack":
          Error: Premature close
              at PassThrough.onclose (~/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)
              at PassThrough.emit (events.js:327:22)
              at emitCloseNT (~/node_modules/readable-stream/lib/internal/streams/destroy.js:64:8)
              at processTicksAndRejections (internal/process/task_queues.js:83:21)
      "name": "Error",
      "code": "ERR_STREAM_PREMATURE_CLOSE"
    }
[1594213861934] ERROR (76360 dev.local): Premature close
    reqId: 69660
    req: {
      "method": "GET",
      "url": "/public/world.geo.json",
      "hostname": "127.0.0.1:3000",
      "remoteAddress": "127.0.0.1",
      "remotePort": 63147
    }
    res: {
      "statusCode": 500
    }
    err: {
      "type": "NodeError",
      "message": "Premature close",
      "stack":
          Error: Premature close
              at PassThrough.onclose (~/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)
              at PassThrough.emit (events.js:327:22)
              at emitCloseNT ~/node_modules/readable-stream/lib/internal/streams/destroy.js:64:8)
              at processTicksAndRejections (internal/process/task_queues.js:83:21)
      "name": "Error",
      "code": "ERR_STREAM_PREMATURE_CLOSE"
    }

When the number of requests is predefined, and no connection is interrupted - there is no error

counted requests (not timed)
autocannon -m GET 'http://127.0.0.1:3000/public/world.geo.json' -c 10 -a 18000 - equivalent number of requests, but no error, because it doesn't end with the end of a timer.

with compression
autocannon -m GET 'http://127.0.0.1:3000/public/world.geo.json' -H accept-encoding=gzip,deflate -d 10

[admataz]

can anyone reproduce the reported crash?

[mcollina]

Closing for now.