feat: Redact token information from debug logs [HEAD-1184] (#4983)

* test: add failing token redact test

* feat: adopt log scrubbing

* fix: debuglog test

* use common func to get scrubdict
* use scrub logger in Extensible CLI

* chore: run formatter

* fix: acceptance test through gaf upgrade

* refactor: cleaning up logger initialization

* fix: toolchain

* refactor: move debug logic in separate file to reduce main

* fix: init order and redact tests

* chore: run formatter

* chore: use final gaf commit hash

* chore: undo unneccessary change

* fix: add missing fips_enable import

---------

Co-authored-by: Luke Watts <[email protected]>

Author: PeterSchafer

cliv2/cmd/cliv2/debug.go

@@ -0,0 +1,61 @@
+package main
+
+// !!! This import needs to be the first import, please do not change this !!!
+import _ "github.com/snyk/go-application-framework/pkg/networking/fips_enable"
+
+import (
+	"fmt"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/rs/zerolog"
+	"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
+}
+
+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(fmt.Sprintf("%s", 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
+	}
+}

cliv2/cmd/cliv2/logheader.go

@@ -36,7 +36,7 @@ func logHeaderAuthorizationInfo(
 
 	err := networkAccess.AddHeaders(apiRequest)
 	if err != nil {
-		debugLogger.Print(err)
+		globalLogger.Print(err)
 	}
 
 	authHeader := apiRequest.Header.Get("Authorization")
@@ -97,7 +97,7 @@ func writeLogHeader(config configuration.Configuration, networkAccess networking
 	}
 
 	tablePrint := func(name string, value string) {
-		debugLogger.Printf("%-22s %s", name+":", value)
+		globalLogger.Printf("%-22s %s", name+":", value)
 	}
 
 	fipsEnabled := getFipsStatus(config)

cliv2/cmd/cliv2/main.go

@@ -44,23 +44,9 @@ var internalOS string
 var engine workflow.Engine
 var globalConfiguration configuration.Configuration
 var helpProvided bool
-var debugLogger = zerolog.New(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(fmt.Sprintf("%s", t.UTC().Format(time.RFC3339)))
-	},
-}).With().Str("ext", "main").Str("separator", "-").Timestamp().Logger()
+
+var noopLogger zerolog.Logger = zerolog.New(io.Discard)
+var globalLogger *zerolog.Logger = &noopLogger
 
 const (
 	unknownCommandMessage  string = "unknown command"
@@ -81,32 +67,6 @@ const (
 	handleErrorUnhandled           HandleError = iota
 )
 
-func getDebugLevel(config configuration.Configuration) zerolog.Level {
-	loglevel := zerolog.DebugLevel
-	if loglevelString := config.GetString("snyk_log_level"); loglevelString != "" {
-		var err error
-		loglevel, err = zerolog.ParseLevel(loglevelString)
-		if err == nil {
-			debugLogger.Log().Msgf("Setting log level to %s", loglevelString)
-		} else {
-			debugLogger.Log().Msgf("%v", err)
-			loglevel = zerolog.DebugLevel
-		}
-	}
-	return loglevel
-}
-
-func initDebugLogger(config configuration.Configuration) *zerolog.Logger {
-	debug := config.GetBool(configuration.DEBUG)
-	if !debug {
-		debugLogger = debugLogger.Output(io.Discard)
-	} else {
-		loglevel := getDebugLevel(config)
-		debugLogger = debugLogger.Level(loglevel)
-	}
-	return &debugLogger
-}
-
 func main() {
 	errorCode := MainWithErrorCode()
 	os.Exit(errorCode)
@@ -132,7 +92,7 @@ func initApplicationConfiguration(config configuration.Configuration) {
 				formattedKey := strings.ToUpper(key)
 				_, ok := os.LookupEnv(formattedKey)
 				if ok {
-					debugLogger.Printf("Found environment variable %s, disabling OAuth flow", formattedKey)
+					globalLogger.Printf("Found environment variable %s, disabling OAuth flow", formattedKey)
 					config.Set(configuration.FF_OAUTH_AUTH_FLOW_ENABLED, false)
 					break
 				}
@@ -187,21 +147,21 @@ func runMainWorkflow(config configuration.Configuration, cmd *cobra.Command, arg
 
 	err := config.AddFlagSet(cmd.Flags())
 	if err != nil {
-		debugLogger.Print("Failed to add flags", err)
+		globalLogger.Print("Failed to add flags", err)
 		return err
 	}
 
 	updateConfigFromParameter(config, args, rawArgs)
 
 	name := getFullCommandString(cmd)
-	debugLogger.Print("Running ", name)
+	globalLogger.Print("Running ", name)
 	engine.GetAnalytics().SetCommand(name)
 
 	data, err := engine.Invoke(workflow.NewWorkflowIdentifier(name))
 	if err == nil {
 		_, err = engine.InvokeWithInput(localworkflows.WORKFLOWID_OUTPUT_WORKFLOW, data)
 	} else {
-		debugLogger.Print("Failed to execute the command!", err)
+		globalLogger.Print("Failed to execute the command!", err)
 	}
 
 	return err
@@ -391,14 +351,16 @@ func MainWithErrorCode() int {
 	globalConfiguration = configuration.New()
 	err = globalConfiguration.AddFlagSet(rootCommand.LocalFlags())
 	if err != nil {
-		debugLogger.Print("Failed to add flags to root command", err)
+		fmt.Fprintln(os.Stderr, "Failed to add flags to root command", err)
 	}
 
+	// ensure to init configuration before using it
+	initApplicationConfiguration(globalConfiguration)
+
 	debugEnabled := globalConfiguration.GetBool(configuration.DEBUG)
-	debugLogger := initDebugLogger(globalConfiguration)
+	globalLogger = initDebugLogger(globalConfiguration)
 
-	initApplicationConfiguration(globalConfiguration)
-	engine = app.CreateAppEngineWithOptions(app.WithZeroLogger(debugLogger), app.WithConfiguration(globalConfiguration), app.WithRuntimeInfo(rInfo))
+	engine = app.CreateAppEngineWithOptions(app.WithZeroLogger(globalLogger), app.WithConfiguration(globalConfiguration), app.WithRuntimeInfo(rInfo))
 
 	if noProxyAuth := globalConfiguration.GetBool(basic_workflows.PROXY_NOAUTH); noProxyAuth {
 		globalConfiguration.Set(configuration.PROXY_AUTHENTICATION_MECHANISM, httpauth.StringFromAuthenticationMechanism(httpauth.NoAuth))
@@ -416,7 +378,7 @@ func MainWithErrorCode() int {
 	// init engine
 	err = engine.Init()
 	if err != nil {
-		debugLogger.Print("Failed to init Workflow Engine!", err)
+		globalLogger.Print("Failed to init Workflow Engine!", err)
 		return constants.SNYK_EXIT_CODE_ERROR
 	}
 
@@ -449,7 +411,7 @@ func MainWithErrorCode() int {
 	cliAnalytics.SetCmdArguments(os.Args[1:])
 	cliAnalytics.SetOperatingSystem(internalOS)
 	if globalConfiguration.GetBool(configuration.ANALYTICS_DISABLED) == false {
-		defer sendAnalytics(cliAnalytics, debugLogger)
+		defer sendAnalytics(cliAnalytics, globalLogger)
 	}
 
 	setTimeout(globalConfiguration, func() {
@@ -462,7 +424,7 @@ func MainWithErrorCode() int {
 	// fallback to the legacy cli or show help
 	handleErrorResult := handleError(err)
 	if handleErrorResult == handleErrorFallbackToLegacyCLI {
-		debugLogger.Printf("Using Legacy CLI to serve the command. (reason: %v)", err)
+		globalLogger.Printf("Using Legacy CLI to serve the command. (reason: %v)", err)
 		err = defaultCmd(os.Args[1:])
 	} else if handleErrorResult == handleErrorShowHelp {
 		err = help(nil, []string{})
@@ -475,7 +437,7 @@ func MainWithErrorCode() int {
 	displayError(err)
 
 	exitCode := cliv2.DeriveExitCode(err)
-	debugLogger.Printf("Exiting with %d", exitCode)
+	globalLogger.Printf("Exiting with %d", exitCode)
 
 	return exitCode
 }
@@ -485,7 +447,7 @@ func setTimeout(config configuration.Configuration, onTimeout func()) {
 	if timeout == 0 {
 		return
 	}
-	debugLogger.Printf("Command timeout set for %d seconds", timeout)
+	globalLogger.Printf("Command timeout set for %d seconds", timeout)
 	go func() {
 		const gracePeriodForSubProcesses = 3
 		<-time.After(time.Duration(timeout+gracePeriodForSubProcesses) * time.Second)

cliv2/go.mod

@@ -13,7 +13,7 @@ require (
 	github.com/snyk/cli-extension-iac-rules v0.0.0-20230601153200-c572cfce46ce
 	github.com/snyk/cli-extension-sbom v0.0.0-20231123083311-52b1cecc1a7a
 	github.com/snyk/container-cli v0.0.0-20230920093251-fe865879a91f
-	github.com/snyk/go-application-framework v0.0.0-20231222162659-c767e4a7440b
+	github.com/snyk/go-application-framework v0.0.0-20240105122614-54e2b7c15259
 	github.com/snyk/go-httpauth v0.0.0-20231117135515-eb445fea7530
 	github.com/snyk/snyk-iac-capture v0.6.5
 	github.com/snyk/snyk-ls v0.0.0-20231124091213-5a223c21e0aa
@@ -173,3 +173,5 @@ require (
 
 // version 2491eb6c1c75 contains a valid license
 replace github.com/mattn/go-localereader v0.0.1 => github.com/mattn/go-localereader v0.0.2-0.20220822084749-2491eb6c1c75
+
+//replace github.com/snyk/go-application-framework => ../../go-application-framework

cliv2/go.sum

@@ -665,8 +665,8 @@ github.com/snyk/cli-extension-sbom v0.0.0-20231123083311-52b1cecc1a7a h1:oRrk9bv
 github.com/snyk/cli-extension-sbom v0.0.0-20231123083311-52b1cecc1a7a/go.mod h1:IwRGWjRuNkY08O7NJb7u3JuQkroEB8Qi1MlASpZVu1Q=
 github.com/snyk/container-cli v0.0.0-20230920093251-fe865879a91f h1:ghajT5PEiLP8XNFIdc7Yn4Th74RH/9Q++dDOp6Cb9eo=
 github.com/snyk/container-cli v0.0.0-20230920093251-fe865879a91f/go.mod h1:38w+dcAQp9eG3P5t2eNS9eG0reut10AeJjLv5lJ5lpM=
-github.com/snyk/go-application-framework v0.0.0-20231222162659-c767e4a7440b h1:NNiXGaKELaFmejlw5BOWf8dVThl8iisU9Yhx+FSUrL4=
-github.com/snyk/go-application-framework v0.0.0-20231222162659-c767e4a7440b/go.mod h1:Yz/qxFyfhf0xbA+z8Vzr5IM9IDG+BS+2PiGaP1yAsEw=
+github.com/snyk/go-application-framework v0.0.0-20240105122614-54e2b7c15259 h1:u6CV0KCHuqPINEs83CbVCjsxG5wMxa42T5HtMvKgm+o=
+github.com/snyk/go-application-framework v0.0.0-20240105122614-54e2b7c15259/go.mod h1:Yz/qxFyfhf0xbA+z8Vzr5IM9IDG+BS+2PiGaP1yAsEw=
 github.com/snyk/go-httpauth v0.0.0-20231117135515-eb445fea7530 h1:s9PHNkL6ueYRiAKNfd8OVxlUOqU3qY0VDbgCD1f6WQY=
 github.com/snyk/go-httpauth v0.0.0-20231117135515-eb445fea7530/go.mod h1:88KbbvGYlmLgee4OcQ19yr0bNpXpOr2kciOthaSzCAg=
 github.com/snyk/policy-engine v0.22.0 h1:od9pduGrXyfWO791X+8M1qmnvWUxaIXh0gBzGKqeseA=

cliv2/pkg/basic_workflows/legacycli.go

@@ -9,6 +9,7 @@ import (
 	"github.com/pkg/errors"
 	"github.com/snyk/go-application-framework/pkg/auth"
 	"github.com/snyk/go-application-framework/pkg/configuration"
+	"github.com/snyk/go-application-framework/pkg/logging"
 	pkg_utils "github.com/snyk/go-application-framework/pkg/utils"
 	"github.com/snyk/go-application-framework/pkg/workflow"
 	"github.com/snyk/go-httpauth/pkg/httpauth"
@@ -124,6 +125,10 @@ func legacycliWorkflow(
 		outWriter = bufio.NewWriter(&outBuffer)
 		errWriter = bufio.NewWriter(&errBuffer)
 		cli.SetIoStreams(in, outWriter, errWriter)
+	} else {
+		scrubDict := logging.GetScrubDictFromConfig(config)
+		scrubbedStderr := logging.NewScrubbingIoWriter(os.Stderr, scrubDict)
+		cli.SetIoStreams(os.Stdin, os.Stdout, scrubbedStderr)
 	}
 
 	// init proxy object

test/jest/acceptance/debuglog.spec.ts

@@ -0,0 +1,44 @@
+import { runSnykCLI } from '../util/runSnykCLI';
+import { createProjectFromWorkspace } from '../util/createProject';
+
+jest.setTimeout(1000 * 60);
+
+describe('debug log', () => {
+  it('redacts token from env var', async () => {
+    const project = await createProjectFromWorkspace('cocoapods-app');
+    const token = 'mytoken';
+
+    const { stderr } = await runSnykCLI('test -d', {
+      cwd: project.path(),
+      env: {
+        ...process.env,
+        SNYK_DISABLE_ANALYTICS: '1',
+        DEBUG: '*',
+        SNYK_LOG_LEVEL: 'trace',
+        SNYK_TOKEN: token,
+      },
+    });
+
+    expect(stderr).not.toContain(token);
+  });
+
+  it('redacts token from config file', async () => {
+    const project = await createProjectFromWorkspace('cocoapods-app');
+
+    const config = await runSnykCLI('config get api');
+    const expectedToken = config.stdout.trim();
+
+    const { stderr } = await runSnykCLI('test -d', {
+      cwd: project.path(),
+      env: {
+        ...process.env,
+        SNYK_DISABLE_ANALYTICS: '1',
+        DEBUG: '*',
+        SNYK_LOG_LEVEL: 'trace',
+      },
+    });
+
+    expect(expectedToken).not.toBeFalsy();
+    expect(stderr).not.toContain(expectedToken);
+  });
+});