Unable to gracefully shut down transport

[chernodub]

Currently, it is not possible to gracefully handle the external exit signals (SIGTERM, SIGINT for example). Pino does not send close or any similar events to transport when the app is being stopped.

/index.js

import { createServer } from 'http';
import pino from 'pino';

const logger = pino({
  transport: {
    target: './transport.js',
  },
});

// using server to keep the app running
createServer((req, res) => { res.end() }).listen(8080, () => { logger.info('App started'); });

/transport.js

import { appendFileSync as appendFile, writeFileSync } from 'fs';
import build from 'pino-abstract-transport';

// writing to file for 
const LOG_FILE_NAME = 'tmp.log';
writeFileSync(LOG_FILE_NAME, '');

export default (_options) =>
  build(
    function (source) {
      source.forEach((s) =>
        // writing to file for the sake of example, it could be a persistent connection to some external service/storage
        appendFile(LOG_FILE_NAME, JSON.stringify(s) + '\n')
      );
    },
    {
      close() {
        // this will never be called on SIGTERM, SIGINT
        appendFile(LOG_FILE_NAME, 'close\n');
      },
    }
  );

Expected behavior:

Pino will send a notification to transport code when a server is being shut down

Actual behavior:

Pino silently kills the transport so it is impossible to clean up or do the graceful shutdown

Code with reproduction: https://github.com/chernodub/pino-transport-shutdown-repro

Steps to reproduce:

1. Run the app via node index.js
2. Stop the app via external signal, for example Ctrl+C will send SIGINT to the app
3. See tmp.log, there are no events similar to close

This is probably related to #1430, but I wanted to create a more focused issue with a simple reproduction

[chernodub]

I was able to process the shut down by accessing worker in pino's private APIs, definitely not the best solution, but it solves the issue temporarily.

Application code:

import { createServer } from 'http';
import pino, { symbols } from 'pino';

const logger = pino({
  transport: {
    target: './transport.js',
  },
});

function shutdownLogger() {
  const transportWorker = logger?.[symbols.streamSym]?.worker;
  transportWorker?.postMessage({
    code: 'CUSTOM_LOGGER_STOP',
  });
}

createServer((req, res) => {
  logger.info(req.url);
  res.end();
}).listen(8080, () => {
  logger.info('App started');
});

process.once('SIGINT', () => {
  shutdownLogger();
  process.exit(0);
});

Transport code:

import { appendFileSync, writeFileSync } from 'fs';
import build from 'pino-abstract-transport';
import { parentPort } from 'worker_threads';

function initDummyConnection() {
  writeFileSync('tmp.log', 'initiated\n');
  return {
    send: (message) => {
      appendFileSync('tmp.log', message);
    },
    close: () => {
      appendFileSync('tmp.log', 'closed\n');
    },
  };
}

export default async (_options) => {
  const connection = initDummyConnection();

  onShutdown(() => connection.close());

  return build(function (source) {
    source.forEach((s) => connection.send(JSON.stringify(s) + '\n'));
  });
};

/**
 * @param {() => void} handleShutdown Shutdown handler.
 * @see multiTransportLogger.ts for more information
 */
function onShutdown(handleShutdown) {
  /** @param {unknown} message */
  const messageHandler = (message) => {
    if (isStopSignal(message)) {
      handleShutdown();
      parentPort?.removeListener('message', messageHandler);
    }
  };

  parentPort?.on('message', messageHandler);
}

/**
 * @param {unknown} message
 */
function isStopSignal(message) {
  const CODE_KEY = 'code';
  const CODE_VALUE = 'CUSTOM_LOGGER_STOP';

  return (
    typeof message === 'object' &&
    message != null &&
    CODE_KEY in message &&
    message[CODE_KEY] === CODE_VALUE
  );
}

[mcollina]

There is no need for any special postMessage here.

The underlining problem is that sending 'SIGINT' does not emit the 'exit' event.

The following would log everything:

import { createServer } from 'http';
import pino from './pino.js';

const logger = pino({
  transport: {
    target: './transport.mjs',
  },
});

// using server to keep the app running
createServer((req, res) => { res.end() }).listen(8080, () => { logger.info('App started'); });

process.on('SIGINT', () => {
  logger.info('SIGINT received');
  process.exit(0); // Calling `.exit()` manually actually fixes this problem
})

I recommend you to use https://github.com/mcollina/close-with-grace.

[chernodub]

You're right, it works just fine with process.exit, my bad I missed this. Thanks for your time, @mcollina! I'm closing the issue then :)

[mcollina]

I'm reopening because I think I can do some magic to handle these.