ddtrace/tracer: add startup logging (DataDog#685)

This commit adds a json-formatted log line and other diagnostic messages to
tracer startup in order make debugging the tracer easier.

ddtrace/tracer/log.go

@@ -0,0 +1,107 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+package tracer
+
+import (
+	"encoding/json"
+	"fmt"
+	"math"
+	"net/http"
+	"runtime"
+	"time"
+
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/globalconfig"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/version"
+)
+
+const (
+	unknown = "unknown"
+)
+
+// startupInfo contains various information about the status of the tracer on startup.
+type startupInfo struct {
+	Date                  string            `json:"date"`                    // ISO 8601 date and time of start
+	OSName                string            `json:"os_name"`                 // Windows, Darwin, Debian, etc.
+	OSVersion             string            `json:"os_version"`              // Version of the OS
+	Version               string            `json:"version"`                 // Tracer version
+	Lang                  string            `json:"lang"`                    // "Go"
+	LangVersion           string            `json:"lang_version"`            // Go version, e.g. go1.13
+	Env                   string            `json:"env"`                     // Tracer env
+	Service               string            `json:"service"`                 // Tracer Service
+	AgentURL              string            `json:"agent_url"`               // The address of the agent
+	AgentError            string            `json:"agent_error"`             // Any error that occurred trying to connect to agent
+	Debug                 bool              `json:"debug"`                   // Whether debug mode is enabled
+	AnalyticsEnabled      bool              `json:"analytics_enabled"`       // True if there is a global analytics rate set
+	SampleRate            string            `json:"sample_rate"`             // The default sampling rate for the rules sampler
+	SamplingRules         []SamplingRule    `json:"sampling_rules"`          // Rules used by the rules sampler
+	SamplingRulesError    string            `json:"sampling_rules_error"`    // Any errors that occurred while parsing sampling rules
+	Tags                  map[string]string `json:"tags"`                    // Global tags
+	RuntimeMetricsEnabled bool              `json:"runtime_metrics_enabled"` // Whether or not runtime metrics are enabled
+	HealthMetricsEnabled  bool              `json:"health_metrics_enabled"`  // Whether or not health metrics are enabled
+	ApplicationVersion    string            `json:"dd_version"`              // Version of the user's application
+	Architecture          string            `json:"architecture"`            // Architecture of host machine
+	GlobalService         string            `json:"global_service"`          // Global service string. If not-nil should be same as Service. (#614)
+}
+
+// checkEndpoint tries to connect to the URL specified by endpoint.
+// If the endpoint is not reachable, checkEndpoint returns an error
+// explaining why.
+func checkEndpoint(endpoint string) error {
+	req, err := http.NewRequest("POST", endpoint, nil)
+	if err != nil {
+		return fmt.Errorf("cannot create http request: %v", err)
+	}
+	_, err = defaultClient.Do(req)
+	if err != nil {
+		return err
+	}
+	return nil
+}
+
+// logStartup generates a startupInfo for a tracer and writes it to the log in
+// JSON format.
+func logStartup(t *tracer) {
+	tags := make(map[string]string)
+	for k, v := range t.globalTags {
+		tags[k] = fmt.Sprintf("%v", v)
+	}
+
+	info := startupInfo{
+		Date:                  time.Now().Format(time.RFC3339),
+		OSName:                osName(),
+		OSVersion:             osVersion(),
+		Version:               version.Tag,
+		Lang:                  "Go",
+		LangVersion:           runtime.Version(),
+		Env:                   t.config.env,
+		Service:               t.config.serviceName,
+		AgentURL:              t.transport.endpoint(),
+		Debug:                 t.config.debug,
+		AnalyticsEnabled:      !math.IsNaN(globalconfig.AnalyticsRate()),
+		SampleRate:            fmt.Sprintf("%f", t.rulesSampling.globalRate),
+		SamplingRules:         t.rulesSampling.rules,
+		Tags:                  tags,
+		RuntimeMetricsEnabled: t.config.runtimeMetrics,
+		HealthMetricsEnabled:  t.config.runtimeMetrics,
+		ApplicationVersion:    t.config.version,
+		Architecture:          runtime.GOARCH,
+		GlobalService:         globalconfig.ServiceName(),
+	}
+	if _, err := samplingRulesFromEnv(); err != nil {
+		info.SamplingRulesError = fmt.Sprintf("%s", err)
+	}
+	if err := checkEndpoint(t.transport.endpoint()); err != nil {
+		info.AgentError = fmt.Sprintf("%s", err)
+		log.Warn("DIAGNOSTICS Unable to reach agent: %s", err)
+	}
+	bs, err := json.Marshal(info)
+	if err != nil {
+		log.Warn("DIAGNOSTICS Failed to serialize json for startup log (%v) %#v\n", err, info)
+		return
+	}
+	log.Info("DATADOG TRACER CONFIGURATION %s\n", string(bs))
+}

ddtrace/tracer/log_test.go

@@ -0,0 +1,96 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+package tracer
+
+import (
+	"math"
+	"os"
+	"testing"
+
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/globalconfig"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestStartupLog(t *testing.T) {
+	t.Run("basic", func(t *testing.T) {
+		assert := assert.New(t)
+		tp := new(testLogger)
+		tracer, _, _, stop := startTestTracer(t, WithLogger(tp))
+		defer stop()
+
+		tp.Reset()
+		logStartup(tracer)
+		assert.Len(tp.Lines(), 2)
+		assert.Regexp(`Datadog Tracer v[0-9]+\.[0-9]+\.[0-9]+ INFO: DATADOG TRACER CONFIGURATION {"date":"[^"]*","os_name":"[^"]*","os_version":"[^"]*","version":"[^"]*","lang":"Go","lang_version":"[^"]*","env":"","service":"tracer\.test","agent_url":"http://localhost:9/v0.4/traces","agent_error":"Post .*","debug":false,"analytics_enabled":false,"sample_rate":"NaN","sampling_rules":null,"sampling_rules_error":"","tags":{},"runtime_metrics_enabled":false,"health_metrics_enabled":false,"dd_version":"","architecture":"[^"]*","global_service":""}`, tp.Lines()[1])
+	})
+
+	t.Run("configured", func(t *testing.T) {
+		assert := assert.New(t)
+		tp := new(testLogger)
+		os.Setenv("DD_TRACE_SAMPLE_RATE", "0.123")
+		defer os.Unsetenv("DD_TRACE_SAMPLE_RATE")
+		tracer, _, _, stop := startTestTracer(t,
+			WithLogger(tp),
+			WithService("configured.service"),
+			WithAgentAddr("test.host:1234"),
+			WithEnv("configuredEnv"),
+			WithGlobalTag("tag", "value"),
+			WithGlobalTag("tag2", math.NaN()),
+			WithRuntimeMetrics(),
+			WithAnalyticsRate(1.0),
+			WithServiceVersion("2.3.4"),
+			WithSamplingRules([]SamplingRule{ServiceRule("mysql", 0.75)}),
+			WithDebugMode(true),
+		)
+		defer globalconfig.SetAnalyticsRate(math.NaN())
+		defer globalconfig.SetServiceName("")
+		defer stop()
+
+		tp.Reset()
+		logStartup(tracer)
+		assert.Len(tp.Lines(), 2)
+		assert.Regexp(`Datadog Tracer v[0-9]+\.[0-9]+\.[0-9]+ INFO: DATADOG TRACER CONFIGURATION {"date":"[^"]*","os_name":"[^"]*","os_version":"[^"]*","version":"[^"]*","lang":"Go","lang_version":"[^"]*","env":"configuredEnv","service":"configured.service","agent_url":"http://localhost:9/v0.4/traces","agent_error":"Post .*","debug":true,"analytics_enabled":true,"sample_rate":"0\.123000","sampling_rules":\[{"service":"mysql","name":"","sample_rate":0\.75}\],"sampling_rules_error":"","tags":{"tag":"value","tag2":"NaN"},"runtime_metrics_enabled":true,"health_metrics_enabled":true,"dd_version":"2.3.4","architecture":"[^"]*","global_service":"configured.service"}`, tp.Lines()[1])
+	})
+
+	t.Run("errors", func(t *testing.T) {
+		assert := assert.New(t)
+		tp := new(testLogger)
+		os.Setenv("DD_TRACE_SAMPLING_RULES", `[{"service": "some.service", "sample_rate": 0.234}, {"service": "other.service"}]`)
+		defer os.Unsetenv("DD_TRACE_SAMPLING_RULES")
+		tracer, _, _, stop := startTestTracer(t, WithLogger(tp))
+		defer stop()
+
+		tp.Reset()
+		logStartup(tracer)
+		assert.Len(tp.Lines(), 2)
+		assert.Regexp(`Datadog Tracer v[0-9]+\.[0-9]+\.[0-9]+ INFO: DATADOG TRACER CONFIGURATION {"date":"[^"]*","os_name":"[^"]*","os_version":"[^"]*","version":"[^"]*","lang":"Go","lang_version":"[^"]*","env":"","service":"tracer\.test","agent_url":"http://localhost:9/v0.4/traces","agent_error":"Post .*","debug":false,"analytics_enabled":false,"sample_rate":"NaN","sampling_rules":\[{"service":"some.service","name":"","sample_rate":0\.234}\],"sampling_rules_error":"found errors:\\n\\tat index 1: rate not provided","tags":{},"runtime_metrics_enabled":false,"health_metrics_enabled":false,"dd_version":"","architecture":"[^"]*","global_service":""}`, tp.Lines()[1])
+	})
+}
+
+func TestLogSamplingRules(t *testing.T) {
+	assert := assert.New(t)
+	tp := new(testLogger)
+	os.Setenv("DD_TRACE_SAMPLING_RULES", `[{"service": "some.service", "sample_rate": 0.234}, {"service": "other.service"}, {"service": "last.service", "sample_rate": 0.56}, {"odd": "pairs"}, {"sample_rate": 9.10}]`)
+	defer os.Unsetenv("DD_TRACE_SAMPLING_RULES")
+	_, _, _, stop := startTestTracer(t, WithLogger(tp))
+	defer stop()
+
+	assert.Len(tp.Lines(), 2)
+	assert.Contains(tp.Lines()[0], "WARN: at index 4: ignoring rule {Service: Name: Rate:9.10}: rate is out of [0.0, 1.0] range")
+	assert.Regexp(`Datadog Tracer v[0-9]+\.[0-9]+\.[0-9]+ WARN: DIAGNOSTICS Error\(s\) parsing DD_TRACE_SAMPLING_RULES: found errors:\n\tat index 1: rate not provided\n\tat index 3: rate not provided$`, tp.Lines()[1])
+}
+
+func TestLogAgentReachable(t *testing.T) {
+	assert := assert.New(t)
+	tp := new(testLogger)
+	tracer, _, _, stop := startTestTracer(t, WithLogger(tp))
+	defer stop()
+	tp.Reset()
+	logStartup(tracer)
+	assert.Len(tp.Lines(), 2)
+	assert.Regexp(`Datadog Tracer v[0-9]+\.[0-9]+\.[0-9]+ WARN: DIAGNOSTICS Unable to reach agent: Post`, tp.Lines()[0])
+}

ddtrace/tracer/option.go

@@ -12,6 +12,7 @@ import (
 	"os"
 	"path/filepath"
 	"runtime"
+	"strconv"
 	"strings"
 	"time"
 
@@ -29,6 +30,10 @@ type config struct {
 	// debug, when true, writes details to logs.
 	debug bool
 
+	// logStartup, when true, causes various startup info to be written
+	// when the tracer starts.
+	logStartup bool
+
 	// serviceName specifies the name of this application.
 	serviceName string
 
@@ -135,6 +140,7 @@ func newConfig(opts ...StartOption) *config {
 			}
 		}
 	}
+	c.logStartup = boolEnv("DD_TRACE_STARTUP_LOGS", true)
 	for _, fn := range opts {
 		fn(c)
 	}
@@ -484,3 +490,13 @@ func StackFrames(n, skip uint) FinishOption {
 		cfg.SkipStackFrames = skip
 	}
 }
