Sending file with Fastify server prematurely marks transfer as finished

[jkscx]

Version:
deno 2.1.4 (stable, release, x86_64-unknown-linux-gnu)
v8 13.0.245.12-rusty
typescript 5.6.2

Description

I was trying to send a file with a Fastify server and upon completion of the file's transfer have some post-transfer action execute, but realized that the post-transfer action was executing too quickly. The file transfer was taking at least 10 seconds, but the post-transfer action was executed almost immediately after starting the transfer...

Upon extensive debugging I have realized that it's a bug in Deno because the same code correctly works with Node. The problem lies in the fact that the file stream which is sent prematurely closes (which does not happen in Node). The file does get transferred in it's entirety, but the file stream which is used to read from the file gets closed before that and I think that makes Fastify think that the transfer finished.

For now I'm switching back to Node, but here's a minimal reproducible example which showcases the bug in case someone is interested in fixing it.

How to reproduce

import * as fs from "node:fs"

import Fastify from 'fastify'
import { Readable, Transform, Writable } from 'node:stream';

// helper
async function sleep(ms) {
    return new Promise((resolve) => {
        setTimeout(resolve, ms);
    });
}

const fastifyServer = Fastify();
fastifyServer.post("/get-file-stream", async (req, reply) => {
    console.time();
    console.info(new Date(), "Request received!");

    // print "ping" every second while sending data
    const pingTaskId = setInterval(() => {
        console.log(new Date(), "ping");
    }, 1000);

    // file can be created via 'head -c 15MB /dev/urandom > ./random-15mb.txt'
    const fileStream = fs.createReadStream('./random-15mb.txt');
    fileStream.on('end', () => {console.info(new Date(), "💧 Stream finished");})
    fileStream.on('close', () => {
        console.info(new Date(), "💧 Stream CLOSED");
        console.timeEnd();
        console.log(); // newline to visually separate stuff
    })

    reply.status(200).send(fileStream);
    await reply; // wait until the file is fully sent
    console.info(new Date(), "📩 Reply awaited");
    clearInterval(pingTaskId); // stop printing "ping"
});

await fastifyServer.listen({port: 42105, host: "0.0.0.0"});
console.log("Server listening...");

One can curl the server to trigger the bug:

curl -X POST http://0.0.0.0:42105/get-file-stream > /dev/null

NOTE: the file transfer needs to be longer so that one can actually notice that the post-transfer action is triggered before the transfer is finished, so either a slow network is required over which the file is sent or (if querying the server locally) the file needs to be quite large.

What is the expected behavior?

Running with Node produces:

$ node ./test2.js
Server listening...
2024-12-29T00:36:51.479Z Request received!
2024-12-29T00:36:52.483Z ping
2024-12-29T00:36:53.483Z ping
2024-12-29T00:36:54.483Z ping
2024-12-29T00:36:55.483Z ping
2024-12-29T00:36:56.406Z 💧 Stream finished
2024-12-29T00:36:56.408Z 📩 Reply awaited
2024-12-29T00:36:56.408Z 💧 Stream CLOSED
default: 4.930s

Notice the 4 pings while the file is transferred and how the transfer takes 4.9 sec.

What do you see instead?

Running with Deno produces:

$ deno run -A test2.js
Not implemented: Server.setTimeout()
Server listening...
2024-12-29T01:36:04.073Z Request received!
2024-12-29T01:36:04.131Z 💧 Stream finished
2024-12-29T01:36:04.132Z 📩 Reply awaited
2024-12-29T01:36:04.134Z 💧 Stream CLOSED
default: 60.6ms

Notice that there's no pings and how the transfer allegedly took only 60 millisec (which is obviously wrong), the transfer was still ongoing for 4 more sec after the message got printed.

Additional information

Platform

This is just for Linux, on MacOS the bug doesn't occur and follows the behavior of Node.

Sending a stream (as in /dev/random) and aborting causes the server to never close the stream

Try adding the below endpoint to the server, curling it and then Ctrl-C curl. Node closes the stream normally, while it remains open forever in Deno and we never await the reply.

fastifyServer.post("/get-infinite-file-stream", async (req, reply) => {
    console.time();
    console.info(new Date(), "Request received!");
    // print "ping" every second while sending data
    const pingTaskId = setInterval(() => {
        console.log(new Date(), "ping");
    }, 1000);

    const fileStream = fs.createReadStream("/dev/random");
    fileStream.on('end', () => {console.info(new Date(), "💧 Stream finished");});
    fileStream.on('close', () => {
        console.info(new Date(), "💧 Stream CLOSED");
        console.timeEnd();
        console.log(); // newline to visually separate stuff
    });

    reply.status(200).send(fileStream);
    await reply;
    console.info(new Date(), "📩 Reply awaited");
    clearInterval(pingTaskId); // stop printing "ping"
});

Sending a generated stream works normally (as in Node)

fastifyServer.post("/get-generator-stream", async (req, reply) => {
    console.time();
    console.info(new Date(), "Request received!");
    // print "ping" every second while sending data
    const pingTaskId = setInterval(() => {
        console.log(new Date(), "ping");
    }, 1000);

    async function* generate() {
        await sleep(1000);
        yield '1000\n';
        await sleep(1000);
        yield '2000\n'
        await sleep(3000);
        yield '5000\n'
        await sleep(1000);
        yield 'END\n'
    }
    const fileStream = new Readable.from(generate());
    fileStream.on('end', () => {console.info(new Date(), "💧 Stream finished");})
    fileStream.on('close', () => {
        console.info(new Date(), "💧 Stream CLOSED");
        console.timeEnd();
        console.log(); // newline to visually separate stuff
    });

    reply.status(200).send(fileStream);
    await reply;
    console.log(new Date(), `📩 Reply awaited`);
    clearInterval(pingTaskId); // stop printing "ping"
});

$ deno run -A test2.js
Server listening...
2024-12-29T01:31:21.644Z Request received!
2024-12-29T01:31:22.648Z ping
2024-12-29T01:31:23.646Z ping
2024-12-29T01:31:24.647Z ping
2024-12-29T01:31:25.647Z ping
2024-12-29T01:31:26.648Z ping
2024-12-29T01:31:27.649Z ping
2024-12-29T01:31:27.665Z 💧 Stream finished
2024-12-29T01:31:27.673Z 📩 Reply awaited
2024-12-29T01:31:27.674Z 💧 Stream CLOSED
[6.03s] default