security: sanitize driver log fields

dynamic/builtin.go

@@ -3,6 +3,7 @@ package dynamic
 import (
 	"time"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/docker/machine/libmachine/drivers/plugin/localbinary"
 	"github.com/rancher/go-rancher/v2"
 )
@@ -53,14 +54,14 @@ Loop:
 			installed[driver.Name] = driver
 		}
 		if driver.State == "inactive" && driver.DefaultActive {
-			logger.Infof("Activating driver %s", driver.Name)
+			logger.Infof("Activating driver %s", logsafe.Value(driver.Name))
 			apiClient.MachineDriver.ActionActivate(&driver)
 		}
 	}
 
 	for _, driver := range localbinary.CoreDrivers {
 		if _, ok := installed[driver]; !ok && !ignoredDrivers[driver] {
-			logger.Infof("Installing builtin driver %s", driver)
+			logger.Infof("Installing builtin driver %s", logsafe.Value(driver))
 			apiClient.MachineDriver.Create(&client.MachineDriver{
 				Name:    driver,
 				Builtin: true,
@@ -71,7 +72,7 @@ Loop:
 	}
 
 	for _, driver := range installed {
-		logger.Infof("Deleting old builtin driver %s", driver.Name)
+		logger.Infof("Deleting old builtin driver %s", logsafe.Value(driver.Name))
 		apiClient.MachineDriver.Delete(&driver)
 	}
 

dynamic/driver.go

@@ -21,6 +21,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/PastureStack/host-provisioner/logging"
 )
 
@@ -142,12 +143,12 @@ func (d *Driver) getError() error {
 func (d *Driver) ClearError() {
 	cacheRoot, err := openDriverCacheRoot()
 	if err != nil {
-		logger.Errorf("Failed to open driver cache: %v", err)
+		logger.Errorf("Failed to open driver cache: %s", logsafe.Value(err))
 		return
 	}
 	defer cacheRoot.Close()
 	if err := removeIfPresent(cacheRoot, d.cacheKey()+".error"); err != nil {
-		logger.Errorf("Failed to clear driver error: %v", err)
+		logger.Errorf("Failed to clear driver error: %s", logsafe.Value(err))
 	}
 }
 
@@ -243,7 +244,7 @@ func (d *Driver) Install() error {
 	}
 	defer src.Close()
 
-	logger.Infof("Installing driver %v", driverName)
+	logger.Infof("Installing driver %s", logsafe.Value(driverName))
 	_, err = io.Copy(f, src)
 	if err != nil {
 		f.Close()
@@ -340,7 +341,7 @@ func (d *Driver) copyBinary(cacheRoot *os.Root, cacheKey, input string) (string,
 		return "", err
 	}
 
-	logger.Infof("Found driver %s", driverName)
+	logger.Infof("Found driver %s", logsafe.Value(driverName))
 	return driverName, nil
 }
 
@@ -489,7 +490,7 @@ func (d *Driver) download(dest io.Writer) error {
 	if err != nil || (u.Scheme != "https" && u.Scheme != "http") || u.Host == "" {
 		return fmt.Errorf("invalid driver download URL")
 	}
-	logger.Infof("Downloading machine driver from host %q", u.Hostname())
+	logger.Infof("Downloading machine driver from host %q", logsafe.Value(u.Hostname()))
 	client := &http.Client{Timeout: 5 * time.Minute}
 	resp, err := client.Get(u.String())
 	if err != nil {

dynamic/driver_info.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 	"sync"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/docker/machine/libmachine/drivers/plugin/localbinary"
 	rpcdriver "github.com/docker/machine/libmachine/drivers/rpc"
 	cli "github.com/docker/machine/libmachine/mcnflag"
@@ -140,7 +141,7 @@ func RemoveSchemas(schemaName string, apiClient *client.RancherClient) error {
 			continue
 		}
 
-		logger.Debugf("Removing %s id: %s state: %s", schemaName, schema.Id, schema.State)
+		logger.Debugf("Removing %s id: %s state: %s", logsafe.Value(schemaName), logsafe.Value(schema.Id), logsafe.Value(schema.State))
 		if err := apiClient.DynamicSchema.Delete(&schema); err != nil {
 			return err
 		}
@@ -168,24 +169,24 @@ func uploadDynamicSchema(schemaName, definition, parent string, roles []string,
 		Parent:     parent,
 		Roles:      roles,
 	})
-	logger.WithField("id", schema.Id).Infof("Creating schema %s, roles %v", schemaName, roles)
 	if err != nil {
 		return fmt.Errorf("Failed when uploading %s schema: %v", schemaName, err)
 	}
+	logger.WithField("id", logsafe.Value(schema.Id)).Infof("Creating schema %s, roles %s", logsafe.Value(schemaName), logsafe.Value(roles))
 
 	return waitSchema(*schema, apiClient)
 }
 
 func getCreateFlagsForDriver(driver string) ([]cli.Flag, error) {
-	logger.Debug("Starting binary ", driver)
+	logger.Debug("Starting binary ", logsafe.Value(driver))
 	p, err := localbinary.NewPlugin(driver)
 	if err != nil {
 		return nil, err
 	}
 	go func() {
 		err := p.Serve()
 		if err != nil {
-			logger.Debugf("Error serving plugin server for driver=%s, err=%v", driver, err)
+			logger.Debugf("Error serving plugin server for driver=%s, err=%s", logsafe.Value(driver), logsafe.Value(err))
 		}
 	}()
 	defer p.Close()

dynamic/machine.go

@@ -3,6 +3,7 @@ package dynamic
 import (
 	"strings"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/rancher/go-rancher/v2"
 )
 
@@ -25,7 +26,7 @@ func UploadMachineSchemas(apiClient *client.RancherClient, drivers ...string) er
 		}
 	}
 
-	logger.Infof("Updating machine jsons for  %v", drivers)
+	logger.Infof("Updating machine jsons for %s", logsafe.Value(drivers))
 	if err := uploadMachineServiceJSON(drivers, true); err != nil {
 		return err
 	}

dynamic/start.go

@@ -1,6 +1,7 @@
 package dynamic
 
 import (
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/rancher/go-rancher/v2"
 )
 
@@ -37,7 +38,7 @@ func ReactivateOldDrivers() error {
 
 	for _, driver := range drivers.Data {
 		if driver.SchemaVersion != version {
-			logger.Infof("Updating driver %s from %s => %s", driver.Name, driver.SchemaVersion, version)
+			logger.Infof("Updating driver %s from %s => %s", logsafe.Value(driver.Name), logsafe.Value(driver.SchemaVersion), logsafe.Value(version))
 			_, err := apiClient.MachineDriver.ActionReactivate(&driver)
 			if err != nil {
 				return err
@@ -76,7 +77,7 @@ func DownloadAllDrivers() error {
 		}
 
 		if err != nil {
-			logger.Errorf("Failed to download/install driver %s: %v", driverInfo.Name, err)
+			logger.Errorf("Failed to download/install driver %s: %s", logsafe.Value(driverInfo.Name), logsafe.Value(err))
 			if _, err := apiClient.MachineDriver.ActionReactivate(&driverInfo); err != nil {
 				return err
 			}

handlers/common.go

@@ -14,6 +14,7 @@ import (
 	"time"
 	"unicode"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/rancher/event-subscriber/events"
 	client "github.com/rancher/go-rancher/v2"
 	"github.com/sirupsen/logrus"
@@ -367,7 +368,7 @@ func newReply(event *events.Event) *client.Publish {
 
 func cleanupResources(machineDir, name string) error {
 	logger.WithFields(logrus.Fields{
-		"machine name": name,
+		"machine name": logsafe.Value(name),
 	}).Info("starting cleanup...")
 	dExists, err := dirExists(machineDir)
 	if !dExists {
@@ -401,7 +402,7 @@ func cleanupResources(machineDir, name string) error {
 	removeMachineDir(machineDir)
 
 	logger.WithFields(logrus.Fields{
-		"machine name": name,
+		"machine name": logsafe.Value(name),
 	}).Info("cleanup successful")
 	return nil
 }
@@ -478,7 +479,7 @@ func createJail(machineDir string) error {
 		}
 	}
 
-	logrus.Debugf("Creating jail for %v", machineDir)
+	logrus.Debugf("Creating jail for %s", logsafe.Value(machineDir))
 	// This creates a nested dir, the first nest is the jail root, the 2nd makes everything
 	// appear normal for commands being called in the jail - Something like:
 	// "/var/lib/cattle/machine/machines/{ExternalId}/var/lib/cattle/machine/machines/{ExternalId}"
@@ -495,6 +496,6 @@ func createJail(machineDir string) error {
 	if err != nil {
 		return fmt.Errorf("error running the jail command: %s: %w", out, err)
 	}
-	logrus.Debugf("Output from create jail command %v", string(out))
+	logrus.WithField("outputBytes", len(out)).Debug("Create jail command completed")
 	return nil
 }

handlers/config.go

@@ -12,6 +12,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/PastureStack/host-provisioner/logging"
 	client "github.com/rancher/go-rancher/v2"
 	"github.com/sirupsen/logrus"
@@ -83,7 +84,7 @@ func restoreMachineDir(machine *client.Machine, baseDir string) error {
 			continue
 		}
 		filePath := filepath.Join(machineBaseDir, filename)
-		logger.Infof("Extracting %v", filePath)
+		logger.Infof("Extracting %s", logsafe.Value(filePath))
 
 		info := header.FileInfo()
 		mode := info.Mode()
@@ -121,7 +122,7 @@ func restoreMachineDir(machine *client.Machine, baseDir string) error {
 
 func createExtractedConfig(baseDir string, machine *client.Machine) (string, error) {
 	logger.WithFields(logrus.Fields{
-		"resourceId": machine.Id,
+		"resourceId": logsafe.Value(machine.Id),
 	}).Info("Creating and uploading extracted machine config")
 
 	// create the tar.gz file
@@ -244,22 +245,22 @@ func saveMachineConfig(machineDir string, machine *client.Machine, apiClient *cl
 func removeMachineDir(machineDir string) {
 	workDir, err := trustedWorkDir()
 	if err != nil {
-		logger.WithError(err).Warn("Refusing to remove unresolved machine directory")
+		logger.WithField("error", logsafe.Value(err)).Warn("Refusing to remove unresolved machine directory")
 		return
 	}
 	machinesDir := filepath.Join(workDir, "machines")
 	rel, err := filepath.Rel(machinesDir, machineDir)
 	if err != nil || !filepath.IsLocal(rel) || rel == "." {
-		logger.WithField("machineDir", machineDir).Warn("Refusing to remove machine directory outside storage root")
+		logger.WithField("machineDir", logsafe.Value(machineDir)).Warn("Refusing to remove machine directory outside storage root")
 		return
 	}
 	root, err := os.OpenRoot(machinesDir)
 	if err != nil {
-		logger.WithError(err).Warn("Refusing to remove machine directory without a trusted root")
+		logger.WithField("error", logsafe.Value(err)).Warn("Refusing to remove machine directory without a trusted root")
 		return
 	}
 	defer root.Close()
 	if err := root.RemoveAll(rel); err != nil {
-		logger.WithError(err).Warn("Unable to remove machine directory")
+		logger.WithField("error", logsafe.Value(err)).Warn("Unable to remove machine directory")
 	}
 }

handlers/machine_driver.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 
 	"github.com/PastureStack/host-provisioner/dynamic"
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/rancher/event-subscriber/events"
 	"github.com/rancher/go-rancher/v2"
 	"github.com/sirupsen/logrus"
@@ -19,9 +20,9 @@ func RemoveDriver(event *events.Event, apiClient *client.RancherClient) error {
 
 func removeDriver(event *events.Event, apiClient *client.RancherClient, delete bool) error {
 	logger.WithFields(logrus.Fields{
-		"resourceId": event.ResourceID,
-		"eventId":    event.ID,
-		"name":       event.Name,
+		"resourceId": logsafe.Value(event.ResourceID),
+		"eventId":    logsafe.Value(event.ID),
+		"name":       logsafe.Value(event.Name),
 	}).Info("Event")
 
 	driverInfo, err := apiClient.MachineDriver.ById(event.ResourceID)
@@ -36,7 +37,7 @@ func removeDriver(event *events.Event, apiClient *client.RancherClient, delete b
 	if driverInfo.Checksum == "" || delete {
 		driver, err := getDriver(event.ResourceID, apiClient)
 		if err == nil {
-			logger.Infof("Removing driver %s", driverInfo.Name)
+			logger.Infof("Removing driver %s", logsafe.Value(driverInfo.Name))
 			driver.Remove()
 		}
 	}
@@ -51,9 +52,9 @@ func removeDriver(event *events.Event, apiClient *client.RancherClient, delete b
 
 func ErrorDriver(event *events.Event, apiClient *client.RancherClient) error {
 	logger.WithFields(logrus.Fields{
-		"resourceId": event.ResourceID,
-		"eventId":    event.ID,
-		"name":       event.Name,
+		"resourceId": logsafe.Value(event.ResourceID),
+		"eventId":    logsafe.Value(event.ID),
+		"name":       logsafe.Value(event.Name),
 	}).Info("Event")
 
 	driver, err := getDriver(event.ResourceID, apiClient)
@@ -70,9 +71,9 @@ func ErrorDriver(event *events.Event, apiClient *client.RancherClient) error {
 
 func ActivateDriver(event *events.Event, apiClient *client.RancherClient) error {
 	logger.WithFields(logrus.Fields{
-		"resourceId": event.ResourceID,
-		"eventId":    event.ID,
-		"name":       event.Name,
+		"resourceId": logsafe.Value(event.ResourceID),
+		"eventId":    logsafe.Value(event.ID),
+		"name":       logsafe.Value(event.Name),
 	}).Info("Event")
 
 	driver, err := activate(event.ResourceID, apiClient)
@@ -131,7 +132,7 @@ func activate(id string, apiClient *client.RancherClient) (*dynamic.Driver, erro
 	}
 
 	if err := driver.Install(); err != nil {
-		logger.Errorf("Failed to download/install driver %s: %v", driver.Name(), err)
+		logger.Errorf("Failed to download/install driver %s: %s", logsafe.Value(driver.Name()), logsafe.Value(err))
 		return nil, err
 	}
 

handlers/remove.go

@@ -4,6 +4,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/PastureStack/host-provisioner/internal/logsafe"
 	"github.com/rancher/event-subscriber/events"
 	client "github.com/rancher/go-rancher/v2"
 	"github.com/sirupsen/logrus"
@@ -50,14 +51,14 @@ var removeCache = newExpiringSet(5 * time.Minute)
 
 func PurgeMachine(event *events.Event, apiClient *client.RancherClient) error {
 	logger.WithFields(logrus.Fields{
-		"resourceId": event.ResourceID,
-		"eventId":    event.ID,
+		"resourceId": logsafe.Value(event.ResourceID),
+		"eventId":    logsafe.Value(event.ID),
 	}).Info("Purging Machine")
 
 	if removeCache.contains(event.ResourceID, time.Now()) {
 		logger.WithFields(logrus.Fields{
-			"resourceId": event.ResourceID,
-			"eventId":    event.ID,
+			"resourceId": logsafe.Value(event.ResourceID),
+			"eventId":    logsafe.Value(event.ID),
 		}).Info("Machine already purged")
 		return publishReply(newReply(event), apiClient)
 	}
@@ -82,9 +83,9 @@ func PurgeMachine(event *events.Event, apiClient *client.RancherClient) error {
 	removeCache.add(event.ResourceID, time.Now())
 
 	logger.WithFields(logrus.Fields{
-		"resourceId":        event.ResourceID,
-		"machineExternalId": machine.ExternalId,
-		"machineDir":        machineDirs.jailDir,
+		"resourceId":        logsafe.Value(event.ResourceID),
+		"machineExternalId": logsafe.Value(machine.ExternalId),
+		"machineDir":        logsafe.Value(machineDirs.jailDir),
 	}).Info("Machine purged")
 
 	removeMachineDir(machineDirs.jailDir)

internal/logsafe/value.go

@@ -0,0 +1,13 @@
+// Package logsafe provides single-record formatting for external log values.
+package logsafe
+
+import (
+	"fmt"
+	"strings"
+)
+
+func Value(value interface{}) string {
+	text := fmt.Sprint(value)
+	text = strings.ReplaceAll(text, "\r", "")
+	return strings.ReplaceAll(text, "\n", " ")
+}

internal/logsafe/value_test.go

@@ -0,0 +1,9 @@
+package logsafe
+
+import "testing"
+
+func TestValueProducesSingleRecord(t *testing.T) {
+	if got := Value("first\r\nforged\nthird"); got != "first forged third" {
+		t.Fatalf("unexpected safe log value: %q", got)
+	}
+}