+
+// boolEnv returns the parsed boolean value of an environment variable, or
+// def if it fails to parse.
+func boolEnv(key string, def bool) bool {
+	v, err := strconv.ParseBool(os.Getenv(key))
+	if err != nil {
+		return def
+	}
+	return v
+}

ddtrace/tracer/osinfo_darwin.go

@@ -0,0 +1,24 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+package tracer
+
+import (
+	"os/exec"
+	"runtime"
+	"strings"
+)
+
+func osName() string {
+	return runtime.GOOS
+}
+
+func osVersion() string {
+	out, err := exec.Command("sw_vers", "-productVersion").Output()
+	if err != nil {
+		return unknown
+	}
+	return strings.Trim(string(out), "\n")
+}

ddtrace/tracer/osinfo_default.go

@@ -0,0 +1,20 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+// +build !windows,!linux,!darwin
+
+package tracer
+
+import (
+	"runtime"
+)
+
+func osName() string {
+	return runtime.GOOS
+}
+
+func osVersion() string {
+	return unknownVersion
+}

ddtrace/tracer/osinfo_linux.go

@@ -0,0 +1,52 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+package tracer
+
+import (
+	"bufio"
+	"os"
+	"strings"
+)
+
+func osName() string {
+	f, err := os.Open("/etc/os-release")
+	if err != nil {
+		return "Linux (Unknown Distribution)"
+	}
+	defer f.Close()
+	s := bufio.NewScanner(f)
+	name := "Linux (Unknown Distribution)"
+	for s.Scan() {
+		parts := strings.SplitN(s.Text(), "=", 2)
+		switch parts[0] {
+		case "Name":
+			name = strings.Trim(parts[1], "\"")
+		}
+	}
+	return name
+}
+
+func osVersion() string {
+	f, err := os.Open("/etc/os-release")
+	if err != nil {
+		return unknown
+	}
+	defer f.Close()
+	s := bufio.NewScanner(f)
+	version := unknown
+	for s.Scan() {
+		parts := strings.SplitN(s.Text(), "=", 2)
+		switch parts[0] {
+		case "VERSION":
+			version = strings.Trim(parts[1], "\"")
+		case "VERSION_ID":
+			if version == "" {
+				version = strings.Trim(parts[1], "\"")
+			}
+		}
+	}
+	return version
+}

