Merge pull request #5390 from snyk/chore/CLI-409_improve_logging

chore(logging): Improve and fix issues in trace level logging

cliv2/cmd/cliv2/debug.go

@@ -12,50 +12,33 @@ import (
 
 	"github.com/snyk/go-application-framework/pkg/configuration"
 	"github.com/snyk/go-application-framework/pkg/logging"
-)
 
-func getDebugLevel(config configuration.Configuration, logger *zerolog.Logger) zerolog.Level {
-	loglevel := zerolog.DebugLevel
-	if loglevelString := config.GetString("snyk_log_level"); loglevelString != "" {
-		var err error
-		loglevel, err = zerolog.ParseLevel(loglevelString)
-		if err == nil {
-			logger.Log().Msgf("Setting log level to %s", loglevelString)
-		} else {
-			logger.Log().Msgf("%v", err)
-			loglevel = zerolog.DebugLevel
-		}
-	}
-	return loglevel
-}
+	debug_tools "github.com/snyk/cli/cliv2/internal/debug"
+)
 
 func initDebugLogger(config configuration.Configuration) *zerolog.Logger {
-	debug := config.GetBool(configuration.DEBUG)
-	if !debug {
-		return &noopLogger
-	} else {
-		var consoleWriter = zerolog.ConsoleWriter{
-			Out:        os.Stderr,
-			TimeFormat: time.RFC3339,
-			NoColor:    true,
-			PartsOrder: []string{
-				zerolog.TimestampFieldName,
-				"ext",
-				"separator",
-				zerolog.CallerFieldName,
-				zerolog.MessageFieldName,
-			},
-			FieldsExclude: []string{"ext", "separator"},
-			FormatTimestamp: func(i interface{}) string {
-				t, _ := time.Parse(time.RFC3339, i.(string))
-				return strings.ToUpper(t.UTC().Format(time.RFC3339))
-			},
-		}
-
-		scrubLogger := logging.NewScrubbingWriter(zerolog.MultiLevelWriter(consoleWriter), logging.GetScrubDictFromConfig(config))
-		localLogger := zerolog.New(scrubLogger).With().Str("ext", "main").Str("separator", "-").Timestamp().Logger()
-		loglevel := getDebugLevel(config, &localLogger)
-		debugLogger := localLogger.Level(loglevel)
-		return &debugLogger
+	var consoleWriter = zerolog.ConsoleWriter{
+		Out:        os.Stderr,
+		TimeFormat: time.RFC3339,
+		NoColor:    true,
+		PartsOrder: []string{
+			zerolog.TimestampFieldName,
+			"ext",
+			"separator",
+			zerolog.CallerFieldName,
+			zerolog.MessageFieldName,
+		},
+		FieldsExclude: []string{"ext", "separator"},
+		FormatTimestamp: func(i interface{}) string {
+			t, _ := time.Parse(time.RFC3339, i.(string))
+			return strings.ToUpper(t.UTC().Format(time.RFC3339))
+		},
 	}
+
+	scrubLogger := logging.NewScrubbingWriter(zerolog.MultiLevelWriter(consoleWriter), logging.GetScrubDictFromConfig(config))
+	localLogger := zerolog.New(scrubLogger).With().Str("ext", "main").Str("separator", "-").Timestamp().Logger()
+	loglevel := debug_tools.GetDebugLevel(config)
+	debugLogger := localLogger.Level(loglevel)
+	debugLogger.Log().Msgf("Using log level: %s", loglevel)
+	return &debugLogger
 }

cliv2/cmd/cliv2/main.go

@@ -60,6 +60,7 @@ var interactionId = uuid.NewString()
 const (
 	unknownCommandMessage  string = "unknown command"
 	disable_analytics_flag string = "DISABLE_ANALYTICS"
+	debug_level_flag       string = "log-level"
 )
 
 type JsonErrorStruct struct {
@@ -90,6 +91,7 @@ func initApplicationConfiguration(config configuration.Configuration) {
 	config.AddAlternativeKeys(configuration.ANALYTICS_DISABLED, []string{strings.ToLower(constants.SNYK_ANALYTICS_DISABLED_ENV), "snyk_cfg_disable_analytics", "disable-analytics", "disable_analytics"})
 	config.AddAlternativeKeys(configuration.ORGANIZATION, []string{"snyk_cfg_org"})
 	config.AddAlternativeKeys(configuration.PREVIEW_FEATURES_ENABLED, []string{"snyk_preview"})
+	config.AddAlternativeKeys(configuration.LOG_LEVEL, []string{debug_level_flag})
 
 	// if the CONFIG_KEY_OAUTH_TOKEN is specified as env var, we don't apply any additional logic
 	_, ok := os.LookupEnv(auth.CONFIG_KEY_OAUTH_TOKEN)
@@ -311,6 +313,7 @@ func getGlobalFLags() *pflag.FlagSet {
 	globalFLags := workflow.FlagsetFromConfigurationOptions(globalConfigurationOptions)
 	globalFLags.Bool(basic_workflows.PROXY_NOAUTH, false, "")
 	globalFLags.Bool(disable_analytics_flag, false, "")
+	globalFLags.String(debug_level_flag, "debug", "")
 	return globalFLags
 }
 

cliv2/go.mod

@@ -15,7 +15,7 @@ require (
 	github.com/snyk/cli-extension-sbom v0.0.0-20240722082449-69a631da39ad
 	github.com/snyk/container-cli v0.0.0-20240322120441-6d9b9482f9b1
 	github.com/snyk/error-catalog-golang-public v0.0.0-20240724122202-c7d3fb545c88
-	github.com/snyk/go-application-framework v0.0.0-20240725135406-ef950283001b
+	github.com/snyk/go-application-framework v0.0.0-20240805133359-9b7c985cfc80
 	github.com/snyk/go-httpauth v0.0.0-20240307114523-1f5ea3f55c65
 	github.com/snyk/snyk-iac-capture v0.6.5
 	github.com/snyk/snyk-ls v0.0.0-20240724110216-fff14d6d09e0

cliv2/go.sum

@@ -744,8 +744,8 @@ github.com/snyk/container-cli v0.0.0-20240322120441-6d9b9482f9b1 h1:9RKY9NdX5DrJ
 github.com/snyk/container-cli v0.0.0-20240322120441-6d9b9482f9b1/go.mod h1:38w+dcAQp9eG3P5t2eNS9eG0reut10AeJjLv5lJ5lpM=
 github.com/snyk/error-catalog-golang-public v0.0.0-20240724122202-c7d3fb545c88 h1:ZiFV5IDPI2p1wx1D3B2iSC/8nxTGvlKuyUekZlm1ptU=
 github.com/snyk/error-catalog-golang-public v0.0.0-20240724122202-c7d3fb545c88/go.mod h1:Ytttq7Pw4vOCu9NtRQaOeDU2dhBYUyNBe6kX4+nIIQ4=
-github.com/snyk/go-application-framework v0.0.0-20240725135406-ef950283001b h1:LOuM03NjJlUgz4pjV6OpvEPR0/94glwSfLkxF11wjF0=
-github.com/snyk/go-application-framework v0.0.0-20240725135406-ef950283001b/go.mod h1:3DhXDHbBbGWRRZESbYVZyunyIDaet9SOtuOZCK7AC3g=
+github.com/snyk/go-application-framework v0.0.0-20240805133359-9b7c985cfc80 h1:WbOtJt49aR3uN2RU9mBTfjW8wGbqZhW8AmX6H3QTgAc=
+github.com/snyk/go-application-framework v0.0.0-20240805133359-9b7c985cfc80/go.mod h1:3DhXDHbBbGWRRZESbYVZyunyIDaet9SOtuOZCK7AC3g=
 github.com/snyk/go-httpauth v0.0.0-20240307114523-1f5ea3f55c65 h1:CEQuYv0Go6MEyRCD3YjLYM2u3Oxkx8GpCpFBd4rUTUk=
 github.com/snyk/go-httpauth v0.0.0-20240307114523-1f5ea3f55c65/go.mod h1:88KbbvGYlmLgee4OcQ19yr0bNpXpOr2kciOthaSzCAg=
 github.com/snyk/policy-engine v0.30.11 h1:wUy5LMar2vccMbNM62MSBRdjAQAhAbIm7aNXXO+g2tk=

cliv2/internal/cliv2/cliv2.go

@@ -22,13 +22,15 @@ import (
 	"time"
 
 	"github.com/gofrs/flock"
+	"github.com/rs/zerolog"
 	"github.com/snyk/go-application-framework/pkg/configuration"
 	"github.com/snyk/go-application-framework/pkg/instrumentation"
 	"github.com/snyk/go-application-framework/pkg/utils"
 
 	cli_errors "github.com/snyk/cli/cliv2/internal/errors"
 
 	"github.com/snyk/cli/cliv2/internal/constants"
+	debug_utils "github.com/snyk/cli/cliv2/internal/debug"
 	"github.com/snyk/cli/cliv2/internal/embedded"
 	"github.com/snyk/cli/cliv2/internal/embedded/cliv1"
 	"github.com/snyk/cli/cliv2/internal/proxy"
@@ -391,22 +393,8 @@ func PrepareV1EnvironmentVariables(
 		inputAsMap[constants.SNYK_HTTPS_PROXY_ENV] = proxyAddress
 		inputAsMap[constants.SNYK_HTTP_PROXY_ENV] = proxyAddress
 		inputAsMap[constants.SNYK_CA_CERTIFICATE_LOCATION_ENV] = caCertificateLocation
-		inputAsMap[constants.SNYK_INTERNAL_ORGID_ENV] = config.GetString(configuration.ORGANIZATION)
 
-		if config.GetBool(configuration.PREVIEW_FEATURES_ENABLED) {
-			inputAsMap[constants.SNYK_INTERNAL_PREVIEW_FEATURES_ENABLED] = "1"
-		}
-
-		if config.IsSet(configuration.API_URL) {
-			inputAsMap[constants.SNYK_ENDPOINT_ENV] = config.GetString(configuration.API_URL)
-		}
-
-		_, orgEnVarExists := inputAsMap[constants.SNYK_ORG_ENV]
-		if !utils.ContainsPrefix(args, "--org=") &&
-			!orgEnVarExists &&
-			config.IsSet(configuration.ORGANIZATION) {
-			inputAsMap[constants.SNYK_ORG_ENV] = config.GetString(configuration.ORGANIZATION)
-		}
+		fillEnvironmentFromConfig(inputAsMap, config, args)
 
 		// merge user defined (external) and internal no_proxy configuration
 		if len(inputAsMap[constants.SNYK_HTTP_NO_PROXY_ENV_SYSTEM]) > 0 {
@@ -424,6 +412,30 @@ func PrepareV1EnvironmentVariables(
 	return result, err
 }
 
+// Fill environment variables for the legacy CLI from the given configuration.
+func fillEnvironmentFromConfig(inputAsMap map[string]string, config configuration.Configuration, args []string) {
+	inputAsMap[constants.SNYK_INTERNAL_ORGID_ENV] = config.GetString(configuration.ORGANIZATION)
+
+	if config.GetBool(configuration.PREVIEW_FEATURES_ENABLED) {
+		inputAsMap[constants.SNYK_INTERNAL_PREVIEW_FEATURES_ENABLED] = "1"
+	}
+
+	if config.IsSet(configuration.API_URL) {
+		inputAsMap[constants.SNYK_ENDPOINT_ENV] = config.GetString(configuration.API_URL)
+	}
+
+	if debug_utils.GetDebugLevel(config) == zerolog.TraceLevel {
+		inputAsMap["DEBUG"] = "*"
+	}
+
+	_, orgEnVarExists := inputAsMap[constants.SNYK_ORG_ENV]
+	if !utils.ContainsPrefix(args, "--org=") &&
+		!orgEnVarExists &&
+		config.IsSet(configuration.ORGANIZATION) {
+		inputAsMap[constants.SNYK_ORG_ENV] = config.GetString(configuration.ORGANIZATION)
+	}
+}
+
 func (c *CLI) PrepareV1Command(
 	ctx context.Context,
 	cmd string,

cliv2/internal/debug/debug.go

@@ -0,0 +1,24 @@
+package debug
+
+import (
+	"github.com/rs/zerolog"
+	"github.com/snyk/go-application-framework/pkg/configuration"
+)
+
+func GetDebugLevel(config configuration.Configuration) zerolog.Level {
+	loglevel := zerolog.Disabled
+
+	if config.GetBool(configuration.DEBUG) {
+		loglevel = zerolog.DebugLevel
+
+		if loglevelString := config.GetString(configuration.LOG_LEVEL); loglevelString != "" {
+			var err error
+			loglevel, err = zerolog.ParseLevel(loglevelString)
+			if err != nil {
+				loglevel = zerolog.DebugLevel
+			}
+		}
+	}
+
+	return loglevel
+}

cliv2/internal/proxy/proxy.go

@@ -199,6 +199,8 @@ func (p *WrapperProxy) Start() error {
 	proxy.OnRequest().DoFunc(p.replaceVersionHandler)
 	proxy.OnRequest().HandleConnect(p)
 	proxy.OnResponse().DoFunc(func(resp *http.Response, ctx *goproxy.ProxyCtx) *http.Response {
+		networking.LogResponse(resp, p.DebugLogger)
+
 		if authFailed := resp.Request.Header.Get(headerSnykAuthFailed); authFailed != "" {
 			resp.Header.Set(headerSnykAuthFailed, authFailed)
 		}