Repository: deislabs/ratify (go)

Issue:
Add Debug Logging 
Currently, there's no mechanism to enable debug log levels for `logrus`. We would need to add a flag to the ratify CLI and add the log level changing support too.

Pull request:
Add configurable logging level
# Description

## What this PR does / why we need it:

As part of plugin development, I'd like to be able to turn on some `DEBUG` logs so I can see what's actually being passed into my plugin, but I don't want to spam users with verbose info at runtime. Ratify currently defaults to the `INFO` log level, and it's not configurable. Other folks have asked for this as well in the issues

* Implements configurable log levels via `RATIFY_LOG_LEVEL`, with the default to the current `INFO` level
* Adds tests for the above
* Adds a new "usage" docs page that documents the `RATIFY_*` environment variables
* Adds debug logging for plugin executables

> Note: I believe it could be valuable to have Cobra-generated markdown docs, and/or add robust documentation for the other env vars that are in use, particularly around auth stores (ex: `AWS_REGION`, `AZURE_TENANT_ID`, etc). Will track in a separate Issue/PR

Fixes #348

## Type of change

Please delete options that are not relevant.

- [x] New feature (non-breaking change which adds functionality)
- [x] 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] Unit tests
- [x] Verified that env vars / STDIN data is omitted by default, and is correctly logged with `RATIFY_LOG_LEVEL=DEBUG`

# Checklist:

- [x] Does the affected code have corresponding tests?
- [x] Are the changes documented, not just with inline documentation, but also with conceptual documentation such as an overview of a new feature, or task-based documentation like a tutorial? Consider if this change should be announced on your project blog.
- [ ] Does this introduce breaking changes that would require an announcement or bumping the major version?
- [x] Do all new files have appropriate license header?


Patch:
diff --git a/.vscode/launch.json b/.vscode/launch.json
index 9af75f3..421fe8c 100644
--- a/.vscode/launch.json
+++ b/.vscode/launch.json
@@ -28,6 +28,23 @@
         ":6001"
       ],
     },
