debug warnings when init after instrumented packages #4307

tlhunter · 2024-05-15T17:30:55Z

What does this PR do?

this change only runs when DD_TRACE_DEBUG=true has been set and has no correlating init/config entry
checks to see if any instrumented packages are in the require cache during init
prints warnings to STDERR when encountering such modules
really more intended for local debugging
note that it will not detect when built-in modules such as http have been required before the tracer

$ DD_TRACE_DEBUG=true node main.js
Warning: The package 'redis' was loaded before dd-trace! This may cause errors with instrumentation
Warning: The package '@redis/client' was loaded before dd-trace! This may cause errors with instrumentation
Warning: The package 'generic-pool' was loaded before dd-trace! This may cause errors with instrumentation
Warning: Please ensure dd-trace is loaded before any other modules to ensure proper functionality

Motivation

this is the lowest hanging fruit when it comes to debugging an app which isn't properly instrumented

github-actions · 2024-05-15T17:31:35Z

Overall package size

Self size: 6.49 MB
Deduped: 60.62 MB
No deduping: 60.9 MB

Dependency sizes

name	version	self size	total size
@datadog/native-iast-taint-tracking	2.1.0	14.91 MB	14.92 MB
@datadog/native-appsec	7.1.1	14.39 MB	14.4 MB
@datadog/pprof	5.3.0	9.85 MB	10.22 MB
protobufjs	7.2.5	2.77 MB	6.56 MB
@datadog/native-iast-rewriter	2.3.1	2.15 MB	2.24 MB
@opentelemetry/core	1.14.0	872.87 kB	1.47 MB
@datadog/native-metrics	2.0.0	898.77 kB	1.3 MB
@opentelemetry/api	1.8.0	1.21 MB	1.21 MB
import-in-the-middle	1.7.4	70.19 kB	739.86 kB
msgpack-lite	0.1.26	201.16 kB	281.59 kB
opentracing	0.14.7	194.81 kB	194.81 kB
semver	7.5.4	93.4 kB	123.8 kB
pprof-format	2.1.0	111.69 kB	111.69 kB
@datadog/sketches-js	2.1.0	109.9 kB	109.9 kB
lodash.sortby	4.7.0	75.76 kB	75.76 kB
lru-cache	7.14.0	74.95 kB	74.95 kB
ipaddr.js	2.1.0	60.23 kB	60.23 kB
ignore	5.2.4	51.22 kB	51.22 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
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
node-abort-controller	3.1.1	16.89 kB	16.89 kB
jest-docblock	29.7.0	8.99 kB	12.76 kB
crypto-randomuuid	1.0.0	11.18 kB	11.18 kB
path-to-regexp	0.1.7	6.78 kB	6.78 kB
koalas	1.0.2	6.47 kB	6.47 kB
methods	1.1.2	5.29 kB	5.29 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 · 2024-05-15T17:36:31Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 60.73%. Comparing base (7000ae5) to head (1891681).
Report is 15 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #4307      +/-   ##
==========================================
- Coverage   69.19%   60.73%   -8.46%     
==========================================
  Files           1      101     +100     
  Lines         198     3273    +3075     
  Branches       33       33              
==========================================
+ Hits          137     1988    +1851     
- Misses         61     1285    +1224

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

pr-commenter · 2024-05-15T17:42:48Z

Benchmarks

Benchmark execution time: 2024-05-16 22:44:41

Comparing candidate commit 1891681 in PR branch tlhunter/debug-late-load-tracer with baseline commit 79f0d64 in branch master.

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

rochdev · 2024-05-15T22:23:58Z

packages/datadog-core/src/utils/src/extract-package-and-module-path.js

@@ -0,0 +1,33 @@
+'use strict'


This doesn't really belong in core as it's only needed for auto-instrumentation. Maybe it could go in datadog-instrumentations?

rochdev · 2024-05-15T22:25:13Z

packages/dd-trace/src/check_require_cache.js

+    if (naughties.has(pkg)) continue
+    if (!(pkg in packages)) continue
+
+    console.error(`Warning: Package '${pkg}' was loaded before dd-trace! This may break instrumentation.`)


What happens if tens of thousands of packages were loaded before dd-trace?

Also, what about frameworks that load the app from a CLI tool, for example micro? These would likely have a lot of warnings that are not possible to fix. Same for CI Visibility probably.

What happens if tens of thousands of packages were loaded before dd-trace?

It will print at most 1 message for each package name. E.g. if it finds 10 redis entries there will be one line printed.

Also, what about frameworks that load the app from a CLI tool, for example micro? These would likely have a lot of warnings that are not possible to fix. Same for CI Visibility probably.

These logs only appear when in debug mode wherein a user should be expecting lots of debug logs.

Qard

LGTM, just one minor nit/question.

Qard · 2024-05-16T09:15:08Z

