log template messages and errors

[iunanua]

What does this PR do?

Update log methods (error and warn, info, debug) to accept multiple arguments in order to use template messages.
util.format is used to format the templates

log.error(err)
log.error('template message %s %d', arg1, arg2)
log.error('template %s', arg1, err)

Notes

Legacy cases are still supported

log.error() // no message, no error
log.error({ message: 'error' }) // object with a message property
log.error({ stack: 'stack' }) // non Error object with a stack property

There is a case, used often with log.debug(), where a callback or delegate is passed to the logger: log.debug(() => do_something_heavy()).
The delegate is executed by log/writer.js but not by telemetry/log.
So when executing log.error(() => error) the error will be written to the configured logger but won't be sent via telemetry.

Motivation

• meet the 'no dynamic messages' telemetry requirement
• avoid calling twice to log an error and a message

Plugin Checklist

• Unit tests.
• TypeScript definitions.
• TypeScript tests.
• API documentation.
• CircleCI jobs/workflows.
• Plugin is exported.

Additional Notes

[github-actions]

Overall package size

Self size: 8.01 MB
Deduped: 94.51 MB
No deduping: 94.85 MB

Dependency sizes

| name | version | self size | total size | |------|---------|-----------|------------| | @datadog/libdatadog | 0.2.2 | 29.27 MB | 29.27 MB | | @datadog/native-appsec | 8.3.0 | 19.37 MB | 19.38 MB | | @datadog/native-iast-taint-tracking | 3.2.0 | 13.9 MB | 13.91 MB | | @datadog/pprof | 5.4.1 | 9.76 MB | 10.13 MB | | protobufjs | 7.2.5 | 2.77 MB | 5.16 MB | | @datadog/native-iast-rewriter | 2.5.0 | 2.51 MB | 2.65 MB | | @opentelemetry/core | 1.14.0 | 872.87 kB | 1.47 MB | | @datadog/native-metrics | 3.0.1 | 1.06 MB | 1.46 MB | | @opentelemetry/api | 1.8.0 | 1.21 MB | 1.21 MB | | import-in-the-middle | 1.11.2 | 112.74 kB | 826.22 kB | | msgpack-lite | 0.1.26 | 201.16 kB | 281.59 kB | | opentracing | 0.14.7 | 194.81 kB | 194.81 kB | | lru-cache | 7.18.3 | 133.92 kB | 133.92 kB | | pprof-format | 2.1.0 | 111.69 kB | 111.69 kB | | @datadog/sketches-js | 2.1.0 | 109.9 kB | 109.9 kB | | semver | 7.6.3 | 95.82 kB | 95.82 kB | | lodash.sortby | 4.7.0 | 75.76 kB | 75.76 kB | | ignore | 5.3.1 | 51.46 kB | 51.46 kB | | int64-buffer | 0.1.10 | 49.18 kB | 49.18 kB | | shell-quote | 1.8.1 | 44.96 kB | 44.96 kB | | istanbul-lib-coverage | 3.2.0 | 29.34 kB | 29.34 kB | | rfdc | 1.3.1 | 25.21 kB | 25.21 kB | | @isaacs/ttlcache | 1.4.1 | 25.2 kB | 25.2 kB | | tlhunter-sorted-set | 0.1.0 | 24.94 kB | 24.94 kB | | limiter | 1.1.5 | 23.17 kB | 23.17 kB | | dc-polyfill | 0.1.4 | 23.1 kB | 23.1 kB | | retry | 0.13.1 | 18.85 kB | 18.85 kB | | jest-docblock | 29.7.0 | 8.99 kB | 12.76 kB | | crypto-randomuuid | 1.0.0 | 11.18 kB | 11.18 kB | | koalas | 1.0.2 | 6.47 kB | 6.47 kB | | path-to-regexp | 0.1.10 | 6.38 kB | 6.38 kB | | module-details-from-path | 1.0.3 | 4.47 kB | 4.47 kB |

_{🤖 This report was automatically generated by heaviest-objects-in-the-universe}

[codecov]

Codecov Report

