runtime: Refactor logger usage

This commit does not change any functionality except it provides
callers with a way to provide a logger when instantiating the
runtime. Previously, the runtime had hardcoded dependencies on the
global logrus logger which made it problematic to test logging
behaviour. With this change, the logger can be supplied as a
parameter (which allows the caller to mock out the logger in tests...)

As part of this change, the dependencies on logrus have been moved out
of the runtime package entirely.

This commit includes a breaking change to the
runtime.NewLoggingHandler function: the function now requires a logger
to be supplied.

Signed-off-by: Torin Sandall <torinsandall@gmail.com>

CHANGELOG.md

@@ -3,6 +3,15 @@
 All notable changes to this project will be documented in this file. This
 project adheres to [Semantic Versioning](http://semver.org/).
 
+## Unreleased
+
+### Backwards Compatibility
+
+* The `github.com/open-policy-agent/opa/runtime#NewLoggingHandler` function now
+  requires a logger instance. Requiring the logger avoids the need for the
+  logging handler to depend on the global logrus logger (which is useful for
+  test purposes.) This change is unlikely to affect users.
+
 ## 0.33.1
 
 This is a bugfix release addressing an issue in the formatting of rego code that contains
@@ -80,8 +89,6 @@ If you use the container images, or the published binaries, of OPA 0.32.0, you a
 
 Many thanks to [James Alseth](https://github.com/jalseth) for triaging this, and engaging with upstream to fix this.
 
-## Unreleased
-
 ## 0.32.0
 
 This release includes a number of improvements and fixes.

internal/logging/logging.go

@@ -0,0 +1,99 @@
+// Copyright 2021 The OPA Authors.  All rights reserved.
+// Use of this source code is governed by an Apache2
+// license that can be found in the LICENSE file.
+
+package logging
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"strings"
+
+	"github.com/sirupsen/logrus"
+)
+
+func GetFormatter(format string) logrus.Formatter {
+	switch format {
+	case "text":
+		return &prettyFormatter{}
+	case "json-pretty":
+		return &logrus.JSONFormatter{PrettyPrint: true}
+	default:
+		return &logrus.JSONFormatter{}
+	}
+}
+
+// prettyFormatter implements the Logrus Formatter interface
+// and provides a more simple, but easier to read, text formatter
+// option than the default logrus.TextFormatter.
+type prettyFormatter struct {
+}
+
+func isJSON(buf []byte) bool {
+	var tmp interface{}
+	err := json.Unmarshal(buf, &tmp)
+	return err == nil
+}
+
+func spaces(num int) string {
+	sb := strings.Builder{}
+	for i := 0; i < num; i++ {
+		sb.WriteByte(' ')
+	}
+	return sb.String()
+}
+
+func (p *prettyFormatter) Format(e *logrus.Entry) ([]byte, error) {
+	b := new(bytes.Buffer)
+
+	level := strings.ToUpper(e.Level.String())
+	b.WriteString(fmt.Sprintf("[%s] %s\n", level, e.Message))
+
+	// Format each key for optimal ease of human reading
+	fieldIndent := 2
+	multiLineIndent := 6
+	for k, v := range e.Data {
+		// Special case for multi-line strings, keep them as-is
+		// but indent them. Everything else gets json'd
+		stringVal, ok := v.(string)
+		if ok && strings.Contains(stringVal, "\n") {
+			sb := strings.Builder{}
+			for i, line := range strings.Split(stringVal, "\n") {
+				// match the json indent helper by not indenting the first value
+				if i != 0 {
+					sb.WriteString(spaces(multiLineIndent))
+				}
+				sb.WriteString(line)
+				sb.WriteByte('\n')
+				stringVal = sb.String()
+			}
+		} else if ok && isJSON([]byte(stringVal)) {
+			var tmp bytes.Buffer
+			err := json.Indent(&tmp, []byte(stringVal), spaces(multiLineIndent), spaces(2))
+			if err != nil {
+				return nil, err
+			}
+			stringVal = tmp.String()
+		} else {
+			jsonVal, err := json.MarshalIndent(v, spaces(multiLineIndent), spaces(2))
+			if err != nil {
+				return nil, err
+			}
+			stringVal = string(jsonVal)
+		}
+
+		b.WriteString(spaces(fieldIndent))
+		b.WriteString(k)
+		if strings.Contains(stringVal, "\n") {
+			b.WriteString(" = |\n")
+			b.WriteString(spaces(multiLineIndent))
+		} else {
+			b.WriteString(" = ")
+		}
+		b.WriteString(stringVal)
+		b.WriteString("\n")
+	}
+	b.WriteByte('\n')
+	return b.Bytes(), nil
+}

internal/logging/logging_test.go

@@ -0,0 +1,190 @@
+// Copyright 2021 The OPA Authors.  All rights reserved.
+// Use of this source code is governed by an Apache2
+// license that can be found in the LICENSE file.
+
+package logging
+
+import (
+	"encoding/json"
+	"errors"
+	"strings"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+)
+
+func TestPrettyFormatterNoFields(t *testing.T) {
+	fmtr := prettyFormatter{}
+
+	e := logrus.NewEntry(logrus.StandardLogger())
+	e.Message = "test"
+	e.Level = logrus.InfoLevel
+
+	out, err := fmtr.Format(e)
+	if err != nil {
+		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
+	}
+
+	actualStr := string(out)
+
+	expectedLvl := strings.ToUpper(e.Level.String())
+	if !strings.Contains(actualStr, expectedLvl) {
+		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
+	}
+
+	if !strings.Contains(actualStr, "test") {
+		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
+	}
+}
+
+func TestPrettyFormatterBasicFields(t *testing.T) {
+	fmtr := prettyFormatter{}
+
+	e := logrus.WithFields(logrus.Fields{
+		"number": 5,
+		"string": "field_string",
+		"nil":    nil,
+		"error":  errors.New("field_error").Error(),
+	})
+
+	e.Message = "test"
+	e.Level = logrus.InfoLevel
+
+	out, err := fmtr.Format(e)
+	if err != nil {
+		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
+	}
+
+	actualStr := string(out)
+
+	expectedLvl := strings.ToUpper(e.Level.String())
+	if !strings.Contains(actualStr, expectedLvl) {
+		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
+	}
+
+	if !strings.Contains(actualStr, "test\n") {
+		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
+	}
+
+	if !strings.Contains(actualStr, "number = 5\n") {
+		t.Errorf("Expected to have the number field in message")
+	}
+
+	if !strings.Contains(actualStr, "string = \"field_string\"\n") {
+		t.Errorf("Expected to have the string field in message")
+	}
+
+	if !strings.Contains(actualStr, "nil = null\n") {
+		t.Errorf("Expected to have the nil field in message")
+	}
+
+	if !strings.Contains(actualStr, "error = \"field_error\"\n") {
+		t.Errorf("Expected to have the nil field in message")
+	}
+
+	expectedLines := 7 // one for the message, 4 fields (one line each), and two trailing \n
+	actualLines := len(strings.Split(actualStr, "\n"))
+	if actualLines != expectedLines {
+		t.Errorf("Expected %d lines in output, found %d\n Output: \n%s\n", expectedLines, actualLines, actualStr)
+	}
+}
+
+func TestPrettyFormatterMultilineStringFields(t *testing.T) {
+	fmtr := prettyFormatter{}
+
+	mlStr := `
+package opa.examples
+
+import data.servers
+import data.networks
+import data.ports
+
+public_servers[server] {
+	server := servers[_]
+	server.ports[_] == ports[k].id
+	ports[k].networks[_] == networks[m].id
+	networks[m].public == true
+}
+`
+
+	e := logrus.WithFields(logrus.Fields{
+		"multi_line": mlStr,
+	})
+
+	e.Message = "test"
+	e.Level = logrus.InfoLevel
+
+	out, err := fmtr.Format(e)
+	if err != nil {
+		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
+	}
+
+	actualStr := string(out)
+
+	expectedLvl := strings.ToUpper(e.Level.String())
+	if !strings.Contains(actualStr, expectedLvl) {
+		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
+	}
+
+	if !strings.Contains(actualStr, "test") {
+		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
+	}
+
+	for _, line := range strings.Split(mlStr, "\n") {
+		// The lines will get prefixed with some padding but should always
+		// still have their real newlines, and not be encoded.
+		expectedStr := line + "\n"
+		if !strings.Contains(actualStr, expectedStr) {
+			t.Errorf("Expected to find line in message:\n\n%s\n\nactual:\n\n%s\n", expectedStr, actualStr)
+		}
+	}
+}
+
+func TestPrettyFormatterMultilineJSONFields(t *testing.T) {
+	fmtr := prettyFormatter{}
+
+	obj := map[string]interface{}{
+		"a": 123,
+		"b": nil,
+		"d": "abc",
+		"e": map[string]interface{}{
+			"test": []string{
+				"aa",
+				"bb",
+				"cc",
+			},
+		},
+	}
+
+	e := logrus.WithFields(logrus.Fields{
+		"json_string": obj,
+	})
+
+	e.Message = "test"
+	e.Level = logrus.InfoLevel
+
+	out, err := fmtr.Format(e)
+	if err != nil {
+		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
+	}
+
+	actualStr := string(out)
+
+	expectedLvl := strings.ToUpper(e.Level.String())
+	if !strings.Contains(actualStr, expectedLvl) {
+		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
+	}
+
+	if !strings.Contains(actualStr, "test") {
+		t.Errorf("Expected log message to have the entry message 'test':\n%s", actualStr)
+	}
+
+	expectedJSON, err := json.MarshalIndent(&obj, "      ", "  ")
+	if err != nil {
+		t.Fatalf("Unexpected error: %v", err)
+	}
+
+	if !strings.Contains(actualStr, string(expectedJSON)) {
+		t.Errorf("Expected JSON to be formatted and included in message:\n\nExpected:\n%s\n\nActual:\n%s\n\n", string(expectedJSON), actualStr)
+	}
+}

logging/logging.go

@@ -1,6 +1,8 @@
 package logging
 
 import (
+	"io"
+
 	"github.com/sirupsen/logrus"
 )
 
@@ -57,6 +59,11 @@ func Get() *StandardLogger {
 	}
 }
 
