diff --git a/cmd/root/root_cmd.go b/cmd/root/root_cmd.go index 9e45e3075..13d9028f4 100644 --- a/cmd/root/root_cmd.go +++ b/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) diff --git a/cmd/validate/image.go b/cmd/validate/image.go index 22e7b2171..2538ada80 100644 --- a/cmd/validate/image.go +++ b/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) diff --git a/cmd/validate/input.go b/cmd/validate/input.go index d5960249b..2259a5bd2 100644 --- a/cmd/validate/input.go +++ b/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) } diff --git a/docs/modules/ROOT/pages/ec.adoc b/docs/modules/ROOT/pages/ec.adoc index f24448899..4ce060790 100644 --- a/docs/modules/ROOT/pages/ec.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_fetch.adoc b/docs/modules/ROOT/pages/ec_fetch.adoc index 974f67971..f40142206 100644 --- a/docs/modules/ROOT/pages/ec_fetch.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_fetch_policy.adoc b/docs/modules/ROOT/pages/ec_fetch_policy.adoc index d501de798..b8a3e905b 100644 --- a/docs/modules/ROOT/pages/ec_fetch_policy.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_init.adoc b/docs/modules/ROOT/pages/ec_init.adoc index 487915d43..6a3d95c1f 100644 --- a/docs/modules/ROOT/pages/ec_init.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_init_policies.adoc b/docs/modules/ROOT/pages/ec_init_policies.adoc index b122cf154..9c1e3e4ec 100644 --- a/docs/modules/ROOT/pages/ec_init_policies.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_inspect.adoc b/docs/modules/ROOT/pages/ec_inspect.adoc index ae67f20f9..531e8c9fc 100644 --- a/docs/modules/ROOT/pages/ec_inspect.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_inspect_policy-data.adoc b/docs/modules/ROOT/pages/ec_inspect_policy-data.adoc index 7b7233309..59a315324 100644 --- a/docs/modules/ROOT/pages/ec_inspect_policy-data.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_inspect_policy.adoc b/docs/modules/ROOT/pages/ec_inspect_policy.adoc index d50dd8c32..d98fc414f 100644 --- a/docs/modules/ROOT/pages/ec_inspect_policy.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_opa.adoc b/docs/modules/ROOT/pages/ec_opa.adoc index 506af70c4..37b2f1ddc 100644 --- a/docs/modules/ROOT/pages/ec_opa.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_opa_bench.adoc b/docs/modules/ROOT/pages/ec_opa_bench.adoc index 5b19145c1..b737f77bb 100644 --- a/docs/modules/ROOT/pages/ec_opa_bench.adoc +++ b/docs/modules/ROOT/pages/ec_opa_bench.adoc @@ -55,7 +55,7 @@ ec opa bench [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 diff --git a/docs/modules/ROOT/pages/ec_opa_build.adoc b/docs/modules/ROOT/pages/ec_opa_build.adoc index 34c1c171d..010b89f6a 100644 --- a/docs/modules/ROOT/pages/ec_opa_build.adoc +++ b/docs/modules/ROOT/pages/ec_opa_build.adoc @@ -193,7 +193,7 @@ ec opa build [ [...]] [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 diff --git a/docs/modules/ROOT/pages/ec_opa_capabilities.adoc b/docs/modules/ROOT/pages/ec_opa_capabilities.adoc index bf22c7cd0..f083b0a54 100644 --- a/docs/modules/ROOT/pages/ec_opa_capabilities.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_opa_check.adoc b/docs/modules/ROOT/pages/ec_opa_check.adoc index 852aaf0fc..97558885d 100644 --- a/docs/modules/ROOT/pages/ec_opa_check.adoc +++ b/docs/modules/ROOT/pages/ec_opa_check.adoc @@ -32,7 +32,7 @@ ec opa check [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 diff --git a/docs/modules/ROOT/pages/ec_opa_deps.adoc b/docs/modules/ROOT/pages/ec_opa_deps.adoc index 94763af5d..7dcfee743 100644 --- a/docs/modules/ROOT/pages/ec_opa_deps.adoc +++ b/docs/modules/ROOT/pages/ec_opa_deps.adoc @@ -54,7 +54,7 @@ ec opa deps [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 diff --git a/docs/modules/ROOT/pages/ec_opa_eval.adoc b/docs/modules/ROOT/pages/ec_opa_eval.adoc index 5960c4833..bd884ac6c 100644 --- a/docs/modules/ROOT/pages/ec_opa_eval.adoc +++ b/docs/modules/ROOT/pages/ec_opa_eval.adoc @@ -157,7 +157,7 @@ ec opa eval [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 diff --git a/docs/modules/ROOT/pages/ec_opa_exec.adoc b/docs/modules/ROOT/pages/ec_opa_exec.adoc index 3d7786ea4..a10e48953 100644 --- a/docs/modules/ROOT/pages/ec_opa_exec.adoc +++ b/docs/modules/ROOT/pages/ec_opa_exec.adoc @@ -56,7 +56,7 @@ ec opa exec [ [...]] [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 diff --git a/docs/modules/ROOT/pages/ec_opa_fmt.adoc b/docs/modules/ROOT/pages/ec_opa_fmt.adoc index c1c7d6adc..3c1b14292 100644 --- a/docs/modules/ROOT/pages/ec_opa_fmt.adoc +++ b/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 diff --git a/docs/modules/ROOT/pages/ec_opa_inspect.adoc b/docs/modules/ROOT/pages/ec_opa_inspect.adoc index ca2fe386f..111ffa1f6 100644 --- a/docs/modules/ROOT/pages/ec_opa_inspect.adoc +++ b/docs/modules/ROOT/pages/ec_opa_inspect.adoc @@ -44,7 +44,7 @@ ec opa inspect [ [...]] [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 diff --git a/docs/modules/ROOT/pages/ec_opa_parse.adoc b/docs/modules/ROOT/pages/ec_opa_parse.adoc index 1da7388d5..6cf4052fc 100644 --- a/docs/modules/ROOT/pages/ec_opa_parse.adoc +++ b/docs/modules/ROOT/pages/ec_opa_parse.adoc @@ -21,7 +21,7 @@ ec opa parse [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 diff --git a/docs/modules/ROOT/pages/ec_opa_run.adoc b/docs/modules/ROOT/pages/ec_opa_run.adoc index 3e1d67cf8..89d531b01 100644 --- a/docs/modules/ROOT/pages/ec_opa_run.adoc +++ b/docs/modules/ROOT/pages/ec_opa_run.adoc @@ -182,7 +182,7 @@ ec opa run [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 diff --git a/docs/modules/ROOT/pages/ec_opa_sign.adoc b/docs/modules/ROOT/pages/ec_opa_sign.adoc index b6cdb820f..7f1663c24 100644 --- a/docs/modules/ROOT/pages/ec_opa_sign.adoc +++ b/docs/modules/ROOT/pages/ec_opa_sign.adoc @@ -105,7 +105,7 @@ ec opa sign [ [...]] [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 diff --git a/docs/modules/ROOT/pages/ec_opa_test.adoc b/docs/modules/ROOT/pages/ec_opa_test.adoc index f5359b637..6ba641016 100644 --- a/docs/modules/ROOT/pages/ec_opa_test.adoc +++ b/docs/modules/ROOT/pages/ec_opa_test.adoc @@ -110,7 +110,7 @@ ec opa test [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) == See also diff --git a/docs/modules/ROOT/pages/ec_opa_version.adoc b/docs/modules/ROOT/pages/ec_opa_version.adoc index 3536454d5..44fb7334e 100644 --- a/docs/modules/ROOT/pages/ec_opa_version.adoc +++ b/docs/modules/ROOT/pages/ec_opa_version.adoc @@ -19,7 +19,7 @@ ec opa version [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 diff --git a/docs/modules/ROOT/pages/ec_sigstore.adoc b/docs/modules/ROOT/pages/ec_sigstore.adoc index 1479f60cf..c42275f4a 100644 --- a/docs/modules/ROOT/pages/ec_sigstore.adoc +++ b/docs/modules/ROOT/pages/ec_sigstore.adoc @@ -12,7 +12,7 @@ Perform certain sigstore operations --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 diff --git a/docs/modules/ROOT/pages/ec_sigstore_initialize.adoc b/docs/modules/ROOT/pages/ec_sigstore_initialize.adoc index 582cb1aae..f2e8af14e 100644 --- a/docs/modules/ROOT/pages/ec_sigstore_initialize.adoc +++ b/docs/modules/ROOT/pages/ec_sigstore_initialize.adoc @@ -48,7 +48,7 @@ ec initialize -mirror -root --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 diff --git a/docs/modules/ROOT/pages/ec_track.adoc b/docs/modules/ROOT/pages/ec_track.adoc index c724e8d02..9f41796c3 100644 --- a/docs/modules/ROOT/pages/ec_track.adoc +++ b/docs/modules/ROOT/pages/ec_track.adoc @@ -12,7 +12,7 @@ Record resource references for tracking purposes --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 diff --git a/docs/modules/ROOT/pages/ec_track_bundle.adoc b/docs/modules/ROOT/pages/ec_track_bundle.adoc index 67359e9bf..b06196416 100644 --- a/docs/modules/ROOT/pages/ec_track_bundle.adoc +++ b/docs/modules/ROOT/pages/ec_track_bundle.adoc @@ -76,7 +76,7 @@ Update existing acceptable bundles: --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 diff --git a/docs/modules/ROOT/pages/ec_validate.adoc b/docs/modules/ROOT/pages/ec_validate.adoc index 1b5105744..63ce55f24 100644 --- a/docs/modules/ROOT/pages/ec_validate.adoc +++ b/docs/modules/ROOT/pages/ec_validate.adoc @@ -13,7 +13,7 @@ Validate conformance with the Enterprise Contract --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 diff --git a/docs/modules/ROOT/pages/ec_validate_image.adoc b/docs/modules/ROOT/pages/ec_validate_image.adoc index f2c106db3..a977428ed 100644 --- a/docs/modules/ROOT/pages/ec_validate_image.adoc +++ b/docs/modules/ROOT/pages/ec_validate_image.adoc @@ -160,7 +160,7 @@ JSON of the "spec" or a reference to a Kubernetes object [/] --quiet:: less verbose output (Default: false) --show-successes:: (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 diff --git a/docs/modules/ROOT/pages/ec_validate_input.adoc b/docs/modules/ROOT/pages/ec_validate_input.adoc index 4d3b9bb80..5258805c8 100644 --- a/docs/modules/ROOT/pages/ec_validate_input.adoc +++ b/docs/modules/ROOT/pages/ec_validate_input.adoc @@ -65,7 +65,7 @@ mark (?) sign, for example: --output text=output.txt?show-successes=false --quiet:: less verbose output (Default: false) --show-successes:: (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 diff --git a/docs/modules/ROOT/pages/ec_validate_policy.adoc b/docs/modules/ROOT/pages/ec_validate_policy.adoc index ed9d8f6f1..935d80f24 100644 --- a/docs/modules/ROOT/pages/ec_validate_policy.adoc +++ b/docs/modules/ROOT/pages/ec_validate_policy.adoc @@ -32,7 +32,7 @@ ec validate policy --policy-configuration github.com/org/repo/policy.yaml --quiet:: less verbose output (Default: false) --show-successes:: (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 diff --git a/docs/modules/ROOT/pages/ec_version.adoc b/docs/modules/ROOT/pages/ec_version.adoc index c9d72e7df..097dd5404 100644 --- a/docs/modules/ROOT/pages/ec_version.adoc +++ b/docs/modules/ROOT/pages/ec_version.adoc @@ -14,7 +14,7 @@ Print version information --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 diff --git a/docs/modules/ROOT/pages/troubleshooting.adoc b/docs/modules/ROOT/pages/troubleshooting.adoc new file mode 100644 index 000000000..c4dde45f7 --- /dev/null +++ b/docs/modules/ROOT/pages/troubleshooting.adoc @@ -0,0 +1,39 @@ += Troubleshooting + +To identify the root cause of an issue encountered when running the `ec` command +line tool re-running the tool while gathering more information about its +execution can be useful. In the order of increasing verbosity the command line +options `--verbose`, `--debug`, and `--trace` emit additional log lines that can +be written to standard error or a file with the `--logfile` option. + +The `--trace` option supports enabling multiple tracing subsystems, one or more +can be combined using the comma (`,`) as a separator, defaulting to `log` to +enable only the trace log level if none were given. For example, specifying +`--trace=opa,log` will output both `ec` trace and the Open Policy Engine trace +logs. + +Policy execution can be traced to show any debug `print` statements in the Rego +files and the full engine execution trace by enabling the `opa` trace with +`--trace=opa`. + +TIP: The trace output can be quite verbose, filtering to include only the lines +containing the `.rego` is helpful to look at only the debug messages +printed by from a particular file. + +When using the `--trace`, memory (`mem`), CPU (`cpu`), or comprehensive +performance (`perf`) tracing metrics are written to files in the temporary +directory, and the path to these files is provided in the last lines of the +logging output. These files can be loaded into Golang tooling for further +analysis. + +For example, performance tracing can be captured and later analyzed using +workflow similar to: + +[source,sh] +---- +$ ec validate image --trace=perf ... +... +Wrote performance trace to: /tmp/perf.3645083324 +$ go tool trace -http=:6060 /tmp/perf.3645083324 +# open browser at http://localhost:6060 +---- \ No newline at end of file diff --git a/docs/modules/ROOT/partials/main_nav.adoc b/docs/modules/ROOT/partials/main_nav.adoc index b152c30b1..04bd89a85 100644 --- a/docs/modules/ROOT/partials/main_nav.adoc +++ b/docs/modules/ROOT/partials/main_nav.adoc @@ -1,4 +1,5 @@ * xref:index.adoc[Home] * xref:configuration.adoc[Configuration] * xref:policy_input.adoc[Policy Input] -* xref:signing.adoc[Signing] \ No newline at end of file +* xref:signing.adoc[Signing] +* xref:troubleshooting.adoc[Troubleshooting] \ No newline at end of file diff --git a/features/__snapshots__/opa.snap b/features/__snapshots__/opa.snap index 7f179202f..c23f6a593 100755 --- a/features/__snapshots__/opa.snap +++ b/features/__snapshots__/opa.snap @@ -25,13 +25,13 @@ Flags: -h, --help help for opa Global Flags: - --debug same as verbose but also show function names and line numbers - --kubeconfig string path to the Kubernetes config file to use - --logfile string file to write the logging output. If not specified logging output will be written to stderr - --quiet less verbose output - --timeout duration max overall execution duration (default 5m0s) - --trace enable trace logging - --verbose more verbose output + --debug same as verbose but also show function names and line numbers + --kubeconfig string path to the Kubernetes config file to use + --logfile string file to write the logging output. If not specified logging output will be written to stderr + --quiet less verbose output + --timeout duration max overall execution duration (default 5m0s) + --trace string[="log"] enable trace logging, set one or more comma separated values: none,all,perf,cpu,mem,opa,log (default "none") + --verbose more verbose output Use "ec opa [command] --help" for more information about a command. diff --git a/features/validate_image.feature b/features/validate_image.feature index cd7ce516b..e03b482a8 100644 --- a/features/validate_image.feature +++ b/features/validate_image.feature @@ -1059,7 +1059,7 @@ Feature: evaluate enterprise contract ] } """ - When ec command is run with "validate image --image ${REGISTRY}/acceptance/trace-debug --policy acceptance/ec-policy --public-key ${trace_debug_PUBLIC_KEY} --rekor-url ${REKOR} --show-successes --output json --trace" + When ec command is run with "validate image --image ${REGISTRY}/acceptance/trace-debug --policy acceptance/ec-policy --public-key ${trace_debug_PUBLIC_KEY} --rekor-url ${REKOR} --show-successes --output json --trace=opa" Then the exit status should be 0 And the standard error should contain """ diff --git a/internal/applicationsnapshot/input.go b/internal/applicationsnapshot/input.go index d746700bc..e35bcc2e7 100644 --- a/internal/applicationsnapshot/input.go +++ b/internal/applicationsnapshot/input.go @@ -20,6 +20,7 @@ import ( "context" "errors" "fmt" + "runtime/trace" "github.com/google/go-containerregistry/pkg/name" app "github.com/konflux-ci/application-api/api/v1alpha1" @@ -181,6 +182,11 @@ func readSnapshotSource(input []byte) (app.SnapshotSpec, error) { } func expandImageIndex(ctx context.Context, snap *app.SnapshotSpec) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:expand-image-index") + defer region.End() + } + client := oci.NewClient(ctx) // For an image index, remove the original component and replace it with an expanded component with all its image manifests var components []app.SnapshotComponent diff --git a/internal/downloader/downloader.go b/internal/downloader/downloader.go index 84787d0d4..af55c61c1 100644 --- a/internal/downloader/downloader.go +++ b/internal/downloader/downloader.go @@ -52,8 +52,8 @@ var gatherFunc = func(ctx context.Context, source, destination string) (metadata var _initialize = func() { if log.IsLevelEnabled(logrus.TraceLevel) { - goci.Transport = http.NewTracingRoundTripperWithLogger(goci.Transport, log) - ghttp.Transport = http.NewTracingRoundTripperWithLogger(ghttp.Transport, log) + goci.Transport = http.NewTracingRoundTripperWithLogger(goci.Transport) + ghttp.Transport = http.NewTracingRoundTripperWithLogger(ghttp.Transport) } backoff := retry.ExponentialBackoff(http.DefaultBackoff.Duration, http.DefaultBackoff.Factor, http.DefaultBackoff.Jitter) diff --git a/internal/downloader/downloader_test.go b/internal/downloader/downloader_test.go index 4673432fc..06f0e4c3f 100644 --- a/internal/downloader/downloader_test.go +++ b/internal/downloader/downloader_test.go @@ -23,12 +23,13 @@ import ( "context" "errors" "fmt" - standardLog "log" "math/rand/v2" "net/http" "net/http/httptest" "net/url" "path" + "regexp" + "runtime/trace" "sync" "testing" @@ -43,6 +44,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" + xtrace "golang.org/x/exp/trace" "oras.land/oras-go/v2/registry/remote/retry" echttp "github.com/enterprise-contract/ec-cli/internal/http" @@ -152,13 +154,19 @@ func TestIsSecure(t *testing.T) { } func TestOCITracing(t *testing.T) { + traceOutput := bytes.Buffer{} + require.NoError(t, trace.Start(&traceOutput)) + t.Cleanup(trace.Stop) + + log.Level = logrus.TraceLevel initialize = _initialize // we want it to re-execute for the test t.Cleanup(func() { - log = logrus.StandardLogger() + log.Level = logrus.InfoLevel initialize = sync.OnceFunc(_initialize) + goci.Transport = http.DefaultTransport + ghttp.Transport = http.DefaultTransport }) - requestLog := &bytes.Buffer{} - registry := httptest.NewServer(registry.New(registry.Logger(standardLog.New(requestLog, "", 0)))) + registry := httptest.NewServer(registry.New()) t.Cleanup(registry.Close) u, err := url.Parse(registry.URL) @@ -171,25 +179,48 @@ func TestOCITracing(t *testing.T) { require.NoError(t, err) require.NoError(t, remote.Push(ref, img)) - traceLog := bytes.Buffer{} - log = &logrus.Logger{ - Out: &traceLog, - Formatter: &logrus.TextFormatter{}, - Level: logrus.TraceLevel, - } - _, err = gatherFunc(context.Background(), ref.String(), t.TempDir()) require.NoError(t, err) - assert.Contains(t, requestLog.String(), "GET /v2/repository/image/manifests/tag") - assert.Contains(t, traceLog.String(), "START: GET http://127.0.0.1") + trace.Stop() + + traceReader, err := xtrace.NewReader(&traceOutput) + require.NoError(t, err) + + logs := []xtrace.Log{} + for err == nil { + var e xtrace.Event + e, err = traceReader.ReadEvent() + if err == nil && e.Kind() == xtrace.EventLog { + logs = append(logs, e.Log()) + } + } + assert.NotZero(t, len(logs)) + + expected := regexp.MustCompile(`^(method="GET")|(?:url="` + registry.URL + `(/v2/repository/image/manifests/tag|/v2/repository/image/blobs/sha256:[0-9a-f]{64})")|(received=\d+)$`) + + found := 0 + for _, l := range logs { + assert.Regexp(t, expected, l.Message) + found++ + } + + // 12 log messages for 4 requests, 3 per request + assert.Equal(t, 12, found) } func TestHTTPTracing(t *testing.T) { + traceOutput := bytes.Buffer{} + require.NoError(t, trace.Start(&traceOutput)) + t.Cleanup(trace.Stop) + + log.Level = logrus.TraceLevel initialize = _initialize // we want it to re-execute for the test t.Cleanup(func() { - log = logrus.StandardLogger() + log.Level = logrus.InfoLevel initialize = sync.OnceFunc(_initialize) + goci.Transport = http.DefaultTransport + ghttp.Transport = http.DefaultTransport }) var requests []string server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -198,18 +229,36 @@ func TestHTTPTracing(t *testing.T) { })) t.Cleanup(server.Close) - traceLog := bytes.Buffer{} - log = &logrus.Logger{ - Out: &traceLog, - Formatter: &logrus.TextFormatter{}, - Level: logrus.TraceLevel, - } - _, err := gatherFunc(context.Background(), server.URL, path.Join(t.TempDir(), "dl")) require.NoError(t, err) + trace.Stop() + + traceReader, err := xtrace.NewReader(&traceOutput) + require.NoError(t, err) + + logs := []xtrace.Log{} + for err == nil { + var e xtrace.Event + e, err = traceReader.ReadEvent() + if err == nil && e.Kind() == xtrace.EventLog { + logs = append(logs, e.Log()) + } + } + assert.NotZero(t, len(logs)) + assert.Equal(t, []string{"GET /"}, requests) - assert.Contains(t, traceLog.String(), "START: GET http://127.0.0.1") + + expected := regexp.MustCompile(`^(method="GET")|(?:url="` + server.URL + `")|(received=\d+)$`) + + found := 0 + for _, l := range logs { + assert.Regexp(t, expected, l.Message) + found++ + } + + // 3 log messages per request + assert.Equal(t, 3, found) } func TestOCIClientConfiguration(t *testing.T) { diff --git a/internal/evaluation_target/application_snapshot_image/application_snapshot_image.go b/internal/evaluation_target/application_snapshot_image/application_snapshot_image.go index 3a5e58e66..f7e14b93f 100644 --- a/internal/evaluation_target/application_snapshot_image/application_snapshot_image.go +++ b/internal/evaluation_target/application_snapshot_image/application_snapshot_image.go @@ -24,6 +24,7 @@ import ( "fmt" "os" "path" + "runtime/trace" "github.com/google/go-containerregistry/pkg/name" app "github.com/konflux-ci/application-api/api/v1alpha1" @@ -87,6 +88,11 @@ func NewApplicationSnapshotImage(ctx context.Context, component app.SnapshotComp // ValidateImageAccess executes the remote.Head method on the ApplicationSnapshotImage image ref func (a *ApplicationSnapshotImage) ValidateImageAccess(ctx context.Context) error { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:validate-image-access") + defer region.End() + } + resp, err := oci.NewClient(ctx).Head(a.reference) if err != nil { return err @@ -211,6 +217,11 @@ func (a *ApplicationSnapshotImage) ValidateAttestationSignature(ctx context.Cont // successful syntax check of no inputs, must invoke // [ValidateAttestationSignature] to prefill the attestations. func (a ApplicationSnapshotImage) ValidateAttestationSyntax(ctx context.Context) error { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:validate-attestation-syntax") + defer region.End() + } + if len(a.attestations) == 0 { log.Debug("No attestation data found, possibly due to attestation image signature not being validated beforehand") return errors.New("no attestation data") diff --git a/internal/evaluator/conftest_evaluator.go b/internal/evaluator/conftest_evaluator.go index 0c739663d..6b5c26ef8 100644 --- a/internal/evaluator/conftest_evaluator.go +++ b/internal/evaluator/conftest_evaluator.go @@ -24,6 +24,7 @@ import ( "os" "path" "path/filepath" + "runtime/trace" "strings" "time" @@ -41,6 +42,7 @@ import ( "github.com/enterprise-contract/ec-cli/internal/opa/rule" "github.com/enterprise-contract/ec-cli/internal/policy" "github.com/enterprise-contract/ec-cli/internal/policy/source" + "github.com/enterprise-contract/ec-cli/internal/tracing" "github.com/enterprise-contract/ec-cli/internal/utils" ) @@ -210,9 +212,7 @@ type conftestRunner struct { } func (r conftestRunner) Run(ctx context.Context, fileList []string) (result []Outcome, data Data, err error) { - if log.IsLevelEnabled(log.TraceLevel) { - r.Trace = true - } + r.Trace = tracing.FromContext(ctx).Enabled(tracing.Opa) var conftestResult []output.CheckResult conftestResult, err = r.TestRunner.Run(ctx, fileList) @@ -290,6 +290,11 @@ func NewConftestEvaluator(ctx context.Context, policySources []source.PolicySour // set the policy namespace func NewConftestEvaluatorWithNamespace(ctx context.Context, policySources []source.PolicySource, p ConfigProvider, source ecc.Source, namespace []string) (Evaluator, error) { + if trace.IsEnabled() { + r := trace.StartRegion(ctx, "ec:conftest-create-evaluator") + defer r.End() + } + fs := utils.FS(ctx) c := conftestEvaluator{ policySources: policySources, @@ -362,6 +367,11 @@ func (r *policyRules) collect(a *ast.AnnotationsRef) error { func (c conftestEvaluator) Evaluate(ctx context.Context, target EvaluationTarget) ([]Outcome, Data, error) { var results []Outcome + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:conftest-evaluate") + defer region.End() + } + // hold all rule annotations from all policy sources // NOTE: emphasis on _all rules from all sources_; meaning that if two rules // exist with the same code in two separate sources the collected rule diff --git a/internal/fetchers/oci/config/config.go b/internal/fetchers/oci/config/config.go index 4f7c97f0b..e3f8dc234 100644 --- a/internal/fetchers/oci/config/config.go +++ b/internal/fetchers/oci/config/config.go @@ -20,6 +20,7 @@ import ( "context" "encoding/json" "fmt" + "runtime/trace" "strings" "github.com/google/go-containerregistry/pkg/name" @@ -29,6 +30,12 @@ import ( // FetchImageConfig retrieves the config for an image from its OCI registry. func FetchImageConfig(ctx context.Context, ref name.Reference) (json.RawMessage, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:image-fetch-config") + defer region.End() + trace.Logf(ctx, "", "image=%q", ref) + } + image, err := oci.NewClient(ctx).Image(ref) if err != nil { return nil, err @@ -48,6 +55,12 @@ func FetchImageConfig(ctx context.Context, ref name.Reference) (json.RawMessage, // FetchParentImage retrieves the reference to an image's parent image from its OCI registry. func FetchParentImage(ctx context.Context, ref name.Reference) (name.Reference, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:image-fetch-parent-image") + defer region.End() + trace.Logf(ctx, "", "image=%q", ref) + } + image, err := oci.NewClient(ctx).Image(ref) if err != nil { return nil, err diff --git a/internal/fetchers/oci/files/files.go b/internal/fetchers/oci/files/files.go index 71b540f98..9809ad9f4 100644 --- a/internal/fetchers/oci/files/files.go +++ b/internal/fetchers/oci/files/files.go @@ -22,6 +22,7 @@ import ( "encoding/json" "io" "path" + "runtime/trace" "strings" "github.com/google/go-containerregistry/pkg/name" @@ -42,6 +43,12 @@ type Matcher func(*tar.Header) bool var supportedExtensions = []string{".yaml", ".yml", ".json"} func ImageFiles(ctx context.Context, ref name.Reference, extractors []Extractor) (map[string]json.RawMessage, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:image-fetch-image-files") + defer region.End() + trace.Logf(ctx, "", "image=%q", ref) + } + img, err := oci.NewClient(ctx).Image(ref) if err != nil { return nil, err diff --git a/internal/http/tracing.go b/internal/http/tracing.go index fe321341a..1ffd430d8 100644 --- a/internal/http/tracing.go +++ b/internal/http/tracing.go @@ -18,28 +18,36 @@ package http import ( "net/http" - - log "github.com/sirupsen/logrus" + "runtime/trace" ) type tracingRoundTripper struct { base http.RoundTripper - log *log.Logger } func NewTracingRoundTripper(transport http.RoundTripper) http.RoundTripper { - return NewTracingRoundTripperWithLogger(transport, log.StandardLogger()) + return NewTracingRoundTripperWithLogger(transport) } -func NewTracingRoundTripperWithLogger(transport http.RoundTripper, l *log.Logger) http.RoundTripper { - return &tracingRoundTripper{transport, l} +func NewTracingRoundTripperWithLogger(transport http.RoundTripper) http.RoundTripper { + return &tracingRoundTripper{transport} } func (t *tracingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) { - t.log.Tracef("START: %s %s", req.Method, req.URL) + ctx := req.Context() + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "http-request") + defer region.End() + + trace.Logf(ctx, "http", "method=%q", req.Method) + trace.Logf(ctx, "http", "url=%q", req.URL.String()) + } + resp, err := t.base.RoundTrip(req) - t.log.Tracef("DONE: %s %s (%d)", req.Method, req.URL, resp.ContentLength) + if trace.IsEnabled() { + trace.Logf(ctx, "http", "received=%d", resp.ContentLength) + } return resp, err } diff --git a/internal/http/tracing_test.go b/internal/http/tracing_test.go index 5b477df45..a92d49ad3 100644 --- a/internal/http/tracing_test.go +++ b/internal/http/tracing_test.go @@ -18,10 +18,12 @@ package http import ( "net/http" + "net/url" "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" + "github.com/stretchr/testify/require" ) type transport struct { @@ -37,8 +39,16 @@ func TestDelegation(t *testing.T) { delegate := &transport{} tracing := NewTracingRoundTripper(delegate) - req := &http.Request{} - res := &http.Response{} + u, err := url.Parse("http://example.com") + require.NoError(t, err) + + req := &http.Request{ + Method: "GET", + URL: u, + } + res := &http.Response{ + ContentLength: 42, + } delegate.On("RoundTrip", req).Return(res, nil) r, err := tracing.RoundTrip(req) assert.Same(t, res, r) diff --git a/internal/image/process.go b/internal/image/process.go index bbdb85506..c008981df 100644 --- a/internal/image/process.go +++ b/internal/image/process.go @@ -20,6 +20,7 @@ import ( "context" "errors" "fmt" + "runtime/trace" "strings" "github.com/google/go-containerregistry/pkg/authn" @@ -35,6 +36,12 @@ const RemoteHead key = "ec.image.remoteHead" // ParseAndResolve parses the url into an ImageReference object. The digest is // resolved if needed. func ParseAndResolve(ctx context.Context, url string, opts ...name.Option) (*ImageReference, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:image-resolve") + defer region.End() + trace.Logf(ctx, "", "image=%q", url) + } + ref, err := NewImageReference(url, opts...) if err != nil { return nil, err diff --git a/internal/image/validate.go b/internal/image/validate.go index eec747f05..9240afae9 100644 --- a/internal/image/validate.go +++ b/internal/image/validate.go @@ -19,6 +19,7 @@ package image import ( "context" "encoding/json" + "runtime/trace" "sort" "time" @@ -36,6 +37,12 @@ import ( // ValidateImage executes the required method calls to evaluate a given policy // against a given image url. func ValidateImage(ctx context.Context, comp app.SnapshotComponent, snap *app.SnapshotSpec, p policy.Policy, evaluators []evaluator.Evaluator, detailed bool) (*output.Output, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:validate-image") + defer region.End() + trace.Logf(ctx, "", "image=%q", comp.ContainerImage) + } + log.Debugf("Validating image %s", comp.ContainerImage) out := &output.Output{ImageURL: comp.ContainerImage, Detailed: detailed, Policy: p} diff --git a/internal/input/validate.go b/internal/input/validate.go index 005f72d9c..00e8ac04d 100644 --- a/internal/input/validate.go +++ b/internal/input/validate.go @@ -20,6 +20,7 @@ import ( "context" "fmt" "path/filepath" + "runtime/trace" log "github.com/sirupsen/logrus" "github.com/spf13/afero" @@ -34,6 +35,12 @@ import ( var inputFile = input.NewInput func ValidateInput(ctx context.Context, fpath string, policy policy.Policy, detailed bool) (*output.Output, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:validate-input") + defer region.End() + trace.Logf(ctx, "", "file=%q", fpath) + } + log.Debugf("Current input filePath: %q", fpath) inputFiles, err := detectInput(ctx, fpath) if err != nil { diff --git a/internal/policy/source/source.go b/internal/policy/source/source.go index 71f7b7c96..bab1810c9 100644 --- a/internal/policy/source/source.go +++ b/internal/policy/source/source.go @@ -28,6 +28,7 @@ import ( "fmt" "path" "path/filepath" + "runtime/trace" "strings" "sync" "time" @@ -139,6 +140,12 @@ func getPolicyThroughCache(ctx context.Context, s PolicySource, workDir string, // GetPolicies clones the repository for a given PolicyUrl func (p *PolicyUrl) GetPolicy(ctx context.Context, workDir string, showMsg bool) (string, error) { + if trace.IsEnabled() { + region := trace.StartRegion(ctx, "ec:get-policy") + defer region.End() + trace.Logf(ctx, "", "policy=%q", p.Url) + } + dl := func(source string, dest string) (metadata.Metadata, error) { x := ctx.Value(DownloaderFuncKey) if dl, ok := x.(downloaderFunc); ok { diff --git a/internal/tracing/flag.go b/internal/tracing/flag.go new file mode 100644 index 000000000..ab7d57724 --- /dev/null +++ b/internal/tracing/flag.go @@ -0,0 +1,27 @@ +// Copyright The Enterprise Contract Contributors +// +// 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. +// +// SPDX-License-Identifier: Apache-2.0 + +package tracing + +func (t *Trace) Set(s string) error { + *t = ParseTrace(s) + + return nil +} + +func (Trace) Type() string { + return "string" +} diff --git a/internal/tracing/flag_test.go b/internal/tracing/flag_test.go new file mode 100644 index 000000000..7f8d7823a --- /dev/null +++ b/internal/tracing/flag_test.go @@ -0,0 +1,35 @@ +// Copyright The Enterprise Contract Contributors +// +// 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. +// +// SPDX-License-Identifier: Apache-2.0 + +package tracing + +import ( + "fmt" + "testing" +) + +func TestSet(t *testing.T) { + for _, c := range parse_cases { + t.Run(fmt.Sprintf("%s => %d", c.given, c.expected), func(t *testing.T) { + v := None + if err := v.Set(c.given); err != nil { + t.Fatal(err) + } else if v != c.expected { + t.Errorf(`ParseTrace("%s") = %d, expected %d`, c.given, v, c.expected) + } + }) + } +} diff --git a/internal/tracing/type.go b/internal/tracing/type.go new file mode 100644 index 000000000..052a58ce0 --- /dev/null +++ b/internal/tracing/type.go @@ -0,0 +1,129 @@ +// Copyright The Enterprise Contract Contributors +// +// 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. +// +// SPDX-License-Identifier: Apache-2.0 + +package tracing + +import ( + "context" + "strconv" + "strings" +) + +type Trace uint8 + +const ( + None Trace = 0 + Perf Trace = 1 << 0 + CPU Trace = 1 << 1 + Memory Trace = 1 << 2 + Opa Trace = 1 << 3 + Log Trace = 1 << 4 + All Trace = Perf | CPU | Memory | Opa | Log + + contextKey Trace = 0xff +) + +var Default = Log + +// ParseTrace returns a Trace for the given comma separated string value +func ParseTrace(s string) Trace { + // backward compatibility, the flag used to be a boolean on/off, we no longer + // advertise this + if v, err := strconv.ParseBool(s); err == nil { + if v { + return Default + } else { + return None + } + } + + trace := None + for _, t := range strings.Split(s, ",") { + v := strings.ToLower(strings.TrimSpace(t)) + switch v { + case "": + trace |= Default + case "none": + return None + case "perf": + trace |= Perf + case "cpu": + trace |= CPU + case "mem": + trace |= Memory + case "opa": + trace |= Opa + case "log": + trace |= Log + case "all": + return All + } + + } + + return trace +} + +// Enabled returns true if one of the provided tracing categories is enabled +func (t Trace) Enabled(categories ...Trace) bool { + for _, c := range categories { + if t&c == c { + return true + } + } + + return false +} + +// String returns a comma separated list of enabled categories +func (t Trace) String() string { + if t == None { + return "none" + } + + s := "" + if t.Enabled(Perf) { + s += "perf," + } + if t.Enabled(CPU) { + s += "cpu," + } + if t.Enabled(Memory) { + s += "mem," + } + if t.Enabled(Opa) { + s += "opa," + } + if t.Enabled(Log) { + s += "log," + } + + return strings.TrimRight(s, ",") +} + +// WithTrace returns the context with the given Trace +func WithTrace(ctx context.Context, t Trace) context.Context { + return context.WithValue(ctx, contextKey, t) +} + +// FromContext returns the stored Trace in context or Default +func FromContext(ctx context.Context) Trace { + if t := ctx.Value(contextKey); t == nil { + return Default + } else { + return t.(Trace) + } +} diff --git a/internal/tracing/type_test.go b/internal/tracing/type_test.go new file mode 100644 index 000000000..43bf3ea98 --- /dev/null +++ b/internal/tracing/type_test.go @@ -0,0 +1,122 @@ +// Copyright The Enterprise Contract Contributors +// +// 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. +// +// SPDX-License-Identifier: Apache-2.0 + +package tracing + +import ( + "context" + "fmt" + "testing" +) + +var parse_cases = []struct { + given string + expected Trace +}{ + {"0", None}, + {"1", Default}, + {"false", None}, + {"true", Default}, + {"False", None}, + {"True", Default}, + {"F", None}, + {"T", Default}, + {"FALSE", None}, + {"TRUE", Default}, + {"none", None}, + {"None", None}, + {"perf", Perf}, + {"cpu", CPU}, + {"mem", Memory}, + {"opa", Opa}, + {"log", Log}, + {"all", All}, + {"none,opa", None}, + {"all, perf", All}, + {"perf, Opa", Perf | Opa}, + {"", Default}, + {",Opa", Default | Opa}, + {"perf,", Default | Perf}, +} + +func TestParseTrace(t *testing.T) { + for _, c := range parse_cases { + t.Run(fmt.Sprintf("%s => %d", c.given, c.expected), func(t *testing.T) { + if got := ParseTrace(c.given); got != c.expected { + t.Errorf(`ParseTrace("%s") = %d, expected %d`, c.given, got, c.expected) + } + }) + } +} + +func TestString(t *testing.T) { + cases := []struct { + value Trace + expected string + }{ + {None, "none"}, + {Default, "log"}, + {Perf, "perf"}, + {CPU, "cpu"}, + {Memory, "mem"}, + {Opa, "opa"}, + {Log, "log"}, + {All, "perf,cpu,mem,opa,log"}, + {Perf | Opa, "perf,opa"}, + {Log | Opa, "opa,log"}, + {Perf | CPU | Memory | Opa | Log, "perf,cpu,mem,opa,log"}, + } + + for _, c := range cases { + t.Run(fmt.Sprintf("%d => %s", c.value, c.expected), func(t *testing.T) { + if got := c.value.String(); got != c.expected { + t.Errorf(`string("%d") = %s, expected %s`, c.value, got, c.expected) + } + }) + } +} + +func TestEnabled(t *testing.T) { + cases := []struct { + value Trace + categories []Trace + expected bool + }{ + {None, []Trace{None}, true}, + {All, []Trace{Opa, Perf, CPU}, true}, + {Opa | Memory, []Trace{CPU, Opa, Perf}, true}, + {Opa | Perf | CPU, []Trace{Memory, Log}, false}, + {Opa | Perf | CPU, []Trace{Opa | Perf, Log}, true}, + } + + for _, c := range cases { + t.Run(fmt.Sprintf("%v enabled in %d => %v", c.categories, c.value, c.expected), func(t *testing.T) { + if got := c.value.Enabled(c.categories...); got != c.expected { + t.Errorf(`%d.Enabled(%v) = %v, expected %v`, c.value, c.categories, got, c.expected) + } + }) + } +} + +func TestContextStorage(t *testing.T) { + if FromContext(context.TODO()) != Default { + t.Error("did not recive the default value from context when unset") + } + + if FromContext(WithTrace(context.TODO(), Opa)) != Opa { + t.Error("did not restore the value from context") + } +} diff --git a/internal/utils/oci/client.go b/internal/utils/oci/client.go index 1872b8d33..8e803c1e8 100644 --- a/internal/utils/oci/client.go +++ b/internal/utils/oci/client.go @@ -21,6 +21,7 @@ import ( "fmt" "os" "path" + "runtime/trace" "strconv" "sync" @@ -125,21 +126,45 @@ type defaultClient struct { } func (c *defaultClient) VerifyImageSignatures(ref name.Reference, opts *cosign.CheckOpts) ([]oci.Signature, bool, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:validate-image-signatures") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + opts.RegistryClientOpts = append(opts.RegistryClientOpts, ociremote.WithRemoteOptions(c.opts...)) return cosign.VerifyImageSignatures(c.ctx, ref, opts) } func (c *defaultClient) VerifyImageAttestations(ref name.Reference, opts *cosign.CheckOpts) ([]oci.Signature, bool, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:validate-image-attestations") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + opts.RegistryClientOpts = append(opts.RegistryClientOpts, ociremote.WithRemoteOptions(c.opts...)) return cosign.VerifyImageAttestations(c.ctx, ref, opts) } func (c *defaultClient) Head(ref name.Reference) (*v1.Descriptor, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-head") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + return remote.Head(ref, c.opts...) } // gather all attestation uris and digests associated with an image func (c *defaultClient) AttestationUri(img string) (string, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-attestation-uri") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", img) + } + imgRef, err := name.ParseReference(img) if err != nil { return "", err @@ -159,6 +184,12 @@ func (c *defaultClient) AttestationUri(img string) (string, error) { } func (c *defaultClient) ResolveDigest(ref name.Reference) (string, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-resolve-digest") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + digest, err := ociremote.ResolveDigest(ref, ociremote.WithRemoteOptions(c.opts...)) if err != nil { return "", err @@ -171,6 +202,12 @@ func (c *defaultClient) ResolveDigest(ref name.Reference) (string, error) { } func (c *defaultClient) Image(ref name.Reference) (v1.Image, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-fetch-image") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + img, err := remote.Image(ref, c.opts...) if err != nil { return nil, err @@ -184,6 +221,12 @@ func (c *defaultClient) Image(ref name.Reference) (v1.Image, error) { } func (c *defaultClient) Layer(ref name.Digest) (v1.Layer, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-fetch-layer") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + // TODO: Caching a layer directly is difficult and may not be possible, see: // https://github.com/google/go-containerregistry/issues/1821 layer, err := remote.Layer(ref, c.opts...) @@ -194,6 +237,12 @@ func (c *defaultClient) Layer(ref name.Digest) (v1.Layer, error) { } func (c *defaultClient) Index(ref name.Reference) (v1.ImageIndex, error) { + if trace.IsEnabled() { + region := trace.StartRegion(c.ctx, "ec:oci-fetch-index") + defer region.End() + trace.Logf(c.ctx, "", "image=%q", ref) + } + index, err := remote.Index(ref, c.opts...) if err != nil { return nil, fmt.Errorf("fetching index: %w", err)