useCallStack and Logging an Error object

[ZachHaber]

I have a library that allows setting a global function to log errors related to it (Oracle error's are notoriously unhelpful by themselves). https://github.com/abbvie-external/oracle-helpers#options

The issue is that the useCallStack option always creates a new Error, which means that even if you are logging an Error object in the data, the line numbers would indicate the location that you set the global logger rather than the location of the Error that you are logging.

log4js.configure({
  appenders: {
    out: {
      type: 'stdout',
      layout: {
        type: 'pattern',
        pattern: '%%x:%n%x{error}%n%%s:%n%s',
        tokens: {
          error: (event) => event.data[0].stack,
        },
      },
    },
  },
  categories: {
    default: { appenders: ['out'], level: 'info', enableCallStack: true },
  },
});

const logger = log4js.getLogger('sql');

setSqlErrorLogger((error) => {
  logger.error(error);
});

try {
  await getSql(dbConfig, `select * from notExtant`);
} catch (error) {}

The error would be thrown from the Oracle helpers package, while logging would happen in a very different stack trace (index.js).

stack trace for the logged Error %x{error} in this example:

Error: ORA-00942: table or view does not exist
    at async getSqlInner (C:\code\ts-hapi-tmplt\node_modules\oracle-helpers\build\main\lib\sqlHelpers.js:73:21)       
    at async getSql (C:\code\ts-hapi-tmplt\node_modules\oracle-helpers\build\main\lib\sqlHelpers.js:41:16)
    at async file:///C:/code/ts-hapi-tmplt/src/test.js:51:3

vs stack trace from the logger %s

    at file:///C:/code/ts-hapi-tmplt/src/test.js:47:10
    at log (C:\code\ts-hapi-tmplt\node_modules\oracle-helpers\build\main\lib\sqlHelpers.js:24:53)
    at getSqlInner (C:\code\ts-hapi-tmplt\node_modules\oracle-helpers\build\main\lib\sqlHelpers.js:76:9)
    at async getSql (C:\code\ts-hapi-tmplt\node_modules\oracle-helpers\build\main\lib\sqlHelpers.js:41:16)
    at async file:///C:/code/ts-hapi-tmplt/src/test.js:51:3

While they both get back to the same line in the end, due to how I have them set up, I can definitely imagine losing out on context due to this difference, and it's fewer lines of the stack trace to ignore using the setParseCallStackFunction function.

Assuming we only make this difference if the first argument in the log event is an Error: The try/catch is for a failsafe in case whatever generated the error messed with the stack trace or was missing due to callbacks/async code.

_log(level, data) {
  debug(`sending log data (${level}) to appenders`);
  let callstack = undefined;
  if(this.useCallStack){
    try{
      if(data[0] instanceof Error){
        callstack = this.parseCallStack(data[0], 1);
      }
    }catch(_err){}
    callstack = callstack || this.parseCallStack(new Error());
  }
  const loggingEvent = new LoggingEvent(
    this.category,
    level,
    data,
    this.context,
    callstack
  );
  clustering.send(loggingEvent);
}

It might also be worth allowing to use a number for setParseCallStackFunction to use the default one but with extra (or fewer down to 0) lines to skip.

[lamweili]

PRs are always welcome! :hugs:

Do include the behaviour before and after changes in your PR for the benefit of whoever might be reading it.