diff --git a/dynamic/builtin.go b/dynamic/builtin.go index 9aaf778..3536d5d 100644 --- a/dynamic/builtin.go +++ b/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) } diff --git a/dynamic/driver.go b/dynamic/driver.go index a0db14c..788a7ab 100644 --- a/dynamic/driver.go +++ b/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 { diff --git a/dynamic/driver_info.go b/dynamic/driver_info.go index 92540f0..1a7d073 100644 --- a/dynamic/driver_info.go +++ b/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,16 +169,16 @@ 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 @@ -185,7 +186,7 @@ func getCreateFlagsForDriver(driver string) ([]cli.Flag, error) { 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() diff --git a/dynamic/machine.go b/dynamic/machine.go index f141342..c94aed9 100644 --- a/dynamic/machine.go +++ b/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 } diff --git a/dynamic/start.go b/dynamic/start.go index 33d93ea..a92f767 100644 --- a/dynamic/start.go +++ b/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 } diff --git a/handlers/common.go b/handlers/common.go index 3eea16a..5b52842 100644 --- a/handlers/common.go +++ b/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 } diff --git a/handlers/config.go b/handlers/config.go index f22f486..0b89f01 100644 --- a/handlers/config.go +++ b/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") } } diff --git a/handlers/machine_driver.go b/handlers/machine_driver.go index cb4bc95..bf3c4ef 100644 --- a/handlers/machine_driver.go +++ b/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 } diff --git a/handlers/remove.go b/handlers/remove.go index 7c1bab9..c83238c 100644 --- a/handlers/remove.go +++ b/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) diff --git a/internal/logsafe/value.go b/internal/logsafe/value.go new file mode 100644 index 0000000..e09d526 --- /dev/null +++ b/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", " ") +} diff --git a/internal/logsafe/value_test.go b/internal/logsafe/value_test.go new file mode 100644 index 0000000..3a6072b --- /dev/null +++ b/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) + } +} diff --git a/main.go b/main.go index c71103a..c504515 100644 --- a/main.go +++ b/main.go @@ -7,6 +7,7 @@ import ( "github.com/PastureStack/host-provisioner/dynamic" "github.com/PastureStack/host-provisioner/handlers" + "github.com/PastureStack/host-provisioner/internal/logsafe" "github.com/PastureStack/host-provisioner/logging" "github.com/rancher/event-subscriber/events" ) @@ -21,7 +22,7 @@ var operatorLocale = "en-US" func main() { processCmdLineFlags() - logger.WithField("gitcommit", GITCOMMIT).Info(operatorMessage(operatorLocale, "start")) + logger.WithField("gitcommit", logsafe.Value(GITCOMMIT)).Info(operatorMessage(operatorLocale, "start")) apiURL := environmentValue("PLATFORM_URL", "CATTLE_URL") accessKey := environmentValue("PLATFORM_ACCESS_KEY", "CATTLE_ACCESS_KEY") @@ -85,10 +86,10 @@ func main() { logger.Infof("Waiting for handler registration (2/2)") <-ready if err := dynamic.ReactivateOldDrivers(); err != nil { - logger.Fatalf("Error reactivating old drivers: %v", err) + logger.Fatalf("Error reactivating old drivers: %s", logsafe.Value(err)) } if err := dynamic.DownloadAllDrivers(); err != nil { - logger.Fatalf("Error updating drivers: %v", err) + logger.Fatalf("Error updating drivers: %s", logsafe.Value(err)) } }() @@ -96,7 +97,7 @@ func main() { if err == nil { logger.Info(operatorMessage(operatorLocale, "exit")) } else { - logger.Fatalf("Exiting host-provisioner: %v", err) + logger.Fatalf("Exiting host-provisioner: %s", logsafe.Value(err)) } }