refactor: refactor log (ratify-project#1008)

.github/ISSUE_TEMPLATE/bug-report.yaml

@@ -27,7 +27,7 @@ body:
       required: true
     attributes:
       label: What happened in your environment? 
-      description: "install ratify with debug logs by adding --set logLevel=debug to helm install command or set RATIFY_LOG_LEVEL=debug as an environment variable"
+      description: "install ratify with debug logs by adding --set logger.level=debug to helm install command or set RATIFY_LOG_LEVEL=debug as an environment variable"
   - type: textarea
     id: expect
     attributes:

Makefile

@@ -442,7 +442,7 @@ e2e-deploy-base-ratify: e2e-notation-setup e2e-notation-leaf-cert-setup e2e-inli
 	--set oras.useHttp=true \
 	--set cosign.enabled=false \
 	--set-file dockerConfig="mount_config.json" \
-	--set logLevel=debug
+	--set logger.level=debug
 
 	rm mount_config.json
 
@@ -477,7 +477,7 @@ e2e-helm-deploy-ratify:
 	--set cosign.key="$$(cat .staging/cosign/cosign.pub)" \
 	--set oras.useHttp=true \
 	--set-file dockerConfig="mount_config.json" \
-	--set logLevel=debug
+	--set logger.level=debug
 
 	rm mount_config.json
 
@@ -495,7 +495,7 @@ e2e-helm-deploy-ratify-without-tls-certs:
 	--set cosign.key="$$(cat .staging/cosign/cosign.pub)" \
 	--set oras.useHttp=true \
 	--set-file dockerConfig="mount_config.json" \
-	--set logLevel=debug
+	--set logger.level=debug
 
 	rm mount_config.json
 
@@ -535,7 +535,7 @@ e2e-helm-deploy-ratify-replica: e2e-helm-deploy-redis e2e-notation-setup e2e-bui
 	--set oras.useHttp=true \
 	--set cosign.enabled=false \
 	--set-file dockerConfig="mount_config.json" \
-	--set logLevel=debug \
+	--set logger.level=debug \
 	--set replicaCount=2 \
 	--set provider.cache.type="dapr" \
 	--set provider.cache.name="dapr-redis" \

charts/ratify/templates/configmap.yaml

@@ -5,6 +5,12 @@ metadata:
 data:
   config.json: |
     {
+      "logger": {
+        "formatter": {{ .Values.logger.formatter | quote }},
+        "requestHeaders": {
+          "traceIDHeaderName": {{ .Values.logger.requestHeaders.traceIDHeaderName | quote }}
+        }
+      },
       "executor": {
         "verificationRequestTimeout": {{ .Values.provider.timeout.validationTimeoutSeconds | int | mul 1000 | add -100 }},
         "mutationRequestTimeout": {{ .Values.provider.timeout.mutationTimeoutSeconds | int | mul 1000 | add -50 }}

charts/ratify/templates/deployment.yaml

@@ -26,7 +26,7 @@ spec:
         {{- if and .Values.provider.cache.enabled  (eq .Values.provider.cache.type "dapr") }}
         dapr.io/enabled: "true"
         dapr.io/app-id: {{ include "ratify.fullname" . }}
-        {{- if eq (lower .Values.logLevel) "debug" }}
+        {{- if eq (lower .Values.logger.level) "debug" }}
         dapr.io/enable-api-logging: "true"
         {{- end }}
         {{- end }}
@@ -103,9 +103,9 @@ spec:
               readOnly: true
             {{- end }}
           env:
-          {{- if .Values.logLevel }}
+          {{- if .Values.logger.level }}
             - name: RATIFY_LOG_LEVEL
-              value: {{ .Values.logLevel }}
+              value: {{ .Values.logger.level }}
           {{- end }}
           {{- if $dockerAuthMode }}
             - name: DOCKER_CONFIG

charts/ratify/values.yaml

@@ -6,7 +6,6 @@ image:
 
 nameOverride: ""
 fullnameOverride: ""
-logLevel: info
 replicaCount: 1
 notationCert: ""
 cosign:
@@ -114,6 +113,13 @@ crds:
 policy:
   useRego: false # Set to true if Rego Policy would be used for evaluation.
 
+logger:
+  formatter: "text" # Formatter can be set to `text`, `json` or `logstash`. Default to `text` if not specified.
+  level: "info" # Default to `info` if not specified.
+  requestHeaders:
+    traceIDHeaderName: # List of headers that include the trace ID in the external data requests to Ratify. The same headers will be passed to upstream services like remote registries.
+      - "" # e.g. Set it to `x-ms-correlation-request-id` to trace across Azure.
+
 # See https://github.com/deislabs/ratify/blob/main/docs/reference/usage.md for a list of available feature flags
 featureFlags:
   # RATIFY_FEATURE_NAME: true

cmd/ratify/cmd/discover.go

@@ -23,6 +23,7 @@ import (
 	"strings"
 
 	"github.com/deislabs/ratify/config"
+	"github.com/deislabs/ratify/internal/logger"
 	"github.com/deislabs/ratify/pkg/common"
 	"github.com/deislabs/ratify/pkg/ocispecs"
 	"github.com/deislabs/ratify/pkg/referrerstore"
@@ -104,6 +105,10 @@ func discover(opts discoverCmdOptions) error {
 		return err
 	}
 
+	if err := logger.InitLogConfig(cf.LoggerConfig); err != nil {
+		return err
+	}
+
 	rootImage := treeprint.NewWithRoot(subRef.String())
 
 	stores, err := sf.CreateStoresFromConfig(cf.StoresConfig, config.GetDefaultPluginPath())

cmd/ratify/cmd/referrer.go

@@ -23,6 +23,7 @@ import (
 	"strings"
 
 	"github.com/deislabs/ratify/config"
+	"github.com/deislabs/ratify/internal/logger"
 	"github.com/deislabs/ratify/pkg/ocispecs"
 	sf "github.com/deislabs/ratify/pkg/referrerstore/factory"
 	"github.com/deislabs/ratify/pkg/utils"
@@ -141,6 +142,10 @@ func showBlob(opts referrerCmdOptions) error {
 		return err
 	}
 
+	if err := logger.InitLogConfig(cf.LoggerConfig); err != nil {
+		return err
+	}
+
 	stores, err := sf.CreateStoresFromConfig(cf.StoresConfig, config.GetDefaultPluginPath())
 
 	if err != nil {

cmd/ratify/cmd/resolve.go

@@ -23,6 +23,7 @@ import (
 	"strings"
 
 	"github.com/deislabs/ratify/config"
+	"github.com/deislabs/ratify/internal/logger"
 	sf "github.com/deislabs/ratify/pkg/referrerstore/factory"
 	su "github.com/deislabs/ratify/pkg/referrerstore/utils"
 	"github.com/deislabs/ratify/pkg/utils"
@@ -80,6 +81,10 @@ func resolve(opts resolveCmdOptions) error {
 		return err
 	}
 
+	if err := logger.InitLogConfig(cf.LoggerConfig); err != nil {
+		return err
+	}
+
 	stores, err := sf.CreateStoresFromConfig(cf.StoresConfig, config.GetDefaultPluginPath())
 
 	if err != nil {

cmd/ratify/cmd/serve.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/deislabs/ratify/config"
 	"github.com/deislabs/ratify/httpserver"
+	"github.com/deislabs/ratify/internal/logger"
 	"github.com/deislabs/ratify/pkg/cache"
 	"github.com/deislabs/ratify/pkg/manager"
 	"github.com/sirupsen/logrus"
@@ -87,6 +88,14 @@ func serve(opts serveCmdOptions) error {
 		}
 		logrus.Debugf("initialized cache of type %s", opts.cacheType)
 	}
+	logConfig, err := config.GetLoggerConfig(opts.configFilePath)
+	if err != nil {
+		return fmt.Errorf("failed to retrieve logger configuration: %w", err)
+	}
+	if err := logger.InitLogConfig(logConfig); err != nil {
+		return fmt.Errorf("failed to initialize logger configuration: %w", err)
+	}
+
 	// in crd mode, the manager gets latest store/verifier from crd and pass on to the http server
 	if opts.enableCrdManager {
 		certRotatorReady := make(chan struct{})

cmd/ratify/cmd/verify.go

@@ -21,6 +21,7 @@ import (
 	"fmt"
 
 	"github.com/deislabs/ratify/config"
+	"github.com/deislabs/ratify/internal/logger"
 	e "github.com/deislabs/ratify/pkg/executor"
 	ef "github.com/deislabs/ratify/pkg/executor/core"
 	pf "github.com/deislabs/ratify/pkg/policyprovider/factory"
@@ -88,6 +89,10 @@ func verify(opts verifyCmdOptions) error {
 		return err
 	}
 
+	if err := logger.InitLogConfig(cf.LoggerConfig); err != nil {
+		return err
+	}
+
 	stores, err := sf.CreateStoresFromConfig(cf.StoresConfig, config.GetDefaultPluginPath())
 
 	if err != nil {

cmd/ratify/main.go

@@ -25,15 +25,8 @@ import (
 	_ "github.com/deislabs/ratify/pkg/policyprovider/regopolicy"   // register regopolicy policy provider
 	_ "github.com/deislabs/ratify/pkg/referrerstore/oras"          // register oras referrer store
 	_ "github.com/deislabs/ratify/pkg/verifier/notation"           // register notation verifier
-	"github.com/sirupsen/logrus"
 )
 
-func init() {
-	logrus.SetFormatter(&logrus.TextFormatter{
-		DisableQuote: true,
-	})
-}
-
 func main() {
 	if err := cmd.Root.Execute(); err != nil {
 		os.Exit(1)

config/config.go

@@ -24,6 +24,7 @@ import (
 	"path/filepath"
 	"sync"
 
+	"github.com/deislabs/ratify/internal/logger"
 	exConfig "github.com/deislabs/ratify/pkg/executor/config"
 	"github.com/deislabs/ratify/pkg/homedir"
 	"github.com/deislabs/ratify/pkg/policyprovider"
@@ -50,6 +51,7 @@ type Config struct {
 	PoliciesConfig  pcConfig.PoliciesConfig  `json:"policy,omitempty"`
 	VerifiersConfig vfConfig.VerifiersConfig `json:"verifier,omitempty"`
 	ExecutorConfig  exConfig.ExecutorConfig  `json:"executor,omitempty"`
+	LoggerConfig    logger.Config            `json:"logger,omitempty"`
 	fileHash        string                   `json:"-"`
 }
 
@@ -136,6 +138,16 @@ func GetDefaultPluginPath() string {
 	return defaultPluginsPath
 }
 
+// GetLoggerConfig returns logger configuration from config file at specified path.
+func GetLoggerConfig(configFilePath string) (logger.Config, error) {
+	config, err := Load(configFilePath)
+	if err != nil {
+		return logger.Config{}, fmt.Errorf("unable to load config: %w", err)
+	}
+
+	return config.LoggerConfig, nil
+}
+
 // if configFilePath is empty, return configuration path from environment variable
 func getConfigurationFile(configFilePath string) string {
 	if configFilePath == "" {

docs/quickstarts/developer-getting-started.md

@@ -132,7 +132,7 @@ helm install ratify ./charts/ratify \
     --set image.crdRepository=localbuildcrd \
     --set image.tag=test \
     --set image.pullPolicy=${IMAGE_PULL_POLICY} \
-    --set logLevel=info      
+    --set logger.level=info      
 ```
 
 ### Upgrade
@@ -149,7 +149,7 @@ helm upgrade -i ratify ./charts/ratify \
     --set image.crdRepository=localbuildcrd \
     --set image.tag=test \
     --set image.pullPolicy=${IMAGE_PULL_POLICY} \
-    --set logLevel=info    
+    --set logger.level=info    
 ```
 
 ### Uninstall
@@ -217,7 +217,7 @@ See [debugging Ratify with VSCode](../../CONTRIBUTING.md#debugging-ratify-with-v
 
 ### Ratify logs 
 
-When installing Ratify the log level can be specified by specifying the switch `--set logLevel=info`.
+When installing Ratify the log level can be specified by specifying the switch `--set logger.level=info`.
 
 The log level can also be configured by setting the env variable `RATIFY_LOG_LEVEL` with one of the follow values:
 

docs/reference/crds/policies.md

@@ -68,7 +68,7 @@ spec:
 ```
 | Name | Required | Description | Default Value |
 | ----------- | -------- | ----------- | ------------- |
-| passthroughEnabled | no | If set to true, the policy will return true if the verification result is not available. | false |
+| passthroughEnabled | no | If set to true, Ratify will NOT make the decision but pass verifier reports to Gatekeeper. | false |
 | policy | no | The policy language that defines the policy. | "" |
 | policyPath | no | The path to the policy file if policy is mounted as a volume | "" |
 

docs/reference/logger.md

@@ -0,0 +1,70 @@
+# Logger
+
+## Overview
+Logging is a very important part of Ratify as it provides a way to debug and understand the behavior of the system. Ratify uses [Logrus](https://github.com/sirupsen/logrus) as the logging library.
+
+## Usage
+Ratify exposes a few options for users to configure the behaviors of the logger in the helm chart values or the configuration file below.
+
+### Configuration
+When running Ratify as a K8s add-on, users could configure the logger by setting [helm chart values](../../charts/ratify/values.yaml), e.g.
+```yaml
+logger:
+  formatter: "text"
+  level: "info"
+  requestHeaders:
+    traceIDHeaderName:
+      - "x-trace-id"
+      - "x-ms-correlation-request-id"
+```
+
+### Formatter
+Users could set the formatter to be `text`, `json` or `logstash`. The default value is `text` if it's not set.
+
+`json` and `text` are 2 commonly used formats for logging system. `logstash` is another format that's compatible with [Logstash](https://www.elastic.co/logstash).
+
+### Log Levels
+Users could configure log level by setting `logger.level` to the expected level. The default value is `info`.
+
+### Request Headers
+Ratify supports logging required headers from the external data request and passing to dependency services through the http header. Users could configure the logger to log the request headers by setting the `requestHeaders` field in the config. The `requestHeaders` field is a map of field name to header name(or array of names) in the request.
+
+Fields that Ratify supports logging are:
+- `traceIDHeaderName`: The trace ID header names in the request. Ratify will log the trace ID if it's set in the request header. Otherwise, it will generate a new trace ID and log it. Futhermore, since Ratify supports multiple oci-compatible registries, users could specify multiple traceID header names that are used by different registries. Note: 1. external data request MUST have at most one traceID in the header, if users specify multiple traceID header names, they MUST have the same traceID. 2. Http requests from Ratify to remote registries will always have all specified traceID names set to the same traceID in the header.
+
+Example:
+```
+logger:
+  formatter: "text"
+  level: "info"
+  requestHeaders:
+    traceIDHeaderName:
+      - "x-ms-correlation-request-id"
+```
+Add `"x-ms-correlation-request-id"` under `traceIDHeaderName` to support tracing requests across Azure and Ratify.
+In Ratify, users could see trace-id is appeneded to each log record.
+![](../imgs/trace-id-log.png)
+
+## Contribution Guide
+### Ratify Repo Contributor
+For Ratify contributors, you only need to follow 2 steps:
+1. Define a constant for the log option or a new log option field within the expecting component struct.
+2. Replace the original `logrus.Info` with `logger.GetLogger(ctx, logOpt).Info()`, which applies to all log levels.
+e.g. [executor](../../pkg/executor/core/executor.go)
+```go
+import "github.com/deislabs/ratify/internal/logger"
+var logOpt = logger.Option{
+	ComponentType: logger.Executor,
+}
+logger.GetLogger(ctx, logOpt).Info("test")
+```
+
+### External Plugin Developer
+For external plugins, if you want to leverage features provided by Ratify, like the trace-id, please follow 2 steps:
+1. Import `github.com/docker/distribution/context`
+2. Replace the original `logrus.Info` with `context.GetLogger.Info()`, which applies to all log levels.
+e.g.
+```go
+import "github.com/docker/distribution/context"
+dcontext.GetLogger(ctx).Info("test")
+```

go.mod

@@ -137,6 +137,7 @@ require (
 	github.com/aws/smithy-go v1.14.2 // indirect
 	github.com/beorn7/perks v1.0.1 // indirect
 	github.com/blang/semver v3.5.1+incompatible // indirect
+	github.com/bshuster-repo/logrus-logstash-hook v1.1.0
 	github.com/containerd/stargz-snapshotter/estargz v0.14.3 // indirect
 	github.com/cyberphone/json-canonicalization v0.0.0-20220623050100-57a0ce2678a7 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
@@ -170,7 +171,7 @@ require (
 	github.com/google/gnostic v0.5.7-v3refs // indirect
 	github.com/google/go-cmp v0.5.9 // indirect
 	github.com/google/gofuzz v1.2.0 // indirect
-	github.com/google/uuid v1.3.0 // indirect
+	github.com/google/uuid v1.3.0
 	github.com/hashicorp/hcl v1.0.0 // indirect
 	github.com/imdario/mergo v0.3.15 // indirect
 	github.com/in-toto/in-toto-golang v0.9.0 // indirect

go.sum

@@ -215,6 +215,8 @@ github.com/bgentry/speakeasy v0.1.0/go.mod h1:+zsyZBPWlz7T6j88CTgSN5bM796AkVf0kB
 github.com/bketelsen/crypt v0.0.3-0.20200106085610-5cbc8cc4026c/go.mod h1:MKsuJmJgSg28kpZDP6UIiPt0e0Oz0kqKNGyRaWEPv84=
 github.com/blang/semver v3.5.1+incompatible h1:cQNTCjp13qL8KC3Nbxr/y2Bqb63oX6wdnnjpJbkM4JQ=
 github.com/blang/semver v3.5.1+incompatible/go.mod h1:kRBLl5iJ+tD4TcOOxsy/0fnwebNt5EWlYSAyrTnjyyk=
+github.com/bshuster-repo/logrus-logstash-hook v1.1.0 h1:o2FzZifLg+z/DN1OFmzTWzZZx/roaqt8IPZCIVco8r4=
+github.com/bshuster-repo/logrus-logstash-hook v1.1.0/go.mod h1:Q2aXOe7rNuPgbBtPCOzYyWDvKX7+FpxE5sRdvcPoui0=
 github.com/bwesterb/go-ristretto v1.2.0/go.mod h1:fUIoIZaG73pV5biE2Blr2xEzDoMj7NFEuV9ekS419A0=
 github.com/bytecodealliance/wasmtime-go/v3 v3.0.2 h1:3uZCA/BLTIu+DqCfguByNMJa2HVHpXvjfy0Dy7g6fuA=
 github.com/cenkalti/backoff/v3 v3.2.2 h1:cfUAAO3yvKMYKPrvhDuHSwQnhZNk/RMHKdZqKTxfm6M=
@@ -782,6 +784,7 @@ github.com/sigstore/timestamp-authority v1.1.1/go.mod h1:cEDLEHl/L3ppqKDaiZ3Cg4i
 github.com/sirupsen/logrus v1.4.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/sirupsen/logrus v1.4.1/go.mod h1:ni0Sbl8bgC9z8RoU9G6nDWqqs/fq4eDPysMBDgk/93Q=
 github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
+github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/sirupsen/logrus v1.9.0/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
 github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
@@ -1095,6 +1098,7 @@ golang.org/x/sys v0.0.0-20190726091711-fc99dfbffb4e/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20190904154756-749cb33beabd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191001151750-bb3f8db39f24/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191005200804-aed5e4c7ecf9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191120155948-bd437916bb0e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191204072324-ce4227a45e2e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191228213918-04cbcbbfeed8/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=