search

winstonjs / winston

A logger for just about everything.
http://github.com/winstonjs/winston
MIT License
22.81k stars 1.81k forks source link

Exception stack duplicated for unhandled exceptions #1713

Open cjbarth opened 5 years ago

cjbarth commented 5 years ago

Please tell us about your environment:

What is the problem?

When an unhandled exception is logged, the stack of the exception is output twice in the log message, once with the property stack, and the other time concatenated with the message of the exception. And the concatenation doesn't work very well either.

const winston = require("winston");
const log = winston.createLogger({
  exitOnError: false,
  level: "error",
  transports: [
    new winston.transports.Console({
      handleExceptions: true
    })
  ],
});

log.log("error", new Error("Logged error w/o message."));
console.log("\n");
log.error("Logged error message", new Error("Logged error w/message."));
console.log("\n");

try {
  throw new Error("Thrown error w/o message.");
} catch (e) {
  log.error(e);
  console.log("\n");
}

try {
  throw new Error("Thrown error w/message.");
} catch (e) {
  log.error("Thrown error message", e);
  console.log("\n");
}

throw new Error("Unhandled exception");
console.log("\n");

I get:

{"level":"error","message":"Logged error w/o message."}

{"level":"error","message":"Logged error messageLogged error w/message.","stack":"Error: Logged error w/message.\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:18:35)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}

{"level":"error","message":"Thrown error w/o message."}

{"level":"error","message":"Thrown error messageThrown error w/message.","stack":"Error: Thrown error w/message.\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:29:8)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}

{"error":{},"level":"error","message":"uncaughtException: Unhandled exception\nError: Unhandled exception\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:35:7)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)","stack":"Error: Unhandled exception\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:35:7)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)","exception":true,"date":"Fri Oct 04 2019 12:44:54 GMT-0400 (Eastern Daylight Time)","process":{"pid":45720,"uid":627336462,"gid":1367992244,"cwd":"/Users/cjbarth/node_scratch","execPath":"/usr/local/Cellar/node@10/10.16.0/bin/node","version":"v10.16.0","argv":["/usr/local/Cellar/node@10/10.16.0/bin/node","/Users/cjbarth/node_scratch/scratch.js"],"memoryUsage":{"rss":31973376,"heapTotal":12304384,"heapUsed":7709320,"external":196348}},"os":{"loadavg":[2.01220703125,2.03173828125,2.19189453125],"uptime":384286},"trace":[{"column":7,"file":"/Users/cjbarth/node_scratch/scratch.js","function":null,"line":35,"method":null,"native":false},{"column":30,"file":"internal/modules/cjs/loader.js","function":"Module._compile","line":776,"method":"_compile","native":false},{"column":10,"file":"internal/modules/cjs/loader.js","function":"Module._extensions..js","line":787,"method":".js","native":false},{"column":32,"file":"internal/modules/cjs/loader.js","function":"Module.load","line":653,"method":"load","native":false},{"column":12,"file":"internal/modules/cjs/loader.js","function":"tryModuleLoad","line":593,"method":null,"native":false},{"column":3,"file":"internal/modules/cjs/loader.js","function":"Module._load","line":585,"method":"_load","native":false},{"column":12,"file":"internal/modules/cjs/loader.js","function":"Module.runMain","line":829,"method":"runMain","native":false},{"column":19,"file":"internal/bootstrap/node.js","function":"startup","line":283,"method":null,"native":false},{"column":3,"file":"internal/bootstrap/node.js","function":"bootstrapNodeJSCore","line":622,"method":null,"native":false}]}

What do you expect to happen instead?

The stack, especially since it is so long, shouldn't be output twice. There is no way to alter or defeat this incorrect behavior such that logged unhandled exceptions look like logged handled exceptions, both of which are logging the same Error object.

I expect something like this:

{"level":"error","message":"Logged error w/o message."}

{"level":"error","message":"Logged error messageLogged error w/message.","stack":"Error: Logged error w/message.\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:18:35)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}

{"level":"error","message":"Thrown error w/o message."}

{"level":"error","message":"Thrown error messageThrown error w/message.","stack":"Error: Thrown error w/message.\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:29:8)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)"}

{"error":{},"level":"error","message":"uncaughtException: Unhandled exception","stack":"Error: Unhandled exception\n    at Object.<anonymous> (/Users/cjbarth/node_scratch/scratch.js:35:7)\n    at Module._compile (internal/modules/cjs/loader.js:776:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)\n    at Module.load (internal/modules/cjs/loader.js:653:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)","exception":true,"date":"Fri Oct 04 2019 12:44:54 GMT-0400 (Eastern Daylight Time)","process":{"pid":45720,"uid":627336462,"gid":1367992244,"cwd":"/Users/cjbarth/node_scratch","execPath":"/usr/local/Cellar/node@10/10.16.0/bin/node","version":"v10.16.0","argv":["/usr/local/Cellar/node@10/10.16.0/bin/node","/Users/cjbarth/node_scratch/scratch.js"],"memoryUsage":{"rss":31973376,"heapTotal":12304384,"heapUsed":7709320,"external":196348}},"os":{"loadavg":[2.01220703125,2.03173828125,2.19189453125],"uptime":384286},"trace":[{"column":7,"file":"/Users/cjbarth/node_scratch/scratch.js","function":null,"line":35,"method":null,"native":false},{"column":30,"file":"internal/modules/cjs/loader.js","function":"Module._compile","line":776,"method":"_compile","native":false},{"column":10,"file":"internal/modules/cjs/loader.js","function":"Module._extensions..js","line":787,"method":".js","native":false},{"column":32,"file":"internal/modules/cjs/loader.js","function":"Module.load","line":653,"method":"load","native":false},{"column":12,"file":"internal/modules/cjs/loader.js","function":"tryModuleLoad","line":593,"method":null,"native":false},{"column":3,"file":"internal/modules/cjs/loader.js","function":"Module._load","line":585,"method":"_load","native":false},{"column":12,"file":"internal/modules/cjs/loader.js","function":"Module.runMain","line":829,"method":"runMain","native":false},{"column":19,"file":"internal/bootstrap/node.js","function":"startup","line":283,"method":null,"native":false},{"column":3,"file":"internal/bootstrap/node.js","function":"bootstrapNodeJSCore","line":622,"method":null,"native":false}]}

Other information

The entire problem can be corrected by changing https://github.com/winstonjs/winston/blob/master/lib/winston/exception-handler.js#L85 to:

      message: `uncaughtException: ${(message || '(no error message)')}`,
      stack: err.stack || '  No stack trace',

The other problem of message concatenation being done with out any sort of separator, making the resulting message very hard to read would be nice to fix too (perhaps with a linefeed), but isn't my primary focus with this issue.

If a PR is desired for this fix, I'll be happy to create one.

dmitry537 commented 1 year ago

Faced the same problem