Winston not displaying error details

Question

I am using winston for logging and most of the time it works well, but when there is an exception, it just does not print any details.

Here is my code for configuring winston:

// Create logger
const logger = winston.createLogger()

// Create timestamp format
const tsFormat = () => (new Date()).toLocaleTimeString()

// Attach transports based on app mode
if (process.env.APP_MODE === 'production') {
  // Log to file
  logger.add(new (winston.transports.DailyRotateFile)({
    filename: path.join(__dirname, '../logs/errors-%DATE%.log'),
    datePattern: 'YYYY-MM-DD-HH',
    zippedArchive: true,
    format: winston.format.json(),
    handleExceptions: true
  }))
} else {
  // Log to the console
  logger.add(new (winston.transports.Console)({
    timestamp: tsFormat,
    colorize: true,
    handleExceptions: true
  }))
}

module.exports = logger

I am also using Express and in my error handling middleware, I have this code:

const logger = require('../config/winston')
function (err, req, res, next) {
    console.log(err)
    logger.error(err)
    res.status(500).send({ error: 'Please try again later.' })
}

The problem is that when an error occurs all winston logs is:

{"level":"error"}

While the good old console.log() displays:

TypeError: Cannot read property 'filename' of undefined
    at router.post (/Users/balazsvincze/Desktop/testapi/app/routes/upload.js:16:33)
    at Layer.handle [as handle_request] (/Users/de/Desktop/testapi/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/balazsvincze/Desktop/testapi/node_modules/express/lib/router/route.js:137:13)
    at Immediate.<anonymous> (/Users/balazsvincze/Desktop/testapi/node_modules/multer/lib/make-middleware.js:53:37)
    at runCallback (timers.js:814:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5)

How do I get winston to log something like this including the stack trace?

Many thanks!

EDIT: If I change the line logger.error(err) to logger.error(err.message), at least I get this:

{"message":"Cannot read property 'filename' of undefined","level":"error"}

Still very far off from what I am after.

Answer 1

I think what you're missing is format.errors({ stack: true }) in winston.createLogger.

const logger = winston.createLogger({
  level: 'debug',
  format: format.combine(
    format.errors({ stack: true }),
    print,
  ),
  transports: [new transports.Console()],
});

See this GitHub thread for more information.

The reason this is happening is because the interesting Error object properties, like .stack, are non-enumerable. Some functions check if the their parameters are Error instances, like console.error, and other functions ignore all non-enumerable properties, like winston.<log-level> and JSON.stringify.

> console.error(new Error('foo'))
Error: foo
    at repl:1:15
    at Script.runInThisContext (vm.js:124:20)
    ...(abbr)

> JSON.stringify(new Error('foo'))
'{}'

All that said, it's horrible usability to have an error logger essentially ignore errors... I just lost too much time to this.

Answer 2

A quick and dirty way would be to log err.stack:

logger.error(err.stack);

A more elaborate method would be to implement a custom format specifically for Error instances. There's some example code on how to implement that in this Github issue.

Answer 3

Using format.

const { combine, timestamp, label, printf } = winston.format;
const myFormat = printf(info => {
    if(info instanceof Error) {
        return `${info.timestamp} [${info.label}] ${info.level}: ${info.message} ${info.stack}`;
    }
    return `${info.timestamp} [${info.label}] ${info.level}: ${info.message}`;
});
winston.createLogger({
    level: "info",
    format: combine(
        winston.format.splat(),
        label({ label: filename}),
        timestamp(),
        myFormat,
    ),
    transports: [
    //
    // - Write to all logs with level `info` and below to `combined.log`
    // - Write all logs error (and below) to `error.log`.
    //
        new winston.transports.File({ filename: path.join(os.tmpdir(), "test", "test.log"), level: "info" }),
    ],
});

Answer 4

If you are using nodejs and having trouble with the rejection handlers, I wrote a little module that you can use for reference.

You have to make sure that when you perform the Array De-structuring for format, that you include 'errors'.

const { combine, timestamp, json, errors } = format;

Winston documentation states

The errors format allows you to pass in an instance of a JavaScript Error directly to the logger. It allows you to specify whether not to include the stack-trace.

const errorsFormat = errors({ stack: true })

The complete code below is for reference. It is a module that I am using to log some information to a file and some to a mysql database.

require('dotenv').config();
const {createLogger, transports, format} = require('winston');
const { combine, timestamp, json, errors } = format;
const winstonMysql = require('winston-mysql');
const logform  = require('logform');


const errorsFormat = errors({ stack: true })


const options_default = {
    host: 'localhost',
    user: process.env.MYSQL_USER,
    password: process.env.MYSQL_LOGIN,
    database: process.env.MYSQL_DATABASE,
    table: 'sys_logs_default'
};

const logger = createLogger({
    level: 'info',
    format: format.json(),
    defaultMeta: { service: 'user-service' },
    transports: [
        new transports.Console({
            format: combine(timestamp(), json(), errorsFormat)
        }),
        // or use: options_custom / options_json
        new winstonMysql(options_default),
    ],
    exceptionHandlers: [
    new transports.File({ filename: 'exception.log' }),
  ],
  rejectionHandlers: [
    new transports.File({ filename: 'rejections.log' }),
  ],
});



module.exports = logger;

Answer 5

I faced the same issue earlier, and I know it's a little but for people who are still looking for a solution can use utils-deep-clone package. Just addded a layer above Winston to handle error objects.

const winston = require('winston')
const { toJSON } = require('utils-deep-clone')

const winstonLogger = new (winston.Logger)({
  transports: [
    new (winston.transports.Console)()
  ]
})

const log = (message, payload) => {
  try {
    payload = toJSON(payload)
    return winstonLogger.log('info', message, payload)
  } catch(error) {
    console.error('some error occured while consoling')
  }
}

const testObj = {
  error: new Error('It should work')
}

log('Testing few bugs', testObj)

The output will be:

info: Testing few bugs message=It should work, stack=Error: It should work
    at Object.<anonymous> (/Users/atishay/Desktop/utils-error-deep-log/logger.js:20:10)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3)
    at Function.Module.runMain (module.js:693:10)
    at startup (bootstrap_node.js:188:16)
    at bootstrap_node.js:609:3