winstonjs/logform

Error formats incorrectly

eurostar-fennec-cooper opened this issue · 10 comments

The error formatter example describes that it will log:

// Error: Oh no!
//     at repl:1:13
//     at ContextifyScript.Script.runInThisContext (vm.js:50:33)
//     at REPLServer.defaultEval (repl.js:240:29)
//     at bound (domain.js:301:14)
//     at REPLServer.runBound [as eval] (domain.js:314:12)
//     at REPLServer.onLine (repl.js:468:10)
//     at emitOne (events.js:121:20)
//     at REPLServer.emit (events.js:211:7)
//     at REPLServer.Interface._onLine (readline.js:282:10)
//     at REPLServer.Interface._line (readline.js:631:8)

Whereas it really logs:
{ level: undefined, message: 'Oh no!', stack: 'Error: Oh no!\n at Object.<anonymous> (C:\\Users\\Fennec\\Documents\\errlog.js:6:37)\n at Module._compile (internal/modules/cjs/loader.js:688:30)\n at Object.Module._extensions..js (internal/modules/cjs/loader.js:699:10)\n at Module.load (internal/modules/cjs/loader.js:598:32)\n at tryModuleLoad (internal/modules/cjs/loader.js:537:12)\n at Function.Module._load (internal/modules/cjs/loader.js:529:3)\n at Function.Module.runMain (internal/modules/cjs/loader.js:741:12)\n at startup (internal/bootstrap/node.js:285:19)\n at bootstrapNodeJSCore (internal/bootstrap/node.js:739:3)', [Symbol(level)]: undefined, [Symbol(message)]: 'Oh no!' }

Same issue here.

Using t he exact code from the docs:

const { format } = require('logform');
const { errors } = format;
 
const errorsFormat = errors({ stack: true })
 
const info = errorsFormat.transform(new Error('Oh no!'));
 
console.log(info);

you get:

module.exports = format((einfo, { stack }) => {
                                  ^

TypeError: Cannot destructure property 'stack' of 'undefined' as it is undefined.
    at Format.transform (/Users/user/Sites/project/node_modules/logform/errors.js:14:35)
    at Object.<anonymous> (/Users/user/Sites/project/src/logger.js:104:27)
    at Module._compile (internal/modules/cjs/loader.js:1201:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1221:10)
    at Module.load (internal/modules/cjs/loader.js:1050:32)
    at Function.Module._load (internal/modules/cjs/loader.js:938:14)
    at Module.require (internal/modules/cjs/loader.js:1090:19)
    at require (internal/modules/cjs/helpers.js:75:18)
    at Object.<anonymous> (/Users/user/Sites/project/index.js:4:16)
    at Module._compile (internal/modules/cjs/loader.js:1201:30)

Yeah same here. It seems that the stack is JSON.strigified and thus escapes newline characters. In winston I tried using a custom format instead (with format.printf) but it becomes a mess when you want to include errors and metadata.

The other issue is that logging without a message as the first argument supresses both the error's message and the stack. So you(in winston) with logger.error('message', new Error('with message')) it works but logger.error(new Error('without message')) does not.

yeah, same complaint, doing this with splat is nicer :/

      log.error('%O', new Error('my error'));

Ran into the same issue just now.

With winston 3.3.3, the following does not work as expected:

const winston = require('winston')

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console({
      format: winston.format.errors(),
    })
  ]
})

logger.error(new Error('I am Error')) // Prints `{"level":"error"}`

Looks like the error properties get dropped when doing Object.assign({}, info) in winston-transport/index.js, line 91

There's a workaround: Apply the errors format before passing the log message to the transports:

const winston = require('winston')

const logger = winston.createLogger({
  format: winston.format.errors(),
  transports: [
    new winston.transports.Console()
  ]
})

logger.error(new Error('I am Error')) // Prints `I am Error`

Same when running the example :

const {format} = require('logform');
const {errors} = format;

const errorsFormat = errors({stack: true});

const info = errorsFormat.transform(new Error('Oh no!'));

console.log(info);
// Error: Oh no!
//     at repl:1:13
//     at ContextifyScript.Script.runInThisContext (vm.js:50:33)
//     at REPLServer.defaultEval (repl.js:240:29)
//     at bound (domain.js:301:14)
//     at REPLServer.runBound [as eval] (domain.js:314:12)
//     at REPLServer.onLine (repl.js:468:10)
//     at emitOne (events.js:121:20)
//     at REPLServer.emit (events.js:211:7)
//     at REPLServer.Interface._onLine (readline.js:282:10)
//     at REPLServer.Interface._line (readline.js:631:8)

Error:

module.exports = format((einfo, { stack }) => {
                                  ^

TypeError: Cannot destructure property 'stack' of 'undefined' as it is undefined.
    at Format.transform (/home/aduponchel/royalcanin/node_modules/logform/errors.js:14:35)
    at Object.<anonymous> (/home/aduponchel/royalcanin/demo/winston.js:7:27)
    at Module._compile (internal/modules/cjs/loader.js:1072:14)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1101:10)
    at Module.load (internal/modules/cjs/loader.js:937:32)
    at Function.Module._load (internal/modules/cjs/loader.js:778:12)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:76:12)
    at internal/main/run_main_module.js:17:47

Node v14.17.4
NPM 6.14.14
Logform 2.2.0

This has to be addressed; as there is currently no solution at all to correctly handle logger.error(anyErrorInstance).

I digged into it; by first copy pasting the logform.format.errors code

const errFormat = Logform.format((einfo, { stack, cause }) => {
  console.log('IM HERE')
  console.log(einfo)
  if (einfo instanceof Error) {
    const info = Object.assign({}, einfo, {
      level: einfo.level,
      [LEVEL]: einfo[LEVEL] || einfo.level,
      message: einfo.message,
      [MESSAGE]: einfo[MESSAGE] || einfo.message,
    })

    if (stack) info.stack = einfo.stack
    if (cause) info.cause = einfo.cause
    return info
  }

  if (!(einfo.message instanceof Error)) return einfo

  // Assign all enumerable properties and the
  // message property from the error provided.
  const err = einfo.message
  Object.assign(einfo, err)
  einfo.message = err.message
  einfo[MESSAGE] = err.message

  // Assign the stack and/or cause if requested.
  if (stack) einfo.stack = err.stack
  if (cause) einfo.cause = err.cause
  return einfo
})

This is a total nonsense; as (thanks to @opitzmic )

the error properties get dropped when doing Object.assign({}, info) in winston-transport/index.js, line 91

As a consequence, einfo has no chance to be an Error instance by any means; and leads to a completely broken logic.


Since it's done at the transport level; there is basically nothing we can do inside formatters that could workaround this.

Any updates?

DABH commented

Open to PRs that the community feels solves things in the right way here (whether at the Winston, Winston-transport, or logform level). I don’t have much time to investigate this but if someone made a well-tested / backwards-compatible PR that articulated why it addressed these issues, it’d be easy for me to approve and do a release. (Or if there’s no backwards compatible way to do this - could fix via a major version bump to winston…)