+    {
+      // This requires your kubeconfig to be pointed at a cluster with Ratify CRDs installed
+      "name": "Serve w/ CRD manager",
+      "type": "go",
+      "request": "launch",
+      "mode": "auto",
+      "program": "${workspaceFolder}/cmd/ratify",
+      "env": {
+        "RATIFY_LOG_LEVEL": "debug"
+      },
+      "args": [
+        "serve",
+        "--enable-crd-manager",
+        "--http",
+        ":6001"
+      ],
+    },
   ],
   "inputs": [
     {
diff --git a/cmd/ratify/cmd/root.go b/cmd/ratify/cmd/root.go
index c0647ba..39b120c 100644
--- a/cmd/ratify/cmd/root.go
+++ b/cmd/ratify/cmd/root.go
@@ -15,7 +15,11 @@ limitations under the License.
 
 package cmd
 
-import "github.com/spf13/cobra"
+import (
+	"github.com/deislabs/ratify/pkg/common"
+	"github.com/sirupsen/logrus"
+	"github.com/spf13/cobra"
+)
 
 const (
 	use       = "ratify"
@@ -25,6 +29,7 @@ const (
 var Root = New(use, shortDesc)
 
 func New(use, short string) *cobra.Command {
+	common.SetLoggingLevelFromEnv(logrus.StandardLogger())
 	root := &cobra.Command{
 		Use:   use,
 		Short: short,
diff --git a/docs/README.md b/docs/README.md
index 92382c2..09cecc0 100644
--- a/docs/README.md
+++ b/docs/README.md
@@ -16,6 +16,7 @@ These walk through end-to-end examples of using ratify.
 
 These documents can be found generally useful to understand using or implementing ratify, but do not walk through end-to-end examples.
 
+- [usage](reference/usage.md) - Additional information for using the `ratify` executable
 - [gatekeeper-policy-authoring](reference/gatekeeper-policy-authoring.md) - Authoring gatekeeper policies for use with ratify, including rego references/examples.
 - [oras-auth-provider](reference/oras-auth-provider.md) - Explanation of various authentication mechanisms available for use with ratify.
 - [creating-plugins](reference/creating-plugins.md) - Details on creating your own plugins for use with ratify.
diff --git a/docs/reference/usage.md b/docs/reference/usage.md
new file mode 100644
index 0000000..c94810f
--- /dev/null
+++ b/docs/reference/usage.md
@@ -0,0 +1,15 @@
+# Usage
+
+This page documents useful flags and options supported by Ratify
+
+## Environment variables
+
+- `RATIFY_LOG_LEVEL`: configure the log level. Valid options are
+  - `PANIC`
+  - `FATAL`
+  - `ERROR`
+  - `WARNING`
+  - `INFO` (default)
+  - `DEBUG`
+  - `TRACE`
+- `RATIFY_CONFIG`: change the default Ratify configuration directory. Defaults to `~/.ratify`
diff --git a/pkg/common/logging.go b/pkg/common/logging.go
new file mode 100644
index 0000000..0af37db
--- /dev/null
+++ b/pkg/common/logging.go
@@ -0,0 +1,45 @@
+/*
+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 common
+
+import (
+	"os"
+
+	"github.com/sirupsen/logrus"
+)
+
+const defaultLevel = logrus.InfoLevel
+
+func SetLoggingLevelFromEnv(logger *logrus.Logger) {
+	SetLoggingLevel(os.Getenv("RATIFY_LOG_LEVEL"), logger)
+}
+
+func SetLoggingLevel(level string, logger *logrus.Logger) {
+	var logrusLevel logrus.Level
+	if level == "" {
+		logrusLevel = defaultLevel
+	} else {
+		var err error
+		logrusLevel, err = logrus.ParseLevel(level)
+		if err != nil {
+			logrusLevel = defaultLevel
+			logger.Infof("Invalid log level %s, defaulting to %s", level, defaultLevel)
+			logger.Infof("Valid log levels are: %v", logrus.AllLevels)
+		}
+	}
+	logger.Infof("Setting log level to %s", logrusLevel)
+	logger.SetLevel(logrusLevel)
+}
diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go
index 4f4b914..b738555 100644
--- a/pkg/common/plugin/exec.go
+++ b/pkg/common/plugin/exec.go
@@ -24,6 +24,8 @@ import (
 	"os/exec"
 	"strings"
 	"time"
+
+	"github.com/sirupsen/logrus"
 )
 
 const (
@@ -53,6 +55,22 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string,
 	c.Stdout = stdout
 	c.Stderr = stderr
 
+	// DEBUG: log the process details used to launch the binary plugin
+	if logrus.IsLevelEnabled(logrus.DebugLevel) {
+		logrus.Debugf("launching plugin %s", pluginPath)
+
+		pluginEnv := make([]string, 3)
+		for _, env := range environ {
+			// plugins inherit all env vars, but we're interested in the RATIFY_* ones. This also helps to keep secret values out of the logs.
+			if strings.HasPrefix(env, "RATIFY_") {
+				pluginEnv = append(pluginEnv, env)
+			}
+		}
+		logrus.Debugf("env vars: %v", pluginEnv)
+		logrus.Debugf("args: %v", cmdArgs)
+		logrus.Debugf("stdin: %s", stdinData)
+	}
+
 	// Retry the command on "text file busy" errors
 	for i := 0; i <= maxRetryCount; i++ {
 		err := c.Run()
diff --git a/pkg/controllers/store_controller.go b/pkg/controllers/store_controller.go
index 2b543ac..65ed172 100644
--- a/pkg/controllers/store_controller.go
+++ b/pkg/controllers/store_controller.go
@@ -24,7 +24,6 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
-	"sigs.k8s.io/controller-runtime/pkg/log"
 
 	configv1alpha1 "github.com/deislabs/ratify/api/v1alpha1"
 	"github.com/deislabs/ratify/config"
@@ -32,6 +31,7 @@ import (
 	rc "github.com/deislabs/ratify/pkg/referrerstore/config"
 	sf "github.com/deislabs/ratify/pkg/referrerstore/factory"
 	"github.com/deislabs/ratify/pkg/referrerstore/types"
+	"github.com/sirupsen/logrus"
 )
 
 // StoreReconciler reconciles a Store object
@@ -42,8 +42,7 @@ type StoreReconciler struct {
 
 var (
 	// a map to track active stores
-	StoreMap    = map[string]referrerstore.ReferrerStore{}
-	storeLogger = log.Log
+	StoreMap = map[string]referrerstore.ReferrerStore{}
 )
 
 //+kubebuilder:rbac:groups=config.ratify.deislabs.io,resources=stores,verbs=get;list;watch;create;update;patch;delete
@@ -56,16 +55,16 @@ var (
 // For more details, check Reconcile and its Result here:
 // - https://pkg.go.dev/sigs.k8s.io/controller-runtime@v0.12.2/pkg/reconcile
 func (r *StoreReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-	storeLogger := log.FromContext(ctx)
+	storeLogger := logrus.WithContext(ctx)
 
 	var store configv1alpha1.Store
 	var resource = req.Name
-	storeLogger.Info(fmt.Sprintf("reconciling store '%v'", resource))
+	storeLogger.Infof("reconciling store '%v'", resource)
 
 	if err := r.Get(ctx, req.NamespacedName, &store); err != nil {
 
 		if apierrors.IsNotFound(err) {
-			storeLogger.Info(fmt.Sprintf("deletion detected, removing store %v", req.Name))
+			storeLogger.Infof("deletion detected, removing store %v", req.Name)
 			storeRemove(resource)
 		} else {
 			storeLogger.Error(err, "unable to fetch store")
@@ -99,17 +98,17 @@ func storeAddOrReplace(spec configv1alpha1.StoreSpec, fullname string) error {
 	storeConfigVersion := "1.0.0"
 	if spec.Address == "" {
 		spec.Address = config.GetDefaultPluginPath()
-		storeLogger.Info(fmt.Sprintf("Address was empty, setting to default path %v", spec.Address))
+		logrus.Infof("Address was empty, setting to default path %v", spec.Address)
 	}
 	storeReference, err := sf.CreateStoreFromConfig(storeConfig, storeConfigVersion, []string{spec.Address})
 
 	if err != nil || storeReference == nil {
-		storeLogger.Error(err, "store factory failed to create store from store config")
+		logrus.Error(err, "store factory failed to create store from store config")
 		return fmt.Errorf("store factory failed to create store from store config, err: %q", err)
 	}
 
 	StoreMap[fullname] = storeReference
-	storeLogger.Info(fmt.Sprintf("store '%v' added to store map", storeReference.Name()))
+	logrus.Infof("store '%v' added to store map", storeReference.Name())
 
 	return nil
 }
@@ -126,7 +125,7 @@ func specToStoreConfig(storeSpec configv1alpha1.StoreSpec) (rc.StorePluginConfig
 
 	if string(storeSpec.Parameters.Raw) != "" {
 		if err := json.Unmarshal(storeSpec.Parameters.Raw, &storeConfig); err != nil {
-			storeLogger.Error(err, "unable to decode store parameters", "Parameters.Raw", storeSpec.Parameters.Raw)
+			logrus.Error(err, "unable to decode store parameters", "Parameters.Raw", storeSpec.Parameters.Raw)
 			return rc.StorePluginConfig{}, err
 		}
 	}
diff --git a/pkg/controllers/verifier_controller.go b/pkg/controllers/verifier_controller.go
index 12025f6..362ded5 100644
--- a/pkg/controllers/verifier_controller.go
+++ b/pkg/controllers/verifier_controller.go
@@ -26,11 +26,11 @@ import (
 	vc "github.com/deislabs/ratify/pkg/verifier/config"
 	vf "github.com/deislabs/ratify/pkg/verifier/factory"
 	"github.com/deislabs/ratify/pkg/verifier/types"
+	"github.com/sirupsen/logrus"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/apimachinery/pkg/runtime"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
-	"sigs.k8s.io/controller-runtime/pkg/log"
 )
 
 // VerifierReconciler reconciles a Verifier object
@@ -41,8 +41,7 @@ type VerifierReconciler struct {
 
 var (
 	// a map to track of active verifiers
-	VerifierMap    = map[string]vr.ReferenceVerifier{}
-	verifierLogger = log.Log
+	VerifierMap = map[string]vr.ReferenceVerifier{}
 )
 
 //+kubebuilder:rbac:groups=config.ratify.deislabs.io,resources=verifiers,verbs=get;list;watch;create;update;patch;delete
@@ -59,17 +58,16 @@ var (
 // For more details, check Reconcile and its Result here:
 // - https://pkg.go.dev/sigs.k8s.io/controller-runtime@v0.12.2/pkg/reconcile
 func (r *VerifierReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-
-	verifierLogger = log.FromContext(ctx)
+	verifierLogger := logrus.WithContext(ctx)
 
 	var verifier configv1alpha1.Verifier
 	var resource = req.Name
-	storeLogger.Info(fmt.Sprintf("reconciling verifier '%v'", resource))
+	verifierLogger.Infof("reconciling verifier '%v'", resource)
 
 	if err := r.Get(ctx, req.NamespacedName, &verifier); err != nil {
 
 		if apierrors.IsNotFound(err) {
-			verifierLogger.Info(fmt.Sprintf("delete event detected, removing verifier %v", resource))
+			verifierLogger.Infof("delete event detected, removing verifier %v", resource)
 			verifierRemove(resource)
 		} else {
 			verifierLogger.Error(err, "unable to fetch verifier")
@@ -93,7 +91,7 @@ func verifierAddOrReplace(spec configv1alpha1.VerifierSpec, objectName string) e
 	verifierConfig, err := specToVerifierConfig(spec)
 
 	if err != nil {
-		verifierLogger.Error(err, "unable to convert crd specification to verifier config")
+		logrus.Error(err, "unable to convert crd specification to verifier config")
 		return fmt.Errorf("unable to convert crd specification to verifier config, err: %q", err)
 	}
 
@@ -102,16 +100,16 @@ func verifierAddOrReplace(spec configv1alpha1.VerifierSpec, objectName string) e
 	verifierConfigVersion := "1.0.0" // TODO: move default values to defaulting webhook in the future #413
 	if spec.Address == "" {
 		spec.Address = config.GetDefaultPluginPath()
-		verifierLogger.Info(fmt.Sprintf("Address was empty, setting to default path: %v", spec.Address))
+		logrus.Infof("Address was empty, setting to default path: %v", spec.Address)
 	}
 	verifierReference, err := vf.CreateVerifierFromConfig(verifierConfig, verifierConfigVersion, []string{spec.Address})
 
 	if err != nil || verifierReference == nil {
-		verifierLogger.Error(err, "unable to create verifier from verifier config")
+		logrus.Error(err, "unable to create verifier from verifier config")
 		return err
 	}
 	VerifierMap[objectName] = verifierReference
-	verifierLogger.Info(fmt.Sprintf("verifier '%v' added to verifier map", verifierReference.Name()))
+	logrus.Infof("verifier '%v' added to verifier map", verifierReference.Name())
 
 	return nil
 }
@@ -128,7 +126,7 @@ func specToVerifierConfig(verifierSpec configv1alpha1.VerifierSpec) (vc.Verifier
 
 	if string(verifierSpec.Parameters.Raw) != "" {
 		if err := json.Unmarshal(verifierSpec.Parameters.Raw, &verifierConfig); err != nil {
-			verifierLogger.Error(err, "unable to decode verifier parameters", "Parameters.Raw", verifierSpec.Parameters.Raw)
+			logrus.Error(err, "unable to decode verifier parameters", "Parameters.Raw", verifierSpec.Parameters.Raw)
 			return vc.VerifierConfig{}, err
 		}
 	}
diff --git a/pkg/manager/manager.go b/pkg/manager/manager.go
index 36ebd0b..3824d08 100644
--- a/pkg/manager/manager.go
+++ b/pkg/manager/manager.go
@@ -55,7 +55,7 @@ import (
 
 var (
 	scheme   = runtime.NewScheme()
-	setupLog = ctrl.Log.WithName("setup")
+	setupLog = logrus.WithField("name", "setup")
 
 	configStores    []referrerstore.ReferrerStore
 	configVerifiers []verifier.ReferenceVerifier


Test patch:
diff --git a/pkg/common/logging_test.go b/pkg/common/logging_test.go
new file mode 100644
index 0000000..59d781f
--- /dev/null
+++ b/pkg/common/logging_test.go
@@ -0,0 +1,64 @@
+/*
+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 common
+
+import (
+	"testing"
+
+	"github.com/sirupsen/logrus"
+)
+
+func TestSetLoggingLevel_DefaultsToInfo_NoEnvVar(t *testing.T) {
+	SetLoggingLevel("", logrus.StandardLogger())
+	defer logrus.SetLevel(logrus.InfoLevel)
+
+	if logrus.GetLevel() != logrus.InfoLevel {
+		t.Errorf("Expected log level to be %s, got %s", logrus.InfoLevel, logrus.GetLevel())
+	}
+}
+
+func TestSetLoggingLevel_DefaultsToInfo_BadEnvVar(t *testing.T) {
+	SetLoggingLevel("undefinedlogginglevel", logrus.StandardLogger())
+	defer logrus.SetLevel(logrus.InfoLevel)
+
+	if logrus.GetLevel() != logrus.InfoLevel {
+		t.Errorf("Expected log level to be %s, got %s", logrus.InfoLevel, logrus.GetLevel())
+	}
+}
+
+func TestSetLoggingLevel_UsesEnvVar(t *testing.T) {
+	SetLoggingLevel("debug", logrus.StandardLogger())
+	defer logrus.SetLevel(logrus.InfoLevel)
+
+	if logrus.GetLevel() != logrus.DebugLevel {
+		t.Errorf("Expected log level to be %s, got %s", logrus.DebugLevel, logrus.GetLevel())
+	}
+}
+
+func TestSetLoggingLevel_UpdatesTargetLogger(t *testing.T) {
+	testLogger := logrus.New()
+	SetLoggingLevel("debug", testLogger)
+
+	// ensure the test logger is updated
+	if testLogger.GetLevel() != logrus.DebugLevel {
+		t.Errorf("Expected log level to be %s, got %s", logrus.DebugLevel, testLogger.GetLevel())
+	}
+
+	// ensure the standard logger is not updated
+	if logrus.GetLevel() != logrus.InfoLevel {
+		t.Errorf("Expected log level to be %s, got %s", logrus.InfoLevel, logrus.GetLevel())
+	}
+}