Creating a custom pino logger per request in koa middleware is resulting in open files accumulating

Question

I'm attempting to set up a custom logger per request on my Koa HTTP server using Koa middleware. The custom pino logger should send logs to both the console and a file. However, I'm encountering an issue with my current implementation regarding files being left open after response.

I've created a Minimum Working Example (MWE) repo. to replicate the problem, which can be found here: https://github.com/benlester/pino-per-request-mwe

To reproduce the issue, clone the repository. After cloning, you need to set up a .env file and add the LOG_BASE_DIR variable, specifying an appropriate directory on your machine where the logs will be stored.

Then, run npm run develop. You will see a pino log like this:

[11:57:11.546] INFO: Process ID: 12329
appName: "TEST PINO"

Make a note of the PID (Process ID), and then open localhost:7777 in your browser. Refresh the page a few times. Next, run the following command, replacing with the actual PID you noted earlier:

lsof -p <PID HERE> | grep TEST_LOG

You will see output similar to the following:

node 12329 ben 35w REG 1,18 327 41451218 /Users/ben/dev/logs/2023-07-19/2023-07-19T10_57_26_540Z_TEST_LOG.log
node 12329 ben 41w REG 1,18 327 41451236 /Users/ben/dev/logs/2023-07-19/2023-07-19T10_57_30_895Z_TEST_LOG.log
node 12329 ben 47w REG 1,18 327 41451238 /Users/ben/dev/logs/2023-07-19/2023-07-19T10_57_31_212Z_TEST_LOG.log

As you can see, even after the request is finished, pino is leaving the log files open. Over time, this accumulation of open files will cause issues.

Is there a way to close these file transports at the end of a Koa request? Is there an intended pattern for achieving this?

I'm aware of koa-pino-logger, but as you can see from my MWE, my logger is highly customized. I wasn't sure from the limited documentation if this level of customisation is possible or easy to achieve with koa-pino-logger.

---

This is basically my implementation without cloning my MWE:

import Koa from "koa";
import Router from "koa-router";
import bodyParser from "koa-bodyparser";
import koaHelmet from "koa-helmet";
import koaCompress from "koa-compress";
import cors from "@koa/cors";

import pino from "pino";

import dotenv from "dotenv";
dotenv.config();

const router = new Router();

const localLogger = pino({
  mixin() {
    return { appName: "TEST PINO" };
  },
  base: undefined,
  level: "silly",
  useOnlyCustomLevels: true,
  customLevels: {
    error: 60,
    warn: 40,
    info: 30,
    http: 25,
    verbose: 21,
    debug: 20,
    silly: 10
  },
  timestamp: pino.stdTimeFunctions.isoTime,
  transport: {
    targets: [{ target: "pino-pretty", level: "silly", options: { destination: 1, colorize: true } }]
  }
});

export type Logger = typeof localLogger;

interface CustomContext extends Koa.Context {
  logger?: Logger;
}

router.get("/", ctx => {
  ctx.logger.verbose("GET endpoint hit");
  ctx.body = "Simple pino logger example";
});

router.post("/", ctx => {
  ctx.logger.verbose("POST endpoint hit");
  ctx.body = "Simple pino logger POST response";
});

async function startServer() {
  const app = new Koa<CustomContext>();

  ////////////////////////////////////////////////////////////////
  // middleware
  app.use(bodyParser({ jsonLimit: "50mb" }));
  app.use(koaHelmet());
  app.use(koaCompress());
  app.use(cors({ origin: "*", credentials: true }));

  app.on("error", async (err, ctx) => {
    ctx.logger.error(err);
  });

  // elapsed time middleware
  app.use(async (ctx, next) => {
    ctx.started = Date.now();
    await next();
  });

  // initialise logger middleware
  app.use(async (ctx, next) => {
    const logFilename = `${process.env.LOG_BASE_DIR}${new Date().toISOString().split("T")[0]}/${
      new Date().toISOString().replace(/[:.]/g, "_") // make filename_safe
    }_TEST_LOG.log`;

    const logger = pino({
      mixin() {
        return { appName: "TEST PINO (PER REQUEST)" };
      },
      base: undefined,
      level: "silly",
      useOnlyCustomLevels: true,
      customLevels: {
        error: 60,
        warn: 40,
        info: 30,
        http: 25,
        verbose: 21,
        debug: 20,
        silly: 10
      },
      timestamp: pino.stdTimeFunctions.isoTime,
      transport: {
        targets: [
          { target: "pino/file", level: "silly", options: { destination: logFilename, mkdir: true } },
          { target: "pino-pretty", level: "silly", options: { destination: 1, colorize: true } }
        ]
      }
    });

    ctx.logger = logger;
    ctx.logger.silly("Logger initialised");
    await next();
  });

  app.use(async (ctx, next) => {
    await next();
    const elapsed = Date.now() - ctx.started + "ms";
    ctx.logger.debug(`Response took ${elapsed}`);
    ctx.set("X-Response-Time", elapsed);
  });

  app.use(router.routes());

  app.listen({ port: 7777 }, () => {
    localLogger.info(`Process ID: ${process.pid}`);
    localLogger.info("HTTP server ready at http://localhost:7777");
  });
}

startServer();