Make log_level centrally configurable (#859)

$ELASTIC_APM_LOG_LEVEL now defines the local
value, and this can be overridden via central
config. If central config is updated and then
removed, we'll revert back to the local value
like with other config.

If a custom logger is defined, the log_level
attribute is ignored regardless of whether
central config is used.

config.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/pkg/errors"
 
+	"go.elastic.co/apm/internal/apmlog"
 	"go.elastic.co/apm/internal/configutil"
 	"go.elastic.co/apm/internal/wildcard"
 	"go.elastic.co/apm/model"
@@ -397,6 +398,22 @@ func (t *Tracer) updateRemoteConfig(logger WarningLogger, old, attrs map[string]
 					cfg.extendedSampler, _ = sampler.(ExtendedSampler)
 				})
 			}
+		case apmlog.EnvLogLevel:
+			level, err := apmlog.ParseLogLevel(v)
+			if err != nil {
+				errorf("central config failure: %s", err)
+				delete(attrs, k)
+				continue
+			}
+			if apmlog.DefaultLogger != nil && apmlog.DefaultLogger == logger {
+				updates = append(updates, func(*instrumentationConfig) {
+					apmlog.DefaultLogger.SetLevel(level)
+				})
+			} else {
+				warningf("central config ignored: %s set to %s, but custom logger in use", k, v)
+				delete(attrs, k)
+				continue
+			}
 		default:
 			warningf("central config failure: unsupported config: %s", k)
 			delete(attrs, k)

config_test.go