+// SetOutput sets the underlying logrus output.
+func (l *StandardLogger) SetOutput(w io.Writer) {
+	l.logger.SetOutput(w)
+}
+
 // SetFormatter sets the underlying logrus formatter.
 func (l *StandardLogger) SetFormatter(formatter logrus.Formatter) {
 	l.logger.SetFormatter(formatter)

plugins/status/plugin.go

@@ -13,7 +13,6 @@ import (
 	"reflect"
 
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 
 	"github.com/open-policy-agent/opa/logging"
 	"github.com/open-policy-agent/opa/metrics"
@@ -430,12 +429,12 @@ func (p *Plugin) logUpdate(update *UpdateRequestV1) error {
 	if err != nil {
 		return err
 	}
-	fields := logrus.Fields{}
+	fields := map[string]interface{}{}
 	err = util.UnmarshalJSON(eventBuf, &fields)
 	if err != nil {
 		return err
 	}
-	p.manager.ConsoleLogger().WithFields(fields).WithFields(logrus.Fields{
+	p.manager.ConsoleLogger().WithFields(fields).WithFields(map[string]interface{}{
 		"type": "openpolicyagent.org/status",
 	}).Info("Status Log")
 	return nil

runtime/logging.go

@@ -7,49 +7,49 @@ package runtime
 import (
 	"bufio"
 	"bytes"
-	"encoding/json"
 	"errors"
-	"fmt"
 	"io"
 	"net"
 	"net/http"
 	"net/url"
-	"strings"
 	"sync/atomic"
 	"time"
 
 	"io/ioutil"
 
-	"github.com/sirupsen/logrus"
-
+	"github.com/open-policy-agent/opa/logging"
 	"github.com/open-policy-agent/opa/server/types"
 )
 
-func loggingEnabled(level logrus.Level) bool {
-	return level <= logrus.GetLevel()
-}
-
 // LoggingHandler returns an http.Handler that will print log messages
 // containing the request information as well as response status and latency.
 type LoggingHandler struct {
+	logger    logging.Logger
 	inner     http.Handler
 	requestID uint64
 }
 
 // NewLoggingHandler returns a new http.Handler.
-func NewLoggingHandler(inner http.Handler) http.Handler {
-	return &LoggingHandler{inner, uint64(0)}
+func NewLoggingHandler(logger logging.Logger, inner http.Handler) http.Handler {
+	return &LoggingHandler{
+		logger:    logger,
+		inner:     inner,
+		requestID: uint64(0),
+	}
+}
+
+func (h *LoggingHandler) loggingEnabled(level logging.Level) bool {
+	return level <= h.logger.GetLevel()
 }
 
 func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	requestID := atomic.AddUint64(&h.requestID, uint64(1))
-
-	recorder := newRecorder(w, r, requestID, loggingEnabled(logrus.DebugLevel))
+	recorder := newRecorder(h.logger, w, r, requestID, h.loggingEnabled(logging.Debug))
 	t0 := time.Now()
 
-	if loggingEnabled(logrus.InfoLevel) {
+	if h.loggingEnabled(logging.Info) {
 
-		fields := logrus.Fields{
+		fields := map[string]interface{}{
 			"client_addr": r.RemoteAddr,
 			"req_id":      requestID,
 			"req_method":  r.Method,
@@ -58,7 +58,7 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 		var err error
 
-		if loggingEnabled(logrus.DebugLevel) {
+		if h.loggingEnabled(logging.Debug) {
 			var bs []byte
 			if r.Body != nil {
 				bs, r.Body, err = readBody(r.Body)
@@ -73,20 +73,20 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		}
 
 		if err == nil {
-			logrus.WithFields(fields).Info("Received request.")
+			h.logger.WithFields(fields).Info("Received request.")
 		} else {
-			logrus.WithFields(fields).Error("Failed to read body.")
+			h.logger.WithFields(fields).Error("Failed to read body.")
 		}
 	}
 
 	params := r.URL.Query()
 
 	if _, ok := params["watch"]; ok {
-		logrus.Warn("Deprecated 'watch' parameter specified in request. See https://github.com/open-policy-agent/opa/releases/tag/v0.23.0 for details.")
+		h.logger.Warn("Deprecated 'watch' parameter specified in request. See https://github.com/open-policy-agent/opa/releases/tag/v0.23.0 for details.")
 	}
 
 	if _, ok := params["partial"]; ok {
-		logrus.Warn("Deprecated 'partial' parameter specified in request. See https://github.com/open-policy-agent/opa/releases/tag/v0.23.0 for details.")
+		h.logger.Warn("Deprecated 'partial' parameter specified in request. See https://github.com/open-policy-agent/opa/releases/tag/v0.23.0 for details.")
 	}
 
 	h.inner.ServeHTTP(recorder, r)
@@ -97,8 +97,8 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		statusCode = recorder.statusCode
 	}
 
-	if loggingEnabled(logrus.InfoLevel) {
-		fields := logrus.Fields{
+	if h.loggingEnabled(logging.Info) {
+		fields := map[string]interface{}{
 			"client_addr":   r.RemoteAddr,
 			"req_id":        requestID,
 			"req_method":    r.Method,
@@ -108,34 +108,36 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			"resp_duration": float64(dt.Nanoseconds()) / 1e6,
 		}
 
-		if loggingEnabled(logrus.DebugLevel) {
+		if h.loggingEnabled(logging.Debug) {
 			fields["resp_body"] = recorder.buf.String()
 		}
 
-		logrus.WithFields(fields).Info("Sent response.")
+		h.logger.WithFields(fields).Info("Sent response.")
 	}
 }
 
 type recorder struct {
-	inner http.ResponseWriter
-	req   *http.Request
-	id    uint64
+	logger logging.Logger
+	inner  http.ResponseWriter
+	req    *http.Request
+	id     uint64
 
 	buf          *bytes.Buffer
 	bytesWritten int
 	statusCode   int
 }
 
-func newRecorder(w http.ResponseWriter, r *http.Request, id uint64, buffer bool) *recorder {
+func newRecorder(logger logging.Logger, w http.ResponseWriter, r *http.Request, id uint64, buffer bool) *recorder {
 	var buf *bytes.Buffer
 	if buffer {
 		buf = new(bytes.Buffer)
 	}
 	return &recorder{
-		buf:   buf,
-		inner: w,
-		req:   r,
-		id:    id,
+		logger: logger,
+		buf:    buf,
+		inner:  w,
+		req:    r,
+		id:     id,
 	}
 }
 
@@ -167,7 +169,7 @@ func (r *recorder) Hijack() (net.Conn, *bufio.ReadWriter, error) {
 		return nil, nil, err
 	}
 
-	fields := logrus.Fields{
+	fields := map[string]interface{}{
 		"client_addr": r.req.RemoteAddr,
 		"req_id":      r.id,
 		"req_method":  r.req.Method,
@@ -178,7 +180,7 @@ func (r *recorder) Hijack() (net.Conn, *bufio.ReadWriter, error) {
 	if len(queries) > 0 {
 		fields["req_query"] = queries[len(queries)-1]
 	}
-	logrus.WithFields(fields).Info("Started watch.")
+	r.logger.WithFields(fields).Info("Started watch.")
 
 	return c, rw, nil
 }
@@ -206,77 +208,3 @@ func readBody(r io.ReadCloser) ([]byte, io.ReadCloser, error) {
 	}
 	return buf.Bytes(), ioutil.NopCloser(bytes.NewReader(buf.Bytes())), nil
 }
-
-// prettyFormatter implements the Logrus Formatter interface
-// and provides a more simple, but easier to read, text formatter
-// option than the default logrus.TextFormatter.
-type prettyFormatter struct {
-}
-
-func isJSON(buf []byte) bool {
-	var tmp interface{}
-	err := json.Unmarshal(buf, &tmp)
-	return err == nil
-}
-
-func spaces(num int) string {
-	sb := strings.Builder{}
-	for i := 0; i < num; i++ {
-		sb.WriteByte(' ')
-	}
-	return sb.String()
-}
-
-func (p *prettyFormatter) Format(e *logrus.Entry) ([]byte, error) {
-	b := new(bytes.Buffer)
-
-	level := strings.ToUpper(e.Level.String())
-	b.WriteString(fmt.Sprintf("[%s] %s\n", level, e.Message))
-
-	// Format each key for optimal ease of human reading
-	fieldIndent := 2
-	multiLineIndent := 6
-	for k, v := range e.Data {
-		// Special case for multi-line strings, keep them as-is
-		// but indent them. Everything else gets json'd
-		stringVal, ok := v.(string)
-		if ok && strings.Contains(stringVal, "\n") {
-			sb := strings.Builder{}
-			for i, line := range strings.Split(stringVal, "\n") {
-				// match the json indent helper by not indenting the first value
-				if i != 0 {
-					sb.WriteString(spaces(multiLineIndent))
-				}
-				sb.WriteString(line)
-				sb.WriteByte('\n')
-				stringVal = sb.String()
-			}
-		} else if ok && isJSON([]byte(stringVal)) {
-			var tmp bytes.Buffer
-			err := json.Indent(&tmp, []byte(stringVal), spaces(multiLineIndent), spaces(2))
-			if err != nil {
-				return nil, err
-			}
-			stringVal = tmp.String()
-		} else {
-			jsonVal, err := json.MarshalIndent(v, spaces(multiLineIndent), spaces(2))
-			if err != nil {
-				return nil, err
-			}
-			stringVal = string(jsonVal)
-		}
-
-		b.WriteString(spaces(fieldIndent))
-		b.WriteString(k)
-		if strings.Contains(stringVal, "\n") {
-			b.WriteString(" = |\n")
-			b.WriteString(spaces(multiLineIndent))
-		} else {
-			b.WriteString(" = ")
-		}
-		b.WriteString(stringVal)
-		b.WriteString("\n")
-	}
-	b.WriteByte('\n')
-	return b.Bytes(), nil
-}

runtime/logging_test.go

@@ -6,14 +6,9 @@
 package runtime
 
 import (
-	"encoding/json"
-	"errors"
 	"fmt"
 	"net/url"
-	"strings"
 	"testing"
-
-	"github.com/sirupsen/logrus"
 )
 
 func TestDropInputParam(t *testing.T) {
@@ -51,179 +46,3 @@ func TestDropInputParam(t *testing.T) {
 	}
 
 }
-
-func TestPrettyFormatterNoFields(t *testing.T) {
-	fmtr := prettyFormatter{}
-
-	e := logrus.NewEntry(logrus.StandardLogger())
-	e.Message = "test"
-	e.Level = logrus.InfoLevel
-
-	out, err := fmtr.Format(e)
-	if err != nil {
-		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
-	}
-
-	actualStr := string(out)
-
-	expectedLvl := strings.ToUpper(e.Level.String())
-	if !strings.Contains(actualStr, expectedLvl) {
-		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
-	}
-
-	if !strings.Contains(actualStr, "test") {
-		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
-	}
-}
-
-func TestPrettyFormatterBasicFields(t *testing.T) {
-	fmtr := prettyFormatter{}
-
-	e := logrus.WithFields(logrus.Fields{
-		"number": 5,
-		"string": "field_string",
-		"nil":    nil,
-		"error":  errors.New("field_error").Error(),
-	})
-
-	e.Message = "test"
-	e.Level = logrus.InfoLevel
-
-	out, err := fmtr.Format(e)
-	if err != nil {
-		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
-	}
-
-	actualStr := string(out)
-
-	expectedLvl := strings.ToUpper(e.Level.String())
-	if !strings.Contains(actualStr, expectedLvl) {
-		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
-	}
-
-	if !strings.Contains(actualStr, "test\n") {
-		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
-	}
-
-	if !strings.Contains(actualStr, "number = 5\n") {
-		t.Errorf("Expected to have the number field in message")
-	}
-
-	if !strings.Contains(actualStr, "string = \"field_string\"\n") {
-		t.Errorf("Expected to have the string field in message")
-	}
-
-	if !strings.Contains(actualStr, "nil = null\n") {
-		t.Errorf("Expected to have the nil field in message")
-	}
-
-	if !strings.Contains(actualStr, "error = \"field_error\"\n") {
-		t.Errorf("Expected to have the nil field in message")
-	}
-
-	expectedLines := 7 // one for the message, 4 fields (one line each), and two trailing \n
-	actualLines := len(strings.Split(actualStr, "\n"))
-	if actualLines != expectedLines {
-		t.Errorf("Expected %d lines in output, found %d\n Output: \n%s\n", expectedLines, actualLines, actualStr)
-	}
-}
-
-func TestPrettyFormatterMultilineStringFields(t *testing.T) {
-	fmtr := prettyFormatter{}
-
-	mlStr := `
-package opa.examples
-
-import data.servers
-import data.networks
-import data.ports
-
-public_servers[server] {
-	server := servers[_]
-	server.ports[_] == ports[k].id
-	ports[k].networks[_] == networks[m].id
-	networks[m].public == true
-}
-`
-
-	e := logrus.WithFields(logrus.Fields{
-		"multi_line": mlStr,
-	})
-
-	e.Message = "test"
-	e.Level = logrus.InfoLevel
-
-	out, err := fmtr.Format(e)
-	if err != nil {
-		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
-	}
-
-	actualStr := string(out)
-
-	expectedLvl := strings.ToUpper(e.Level.String())
-	if !strings.Contains(actualStr, expectedLvl) {
-		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
-	}
-
-	if !strings.Contains(actualStr, "test") {
-		t.Errorf("Expected log message to have the entry message '%s':\n%s", "test", actualStr)
-	}
-
-	for _, line := range strings.Split(mlStr, "\n") {
-		// The lines will get prefixed with some padding but should always
-		// still have their real newlines, and not be encoded.
-		expectedStr := line + "\n"
-		if !strings.Contains(actualStr, expectedStr) {
-			t.Errorf("Expected to find line in message:\n\n%s\n\nactual:\n\n%s\n", expectedStr, actualStr)
-		}
-	}
-}
-
-func TestPrettyFormatterMultilineJSONFields(t *testing.T) {
-	fmtr := prettyFormatter{}
-
-	obj := map[string]interface{}{
-		"a": 123,
-		"b": nil,
-		"d": "abc",
-		"e": map[string]interface{}{
-			"test": []string{
-				"aa",
-				"bb",
-				"cc",
-			},
-		},
-	}
-
-	e := logrus.WithFields(logrus.Fields{
-		"json_string": obj,
-	})
-
-	e.Message = "test"
-	e.Level = logrus.InfoLevel
-
-	out, err := fmtr.Format(e)
-	if err != nil {
-		t.Fatalf("Unexpected error formatting log entry: %s", err.Error())
-	}
-
-	actualStr := string(out)
-
-	expectedLvl := strings.ToUpper(e.Level.String())
-	if !strings.Contains(actualStr, expectedLvl) {
-		t.Errorf("Expected log message to have level %s:\n%s", expectedLvl, actualStr)
-	}
-
-	if !strings.Contains(actualStr, "test") {
-		t.Errorf("Expected log message to have the entry message 'test':\n%s", actualStr)
-	}
-
-	expectedJSON, err := json.MarshalIndent(&obj, "      ", "  ")
-	if err != nil {
-		t.Fatalf("Unexpected error: %v", err)
-	}
-
-	if !strings.Contains(actualStr, string(expectedJSON)) {
-		t.Errorf("Expected JSON to be formatted and included in message:\n\nExpected:\n%s\n\nActual:\n%s\n\n", string(expectedJSON), actualStr)
-	}
-}

runtime/runtime.go

@@ -23,12 +23,12 @@ import (
 	"github.com/fsnotify/fsnotify"
 	"github.com/gorilla/mux"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 	"go.uber.org/automaxprocs/maxprocs"
 
 	"github.com/open-policy-agent/opa/ast"
 	"github.com/open-policy-agent/opa/bundle"
 	"github.com/open-policy-agent/opa/internal/config"
+	internal_logging "github.com/open-policy-agent/opa/internal/logging"
 	"github.com/open-policy-agent/opa/internal/prometheus"
 	"github.com/open-policy-agent/opa/internal/report"
 	"github.com/open-policy-agent/opa/internal/runtime"
@@ -147,6 +147,9 @@ type Params struct {
 	// Logging configures the logging behaviour.
 	Logging LoggingConfig
 
+	// Logger sets the logger implementation to use for debug logs.
+	Logger logging.Logger
+
 	// ConsoleLogger sets the logger implementation to use for console logs.
 	ConsoleLogger logging.Logger
 
@@ -215,6 +218,7 @@ type Runtime struct {
 	Store   storage.Store
 	Manager *plugins.Manager
 
+	logger   logging.Logger
 	server   *server.Server
 	metrics  *prometheus.Provider
 	reporter *report.Reporter
@@ -260,11 +264,36 @@ func NewRuntime(ctx context.Context, params Params) (*Runtime, error) {
 		return nil, err
 	}
 
+	var logger logging.Logger
+
+	if params.Logger != nil {
+		logger = params.Logger
+	} else {
+		stdLogger := logging.New()
+		formatter := internal_logging.GetFormatter(params.Logging.Format)
+		stdLogger.SetFormatter(formatter)
+
+		switch strings.ToLower(params.Logging.Level) {
+		case "debug":
+			stdLogger.SetLevel(logging.Debug)
+		case "", "info":
+			stdLogger.SetLevel(logging.Info)
+		case "warn":
+			stdLogger.SetLevel(logging.Warn)
+		case "error":
+			stdLogger.SetLevel(logging.Error)
+		default:
+			return nil, fmt.Errorf("invalid log level: %v", params.Logging.Level)
+		}
+
+		logger = stdLogger
+	}
+
 	var consoleLogger logging.Logger
 
 	if params.ConsoleLogger == nil {
 		l := logging.New()
-		l.SetFormatter(getFormatter(params.Logging.Format))
+		l.SetFormatter(internal_logging.GetFormatter(params.Logging.Format))
 		consoleLogger = l
 	} else {
 		consoleLogger = params.ConsoleLogger
@@ -287,7 +316,7 @@ func NewRuntime(ctx context.Context, params Params) (*Runtime, error) {
 		return nil, errors.Wrap(err, "initialization error")
 	}
 
-	metrics := prometheus.New(metrics.New(), errorLogger)
+	metrics := prometheus.New(metrics.New(), errorLogger(logger))
 
 	disco, err := discovery.New(manager, discovery.Factories(registeredPlugins), discovery.Metrics(metrics))
 	if err != nil {
@@ -300,6 +329,7 @@ func NewRuntime(ctx context.Context, params Params) (*Runtime, error) {
 		Store:             manager.Store,
 		Params:            params,
 		Manager:           manager,
+		logger:            logger,
 		metrics:           metrics,
 		reporter:          reporter,
 		serverInitialized: false,
@@ -330,32 +360,30 @@ func (rt *Runtime) Serve(ctx context.Context) error {
 		rt.Params.DiagnosticAddrs = &[]string{}
 	}
 
-	setupLogging(rt.Params.Logging)
-
-	logrus.WithFields(logrus.Fields{
+	rt.logger.WithFields(map[string]interface{}{
 		"addrs":            *rt.Params.Addrs,
 		"diagnostic-addrs": *rt.Params.DiagnosticAddrs,
 	}).Info("Initializing server.")
 
 	if rt.Params.Authorization == server.AuthorizationOff && rt.Params.Authentication == server.AuthenticationToken {
-		logrus.Error("Token authentication enabled without authorization. Authentication will be ineffective. See https://www.openpolicyagent.org/docs/latest/security/#authentication-and-authorization for more information.")
+		rt.logger.Error("Token authentication enabled without authorization. Authentication will be ineffective. See https://www.openpolicyagent.org/docs/latest/security/#authentication-and-authorization for more information.")
 	}
 
 	// NOTE(tsandall): at some point, hopefully we can remove this because the
 	// Go runtime will just do the right thing. Until then, try to set
 	// GOMAXPROCS based on the CPU quota applied to the process.
 	undo, err := maxprocs.Set(maxprocs.Logger(func(f string, a ...interface{}) {
-		logrus.Debugf(f, a...)
+		rt.logger.Debug(f, a...)
 	}))
 
 	if err != nil {
-		logrus.WithFields(logrus.Fields{"err": err}).Debug("Failed to set GOMAXPROCS from CPU quota.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Debug("Failed to set GOMAXPROCS from CPU quota.")
 	}
 
 	defer undo()
 
 	if err := rt.Manager.Start(ctx); err != nil {
-		logrus.WithField("err", err).Error("Failed to start plugins.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Failed to start plugins.")
 		return err
 	}
 
@@ -385,13 +413,13 @@ func (rt *Runtime) Serve(ctx context.Context) error {
 
 	rt.server, err = rt.server.Init(ctx)
 	if err != nil {
-		logrus.WithField("err", err).Error("Unable to initialize server.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Unable to initialize server.")
 		return err
 	}
 
 	if rt.Params.Watch {
-		if err := rt.startWatcher(ctx, rt.Params.Paths, onReloadLogger); err != nil {
-			logrus.WithField("err", err).Error("Unable to open watch.")
+		if err := rt.startWatcher(ctx, rt.Params.Paths, rt.onReloadLogger); err != nil {
+			rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Unable to open watch.")
 			return err
 		}
 	}
@@ -408,19 +436,19 @@ func (rt *Runtime) Serve(ctx context.Context) error {
 		}
 	}()
 
-	rt.server.Handler = NewLoggingHandler(rt.server.Handler)
-	rt.server.DiagnosticHandler = NewLoggingHandler(rt.server.DiagnosticHandler)
+	rt.server.Handler = NewLoggingHandler(rt.logger, rt.server.Handler)
+	rt.server.DiagnosticHandler = NewLoggingHandler(rt.logger, rt.server.DiagnosticHandler)
 
 	if err := rt.waitPluginsReady(
 		100*time.Millisecond,
 		time.Second*time.Duration(rt.Params.ReadyTimeout)); err != nil {
-		logrus.WithField("err", err).Error("Failed to wait for plugins activation.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Failed to wait for plugins activation.")
 		return err
 	}
 
 	loops, err := rt.server.Listeners()
 	if err != nil {
-		logrus.WithField("err", err).Error("Unable to create listeners.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Unable to create listeners.")
 		return err
 	}
 
@@ -446,7 +474,7 @@ func (rt *Runtime) Serve(ctx context.Context) error {
 	rt.serverInitMtx.Unlock()
 	rt.Manager.ServerInitialized()
 
-	logrus.Debug("Server initialized.")
+	rt.logger.Debug("Server initialized.")
 
 	for {
 		select {
@@ -455,7 +483,8 @@ func (rt *Runtime) Serve(ctx context.Context) error {
 		case <-signalc:
 			return rt.gracefulServerShutdown(rt.server)
 		case err := <-errc:
-			logrus.WithField("err", err).Fatal("Listener failed.")
+			rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Listener failed.")
+			os.Exit(1)
 		}
 	}
 }
@@ -526,14 +555,14 @@ func (rt *Runtime) checkOPAUpdateLoop(ctx context.Context, uploadDuration time.D
 	for {
 		resp, err := rt.reporter.SendReport(ctx)
 		if err != nil {
-			logrus.WithField("err", err).Debug("Unable to send OPA version report.")
+			rt.logger.WithFields(map[string]interface{}{"err": err}).Debug("Unable to send OPA version report.")
 		} else {
 			if resp.Latest.OPAUpToDate {
-				logrus.WithFields(logrus.Fields{
+				rt.logger.WithFields(map[string]interface{}{
 					"current_version": version.Version,
 				}).Debug("OPA is up to date.")
 			} else {
-				logrus.WithFields(logrus.Fields{
+				rt.logger.WithFields(map[string]interface{}{
 					"download_opa":    resp.Latest.Download,
 					"release_notes":   resp.Latest.ReleaseNotes,
 					"current_version": version.Version,
@@ -578,7 +607,7 @@ func (rt *Runtime) decisionLogger(ctx context.Context, event *server.Info) error
 }
 
 func (rt *Runtime) startWatcher(ctx context.Context, paths []string, onReload func(time.Duration, error)) error {
-	watcher, err := getWatcher(paths)
+	watcher, err := rt.getWatcher(paths)
 	if err != nil {
 		return err
 	}
@@ -591,9 +620,9 @@ func (rt *Runtime) readWatcher(ctx context.Context, watcher *fsnotify.Watcher, p
 		removalMask := fsnotify.Remove | fsnotify.Rename
 		mask := fsnotify.Create | fsnotify.Write | removalMask
 		if (evt.Op & mask) != 0 {
-			logrus.WithFields(logrus.Fields{
+			rt.logger.WithFields(map[string]interface{}{
 				"event": evt.String(),
-			}).Debugf("registered file event")
+			}).Debug("Registered file event.")
 			t0 := time.Now()
 			removed := ""
 			if (evt.Op & removalMask) != 0 {
@@ -674,19 +703,19 @@ func (rt *Runtime) getBanner() string {
 
 func (rt *Runtime) gracefulServerShutdown(s *server.Server) error {
 	if rt.Params.ShutdownWaitPeriod > 0 {
-		logrus.Infof("Waiting %vs before initiating shutdown...", rt.Params.ShutdownWaitPeriod)
+		rt.logger.Info("Waiting %vs before initiating shutdown...", rt.Params.ShutdownWaitPeriod)
 		time.Sleep(time.Duration(rt.Params.ShutdownWaitPeriod) * time.Second)
 	}
 
-	logrus.Info("Shutting down...")
+	rt.logger.Info("Shutting down...")
 	ctx, cancel := context.WithTimeout(context.Background(), time.Duration(rt.Params.GracefulShutdownPeriod)*time.Second)
 	defer cancel()
 	err := s.Shutdown(ctx)
 	if err != nil {
-		logrus.WithField("err", err).Error("Failed to shutdown server gracefully.")
+		rt.logger.WithFields(map[string]interface{}{"err": err}).Error("Failed to shutdown server gracefully.")
 		return err
 	}
-	logrus.Info("Server shutdown.")
+	rt.logger.Info("Server shutdown.")
 	return nil
 }
 
@@ -705,12 +734,19 @@ func (rt *Runtime) waitPluginsReady(checkInterval, timeout time.Duration) error
 		return true
 	}
 
-	logrus.Debugf("Waiting for plugins activation (%v).", timeout)
+	rt.logger.Debug("Waiting for plugins activation (%v).", timeout)
 
 	return util.WaitFunc(pluginsReady, checkInterval, timeout)
 }
 
-func getWatcher(rootPaths []string) (*fsnotify.Watcher, error) {
+func (rt *Runtime) onReloadLogger(d time.Duration, err error) {
+	rt.logger.WithFields(map[string]interface{}{
+		"duration": d,
+		"err":      err,
+	}).Warn("Processed file watch event.")
+}
+
+func (rt *Runtime) getWatcher(rootPaths []string) (*fsnotify.Watcher, error) {
 
 	watchPaths, err := getWatchPaths(rootPaths)
 	if err != nil {
@@ -723,7 +759,7 @@ func getWatcher(rootPaths []string) (*fsnotify.Watcher, error) {
 	}
 
 	for _, path := range watchPaths {
-		logrus.WithField("path", path).Debug("watching path")
+		rt.logger.WithFields(map[string]interface{}{"path": path}).Debug("watching path")
 		if err := watcher.Add(path); err != nil {
 			return nil, err
 		}
@@ -732,6 +768,12 @@ func getWatcher(rootPaths []string) (*fsnotify.Watcher, error) {
 	return watcher, nil
 }
 
+func errorLogger(logger logging.Logger) func(attrs map[string]interface{}, f string, a ...interface{}) {
+	return func(attrs map[string]interface{}, f string, a ...interface{}) {
+		logger.WithFields(map[string]interface{}(attrs)).Error(f, a...)
+	}
+}
+
 func getWatchPaths(rootPaths []string) ([]string, error) {
 	paths := []string{}
 
@@ -749,13 +791,6 @@ func getWatchPaths(rootPaths []string) ([]string, error) {
 	return paths, nil
 }
 
-func onReloadLogger(d time.Duration, err error) {
-	logrus.WithFields(logrus.Fields{
-		"duration": d,
-		"err":      err,
-	}).Warn("Processed file watch event.")
-}
-
 func onReloadPrinter(output io.Writer) func(time.Duration, error) {
 	return func(d time.Duration, err error) {
 		if err != nil {
@@ -766,39 +801,6 @@ func onReloadPrinter(output io.Writer) func(time.Duration, error) {
 	}
 }
 
-func getFormatter(format string) logrus.Formatter {
-	switch format {
-	case "text":
-		return &prettyFormatter{}
-	case "json-pretty":
-		return &logrus.JSONFormatter{PrettyPrint: true}
-	case "json":
-		fallthrough
-	default:
-		return &logrus.JSONFormatter{}
-	}
-}
-
-func setupLogging(config LoggingConfig) {
-	formatter := getFormatter(config.Format)
-	logrus.SetFormatter(formatter)
-	lvl := logrus.InfoLevel
-
-	if config.Level != "" {
-		var err error
-		lvl, err = logrus.ParseLevel(config.Level)
-		if err != nil {
-			logrus.Fatalf("Unable to parse log level: %v", err)
-		}
-	}
-
-	logrus.SetLevel(lvl)
-}
-
-func errorLogger(attrs map[string]interface{}, f string, a ...interface{}) {
-	logrus.WithFields(logrus.Fields(attrs)).Errorf(f, a...)
-}
-
 func generateInstanceID() (string, error) {
 	return uuid.New(rand.Reader)
 }

runtime/runtime_test.go

@@ -20,10 +20,9 @@ import (
 	"time"
 
 	"github.com/open-policy-agent/opa/internal/report"
+	"github.com/open-policy-agent/opa/logging"
 	"github.com/open-policy-agent/opa/server"
 
-	"github.com/sirupsen/logrus"
-
 	"github.com/open-policy-agent/opa/ast"
 	"github.com/open-policy-agent/opa/storage"
 	"github.com/open-policy-agent/opa/util"
@@ -309,19 +308,22 @@ func TestCheckOPAUpdateLoopWithNewUpdate(t *testing.T) {
 func TestCheckAuthIneffective(t *testing.T) {
 	ctx, cancel := context.WithTimeout(context.Background(), 2*time.Millisecond)
 	defer cancel() // NOTE(sr): The timeout will have been reached by the time `done` is closed.
-	var output bytes.Buffer
 
 	params := NewParams()
 	params.Authentication = server.AuthenticationToken
 	params.Authorization = server.AuthorizationOff
-	params.Output = &output
+
+	logger := logging.New()
+	stdout := bytes.NewBuffer(nil)
+	logger.SetOutput(stdout)
+
+	params.Logger = logger
 	params.Addrs = &[]string{":0"}
 	params.GracefulShutdownPeriod = 1
 	rt, err := NewRuntime(ctx, params)
 	if err != nil {
 		t.Fatalf("Unexpected error %v", err)
 	}
-	logrus.SetOutput(rt.Params.Output)
 
 	done := make(chan struct{})
 	go func() {
@@ -331,8 +333,8 @@ func TestCheckAuthIneffective(t *testing.T) {
 	<-done
 
 	expected := "Token authentication enabled without authorization. Authentication will be ineffective. See https://www.openpolicyagent.org/docs/latest/security/#authentication-and-authorization for more information."
-	if !strings.Contains(output.String(), expected) {
-		t.Fatalf("Expected output to contain: \"%v\" but got \"%v\"", expected, output.String())
+	if !strings.Contains(stdout.String(), expected) {
+		t.Fatalf("Expected output to contain: \"%v\" but got \"%v\"", expected, stdout.String())
 	}
 
 }
@@ -346,11 +348,12 @@ func TestServerInitialized(t *testing.T) {
 	params.Output = &output
 	params.Addrs = &[]string{":0"}
 	params.GracefulShutdownPeriod = 1
+	params.Logger = logging.NewNoOpLogger()
+
 	rt, err := NewRuntime(ctx, params)
 	if err != nil {
 		t.Fatalf("Unexpected error %v", err)
 	}
-	logrus.SetOutput(rt.Params.Output)
 
 	initChannel := rt.Manager.ServerInitializedChannel()
 	done := make(chan struct{})
@@ -385,7 +388,7 @@ func testCheckOPAUpdate(t *testing.T, url string, expected *report.DataResponse)
 	os.Setenv("OPA_TELEMETRY_SERVICE_URL", url)
 
 	ctx := context.Background()
-	rt := getTestRuntime(ctx, t)
+	rt := getTestRuntime(ctx, t, logging.NewNoOpLogger())
 	result := rt.checkOPAUpdate(ctx)
 
 	if !reflect.DeepEqual(result, expected) {
@@ -398,12 +401,13 @@ func testCheckOPAUpdateLoop(t *testing.T, url, expected string) {
 	os.Setenv("OPA_TELEMETRY_SERVICE_URL", url)
 
 	ctx := context.Background()
-	rt := getTestRuntime(ctx, t)
-	var stdout bytes.Buffer
-	rt.Params.Output = &stdout
 
-	logrus.SetOutput(rt.Params.Output)
-	logrus.SetLevel(logrus.DebugLevel)
+	logger := logging.New()
+	stdout := bytes.NewBuffer(nil)
+	logger.SetOutput(stdout)
+	logger.SetLevel(logging.Debug)
+
+	rt := getTestRuntime(ctx, t, logger)
 
 	done := make(chan struct{})
 	go func() {
@@ -418,11 +422,12 @@ func testCheckOPAUpdateLoop(t *testing.T, url, expected string) {
 	}
 }
 
-func getTestRuntime(ctx context.Context, t *testing.T) *Runtime {
+func getTestRuntime(ctx context.Context, t *testing.T, logger logging.Logger) *Runtime {
 	t.Helper()
 
 	params := NewParams()
 	params.EnableVersionCheck = true
+	params.Logger = logger
 	rt, err := NewRuntime(ctx, params)
 	if err != nil {
 		t.Fatalf("Unexpected error %v", err)

test/e2e/testing.go

@@ -20,8 +20,7 @@ import (
 	"testing"
 	"time"
 
-	"github.com/sirupsen/logrus"
-
+	"github.com/open-policy-agent/opa/logging"
 	"github.com/open-policy-agent/opa/logging/test"
 	"github.com/open-policy-agent/opa/runtime"
 	"github.com/open-policy-agent/opa/server/types"
@@ -195,7 +194,7 @@ func (t *TestRuntime) runTests(m *testing.M, suppressLogs bool) int {
 	go func() {
 		// Suppress the stdlogger in the server
 		if suppressLogs {
-			logrus.SetOutput(ioutil.Discard)
+			logging.Get().SetOutput(ioutil.Discard)
 		}
 		err := t.Runtime.Serve(t.Ctx)
 		done <- err
@@ -204,7 +203,7 @@ func (t *TestRuntime) runTests(m *testing.M, suppressLogs bool) int {
 	// Turns out this thread gets a different stdlogger
 	// so we need to set the output on it here too.
 	if suppressLogs {
-		logrus.SetOutput(ioutil.Discard)
+		logging.Get().SetOutput(ioutil.Discard)
 	}
 
 	// wait for the server to be ready
@@ -239,7 +238,7 @@ func (t *TestRuntime) WaitForServer() error {
 			// Then make sure it has started serving
 			err := t.HealthCheck(t.URL())
 			if err == nil {
-				logrus.Infof("Test server ready and listening on: %s", t.URL())
+				logging.Get().Info("Test server ready and listening on: %s", t.URL())
 				return nil
 			}
 		}