packages/dd-trace/src/proxy.js

      telemetry.start(config, this._pluginManager)

+      if (config.debug) checkRequireCache()


It only matters that we're loaded before them, not that we init before them, right? So we should maybe just do this at the top-level.

cc @rochdev

This has been moved to right before we start patching things

tlhunter · 2024-05-16T17:02:01Z

packages/datadog-instrumentations/src/helpers/register.js

@@ -27,6 +28,8 @@ if (!disabledInstrumentations.has('fetch')) {
 const HOOK_SYMBOL = Symbol('hookExportsMap')
 // TODO: make this more efficient

+checkRequireCache()


TODO: Need to wrap this in a debug check. I don't think config is ready at this point?

Oh, duh, of course, config can't possibly be ready before init, as init is used to configure the tracer.

tlhunter · 2024-05-16T18:41:01Z

I spoke with @bengl and I'll just check for the DD_TRACE_DEBUG env var and not the config object. Optionally I could make a new env var with no correlating config option.

tlhunter added the semver-patch label May 15, 2024

tlhunter requested a review from a team as a code owner May 15, 2024 17:30

tlhunter force-pushed the tlhunter/debug-late-load-tracer branch from 5928bc6 to ae3c90f Compare May 15, 2024 17:36

tlhunter force-pushed the tlhunter/debug-late-load-tracer branch 5 times, most recently from cc813c4 to 3de98b7 Compare May 15, 2024 21:36

debug warnings when init after instrumented modules

65e0118

tlhunter force-pushed the tlhunter/debug-late-load-tracer branch from 3de98b7 to 65e0118 Compare May 15, 2024 21:48

annoying test suite

96c613b

rochdev reviewed May 15, 2024

View reviewed changes

looks like windows has some issues

9c6f6ac

tlhunter force-pushed the tlhunter/debug-late-load-tracer branch from 38135fa to 9c6f6ac Compare May 16, 2024 00:42

Qard previously approved these changes May 16, 2024

View reviewed changes

move helper file to instrumentations

02b6fc1

tlhunter dismissed Qard’s stale review via a696890 May 16, 2024 16:53

tlhunter requested a review from a team as a code owner May 16, 2024 16:53

modify to warn at load time not init time

70bc9f4

tlhunter force-pushed the tlhunter/debug-late-load-tracer branch from a696890 to 70bc9f4 Compare May 16, 2024 16:58

tlhunter commented May 16, 2024

View reviewed changes

allow the DD_TRACE_DEBUG env var

1891681

Qard approved these changes May 17, 2024

View reviewed changes

tlhunter merged commit c69cd64 into master May 17, 2024
109 of 112 checks passed

tlhunter deleted the tlhunter/debug-late-load-tracer branch May 17, 2024 15:50

tlhunter added a commit that referenced this pull request May 17, 2024

debug warnings when init after instrumented packages (#4307)

d6ef1b6

tlhunter added a commit that referenced this pull request May 17, 2024

debug warnings when init after instrumented packages (#4307)

55bf588

This was referenced May 17, 2024

v4.38.1 proposal #4326

Merged

v5.14.1 proposal #4327

Merged

tlhunter added a commit that referenced this pull request May 20, 2024

debug warnings when init after instrumented packages (#4307)

59f5e82

tlhunter added a commit that referenced this pull request May 20, 2024

debug warnings when init after instrumented packages (#4307)

973f5b8

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

debug warnings when init after instrumented packages #4307

debug warnings when init after instrumented packages #4307

tlhunter commented May 15, 2024 •

edited

github-actions bot commented May 15, 2024 •

edited

codecov bot commented May 15, 2024 •

edited

pr-commenter bot commented May 15, 2024 •

edited

rochdev May 15, 2024

rochdev May 15, 2024

rochdev May 15, 2024

tlhunter May 16, 2024

Qard left a comment

Qard May 16, 2024

tlhunter May 16, 2024

tlhunter May 16, 2024

tlhunter May 16, 2024

tlhunter commented May 16, 2024 •

edited

		telemetry.start(config, this._pluginManager)

		if (config.debug) checkRequireCache()

debug warnings when init after instrumented packages #4307

debug warnings when init after instrumented packages #4307

Conversation

tlhunter commented May 15, 2024 • edited

What does this PR do?

Motivation

github-actions bot commented May 15, 2024 • edited

Overall package size

Dependency sizes

codecov bot commented May 15, 2024 • edited

Codecov Report

pr-commenter bot commented May 15, 2024 • edited

Benchmarks

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Qard left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tlhunter commented May 16, 2024 • edited

tlhunter commented May 15, 2024 •

edited

github-actions bot commented May 15, 2024 •

edited

codecov bot commented May 15, 2024 •

edited

pr-commenter bot commented May 15, 2024 •

edited

tlhunter commented May 16, 2024 •

edited