[3.0.0] Error object is not parsed or printed

[chriswiggins]

Please tell us about your environment:

• winston version?
  • [-] winston@3.0.0-rc5
• node -v outputs: v8.11.1
• Operating System? (Windows, macOS, or Linux) macOS
• Language? (all | TypeScript X.X | ES6/7 | ES5 | Dart) All

What is the problem?

Logging a node Error object results in an empty message:

Example:

const winston = require('winston');
const { createLogger, format, transports } = winston;

const logger = createLogger({
  transports: [
    new transports.Console()
  ]
});

let err = new Error('this is a test');
logger.log({level: 'error', message: err});

Resulting output:

% node test.js
{"level":"error","message":{}}

Also:

logger.error(new Error('hello'))

Results in:

{"level":"error"}

What do you expect to happen instead?

I Expect the message key to have at least the error message included in it. If I try a custom formatter, info also doesn't have the error object in it so it must be stripped out somewhere?

Other information

Let me know how I can help - happy to flick a PR but I don't know my way around winston@3.0.0 enough yet to find it

[tiagonapoli]

This is still an issue? I'm still having problems with this:

const { createLogger, format, transports } = require('winston')

const { combine } = format

const errorFormatter = format((info) => {
  console.log(info)
  return info
})

const consoleTransport = new transports.Console({
  format: combine(errorFormatter()),
})

const logger = createLogger({
  transports: [
    consoleTransport,
  ],
})

try {
  throw new Error('Error message')
} catch(err) {
  logger.error(err) // info doesnt have the error object
  logger.error('', err) // info have the error object
}

[Speedkore]

This is still an issue? I'm still having problems with this:

const { createLogger, format, transports } = require('winston')

const { combine } = format

const errorFormatter = format((info) => {
  console.log(info)
  return info
})

const consoleTransport = new transports.Console({
  format: combine(errorFormatter()),
})

const logger = createLogger({
  transports: [
    consoleTransport,
  ],
})

try {
  throw new Error('Error message')
} catch(err) {
  logger.error(err) // info doesnt have the error object
  logger.error('', err) // info have the error object
}

same problem here...

after looking the source code, i can see what params it accepts:

interface LeveledLogMethod { (message: string, callback: LogCallback): Logger; (message: string, meta: any, callback: LogCallback): Logger; (message: string, ...meta: any[]): Logger; (infoObject: object): Logger; }

so if you pass the error object as first param, it will only take the message of the error because it only understands strings, and if you pass the error in the second param then you can access the stack trace in info.stack

btw i couldn't find this anywhere in the docs

[tiagonapoli]

I found two solutions, the first one is to use format.errors, mentioned on logform in the parent logger, then create a messageFormatter using format.printf and conditionally add a stack field extracted from info (format.errors({ stack: true}) will add that).

The other solution, that I preferred was hack into winston level loggers:

const addArgs = format((info) => {
  const args: any[] = info[Symbol.for('splat')]
  info.args = args ? [...args] : []
  return info
})

const messageFormatter = format.printf(info => {
  const { timestamp: timeString = '', message, args = [] } = info
  const formattedMsgWithArgs = util.formatWithOptions({ colors: true }, message, ...args)
  const msg = `${timeString} - ${info.level}: ${formattedMsgWithArgs}`
  return msg
})

const logger = createLogger({
  format: format.combine(
    addArgs(),
    format.timestamp({ format: 'HH:mm:ss.SSS' })
  ),

  transports: [
    new transports.Console({
      format: format.combine(format.colorize(), messageFormatter),
    }),
  ],
})

const levels = ['debug', 'info', 'error']
levels.forEach((level) => {
  logger[level] = (msg: any, ...remains: any) => {
    if(typeof msg != "string") {
      return logger.log(level, '', msg, ...remains)
    }

    logger.log(level, msg, ...remains)
  }  
})

It seems this way I can get error logging similar to console.log

[cjbarth]

I can verify that @tiagonapoli 's comment about how format.errors has to be on the parent logger is accurate. When I do something like this:

winston.loggers.add("default");
const log = winston.loggers.get("default");
/* get a `transportOptions` object and a `transportType` */
transportOptions.format = logform.format.combine(
  logform.format.errors({ stack: true }),
  logform.format.timestamp(),
  logform.format.printf(myFormatter)
);
log.add(new winston.transports[transportType](transportOptions);

Handling of Error object is does as if they were a string. However, if I do something like this:

winston.loggers.add("default");
const log = winston.loggers.get("default");
log.format = logform.format.errors({ stack: true });
/* get a `transportOptions` object and a `transportType` */
transportOptions.format = logform.format.combine(
  logform.format.timestamp(),
  logform.format.printf(myFormatter)
);
log.add(new winston.transports[transportType](transportOptions);

Handling of Error object works correctly.

It seems to me that the bug here is that there should be no difference in behavior.

[HRK44]

So this is still not fixed after 1year? Do I have to hack winston logger code to make it work?

[lunafoxfire]

Yeah this gave me enough headaches that Winston started to seem like way more trouble than it was worth for my relatively simple use case... I ended up just writing my own small logger class, and I'd recommend others do the same unless Winston provides something you REALLY need.

[TrejGun]

Guys, really? this is frustrating...

[terrisgit]

I’m not a committer but I’m probably correct to say that this is not going to be “fixed” because it’s not broken. Winston is worth using. You just need to configure it - the best advice for me is above at https://github.com/winstonjs/winston/issues/1338#issuecomment-506354691

[kasvith]

Not yet ?

[pkyeck]

Update: because there are still issues with this I have been doing the following for a while and its been working great

// Grab the default winston logger
const winston = require('winston');

const { format } = winston;
const { combine, timestamp } = format;

// Custom format function that will look for an error object and log out the stack and if 
// its not production, the error itself
const myFormat = format.printf((info) => {
  const { timestamp: tmsmp, level, message, error, ...rest } = info;
  let log = `${tmsmp} - ${level}:\t${message}`;
  // Only if there is an error
  if ( error ) {
    if ( error.stack) log = `${log}\n${error.stack}`;
    if (process.env.NODE_ENV !== 'production') log = `${log}\n${JSON.stringify(error, null, 2)}`;
  }
  // Check if rest is object
  if ( !( Object.keys(rest).length === 0 && rest.constructor === Object ) ) {
    log = `${log}\n${JSON.stringify(rest, null, 2)}`;
  }
  return log;
});

 winston.configure({
    transports: [
      new winston.transports.Console({
        level: 'debug',
        timestamp: true,
        handleExceptions: true
    }),
  ];
    format: combine(
      trace(),
      timestamp(),
      myFormat
    ),
  });

// Finally you log like this
logger.error('An error occurred!!!', { error } );

where does the trace come from?

[andretti1977]

No really, this is unacceptable for a logging library. Maintainer should simply put a well highlighted example on docs where it is shown how to log an error, even defining custom printf format and non json format and where you can log error with something like logger.error("something", err) and logger.error(err) Winston seemed to be great but this issue is incredibly unacceptable

[cardin]

This is my take on how to log errors using Winston. It's not unique, a lot of peeps above have working solutions based around the same concepts too.

Background I'm using @jsdevtools/ono to wrap arbitrary object types into custom errors, but regardless, this solution still seems to work fine on native node errors (e.g. fs eperm errors), and custom error classes.

Explanation Basically, I rely on format.errors({stack:true}) and format.metadata(). As mentioned by https://github.com/winstonjs/winston/issues/1338#issuecomment-532327143, this has to be in the parent formatter.

Metadata helps to shift all the error object's custom properties to info.metadata.

I wanted to print 3 types of information: the error message, the stacktrace, and the error object's properties. The error message was already plaintext. I pretty-printed the stack info.metadata.stack using the pretty-error module. For the error object's properties, I didn't want the stacktrace to appear again, so I cloned the object, and deleted the stacktrace property. I then pretty-printed the error object using fast-safe-stringify, which is the same stringify module that winston relies on.

    const lodash = require("lodash");
    const path = require("path");
    const winston = require("winston");
    const { default: stringify } = require("fast-safe-stringify");
    const logDir = "D:/temp/logs";

    // pretty formatting
    const PrettyError = require("pretty-error");
    const pe = new PrettyError();
    pe.withoutColors()
        .appendStyle({
            'pretty-error > trace':
            {
                display: 'inline'
            },
            'pretty-error > trace > item':
            {
                marginBottom: 0,
                bullet: '"*"'
            }
        })
        // @ts-ignore
        .alias(/.*[\\\/]CelebrityQuery/i, "<project>")
        .alias(/\[CelebrityQuery\][\\\/]?/i, "")
        .skip(/** @type {(_:any) => boolean} */ (traceline => {
            if (traceline && traceline.dir) {
                return traceline.dir.toString().startsWith("internal");
            }
            return false;
        }))
        .skipNodeFiles();

    const consoleFormat = winston.format.combine(
        winston.format.colorize(),
        winston.format.timestamp({
            format: 'DD MMM HH:mm:ss'
        }),
        winston.format.printf(info => {
            if (!lodash.isEmpty(info.metadata) && info.metadata.hasOwnProperty("stack")) {
                let dup = lodash.clone(info.metadata);
                delete dup.stack;
                const errBody = stringify(dup, undefined, 4);
                const stack = pe.render({ stack: info.metadata.stack });
                return `${info.timestamp} ${info.level} ${info.message}${errBody}\n${stack}`;
            } else if (lodash.isString(info.message)) {
                return `${info.timestamp} ${info.level} ${info.message}`;
            } else {
                return `${info.timestamp} ${info.level} ${stringify(info.message, undefined, 4)}`;
            }
        })
    );
    const logFormat = winston.format.combine(winston.format.timestamp(), winston.format.json());
    return winston.createLogger({
        level: 'debug',
        format: winston.format.combine(
            winston.format.errors({ stack: true }),
            winston.format.metadata()
        ),
        transports: [
            new winston.transports.Console({
                format: consoleFormat,
                level: 'info',
            }),
            new winston.transports.File({
                filename: path.join(logDir, "stdout.json"),
                format: logFormat,
                level: 'debug',
                maxsize: 1000000,
                tailable: true
            })
        ]
    });

PS: I also find the solution mentioned in https://github.com/winstonjs/winston/issues/1338#issuecomment-506354691 to be a good alternative. I.e. using logger.warn("Oh no", { error: new Error() }), then referencing info.error in your custom formatter.

[will093]

@tiagonapoli your solution about using format.errors on the parent logger worked for me:

const logger = createLogger({
  transports: loggerTransports,
});

logger.format = format.errors({ stack: true });

It is fairly painful configuring this logger... Could it not just behave like console.log out the box?

[OBrown92]

@will093 same here. Been on that issue again and don't get it why my console.log is nice and clean and winston format is shit.

[TeamDman]

My 2¢

// Enable console logging when not in production
if (process.env.NODE_ENV !== "production") {
    logger.add(new transports.Console({
        format: format.combine(
            format.colorize(),
            format.simple(),
            format.printf(info => {
                const { level, ...rest } = info;
                let rtn = "";
                // rtn += info.timestamp;
                rtn += "[" + info.level + "] ";
                if (rest.stack) {
                    rtn += rest.message.replace(rest.stack.split("\n")[0].substr(7),"");
                    rtn += "\n";
                    rtn += "[" + level + "] ";
                    rtn += rest.stack.replace(/\n/g, `\n[${level}]\t`);
                } else {
                    rtn += rest.message;
                }
                return rtn;
            }),
        ),
    }));
}

Example for logger.error("Error during schema stitching", e);

[wcarss]

using @tiagonapoli and @will093's solution of adding it to just the parent seems to be the easiest way to support directly logging errors and still logging messages -- here's a full example of a minimal setup w/ timestamps:

const createLogger = () => {
  const logFormatter = winston.format.printf(info => {
    let { timestamp, level, code, stack, message } = info;

    // print out http error code w/ a space if we have one
    code = code ? ` ${code}` : '';
    // print the stack if we have it, message otherwise.
    message = stack || message;

    return `${timestamp} ${level}${code}: ${message}`;
  });

  return winston.createLogger({
    level: 'info',
    // put the errors formatter in the parent for some reason, only needed there:
    format: winston.format.errors({ stack: true }),
    transports: new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp(),
        logFormatter
      ),
  });
};

works with a stack when called with an error like: logger.error(error), works with a string when called like logger.error('a regular message'), looks like this in my logs:

2020-09-23T20:05:30.30Z info: Feathers application started on http://localhost:3030
2020-09-23T20:05:35.40Z info: job queue - redis ready, registering queues...
2020-09-23T20:05:40.25Z error 401: NotAuthenticated: invalid authorization header
    at new NotAuthenticated (/path/to/server/node_modules/@feathersjs/errors/lib/index.js:94:17)
    at Object.<anonymous> (/path/to/server/src/hooks/authentication.js:123:456)
    at /path/to/server/node_modules/@feathersjs/commons/lib/hooks.js:116:46

this does not attempt to solve winston's logger.error('message here', error)-incompatibility w/ console.log, which @tiagonapoli's more involved solution seems to do.

Also, if you like json logs you can drop the logFormatter here and use winston.format.json() in its place, which will still include the stack -- but it isn't pretty.

[rathernetwork]

Update: because there are still issues with this I have been doing the following for a while and its been working great

// Grab the default winston logger
const winston = require('winston');

const { format } = winston;
const { combine, timestamp } = format;

// Custom format function that will look for an error object and log out the stack and if 
// its not production, the error itself
const myFormat = format.printf((info) => {
  const { timestamp: tmsmp, level, message, error, ...rest } = info;
  let log = `${tmsmp} - ${level}:\t${message}`;
  // Only if there is an error
  if ( error ) {
    if ( error.stack) log = `${log}\n${error.stack}`;
    if (process.env.NODE_ENV !== 'production') log = `${log}\n${JSON.stringify(error, null, 2)}`;
  }
  // Check if rest is object
  if ( !( Object.keys(rest).length === 0 && rest.constructor === Object ) ) {
    log = `${log}\n${JSON.stringify(rest, null, 2)}`;
  }
  return log;
});

 winston.configure({
    transports: [
      new winston.transports.Console({
        level: 'debug',
        timestamp: true,
        handleExceptions: true
    }),
  ];
    format: combine(
      trace(),
      timestamp(),
      myFormat
    ),
  });

// Finally you log like this
logger.error('An error occurred!!!', { error } );

where is trace() definition?

[rathernetwork]

Update: because there are still issues with this I have been doing the following for a while and its been working great

// Grab the default winston logger
const winston = require('winston');

const { format } = winston;
const { combine, timestamp } = format;

// Custom format function that will look for an error object and log out the stack and if 
// its not production, the error itself
const myFormat = format.printf((info) => {
  const { timestamp: tmsmp, level, message, error, ...rest } = info;
  let log = `${tmsmp} - ${level}:\t${message}`;
  // Only if there is an error
  if ( error ) {
    if ( error.stack) log = `${log}\n${error.stack}`;
    if (process.env.NODE_ENV !== 'production') log = `${log}\n${JSON.stringify(error, null, 2)}`;
  }
  // Check if rest is object
  if ( !( Object.keys(rest).length === 0 && rest.constructor === Object ) ) {
    log = `${log}\n${JSON.stringify(rest, null, 2)}`;
  }
  return log;
});

 winston.configure({
    transports: [
      new winston.transports.Console({
        level: 'debug',
        timestamp: true,
        handleExceptions: true
    }),
  ];
    format: combine(
      trace(),
      timestamp(),
      myFormat
    ),
  });

// Finally you log like this
logger.error('An error occurred!!!', { error } );

where does the trace come from?

any answer on this?

[hpl002]

quick and dirty, but lacking proper formatting on errors. Still better than nothing..

const winston = require('winston');

const logger = winston.createLogger({
  level: 'debug',
  transports: [
    new winston.transports.File({ filename: 'error.log', level: 'error' }),
    new winston.transports.File({ filename: 'combined.log' }),
    new winston.transports.Console({ format: winston.format.json() })
  ],
});

logger.format = winston.format.combine(
  winston.format.errors({ stack: true }),
)

[alolis]

I switched to pino and never looked back instead of wasting so much time trying to make something work that should have been working out of the box since it's the most common use case.

[b4ti1c]

To leave my bits I have put together the following winston configuration to accommodate both errors and multiple parameters in the logs.

const winston = require('winston');
const util = require('util');

const enumerateErrorFormat = winston.format(info => {
    if (info.message instanceof Error) {
      info.message = Object.assign({
        message: info.message.message,
        stack: info.message.stack
      }, info.message);
    }

    if (info instanceof Error) {
      return Object.assign({
        message: info.message,
        stack: info.stack
      }, info);
    }

    return info;
  });

  const logger = winston.createLogger({
    level: 'silly',
    format: winston.format.combine(
        enumerateErrorFormat(),
        {
            transform: (info) => {
                const args = [info.message, ...(info[Symbol.for('splat')] || [])];
                info.message = args;

                const msg = args.map(arg => {
                    if (typeof arg == 'object')
                        return util.inspect(arg, {compact: true, depth: Infinity});
                    return arg;
                }).join(' ');

                info[Symbol.for('message')] = `${info[Symbol.for('level')]}: ${msg}${info.stack ? ' ' + info.stack : ''}`;

                return info;
            }
        }
    )
});

logger.add(new winston.transports.Console())
logger.add(new winston.transports.File({filename: './logs.txt.'}));

logger.silly('hello silly', 1234, 'my condolence', {ahmet:1, meh:[{ahmet:1, meh:'alo'},{ahmet:1, meh:'alo'}]}, [{ahmet:1, meh:'alo'},{ahmet:1, meh:'alo'}]);
logger.debug('hello debug', () => console.log(1+2));
logger.info('hello info');
logger.warn('hello warn');
logger.error('hello error');
logger.error(new Error('error 1'), 123, new Error('error 2'));

[MatthiasGwiozda]

You can define a simple ConsoleLogger to show complete Error - objects. It doesn't fix the weird behavior of the inbuilt winston - logger but it does exactly what console.log would do because we use it in the ConsoleLogger.

IMHO the amount of code to get the result is okay for the purpose.

const { createLogger } = require('winston');
const Transport = require('winston-transport');

/**
 * The simple "custom" console - logger,
 * which logs the complete Error - object.
 */
class ConsoleLogger extends Transport {
    constructor(opts) {
        super(opts);
    }

    log(info, callback) {
        console.log(info);
        callback();
    }
};

const logger = createLogger({
    transports: [
        // use the ConsoleLogger instead of the winston "cOnSoLEtRaNSpOrt"
        new ConsoleLogger()
    ]
});

let err = new Error('this is a test');
logger.log({ level: 'error', message: err });

[wbt]

It appears that the original issue this thread was supposed to be about was solved a while ago and it continues on in closed state because a second issue brought up still requires a workaround. This comment from a project founder may shed some light on why that is likely to remain the case for a while.

[mayeaux]

Doesn't work

[teadrinker2015]

I searched for node logger in youtube and can only find this package. All I want is just log to file (may be a little prettify), otherwise I have to implement myself. Could someone suggest me some user-friendly, or work out-of-box logging package?

[cyrilchapon]

See my comment here : https://github.com/winstonjs/logform/issues/100

This is an internal bug inside base Transport class, that needs to be adressed.

[chuckbakwi]

Long running issue given the above answers. 1) is this FIXED in the latest release? If fixed, specify release please. 2) if not fixed, then can someone summarize maybe the TOP TWO workaround solutions with some explanation of what they do and and what they do NOT support? There are other alternatives out there, but I invested my time into getting this to work and just need this last piece of the puzzle.