ddtrace/tracer/osinfo_windows.go

@@ -0,0 +1,54 @@
+// Unless explicitly stated otherwise all files in this repository are licensed
+// under the Apache License Version 2.0.
+// This product includes software developed at Datadog (https://www.datadoghq.com/).
+// Copyright 2016-2020 Datadog, Inc.
+
+package tracer
+
+import (
+	"fmt"
+	"runtime"
+	"strings"
+
+	"golang.org/x/sys/windows/registry"
+)
+
+func osName() string {
+	return runtime.GOOS
+}
+
+func osVersion() string {
+	k, err := registry.OpenKey(registry.LOCAL_MACHINE, `SOFTWARE\Microsoft\Windows NT\CurrentVersion`, registry.QUERY_VALUE)
+	if err != nil {
+		return unknown
+	}
+	defer k.Close()
+
+	var version strings.Builder
+
+	maj, _, err := k.GetIntegerValue("CurrentMajorVersionNumber")
+	if err == nil {
+		version.WriteString(fmt.Sprintf("%d", maj))
+		min, _, err := k.GetIntegerValue("CurrentMinorVersionNumber")
+		if err == nil {
+			version.WriteString(fmt.Sprintf(".%d", min))
+		}
+	} else {
+		version.WriteString(unknown)
+	}
+
+	ed, _, err := k.GetStringValue("EditionID")
+	if err == nil {
+		version.WriteString(" " + ed)
+	} else {
+		version.WriteString(" Unknown Edition")
+	}
+
+	build, _, err := k.GetStringValue("CurrentBuild")
+	if err == nil {
+		version.WriteString(" Build " + build)
+	} else {
+		version.WriteString(" Unknown Build")
+	}
+	return version.String()
+}