Skip to content

useCallStack and Logging an Error object #1268

@ZachHaber

Description

@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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    enhancementNew feature or request

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions