Mask sensitive values logged through spans (#3290)

feat: Mask sensitive values logged through spans

closes #3216
closes #2256

Signed-off-by: Kim Christensen <kimworking@gmail.com>

pkg/portercontext/context.go

@@ -21,6 +21,7 @@ import (
 	"github.com/spf13/afero"
 	"go.opentelemetry.io/otel/attribute"
 	"go.uber.org/zap"
+	"go.uber.org/zap/buffer"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -79,6 +80,8 @@ type Context struct {
 
 	// InternalPluginKey is the current plugin that Porter is running as, e.g. storage.porter.mongodb
 	InternalPluginKey string
+
+	censoredWriter *CensoredWriter
 }
 
 // New creates a new context in the specified directory.
@@ -95,13 +98,14 @@ func New() *Context {
 	}
 
 	c := &Context{
-		environ:       getEnviron(),
-		FileSystem:    aferox.NewAferox(pwd, afero.NewOsFs()),
-		In:            os.Stdin,
-		Out:           NewCensoredWriter(os.Stdout),
-		Err:           NewCensoredWriter(os.Stderr),
-		correlationId: correlationId,
-		timestampLogs: true,
+		environ:        getEnviron(),
+		FileSystem:     aferox.NewAferox(pwd, afero.NewOsFs()),
+		In:             os.Stdin,
+		Out:            NewCensoredWriter(os.Stdout),
+		Err:            NewCensoredWriter(os.Stderr),
+		correlationId:  correlationId,
+		timestampLogs:  true,
+		censoredWriter: NewCensoredWriter(os.Stdout),
 	}
 
 	// Make the correlation id available for the plugins to use
@@ -132,6 +136,7 @@ func (c *Context) makeLogEncoding() zapcore.EncoderConfig {
 			encoder.AppendString("")
 		}
 	}
+
 	return enc
 }
 
@@ -234,7 +239,7 @@ func (c *Context) makeConsoleLogger() zapcore.Core {
 		encoding.TimeKey = ""
 		encoding.LevelKey = ""
 	}
-	consoleEncoder := zapcore.NewConsoleEncoder(encoding)
+	censoredEncoder := &CensoredEncoder{Encoder: zapcore.NewConsoleEncoder(encoding), censoredWriter: c.censoredWriter}
 
 	isInformational := func(lvl zapcore.Level) bool {
 		return lvl < zapcore.ErrorLevel && lvl >= c.logCfg.Verbosity
@@ -245,10 +250,9 @@ func (c *Context) makeConsoleLogger() zapcore.Core {
 	})
 
 	return zapcore.NewTee(
-		zapcore.NewCore(consoleEncoder, zapcore.AddSync(stdout), stdoutEnabler),
-		zapcore.NewCore(consoleEncoder, zapcore.AddSync(stderr), stderrEnabler),
+		zapcore.NewCore(censoredEncoder, zapcore.AddSync(stdout), stdoutEnabler),
+		zapcore.NewCore(censoredEncoder, zapcore.AddSync(stderr), stderrEnabler),
 	)
-	// return zapcore.NewCore(consoleEncoder, zapcore.AddSync(stdout), c.logCfg.Verbosity)
 }
 
 func (c *Context) configureFileLog(dir string) (zapcore.Core, error) {
@@ -268,7 +272,8 @@ func (c *Context) configureFileLog(dir string) (zapcore.Core, error) {
 
 	// Split logs to the console and file
 	fileEncoder := zapcore.NewJSONEncoder(c.makeLogEncoding())
-	return zapcore.NewCore(fileEncoder, zapcore.AddSync(c.logFile), c.logCfg.LogLevel), nil
+	censoredEncoder := &CensoredEncoder{Encoder: fileEncoder, censoredWriter: c.censoredWriter}
+	return zapcore.NewCore(censoredEncoder, zapcore.AddSync(c.logFile), c.logCfg.LogLevel), nil
 }
 
 func (c *Context) buildLogFileName() string {
@@ -451,6 +456,16 @@ func (cw *CensoredWriter) Write(b []byte) (int, error) {
 	return len(b), err
 }
 
+func (cw *CensoredWriter) Censor(b []byte) []byte {
+	for _, val := range cw.sensitiveValues {
+		if strings.TrimSpace(val) != "" {
+			b = bytes.Replace(b, []byte(val), []byte("*******"), -1)
+		}
+	}
+
+	return b
+}
+
 func (c *Context) CopyDirectory(srcDir, destDir string, includeBaseDir bool) error {
 	var stripPrefix string
 	if includeBaseDir {
@@ -527,9 +542,30 @@ func (c *Context) SetSensitiveValues(vals []string) {
 		out := NewCensoredWriter(c.Out)
 		out.SetSensitiveValues(vals)
 		c.Out = out
+		c.censoredWriter.SetSensitiveValues(vals)
 
 		err := NewCensoredWriter(c.Err)
 		err.SetSensitiveValues(vals)
 		c.Err = err
 	}
 }
+
+type CensoredEncoder struct {
+	zapcore.Encoder
+	censoredWriter *CensoredWriter
+}
+
+func (ce CensoredEncoder) Clone() zapcore.Encoder {
+	return &CensoredEncoder{Encoder: ce.Encoder.Clone(), censoredWriter: ce.censoredWriter}
+}
+
+func (ce CensoredEncoder) EncodeEntry(entry zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) {
+	entry.Message = string(ce.censoredWriter.Censor([]byte(entry.Message)))
+	for _, field := range fields {
+		if field.Type == zapcore.StringType {
+			field.String = string(ce.censoredWriter.Censor([]byte(field.String)))
+		}
+	}
+
+	return ce.Encoder.EncodeEntry(entry, fields)
+}

pkg/portercontext/context_test.go

@@ -131,3 +131,76 @@ func TestContext_PluginLogCollectorLevel(t *testing.T) {
 	require.Contains(t, lines[3], "\"@level\":\"error\"")
 	require.Contains(t, lines[3], "\"@message\":\"error log\"")
 }
+
+func TestContext_SensitiveLogsAreCensored(t *testing.T) {
+	c := NewTestContext(t)
+	defer c.Close()
+	c.ConfigureLogging(context.Background(), LogConfiguration{
+		Verbosity: zapcore.DebugLevel,
+	})
+	c.SetSensitiveValues([]string{"topsecret"})
+
+	c.logger.Info("this is a test with sensitive data: topsecret")
+
+	logs := c.captureLogs.String()
+	require.Contains(t, logs, "this is a test with sensitive data: *******")
+	require.NotContains(t, logs, "topsecret")
+}
+
+func TestContext_TracesWithSensitiveLogsAreCensored(t *testing.T) {
+	c := NewTestContext(t)
+	c.ConfigureLogging(context.Background(), LogConfiguration{
+		Verbosity: zapcore.DebugLevel,
+	})
+	c.SetSensitiveValues([]string{"topsecret"})
+
+	_, log := c.StartRootSpan(context.Background(), t.Name())
+	log.Debug("this is a test with sensitive data: topsecret")
+	log.EndSpan()
+	c.Close()
+
+	logs := c.captureLogs.String()
+	require.Contains(t, logs, "this is a test with sensitive data: *******")
+	require.NotContains(t, logs, "topsecret")
+}
+
+func TestContext_PluginLogsAreCensored(t *testing.T) {
+	c := NewTestContext(t)
+	c.IsInternalPlugin = true
+	c.ConfigureLogging(context.Background(), LogConfiguration{
+		Verbosity: zapcore.DebugLevel,
+	})
+	c.SetSensitiveValues([]string{"topsecret"})
+
+	_, log := c.StartRootSpan(context.Background(), t.Name())
+	log.Debug("this is a test with sensitive data: topsecret")
+	log.EndSpan()
+	c.Close()
+
+	logs := c.captureLogs.String()
+	require.Contains(t, logs, "this is a test with sensitive data: *******")
+	require.NotContains(t, logs, "topsecret")
+}
+
+func TestContext_LogToFileWithCensoredValues(t *testing.T) {
+	c := NewTestContext(t)
+	c.ConfigureLogging(context.Background(), LogConfiguration{
+		Verbosity:    zapcore.DebugLevel,
+		LogLevel:     zapcore.DebugLevel,
+		LogToFile:    true,
+		LogDirectory: "/.porter/logs",
+	})
+	c.SetSensitiveValues([]string{"topsecret"})
+	c.timestampLogs = false // turn off timestamps so we can compare more easily
+	logfile := c.logFile.Name()
+	_, log := c.StartRootSpan(context.Background(), t.Name())
+	log.Info("this is a test with sensitive data: topsecret")
+
+	log.EndSpan()
+	c.Close()
+
+	logContents, err := c.FileSystem.ReadFile(logfile)
+	require.NoError(t, err)
+	require.Contains(t, string(logContents), "this is a test with sensitive data: *******")
+	require.NotContains(t, string(logContents), "topsecret")
+}

pkg/portercontext/plugins.go

@@ -22,7 +22,8 @@ func (c *Context) makePluginLogger(pluginKey string, cfg LogConfiguration) zapco
 
 	enc := zap.NewProductionEncoderConfig()
 	jsonEncoder := zapcore.NewJSONEncoder(enc)
-	return zapcore.NewCore(jsonEncoder, zapcore.AddSync(pluginLogger), cfg.Verbosity)
+	censoredEncoder := &CensoredEncoder{Encoder: jsonEncoder, censoredWriter: c.censoredWriter}
+	return zapcore.NewCore(censoredEncoder, zapcore.AddSync(pluginLogger), cfg.Verbosity)
 }
 
 // Accepts zap log commands and translates them to a format that hclog understands

tests/integration/install_test.go

@@ -127,3 +127,24 @@ func TestInstall_stringParam(t *testing.T) {
 	output := p.TestConfig.TestContext.GetOutput()
 	require.Contains(t, output, "Hello, Demo Time", "expected action output to contain provided file contents")
 }
+
+func TestInstall_SensitiveValuesAreNotLogged(t *testing.T) {
+	p := porter.NewTestPorter(t)
+	defer p.Close()
+	ctx := p.SetupIntegrationTest()
+
+	p.AddTestBundleDir("testdata/bundles/failing-bundle-with-sensitive-data", false)
+
+	installOpts := porter.NewInstallOptions()
+	installOpts.Params = []string{"password=topsecret"}
+
+	err := installOpts.Validate(ctx, []string{}, p.Porter)
+	require.NoError(t, err)
+
+	err = p.InstallBundle(ctx, installOpts)
+	require.Error(t, err)
+
+	output := p.TestConfig.TestContext.GetOutput()
+	require.NotContains(t, output, "topsecret", "expected sensitive data to not be logged")
+	require.Contains(t, output, "*******")
+}

tests/integration/testdata/bundles/failing-bundle-with-sensitive-data/helpers.sh

@@ -0,0 +1,21 @@
+#!/usr/bin/env bash
+set -euo pipefail
+
+install() {
+    echo Hello, $1
+}
+
+open_door() {
+	echo opening door using $1
+}
+
+upgrade() {
+    echo World 2.0
+}
+
+uninstall() {
+    echo Goodbye World
+}
+
+# Call the requested function and pass the arguments as-is
+"$@"

tests/integration/testdata/bundles/failing-bundle-with-sensitive-data/porter.yaml

@@ -0,0 +1,50 @@
+schemaVersion: 1.0.0-alpha.1
+name: mybuns
+version: 0.1.2
+description: "A test bundle for sensitive data"
+registry: localhost:5000
+
+parameters:
+  - name: name
+    description: "author name"
+    type: string
+    default: "porter"
+  - name: password
+    description: "The super secret data"
+    type: string
+    sensitive: true
+
+outputs:
+  - name: mylogs
+    applyTo:
+      - install
+      - upgrade
+  - name: result
+    applyTo:
+      - install
+    sensitive: true
+
+mixins:
+  - exec
+
+install:
+  - exec:
+      description: "Failing step to test sensitive data logging"
+      command: fail
+      arguments:
+        - open_door
+        - "{{ bundle.parameters.password }}"
+
+upgrade:
+  - exec:
+      description: "upgrade"
+      command: ./helpers.sh
+      arguments:
+        - upgrade
+
+uninstall:
+  - exec:
+      description: "uninstall"
+      command: ./helpers.sh
+      arguments:
+        - uninstall