From 491755fcfa848f61a5af47a8eabc1c3ebce59179 Mon Sep 17 00:00:00 2001 From: Andrew Wilkins Date: Thu, 10 Dec 2020 18:56:01 +0800 Subject: [PATCH] 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 | 17 ++++ config_test.go | 31 ++++++- internal/apmcloudutil/provider.go | 10 ++- internal/apmcloudutil/provider_test.go | 5 +- internal/apmlog/logger.go | 112 +++++++++++++++---------- internal/apmlog/logger_test.go | 14 ++-- tracer.go | 8 ++ utils.go | 2 +- 8 files changed, 140 insertions(+), 59 deletions(-) diff --git a/config.go b/config.go index 5e5411b50..5a99487e1 100644 --- a/config.go +++ b/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) diff --git a/config_test.go b/config_test.go index 7edfd31e0..1cf0bd8e5 100644 --- a/config_test.go +++ b/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) diff --git a/internal/apmcloudutil/provider.go b/internal/apmcloudutil/provider.go index 96843a1ee..0389945cf 100644 --- a/internal/apmcloudutil/provider.go +++ b/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{}) +} diff --git a/internal/apmcloudutil/provider_test.go b/internal/apmcloudutil/provider_test.go index bf970f4c3..c84a1f8ac 100644 --- a/internal/apmcloudutil/provider_test.go +++ b/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{}) { diff --git a/internal/apmlog/logger.go b/internal/apmlog/logger.go index d5cb16893..fae24934f 100644 --- a/internal/apmlog/logger.go +++ b/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) diff --git a/internal/apmlog/logger_test.go b/internal/apmlog/logger_test.go index 58018f07f..9e2cd8120 100644 --- a/internal/apmlog/logger_test.go +++ b/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() diff --git a/tracer.go b/tracer.go index 66dc57484..30f33a094 100644 --- a/tracer.go +++ b/tracer.go @@ -426,6 +426,14 @@ func newTracer(opts TracerOptions) *Tracer { t.setLocalInstrumentationConfig(envSanitizeFieldNames, func(cfg *instrumentationConfigValues) { cfg.sanitizedFieldNames = opts.sanitizedFieldNames }) + if apmlog.DefaultLogger != nil { + defaultLogLevel := apmlog.DefaultLogger.Level() + t.setLocalInstrumentationConfig(apmlog.EnvLogLevel, func(cfg *instrumentationConfigValues) { + // Revert to the original, local, log level when + // the centrally defined log level is removed. + apmlog.DefaultLogger.SetLevel(defaultLogLevel) + }) + } if !opts.active { t.active = 0 diff --git a/utils.go b/utils.go index 165e52ee5..21d3efc5c 100644 --- a/utils.go +++ b/utils.go @@ -178,7 +178,7 @@ func getCloudMetadata() *model.Cloud { var err error provider, err = apmcloudutil.ParseProvider(str) if err != nil && logger != nil { - logger.Warningf("disabling cloud metadata: %s", envCloudProvider, err) + logger.Warningf("disabling %q cloud metadata: %s", envCloudProvider, err) } } ctx, cancel := context.WithTimeout(context.Background(), time.Second)