@@ -20,10 +20,12 @@ package apm_test
 import (
 	"context"
 	"encoding/json"
+	"io/ioutil"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
 	"os"
+	"path/filepath"
 	"strconv"
 	"strings"
 	"testing"
@@ -36,6 +38,7 @@ import (
 	"go.elastic.co/apm"
 	"go.elastic.co/apm/apmconfig"
 	"go.elastic.co/apm/apmtest"
+	"go.elastic.co/apm/internal/apmlog"
 	"go.elastic.co/apm/transport"
 	"go.elastic.co/apm/transport/transporttest"
 )
@@ -44,7 +47,7 @@ func TestTracerCentralConfigUpdate(t *testing.T) {
 	run := func(configKey, configValue string, isRemote func(*apmtest.RecordingTracer) bool) {
 		t.Run(configKey, func(t *testing.T) {
 			response, _ := json.Marshal(map[string]string{configKey: configValue})
-			testTracerCentralConfigUpdate(t, string(response), isRemote)
+			testTracerCentralConfigUpdate(t, apmtest.NewTestLogger(t), string(response), isRemote)
 		})
 	}
 	run("transaction_sample_rate", "0", func(tracer *apmtest.RecordingTracer) bool {
@@ -97,9 +100,31 @@ func TestTracerCentralConfigUpdate(t *testing.T) {
 		assert.Len(t, payloads.Transactions[0].Context.Request.Cookies, 1)
 		return payloads.Transactions[0].Context.Request.Cookies[0].Value == "[REDACTED]"
 	})
+	t.Run("log_level", func(t *testing.T) {
+		tempdir, err := ioutil.TempDir("", "apmtest_log_level")
+		require.NoError(t, err)
+		defer os.RemoveAll(tempdir)
+
+		logfile := filepath.Join(tempdir, "apm.log")
+		os.Setenv(apmlog.EnvLogFile, logfile)
+		os.Setenv(apmlog.EnvLogLevel, "off")
+		defer os.Unsetenv(apmlog.EnvLogFile)
+		defer os.Unsetenv(apmlog.EnvLogLevel)
+		apmlog.InitDefaultLogger()
+
+		response, _ := json.Marshal(map[string]string{"log_level": "debug"})
+		testTracerCentralConfigUpdate(t, apmlog.DefaultLogger, string(response), func(tracer *apmtest.RecordingTracer) bool {
+			require.NoError(t, os.Truncate(logfile, 0))
+			tracer.StartTransaction("name", "type").End()
+			tracer.Flush(nil)
+			log, err := ioutil.ReadFile(logfile)
+			require.NoError(t, err)
+			return len(log) > 0
+		})
+	})
 }
 
-func testTracerCentralConfigUpdate(t *testing.T, serverResponse string, isRemote func(*apmtest.RecordingTracer) bool) {
+func testTracerCentralConfigUpdate(t *testing.T, logger apm.Logger, serverResponse string, isRemote func(*apmtest.RecordingTracer) bool) {
 	type response struct {
 		etag string
 		body string
@@ -139,7 +164,7 @@ func testTracerCentralConfigUpdate(t *testing.T, serverResponse string, isRemote
 	// configuration.
 	t.Parallel()
 
-	tracer.SetLogger(apmtest.NewTestLogger(t))
+	tracer.SetLogger(logger)
 	assert.False(t, isRemote(tracer))
 
 	timeout := time.After(10 * time.Second)

internal/apmcloudutil/provider.go

@@ -24,7 +24,6 @@ import (
 	"net/http"
 	"time"
 
-	"go.elastic.co/apm/internal/apmlog"
 	"go.elastic.co/apm/model"
 )
 
@@ -81,11 +80,11 @@ func ParseProvider(s string) (Provider, error) {
 //
 // It is the caller's responsibility to set a reasonable timeout, to ensure
 // requests do not block normal operation in non-cloud environments.
-func (p Provider) GetCloudMetadata(ctx context.Context, logger apmlog.Logger, out *model.Cloud) bool {
+func (p Provider) GetCloudMetadata(ctx context.Context, logger Logger, out *model.Cloud) bool {
 	return p.getCloudMetadata(ctx, defaultClient, logger, out)
 }
 
-func (p Provider) getCloudMetadata(ctx context.Context, client *http.Client, logger apmlog.Logger, out *model.Cloud) bool {
+func (p Provider) getCloudMetadata(ctx context.Context, client *http.Client, logger Logger, out *model.Cloud) bool {
 	if p == None {
 		return false
 	}
@@ -117,3 +116,8 @@ func (p Provider) getCloudMetadata(ctx context.Context, client *http.Client, log
 	}
 	return false
 }
+
+// Logger defines the interface for logging while fetching cloud metadata.
+type Logger interface {
+	Warningf(format string, args ...interface{})
+}

internal/apmcloudutil/provider_test.go

@@ -29,7 +29,6 @@ import (
 
 	"github.com/stretchr/testify/assert"
 
-	"go.elastic.co/apm/internal/apmlog"
 	"go.elastic.co/apm/model"
 )
 
@@ -86,8 +85,8 @@ func (rt *targetedRoundTripper) RoundTrip(req *http.Request) (*http.Response, er
 }
 
 type testLogger struct {
-	apmlog.Logger // panic on unexpected method calls
-	buf           bytes.Buffer
+	Logger // panic on unexpected method calls
+	buf    bytes.Buffer
 }
 
 func (tl *testLogger) Warningf(format string, args ...interface{}) {

internal/apmlog/logger.go

@@ -24,14 +24,26 @@ import (
 	"os"
 	"strings"
 	"sync"
+	"sync/atomic"
 	"time"
 
 	"go.elastic.co/fastjson"
 )
 
+const (
+	// EnvLogFile is the environment variable that controls where the default logger writes.
+	EnvLogFile = "ELASTIC_APM_LOG_FILE"
+
+	// EnvLogLevel is the environment variable that controls the default logger's level.
+	EnvLogLevel = "ELASTIC_APM_LOG_LEVEL"
+
+	// DefaultLevel holds the default log level, if EnvLogLevel is not specified.
+	DefaultLevel Level = ErrorLevel
+)
+
 var (
 	// DefaultLogger is the default Logger to use, if ELASTIC_APM_LOG_* are specified.
-	DefaultLogger Logger
+	DefaultLogger *LevelLogger
 
 	fastjsonPool = &sync.Pool{
 		New: func() interface{} {
@@ -41,12 +53,15 @@ var (
 )
 
 func init() {
-	initDefaultLogger()
+	InitDefaultLogger()
 }
 
-func initDefaultLogger() {
-	fileStr := strings.TrimSpace(os.Getenv("ELASTIC_APM_LOG_FILE"))
+// InitDefaultLogger initialises DefaultLogger using the environment variables
+// ELASTIC_APM_LOG_FILE and ELASTIC_APM_LOG_LEVEL.
+func InitDefaultLogger() {
+	fileStr := strings.TrimSpace(os.Getenv(EnvLogFile))
 	if fileStr == "" {
+		DefaultLogger = nil
 		return
 	}
 
@@ -65,85 +80,98 @@ func initDefaultLogger() {
 		logWriter = &syncFile{File: f}
 	}
 
-	logLevel := errorLevel
-	if levelStr := strings.TrimSpace(os.Getenv("ELASTIC_APM_LOG_LEVEL")); levelStr != "" {
-		level, err := parseLogLevel(levelStr)
+	logLevel := DefaultLevel
+	if levelStr := strings.TrimSpace(os.Getenv(EnvLogLevel)); levelStr != "" {
+		level, err := ParseLogLevel(levelStr)
 		if err != nil {
-			log.Printf("invalid ELASTIC_APM_LOG_LEVEL %q, falling back to %q", levelStr, logLevel)
+			log.Printf("invalid %s %q, falling back to %q", EnvLogLevel, levelStr, logLevel)
 		} else {
 			logLevel = level
 		}
 	}
-	DefaultLogger = levelLogger{w: logWriter, level: logLevel}
+	DefaultLogger = &LevelLogger{w: logWriter, level: logLevel}
 }
 
+// Log levels.
 const (
-	debugLevel logLevel = iota
-	infoLevel
-	warnLevel
-	errorLevel
-	noLevel
+	DebugLevel Level = iota
+	InfoLevel
+	WarnLevel
+	ErrorLevel
+	CriticalLevel
+	OffLevel
 )
 
-type logLevel uint8
+// Level represents a log level.
+type Level uint32
 
-func (l logLevel) String() string {
+func (l Level) String() string {
 	switch l {
-	case debugLevel:
+	case DebugLevel:
 		return "debug"
-	case infoLevel:
+	case InfoLevel:
 		return "info"
-	case warnLevel:
+	case WarnLevel:
 		return "warn"
-	case errorLevel:
+	case ErrorLevel:
 		return "error"
 	}
 	return ""
 }
 
-func parseLogLevel(s string) (logLevel, error) {
+// ParseLogLevel parses s as a log level.
+func ParseLogLevel(s string) (Level, error) {
 	switch strings.ToLower(s) {
 	case "debug":
-		return debugLevel, nil
+		return DebugLevel, nil
 	case "info":
-		return infoLevel, nil
+		return InfoLevel, nil
 	case "warn":
-		return warnLevel, nil
+		return WarnLevel, nil
 	case "error":
-		return errorLevel, nil
+		return ErrorLevel, nil
+	case "critical":
+		return CriticalLevel, nil
+	case "off":
+		return OffLevel, nil
 	}
-	return noLevel, fmt.Errorf("invalid log level string %q", s)
+	return OffLevel, fmt.Errorf("invalid log level string %q", s)
 }
 
-// Logger provides methods for logging.
-type Logger interface {
-	Debugf(format string, args ...interface{})
-	Errorf(format string, args ...interface{})
-	Warningf(format string, args ...interface{})
+// LevelLogger is a level logging implementation that will log to a file,
+// stdout, or stderr. The level may be updated dynamically via SetLevel.
+type LevelLogger struct {
+	level Level // should be accessed with sync/atomic
+	w     io.Writer
 }
 
-type levelLogger struct {
-	w     io.Writer
-	level logLevel
+// Level returns the current logging level.
+func (l *LevelLogger) Level() Level {
+	return Level(atomic.LoadUint32((*uint32)(&l.level)))
+}
+
+// SetLevel sets level as the minimum logging level.
+func (l *LevelLogger) SetLevel(level Level) {
+	atomic.StoreUint32((*uint32)(&l.level), uint32(level))
 }
 
 // Debugf logs a message with log.Printf, with a DEBUG prefix.
-func (l levelLogger) Debugf(format string, args ...interface{}) {
-	l.logf(debugLevel, format, args...)
+func (l *LevelLogger) Debugf(format string, args ...interface{}) {
+	l.logf(DebugLevel, format, args...)
 }
 
 // Errorf logs a message with log.Printf, with an ERROR prefix.
-func (l levelLogger) Errorf(format string, args ...interface{}) {
-	l.logf(errorLevel, format, args...)
+func (l *LevelLogger) Errorf(format string, args ...interface{}) {
+	l.logf(ErrorLevel, format, args...)
 }
 
 // Warningf logs a message with log.Printf, with a WARNING prefix.
-func (l levelLogger) Warningf(format string, args ...interface{}) {
-	l.logf(warnLevel, format, args...)
+func (l *LevelLogger) Warningf(format string, args ...interface{}) {
+	l.logf(WarnLevel, format, args...)
 }
 
-func (l levelLogger) logf(level logLevel, format string, args ...interface{}) {
-	if level < l.level {
+func (l *LevelLogger) logf(level Level, format string, args ...interface{}) {
+	if level < l.Level() {
 		return
 	}
 	jw := fastjsonPool.Get().(*fastjson.Writer)

internal/apmlog/logger_test.go

@@ -37,7 +37,7 @@ func init() {
 
 func TestInitDefaultLoggerNoEnv(t *testing.T) {
 	DefaultLogger = nil
-	initDefaultLogger()
+	InitDefaultLogger()
 	assert.Nil(t, DefaultLogger)
 }
 
@@ -48,7 +48,7 @@ func TestInitDefaultLoggerInvalidFile(t *testing.T) {
 	DefaultLogger = nil
 	os.Setenv("ELASTIC_APM_LOG_FILE", ".")
 	defer os.Unsetenv("ELASTIC_APM_LOG_FILE")
-	initDefaultLogger()
+	InitDefaultLogger()
 
 	assert.Nil(t, DefaultLogger)
 	assert.Regexp(t, `failed to create "\.": .* \(disabling logging\)`, logbuf.String())
@@ -62,7 +62,7 @@ func TestInitDefaultLoggerFile(t *testing.T) {
 	DefaultLogger = nil
 	os.Setenv("ELASTIC_APM_LOG_FILE", filepath.Join(dir, "log.json"))
 	defer os.Unsetenv("ELASTIC_APM_LOG_FILE")
-	initDefaultLogger()
+	InitDefaultLogger()
 
 	require.NotNil(t, DefaultLogger)
 	DefaultLogger.Debugf("debug message")
@@ -95,7 +95,7 @@ func TestInitDefaultLoggerStdio(t *testing.T) {
 	for _, filename := range []string{"stdout", "stderr"} {
 		DefaultLogger = nil
 		os.Setenv("ELASTIC_APM_LOG_FILE", filename)
-		initDefaultLogger()
+		InitDefaultLogger()
 		require.NotNil(t, DefaultLogger)
 		DefaultLogger.Errorf("%s", filename)
 	}
@@ -122,7 +122,7 @@ func TestInitDefaultLoggerInvalidLevel(t *testing.T) {
 	os.Setenv("ELASTIC_APM_LOG_LEVEL", "panic")
 	defer os.Unsetenv("ELASTIC_APM_LOG_FILE")
 	defer os.Unsetenv("ELASTIC_APM_LOG_LEVEL")
-	initDefaultLogger()
+	InitDefaultLogger()
 
 	require.NotNil(t, DefaultLogger)
 	DefaultLogger.Debugf("debug message")
@@ -147,7 +147,7 @@ func TestInitDefaultLoggerLevel(t *testing.T) {
 	os.Setenv("ELASTIC_APM_LOG_LEVEL", "debug")
 	defer os.Unsetenv("ELASTIC_APM_LOG_FILE")
 	defer os.Unsetenv("ELASTIC_APM_LOG_LEVEL")
-	initDefaultLogger()
+	InitDefaultLogger()
 
 	require.NotNil(t, DefaultLogger)
 	DefaultLogger.Debugf("debug message")
@@ -169,7 +169,7 @@ func BenchmarkDefaultLogger(b *testing.B) {
 	DefaultLogger = nil
 	os.Setenv("ELASTIC_APM_LOG_FILE", filepath.Join(dir, "log.json"))
 	defer os.Unsetenv("ELASTIC_APM_LOG_FILE")
-	initDefaultLogger()
+	InitDefaultLogger()
 	require.NotNil(b, DefaultLogger)
 
 	b.ResetTimer()