Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
62 changes: 62 additions & 0 deletions ddtrace/tracer/telemetry_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import (
"github.com/DataDog/dd-trace-go/v2/internal/orchestrion"
"github.com/DataDog/dd-trace-go/v2/internal/telemetry"
"github.com/DataDog/dd-trace-go/v2/internal/telemetry/telemetrytest"
"github.com/DataDog/dd-trace-go/v2/internal/traceprof"
"github.com/DataDog/dd-trace-go/v2/profiler"

"github.com/stretchr/testify/assert"
Expand Down Expand Up @@ -232,3 +233,64 @@ func TestRepeatStartRecordsEnvDiffOnActiveClient(t *testing.T) {
require.True(t, ok, "expected config.repeat_start_env_diff to be recorded on the active telemetry client")
assert.Equal(t, float64(1), handle.Get())
}

func TestTracerStopFlushesTelemetry(t *testing.T) {
Start()
defer globalconfig.SetServiceName("")
require.NotNil(t, telemetry.GlobalClient())

Stop()

assert.Nil(t, telemetry.GlobalClient())
}

func TestTracerStopDoesNotStopForeignTelemetry(t *testing.T) {
telemetryClient := new(telemetrytest.RecordClient)
defer telemetry.MockClient(telemetryClient)()

Start()
defer globalconfig.SetServiceName("")
Stop()

// Profiler or another product already owns the global client. Stop must
// not call StopApp on it.
assert.False(t, telemetryClient.Stopped)
assert.Equal(t, telemetry.Client(telemetryClient), telemetry.GlobalClient())
Comment on lines +257 to +258

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These assertions prove StopApp wasn't called on the foreign client — good — but none of the
three tests observe the behavior the PR is named after. assert.Nil(GlobalClient()) in
TestTracerStopFlushesTelemetry proves StopApp ran, not that the queue flushed; and here the
leftover-client Close() (the ticker-leak fix the code comment describes) is unverified,
because RecordClient.Flush() is a no-op (telemetrytest/record.go:216) and Close() records
nothing (record.go:44-46).

RecordClient.Products does record ProductStopped — worth asserting here to pin down that the
tracer's product-stopped still propagates to the foreign-owned client:

Suggested change
assert.False(t, telemetryClient.Stopped)
assert.Equal(t, telemetry.Client(telemetryClient), telemetry.GlobalClient())
// Profiler or another product already owns the global client. Stop must
// not call StopApp on it.
assert.False(t, telemetryClient.Stopped)
assert.Equal(t, telemetry.Client(telemetryClient), telemetry.GlobalClient())
// ProductStopped(tracers) must still propagate to the foreign client
// (ProductStarted set it true during Start; Stop sets it back to false).
assert.False(t, telemetryClient.Products[telemetry.NamespaceTracers])

If you also want the flush and leftover-close directly observable, that needs a small
telemetrytest extension (e.g. Flushes int / Closed bool on RecordClient) — happy to review
that as a follow-up.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

added the ProductStopped assert. leaving Flushes/Closed on RecordClient for a follow up

// ProductStopped(tracers) must still propagate to the foreign client
// (ProductStarted set it true during Start; Stop sets it back to false).
assert.False(t, telemetryClient.Products[telemetry.NamespaceTracers])
}

func TestTracerStopKeepsTelemetryWhenProfilerStillRunning(t *testing.T) {
Start()
defer globalconfig.SetServiceName("")
require.NotNil(t, telemetry.GlobalClient())

wasEnabled := traceprof.SetProfilerEnabled(true)
defer func() {
traceprof.SetProfilerEnabled(wasEnabled)
telemetry.StopApp()
}()

Stop()

// Profiler started after the tracer and still shares the client, so Stop
// must flush without emitting app-stopped / clearing the global client.
assert.NotNil(t, telemetry.GlobalClient())
}
Comment on lines +277 to +280

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The three tests cover tracer-only, foreign-owner, and profiler-still-running, but skip the
fourth ordering: the profiler started after the tracer and then stopped before tracer.Stop()
runs. That's the path where Stop must fall through to StopApp — and it's the one whose
behavior changed (on main the global client survived StopApp-less shutdown, so a
GlobalClient()==nil assertion distinguishes this PR from main). Suggested addition:

Suggested change
// Profiler started after the tracer and still shares the client, so Stop
// must flush without emitting app-stopped / clearing the global client.
assert.NotNil(t, telemetry.GlobalClient())
}
// Profiler started after the tracer and still shares the client, so Stop
// must flush without emitting app-stopped / clearing the global client.
assert.NotNil(t, telemetry.GlobalClient())
}
func TestTracerStopStopsTelemetryAfterProfilerStopped(t *testing.T) {
Start()
defer globalconfig.SetServiceName("")
require.NotNil(t, telemetry.GlobalClient())
wasEnabled := traceprof.SetProfilerEnabled(true)
defer traceprof.SetProfilerEnabled(wasEnabled)
// The profiler started after the tracer, then stopped before tracer.Stop().
traceprof.SetProfilerEnabled(false)
Stop()
// Nobody else needs the client anymore, so Stop must fully stop the app.
assert.Nil(t, telemetry.GlobalClient())
}

