From 128b0e506d3e41fc01465f069cd563262c78e195 Mon Sep 17 00:00:00 2001 From: Adam Ross Date: Wed, 31 Jan 2018 18:43:54 -0800 Subject: [PATCH 1/3] Retrofit spinner logging to file sync. --- commands/project_sync.go | 44 ++++++++++++++++++++-------------------- util/logger.go | 8 ++++++++ 2 files changed, 30 insertions(+), 22 deletions(-) diff --git a/commands/project_sync.go b/commands/project_sync.go index 8d01cbf..0c20785 100644 --- a/commands/project_sync.go +++ b/commands/project_sync.go @@ -119,20 +119,22 @@ func (cmd *ProjectSync) RunStart(ctx *cli.Context) error { // StartUnisonSync will create and launch the volumes and containers on systems that need/support Unison func (cmd *ProjectSync) StartUnisonSync(ctx *cli.Context, volumeName string, config *ProjectConfig, workingDir string) error { + cmd.out.Spin("Starting Outrigger Filesync (unison)...") + // Ensure the processes can handle a large number of watches if err := cmd.machine.SetSysctl("fs.inotify.max_user_watches", maxWatches); err != nil { cmd.Failure(fmt.Sprintf("Failure configuring file watches on Docker Machine: %v", err), "INOTIFY-WATCH-FAILURE", 12) } - cmd.out.Channel.Info.Printf("Starting sync volume: %s", volumeName) + cmd.out.Info("Starting sync volume: %s", volumeName) if err := util.Command("docker", "volume", "create", volumeName).Run(); err != nil { return cmd.Failure(fmt.Sprintf("Failed to create sync volume: %s", volumeName), "VOLUME-CREATE-FAILED", 13) } - - cmd.out.Info("Starting Unison container") + cmd.out.Info("Sync volume '%s' created", volumeName) + cmd.out.SpinWithVerbose(fmt.Sprintf("Starting sync container: %s (same name)", volumeName)) unisonMinorVersion := cmd.GetUnisonMinorVersion() - cmd.out.Channel.Verbose.Printf("Local Unison version for compatibilty: %s", unisonMinorVersion) + cmd.out.Verbose("Local Unison version for compatibilty: %s", unisonMinorVersion) util.Command("docker", "container", "stop", volumeName).Run() containerArgs := []string{ "container", "run", "--detach", "--rm", @@ -151,8 +153,8 @@ func (cmd *ProjectSync) StartUnisonSync(ctx *cli.Context, volumeName string, con if err != nil { return cmd.Failure(err.Error(), "SYNC-INIT-FAILED", 13) } - - cmd.out.Info("Initializing sync") + cmd.out.Info("Sync container '%s' started", volumeName) + cmd.out.SpinWithVerbose("Initializing file sync...") // Determine the location of the local Unison log file. var logFile = fmt.Sprintf("%s.log", volumeName) @@ -179,7 +181,7 @@ func (cmd *ProjectSync) StartUnisonSync(ctx *cli.Context, volumeName string, con unisonArgs = append(unisonArgs, "-ignore", ignore) } } - cmd.out.Verbose("Unison Args: %s", strings.Join(unisonArgs[:], " ")) + /* #nosec */ command := exec.Command("unison", unisonArgs...) command.Dir = workingDir @@ -197,7 +199,7 @@ func (cmd *ProjectSync) StartUnisonSync(ctx *cli.Context, volumeName string, con // SetupBindVolume will create minimal Docker Volumes for systems that have native container/volume support func (cmd *ProjectSync) SetupBindVolume(volumeName string, workingDir string) error { - cmd.out.Info("Starting local bind volume: %s", volumeName) + cmd.out.SpinWithVerbose("Starting local bind volume: %s", volumeName) util.Command("docker", "volume", "rm", volumeName).Run() volumeArgs := []string{ @@ -220,6 +222,7 @@ func (cmd *ProjectSync) RunStop(ctx *cli.Context) error { if runtime.GOOS == "linux" { return cmd.Success("No Unison container to stop, using local bind volume") } + cmd.out.Spin(fmt.Sprintf("Stopping Unison container")) cmd.Config = NewProjectConfig() if cmd.Config.NotEmpty() { @@ -238,7 +241,7 @@ func (cmd *ProjectSync) RunStop(ctx *cli.Context) error { return cmd.Failure(err.Error(), "SYNC-CONTAINER-FAILURE", 13) } - return cmd.Success(fmt.Sprintf("Unison container %s stopped", volumeName)) + return cmd.Success(fmt.Sprintf("Unison container '%s' stopped", volumeName)) } // GetVolumeName will find the volume name through a variety of fall backs @@ -283,7 +286,7 @@ func (cmd *ProjectSync) LoadComposeFile() (*ComposeFile, error) { // when compiled without -cgo this executable will not use the native mac dns resolution // which is how we have configured dnsdock to provide names for containers. func (cmd *ProjectSync) WaitForUnisonContainer(containerName string, timeoutSeconds int) (string, error) { - cmd.out.Info("Waiting for container to start") + cmd.out.SpinWithVerbose("Sync container '%s' started , waiting for unison server process...", containerName) var timeoutLoopSleep = time.Duration(100) * time.Millisecond // * 10 here because we loop once every 100 ms and we want to get to seconds @@ -303,7 +306,7 @@ func (cmd *ProjectSync) WaitForUnisonContainer(containerName string, timeoutSeco return ip, nil } - cmd.out.Info("Failure: %v", err) + cmd.out.SpinWithVerbose("Failure: %v", err) time.Sleep(timeoutLoopSleep) } @@ -313,12 +316,12 @@ func (cmd *ProjectSync) WaitForUnisonContainer(containerName string, timeoutSeco // WaitForSyncInit will wait for the local unison process to finish initializing // when the log file exists and has stopped growing in size func (cmd *ProjectSync) WaitForSyncInit(logFile string, workingDir string, timeoutSeconds int, syncWaitSeconds int) error { - cmd.out.Info("Waiting for initial sync detection") + cmd.out.SpinWithVerbose("Waiting for initial sync detection...") // The use of os.Stat below is not subject to our working directory configuration, // so to ensure we can stat the log file we convert it to an absolute path. if logFilePath, err := util.AbsJoin(workingDir, logFile); err != nil { - cmd.out.Info(err.Error()) + cmd.out.Error(err.Error()) } else { // Create a temp file to cause a sync action var tempFile = ".rig-check-sync-start" @@ -333,32 +336,29 @@ func (cmd *ProjectSync) WaitForSyncInit(logFile string, workingDir string, timeo var timeoutLoops = timeoutSeconds * 10 var statSleep = time.Duration(syncWaitSeconds) * time.Second for i := 1; i <= timeoutLoops; i++ { - if i%10 == 0 { - os.Stdout.WriteString(".") - } - statInfo, err := os.Stat(logFilePath) if err == nil { - os.Stdout.WriteString(" initial sync detected\n") + cmd.out.Info("Initial sync detected") - cmd.out.Info("Waiting for initial sync to finish") + cmd.out.SpinWithVerbose("Waiting for initial sync to finish") // Initialize at -2 to force at least one loop var lastSize = int64(-2) for lastSize != statInfo.Size() { - os.Stdout.WriteString(".") time.Sleep(statSleep) lastSize = statInfo.Size() if statInfo, err = os.Stat(logFilePath); err != nil { - cmd.out.Info(err.Error()) + cmd.out.Error(err.Error()) lastSize = -1 } } - os.Stdout.WriteString(" done\n") + // Remove the temp file, waiting until after sync so spurious // failure message doesn't show in log if err := util.RemoveFile(tempFile, workingDir); err != nil { cmd.out.Warning("Could not remove the temporary file: %s: %s", tempFile, err.Error()) } + + cmd.out.Info("File sync completed") return nil } diff --git a/util/logger.go b/util/logger.go index 0095225..29a9453 100644 --- a/util/logger.go +++ b/util/logger.go @@ -74,6 +74,14 @@ func (log *RigLogger) Spin(message string) { } } +// SpinWithVerbose operates the spinner but also writes to the verbose log. +// This is used in cases where the spinner's initial context is needed for +// detailed verbose logging purposes. +func (log *RigLogger) SpinWithVerbose(message string, a ...interface{}) { + log.Spin(fmt.Sprintf(message, a...)) + log.Verbose(message, a...) +} + // NoSpin stops the Progress spinner. func (log *RigLogger) NoSpin() { log.Progress.Spins.Stop() From 410b504eb07d10b933fc06cb68b8dbbd83c3024d Mon Sep 17 00:00:00 2001 From: Chris Johnson Date: Fri, 2 Feb 2018 18:28:51 -0500 Subject: [PATCH 2/3] Add some more direction of what to do in the case of timeouts during sync start --- commands/project_sync.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/commands/project_sync.go b/commands/project_sync.go index 0c20785..21c8004 100644 --- a/commands/project_sync.go +++ b/commands/project_sync.go @@ -49,8 +49,8 @@ func (cmd *ProjectSync) Commands() []cli.Command { Flags: []cli.Flag{ cli.IntFlag{ Name: "initial-sync-timeout", - Value: 60, - Usage: "Maximum amount of time in seconds to allow for detecting each of start of the Unison container and start of initial sync. (not needed on linux)", + Value: 120, + Usage: "Maximum amount of time in seconds to allow for detecting each of start of the Unison container and start of initial sync. If you encounter failures detecting initial sync increasing this value may help. Search for sync on http://docs.outrigger.sh/faq/troubleshooting/ (not needed on linux)", EnvVar: "RIG_PROJECT_SYNC_TIMEOUT", }, // Arbitrary sleep length but anything less than 3 wasn't catching @@ -373,7 +373,7 @@ func (cmd *ProjectSync) WaitForSyncInit(logFile string, workingDir string, timeo } } - return fmt.Errorf("Failed to detect start of initial sync") + return fmt.Errorf("Failed to detect start of initial sync, this could indicate a need to increase the initial-sync-timeout. See rig project sync --help") } // GetUnisonMinorVersion will return the local Unison version to try to load a compatible unison image From 6ffc5d927facb0ae89227f1f38ca54aba878cb4e Mon Sep 17 00:00:00 2001 From: Chris Johnson Date: Fri, 2 Feb 2018 18:44:21 -0500 Subject: [PATCH 3/3] Adjusting error message on sync failure to work better with spinner --- commands/project_sync.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/commands/project_sync.go b/commands/project_sync.go index 21c8004..a85c1e0 100644 --- a/commands/project_sync.go +++ b/commands/project_sync.go @@ -373,7 +373,8 @@ func (cmd *ProjectSync) WaitForSyncInit(logFile string, workingDir string, timeo } } - return fmt.Errorf("Failed to detect start of initial sync, this could indicate a need to increase the initial-sync-timeout. See rig project sync --help") + cmd.out.Error("Initial sync detection failed, this could indicate a need to increase the initial-sync-timeout. See rig project sync --help") + return fmt.Errorf("Failed to detect start of initial sync") } // GetUnisonMinorVersion will return the local Unison version to try to load a compatible unison image