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 6c91bebe0..daf5fb970 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)