Implement DD_TRACE_LOG_DIRECTORY (DataDog#2901)

ddtrace/tracer/option.go

@@ -276,6 +276,9 @@ type config struct {
 
 	// ciVisibilityEnabled controls if the tracer is loaded with CI Visibility mode. default false
 	ciVisibilityEnabled bool
+
+	// logDirectory is directory for tracer logs specified by user-setting DD_TRACE_LOG_DIRECTORY. default empty/unused
+	logDirectory string
 }
 
 // orchestrionConfig contains Orchestrion configuration.
@@ -379,6 +382,7 @@ func newConfig(opts ...StartOption) *config {
 	c.logStartup = internal.BoolEnv("DD_TRACE_STARTUP_LOGS", true)
 	c.runtimeMetrics = internal.BoolVal(getDDorOtelConfig("metrics"), false)
 	c.debug = internal.BoolVal(getDDorOtelConfig("debugMode"), false)
+	c.logDirectory = os.Getenv("DD_TRACE_LOG_DIRECTORY")
 	c.enabled = newDynamicConfig("tracing_enabled", internal.BoolVal(getDDorOtelConfig("enabled"), true), func(b bool) bool { return true }, equal[bool])
 	if _, ok := os.LookupEnv("DD_TRACE_ENABLED"); ok {
 		c.enabled.cfgOrigin = telemetry.OriginEnvVar
@@ -505,7 +509,6 @@ func newConfig(opts ...StartOption) *config {
 	if c.debug {
 		log.SetLevel(log.LevelDebug)
 	}
-
 	// if using stdout or traces are disabled, agent is disabled
 	agentDisabled := c.logToStdout || !c.enabled.current
 	c.agent = loadAgentFeatures(agentDisabled, c.agentURL, c.httpClient)

ddtrace/tracer/telemetry.go

@@ -62,6 +62,7 @@ func startTelemetry(c *config) {
 		{Name: "trace_peer_service_defaults_enabled", Value: c.peerServiceDefaultsEnabled},
 		{Name: "orchestrion_enabled", Value: c.orchestrionCfg.Enabled},
 		{Name: "trace_enabled", Value: c.enabled.current, Origin: c.enabled.cfgOrigin},
+		{Name: "trace_log_directory", Value: c.logDirectory},
 		c.traceSampleRate.toTelemetry(),
 		c.headerAsTags.toTelemetry(),
 		c.globalTags.toTelemetry(),

ddtrace/tracer/tracer.go

@@ -111,6 +111,11 @@ type tracer struct {
 	// abandonedSpansDebugger specifies where and how potentially abandoned spans are stored
 	// when abandoned spans debugging is enabled.
 	abandonedSpansDebugger *abandonedSpansDebugger
+
+	// logFile contains a pointer to the file for writing tracer logs along with helper functionality for closing the file
+	// logFile is closed when tracer stops
+	// by default, tracer logs to stderr and this setting is unused
+	logFile *log.ManagedFile
 }
 
 const (
@@ -272,6 +277,14 @@ func newUnstartedTracer(opts ...StartOption) *tracer {
 	if c.dataStreamsMonitoringEnabled {
 		dataStreamsProcessor = datastreams.NewProcessor(statsd, c.env, c.serviceName, c.version, c.agentURL, c.httpClient)
 	}
+	var logFile *log.ManagedFile
+	if v := c.logDirectory; v != "" {
+		logFile, err = log.OpenFileAtPath(v)
+		if err != nil {
+			log.Warn("%v", err)
+			c.logDirectory = ""
+		}
+	}
 	t := &tracer{
 		config:           c,
 		traceWriter:      writer,
@@ -294,6 +307,7 @@ func newUnstartedTracer(opts ...StartOption) *tracer {
 		}),
 		statsd:      statsd,
 		dataStreams: dataStreamsProcessor,
+		logFile:     logFile,
 	}
 	return t
 }
@@ -679,6 +693,10 @@ func (t *tracer) Stop() {
 	}
 	appsec.Stop()
 	remoteconfig.Stop()
+	// Close log file last to account for any logs from the above calls
+	if t.logFile != nil {
+		t.logFile.Close()
+	}
 }
 
 // Inject uses the configured or default TextMap Propagator.

ddtrace/tracer/tracer_test.go

@@ -255,6 +255,27 @@ func TestTracerStart(t *testing.T) {
 	})
 }
 
+func TestTracerLogFile(t *testing.T) {
+	t.Run("valid", func(t *testing.T) {
+		dir, err := os.MkdirTemp("", "example")
+		if err != nil {
+			t.Fatalf("Failure to make temp dir: %v", err)
+		}
+		t.Setenv("DD_TRACE_LOG_DIRECTORY", dir)
+		tracer := newTracer()
+		assert.Equal(t, dir, tracer.config.logDirectory)
+		assert.NotNil(t, tracer.logFile)
+		assert.Equal(t, dir+"/"+log.LoggerFile, tracer.logFile.Name())
+	})
+	t.Run("invalid", func(t *testing.T) {
+		t.Setenv("DD_TRACE_LOG_DIRECTORY", "some/nonexistent/path")
+		tracer := newTracer()
+		defer Stop()
+		assert.Empty(t, tracer.config.logDirectory)
+		assert.Nil(t, tracer.logFile)
+	})
+}
+
 func TestTracerStartSpan(t *testing.T) {
 	t.Run("generic", func(t *testing.T) {
 		tracer := newTracer()

internal/log/log.go

@@ -39,6 +39,40 @@ type Logger interface {
 	Log(msg string)
 }
 
+// File name for writing tracer logs, if DD_TRACE_LOG_DIRECTORY has been configured
+const LoggerFile = "ddtrace.log"
+
+// ManagedFile functions like a *os.File but is safe for concurrent use
+type ManagedFile struct {
+	mu     sync.RWMutex
+	file   *os.File
+	closed bool
+}
+
+// Close closes the ManagedFile's *os.File in a concurrent-safe manner, ensuring the file is closed only once
+func (m *ManagedFile) Close() error {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+	if m.file == nil || m.closed {
+		return nil
+	}
+	err := m.file.Close()
+	if err != nil {
+		return err
+	}
+	m.closed = true
+	return nil
+}
+
+func (m *ManagedFile) Name() string {
+	m.mu.RLock()
+	defer m.mu.RUnlock()
+	if m.file == nil {
+		return ""
+	}
+	return m.file.Name()
+}
+
 var (
 	mu     sync.RWMutex // guards below fields
 	level               = LevelWarn
@@ -58,6 +92,25 @@ func UseLogger(l Logger) (undo func()) {
 	}
 }
 
+// OpenFileAtPath creates a new file at the specified dirPath and configures the logger to write to this file. The dirPath must already exist on the underlying os.
+// It returns the file that was created, or nil and an error if the file creation was unsuccessful.
+// The caller of OpenFileAtPath is responsible for calling Close() on the ManagedFile
+func OpenFileAtPath(dirPath string) (*ManagedFile, error) {
+	path, err := os.Stat(dirPath)
+	if err != nil || !path.IsDir() {
+		return nil, fmt.Errorf("file path %v invalid or does not exist on the underlying os; using default logger to stderr", dirPath)
+	}
+	filepath := dirPath + "/" + LoggerFile
+	f, err := os.OpenFile(filepath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
+	if err != nil {
+		return nil, fmt.Errorf("using default logger to stderr due to error creating or opening log file: %v", err)
+	}
+	UseLogger(&defaultLogger{l: log.New(f, "", log.LstdFlags)})
+	return &ManagedFile{
+		file: f,
+	}, nil
+}
+
 // SetLevel sets the given lvl for logging.
 func SetLevel(lvl Level) {
 	mu.Lock()

internal/log/log_test.go

@@ -6,7 +6,9 @@
 package log
 
 import (
+	"bytes"
 	"fmt"
+	"os"
 	"strings"
 	"sync"
 	"testing"
@@ -42,6 +44,76 @@ func (tp *testLogger) Reset() {
 	tp.mu.Unlock()
 }
 
+func TestLogDirectory(t *testing.T) {
+	t.Run("invalid", func(t *testing.T) {
+		f, err := OpenFileAtPath("/some/nonexistent/path")
+		assert.Nil(t, f)
+		assert.Error(t, err)
+	})
+	t.Run("valid", func(t *testing.T) {
+		// ensure File is created successfully
+		dir, err := os.MkdirTemp("", "example")
+		if err != nil {
+			t.Fatalf("Failure creating directory %v", err)
+		}
+		f, err := OpenFileAtPath(dir)
+		assert.Nil(t, err)
+		fp := dir + "/" + LoggerFile
+		assert.NotNil(t, f.file)
+		assert.Equal(t, fp, f.file.Name())
+		assert.False(t, f.closed)
+
+		// ensure this setting plays nicely with other log features
+		oldLvl := level
+		SetLevel(LevelDebug)
+		defer func() {
+			SetLevel(oldLvl)
+		}()
+		Info("info!")
+		Warn("warn!")
+		Debug("debug!")
+		// shorten errrate to test Error() behavior in a reasonable amount of time
+		oldRate := errrate
+		errrate = time.Microsecond
+		defer func() {
+			errrate = oldRate
+		}()
+		Error("error!")
+		time.Sleep(1 * time.Second)
+
+		b, err := os.ReadFile(fp)
+		if err != nil {
+			t.Fatalf("Failure reading file: %v", err)
+		}
+		// convert file content to []string{}, split by \n, to easily check its contents
+		lines := bytes.Split(b, []byte{'\n'})
+		var logs []string
+		for _, line := range lines {
+			logs = append(logs, string(line))
+		}
+
+		assert.True(t, containsMessage("INFO", "info!", logs))
+		assert.True(t, containsMessage("WARN", "warn!", logs))
+		assert.True(t, containsMessage("DEBUG", "debug!", logs))
+		assert.True(t, containsMessage("ERROR", "error!", logs))
+
+		f.Close()
+		assert.True(t, f.closed)
+
+		//ensure f.Close() is concurrent-safe and free of deadlocks
+		var wg sync.WaitGroup
+		for i := 0; i < 100; i++ {
+			wg.Add(1)
+			go func() {
+				defer wg.Done()
+				f.Close()
+			}()
+		}
+		wg.Wait()
+		assert.True(t, f.closed)
+	})
+}
+
 func TestLog(t *testing.T) {
 	defer func(old Logger) { UseLogger(old) }(logger)
 	tp := &testLogger{}
@@ -195,3 +267,12 @@ func hasMsg(lvl, m string, lines []string) bool {
 func msg(lvl, msg string) string {
 	return fmt.Sprintf("%s %s: %s", prefixMsg, lvl, msg)
 }
+
+func containsMessage(lvl, m string, lines []string) bool {
+	for _, line := range lines {
+		if strings.Contains(line, msg(lvl, m)) {
+			return true
+		}
+	}
+	return false
+}