MatrixAI / js-logger

TypeScript/JavaScript Logger Library
https://polykey.com
Apache License 2.0
1 stars 0 forks source link

Integrate optional trace in order to easily identify where logs are being outputted #4

Closed CMCDragonkai closed 2 years ago

CMCDragonkai commented 2 years ago

Specification

Sometimes we get logging messages where we don't know where they came from, and it would be nice to know how the code arrived at that execution point.

The console.trace() can immediately show a trace of where you are.

Trace
    at abc (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/trace.ts:4:11)
    at Object.<anonymous> (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/trace.ts:11:1)
    at Module._compile (node:internal/modules/cjs/loader:1103:14)
    at Module.m._compile (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/index.ts:1455:23)
    at Module._extensions..js (node:internal/modules/cjs/loader:1157:10)
    at Object.require.extensions.<computed> [as .ts] (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/index.ts:1458: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)
    at phase4 (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/bin.ts:567:12)

But it prints to stdout, and we would want it as a variable. The Error.stack property seems to be something we can use. https://stackoverflow.com/a/36172532/582917

function getStackTrace () {
    let stack = new Error().stack || '';
    stack = stack.split('\n').map(function (line) { return line.trim(); });
    return stack.splice(stack[0] == 'Error' ? 2 : 1);
}

getStackTrace()[2]; // get stack trace info 2 levels-deep

This trace string can then be part of the logged out information, which would make it easier to find out where a particular log message is occurring.

Adding it into the formatting however can make logs VERY noisy. Which would rely on #3 to help decipher.

Additionally we can add "custom formatting" override to the logging method logger.info which can help us to interactive debugging.

Note that enabling traces would be quite expensive.

Tasks

  1. Add in additional trace keyword
  2. Consider that traces are multi-line strings, but loggers are supposed to output a single line
  3. Therefore these things will be part of whether we have human readable logging or structured logging
  4. Add the ability to override the format in the logger.info and related methods
CMCDragonkai commented 2 years ago

So I imagine that when trace keyword is applied, the log message should end up looking like:

INFO:PolykeyAgent:OH NO
  at abc (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/trace.ts:4:11)
  at Object.<anonymous> (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/trace.ts:11:1)
  at Module._compile (node:internal/modules/cjs/loader:1103:14)
  at Module.m._compile (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/index.ts:1455:23)
  at Module._extensions..js (node:internal/modules/cjs/loader:1157:10)
  at Object.require.extensions.<computed> [as .ts] (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/index.ts:1458: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)
  at phase4 (/home/cmcdragonkai/Projects/TypeScript-Demo-Lib/node_modules/ts-node/src/bin.ts:567:12)

We may need to add a formatting override parameter to our logger:

logger.debug("OH NO", format'${level}:${key}${trace}');

Furthermore we can expand the symbols to be functions which can allow us to parameterise what we want to do:

logger.debug("OH NO", format'${level}:${key}${trace(3)}');

Note that the trace keyword would add a \n in front of it so that the trace occurs underneath the log message.

This does mean that our "human readable" log messages are not always terminated by a newline. Because it may have newlines inside a single message. This will cause issues for downstream log analyzers, because most are pretty simple and just parse messages by newlines. But this trace keyword would only be used for debugging/development.