From 958772467a8309279bcae3e6fbcca3e6f7f2988d Mon Sep 17 00:00:00 2001 From: Kaloyan Raev Date: Tue, 3 Dec 2019 15:56:49 +0200 Subject: [PATCH] cmd/storagenode-updater, pkg/process: Fix logging timestamp After changing how we execute the storagenode-updater process we lost timestamps in the log. The fix is to start using zap logging. The Windows Installer is changed to register the storagenode-updater service in a way that the Windows Service Manager passes the --log.output flag instead of the old --log. The old --log flag is deprecated, but not removed. We will support it for backward compatibility. This is required as the storagenode-updater can auto-updated itself, but the Windows Service Manager of this old installtion will continue passing the old --log flag when starting it. Change-Id: I690dff27e01335e617aa314032ecbadc4ea8cbd5 Signed-off-by: Kaloyan Raev --- cmd/storagenode-updater/main.go | 64 +++++++++++++++--------------- cmd/storagenode-updater/windows.go | 12 +++--- installer/windows/Product.wxs | 2 +- pkg/process/exec_conf.go | 2 +- pkg/process/logging.go | 12 ++++-- 5 files changed, 49 insertions(+), 43 deletions(-) diff --git a/cmd/storagenode-updater/main.go b/cmd/storagenode-updater/main.go index e967f647c..449731aae 100644 --- a/cmd/storagenode-updater/main.go +++ b/cmd/storagenode-updater/main.go @@ -65,8 +65,8 @@ var ( BinaryLocation string `help:"the storage node executable binary location" default:"storagenode.exe"` ServiceName string `help:"storage node OS service name" default:"storagenode"` - // NB: can't use `log.output` because windows service command args containing "." are bugged. - Log string `help:"path to log file, if empty standard output will be used" default:""` + // deprecated + Log string `help:"deprecated, use --log.output" default:""` } confDir string @@ -87,20 +87,22 @@ func init() { } func cmdRun(cmd *cobra.Command, args []string) (err error) { - closeLog, err := openLog() - defer func() { err = errs.Combine(err, closeLog()) }() + err = openLog() + if err != nil { + zap.S().Errorf("Error creating new logger: %v", err) + } if !fileExists(runCfg.BinaryLocation) { - log.Fatal("unable to find storage node executable binary") + zap.S().Fatal("Unable to find storage node executable binary") } ident, err := runCfg.Identity.Load() if err != nil { - log.Fatalf("error loading identity: %s", err) + zap.S().Fatalf("Error loading identity: %v", err) } nodeID = ident.ID if nodeID.IsZero() { - log.Fatal("empty node ID") + zap.S().Fatal("Empty node ID") } var ctx context.Context @@ -118,13 +120,13 @@ func cmdRun(cmd *cobra.Command, args []string) (err error) { loopFunc := func(ctx context.Context) (err error) { if err := update(ctx, runCfg.BinaryLocation, runCfg.ServiceName); err != nil { // don't finish loop in case of error just wait for another execution - log.Println(err) + zap.S().Errorf("Error updating %s: %v", runCfg.ServiceName, err) } updaterBinName := os.Args[0] if err := update(ctx, updaterBinName, updaterServiceName); err != nil { // don't finish loop in case of error just wait for another execution - log.Println(err) + zap.S().Errorf("Error updating %s: %v", updaterServiceName, err) } return nil } @@ -133,7 +135,7 @@ func cmdRun(cmd *cobra.Command, args []string) (err error) { case runCfg.CheckInterval <= 0: err = loopFunc(ctx) case runCfg.CheckInterval < minCheckInterval: - log.Printf("check interval below minimum: \"%s\", setting to %s", runCfg.CheckInterval, minCheckInterval) + zap.S().Errorf("Check interval below minimum: %s, setting to %s", runCfg.CheckInterval, minCheckInterval) runCfg.CheckInterval = minCheckInterval fallthrough default: @@ -148,7 +150,7 @@ func cmdRun(cmd *cobra.Command, args []string) (err error) { func update(ctx context.Context, binPath, serviceName string) (err error) { if nodeID.IsZero() { - log.Fatal("empty node ID") + zap.S().Fatal("Empty node ID") } var currentVersion version.SemVer @@ -163,7 +165,7 @@ func update(ctx context.Context, binPath, serviceName string) (err error) { } client := checker.New(runCfg.ClientConfig) - log.Println("downloading versions from", runCfg.ServerAddress) + zap.S().Infof("Downloading versions from %s", runCfg.ServerAddress) processVersion, err := client.Process(ctx, serviceName) if err != nil { return errs.Wrap(err) @@ -176,12 +178,12 @@ func update(ctx context.Context, binPath, serviceName string) (err error) { } if currentVersion.Compare(suggestedVersion) >= 0 { - log.Printf("%s version is up to date\n", serviceName) + zap.S().Infof("%s version is up to date", serviceName) return nil } if !version.ShouldUpdate(processVersion.Rollout, nodeID) { - log.Printf("new %s version available but not rolled out to this nodeID yet\n", serviceName) + zap.S().Infof("New %s version available but not rolled out to this nodeID yet", serviceName) return nil } @@ -197,12 +199,12 @@ func update(ctx context.Context, binPath, serviceName string) (err error) { }() downloadURL := parseDownloadURL(processVersion.Suggested.URL) - log.Println("start downloading", downloadURL, "to", tempArchive.Name()) + zap.S().Infof("Start downloading %s to %s", downloadURL, tempArchive.Name()) err = downloadArchive(ctx, tempArchive, downloadURL) if err != nil { return errs.Wrap(err) } - log.Println("finished downloading", downloadURL, "to", tempArchive.Name()) + zap.S().Infof("Finished downloading %s to %s", downloadURL, tempArchive.Name()) newVersionPath := prependExtension(binPath, suggestedVersion.String()) err = unpackBinary(ctx, tempArchive.Name(), newVersionPath) @@ -238,13 +240,13 @@ func update(ctx context.Context, binPath, serviceName string) (err error) { return errs.Wrap(err) } - log.Println("restarting service", serviceName) + zap.S().Infof("Restarting service %s", serviceName) err = restartService(serviceName) if err != nil { // TODO: should we try to recover from this? - return errs.New("unable to restart service: %v", err) + return errs.New("Unable to restart service: %v", err) } - log.Println("service", serviceName, "restarted successfully") + zap.S().Infof("Service %s restarted successfully", serviceName) // TODO remove old binary ?? return nil @@ -266,7 +268,7 @@ func parseDownloadURL(template string) string { func binaryVersion(location string) (version.SemVer, error) { out, err := exec.Command(location, "version").CombinedOutput() if err != nil { - log.Printf("command output: %s", out) + zap.S().Infof("Command output: %s", out) return version.SemVer{}, err } @@ -338,21 +340,19 @@ func fileExists(filename string) bool { return info.Mode().IsRegular() } -// TODO: improve logging; other commands use zap but due to an apparent -// windows bug we're unable to use the existing process logging infrastructure. -func openLog() (closeFunc func() error, err error) { - closeFunc = func() error { return nil } - +func openLog() error { if runCfg.Log != "" { - logFile, err := os.OpenFile(runCfg.Log, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666) - if err != nil { - log.Printf("error opening log file: %s", err) - return closeFunc, err + logPath := runCfg.Log + if runtime.GOOS == "windows" && !strings.HasPrefix(logPath, "winfile:///") { + logPath = "winfile:///" + logPath } - log.SetOutput(logFile) - return logFile.Close, nil + logger, err := process.NewLoggerWithOutputPaths(logPath) + if err != nil { + return err + } + zap.ReplaceGlobals(logger) } - return closeFunc, nil + return nil } func main() { diff --git a/cmd/storagenode-updater/windows.go b/cmd/storagenode-updater/windows.go index 8c9520cca..5852c99e3 100644 --- a/cmd/storagenode-updater/windows.go +++ b/cmd/storagenode-updater/windows.go @@ -12,10 +12,10 @@ package main import ( - "log" "os" "time" + "go.uber.org/zap" "golang.org/x/sync/errgroup" "golang.org/x/sys/windows/svc" @@ -26,7 +26,7 @@ func init() { // Check if session is interactive interactive, err := svc.IsAnInteractiveSession() if err != nil { - panic("Failed to determine if session is interactive:" + err.Error()) + zap.S().Fatalf("Failed to determine if session is interactive: %v", err) } if interactive { @@ -45,7 +45,7 @@ func init() { // Initialize the Windows Service handler err = svc.Run("storagenode-updater", &service{}) if err != nil { - panic("Service failed: " + err.Error()) + zap.S().Fatalf("Service failed: %v", err) } // avoid starting main() when service was stopped os.Exit(0) @@ -69,13 +69,13 @@ func (m *service) Execute(args []string, r <-chan svc.ChangeRequest, changes cha for c := range r { switch c.Cmd { case svc.Interrogate: - log.Println("Interrogate request received.") + zap.S().Info("Interrogate request received.") changes <- c.CurrentStatus // Testing deadlock from https://code.google.com/p/winsvc/issues/detail?id=4 time.Sleep(100 * time.Millisecond) changes <- c.CurrentStatus case svc.Stop, svc.Shutdown: - log.Println("Stop/Shutdown request received.") + zap.S().Info("Stop/Shutdown request received.") changes <- svc.Status{State: svc.StopPending} // Cancel the command's root context to cleanup resources _, cancel := process.Ctx(runCmd) @@ -84,7 +84,7 @@ func (m *service) Execute(args []string, r <-chan svc.ChangeRequest, changes cha // After returning the Windows Service is stopped and the process terminates return default: - log.Println("Unexpected control request:", c) + zap.S().Infof("Unexpected control request: %d\n", c) } } return diff --git a/installer/windows/Product.wxs b/installer/windows/Product.wxs index b6e56d700..335292219 100644 --- a/installer/windows/Product.wxs +++ b/installer/windows/Product.wxs @@ -57,7 +57,7 @@ Account="[SERVICEACCOUNT]" Password="[SERVICEPASSWORD]" ErrorControl="normal" - Arguments="run --config-dir "[INSTALLFOLDER]\" --binary-location "[INSTALLFOLDER]storagenode.exe" --log "[INSTALLFOLDER]storagenode-updater.log""> + Arguments="run --config-dir "[INSTALLFOLDER]\" --binary-location "[INSTALLFOLDER]storagenode.exe" --log.output "winfile:///[INSTALLFOLDER]storagenode-updater.log"">