From afed925404c0bb9ca98914aa756ce269a78e5365 Mon Sep 17 00:00:00 2001 From: Codescribe Date: Tue, 21 Apr 2026 17:40:51 -0400 Subject: [PATCH] log: persist internal runtime logs to disk MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add file-backed persistence to the internal logWriter so runtime logs survive service restarts. When internal logging is enabled (CD mode, no explicit log_path), writes are teed to both the existing in-memory ring buffer and a rotated file on disk (ctrld.log in the home directory). File rotation: 5MB max with 1 backup (ctrld.log.1), so max ~10MB on disk. Log view/send now reads from the persisted files (including backup) to provide complete history across restarts. Live tail continues to use the in-memory subscriber mechanism unchanged. Activation: same conditions as existing internal logging — CD mode only, no log_path configured. No new config options or dependencies. --- cmd/cli/log_writer.go | 199 ++++++++++++++++++++++++++++++++++++- cmd/cli/log_writer_test.go | 125 +++++++++++++++++++++++ 2 files changed, 323 insertions(+), 1 deletion(-) diff --git a/cmd/cli/log_writer.go b/cmd/cli/log_writer.go index f84dcdf..609b1d6 100644 --- a/cmd/cli/log_writer.go +++ b/cmd/cli/log_writer.go @@ -6,6 +6,7 @@ import ( "fmt" "io" "os" + "path/filepath" "strings" "sync" "time" @@ -22,6 +23,9 @@ const ( logWriterSentInterval = time.Minute logWriterInitEndMarker = "\n\n=== INIT_END ===\n\n" logWriterLogEndMarker = "\n\n=== LOG_END ===\n\n" + + logFileName = "ctrld.log" + logFileMaxSize = 1024 * 1024 * 5 // 5 MB ) type logViewResponse struct { @@ -44,11 +48,18 @@ type logSubscriber struct { } // logWriter is an internal buffer to keep track of runtime log when no logging is enabled. +// When a file path is configured via setLogFile, writes are also persisted to +// a rotated file on disk (max logFileMaxSize, 1 backup) so logs survive restarts. type logWriter struct { mu sync.Mutex buf bytes.Buffer size int subscribers []*logSubscriber + + // File persistence fields. + logFile *os.File + logFilePath string + logFileSize int64 } // newLogWriter creates an internal log writer. @@ -67,6 +78,80 @@ func newLogWriterWithSize(size int) *logWriter { return lw } +// setLogFile configures file-backed persistence for the log writer. +// The directory is created if it does not exist. An existing file is +// opened in append mode and its current size is tracked for rotation. +func (lw *logWriter) setLogFile(path string) error { + dir := filepath.Dir(path) + if err := os.MkdirAll(dir, 0750); err != nil { + return fmt.Errorf("creating log directory: %w", err) + } + f, err := os.OpenFile(path, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0600) + if err != nil { + return fmt.Errorf("opening log file: %w", err) + } + st, err := f.Stat() + if err != nil { + f.Close() + return fmt.Errorf("stat log file: %w", err) + } + lw.mu.Lock() + defer lw.mu.Unlock() + lw.logFile = f + lw.logFilePath = path + lw.logFileSize = st.Size() + return nil +} + +// rotateLogFile rotates the current log file to a .1 backup. +// It returns true if lw.logFile is usable after the call, false otherwise. +// Must be called with lw.mu held. +func (lw *logWriter) rotateLogFile() bool { + if lw.logFile == nil { + return false + } + lw.logFile.Close() + backupPath := lw.logFilePath + ".1" + // Best effort: rename current to backup (overwrites old backup). + os.Rename(lw.logFilePath, backupPath) + f, err := os.OpenFile(lw.logFilePath, os.O_CREATE|os.O_RDWR|os.O_TRUNC, 0600) + if err != nil { + // If we can't reopen, disable file logging. + lw.logFile = nil + lw.logFileSize = 0 + return false + } + lw.logFile = f + lw.logFileSize = 0 + return true +} + +// closeLogFile closes the backing file if open. +func (lw *logWriter) closeLogFile() { + lw.mu.Lock() + defer lw.mu.Unlock() + if lw.logFile != nil { + lw.logFile.Close() + lw.logFile = nil + } +} + +// logFilePaths returns the paths to the current log file and its backup +// (if they exist) for inclusion in log send payloads. +func (lw *logWriter) logFilePaths() (current, backup string) { + lw.mu.Lock() + defer lw.mu.Unlock() + if lw.logFilePath == "" { + return "", "" + } + current = lw.logFilePath + bp := lw.logFilePath + ".1" + if _, err := os.Stat(bp); err == nil { + backup = bp + } + return current, backup +} + // Subscribe returns a channel that receives new log data as it's written, // and an unsubscribe function to clean up when done. func (lw *logWriter) Subscribe() (<-chan []byte, func()) { @@ -131,6 +216,16 @@ func (lw *logWriter) Write(p []byte) (int, error) { } } + // Write to backing file if configured. + if lw.logFile != nil { + needsRotation := lw.logFileSize+int64(len(p)) > logFileMaxSize + if !needsRotation || lw.rotateLogFile() { + if n, err := lw.logFile.Write(p); err == nil { + lw.logFileSize += int64(n) + } + } + } + // If writing p causes overflows, discard old data. if lw.buf.Len()+len(p) > lw.size { buf := lw.buf.Bytes() @@ -168,6 +263,12 @@ func (p *prog) initLogging(backup bool) { p.initInternalLogging(logWriters) } +// internalLogFilePath returns the path for persisted internal logs. +// The file lives in the ctrld home directory alongside other runtime state. +func internalLogFilePath() string { + return absHomeDir(logFileName) +} + // initInternalLogging performs internal logging if there's no log enabled. func (p *prog) initInternalLogging(writers []io.Writer) { if !p.needInternalLogging() { @@ -178,6 +279,14 @@ func (p *prog) initInternalLogging(writers []io.Writer) { p.internalLogWriter = newLogWriter() p.internalLogSent = time.Now().Add(-logWriterSentInterval) p.internalWarnLogWriter = newSmallLogWriter() + // Persist internal logs to disk so they survive restarts. + if path := internalLogFilePath(); path != "" { + if err := p.internalLogWriter.setLogFile(path); err != nil { + mainLog.Load().Warn().Err(err).Msg("could not enable persistent internal logging") + } else { + mainLog.Load().Notice().Msgf("internal log file: %s", path) + } + } }) p.mu.Lock() lw := p.internalLogWriter @@ -232,7 +341,15 @@ func (p *prog) logReader() (*logReader, error) { if wlw == nil { return nil, errors.New("nil internal warn log writer") } - // Normal log content. + + // If we have a persisted log file, read from disk (includes data + // from previous runs that the in-memory buffer wouldn't have). + current, backup := lw.logFilePaths() + if current != "" { + return p.logReaderFromFiles(current, backup, wlw) + } + + // Fall back to in-memory buffer. lw.mu.Lock() lwReader := bytes.NewReader(lw.buf.Bytes()) lwSize := lw.buf.Len() @@ -268,3 +385,83 @@ func (p *prog) logReader() (*logReader, error) { } return lr, nil } + +// logReaderFromFiles builds a logReader that concatenates the backup file +// (if it exists), the current log file, and the in-memory warn log buffer. +func (p *prog) logReaderFromFiles(current, backup string, wlw *logWriter) (*logReader, error) { + var rcs []io.ReadCloser + var totalSize int64 + + closeAll := func() { + for _, rc := range rcs { + rc.Close() + } + } + + // Read backup file first (older entries). + if backup != "" { + if bf, err := os.Open(backup); err == nil { + if st, err := bf.Stat(); err == nil { + totalSize += st.Size() + } + rcs = append(rcs, bf) + } + } + + // Read current file. + cf, err := os.Open(current) + if err != nil { + closeAll() + return nil, fmt.Errorf("opening current log file: %w", err) + } + if st, err := cf.Stat(); err == nil { + totalSize += st.Size() + } + rcs = append(rcs, cf) + + // Append warn log content from memory. + wlw.mu.Lock() + warnData := make([]byte, wlw.buf.Len()) + copy(warnData, wlw.buf.Bytes()) + wlw.mu.Unlock() + + if len(warnData) > 0 { + rcs = append(rcs, io.NopCloser(bytes.NewReader([]byte(logWriterLogEndMarker)))) + rcs = append(rcs, io.NopCloser(bytes.NewReader(warnData))) + totalSize += int64(len(logWriterLogEndMarker) + len(warnData)) + } + + if totalSize == 0 { + closeAll() + return nil, errors.New("internal log is empty") + } + + readers := make([]io.Reader, len(rcs)) + closers := make([]io.Closer, len(rcs)) + for i, rc := range rcs { + readers[i] = rc + closers[i] = rc + } + combined := io.MultiReader(readers...) + lr := &logReader{ + r: &multiCloser{Reader: combined, closers: closers}, + size: totalSize, + } + return lr, nil +} + +// multiCloser wraps an io.Reader and closes multiple underlying closers. +type multiCloser struct { + io.Reader + closers []io.Closer +} + +func (mc *multiCloser) Close() error { + var firstErr error + for _, c := range mc.closers { + if err := c.Close(); err != nil && firstErr == nil { + firstErr = err + } + } + return firstErr +} diff --git a/cmd/cli/log_writer_test.go b/cmd/cli/log_writer_test.go index 5336d4e..f6d1f94 100644 --- a/cmd/cli/log_writer_test.go +++ b/cmd/cli/log_writer_test.go @@ -1,6 +1,8 @@ package cli import ( + "os" + "path/filepath" "strings" "sync" "testing" @@ -83,3 +85,126 @@ func Test_logWriter_MarkerInitEnd(t *testing.T) { t.Fatalf("unexpected log content: %s", lw.buf.String()) } } + +func Test_logWriter_SetLogFile(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "test.log") + lw := newLogWriterWithSize(logWriterSize) + if err := lw.setLogFile(path); err != nil { + t.Fatalf("setLogFile: %v", err) + } + defer lw.closeLogFile() + + msg := "hello file\n" + lw.Write([]byte(msg)) + + // Verify data in memory buffer. + if lw.buf.String() != msg { + t.Fatalf("buffer: got %q, want %q", lw.buf.String(), msg) + } + // Verify data on disk. + data, err := os.ReadFile(path) + if err != nil { + t.Fatalf("ReadFile: %v", err) + } + if string(data) != msg { + t.Fatalf("file: got %q, want %q", data, msg) + } +} + +func Test_logWriter_FileRotation(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "test.log") + // Use a tiny max size to trigger rotation quickly. + lw := newLogWriterWithSize(logWriterSize) + if err := lw.setLogFile(path); err != nil { + t.Fatalf("setLogFile: %v", err) + } + defer lw.closeLogFile() + + // Write enough to exceed logFileMaxSize. + chunk := strings.Repeat("X", 1024) + "\n" + written := 0 + for written < logFileMaxSize+1024 { + lw.Write([]byte(chunk)) + written += len(chunk) + } + + // Backup file should exist. + backupPath := path + ".1" + if _, err := os.Stat(backupPath); os.IsNotExist(err) { + t.Fatal("expected backup file to exist after rotation") + } + + // Current file should be smaller than max (it was rotated). + st, err := os.Stat(path) + if err != nil { + t.Fatalf("stat current: %v", err) + } + if st.Size() > logFileMaxSize { + t.Fatalf("current file too large after rotation: %d", st.Size()) + } +} + +func Test_logWriter_FilePaths(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "test.log") + lw := newLogWriterWithSize(logWriterSize) + + // No file configured. + c, b := lw.logFilePaths() + if c != "" || b != "" { + t.Fatalf("expected empty paths, got %q %q", c, b) + } + + if err := lw.setLogFile(path); err != nil { + t.Fatalf("setLogFile: %v", err) + } + defer lw.closeLogFile() + + // Current exists, no backup yet. + c, b = lw.logFilePaths() + if c != path { + t.Fatalf("current: got %q, want %q", c, path) + } + if b != "" { + t.Fatalf("backup should be empty, got %q", b) + } + + // Create a backup file manually. + os.WriteFile(path+".1", []byte("old"), 0600) + _, b = lw.logFilePaths() + if b != path+".1" { + t.Fatalf("backup: got %q, want %q", b, path+".1") + } +} + +func Test_logWriter_FileAppendOnRestart(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "test.log") + + // Simulate first run. + lw1 := newLogWriterWithSize(logWriterSize) + if err := lw1.setLogFile(path); err != nil { + t.Fatalf("setLogFile: %v", err) + } + lw1.Write([]byte("run1\n")) + lw1.closeLogFile() + + // Simulate second run (restart) — file should be appended. + lw2 := newLogWriterWithSize(logWriterSize) + if err := lw2.setLogFile(path); err != nil { + t.Fatalf("setLogFile: %v", err) + } + lw2.Write([]byte("run2\n")) + lw2.closeLogFile() + + data, err := os.ReadFile(path) + if err != nil { + t.Fatalf("ReadFile: %v", err) + } + want := "run1\nrun2\n" + if string(data) != want { + t.Fatalf("file: got %q, want %q", data, want) + } +}