Logging with express-winston: wrong order of logs

Question

I'm using code like this:

const app = require('express')();
const winston = require('winston');
const expressWinston = require('express-winston');

app.use(expressWinston.logger({
  transports: [
    new winston.transports.Console(),
  ],
  format: winston.format.combine(
    winston.format.printf(info => `Date from winston: ${Date.now()} ${info.message}`),
  ),
  expressFormat: true,
}));

app.get('/check', (req, res) => {
    console.log(`Date from route: ${Date.now()}`);
    res.end('OK');
});

app.listen(3000, () => console.log('Listening...'));

and when I try to call /check route, I get this in the console:

Date from route: 1588531901238
Date from winston: 1588531901247 GET /check 200 2ms

As you can see, time from middleware is later than time from route handler.

Why? How can I fix it? I need to get right order of passing middlewares.

Answer 1

Update

This feature doesn't exist in express-winston yet according to this issue.

A workaround could be that you add a middleware to express before your routes to intercept all request and then log the information you need through your custom logger or you create a custom transport in winston for that. A simple example is just

function logRequest(req, res, next) {
  console.log('Request', req.path, Date.now());

  next();
}

app.use(logRequest);
// routes...

Previous answer

Question 1:

As you can see, time from middleware is later than time from route handler. Why?

Answer:

This because the console transport new winston.transports.Console() logs your HTTP reqest to the console and not your console.log(<some-text>). This is from the documentation of express-winston

Use expressWinston.logger(options) to create a middleware to log your HTTP requests

To demonstrate this, lets take your code and see the result:

// Your above code here...

app.get('/check', (req, res) => {
    console.log(`Date from route: ${Date.now()}`);
    let i = 1;

    const handle = setInterval(() => {
      console.log('i:', i);
      i++;
    }, 1000);

    setTimeout(() => {
      console.log('i before response:', i);
      clearInterval(handle);
      res.end('OK');
    }, 3000);
});

app.listen(3000, () => console.log('Listening...'));

Result

Listening...
Date from route: 1588616514869
i: 1
i: 2
i before response: 3
Date from winston: 1588616517889 GET /check 200 3005ms

From the result we see that you only get the custom message Date from winston: 1588616065807 from winston after you we call res.end('OK') instead of when we call console.log('Date from route: ${Date.now()}');.

Question 2:

How can I fix it?

Answer:

Rather than using the default console.log you create your own logger where you format the message and then stdout. Something like this:

const app = require('express')();
const winston = require('winston');

const { combine, timestamp, printf } = winston.format;
const myFormat = printf(({ message, timestamp }) => {
  const customMessage = `Date from winston: ${timestamp}`;
  return `${customMessage}\n${message}`;
});

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console(),
  ],
  format: combine(timestamp(), myFormat)
});

app.get('/check', (req, res) => {
  logger.info(`Date from route: ${Date.now()}`);
  let i = 1;

  const handle = setInterval(() => {
    console.log('i:', i);
    i++;
  }, 1000);

  setTimeout(() => {
    console.log('i before response:', i);
    clearInterval(handle);
    res.end('OK');
  }, 3000);
});

app.listen(3000, () => console.log('Listening...'));

Result

Listening...
Date from winston: 2020-05-04T18:26:26.508Z
Date from route: 1588616786506
i: 1
i: 2
i before response: 3

In this case you see the formatted message displays when you call logger.info rather than when you call res.end('OK').

In summary use your custom logger to get the logs look the way you want.