Repository: deislabs/ratify (go)

Issue:
Unify ratify logging library 
Noel's [investigation ](https://github.com/deislabs/ratify/pull/498) pointed out the the manager must use logr, and rest of ratify uses logrus. This item tracks the work to unify the logging library. 

"
The manager must use a logr instance, and that uses a different scheme for tracking levels - ex: +v, +vv, +vvvvv rather than levels like INFO/DEBUG/etc. So that particular path won't get log level set, but everything else will, which I've manually tested

I looked around, saw that there are libraries that convert logrus -> logr, or we could write our own adapter as something to be handled in a future issue?  " 

Pull request:
feat: use logrus for CRD manager for common log format
# Description

Adds a `logr` -> `logrus` adapter sink so that k8s `controller-runtime` components emit the same output as the rest of the Ratify codebase

~~It's currently behind the `RATIFY_UNIFIED_LOGGING=1` feature flag since I was new to these libraries. I'm happy to remove the flag and just make the swap, make it flag enabled by default so you can opt-into the current behavior, etc.~~

Fixes #503

## Type of change

Please delete options that are not relevant.

- [x] Bug fix (non-breaking change which fixes an issue)
- [x] New feature (non-breaking change which adds functionality)
- [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected)
- [ ] This change requires a documentation update

# How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Please also list any relevant details for your test configuration

- [x] Manually tested and invoked an error on purpose:

Existing behavior:

Note the different timestamp/format/etc

```text
time="2023-02-09T21:01:01Z" level=info msg="Setting log level to debug"
time="2023-02-09T21:01:01Z" level=info msg="Feature flag DYNAMIC_PLUGINS is enabled"
time="2023-02-09T21:01:01Z" level=info msg="starting crd manager"
time="2023-02-09T21:01:01Z" level=info msg="initializing executor with config file at default config path"
time="2023-02-09T21:01:01Z" level=info msg="selected default auth provider: dockerConfig"
1.675976461844683e+09	ERROR	controller-runtime.client.config	unable to get kubeconfig	{"error": "invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable", "errorCauses": [{"error": "no configuration has been provided, try setting KUBERNETES_MASTER environment variable"}]}
sigs.k8s.io/controller-runtime/pkg/client/config.GetConfigOrDie
	/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.12.3/pkg/client/config/config.go:153
github.com/deislabs/ratify/pkg/manager.StartManager
	/workspaces/ratify/pkg/manager/manager.go:148
```

~~Setting `RATIFY_UNIFIED_LOGGING=1`:~~

Logging output is consistent

```text
time="2023-02-13T18:40:54Z" level=info msg="Setting log level to info"
time="2023-02-13T18:40:54Z" level=info msg="Feature flag DYNAMIC_PLUGINS is enabled"
time="2023-02-13T18:40:54Z" level=info msg="starting crd manager"
time="2023-02-13T18:40:54Z" level=info msg="initializing executor with config file at default config path"
time="2023-02-13T18:40:54Z" level=info msg="selected default auth provider: dockerConfig"
time="2023-02-13T18:40:54Z" level=error msg="[controller-runtime.client.config] unable to get kubeconfig" error="invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable" name=controller-runtime.client.config
```

Setting `RATIFY_LOG_LEVEL=debug`:

Logging output is consistent and stack trace is available in the `stacktrace` property

