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.