node.jsexpressloggingwinstonmorgan

Express logs resource usage after everything happened for that operation


I'm using Express 4.17.1 — and Winston 3.3.3 / Morgan 1.10.0 for logging purposes, which I've managed to configure in this way:

import winston from "winston";

const options = {
  console: {
    colorize: true,
    format: winston.format.combine(
      winston.format.colorize(),
      winston.format.timestamp(),
      winston.format.printf((msg) => {
        return `${msg.timestamp} [${msg.level}] - ${msg.message}`;
      })
    ),
    handleExceptions: true,
    json: true,
    level: "debug",
  },
};
const logger = winston.createLogger({
  exitOnError: false,
  transports: [new winston.transports.Console(options.console)], // alert > error > warning > notice > info > debug
});

logger.stream = {
  write: (message) => {
    logger.info(message.slice(0, -1)); // ...use lowest log level so the output will be picked up by any transports
  },
};

export { logger };

I then import the Winston config inside application.js where all the Express setup is done like this:

import express from "express";
import morgan from "morgan";

import { logger } from "./config/winston.js";

const app = express();

app.use(express.json());
// ...some more settings
app.use(morgan("dev", { stream: logger.stream })); // combined, dev

// ...route Definitions

export { app };

The issue I have is with some log statements that looks like are automatically handled by Winston (I guess) based on the Express route that was processed (which I like), but they are being logged after all the usual statements for the corresponding workflow. This is an example:

2021-03-03T16:25:22.199Z [info] - Searching all customers...
{
  method: 'select',
  options: {},
  timeout: false,
  cancelOnTimeout: false,
  bindings: [],
  __knexQueryUid: 'dFKYVOlaQyJswbxoex7Y6',
  sql: 'select `customers`.* from `customers`'
}
2021-03-03T16:25:22.203Z [info] - Done with all customers workflow...
2021-03-03T16:25:22.215Z [info] - GET /api/customers 200 11.727 ms - 395

I would expect 2021-03-03T16:25:22.215Z [info] - GET /api/customers 200 11.727 ms - 395 to be the very first piece in that workflow because it's the start of it, but it's being logged at the end — which is kind of confusing.

Is there a way to fix this or is this like that by design? If it can be fixed, what should I add/remove/tweak in the Winston config or anywhere else.


Solution

  • According to the morgan-documentation, there's a setting which allows you to write the access-log on request instead of on response (with the latter being the default):

    Write log line on request instead of response. This means that a requests will be logged even if the server crashes, but data from the response (like the response code, content length, etc.) cannot be logged.

    So passing { immediate: true } to morgan should make the log appear at the beginning of the workflow, but the log will obviously only contain request related data.