```text
time="2023-02-13T19:17:03Z" level=info msg="Setting log level to debug"
time="2023-02-13T19:17:03Z" level=info msg="Feature flag DYNAMIC_PLUGINS is enabled"
time="2023-02-13T19:17:03Z" level=info msg="starting crd manager"
time="2023-02-13T19:17:03Z" level=info msg="initializing executor with config file at default config path"
time="2023-02-13T19:17:03Z" level=info msg="selected default auth provider: dockerConfig"
time="2023-02-13T19:17:03Z" level=error msg="[controller-runtime.client.config] unable to get kubeconfig" error="invalid configuration: no configuration has been provided, try setting KUBERNETES_MASTER environment variable" name=controller-runtime.client.config stacktrace="goroutine 69 [running]:\nruntime/debug.Stack()\n\t/usr/local/go/src/runtime/debug/stack.go:24 +0x7a\ngithub.com/deislabs/ratify/pkg/controllers.(*LogrusSink).Error(0xc00052c900, {0x2886600, 0xc0003322b8}, {0x26c80a5, 0x18}, {0x0, 0x0, 0x0})\n\t/workspaces/ratify/pkg/controllers/logging.go:73 +0xac\nsigs.k8s.io/controller-runtime/pkg/log.(*DelegatingLogSink).Error(0xc0004aa480, {0x2886600, 0xc0003322b8}, {0x26c80a5, 0x18}, {0x0, 0x0, 0x0})\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.12.3/pkg/log/deleg.go:135 +0x135\ngithub.com/go-logr/logr.Logger.Error({{0x289ef08, 0xc0004aa480}, 0x0}, {0x2886600, 0xc0003322b8}, {0x26c80a5, 0x18}, {0x0, 0x0, 0x0})\n\t/go/pkg/mod/github.com/go-logr/logr@v1.2.3/logr.go:279 +0x11d\nsigs.k8s.io/controller-runtime/pkg/client/config.GetConfigOrDie()\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.12.3/pkg/client/config/config.go:153 +0xc5\ngithub.com/deislabs/ratify/pkg/manager.StartManager()\n\t/workspaces/ratify/pkg/manager/manager.go:138 +0x1b7\ncreated by github.com/deislabs/ratify/cmd/ratify/cmd.serve\n\t/workspaces/ratify/cmd/ratify/cmd/serve.go:72 +0x69\n"
```