Two other gaps I'd leave for a follow-up rather than this PR: the telemetry-disabled path
(client == nil early return) is hard to test because Disabled() caches the env var in a
package-level sync.Once (internal/telemetry/globalclient.go:135-144) — t.Setenv alone won't
work unless the test runs before anything primes the once — and the stale-flag sequences
from my other comment have no coverage either.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

added TestTracerStopStopsTelemetryAfterProfilerStopped


func TestTracerStopStopsTelemetryAfterProfilerStopped(t *testing.T) {
Start()
defer globalconfig.SetServiceName("")
require.NotNil(t, telemetry.GlobalClient())

wasEnabled := traceprof.SetProfilerEnabled(true)
defer traceprof.SetProfilerEnabled(wasEnabled)
// The profiler started after the tracer, then stopped before tracer.Stop().
traceprof.SetProfilerEnabled(false)

Stop()

// Nobody else needs the client anymore, so Stop must fully stop the app.
assert.Nil(t, telemetry.GlobalClient())
}
34 changes: 31 additions & 3 deletions ddtrace/tracer/tracer.go
Original file line number Diff line number Diff line change
Expand Up @@ -132,6 +132,8 @@ type tracer struct {

// stopOnce ensures the tracer is stopped exactly once.
stopOnce sync.Once
// telemetryStopOnce ensures telemetry shutdown runs once across concurrent Stop calls.
telemetryStopOnce sync.Once

// wg waits for all goroutines to exit when stopping.
wg sync.WaitGroup
Expand Down Expand Up @@ -1271,13 +1273,39 @@ func (t *tracer) Stop() {
}
appsec.Stop()
remoteconfig.Stop()
// Flush telemetry before closing the log file so StopApp diagnostics still land.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This block is the tracer/profiler ownership handshake for the global telemetry client, but
nothing ties it to the end-state the codebase already anticipates — the TODO at
tracer.go:264-267 ("Will be fixed when the tracer and profiler share control of the global
telemetry client", APMAPI-1771). The current shape — pointer equality plus
traceprof.ProfilerEnabled() — hard-codes a two-product world: appsec already shares the
global client too (appsec.Stop() queues ProductStopped on it), and any future product
sharing it would need another flag or special case here. A refcount in internal/telemetry
(products register on start, StopApp fires when the last one stops) would also dissolve the
flag race and the profiler-never-stops-telemetry gap from my other comments — worth
considering as the follow-up that retires this TODO.

Until then, a pointer from this block to that plan would help the next refactor find it:

Suggested change
// Flush telemetry before closing the log file so StopApp diagnostics still land.
// Flush telemetry before closing the log file so StopApp diagnostics still land.
// Interim tracer/profiler ownership handshake for the global telemetry client;
// to be superseded by shared client control (see TODO at newTracer, APMAPI-1771).

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

comment now points at the newTracer APMAPI-1771 TODO

// Interim tracer/profiler ownership handshake for the global telemetry client;
// to be superseded by shared client control (see TODO at newTracer, APMAPI-1771).
t.telemetryStopOnce.Do(func() {
client := t.telemetry
t.telemetry = nil
if client == nil {
return
}
telemetry.ProductStopped(telemetry.NamespaceTracers)
if telemetry.GlobalClient() != client {
// StartApp ignored this client because another product already owns
// the global one. Close the leftover so its ticker does not leak.
client.Close()
return
}
if traceprof.ProfilerEnabled() {

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This check has a small TOCTOU window against profiler.Start(). SetProfilerEnabled(true)
is the last statement of profiler.Start (profiler/profiler.go:94), after run() has already
called startTelemetry synchronously (profiler/profiler.go:314). If tracer.Stop() executes
in between — profiler's package mu doesn't help, tracer.Stop() never takes it — this
check reads false and StopApp() closes the very client the profiler just registered
ProductStarted(profilers) on, leaving the profiler running with dead telemetry.

This race is pre-existing (main closes the same shared client unconditionally in that
window) and the window is only a handful of statements wide, so not blocking. The cheap
fix is in profiler/profiler.go: set the flag before activeProfiler.run() instead of
after — flush-only is the safe direction during profiler start, since the client
survives and the profiler attaches to it normally. The reverse interleaving is already
fine: if StopApp() completes first, profiler startTelemetry sees GlobalClient() == nil
and starts a fresh app.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

raised SetProfilerEnabled(true) before run() so the window is closed

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This check also trusts a flag that can go stale. In profiler.Start() (profiler/profiler.go:87-89),
when a profiler is already active, the old instance is stopped but neither activeProfiler nor
traceprof.SetProfilerEnabled is reset, and every early return afterwards leaves that state behind:

  • Start() ok, then Start() where the new config is disabled (DD_PROFILING_ENABLED flipped
    in-process; returns nil, so nothing signals a problem): flag stays true with a stopped
    activeProfiler.
  • Start() ok, then Start() failing in newProfiler (agentless without API key,
    AWS_Lambda env, hostname error): same stale state, though at least an error is returned.

In both sequences no profiler is running, but this branch sees ProfilerEnabled() == true,
takes the flush-only path, and leaves the global telemetry client and its ticker goroutine
orphaned until process exit — no app-stopped, and profiler.Stop() afterwards clears the flag
but touches no telemetry. The stale state itself is pre-existing (the branch is unchanged on
main), but this PR is the first consumer that branches on the flag, so main's unconditional
Close() was accidentally correct here while the new check inherits the bug.

The staleness is fixable in five lines, in profiler.Start's stop-old-profiler branch:

if activeProfiler != nil {
    activeProfiler.stop()
    activeProfiler = nil
    traceprof.SetProfilerEnabled(false)
}

That makes the flag strictly track "a profiler is assigned and running" on every early return,
and doesn't widen the (separate) race window between run() and the flag being re-raised. It's
a pre-existing bug so it could be a follow-up PR, but since this change is what makes it
observable, it's worth riding along. No existing test covers Start-then-Start-disabled or
Start-then-Start-error; one should be added with whichever fix lands.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

clearing activeProfiler + SetProfilerEnabled(false) in the stop-old branch now, plus a restart-disabled test

// Profiler started after us and still shares this client. Mark the
// tracer product stopped and flush, but leave the app running.
Comment on lines +1293 to +1294

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In this branch the app is deliberately left running because the profiler still
shares the client, but nothing ever stops it afterwards: profiler.Stop() has no
telemetry teardown at all (no ProductStopped(profilers) and no StopApp anywhere
in the profiler package), so when the profiler is the last product to stop,
app-stopped is never sent and the client's ticker goroutine lives until process
exit. The periodic ticker does keep flushing while the process runs, so this is
bounded (one goroutine + ticker per process), and the gap is pre-existing — in
the profiler-first ordering, main has the same leak. Still worth a TODO here so
the assumption is recorded, with the profiler-side fix as a follow-up PR.

Suggested change
// Profiler started after us and still shares this client. Mark the
// tracer product stopped and flush, but leave the app running.
// Profiler started after us and still shares this client. Mark the
// tracer product stopped and flush, but leave the app running.
// TODO: profiler.Stop() never stops telemetry, so when the profiler is
// the last product to stop, app-stopped is never sent and the client's
// ticker goroutine lives until process exit. Follow-up: profiler.Stop()
// should send ProductStopped(NamespaceProfilers) and StopApp() when it
// owns the global client.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

added the TODO as suggested

// TODO: profiler.Stop() never stops telemetry, so when the profiler is
// the last product to stop, app-stopped is never sent and the client's
// ticker goroutine lives until process exit. Follow-up: profiler.Stop()
// should send ProductStopped(NamespaceProfilers) and StopApp() when it
// owns the global client.
client.Flush()
return
}
telemetry.StopApp()
})
// Close log file last to account for any logs from the above calls
if t.logFile != nil {
t.logFile.Close()
}
if t.telemetry != nil {
t.telemetry.Close()
}
t.config.httpClient.CloseIdleConnections()
}

Expand Down
5 changes: 5 additions & 0 deletions internal/traceprof/profiler.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,11 @@ func SetProfilerEnabled(val bool) bool {
return profiler.enabled.Swap(boolToUint32(val)) != 0
}

// ProfilerEnabled reports whether the continuous profiler is currently running.
func ProfilerEnabled() bool {
return profiler.enabled.Load() != 0
}

func profilerEnabled() int {
return int(profiler.enabled.Load())
}
Expand Down
6 changes: 5 additions & 1 deletion profiler/profiler.go
Original file line number Diff line number Diff line change
Expand Up @@ -81,6 +81,8 @@ func Start(opts ...Option) error {

if activeProfiler != nil {
activeProfiler.stop()
activeProfiler = nil
traceprof.SetProfilerEnabled(false)
}
p, err := newProfiler(opts...)
if err != nil {
Expand All @@ -90,8 +92,10 @@ func Start(opts ...Option) error {
return nil
}
activeProfiler = p
activeProfiler.run()
// Raise the flag before run() so tracer.Stop() sees the profiler as active
// while startTelemetry registers on the shared client (avoids a TOCTOU close).
traceprof.SetProfilerEnabled(true)
activeProfiler.run()
return nil
}

Expand Down
14 changes: 14 additions & 0 deletions profiler/profiler_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -174,6 +174,20 @@ func TestStart(t *testing.T) {
defer Stop()
assert.ErrorIs(t, err, errProfilingNotSupportedInAWSLambda)
})

t.Run("restart-disabled-clears-enabled-flag", func(t *testing.T) {
require.NoError(t, Start())
require.True(t, traceprof.ProfilerEnabled())

t.Setenv("DD_PROFILING_ENABLED", "false")
require.NoError(t, Start())
defer Stop()

mu.Lock()
assert.Nil(t, activeProfiler)
mu.Unlock()
assert.False(t, traceprof.ProfilerEnabled())
})
}

// TestStartWithoutStopReconfigures verifies that calling Start while the
Expand Down
Loading