diff --git a/download/download.go b/download/download.go index 6396bd6328..522130f016 100644 --- a/download/download.go +++ b/download/download.go @@ -15,13 +15,11 @@ import ( "sync" "time" - "github.com/open-policy-agent/opa/sdk" - "github.com/pkg/errors" - "github.com/open-policy-agent/opa/metrics" - "github.com/open-policy-agent/opa/bundle" + "github.com/open-policy-agent/opa/logging" + "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins/rest" "github.com/open-policy-agent/opa/util" ) @@ -53,9 +51,9 @@ type Downloader struct { etag string // HTTP Etag for caching purposes sizeLimitBytes *int64 // max bundle file size in bytes (passed to reader) bvc *bundle.VerificationConfig - logger sdk.Logger respHdrTimeoutSec int64 wg sync.WaitGroup + logger logging.Logger } // New returns a new Downloader that can be started. diff --git a/internal/config/config.go b/internal/config/config.go index ef80559603..69d930f4a4 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -13,13 +13,11 @@ import ( "regexp" "strings" - "github.com/open-policy-agent/opa/sdk" - - "github.com/open-policy-agent/opa/keys" - "github.com/ghodss/yaml" "github.com/open-policy-agent/opa/internal/strvals" + "github.com/open-policy-agent/opa/keys" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/plugins/rest" "github.com/open-policy-agent/opa/util" ) @@ -29,7 +27,7 @@ type ServiceOptions struct { Raw json.RawMessage AuthPlugin func(string) rest.HTTPAuthPlugin Keys map[string]*keys.Config - Logger sdk.Logger + Logger logging.Logger } // ParseServicesConfig returns a set of named service clients. The service diff --git a/sdk/logging.go b/logging/logging.go similarity index 95% rename from sdk/logging.go rename to logging/logging.go index 50adaa0655..035f8394fe 100644 --- a/sdk/logging.go +++ b/logging/logging.go @@ -1,4 +1,4 @@ -package sdk +package logging import ( "github.com/sirupsen/logrus" @@ -45,6 +45,11 @@ func NewStandardLogger() *StandardLogger { } } +// SetFormatter sets the underlying logrus formatter. +func (l *StandardLogger) SetFormatter(formatter logrus.Formatter) { + l.logger.SetFormatter(formatter) +} + // WithFields provides additional fields to include in log output func (l *StandardLogger) WithFields(fields map[string]interface{}) Logger { cp := *l diff --git a/sdk/logging_test.go b/logging/logging_test.go similarity index 99% rename from sdk/logging_test.go rename to logging/logging_test.go index aa72c0a061..cdde32089d 100644 --- a/sdk/logging_test.go +++ b/logging/logging_test.go @@ -1,4 +1,4 @@ -package sdk +package logging import ( "testing" diff --git a/logging/test/test.go b/logging/test/test.go new file mode 100644 index 0000000000..73ea95d810 --- /dev/null +++ b/logging/test/test.go @@ -0,0 +1,93 @@ +package test + +import ( + "fmt" + + "github.com/open-policy-agent/opa/logging" +) + +// LogEntry represents a log message. +type LogEntry struct { + Level logging.Level + Fields map[string]interface{} + Message string +} + +// Logger implementation that buffers messages for test purposes. +type Logger struct { + level logging.Level + fields map[string]interface{} + entries *[]LogEntry +} + +// New instantiates new Logger. +func New() *Logger { + return &Logger{ + level: logging.Info, + entries: &[]LogEntry{}, + } +} + +// WithFields provides additional fields to include in log output. +// Implemented here primarily to be able to switch between implementations without loss of data. +func (l *Logger) WithFields(fields map[string]interface{}) logging.Logger { + cp := *l + flds := make(map[string]interface{}) + for k, v := range cp.fields { + flds[k] = v + } + for k, v := range fields { + flds[k] = v + } + cp.fields = flds + return &cp +} + +// GetFields returns additional fields of this logger +// Implemented here primarily to be able to switch between implementations without loss of data. +func (l *Logger) GetFields() map[string]interface{} { + return l.fields +} + +// Debug buffers a log message. +func (l *Logger) Debug(f string, a ...interface{}) { + l.append(logging.Debug, f, a...) +} + +// Info buffers a log message. +func (l *Logger) Info(f string, a ...interface{}) { + l.append(logging.Info, f, a...) +} + +// Error buffers a log message. +func (l *Logger) Error(f string, a ...interface{}) { + l.append(logging.Error, f, a...) +} + +// Warn buffers a log message. +func (l *Logger) Warn(f string, a ...interface{}) { + l.append(logging.Warn, f, a...) +} + +// SetLevel set log level. +func (l *Logger) SetLevel(level logging.Level) { + l.level = level +} + +// GetLevel get log level. +func (l *Logger) GetLevel() logging.Level { + return l.level +} + +// Entries returns buffered log entries. +func (l *Logger) Entries() []LogEntry { + return *l.entries +} + +func (l *Logger) append(lvl logging.Level, f string, a ...interface{}) { + *l.entries = append(*l.entries, LogEntry{ + Level: lvl, + Fields: l.fields, + Message: fmt.Sprintf(f, a...), + }) +} diff --git a/plugins/bundle/plugin.go b/plugins/bundle/plugin.go index 186faa497e..4e2d909d23 100644 --- a/plugins/bundle/plugin.go +++ b/plugins/bundle/plugin.go @@ -17,12 +17,11 @@ import ( "sync" "time" - "github.com/open-policy-agent/opa/sdk" - "github.com/open-policy-agent/opa/ast" "github.com/open-policy-agent/opa/bundle" "github.com/open-policy-agent/opa/download" bundleUtils "github.com/open-policy-agent/opa/internal/bundle" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/storage" @@ -37,7 +36,7 @@ type Plugin struct { listeners map[interface{}]func(Status) // listeners to send status updates to bulkListeners map[interface{}]func(map[string]*Status) // listeners to send aggregated status updates to downloaders map[string]*download.Downloader - logger sdk.Logger + logger logging.Logger mtx sync.Mutex cfgMtx sync.Mutex legacyConfig bool @@ -570,9 +569,9 @@ func loadBundleFromDisk(path, name string, src *Source) (*bundle.Bundle, error) } } -func (p *Plugin) log(name string) sdk.Logger { +func (p *Plugin) log(name string) logging.Logger { if p.logger == nil { - p.logger = sdk.NewStandardLogger() + p.logger = logging.NewStandardLogger() } return p.logger.WithFields(map[string]interface{}{"name": name, "plugin": Name}) } diff --git a/plugins/discovery/discovery.go b/plugins/discovery/discovery.go index 0e916d95f8..2398e8dd87 100644 --- a/plugins/discovery/discovery.go +++ b/plugins/discovery/discovery.go @@ -11,14 +11,13 @@ import ( "fmt" "sync" - "github.com/open-policy-agent/opa/sdk" - "github.com/open-policy-agent/opa/ast" bundleApi "github.com/open-policy-agent/opa/bundle" "github.com/open-policy-agent/opa/config" "github.com/open-policy-agent/opa/download" cfg "github.com/open-policy-agent/opa/internal/config" "github.com/open-policy-agent/opa/keys" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/bundle" @@ -43,7 +42,7 @@ type Discovery struct { etag string // discovery bundle etag for caching purposes metrics metrics.Metrics readyOnce sync.Once - logger sdk.Logger + logger logging.Logger } // Factories provides a set of factory functions to use for diff --git a/plugins/discovery/discovery_test.go b/plugins/discovery/discovery_test.go index a7d46d2584..251b145dde 100644 --- a/plugins/discovery/discovery_test.go +++ b/plugins/discovery/discovery_test.go @@ -16,8 +16,7 @@ import ( "testing" "time" - "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/ast" bundleApi "github.com/open-policy-agent/opa/bundle" @@ -999,16 +998,10 @@ func TestStatusUpdatesTimestamp(t *testing.T) { func TestStatusMetricsForLogDrops(t *testing.T) { - logLevel := logrus.GetLevel() - defer logrus.SetLevel(logLevel) - - // Ensure that status messages are printed to console even with the standard logger configured to log errors only - logrus.SetLevel(logrus.ErrorLevel) - - hook := test.NewLocal(plugins.GetConsoleLogger()) - ctx := context.Background() + testLogger := test.New() + manager, err := plugins.New([]byte(`{ "services": { "localhost": { @@ -1016,7 +1009,7 @@ func TestStatusMetricsForLogDrops(t *testing.T) { } }, "discovery": {"name": "config"}, - }`), "test-id", inmem.New()) + }`), "test-id", inmem.New(), plugins.ConsoleLogger(testLogger)) if err != nil { t.Fatal(err) } @@ -1095,7 +1088,7 @@ func TestStatusMetricsForLogDrops(t *testing.T) { } }`)}) - entries := hook.AllEntries() + entries := testLogger.Entries() if len(entries) == 0 { t.Fatal("Expected log entries but got none") } @@ -1103,11 +1096,11 @@ func TestStatusMetricsForLogDrops(t *testing.T) { // Pick the last entry as it should have the drop count e := entries[len(entries)-1] - if _, ok := e.Data["metrics"]; !ok { + if _, ok := e.Fields["metrics"]; !ok { t.Fatal("Expected metrics") } - builtInMet := e.Data["metrics"].(map[string]interface{})[""] + builtInMet := e.Fields["metrics"].(map[string]interface{})[""] dropCount := builtInMet.(map[string]interface{})["counter_decision_logs_dropped"] actual, err := dropCount.(json.Number).Int64() diff --git a/plugins/logs/plugin.go b/plugins/logs/plugin.go index 26541d97e9..8e5a9eadc5 100644 --- a/plugins/logs/plugin.go +++ b/plugins/logs/plugin.go @@ -9,7 +9,6 @@ import ( "context" "encoding/json" "fmt" - "math" "math/rand" "net/http" @@ -19,16 +18,15 @@ import ( "time" "github.com/pkg/errors" - "golang.org/x/time/rate" "github.com/open-policy-agent/opa/ast" "github.com/open-policy-agent/opa/internal/ref" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/rest" "github.com/open-policy-agent/opa/rego" - "github.com/open-policy-agent/opa/sdk" "github.com/open-policy-agent/opa/server" "github.com/open-policy-agent/opa/storage" "github.com/open-policy-agent/opa/util" @@ -345,9 +343,9 @@ type Plugin struct { reconfig chan reconfigure mask *rego.PreparedEvalQuery maskMutex sync.Mutex - logger sdk.Logger limiter *rate.Limiter metrics metrics.Metrics + logger logging.Logger } type reconfigure struct { @@ -809,7 +807,7 @@ func (p *Plugin) logEvent(event EventV1) error { if err != nil { return err } - plugins.GetConsoleLogger().WithFields(fields).WithFields(map[string]interface{}{ + p.manager.ConsoleLogger().WithFields(fields).WithFields(map[string]interface{}{ "type": "openpolicyagent.org/decision_logs", }).Info("Decision Log") return nil diff --git a/plugins/logs/plugin_test.go b/plugins/logs/plugin_test.go index db53b19763..502ee43d21 100644 --- a/plugins/logs/plugin_test.go +++ b/plugins/logs/plugin_test.go @@ -20,6 +20,7 @@ import ( "time" "github.com/open-policy-agent/opa/ast" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/bundle" @@ -31,8 +32,6 @@ import ( "github.com/open-policy-agent/opa/topdown" "github.com/open-policy-agent/opa/util" "github.com/open-policy-agent/opa/version" - "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" ) func TestMain(m *testing.M) { @@ -44,8 +43,6 @@ type testPlugin struct { events []EventV1 } -type testPluginCustomizer func(c *Config) - func (p *testPlugin) Start(context.Context) error { return nil } @@ -456,10 +453,7 @@ func logServerInfo(id string, input interface{}, result interface{}) *server.Inf func TestPluginRequeBufferPreserved(t *testing.T) { ctx := context.Background() - fixture := newTestFixture(t, func(c *Config) { - limit := int64(300) - c.Reporting.UploadSizeLimitBytes = &limit - }) + fixture := newTestFixture(t, testFixtureOptions{ReportingUploadSizeLimitBytes: 300}) defer fixture.server.stop() fixture.server.ch = make(chan []EventV1, 3) @@ -499,12 +493,9 @@ func TestPluginRateLimitInt(t *testing.T) { numDecisions := 1 // 1 decision per second - fixture := newTestFixture(t, func(c *Config) { - limit := float64(numDecisions) - c.Reporting.MaxDecisionsPerSecond = &limit - }, func(c *Config) { - limit := int64(300) - c.Reporting.UploadSizeLimitBytes = &limit + fixture := newTestFixture(t, testFixtureOptions{ + ReportingMaxDecisionsPerSecond: float64(numDecisions), + ReportingUploadSizeLimitBytes: 300, }) defer fixture.server.stop() @@ -595,13 +586,9 @@ func TestPluginRateLimitFloat(t *testing.T) { } numDecisions := 0.1 // 0.1 decision per second ie. 1 decision per 10 seconds - - fixture := newTestFixture(t, func(c *Config) { - limit := float64(numDecisions) - c.Reporting.MaxDecisionsPerSecond = &limit - }, func(c *Config) { - limit := int64(300) - c.Reporting.UploadSizeLimitBytes = &limit + fixture := newTestFixture(t, testFixtureOptions{ + ReportingMaxDecisionsPerSecond: float64(numDecisions), + ReportingUploadSizeLimitBytes: 300, }) defer fixture.server.stop() @@ -696,12 +683,9 @@ func TestPluginRateLimitRequeue(t *testing.T) { numDecisions := 100 // 100 decisions per second - fixture := newTestFixture(t, func(c *Config) { - limit := float64(numDecisions) - c.Reporting.MaxDecisionsPerSecond = &limit - }, func(c *Config) { - limit := int64(300) - c.Reporting.UploadSizeLimitBytes = &limit + fixture := newTestFixture(t, testFixtureOptions{ + ReportingMaxDecisionsPerSecond: float64(numDecisions), + ReportingUploadSizeLimitBytes: 300, }) defer fixture.server.stop() @@ -751,13 +735,10 @@ func TestPluginRateLimitDropCountStatus(t *testing.T) { } numDecisions := 1 // 1 decision per second - - fixture := newTestFixture(t, func(c *Config) { - limit := float64(numDecisions) - c.Reporting.MaxDecisionsPerSecond = &limit - }, func(c *Config) { - limit := int64(300) - c.Reporting.UploadSizeLimitBytes = &limit + fixture := newTestFixture(t, testFixtureOptions{ + ConsoleLogger: test.New(), + ReportingMaxDecisionsPerSecond: float64(numDecisions), + ReportingUploadSizeLimitBytes: 300, }) defer fixture.server.stop() @@ -812,14 +793,6 @@ func TestPluginRateLimitDropCountStatus(t *testing.T) { panic(err) } - logLevel := logrus.GetLevel() - defer logrus.SetLevel(logLevel) - - // Ensure that status messages are printed to console even with the standard logger configured to log errors only - logrus.SetLevel(logrus.ErrorLevel) - - hook := test.NewLocal(plugins.GetConsoleLogger()) - _ = fixture.plugin.Log(ctx, event2) // event 2 should not be written into the encoder as rate limit exceeded _ = fixture.plugin.Log(ctx, event3) // event 3 should not be written into the encoder as rate limit exceeded @@ -830,7 +803,7 @@ func TestPluginRateLimitDropCountStatus(t *testing.T) { // Give the logger / console some time to process and print the events time.Sleep(10 * time.Millisecond) - entries := hook.AllEntries() + entries := fixture.consoleLogger.Entries() if len(entries) == 0 { t.Fatal("Expected log entries but got none") } @@ -838,14 +811,14 @@ func TestPluginRateLimitDropCountStatus(t *testing.T) { // Pick the last entry as it should have the drop count e := entries[len(entries)-1] - if _, ok := e.Data["metrics"]; !ok { + if _, ok := e.Fields["metrics"]; !ok { t.Fatal("Expected metrics") } exp := map[string]interface{}{"": map[string]interface{}{"counter_decision_logs_dropped": json.Number("2")}} - if !reflect.DeepEqual(e.Data["metrics"], exp) { - t.Fatalf("Expected %v but got %v", exp, e.Data["metrics"]) + if !reflect.DeepEqual(e.Fields["metrics"], exp) { + t.Fatalf("Expected %v but got %v", exp, e.Fields["metrics"]) } } @@ -1012,10 +985,9 @@ func TestPluginReconfigureUploadSizeLimit(t *testing.T) { ctx := context.Background() limit := int64(300) - fixture := newTestFixture(t, func(c *Config) { - c.Reporting.UploadSizeLimitBytes = &limit + fixture := newTestFixture(t, testFixtureOptions{ + ReportingUploadSizeLimitBytes: limit, }) - defer fixture.server.stop() if err := fixture.plugin.Start(ctx); err != nil { @@ -1352,13 +1324,20 @@ func TestPluginMasking(t *testing.T) { } } -type testFixture struct { - manager *plugins.Manager - plugin *Plugin - server *testServer +type testFixtureOptions struct { + ConsoleLogger *test.Logger + ReportingUploadSizeLimitBytes int64 + ReportingMaxDecisionsPerSecond float64 } -func newTestFixture(t *testing.T, options ...testPluginCustomizer) testFixture { +type testFixture struct { + manager *plugins.Manager + consoleLogger *test.Logger + plugin *Plugin + server *testServer +} + +func newTestFixture(t *testing.T, opts ...testFixtureOptions) testFixture { ts := testServer{ t: t, @@ -1384,14 +1363,30 @@ func newTestFixture(t *testing.T, options ...testPluginCustomizer) testFixture { } ]}`, ts.server.URL)) - manager, err := plugins.New(managerConfig, "test-instance-id", inmem.New(), plugins.GracefulShutdownPeriod(10)) + var options testFixtureOptions + + if len(opts) > 0 { + options = opts[0] + } + + manager, err := plugins.New( + managerConfig, + "test-instance-id", + inmem.New(), + plugins.GracefulShutdownPeriod(10), + plugins.ConsoleLogger(options.ConsoleLogger)) if err != nil { t.Fatal(err) } config, _ := ParseConfig([]byte(`{"service": "example"}`), manager.Services(), nil) - for _, option := range options { - option(config) + + if options.ReportingMaxDecisionsPerSecond != 0 { + config.Reporting.MaxDecisionsPerSecond = &options.ReportingMaxDecisionsPerSecond + } + + if options.ReportingUploadSizeLimitBytes != 0 { + config.Reporting.UploadSizeLimitBytes = &options.ReportingUploadSizeLimitBytes } if s, ok := manager.PluginStatus()[Name]; ok { @@ -1403,9 +1398,10 @@ func newTestFixture(t *testing.T, options ...testPluginCustomizer) testFixture { ensurePluginState(t, p, plugins.StateNotReady) return testFixture{ - manager: manager, - plugin: p, - server: &ts, + manager: manager, + consoleLogger: options.ConsoleLogger, + plugin: p, + server: &ts, } } diff --git a/plugins/plugins.go b/plugins/plugins.go index 489a483b4e..c57f8b55b4 100644 --- a/plugins/plugins.go +++ b/plugins/plugins.go @@ -11,19 +11,15 @@ import ( "sync" "time" - "github.com/open-policy-agent/opa/sdk" - - "github.com/open-policy-agent/opa/keys" - - "github.com/sirupsen/logrus" - "github.com/open-policy-agent/opa/ast" "github.com/open-policy-agent/opa/bundle" "github.com/open-policy-agent/opa/config" bundleUtils "github.com/open-policy-agent/opa/internal/bundle" cfg "github.com/open-policy-agent/opa/internal/config" initload "github.com/open-policy-agent/opa/internal/runtime/init" + "github.com/open-policy-agent/opa/keys" "github.com/open-policy-agent/opa/loader" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/plugins/rest" "github.com/open-policy-agent/opa/resolver/wasm" "github.com/open-policy-agent/opa/storage" @@ -158,7 +154,8 @@ type Manager struct { interQueryBuiltinCacheConfig *cache.Config gracefulShutdownPeriod int registeredCacheTriggers []func(*cache.Config) - logger sdk.Logger + logger logging.Logger + consoleLogger logging.Logger } type managerContextKey string @@ -167,14 +164,6 @@ type managerWasmResolverKey string const managerCompilerContextKey = managerContextKey("compiler") const managerWasmResolverContextKey = managerWasmResolverKey("wasmResolvers") -// Dedicated logger for plugins logging to console independently of configured --log-level -var logrusConsole = logrus.New() - -// GetConsoleLogger return plugin console logger -func GetConsoleLogger() *logrus.Logger { - return logrusConsole -} - // SetCompilerOnContext puts the compiler into the storage context. Calling this // function before committing updated policies to storage allows the manager to // skip parsing and compiling of modules. Instead, the manager will use the @@ -250,13 +239,22 @@ func GracefulShutdownPeriod(gracefulShutdownPeriod int) func(*Manager) { } } -// Logger configures the passed logger on the plugin manager (useful to configure default fields) -func Logger(logger sdk.Logger) func(*Manager) { +// Logger configures the passed logger on the plugin manager (useful to +// configure default fields) +func Logger(logger logging.Logger) func(*Manager) { return func(m *Manager) { m.logger = logger } } +// ConsoleLogger sets the passed logger to be used by plugins that are +// configured with console logging enabled. +func ConsoleLogger(logger logging.Logger) func(*Manager) { + return func(m *Manager) { + m.consoleLogger = logger + } +} + // New creates a new Manager using config. func New(raw []byte, id string, store storage.Store, opts ...func(*Manager)) (*Manager, error) { @@ -287,7 +285,11 @@ func New(raw []byte, id string, store storage.Store, opts ...func(*Manager)) (*M } if m.logger == nil { - m.logger = sdk.NewStandardLogger() + m.logger = logging.NewStandardLogger() + } + + if m.consoleLogger == nil { + m.consoleLogger = logging.NewStandardLogger() } serviceOpts := cfg.ServiceOptions{ @@ -743,11 +745,16 @@ func (m *Manager) Services() []string { return s } -// Logger gets the logger implementation associated with this plugin manager -func (m *Manager) Logger() sdk.Logger { +// Logger gets the standard logger for this plugin manager. +func (m *Manager) Logger() logging.Logger { return m.logger } +// ConsoleLogger gets the console logger for this plugin manager. +func (m *Manager) ConsoleLogger() logging.Logger { + return m.consoleLogger +} + // RegisterCacheTrigger accepts a func that receives new inter-query cache config generated by // a reconfigure of the plugin manager, so that it can be propagated to existing inter-query caches. func (m *Manager) RegisterCacheTrigger(trigger func(*cache.Config)) { diff --git a/plugins/plugins_test.go b/plugins/plugins_test.go index a302a86fd5..02efdd2f08 100644 --- a/plugins/plugins_test.go +++ b/plugins/plugins_test.go @@ -11,9 +11,12 @@ import ( "reflect" "testing" + "github.com/sirupsen/logrus" + "github.com/open-policy-agent/opa/internal/storage/mock" + "github.com/open-policy-agent/opa/logging" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/plugins/rest" - "github.com/open-policy-agent/opa/sdk" "github.com/open-policy-agent/opa/storage/inmem" "github.com/open-policy-agent/opa/topdown/cache" ) @@ -296,7 +299,7 @@ func TestPluginManagerAuthPlugin(t *testing.T) { func TestPluginManagerLogger(t *testing.T) { - logger := sdk.NewStandardLogger().WithFields(map[string]interface{}{"context": "myloggincontext"}) + logger := logging.NewStandardLogger().WithFields(map[string]interface{}{"context": "myloggincontext"}) m, err := New([]byte(`{}`), "test", inmem.New(), Logger(logger)) if err != nil { @@ -308,6 +311,37 @@ func TestPluginManagerLogger(t *testing.T) { } } +func TestPluginManagerConsoleLogger(t *testing.T) { + logLevel := logrus.GetLevel() + defer logrus.SetLevel(logLevel) + + // Ensure that status messages are printed to console even with the standard logger configured to log errors only + logrus.SetLevel(logrus.ErrorLevel) + + consoleLogger := test.New() + + mgr, err := New([]byte(`{}`), "", inmem.New(), ConsoleLogger(consoleLogger)) + if err != nil { + t.Fatal(err) + } + + mgr.ConsoleLogger().WithFields(map[string]interface{}{"foo": "bar"}).Info("Some message") + + entries := consoleLogger.Entries() + + exp := []test.LogEntry{ + { + Level: logging.Info, + Fields: map[string]interface{}{"foo": "bar"}, + Message: "Some message", + }, + } + + if !reflect.DeepEqual(exp, entries) { + t.Fatalf("want %v but got %v", exp, entries) + } +} + type myAuthPluginMock struct{} func (m *myAuthPluginMock) NewClient(c rest.Config) (*http.Client, error) { diff --git a/plugins/rest/aws.go b/plugins/rest/aws.go index 8af5f32c71..2d0ec0278e 100644 --- a/plugins/rest/aws.go +++ b/plugins/rest/aws.go @@ -20,7 +20,7 @@ import ( "strings" "time" - "github.com/open-policy-agent/opa/sdk" + "github.com/open-policy-agent/opa/logging" ) const ( @@ -72,7 +72,7 @@ type awsCredentialService interface { // awsEnvironmentCredentialService represents an static environment-variable credential provider for AWS type awsEnvironmentCredentialService struct { - logger sdk.Logger + logger logging.Logger } func (cs *awsEnvironmentCredentialService) credentials() (awsCredentials, error) { @@ -109,7 +109,7 @@ type awsMetadataCredentialService struct { expiration time.Time credServicePath string tokenPath string - logger sdk.Logger + logger logging.Logger } func (cs *awsMetadataCredentialService) urlForMetadataService() (string, error) { @@ -239,7 +239,7 @@ type awsWebIdentityCredentialService struct { stsURL string creds awsCredentials expiration time.Time - logger sdk.Logger + logger logging.Logger } func (cs *awsWebIdentityCredentialService) populateFromEnv() error { @@ -360,7 +360,7 @@ func isECS() bool { return isECS } -func doMetaDataRequestWithClient(req *http.Request, client *http.Client, desc string, logger sdk.Logger) ([]byte, error) { +func doMetaDataRequestWithClient(req *http.Request, client *http.Client, desc string, logger logging.Logger) ([]byte, error) { // convenience function to get the body of an AWS EC2 metadata service request with // appropriate error-handling boilerplate and logging for this special case resp, err := client.Do(req) diff --git a/plugins/rest/aws_test.go b/plugins/rest/aws_test.go index a169ee412a..b16736add4 100644 --- a/plugins/rest/aws_test.go +++ b/plugins/rest/aws_test.go @@ -15,7 +15,7 @@ import ( "testing" "time" - "github.com/open-policy-agent/opa/sdk" + "github.com/open-policy-agent/opa/logging" ) // this is usually private; but we need it here @@ -109,7 +109,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: "this is not a URL", // malformed tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } _, err := cs.credentials() assertErr("unsupported protocol scheme \"\"", err, t) @@ -118,7 +118,7 @@ func TestMetadataCredentialService(t *testing.T) { os.Unsetenv(ecsRelativePathEnvVar) cs = awsMetadataCredentialService{ RegionName: "us-east-1", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } _, err = cs.credentials() assertErr("metadata endpoint cannot be determined from settings and environment", err, t) @@ -129,7 +129,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } _, err = cs.credentials() assertErr("metadata HTTP request returned unexpected status: 404 Not Found", err, t) @@ -140,7 +140,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } _, err = cs.credentials() assertErr("failed to parse credential response from metadata service: invalid character 'T' looking for beginning of value", err, t) @@ -151,7 +151,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/missing_token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } // will 404 _, err = cs.credentials() assertErr("metadata token HTTP request returned unexpected status: 404 Not Found", err, t) @@ -162,7 +162,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/bad_token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } // not good _, err = cs.credentials() assertErr("metadata HTTP request returned unexpected status: 401 Unauthorized", err, t) @@ -179,7 +179,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } _, err = cs.credentials() assertErr("metadata service query did not succeed: Failure", err, t) @@ -196,7 +196,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } var creds awsCredentials creds, err = cs.credentials() @@ -222,7 +222,7 @@ func TestMetadataCredentialService(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -268,7 +268,7 @@ func TestV4Signing(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } req, _ := http.NewRequest("GET", "https://mybucket.s3.amazonaws.com/bundle.tar.gz", strings.NewReader("")) err := signV4(req, "s3", cs, time.Unix(1556129697, 0)) @@ -281,7 +281,7 @@ func TestV4Signing(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -318,7 +318,7 @@ func TestV4SigningForApiGateway(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -358,7 +358,7 @@ func TestV4SigningOmitsIgnoredHeaders(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -401,7 +401,7 @@ func TestV4SigningCustomPort(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -438,7 +438,7 @@ func TestV4SigningDoesNotMutateBody(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -470,7 +470,7 @@ func TestV4SigningWithMultiValueHeaders(t *testing.T) { RegionName: "us-east-1", credServicePath: ts.server.URL + "/latest/meta-data/iam/security-credentials/", tokenPath: ts.server.URL + "/latest/api/token", - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } ts.payload = metadataPayload{ AccessKeyID: "MYAWSACCESSKEYGOESHERE", @@ -565,7 +565,7 @@ func TestWebIdentityCredentialService(t *testing.T) { defer ts.stop() cs := awsWebIdentityCredentialService{ stsURL: ts.server.URL, - logger: sdk.NewStandardLogger(), + logger: logging.NewStandardLogger(), } goodTokenFile, err := ioutil.TempFile(os.TempDir(), "opa-aws-test-") diff --git a/plugins/rest/rest.go b/plugins/rest/rest.go index f6b0831390..d16494c465 100644 --- a/plugins/rest/rest.go +++ b/plugins/rest/rest.go @@ -15,12 +15,9 @@ import ( "reflect" "strings" - "github.com/open-policy-agent/opa/sdk" - - "github.com/open-policy-agent/opa/keys" - "github.com/open-policy-agent/opa/internal/version" - + "github.com/open-policy-agent/opa/keys" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/util" ) @@ -52,7 +49,7 @@ type Config struct { } `json:"credentials"` keys map[string]*keys.Config - logger sdk.Logger + logger logging.Logger } // Equal returns true if this client config is equal to the other. @@ -111,7 +108,7 @@ type Client struct { config Config headers map[string]string authPluginLookup func(string) HTTPAuthPlugin - logger sdk.Logger + logger logging.Logger } // Name returns an option that overrides the service name on the client. @@ -132,7 +129,7 @@ func AuthPluginLookup(l func(string) HTTPAuthPlugin) func(*Client) { } // Logger assigns a logger to the client -func Logger(l sdk.Logger) func(*Client) { +func Logger(l logging.Logger) func(*Client) { return func(c *Client) { c.logger = l } @@ -165,7 +162,7 @@ func New(config []byte, keys map[string]*keys.Config, opts ...func(*Client)) (Cl } if client.logger == nil { - client.logger = sdk.NewStandardLogger() + client.logger = logging.NewStandardLogger() } client.config.logger = client.logger @@ -189,7 +186,7 @@ func (c Client) SetResponseHeaderTimeout(timeout *int64) Client { } // Logger returns the logger assigned to the Client -func (c Client) Logger() sdk.Logger { +func (c Client) Logger() logging.Logger { return c.logger } diff --git a/plugins/rest/rest_auth.go b/plugins/rest/rest_auth.go index 2f633d5941..cd4229ef89 100644 --- a/plugins/rest/rest_auth.go +++ b/plugins/rest/rest_auth.go @@ -22,12 +22,11 @@ import ( "time" "github.com/open-policy-agent/opa/internal/jwx/jwa" - "github.com/open-policy-agent/opa/internal/jwx/jws/sign" - "github.com/open-policy-agent/opa/internal/jwx/jws" + "github.com/open-policy-agent/opa/internal/jwx/jws/sign" "github.com/open-policy-agent/opa/internal/uuid" "github.com/open-policy-agent/opa/keys" - "github.com/open-policy-agent/opa/sdk" + "github.com/open-policy-agent/opa/logging" ) const ( @@ -141,7 +140,7 @@ type oauth2ClientCredentialsAuthPlugin struct { signingKeyParsed interface{} tokenCache *oauth2Token tlsSkipVerify bool - logger sdk.Logger + logger logging.Logger } type oauth2Token struct { @@ -463,7 +462,7 @@ type awsSigningAuthPlugin struct { AWSWebIdentityCredentials *awsWebIdentityCredentialService `json:"web_identity_credentials,omitempty"` AWSService string `json:"service,omitempty"` - logger sdk.Logger + logger logging.Logger } func (ap *awsSigningAuthPlugin) awsCredentialService() awsCredentialService { diff --git a/plugins/status/plugin.go b/plugins/status/plugin.go index 306ccd89e1..ca3a80c507 100644 --- a/plugins/status/plugin.go +++ b/plugins/status/plugin.go @@ -12,11 +12,10 @@ import ( "net/http" "reflect" - "github.com/open-policy-agent/opa/sdk" - "github.com/pkg/errors" "github.com/sirupsen/logrus" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/bundle" @@ -56,7 +55,7 @@ type Plugin struct { metrics metrics.Metrics lastPluginStatuses map[string]*plugins.Status pluginStatusCh chan map[string]*plugins.Status - logger sdk.Logger + logger logging.Logger } // Config contains configuration for the plugin. @@ -344,7 +343,7 @@ func (p *Plugin) logUpdate(update *UpdateRequestV1) error { if err != nil { return err } - plugins.GetConsoleLogger().WithFields(fields).WithFields(logrus.Fields{ + p.manager.ConsoleLogger().WithFields(fields).WithFields(logrus.Fields{ "type": "openpolicyagent.org/status", }).Info("Status Log") return nil diff --git a/plugins/status/plugin_test.go b/plugins/status/plugin_test.go index 143fcddc73..f7bf56c823 100644 --- a/plugins/status/plugin_test.go +++ b/plugins/status/plugin_test.go @@ -14,9 +14,6 @@ import ( "testing" "time" - "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" - "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/bundle" @@ -203,42 +200,6 @@ func TestPluginStartDiscovery(t *testing.T) { } } -func TestPluginConsoleLogging(t *testing.T) { - logLevel := logrus.GetLevel() - defer logrus.SetLevel(logLevel) - - // Ensure that status messages are printed to console even with the standard logger configured to log errors only - logrus.SetLevel(logrus.ErrorLevel) - - hook := test.NewLocal(plugins.GetConsoleLogger()) - - fixture := newTestFixture(t, nil, func(c *Config) { - c.ConsoleLogs = true - c.Service = "" - }) - - ctx := context.Background() - _ = fixture.plugin.Start(ctx) - defer fixture.plugin.Stop(ctx) - - status := testStatus() - - fixture.plugin.UpdateDiscoveryStatus(*status) - - // Give the logger / console some time to process and print the events - time.Sleep(10 * time.Millisecond) - - // Skip the first entry as it is about the plugin getting updated - e := hook.AllEntries()[1] - - if e.Message != "Status Log" { - t.Fatal("Expected status log to console") - } - if _, ok := e.Data["discovery"]; !ok { - t.Fatal("Expected discovery status update") - } -} - func TestPluginBadAuth(t *testing.T) { fixture := newTestFixture(t, nil) ctx := context.Background() diff --git a/runtime/runtime.go b/runtime/runtime.go index 51c903c424..7921bc2dfb 100644 --- a/runtime/runtime.go +++ b/runtime/runtime.go @@ -34,6 +34,7 @@ import ( initload "github.com/open-policy-agent/opa/internal/runtime/init" "github.com/open-policy-agent/opa/internal/uuid" "github.com/open-policy-agent/opa/loader" + "github.com/open-policy-agent/opa/logging" "github.com/open-policy-agent/opa/metrics" "github.com/open-policy-agent/opa/plugins" "github.com/open-policy-agent/opa/plugins/discovery" @@ -141,6 +142,9 @@ type Params struct { // Logging configures the logging behaviour. Logging LoggingConfig + // ConsoleLogger sets the logger implementation to use for console logs. + ConsoleLogger logging.Logger + // ConfigFile refers to the OPA configuration to load on startup. ConfigFile string @@ -246,7 +250,25 @@ func NewRuntime(ctx context.Context, params Params) (*Runtime, error) { return nil, err } - manager, err := plugins.New(config, params.ID, inmem.New(), plugins.Info(info), plugins.InitBundles(loaded.Bundles), plugins.InitFiles(loaded.Files), plugins.MaxErrors(params.ErrorLimit), plugins.GracefulShutdownPeriod(params.GracefulShutdownPeriod)) + var consoleLogger logging.Logger + + if params.ConsoleLogger == nil { + stdLogger := logging.NewStandardLogger() + stdLogger.SetFormatter(getFormatter(params.Logging.Format)) + consoleLogger = stdLogger + } else { + consoleLogger = params.ConsoleLogger + } + + manager, err := plugins.New(config, + params.ID, + inmem.New(), + plugins.Info(info), + plugins.InitBundles(loaded.Bundles), + plugins.InitFiles(loaded.Files), + plugins.MaxErrors(params.ErrorLimit), + plugins.GracefulShutdownPeriod(params.GracefulShutdownPeriod), + plugins.ConsoleLogger(consoleLogger)) if err != nil { return nil, errors.Wrap(err, "config error") } @@ -728,23 +750,22 @@ func onReloadPrinter(output io.Writer) func(time.Duration, error) { } } -func setupLogging(config LoggingConfig) { - var formatter logrus.Formatter - switch config.Format { +func getFormatter(format string) logrus.Formatter { + switch format { case "text": - formatter = &prettyFormatter{} + return &prettyFormatter{} case "json-pretty": - formatter = &logrus.JSONFormatter{PrettyPrint: true} + return &logrus.JSONFormatter{PrettyPrint: true} case "json": fallthrough default: - formatter = &logrus.JSONFormatter{} + return &logrus.JSONFormatter{} } - logrus.SetFormatter(formatter) - // While the plugin console logger logs independently of the configured --log-level, - // it should follow the configured --log-format - plugins.GetConsoleLogger().SetFormatter(formatter) +} +func setupLogging(config LoggingConfig) { + formatter := getFormatter(config.Format) + logrus.SetFormatter(formatter) lvl := logrus.InfoLevel if config.Level != "" { diff --git a/test/e2e/logs/console/console_decision_logger_test.go b/test/e2e/logs/console/console_decision_logger_test.go index c4f52c4e36..c9f33555fd 100644 --- a/test/e2e/logs/console/console_decision_logger_test.go +++ b/test/e2e/logs/console/console_decision_logger_test.go @@ -11,10 +11,7 @@ import ( "strings" "testing" - "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" - - "github.com/open-policy-agent/opa/plugins" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/runtime" "github.com/open-policy-agent/opa/test/e2e" ) @@ -30,6 +27,8 @@ func TestMain(m *testing.M) { } // Ensure decisions are logged regardless of regular log level testServerParams.Logging = runtime.LoggingConfig{Level: "error"} + consoleLogger := test.New() + testServerParams.ConsoleLogger = consoleLogger var err error testRuntime, err = e2e.NewTestRuntime(testServerParams) @@ -37,13 +36,13 @@ func TestMain(m *testing.M) { os.Exit(1) } + testRuntime.ConsoleLogger = consoleLogger os.Exit(testRuntime.RunTests(m)) } func TestConsoleDecisionLogWithInput(t *testing.T) { // Setup a test hook on the console logger (what the console decision logger uses) - hook := test.NewLocal(plugins.GetConsoleLogger()) policy := ` package test @@ -102,19 +101,21 @@ func TestConsoleDecisionLogWithInput(t *testing.T) { }}, } - var entry *logrus.Entry - for _, e := range hook.AllEntries() { - if e.Message == "Decision Log" { - entry = e + var entry test.LogEntry + var found bool + + for _, entry = range testRuntime.ConsoleLogger.Entries() { + if entry.Message == "Decision Log" { + found = true } } - if entry == nil { - t.Fatalf("Did not find 'Decision Log' event in captured logrus entries") + if !found { + t.Fatalf("Did not find 'Decision Log' event in captured log entries") } // Ensure expected fields exist - for fieldName, rawField := range entry.Data { + for fieldName, rawField := range entry.Fields { if fd, ok := expectedFields[fieldName]; ok { if fieldValue, ok := rawField.(string); ok && fd.match != nil { fd.match(t, fieldValue) diff --git a/test/e2e/testing.go b/test/e2e/testing.go index 28e50c5ab1..4aeceb8925 100644 --- a/test/e2e/testing.go +++ b/test/e2e/testing.go @@ -22,6 +22,7 @@ import ( "github.com/sirupsen/logrus" + "github.com/open-policy-agent/opa/logging/test" "github.com/open-policy-agent/opa/runtime" "github.com/open-policy-agent/opa/server/types" "github.com/open-policy-agent/opa/util" @@ -53,14 +54,15 @@ func NewAPIServerTestParams() runtime.Params { // TestRuntime holds metadata and provides helper methods // to interact with the runtime being tested. type TestRuntime struct { - Params runtime.Params - Runtime *runtime.Runtime - Ctx context.Context - Cancel context.CancelFunc - Client *http.Client - url string - diagURL string - urlMtx *sync.Mutex + Params runtime.Params + Runtime *runtime.Runtime + Ctx context.Context + Cancel context.CancelFunc + Client *http.Client + ConsoleLogger *test.Logger + url string + diagURL string + urlMtx *sync.Mutex } // NewTestRuntime returns a new TestRuntime which