Patch:
diff --git a/pkg/controllers/logging.go b/pkg/controllers/logging.go
new file mode 100644
index 0000000..1a97fe3
--- /dev/null
+++ b/pkg/controllers/logging.go
@@ -0,0 +1,130 @@
+/*
+Copyright The Ratify Authors.
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package controllers
+
+import (
+	"fmt"
+	"runtime/debug"
+	"strings"
+
+	"github.com/go-logr/logr"
+	"github.com/sirupsen/logrus"
+)
+
+// LogrusSink is an adapter to allow the use of logrus with logr, as required by k8s controller-runtime.
+type LogrusSink struct {
+	logger        *logrus.Logger
+	names         []string
+	keysAndValues []interface{}
+}
+
+func NewLogrusSink(logger *logrus.Logger) *LogrusSink {
+	return &LogrusSink{
+		logger: logger,
+	}
+}
+
+// Init receives optional information about the logr library for LogSink
+// implementations that need it.
+func (s *LogrusSink) Init(info logr.RuntimeInfo) {
+}
+
+// Enabled tests whether this LogSink is enabled at the specified V-level.
+// For example, commandline flags might be used to set the logging
+// verbosity and disable some info logs.
+func (sink *LogrusSink) Enabled(level int) bool {
+	// controller-runtime uses V=0 for Info and V=1 for Debug: https://github.com/kubernetes-sigs/controller-runtime/blob/master/TMP-LOGGING.md
+	switch level {
+	case 0:
+		return sink.logger.IsLevelEnabled(logrus.InfoLevel)
+	default:
+		return sink.logger.IsLevelEnabled(logrus.DebugLevel)
+	}
+}
+
+// Info logs a non-error message with the given key/value pairs as context.
+// The level argument is provided for optional logging.  This method will
+// only be called when Enabled(level) is true. See Logger.Info for more
+// details.
+func (sink *LogrusSink) Info(level int, msg string, keysAndValues ...interface{}) {
+	entry := sink.createEntry(keysAndValues...)
+	entry.Info(sink.formatMessage(msg))
+}
+
+// Error logs an error, with the given message and key/value pairs as
+// context.  See Logger.Error for more details.
+func (sink *LogrusSink) Error(err error, msg string, keysAndValues ...interface{}) {
+	entry := sink.createEntry(keysAndValues...)
+
+	if sink.logger.IsLevelEnabled(logrus.DebugLevel) {
+		stacktrace := string(debug.Stack())
+		entry = entry.WithField("stacktrace", stacktrace)
+	}
+
+	entry.WithError(err).Error(sink.formatMessage(msg))
+}
+
+// WithValues returns a new LogSink with additional key/value pairs.  See
+// Logger.WithValues for more details.
+func (sink *LogrusSink) WithValues(keysAndValues ...interface{}) logr.LogSink {
+	newSink := &LogrusSink{
+		logger:        sink.logger,
+		names:         sink.names,
+		keysAndValues: append(sink.keysAndValues, keysAndValues...),
+	}
+	return newSink
+}
+
+// WithName returns a new LogSink with the specified name appended.  See
+// Logger.WithName for more details.
+func (sink *LogrusSink) WithName(name string) logr.LogSink {
+	newSink := &LogrusSink{
+		logger:        sink.logger,
+		names:         append(sink.names, name),
+		keysAndValues: sink.keysAndValues,
+	}
+	return newSink
+}
+
+func (sink *LogrusSink) createEntry(keysAndValues ...interface{}) *logrus.Entry {
+	entry := logrus.NewEntry(sink.logger)
+
+	if sink.names != nil {
+		entry = entry.WithField("name", strings.Join(sink.names, "."))
+	}
+
+	if sink.keysAndValues != nil {
+		for i := 0; i < len(sink.keysAndValues); i += 2 {
+			entry = entry.WithField(fmt.Sprintf("%v", sink.keysAndValues[i]), sink.keysAndValues[i+1])
+		}
+	}
+
+	if keysAndValues != nil {
+		for i := 0; i < len(keysAndValues); i += 2 {
+			entry = entry.WithField(fmt.Sprintf("%v", keysAndValues[i]), keysAndValues[i+1])
+		}
+	}
+
+	return entry
+}
+
+func (sink *LogrusSink) formatMessage(msg string) string {
+	if sink.names == nil || len(sink.names) == 0 {
+		return msg
+	}
+
+	return fmt.Sprintf("[%s] %s", strings.Join(sink.names, "."), msg)
+}
diff --git a/pkg/manager/manager.go b/pkg/manager/manager.go
index c8cf1b4..5bc32eb 100644
--- a/pkg/manager/manager.go
+++ b/pkg/manager/manager.go
@@ -24,6 +24,7 @@ import (
 	_ "github.com/deislabs/ratify/pkg/policyprovider/configpolicy"
 	_ "github.com/deislabs/ratify/pkg/referrerstore/oras"
 	_ "github.com/deislabs/ratify/pkg/verifier/notaryv2"
+	"github.com/go-logr/logr"
 	_ "k8s.io/client-go/plugin/pkg/client/auth"
 
 	// Import all Kubernetes client auth plugins (e.g. Azure, GCP, OIDC, etc.)
@@ -41,7 +42,6 @@ import (
 	clientgoscheme "k8s.io/client-go/kubernetes/scheme"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/healthz"
-	"sigs.k8s.io/controller-runtime/pkg/log/zap"
 
 	configv1alpha1 "github.com/deislabs/ratify/api/v1alpha1"
 	"github.com/deislabs/ratify/pkg/controllers"
@@ -130,13 +130,10 @@ func StartManager() {
 	flag.BoolVar(&enableLeaderElection, "leader-elect", false,
 		"Enable leader election for controller manager. "+
 			"Enabling this will ensure there is only one active controller manager.")
-	opts := zap.Options{
-		Development: true,
-	}
-	opts.BindFlags(flag.CommandLine)
 	flag.Parse()
 
-	ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))
+	logrusSink := controllers.NewLogrusSink(logrus.StandardLogger())
+	ctrl.SetLogger(logr.New(logrusSink))
 
 	mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), ctrl.Options{
 		Scheme:                 scheme,


Test patch:
diff --git a/pkg/controllers/logging_test.go b/pkg/controllers/logging_test.go
new file mode 100644
index 0000000..da13f23
--- /dev/null
+++ b/pkg/controllers/logging_test.go
@@ -0,0 +1,151 @@
+/*
+Copyright The Ratify Authors.
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package controllers
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/go-logr/logr"
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestNewLogSink(t *testing.T) {
+	logger := logrus.New()
+	sink := NewLogrusSink(logger)
+
+	if sink.logger != logger {
+		t.Errorf("expected logger to be %v, got %v", logger, sink.logger)
+	}
+}
+
+func TestInit(t *testing.T) {
+	logger := logrus.New()
+	sink := NewLogrusSink(logger)
+	sink.Init(logr.RuntimeInfo{})
+}
+
+func TestEnabled_UsesInfoLevel(t *testing.T) {
+	logger := logrus.New()
+	logger.SetLevel(logrus.InfoLevel)
+	sink := NewLogrusSink(logger)
+
+	if !sink.Enabled(0) {
+		t.Errorf("expected enabled to be true, got false")
+	}
+}
+
+func TestEnabled_UsesDebugLevel(t *testing.T) {
+	logger := logrus.New()
+	logger.SetLevel(logrus.DebugLevel)
+	sink := NewLogrusSink(logger)
+
+	if !sink.Enabled(1) {
+		t.Errorf("expected enabled to be true, got false")
+	}
+}
+
+func TestInfo(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	sink.Info(0, "test", "property1", 100, "property2", "value2")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+	assert.Equal(t, "test", hook.LastEntry().Message)
+	assert.Equal(t, 100, hook.LastEntry().Data["property1"])
+	assert.Equal(t, "value2", hook.LastEntry().Data["property2"])
+}
+
+func TestError(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	err := fmt.Errorf("myerror")
+	sink.Error(err, "test", "property1", 100, "property2", "value2")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.ErrorLevel, hook.LastEntry().Level)
+	assert.Equal(t, "test", hook.LastEntry().Message)
+	assert.Equal(t, 100, hook.LastEntry().Data["property1"])
+	assert.Equal(t, "value2", hook.LastEntry().Data["property2"])
+}
+
+func TestError_WithDebug(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	logger.SetLevel(logrus.DebugLevel)
+	sink := NewLogrusSink(logger)
+
+	err := fmt.Errorf("myerror")
+	sink.Error(err, "test", "property1", 100, "property2", "value2")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.ErrorLevel, hook.LastEntry().Level)
+	assert.NotNil(t, hook.LastEntry().Data["stacktrace"])
+}
+
+func TestWithValues(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	sink.WithValues("property1", 100, "property2", "value2").Info(0, "test")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+	assert.Equal(t, "test", hook.LastEntry().Message)
+	assert.Equal(t, 100, hook.LastEntry().Data["property1"])
+	assert.Equal(t, "value2", hook.LastEntry().Data["property2"])
+}
+
+func TestWithName(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	sink.WithName("myname").WithName("subname").Info(0, "test")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+	assert.Equal(t, "[myname.subname] test", hook.LastEntry().Message)
+}
+
+func TestError_WithName(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	err := fmt.Errorf("myerror")
+	sink.WithName("myname").WithName("subname").Error(err, "test")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.ErrorLevel, hook.LastEntry().Level)
+	assert.Equal(t, "[myname.subname] test", hook.LastEntry().Message)
+}
+
+func TestError_WithValues(t *testing.T) {
+	logger, hook := test.NewNullLogger()
+	sink := NewLogrusSink(logger)
+
+	err := fmt.Errorf("myerror")
+	sink.WithValues("property1", 100, "property2", "value2").Error(err, "test")
+
+	assert.Equal(t, 1, len(hook.Entries))
+	assert.Equal(t, logrus.ErrorLevel, hook.LastEntry().Level)
+	assert.Equal(t, "test", hook.LastEntry().Message)
+	assert.Equal(t, 100, hook.LastEntry().Data["property1"])
+	assert.Equal(t, "value2", hook.LastEntry().Data["property2"])
+}