diff --git a/internal/command/agent/logfile.go b/internal/command/agent/logfile.go new file mode 100644 index 0000000000..95ea424550 --- /dev/null +++ b/internal/command/agent/logfile.go @@ -0,0 +1,98 @@ +package agent + +import ( + "os" + "strings" + "sync" +) + +// maxLogSize bounds the log the agent is currently writing to. The directory as +// a whole is pruned when a daemon starts, but that only reaps files nothing has +// touched for a day: the agent runs for days at a time and writes a single log +// for its whole lifetime, so its own log is never a candidate. +const maxLogSize = 128 << 20 // 128MB + +// rotatingFile writes to path, moving the file aside once it has taken +// maxLogSize. Only the previous generation is kept, so the pair costs at most +// twice maxLogSize until the next daemon start prunes them. +type rotatingFile struct { + path string + + mu sync.Mutex + file *os.File + written int64 +} + +func openRotatingFile(path string) (*rotatingFile, error) { + file, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND, 0o600) + if err != nil { + return nil, err + } + + // Resume from the size on disk so restarting the agent against an existing + // log doesn't hand it a fresh budget. + var written int64 + if inf, err := file.Stat(); err == nil { + written = inf.Size() + } + + return &rotatingFile{path: path, file: file, written: written}, nil +} + +func (rf *rotatingFile) Write(p []byte) (int, error) { + rf.mu.Lock() + defer rf.mu.Unlock() + + if rf.written+int64(len(p)) > maxLogSize { + if err := rf.rotate(); err != nil { + return 0, err + } + } + + n, err := rf.file.Write(p) + rf.written += int64(n) + + return n, err +} + +// rotate counts the bytes it has written instead of measuring the file, so a +// log deleted from under the agent is replaced at the next threshold rather +// than growing forever on an unlinked descriptor. +func (rf *rotatingFile) rotate() error { + // Windows refuses to rename an open file. + _ = rf.file.Close() + + if err := os.Rename(rf.path, previousPath(rf.path)); err != nil && !os.IsNotExist(err) { + return err + } + + file, err := os.OpenFile(rf.path, os.O_WRONLY|os.O_CREATE|os.O_TRUNC|os.O_APPEND, 0o600) + if err != nil { + return err + } + + rf.file = file + rf.written = 0 + + return nil +} + +func (rf *rotatingFile) Sync() error { + rf.mu.Lock() + defer rf.mu.Unlock() + + return rf.file.Sync() +} + +func (rf *rotatingFile) Close() error { + rf.mu.Lock() + defer rf.mu.Unlock() + + return rf.file.Close() +} + +// previousPath keeps the .log suffix: fly doctor diag collects agent logs by +// that pattern. +func previousPath(path string) string { + return strings.TrimSuffix(path, ".log") + ".prev.log" +} diff --git a/internal/command/agent/logfile_test.go b/internal/command/agent/logfile_test.go new file mode 100644 index 0000000000..d1dd54641f --- /dev/null +++ b/internal/command/agent/logfile_test.go @@ -0,0 +1,85 @@ +package agent + +import ( + "os" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/require" +) + +// write enough lines to cross the threshold a few times over. +func writeLines(t *testing.T, rf *rotatingFile, line string, count int) { + t.Helper() + + for range count { + n, err := rf.Write([]byte(line)) + require.NoError(t, err) + require.Equal(t, len(line), n) + } +} + +func TestRotatingFileBoundsTheLog(t *testing.T) { + path := filepath.Join(t.TempDir(), "agent.log") + require.NoError(t, os.WriteFile(path, nil, 0o600)) + + rf, err := openRotatingFile(path) + require.NoError(t, err) + defer rf.Close() + + line := strings.Repeat("x", 4096) + "\n" + writeLines(t, rf, line, 3*(maxLogSize/len(line))) + + inf, err := os.Stat(path) + require.NoError(t, err) + require.LessOrEqual(t, inf.Size(), int64(maxLogSize)) + + prev, err := os.Stat(previousPath(path)) + require.NoError(t, err, "the previous generation should be kept") + require.LessOrEqual(t, prev.Size(), int64(maxLogSize)) +} + +func TestRotatingFileResumesFromSizeOnDisk(t *testing.T) { + path := filepath.Join(t.TempDir(), "agent.log") + require.NoError(t, os.WriteFile(path, make([]byte, maxLogSize), 0o600)) + + rf, err := openRotatingFile(path) + require.NoError(t, err) + defer rf.Close() + + writeLines(t, rf, "hello\n", 1) + + prev, err := os.Stat(previousPath(path)) + require.NoError(t, err) + require.Equal(t, int64(maxLogSize), prev.Size()) + + got, err := os.ReadFile(path) + require.NoError(t, err) + require.Equal(t, "hello\n", string(got)) +} + +// The agent kept growing an unlinked descriptor after a user cleared the log +// directory by hand. +func TestRotatingFileReplacesADeletedLog(t *testing.T) { + path := filepath.Join(t.TempDir(), "agent.log") + require.NoError(t, os.WriteFile(path, nil, 0o600)) + + rf, err := openRotatingFile(path) + require.NoError(t, err) + defer rf.Close() + + line := strings.Repeat("x", 4096) + "\n" + writeLines(t, rf, line, maxLogSize/len(line)/2) + require.NoError(t, os.Remove(path)) + + writeLines(t, rf, line, maxLogSize/len(line)) + + inf, err := os.Stat(path) + require.NoError(t, err, "writes should land in a fresh log") + require.LessOrEqual(t, inf.Size(), int64(maxLogSize)) +} + +func TestPreviousPathKeepsTheLogSuffix(t *testing.T) { + require.Equal(t, "/tmp/agent-logs/123.prev.log", previousPath("/tmp/agent-logs/123.log")) +} diff --git a/internal/command/agent/run.go b/internal/command/agent/run.go index 0e72f280d4..4bd2b1afd5 100644 --- a/internal/command/agent/run.go +++ b/internal/command/agent/run.go @@ -77,7 +77,7 @@ func run(ctx context.Context) error { func setupLogger(path string) (logger *log.Logger, close func(), err error) { var out io.Writer if path != "" { - f, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND, 0o600) + f, err := openRotatingFile(path) if err != nil { return nil, nil, err }