From ab4ab0e8f9ead6dde47cc6d82ac61057aac20175 Mon Sep 17 00:00:00 2001 From: Todd Date: Fri, 3 Nov 2023 14:59:42 -0700 Subject: [PATCH] Handle log rotation (#3948) * Handle log rotation --- go.mod | 1 + go.sum | 2 + .../clientcache/cmd/daemon/logfile_test.go | 131 ++++++++++++++++++ internal/clientcache/cmd/daemon/start.go | 42 ++++-- internal/clientcache/cmd/daemon/status.go | 11 +- 5 files changed, 175 insertions(+), 12 deletions(-) create mode 100644 internal/clientcache/cmd/daemon/logfile_test.go diff --git a/go.mod b/go.mod index eda94030c2..00f84e6b40 100644 --- a/go.mod +++ b/go.mod @@ -218,6 +218,7 @@ require ( golang.org/x/time v0.3.0 // indirect google.golang.org/appengine v1.6.8 // indirect google.golang.org/genproto/googleapis/rpc v0.0.0-20231030173426-d783a09b4405 // indirect + gopkg.in/natefinch/lumberjack.v2 v2.2.1 gopkg.in/yaml.v2 v2.4.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index b6eaf65533..c63e9efb0a 100644 --- a/go.sum +++ b/go.sum @@ -914,6 +914,8 @@ gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EV gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI= gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMys= gopkg.in/inconshreveable/log15.v2 v2.0.0-20180818164646-67afb5ed74ec/go.mod h1:aPpfJ7XW+gOuirDoZ8gHhLh3kZ1B08FtV2bbmy7Jv3s= +gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc= +gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc= gopkg.in/square/go-jose.v2 v2.6.0 h1:NGk74WTnPKBNUhNzQX7PYcTLUjoq7mzKk2OKbvwk2iI= gopkg.in/square/go-jose.v2 v2.6.0/go.mod h1:M9dMgbHiYLoDGQrXy7OpJDJWiKiU//h+vD76mk0e1AI= gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw= diff --git a/internal/clientcache/cmd/daemon/logfile_test.go b/internal/clientcache/cmd/daemon/logfile_test.go new file mode 100644 index 0000000000..80293b21c8 --- /dev/null +++ b/internal/clientcache/cmd/daemon/logfile_test.go @@ -0,0 +1,131 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: BUSL-1.1 + +package daemon + +import ( + "bytes" + "context" + "crypto/rand" + "encoding/json" + "fmt" + "io/fs" + "os" + "path/filepath" + "strings" + "sync" + "testing" + + "github.com/hashicorp/boundary/internal/event" + "github.com/hashicorp/go-hclog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestWithEventer(t *testing.T) { + ctx := context.Background() + dir := t.TempDir() + l, err := logFile(ctx, dir, 1) + require.NoError(t, err) + + var logLock sync.Mutex + logger := hclog.New(&hclog.LoggerOptions{ + Output: l, + Level: hclog.Debug, + JSONFormat: false, + Mutex: &logLock, + }) + require.NoError(t, event.InitFallbackLogger(logger)) + + cfg := event.EventerConfig{ + AuditEnabled: false, + ObservationsEnabled: true, + SysEventsEnabled: true, + Sinks: []*event.SinkConfig{ + { + Name: "default", + EventTypes: []event.Type{event.EveryType}, + Format: event.JSONHclogSinkFormat, + Type: event.WriterSink, + WriterConfig: &event.WriterSinkTypeConfig{ + Writer: l, + }, + }, + }, + } + require.NoError(t, event.InitSysEventer(logger, &logLock, "test", event.WithEventerConfig(&cfg))) + + // Measured to have at least 1 record written in a rotated log file. + for i := 0; i < 8129; i++ { + event.WriteSysEvent(ctx, "test.caller", "this is a test event I am writing out.") + } + require.NoError(t, l.Close()) + ret, err := os.ReadDir(dir) + require.NoError(t, err) + require.GreaterOrEqual(t, len(ret), 2) + + t.Run("new logfile valid event", func(t *testing.T) { + out, err := os.ReadFile(filepath.Join(dir, logFileName)) + require.NoError(t, err) + t.Logf("Got output of length %d", len(out)) + jd := json.NewDecoder(bytes.NewReader(out)) + m := make(map[string]interface{}) + assert.NoError(t, jd.Decode(&m), fmt.Sprintf("parsing %q", out)) + }) +} + +func TestRotation(t *testing.T) { + ctx := context.Background() + dir := t.TempDir() + l, err := logFile(ctx, dir, 1) + require.NoError(t, err) + + fi, err := os.Stat(filepath.Join(dir, logFileName)) + require.NoError(t, err) + assert.Zero(t, fi.Size()) + assert.Equal(t, fs.FileMode(0o600), fi.Mode()) + + // write 1 mb and see it all contained in a single log file + toWrite := make([]byte, 1024) + for i := 0; i < 1024; i++ { + rand.Read(toWrite) + _, err := l.Write(toWrite) + require.NoError(t, err) + } + ret, err := os.ReadDir(dir) + require.NoError(t, err) + require.Len(t, ret, 1) + assert.Equal(t, ret[0].Name(), logFileName) + + // write 1 more byte and see that it caused the log file to rotate + _, err = l.Write([]byte("1")) + require.NoError(t, err) + + ret, err = os.ReadDir(dir) + require.NoError(t, err) + // GreaterOrEqual is used here because while backups are compressed, both + // the renamed backup .log and the log.gz files exist + require.GreaterOrEqual(t, len(ret), 2) + assert.True(t, strings.HasPrefix(ret[0].Name(), "cache")) + assert.True(t, strings.HasPrefix(ret[1].Name(), "cache")) + + // write another 1 mb and see a third log file is created + for i := 0; i < 1024; i++ { + rand.Read(toWrite) + _, err := l.Write(toWrite) + require.NoError(t, err) + } + ret, err = os.ReadDir(dir) + require.NoError(t, err) + require.GreaterOrEqual(t, len(ret), 3) + + // and a 4th (3 backups plus the cache.log file) + for i := 0; i < 1024; i++ { + rand.Read(toWrite) + _, err := l.Write(toWrite) + require.NoError(t, err) + } + ret, err = os.ReadDir(dir) + require.NoError(t, err) + require.GreaterOrEqual(t, len(ret), 4) +} diff --git a/internal/clientcache/cmd/daemon/start.go b/internal/clientcache/cmd/daemon/start.go index ea0a4f26f0..b07f937255 100644 --- a/internal/clientcache/cmd/daemon/start.go +++ b/internal/clientcache/cmd/daemon/start.go @@ -21,6 +21,7 @@ import ( "github.com/mitchellh/cli" "github.com/mitchellh/go-homedir" "github.com/posener/complete" + "gopkg.in/natefinch/lumberjack.v2" ) const ( @@ -150,6 +151,10 @@ func (c *StartCommand) Run(args []string) int { if err != nil { return base.CommandCliError } + if err := os.MkdirAll(dotDir, 0o700); err != nil { + c.PrintCliError(err) + return base.CommandCliError + } continueRun, writers, cleanup, err := makeBackground(ctx, dotDir, c.flagBackground) defer func() { @@ -168,18 +173,13 @@ func (c *StartCommand) Run(args []string) int { // TODO: print something out for the spawner to consume in case they can easily // report if the daemon started or not. - logFilePath := filepath.Join(dotDir, logFileName) - logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY, 0o600) + lf, err := logFile(ctx, dotDir, 5) if err != nil { c.PrintCliError(err) return base.CommandCliError } - defer logFile.Close() - if _, err := logFile.Seek(0, io.SeekEnd); err != nil { - c.PrintCliError(err) - return base.CommandCliError - } - writers = append(writers, logFile) + defer lf.Close() + writers = append(writers, lf) cfg := &daemon.Config{ ContextCancel: cancel, @@ -233,6 +233,32 @@ func DefaultDotDirectory(ctx context.Context) (string, error) { return filepath.Join(homeDir, dotDirname), nil } +// logFile returns a log file which is rotated after it reaches the provided +// maximum size in mb before being rotated out. The rotated out log file gets +// a suffix that matches the time that the rotation happened. Up to 3 log files +// are saved as backup. When a new log file is rotated and there is already 3 +// backups created, the oldest one is deleted. +func logFile(ctx context.Context, dotDir string, maxSizeMb int) (io.WriteCloser, error) { + const op = "daemon.logFile" + logFilePath := filepath.Join(dotDir, logFileName) + { + // Ensure the file is created with the desired permissions. + logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY, 0o600) + if err != nil { + return nil, errors.Wrap(ctx, err, op) + } + logFile.Close() + } + + logFile := &lumberjack.Logger{ + Filename: logFilePath, + MaxSize: maxSizeMb, + MaxBackups: 3, + Compress: true, + } + return logFile, nil +} + func makeBackground(ctx context.Context, dotDir string, runBackgroundFlag bool) (bool, []io.Writer, pidCleanup, error) { const op = "daemon.makeBackground" diff --git a/internal/clientcache/cmd/daemon/status.go b/internal/clientcache/cmd/daemon/status.go index 1779d7725d..73fc88967a 100644 --- a/internal/clientcache/cmd/daemon/status.go +++ b/internal/clientcache/cmd/daemon/status.go @@ -109,12 +109,15 @@ func status(ctx context.Context, daemonPath string) (*api.Response, error) { if err != nil { return nil, fmt.Errorf("Error creating a new API client: %w", err) } - addr := daemon.SocketAddress(daemonPath) - _, err = os.Stat(strings.TrimPrefix(addr, "unix://")) - if strings.HasPrefix(addr, "unix://") && err != nil { + addr, err := daemon.SocketAddress(daemonPath) + if err != nil { + return nil, fmt.Errorf("Error getting socket address: %w", err) + } + _, err = os.Stat(addr.Path) + if addr.Scheme == "unix" && err != nil { return nil, errDaemonNotRunning } - if err := client.SetAddr(addr); err != nil { + if err := client.SetAddr(addr.String()); err != nil { return nil, fmt.Errorf("Error when setting the client's address: %w", err) } // Because this is using the real lib it can pick up from stored locations