Separate console logger for plugins

This allows logging to console for decisions and status (and possibly other use cases) without having to follow the generic --log-level.

Fixes #2733

Signed-off-by: Anders Eknert <anders.eknert@bisnode.com>

plugins/logs/plugin.go

@@ -775,7 +775,7 @@ func (p *Plugin) logEvent(event EventV1) error {
 	if err != nil {
 		return err
 	}
-	logrus.WithFields(fields).WithFields(logrus.Fields{
+	plugins.GetConsoleLogger().WithFields(fields).WithFields(logrus.Fields{
 		"type": "openpolicyagent.org/decision_logs",
 	}).Info("Decision Log")
 	return nil

plugins/plugins.go

@@ -10,6 +10,8 @@ import (
 	"sync"
 	"time"
 
+	"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"
@@ -146,6 +148,14 @@ type managerContextKey string
 
 const managerCompilerContextKey = managerContextKey("compiler")
 
+// 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

plugins/status/plugin.go

@@ -331,7 +331,7 @@ func (p *Plugin) logUpdate(update *UpdateRequestV1) error {
 	if err != nil {
 		return err
 	}
-	logrus.WithFields(fields).WithFields(logrus.Fields{
+	plugins.GetConsoleLogger().WithFields(fields).WithFields(logrus.Fields{
 		"type": "openpolicyagent.org/status",
 	}).Info("Status Log")
 	return nil

plugins/status/plugin_test.go

@@ -14,6 +14,9 @@ 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"
@@ -200,6 +203,42 @@ 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()
@@ -345,7 +384,9 @@ type testFixture struct {
 	server  *testServer
 }
 
-func newTestFixture(t *testing.T, m metrics.Metrics) testFixture {
+type testPluginCustomizer func(c *Config)
+
+func newTestFixture(t *testing.T, m metrics.Metrics, options ...testPluginCustomizer) testFixture {
 
 	ts := testServer{
 		t:       t,
@@ -381,6 +422,9 @@ func newTestFixture(t *testing.T, m metrics.Metrics) testFixture {
 		}`))
 
 	config, _ := ParseConfig(pluginConfig, manager.Services())
+	for _, option := range options {
+		option(config)
+	}
 
 	p := New(config, manager).WithMetrics(m)
 

runtime/runtime.go

@@ -703,16 +703,21 @@ func onReloadPrinter(output io.Writer) func(time.Duration, error) {
 }
 
 func setupLogging(config LoggingConfig) {
+	var formatter logrus.Formatter
 	switch config.Format {
 	case "text":
-		logrus.SetFormatter(&prettyFormatter{})
+		formatter = &prettyFormatter{}
 	case "json-pretty":
-		logrus.SetFormatter(&logrus.JSONFormatter{PrettyPrint: true})
+		formatter = &logrus.JSONFormatter{PrettyPrint: true}
 	case "json":
 		fallthrough
 	default:
-		logrus.SetFormatter(&logrus.JSONFormatter{})
+		formatter = &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)
 
 	lvl := logrus.InfoLevel
 

test/e2e/logs/console/console_decision_logger_test.go

@@ -11,6 +11,9 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/open-policy-agent/opa/plugins"
+	"github.com/open-policy-agent/opa/runtime"
+
 	"github.com/sirupsen/logrus"
 
 	"github.com/sirupsen/logrus/hooks/test"
@@ -27,6 +30,8 @@ func TestMain(m *testing.M) {
 	testServerParams.ConfigOverrides = []string{
 		"decision_logs.console=true",
 	}
+	// Ensure decisions are logged regardless of regular log level
+	testServerParams.Logging = runtime.LoggingConfig{Level: "error"}
 
 	var err error
 	testRuntime, err = e2e.NewTestRuntime(testServerParams)
@@ -39,9 +44,8 @@ func TestMain(m *testing.M) {
 
 func TestConsoleDecisionLogWithInput(t *testing.T) {
 
-	// Setup a test hook on the global logrus logger (what
-	// the console decision logger uses)
-	hook := test.NewGlobal()
+	// Setup a test hook on the console logger (what the console decision logger uses)
+	hook := test.NewLocal(plugins.GetConsoleLogger())
 
 	policy := `
 	package test
@@ -99,6 +103,7 @@ func TestConsoleDecisionLogWithInput(t *testing.T) {
 			}
 		}},
 	}
+
 	var entry *logrus.Entry
 	for _, e := range hook.AllEntries() {
 		if e.Message == "Decision Log" {