Merge pull request #2048 from zregvart/issue/EC-801

Tracing support

cmd/root/root_cmd.go

@@ -23,23 +23,26 @@ import (
 	"os"
 	"runtime"
 	"runtime/pprof"
+	"runtime/trace"
 	"sync"
 	"time"
 
 	hd "github.com/MakeNowJust/heredoc"
 	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
+	"github.com/spf13/pflag"
 
 	"github.com/enterprise-contract/ec-cli/internal/kubernetes"
 	"github.com/enterprise-contract/ec-cli/internal/logging"
+	"github.com/enterprise-contract/ec-cli/internal/tracing"
 )
 
 var (
-	quiet         bool = false
-	verbose       bool = false
-	debug         bool = false
-	trace         bool = false
-	globalTimeout      = 5 * time.Minute
+	quiet         bool          = false
+	verbose       bool          = false
+	debug         bool          = false
+	enabledTraces tracing.Trace = tracing.None
+	globalTimeout               = 5 * time.Minute
 	logfile       string
 	OnExit        func() = func() {}
 )
@@ -66,30 +69,41 @@ func NewRootCmd() *cobra.Command {
 		SilenceUsage: true,
 
 		PersistentPreRun: func(cmd *cobra.Command, _ []string) {
-			logging.InitLogging(verbose, quiet, debug, trace, logfile)
+			logging.InitLogging(verbose, quiet, debug, enabledTraces.Enabled(tracing.Log, tracing.Opa), logfile)
 
 			// set a custom message for context.DeadlineExceeded error
 			context.DeadlineExceeded = customDeadlineExceededError{}
 
 			// Create a new context now that flags have been parsed so a custom timeout can be used.
 			ctx, cancel := context.WithTimeout(cmd.Context(), globalTimeout)
+			ctx = tracing.WithTrace(ctx, enabledTraces)
 			cmd.SetContext(ctx)
 			log.Debugf("globalTimeout is %d", globalTimeout)
 
-			// if trace is enabled setup CPU profiling
 			var cpuprofile *os.File
-			if trace {
+			var tracefile *os.File
+			if enabledTraces.Enabled(tracing.CPU) {
 				var err error
 				if cpuprofile, err = os.CreateTemp("", "cpuprofile.*"); err != nil {
-					log.Fatal("could not create CPU profile: ", err)
+					log.Fatalf("could not create CPU profile: %v", err)
 				}
 				if err := pprof.StartCPUProfile(cpuprofile); err != nil {
-					log.Fatal("could not start CPU profile: ", err)
+					log.Fatalf("could not start CPU profile: %v", err)
+				}
+			}
+
+			if enabledTraces.Enabled(tracing.Perf) {
+				var err error
+				if tracefile, err = os.CreateTemp("", "perf.*"); err != nil {
+					log.Fatalf("could not create trace file: %v", err)
+				}
+				if err := trace.Start(tracefile); err != nil {
+					log.Fatalf("failed to start trace: %v", err)
 				}
 			}
 
 			OnExit = sync.OnceFunc(func() {
-				if trace {
+				if enabledTraces.Enabled(tracing.Memory) {
 					// dump memory profile
 					if memprofile, err := os.CreateTemp("", "memprofile.*"); err != nil {
 						log.Fatal("could not create memory profile: ", err)
@@ -100,14 +114,24 @@ func NewRootCmd() *cobra.Command {
 							log.Fatal("could not start CPU profile: ", err)
 						}
 
-						log.Tracef("wrote memory profile to: %s", memprofile.Name())
+						cmd.PrintErrf("Wrote memory profile to: %s\n", memprofile.Name())
 					}
+				}
 
+				if enabledTraces.Enabled(tracing.CPU) {
 					// dump the CPU profile
 					pprof.StopCPUProfile()
 					if cpuprofile != nil {
 						_ = cpuprofile.Close() // ignore errors
-						log.Tracef("wrote CPU profile to: %s", cpuprofile.Name())
+						cmd.PrintErrf("Wrote CPU profile to: %s\n", cpuprofile.Name())
+					}
+				}
+
+				if enabledTraces.Enabled(tracing.Perf) {
+					trace.Stop()
+					if tracefile != nil {
+						_ = tracefile.Close() // ignore errors
+						cmd.PrintErrf("Wrote performance trace to: %s\n", tracefile.Name())
 					}
 				}
 
@@ -128,10 +152,18 @@ func NewRootCmd() *cobra.Command {
 }
 
 func setFlags(rootCmd *cobra.Command) {
+	traceFlag := &pflag.Flag{
+		Name:        "trace",
+		Usage:       "enable trace logging, set one or more comma separated values: none,all," + tracing.All.String(),
+		Value:       &enabledTraces,
+		DefValue:    enabledTraces.String(),
+		NoOptDefVal: tracing.Default.String(),
+	}
+	rootCmd.PersistentFlags().AddFlag(traceFlag)
+
 	rootCmd.PersistentFlags().BoolVar(&quiet, "quiet", quiet, "less verbose output")
 	rootCmd.PersistentFlags().BoolVar(&verbose, "verbose", verbose, "more verbose output")
 	rootCmd.PersistentFlags().BoolVar(&debug, "debug", debug, "same as verbose but also show function names and line numbers")
-	rootCmd.PersistentFlags().BoolVar(&trace, "trace", trace, "enable trace logging")
 	rootCmd.PersistentFlags().DurationVar(&globalTimeout, "timeout", globalTimeout, "max overall execution duration")
 	rootCmd.PersistentFlags().StringVar(&logfile, "logfile", "", "file to write the logging output. If not specified logging output will be written to stderr")
 	kubernetes.AddKubeconfigFlag(rootCmd)

cmd/validate/image.go

@@ -21,6 +21,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"runtime/trace"
 	"sort"
 	"strings"
 
@@ -189,6 +190,13 @@ func validateImageCmd(validate imageValidationFunc) *cobra.Command {
 
 		PreRunE: func(cmd *cobra.Command, args []string) (allErrors error) {
 			ctx := cmd.Context()
+			if trace.IsEnabled() {
+				var task *trace.Task
+				ctx, task = trace.NewTask(ctx, "ec:validate-image-prepare")
+				defer task.End()
+				cmd.SetContext(ctx)
+			}
+
 			if s, err := applicationsnapshot.DetermineInputSpec(ctx, applicationsnapshot.Input{
 				File:     data.filePath,
 				JSON:     data.input,
@@ -284,6 +292,12 @@ func validateImageCmd(validate imageValidationFunc) *cobra.Command {
 		},
 
 		RunE: func(cmd *cobra.Command, args []string) error {
+			if trace.IsEnabled() {
+				ctx, task := trace.NewTask(cmd.Context(), "ec:validate-images")
+				cmd.SetContext(ctx)
+				defer task.End()
+			}
+
 			type result struct {
 				err         error
 				component   applicationsnapshot.Component
@@ -321,8 +335,15 @@ func validateImageCmd(validate imageValidationFunc) *cobra.Command {
 			worker := func(id int, jobs <-chan app.SnapshotComponent, results chan<- result) {
 				log.Debugf("Starting worker %d", id)
 				for comp := range jobs {
+					ctx := cmd.Context()
+					var task *trace.Task
+					if trace.IsEnabled() {
+						ctx, task = trace.NewTask(ctx, "ec:validate-component")
+						trace.Logf(ctx, "", "workerID=%d", id)
+					}
+
 					log.Debugf("Worker %d got a component %q", id, comp.ContainerImage)
-					out, err := validate(cmd.Context(), comp, data.spec, data.policy, evaluators, data.info)
+					out, err := validate(ctx, comp, data.spec, data.policy, evaluators, data.info)
 					res := result{
 						err: err,
 						component: applicationsnapshot.Component{
@@ -351,6 +372,9 @@ func validateImageCmd(validate imageValidationFunc) *cobra.Command {
 					}
 					res.component.Success = err == nil && len(res.component.Violations) == 0
 
+					if task != nil {
+						task.End()
+					}
 					results <- res
 				}
 				log.Debugf("Done with worker %d", id)

cmd/validate/input.go

@@ -20,6 +20,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"runtime/trace"
 	"sort"
 	"strings"
 	"sync"
@@ -102,6 +103,12 @@ func validateInputCmd(validate InputValidationFunc) *cobra.Command {
 			return
 		},
 		RunE: func(cmd *cobra.Command, args []string) error {
+			if trace.IsEnabled() {
+				ctx, task := trace.NewTask(cmd.Context(), "ec:validate-inputs")
+				cmd.SetContext(ctx)
+				defer task.End()
+			}
+
 			type result struct {
 				err         error
 				input       input.Input
@@ -118,9 +125,14 @@ func validateInputCmd(validate InputValidationFunc) *cobra.Command {
 			for _, f := range data.filePaths {
 				lock.Add(1)
 				go func(fpath string) {
+					ctx := cmd.Context()
+					var task *trace.Task
+					if trace.IsEnabled() {
+						ctx, task = trace.NewTask(ctx, "ec:validate-input")
+					}
+
 					defer lock.Done()
 
-					ctx := cmd.Context()
 					out, err := validate(ctx, fpath, data.policy, data.info)
 					res := result{
 						err: err,
@@ -142,6 +154,10 @@ func validateInputCmd(validate InputValidationFunc) *cobra.Command {
 						res.data = out.Data
 					}
 					res.input.Success = err == nil && len(res.input.Violations) == 0
+
+					if task != nil {
+						task.End()
+					}
 					ch <- res
 				}(f)
 			}

docs/modules/ROOT/pages/ec.adoc

@@ -18,7 +18,7 @@ ec [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == Options inherited from parent commands

docs/modules/ROOT/pages/ec_fetch.adoc

@@ -12,7 +12,7 @@ Fetch remote resources
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_fetch_policy.adoc

@@ -74,7 +74,7 @@ Notes:
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_init.adoc

@@ -12,7 +12,7 @@ Initialize a directory for use
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_init_policies.adoc

@@ -30,7 +30,7 @@ Initialize the "my-policy" directory with minimal EC policy scaffolding:
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_inspect.adoc

@@ -12,7 +12,7 @@ Inspect policy rules
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_inspect_policy-data.adoc

@@ -35,7 +35,7 @@ ec inspect policy-data --source git::https://github.com/enterprise-contract/ec-p
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_inspect_policy.adoc

@@ -47,7 +47,7 @@ Display details about the latest Enterprise Contract release policy in json form
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa.adoc

@@ -18,7 +18,7 @@ ec opa [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_bench.adoc

@@ -55,7 +55,7 @@ ec opa bench <query> [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_build.adoc

@@ -193,7 +193,7 @@ ec opa build <path> [<path> [...]] [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_capabilities.adoc

@@ -63,7 +63,7 @@ ec opa capabilities [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_check.adoc

@@ -32,7 +32,7 @@ ec opa check <path> [path [...]] [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_deps.adoc

@@ -54,7 +54,7 @@ ec opa deps <query> [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_eval.adoc

@@ -157,7 +157,7 @@ ec opa eval <query> [flags]
 --kubeconfig:: path to the Kubernetes config file to use
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_exec.adoc

@@ -56,7 +56,7 @@ ec opa exec <path> [<path> [...]] [flags]
 --kubeconfig:: path to the Kubernetes config file to use
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_fmt.adoc

@@ -44,7 +44,7 @@ ec opa fmt [path [...]] [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also

docs/modules/ROOT/pages/ec_opa_inspect.adoc

@@ -44,7 +44,7 @@ ec opa inspect <path> [<path> [...]] [flags]
 --logfile:: file to write the logging output. If not specified logging output will be written to stderr
 --quiet:: less verbose output (Default: false)
 --timeout:: max overall execution duration (Default: 5m0s)
---trace:: enable trace logging (Default: false)
+--trace:: enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (Default: none)
 --verbose:: more verbose output (Default: false)
 
 == See also