feat: Updater logging (#589)

* add zap logging

* add log level flag

* add license headers

* lint fixes

* remove unimplemented comment

* skip NewLogger test on windows

* remove ability to specify level

* remove rotation

* remove copyFiles receiver

* remove stringer implementation

* remove previous log file on logger creation

* tidy go mod

* re-add stringer for copy file action

updater/cmd/updater/main.go

@@ -24,6 +24,8 @@ import (
 
 	"github.com/observiq/observiq-otel-collector/packagestate"
 	"github.com/observiq/observiq-otel-collector/updater/internal/install"
+	"github.com/observiq/observiq-otel-collector/updater/internal/logging"
+	"github.com/observiq/observiq-otel-collector/updater/internal/path"
 	"github.com/observiq/observiq-otel-collector/updater/internal/rollback"
 	"github.com/observiq/observiq-otel-collector/updater/internal/state"
 	"github.com/observiq/observiq-otel-collector/updater/internal/version"
@@ -32,9 +34,8 @@ import (
 	"go.uber.org/zap"
 )
 
-// Unimplemented
 func main() {
-	var showVersion = pflag.BoolP("version", "v", false, "Prints the version of the collector and exits, if specified.")
+	var showVersion = pflag.BoolP("version", "v", false, "Prints the version of the updater and exits, if specified.")
 	var tmpDir = pflag.String("tmpdir", "", "Temporary directory for artifacts. Parent of the 'rollback' directory.")
 	pflag.Parse()
 
@@ -51,58 +52,71 @@ func main() {
 		os.Exit(1)
 	}
 
+	// We can't create the zap logger yet, because we don't know the install dir, which is needed
+	// to create the logger. So we pass a Nop logger here.
+	installDir, err := path.InstallDir(zap.NewNop())
+	if err != nil {
+		log.Fatalf("Failed to determine install directory: %s", err)
+	}
+
+	logger, err := logging.NewLogger(installDir)
+	if err != nil {
+		log.Fatalf("Failed to create logger: %s", err)
+	}
+
 	// Create a monitor and load the package status file
-	// TODO replace nop logger with real one
-	monitor, err := state.NewCollectorMonitor(zap.NewNop())
+	monitor, err := state.NewCollectorMonitor(logger)
 	if err != nil {
-		log.Fatalln("Failed to create monitor:", err)
+		logger.Fatal("Failed to create monitor", zap.Error(err))
 	}
 
-	installer, err := install.NewInstaller(*tmpDir)
+	installer, err := install.NewInstaller(logger, *tmpDir)
 	if err != nil {
-		log.Fatalf("Failed to create installer: %s", err)
+		logger.Fatal("Failed to create installer", zap.Error(err))
 	}
 
-	rb, err := rollback.NewRollbacker(*tmpDir)
+	rb, err := rollback.NewRollbacker(logger, *tmpDir)
 	if err != nil {
-		log.Fatalf("Failed to create rollbacker: %s", err)
+		logger.Fatal("Failed to create rollbacker", zap.Error(err))
 	}
 
 	if err := rb.Backup(); err != nil {
-		log.Fatalf("Failed to backup: %s", err)
+		logger.Fatal("Failed to backup", zap.Error(err))
 	}
 
 	if err := installer.Install(rb); err != nil {
-		log.Default().Printf("Failed to install: %s", err)
+		logger.Error("Failed to install", zap.Error(err))
 
 		// Set the state to failed before rollback so collector knows it failed
 		if setErr := monitor.SetState(packagestate.DefaultFileName, protobufs.PackageStatus_InstallFailed, err); setErr != nil {
-			log.Println("Failed to set state on install failure:", setErr)
+			logger.Error("Failed to set state on install failure", zap.Error(setErr))
 		}
 		rb.Rollback()
-		log.Default().Fatalf("Rollback complete")
+		logger.Fatal("Rollback complete")
 	}
 
 	// Create a context with timeout to wait for a success or failed status
 	checkCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 	defer cancel()
 
+	logger.Debug("Installation successful, begin monitor for success")
+
 	// Monitor the install state
 	if err := monitor.MonitorForSuccess(checkCtx, packagestate.DefaultFileName); err != nil {
-		log.Println("Failed to install:", err)
+		logger.Error("Failed to install", zap.Error(err))
 
 		// If this is not an error due to the collector setting a failed status we need to set a failed status
 		if !errors.Is(err, state.ErrFailedStatus) {
 			// Set the state to failed before rollback so collector knows it failed
 			if setErr := monitor.SetState(packagestate.DefaultFileName, protobufs.PackageStatus_InstallFailed, err); setErr != nil {
-				log.Println("Failed to set state on install failure:", setErr)
+				logger.Error("Failed to set state on install failure", zap.Error(setErr))
 			}
 		}
 
 		rb.Rollback()
-		log.Fatalln("Rollback complete")
+		logger.Fatal("Rollback complete")
 	}
 
 	// Successful update
-	log.Println("Update Complete")
+	logger.Info("Update Complete")
 }

updater/go.mod

@@ -13,6 +13,7 @@ require (
 )
 
 require (
+	github.com/benbjohnson/clock v1.1.0 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/stretchr/objx v0.4.0 // indirect

updater/go.sum

@@ -1,22 +1,29 @@
 github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
 github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
+github.com/cenkalti/backoff/v4 v4.1.2/go.mod h1:scbssz8iZGpm3xbr14ovlUdkxfGXNInqkPWOWmG2CLw=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk=
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
+github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg=
+github.com/google/go-cmp v0.5.8/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY=
+github.com/gorilla/websocket v1.4.2/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE=
 github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 h1:Z9n2FFNUXsshfwJMBgNA0RU6/i7WVaAegv3PtuIHPMs=
 github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51/go.mod h1:CzGEWj7cYgsdH8dAjBGEr58BoE7ScuLd+fwFZ44+/x8=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/oklog/ulid/v2 v2.0.2/go.mod h1:mtBL0Qe/0HAx6/a4Z30qxVIAL1eQDweXq5lxOEiwQ68=
 github.com/open-telemetry/opamp-go v0.2.0 h1:dV7wTkG5XNiorU62N1CJPr3f5dM0PGEtUUBtvK+LEG0=
 github.com/open-telemetry/opamp-go v0.2.0/go.mod h1:IMdeuHGVc5CjKSu5/oNV0o+UmiXuahoHvoZ4GOmAI9M=
+github.com/pborman/getopt v0.0.0-20170112200414-7148bc3a4c30/go.mod h1:85jBQOZwpVEaDAr341tbn15RS4fCAsIst0qp7i8ex1o=
 github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
@@ -35,6 +42,7 @@ go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE=
 go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
 go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
 go.uber.org/goleak v1.1.12 h1:gZAh5/EyT/HQwlpkCy6wTpqfH9H8Lz8zbm3dZh+OyzA=
+go.uber.org/goleak v1.1.12/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
 go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
 go.uber.org/multierr v1.8.0 h1:dg6GjLku4EH+249NNmoIciG9N/jURbDG+pFlTkhzIC8=
 go.uber.org/multierr v1.8.0/go.mod h1:7EAYxJLBy9rStEaz58O2t4Uvip6FSURkq8/ppBp95ak=
@@ -68,13 +76,15 @@ golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8T
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=
+google.golang.org/protobuf v1.27.1/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc=
 google.golang.org/protobuf v1.28.0 h1:w43yiav+6bVFTBQFZX0r7ipe9JQ1QsbMgHwbBziscLw=
 google.golang.org/protobuf v1.28.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY=
+gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=

updater/internal/action/file_action.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/observiq/observiq-otel-collector/updater/internal/file"
 	"github.com/observiq/observiq-otel-collector/updater/internal/path"
+	"go.uber.org/zap"
 )
 
 // CopyFileAction is an action that records a file being copied from FromPath to ToPath
@@ -34,16 +35,17 @@ type CopyFileAction struct {
 	// FileCreated is a bool that records whether this action had to create a new file or not
 	FileCreated bool
 	backupDir   string
-	latestDir   string
+	logger      *zap.Logger
 }
 
 var _ RollbackableAction = (*CopyFileAction)(nil)
+var _ fmt.Stringer = (*CopyFileAction)(nil)
 
 // NewCopyFileAction creates a new CopyFileAction that indicates a file was copied from
 // fromPathRel into toPath. tmpDir is specified for rollback purposes.
 // NOTE: This action MUST be created BEFORE the action actually takes place; This allows
 // for previous existence of the file to be recorded.
-func NewCopyFileAction(fromPathRel, toPath, tmpDir string) (*CopyFileAction, error) {
+func NewCopyFileAction(logger *zap.Logger, fromPathRel, toPath, tmpDir string) (*CopyFileAction, error) {
 	fileExists := true
 	_, err := os.Stat(toPath)
 	switch {
@@ -59,7 +61,7 @@ func NewCopyFileAction(fromPathRel, toPath, tmpDir string) (*CopyFileAction, err
 		// The file will be created if it doesn't already exist
 		FileCreated: !fileExists,
 		backupDir:   path.BackupDirFromTempDir(tmpDir),
-		latestDir:   path.LatestDirFromTempDir(tmpDir),
+		logger:      logger.Named("copy-file-action"),
 	}, nil
 }
 
@@ -74,9 +76,13 @@ func (c CopyFileAction) Rollback() error {
 
 	// join the relative path to the backup directory to get the location of the backup path
 	backupFilePath := filepath.Join(c.backupDir, c.FromPathRel)
-	if err := file.CopyFile(backupFilePath, c.ToPath, true); err != nil {
+	if err := file.CopyFile(c.logger.Named("copy-file"), backupFilePath, c.ToPath, true); err != nil {
 		return fmt.Errorf("failed to copy file: %w", err)
 	}
 
 	return nil
 }
+
+func (c CopyFileAction) String() string {
+	return fmt.Sprintf("CopyFileAction{FromPathRel: '%s', ToPath: '%s', FileCreated: '%t'}", c.FromPathRel, c.ToPath, c.FileCreated)
+}

updater/internal/action/file_action_test.go

@@ -20,6 +20,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zaptest"
 )
 
 func TestNewCopyFileAction(t *testing.T) {
@@ -29,15 +30,15 @@ func TestNewCopyFileAction(t *testing.T) {
 		outFile := filepath.Join(scratchDir, "test.txt")
 		inFile := filepath.Join(testTempDir, "latest", "test.txt")
 
-		a, err := NewCopyFileAction(inFile, outFile, testTempDir)
+		a, err := NewCopyFileAction(zaptest.NewLogger(t), inFile, outFile, testTempDir)
 		require.NoError(t, err)
 
 		require.Equal(t, &CopyFileAction{
 			FromPathRel: inFile,
 			ToPath:      outFile,
 			FileCreated: true,
 			backupDir:   filepath.Join(testTempDir, "rollback"),
-			latestDir:   filepath.Join(testTempDir, "latest"),
+			logger:      a.logger,
 		}, a)
 	})
 
@@ -51,15 +52,15 @@ func TestNewCopyFileAction(t *testing.T) {
 		require.NoError(t, err)
 		require.NoError(t, f.Close())
 
-		a, err := NewCopyFileAction(inFile, outFile, testTempDir)
+		a, err := NewCopyFileAction(zaptest.NewLogger(t), inFile, outFile, testTempDir)
 		require.NoError(t, err)
 
 		require.Equal(t, &CopyFileAction{
 			FromPathRel: inFile,
 			ToPath:      outFile,
 			FileCreated: false,
 			backupDir:   filepath.Join(testTempDir, "rollback"),
-			latestDir:   filepath.Join(testTempDir, "latest"),
+			logger:      a.logger,
 		}, a)
 	})
 }
@@ -71,7 +72,7 @@ func TestCopyFileActionRollback(t *testing.T) {
 		outFile := filepath.Join(scratchDir, "test.txt")
 		inFile := filepath.Join(testTempDir, "latest", "test.txt")
 
-		a, err := NewCopyFileAction(inFile, outFile, testTempDir)
+		a, err := NewCopyFileAction(zaptest.NewLogger(t), inFile, outFile, testTempDir)
 		require.NoError(t, err)
 
 		inBytes, err := os.ReadFile(inFile)
@@ -100,7 +101,7 @@ func TestCopyFileActionRollback(t *testing.T) {
 		err = os.WriteFile(outFile, originalBytes, 0600)
 		require.NoError(t, err)
 
-		a, err := NewCopyFileAction(inFileRel, outFile, testTempDir)
+		a, err := NewCopyFileAction(zaptest.NewLogger(t), inFileRel, outFile, testTempDir)
 		require.NoError(t, err)
 
 		// Overwrite original file with latest file
@@ -135,7 +136,7 @@ func TestCopyFileActionRollback(t *testing.T) {
 		err = os.WriteFile(outFile, originalBytes, 0600)
 		require.NoError(t, err)
 
-		a, err := NewCopyFileAction(inFile, outFile, testTempDir)
+		a, err := NewCopyFileAction(zaptest.NewLogger(t), inFile, outFile, testTempDir)
 		require.NoError(t, err)
 
 		// Overwrite original file with latest file

updater/internal/action/service_action.go

@@ -17,6 +17,7 @@ package action
 import (
 	"github.com/observiq/observiq-otel-collector/updater/internal/path"
 	"github.com/observiq/observiq-otel-collector/updater/internal/service"
+	"go.uber.org/zap"
 )
 
 // ServiceStopAction is an action that records that a service was stopped.
@@ -65,9 +66,11 @@ type ServiceUpdateAction struct {
 var _ RollbackableAction = (*ServiceUpdateAction)(nil)
 
 // NewServiceUpdateAction creates a new ServiceUpdateAction
-func NewServiceUpdateAction(tmpDir string) *ServiceUpdateAction {
+func NewServiceUpdateAction(logger *zap.Logger, tmpDir string) *ServiceUpdateAction {
+	namedLogger := logger.Named("service-update-action")
 	return &ServiceUpdateAction{
 		backupSvc: service.NewService(
+			namedLogger,
 			"", // latestDir doesn't matter here
 			service.WithServiceFile(path.BackupServiceFile(path.ServiceFileDir(path.BackupDirFromTempDir(tmpDir)))),
 		),

updater/internal/action/service_action_test.go

@@ -19,6 +19,7 @@ import (
 
 	"github.com/observiq/observiq-otel-collector/updater/internal/service/mocks"
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zaptest"
 )
 
 func TestServiceStartAction(t *testing.T) {
@@ -43,7 +44,7 @@ func TestServiceStopAction(t *testing.T) {
 
 func TestServiceUpdateAction(t *testing.T) {
 	svc := mocks.NewService(t)
-	sua := NewServiceUpdateAction("./testdata")
+	sua := NewServiceUpdateAction(zaptest.NewLogger(t), "./testdata")
 	sua.backupSvc = svc
 
 	svc.On("Update").Once().Return(nil)

updater/internal/file/file.go

@@ -17,14 +17,15 @@ package file
 import (
 	"fmt"
 	"io"
-	"log"
 	"os"
 	"path/filepath"
+
+	"go.uber.org/zap"
 )
 
 // CopyFile copies the file from pathIn to pathOut.
 // If the file does not exist, it is created. If the file does exist, it is truncated before writing.
-func CopyFile(pathIn, pathOut string, overwrite bool) error {
+func CopyFile(logger *zap.Logger, pathIn, pathOut string, overwrite bool) error {
 	pathInClean := filepath.Clean(pathIn)
 
 	// Open the input file for reading.
@@ -35,7 +36,7 @@ func CopyFile(pathIn, pathOut string, overwrite bool) error {
 	defer func() {
 		err := inFile.Close()
 		if err != nil {
-			log.Default().Printf("CopyFile: Failed to close input file: %s", err)
+			logger.Info("Failed to close input file", zap.Error(err))
 		}
 	}()
 
@@ -58,7 +59,7 @@ func CopyFile(pathIn, pathOut string, overwrite bool) error {
 	defer func() {
 		err := outFile.Close()
 		if err != nil {
-			log.Default().Printf("CopyFile: Failed to close output file: %s", err)
+			logger.Info("Failed to close output file", zap.Error(err))
 		}
 	}()