Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
CMCDragonkai opened this issue May 18, 2022 · 1 comment · Fixed by #6
Closed
Assignees
Labels
development Standard development

Comments

@CMCDragonkai
Copy link
Member

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 CMCDragonkai added the development Standard development label May 18, 2022
@CMCDragonkai
Copy link
Member Author

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.

@tegefaulkes tegefaulkes self-assigned this Jun 21, 2022
tegefaulkes added a commit that referenced this issue Jun 21, 2022

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature. The key has expired.
This adds a stack trace formatted the same way as an error message. This will allow us to debug where logging messages are coming from.

Related #4
tegefaulkes added a commit that referenced this issue Jun 21, 2022
Added the ability to override a log message format on a per-message basis. You have to provide an optional `LogFormatter` parameter to the message. For example logger.info('INFO MESSAGE', formatting.format`${formatting.date}:${formatting.msg}`);.

Related #4
tegefaulkes added a commit that referenced this issue Jun 21, 2022
Added the ability to override a log message format on a per-message basis. You have to provide an optional `LogFormatter` parameter to the message. For example logger.info('INFO MESSAGE', formatting.format`${formatting.date}:${formatting.msg}`);.

Related #4
tegefaulkes added a commit that referenced this issue Jun 22, 2022
Added the ability to override a log message format on a per-message basis. You have to provide an optional `LogFormatter` parameter to the message. For example logger.info('INFO MESSAGE', formatting.format`${formatting.date}:${formatting.msg}`);.

Related #4
tegefaulkes added a commit that referenced this issue Jun 22, 2022
Added the ability to override a log message format on a per-message basis. You have to provide an optional `LogFormatter` parameter to the message. For example logger.info('INFO MESSAGE', formatting.format`${formatting.date}:${formatting.msg}`);.

Related #4
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
development Standard development
Development

Successfully merging a pull request may close this issue.

2 participants