Skip to content

Use "interpolation values" instead of string interpolation when logging #4080

@acuarica

Description

@acuarica

Our log messages are guarded by the isLevelEnabled method. This guard was introduced in #1118 to avoid building the message argument when the corresponding log level is not active. This is because, in most cases, we use JavaScript's string interpolation to build the message argument. In turn this causes performance issues because the message is built regardless of the active log level.

However, as mentioned in #3574, this clutters the code making harder to read and it is error prone when introducing new logging statements.

An alternative approach can be to use Pino's interpolationValues. In a nutshell, interpolation values allow us to log using a literal string (not a JavaScript template string) and additional values using a printf-like format. In this scenario, no actual message is being built, so any overhead should be negligible.

Therefore, we should remove the log level enabled check. That is, we should revert PR #3154 and any other instance where we use isLevelEnabled. And replace it replace it with Pino's interpolation values.

Ideally, we want to ensure that this change does not affect performance. We should run K6 tests to compare alternatives, and only introduce this change if it does not affect performance.

Acceptance Criteria

  • warn, info, debug and trace calls should receive as first argument a string literal (not a template literal) using interpolation values. The rest of the arguments must be variable expressions. That is, no additional computation, e.g., function call, string concat, object creation, etc., can be passed to a logger method. If an actual computation is needed, the guard must be kept. See below.
  • A few log entries effectively need some preprocessing before doing the actual logging. In those cases, the isLevelEnabled guard should be kept. See for example
    if (this.logger.isLevelEnabled('trace')) {
    const censoredKey = key.replace(Utils.IP_ADDRESS_REGEX, '<REDACTED>');
    const censoredValue = result.replace(/"ipAddress":"[^"]+"/, '"ipAddress":"<REDACTED>"');
    this.logger.trace(`Returning cached value ${censoredKey}:${censoredValue} on ${callingMethod} call`);
    }
  • Many methods decorated with @rpcMethod include a trace at the beginning. These can traces (and their guards) can be safely removed. The dispatcher already logs when an RPC method is being executed.
  • The removal of isLevelEnabled guards should not affect performance.

This is a follow up of #3574. PR #3990 only dealt with removing the Request ID prefix from logging calls.

Metadata

Metadata

Assignees

Labels

Team PromotedIssues to be triaged and discussed by committers, maintainers, to be worked on the following sprintTechnical DebtIssue which resolves technical debtinternalFor changes that affect the project's internal workings but not its outward-facing functionality.

Type

Projects

No projects

Relationships

None yet

Development

No branches or pull requests

Issue actions