Attention: Patch coverage is 95.65217% with 3 lines in your changes missing coverage. Please review.

Project coverage is 76.97%. Comparing base (170a97c) to head (d2cd427).
Report is 2 commits behind head on master.

Files with missing lines	Patch %	Lines
packages/dd-trace/src/log/index.js	66.66%	2 Missing ⚠️
...kages/dd-trace/src/telemetry/logs/log-collector.js	50.00%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #4856      +/-   ##
==========================================
- Coverage   82.43%   76.97%   -5.46%     
==========================================
  Files         290      283       -7     
  Lines       13193    13144      -49     
==========================================
- Hits        10875    10117     -758     
- Misses       2318     3027     +709     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[pr-commenter]

Benchmarks

Benchmark execution time: 2024-11-18 13:35:26

Comparing candidate commit 3a9e1f7 in PR branch igor/log-revamp with baseline commit 61c5a32 in branch master.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 140 metrics, 5 unstable metrics.

[iunanua]

We are assigning the 'Generic Error' message to all errors logged without message.
It allows us to not to update all the log.error(err) cases in the tracer but will be recommended to provide a message for each of the cases

[rochdev]

Not sure I understand. What is the current behaviour for this? Are we just logging nothing?

[iunanua]

It is the message for telemetry logs when there is no message.

We were sending the error message as telemetry log message but guys from telemetry complained about it due to cardinality and possible PII data problems.

Now, with the new log api, it is preferable whenever you log an error that is accompanied by a no dynamic message.

// if you call log.error with a message and an error
// logger: 
//  - logs 'Error loading file'
//  - logs e
// telemetry:
//  - sends 'Error loading file' message + e.stack
log.error('Error loading file', e) 

But if a message is not provided 'Generic Error' message is used

// logger:
// - logs e
// telemetry:
// - sends 'Generic Error' message + e.stack
log.error(e) 

[szegedi]

The delegate is executed by log/writer.js but not by telemetry/log.
So when executing log.error(() => error) the error will be written to the configured logger but won't be sent via telemetry.

This is super subtle and I wonder if it's a behavior we want to rely on. Nobody reading code would think that a delegate is used just for this effect; it's quite cryptic. I'd rather fully embrace the fact this API is – among other things – a facade for telemetry logs and have a dedicated function name for a local-only logging, e.g. log.errorLocally

[iunanua]

The delegate is executed by log/writer.js but not by telemetry/log.
So when executing log.error(() => error) the error will be written to the configured logger but won't be sent via telemetry.

This is super subtle and I wonder if it's a behavior we want to rely on. Nobody reading code would think that a delegate is used just for this effect; it's quite cryptic. I'd rather fully embrace the fact this API is – among other things – a facade for telemetry logs and have a dedicated function name for a local-only logging, e.g. log.errorLocally

This is a side effect, I'll try to explain it.

Delegates are used to "delay" the message composition after logger has checked if certain logging level is enabled:

log.debug(() => `Setting new DSM Context: ${JSON.stringify(dataStreamsContext)}.`) // dataStreamsContext will only be stringifyed if debug level is enabled

They are mostly used for debugging logs. These logs are not sent via telemetry.
At the moment and there is no single case using log.error with a delegate.

To know if a certain logging level is enabled we check if a particular log channel has subscribers

But as we want to enable log collection globally, log channels (at the moment error logs so at least errorChannel) will always have one subscriber (telemetry/log) regardless of whether DD_TRACE_DEBUG value is.
Then there would be no point in doing log.error(() => error)

So I decided to execute the delegate only in log/writer.js.
Other option could be to execute it in each of the log channel listeners. But as it is a debugging case and they are not sent via telemetry I opted for the first option. That we can of course change and do what we all decide together 😄

[szegedi]

Oh I see, basically you're saying that delegates are only used to log debug messages that are deferred as a performance concern. Okay, I guess that makes sense.

[rochdev]

A few questions/comments but otherwise LGTM.

[iunanua]

@rochdev changed an expression to make it work in node 12 because some integration-guardrails(12) tests were failing.