Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Make log_level centrally configurable #859

Merged
merged 8 commits into from
Dec 10, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 17 additions & 0 deletions config.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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)
Expand Down
31 changes: 28 additions & 3 deletions config_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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"
)
Expand All @@ -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 {
Expand Down Expand Up @@ -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) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I might be missing something - but are there any tests for actually applying the remote log level and also falling back to the local config if a remote config is no longer provided?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

testTracerCentralConfigUpdate (which this test calls) does that in

apm-agent-go/config_test.go

Lines 142 to 165 in 879c34a

tracer.SetLogger(apmtest.NewTestLogger(t))
assert.False(t, isRemote(tracer))
timeout := time.After(10 * time.Second)
// We each response payload twice, which causes us to block until
// the first one is fully consumed.
for i := 0; i < 2; i++ {
select {
case responses <- response{etag: "foo", body: serverResponse}:
case <-timeout:
t.Fatal("timed out waiting for config update")
}
}
assert.True(t, isRemote(tracer))
for i := 0; i < 2; i++ {
select {
case responses <- response{etag: "bar", body: "{}"}:
case <-timeout:
t.Fatal("timed out waiting for config update")
}
}
assert.False(t, isRemote(tracer))
.

Each of these sub-tests defines a config key, value to set remotely, and a predicate that indicates whether the remote config has been applied. The code block I pointed to first checks that with the initial tracer config the predicate returns false; then sets the remote config and checks the predicate returns true; then clears out all remote config and again checks that the predicate returns false.

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
Expand Down Expand Up @@ -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)
Expand Down
10 changes: 7 additions & 3 deletions internal/apmcloudutil/provider.go
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,6 @@ import (
"net/http"
"time"

"go.elastic.co/apm/internal/apmlog"
"go.elastic.co/apm/model"
)

Expand Down Expand Up @@ -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
}
Expand Down Expand Up @@ -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{})
}
5 changes: 2 additions & 3 deletions internal/apmcloudutil/provider_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,6 @@ import (

"github.com/stretchr/testify/assert"

"go.elastic.co/apm/internal/apmlog"
"go.elastic.co/apm/model"
)

Expand Down Expand Up @@ -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{}) {
Expand Down
112 changes: 70 additions & 42 deletions internal/apmlog/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{} {
Expand All @@ -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
}

Expand All @@ -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:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

CriticalLevel is missing

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice catch, thanks!

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":
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(This is my first time looking at the go agent, and really reviewing much Go code at all, so feel free to ignore if I'm missing something obvious.)

The spec uses "warning" rather than "warn". Is this function parsing level strings from central config?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@trentm Thanks, nice pick up! You're quite right, I missed that. I'll open another PR to fix it.

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)
Expand Down
14 changes: 7 additions & 7 deletions internal/apmlog/logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,7 @@ func init() {

func TestInitDefaultLoggerNoEnv(t *testing.T) {
DefaultLogger = nil
initDefaultLogger()
InitDefaultLogger()
assert.Nil(t, DefaultLogger)
}

Expand All @@ -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())
Expand All @@ -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")
Expand Down Expand Up @@ -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)
}
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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()
Expand Down
Loading