Winston doesn't log/parse a caught error from an exception

[Infinitay]

Please tell us about your environment:

• winston version? 3.2.1
  • winston@2
  • winston@3
• node -v outputs: v12.8.1
• Operating System? (Windows, macOS, or Linux) Windows
• Language? (all | TypeScript X.X | ES6/7 | ES5 | Dart) ES6

What is the problem?

Winston doesn't seem to log exceptions, it doesn't seem to properly parse the error object.

const logger = winston.createLogger({
	level: 'info',
	format: winston.format.combine(winston.format.timestamp(), winston.format.json()),
	transports: [
		new winston.transports.File({
			filename: `./logs/error-${momentLogger.unix()}.log`,
			level: 'error'
		}),
		new winston.transports.File({
			filename: `./logs/debug-${momentLogger.unix()}.log`,
			level: 'debug'
		}),
		new winston.transports.File({
			filename: `./logs/combined-${momentLogger.unix()}.log`
		}),
		new winston.transports.Console({
			format: winston.format.simple()
		})
	]
});

try {
	logger.debug(folderIdRegex.exec(event.link)[1]);
} catch (ex) {
	console.log(ex); // Correctly prints
	logger.info(ex); // Undefined
	logger.debug(ex); // Undefined
	logger.error(ex); // Undefined
}

Further debugging using VSCode debugger

// Output
TypeError: Cannot read property '1' of null
    at .....google-sheets-scraping-testing.js:188:51
    at processTicksAndRejections (internal/process/task_queues.js:85:5)
info: undefined {"timestamp":"2020-03-04T19:58:36.251Z"}
error: undefined {"timestamp":"2020-03-04T19:58:36.251Z"}

// Here I started using the built-in debug terminal
ex // Input into debug console
> TypeError: Cannot read property '1' of null // Result of ex
logger.log(ex) // Input into debug console
info: undefined {"timestamp":"2020-03-04T20:11:13.924Z"} // Result of logger.log(ex)
> DerivedLogger {_readableState: ReadableState, readable: true, _events: Object, _eventsCount: 3, _maxListeners: undefined, …}  // Result of logger.log(ex)

What do you expect to happen instead?

I expect Winston to log the caught error from the try...catch block. If I instead pass in ex.message instead of just ex, it properly outputs. ex is defined all throughout the catch block, but Winston doesn't seem capable of parsing it for some reason.

Other information

Further more, if I return ex from within the catch block, and then surround everything within another catch block, it seems to properly output it. For more on this unusual behavior, please see a gist here of a support post I made on Discord before I realized this is a bug with Winston.

Additionally, I think this error also entails the issue another user has had for the past month over at #1758

[jleverenz]

I believe this may be due to inconsistent behavior between winston loggers and transports when applying formats. In winston-transport, part of the TransportStream _write function does this:

transformed = this.format.transform(Object.assign({}, info), this.format.options);

The relevant code in winston/logger.js looks like it does this:

this.push(this.format.transform(info, this.format.options));

Here's a simplified repro of the issue.

const winston = require('winston');

// First logger uses a format configured on logger
const logger1 = winston.createLogger({
  level: 'info',
  transports: new winston.transports.Console(),
  format: winston.format.simple()
});


// Second logger uses a format configured on transport
const logger2 = winston.createLogger({
  level: 'info',
  transports: new winston.transports.Console({
    format: winston.format.simple()
  })
});

logger1.info(new Error('err message'));   // logs expected 'err message'
logger2.info(new Error('err message'));   // logs 'undefined'

It's not clear to me which behavior should be preferred.

[Infinitay]

I wonder if this is also the same case when winston doesn't properly log some objects and prints it as [object Object] while other objects print without an issue

[c-vetter]

@jleverenz
Thank you, great find! Yielded a simple workaround to my problem, which was the same as #1758