Trace and optional formatting

tegefaulkes commented 2 years ago

Description

This adds a trace key to the formatter. this when added to the end of the format will print out a error like stack trace in the log message. Note that this breaks the one message per line log convention and should only be used for debugging.

This PR also adds an optional format override to a log message. So now you can change the log formmat on a per-message basis. You can do this by doing.

logger.info('message', formatter.format`new format ${formatter.msg}${formatter.trace}`);

Issues Fixed

Fixes #4

Tasks

[x] 1. add a trace key to the formatter.
[x] 2. add an optional format override to each logger method.

Final checklist

[x] Domain specific tests
[x] Full tests
[x] Updated inline-comment documentation
[x] Lint fixed
[x] Squash and rebased
[x] Sanity check the final build

CMCDragonkai commented 2 years ago

@emmacasolin great this will be useful for debugging spurious logs now!

emmacasolin commented 2 years ago

I don't think the trace symbol is working properly.

I have these two lines to see what's happening at this point in the code:

this.logger.info('', formatting.format`${formatting.keys}:${formatting.trace}`);
this.logger.info(new Error().stack!);

And the output from these lines is:

DMZ test.agent1:polykey.PolykeyAgent.Proxy.ConnectionReverse 10.0.0.2:55552:
DMZ test.agent1:    at constructor_.start (/home/emma/Projects/js-polykey/src/network/ConnectionReverse.ts:174:19)
DMZ test.agent1:    at async /home/emma/Projects/js-polykey/node_modules/@matrixai/async-init/src/StartStop.ts:56:24
DMZ test.agent1:INFO:polykey.PolykeyAgent.Proxy.ConnectionReverse 10.0.0.2:55552:Error
DMZ test.agent1:    at constructor_.start (/home/emma/Projects/js-polykey/src/network/ConnectionReverse.ts:175:24)
DMZ test.agent1:    at async /home/emma/Projects/js-polykey/node_modules/@matrixai/async-init/src/StartStop.ts:56:24
DMZ test.agent1:    at async withF (/home/emma/Projects/js-polykey/node_modules/@matrixai/resources/src/utils.ts:24:12)
DMZ test.agent1:    at async constructor_.establishConnectionReverse (/home/emma/Projects/js-polykey/src/network/Proxy.ts:745:5)
DMZ test.agent1:    at async /home/emma/Projects/js-polykey/src/network/Proxy.ts:620:9
DMZ test.agent1:    at async withF (/home/emma/Projects/js-polykey/node_modules/@matrixai/resources/src/utils.ts:24:12)
DMZ test.agent1:    at async constructor_.openConnectionReverse (/home/emma/Projects/js-polykey/src/network/Proxy.ts:618:5)
DMZ test.agent1:    at async withF (/home/emma/Projects/js-polykey/node_modules/@matrixai/resources/src/utils.ts:24:12)
DMZ test.agent1:    at async constructor_.holePunchReverse (/home/emma/Projects/js-polykey/src/nodes/NodeConnectionManager.ts:367:5)
DMZ test.agent1:    at async /home/emma/Projects/js-polykey/src/agent/service/nodesHolePunchMessageSend.ts:66:11

The trace is a lot shorter in the log using the trace symbol, so it doesn't really help much when debugging.

CMCDragonkai commented 2 years ago

@tegefaulkes there was a recent change to get rid of the first 2 lines of the trace, I think maybe you reversed the filter.

tegefaulkes commented 2 years ago

Weird. It doesn't get rid of the first 2 lines, it removes about 6 of them. It's different if you set the format for the logger of use the override method so I had to filter for an expected line. since it's showing the trace starting from the same point I think that's working. But if the trace is limited to 10 line and we cut off most of them then maybe that's why we're getting a very short trace there. I'll look into it.

You can check this quickly by monkey patching out the filter logic to show the full trace. I should be in the formatting.js file.

tegefaulkes commented 2 years ago

Yeah, by default the stack trace is limited to 10 lines. since we're cutting them off we only get 2 lines at the end in this case. There is a fix for this but it's really not ideal. You can change how many lines you get in the stack trace with Error.stackTraceLimit = 100; but it will affect all errors. Also it's not standard so I can't say it will work consistently or at all on all platforms.

I can quicky set the stackTraceLimit to stackTraceLimit + 8 and then set it back after getting the stack. But we can have a concurrency issue where other errors feel the affects of this. But over all the consequence of this is minimal. We may not even notice it.

In that same vein you can just set the stackTraceLimit whenever so for debugging you can just change it if you need more lines.

CMCDragonkai commented 2 years ago

Using Error.captureStackTrace we can actually do this a little more elegantly:

class C {

  public log () {
    return format();
  }

  public info () {
    return this.log();
  }

}

function format () {
  const e = {} as { stack: string };
  Error.captureStackTrace(e, C.prototype.log);
  return e.stack;
}

async function main () {
  const c = new C;
  console.log(c.info());
}

main();

The resulting function assigns the stack string to the arbitrary object e.

The C.prototype.log can be Logger.prototype.log.

This still gives us:

Error
    at C.info (/home/cmcdragonkai/Projects/js-db/test-errors.ts:8:17)
    at main (/home/cmcdragonkai/Projects/js-db/test-errors.ts:21:17)
    at Object.<anonymous> (/home/cmcdragonkai/Projects/js-db/test-errors.ts:24:1)
    at Module._compile (node:internal/modules/cjs/loader:1103:14)
    at Module.m._compile (/home/cmcdragonkai/Projects/js-db/node_modules/ts-node/src/index.ts:1371:23)
    at Module._extensions..js (node:internal/modules/cjs/loader:1157:10)
    at Object.require.extensions.<computed> [as .ts] (/home/cmcdragonkai/Projects/js-db/node_modules/ts-node/src/index.ts:1374:12)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)

In which case you would need to splice out the remaining C.info. If you do this, in order maintain the default stack limit, increment the Error.stackTraceLimit, then decrement it afterwards.

Resulting in:

class C {

  public log () {
    return format();
  }

  public info () {
    return this.log();
  }

}

function format () {
  const e = {} as { stack: string };
  Error.stackTraceLimit++;
  Error.captureStackTrace(e, C.prototype.log);
  Error.stackTraceLimit--;
  return e.stack;
}

async function main () {
  const c = new C;
  console.log(c.info());
}

main();

This makes use of V8 API (https://v8.dev/docs/stack-trace-api). In fact both are not Ecmascript standards atm. Which means it is limited to nodejs and chrome based browsers.

If we want to make js-loggers generic, the trace keyword would have to be somewhat limited to v8 based systems here. In which case if captureStackTrace or stackTraceLimit properties do not exist on Error, then you are limited to just doing new Error().stack ?? ''. @tegefaulkes please add a check to do so.

So...

if ('stackTraceLimit' in Error && 'captureStackTrace' in Error) {
  // do what we do above
} else {
  // use: new Error().stack ?? '';
}

MatrixAI / js-logger