package cli import ( "bytes" "encoding/json" "io" "os" "regexp" "strings" "sync" "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" "github.com/Control-D-Inc/ctrld" ) // Log writer constants for buffer management and log formatting const ( // logWriterSize is the default buffer size for log writers // This provides sufficient space for runtime logs without excessive memory usage logWriterSize = 1024 * 1024 * 5 // 5 MB // logWriterSmallSize is used for memory-constrained environments // This reduces memory footprint while still maintaining log functionality logWriterSmallSize = 1024 * 1024 * 1 // 1 MB // logWriterInitialSize is the initial buffer allocation // This provides immediate space for early log entries logWriterInitialSize = 32 * 1024 // 32 KB // logWriterSentInterval controls how often logs are sent to external systems // This balances real-time logging with system performance logWriterSentInterval = time.Minute // logWriterInitEndMarker marks the end of initialization logs // This helps separate startup logs from runtime logs logWriterInitEndMarker = "\n\n=== INIT_END ===\n\n" // logWriterLogEndMarker marks the end of log sections // This provides clear boundaries for log parsing and analysis logWriterLogEndMarker = "\n\n=== LOG_END ===\n\n" logFileName = "ctrld.log" ) // Custom level encoders that handle NOTICE level // Since NOTICE and WARN share the same numeric value (1), we handle them specially // in the encoder to display NOTICE messages with the "NOTICE" prefix. // Note: WARN messages will also display as "NOTICE" because they share the same level value. // This is the intended behavior for visual distinction. // noticeLevelEncoder provides custom level encoding for NOTICE level // This ensures NOTICE messages are clearly distinguished from other log levels func noticeLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { switch l { case ctrld.NoticeLevel: enc.AppendString("NOTICE") default: zapcore.CapitalLevelEncoder(l, enc) } } // noticeColorLevelEncoder provides colored level encoding for NOTICE level // This uses cyan color to make NOTICE messages visually distinct in terminal output func noticeColorLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { switch l { case ctrld.NoticeLevel: enc.AppendString("\x1b[36mNOTICE\x1b[0m") // Cyan color for NOTICE default: zapcore.CapitalColorLevelEncoder(l, enc) } } // logViewResponse represents the response structure for log viewing requests // This provides a consistent JSON format for log data retrieval type logViewResponse struct { Data string `json:"data"` } // logSentResponse represents the response structure for log sending operations // This includes size information and error details for debugging type logSentResponse struct { Size int64 `json:"size"` Error string `json:"error"` } // logSubscriber represents a subscriber to live log output. type logSubscriber struct { ch chan []byte } // logWriter is an internal buffer to keep track of runtime log when no logging is enabled. // When a file is configured via setLogFile, writes also go to that file, which // rotates within its budget, so logs survive restarts. type logWriter struct { mu sync.Mutex buf bytes.Buffer size int subscribers []*logSubscriber file *rotatingFile } // newLogWriter creates an internal log writer. // This provides the default log writer with standard buffer size func newLogWriter() *logWriter { return newLogWriterWithSize(logWriterSize) } // newSmallLogWriter creates an internal log writer with small buffer size. // This is used in memory-constrained environments or for temporary logging func newSmallLogWriter() *logWriter { return newLogWriterWithSize(logWriterSmallSize) } // newLogWriterWithSize creates an internal log writer with a given buffer size. // This allows customization of log buffer size based on specific requirements func newLogWriterWithSize(size int) *logWriter { return &logWriter{size: size} } // setLogFile persists the stream to a file that rotates within the budget. func (lw *logWriter) setLogFile(path string, budget logBudget) error { rf, err := newRotatingFile(path, budget, nil) if err != nil { return err } rf.onRotate = emitLogRotated lw.mu.Lock() defer lw.mu.Unlock() lw.file = rf return nil } // closeLogFile closes the backing file if open. func (lw *logWriter) closeLogFile() { lw.mu.Lock() defer lw.mu.Unlock() if lw.file == nil { return } lw.file.close() lw.file = nil } // rotating returns the backing file, so a caller works with the file itself // instead of one pass-through method for each of its calls. A stream that // keeps its lines in memory only has no file. func (lw *logWriter) rotating() *rotatingFile { lw.mu.Lock() defer lw.mu.Unlock() return lw.file } // bufferedBytes copies the memory buffer, so a reader of the copy holds no // writer lock while it works. func (lw *logWriter) bufferedBytes() []byte { lw.mu.Lock() defer lw.mu.Unlock() buffered := make([]byte, lw.buf.Len()) copy(buffered, lw.buf.Bytes()) return buffered } // 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()) { lw.mu.Lock() defer lw.mu.Unlock() sub := &logSubscriber{ch: make(chan []byte, 256)} lw.subscribers = append(lw.subscribers, sub) unsub := func() { lw.mu.Lock() defer lw.mu.Unlock() for i, s := range lw.subscribers { if s == sub { lw.subscribers = append(lw.subscribers[:i], lw.subscribers[i+1:]...) close(sub.ch) break } } } return sub.ch, unsub } // tailLastLines returns the last n lines from the current buffer. func (lw *logWriter) tailLastLines(n int) []byte { lw.mu.Lock() defer lw.mu.Unlock() data := lw.buf.Bytes() if n <= 0 || len(data) == 0 { return nil } // Find the last n newlines from the end. count := 0 pos := len(data) for pos > 0 { pos-- if data[pos] == '\n' { count++ if count == n+1 { pos++ // move past this newline break } } } result := make([]byte, len(data)-pos) copy(result, data[pos:]) return result } // Write implements io.Writer interface for logWriter func (lw *logWriter) Write(p []byte) (int, error) { // The file takes the line outside lw.mu: it holds its own lock, and it // reports its rotation with an event that comes back through this writer. // A file error must not stop the memory buffer, which is the fallback for // the log readers. if rf := lw.rotating(); rf != nil { _, _ = rf.Write(p) } return lw.writeStreams(p) } // writeStreams feeds the subscribers and the memory buffer. // This manages buffer overflow by discarding old data while preserving important markers func (lw *logWriter) writeStreams(p []byte) (int, error) { lw.mu.Lock() defer lw.mu.Unlock() // Fan-out to subscribers (non-blocking). if len(lw.subscribers) > 0 { cp := make([]byte, len(p)) copy(cp, p) for _, sub := range lw.subscribers { select { case sub.ch <- cp: default: // Drop if subscriber is slow to avoid blocking the logger. } } } // If writing p causes overflows, discard old data. // This prevents unbounded memory growth while maintaining recent logs if lw.buf.Len()+len(p) > lw.size { buf := lw.buf.Bytes() haveEndMarker := false // If there's init end marker already, preserve the data til the marker. // This ensures initialization logs are always available for debugging if idx := bytes.LastIndex(buf, []byte(logWriterInitEndMarker)); idx >= 0 { buf = buf[:idx+len(logWriterInitEndMarker)] haveEndMarker = true } else { // Otherwise, preserve the initial size data. buf = buf[:logWriterInitialSize] if idx := bytes.LastIndex(buf, []byte("\n")); idx != -1 { buf = buf[:idx] } } lw.buf.Reset() lw.buf.Write(buf) if !haveEndMarker { lw.buf.WriteString(logWriterInitEndMarker) // indicate that the log was truncated. } } // If p is bigger than buffer size, truncate p by half until its size is smaller. for len(p)+lw.buf.Len() > lw.size { p = p[len(p)/2:] } return lw.buf.Write(p) } // emitLogRotated logs a rotation. The file that rotated guards this call, // because the event is a line that can rotate that file again. A rotation // that could not move the file keeps the lines it holds, so it earns a // warning instead of the normal report. func emitLogRotated(r logRotation) { event := journal(mainLog.Load().Info()) message := "Log rotated" if r.err != nil { event = journal(mainLog.Load().Warn()).Err(r.err) message = "Log rotation failed" } event = event.Str("file", r.file).Int64("bytes_written", r.bytesWritten) // A file that holds a header only carries no event, and the year 1 of the // zero time reads as a wrong date. if !r.firstWrite.IsZero() { event = event.Time("first_event_at", r.firstWrite) } if !r.lastWrite.IsZero() { event = event.Time("last_event_at", r.lastWrite) } event.Int("backups", r.backups).Msg(message) } // initLogging initializes global logging setup. func (p *prog) initLogging(backup bool) { logCores := initLoggingWithBackup(backup) // Initializing internal logging after global logging. p.initInternalLogging(logCores) p.logger.Store(mainLog.Load()) if rf := logPathFile.Load(); rf != nil { p.refreshLogHeader() if err := rf.writeHeader(); err != nil { p.Warn().Err(err).Msg("Could not write log header") } } // A start-time backup happens before the logger reaches the new file, so // its event waits here for a logger that can report it. if record := pendingLogPathRotation.Swap(nil); record != nil { emitLogRotated(*record) } } // initLoggingAfterProvisioning opens the internal streams of a run whose // resolver UID came from the provisioning token. The first logging setup ran // before that UID was known, so it opened no debug file and no journal. func (p *prog) initLoggingAfterProvisioning() { if !p.needInternalLogging() { return } if lw, _ := p.internalWriters(); lw != nil { return } p.initLogging(false) } // switchLogPath moves the logging of this run to the log_path that the API // config set. The header of the new file leads it, the lines of an earlier // local log_path file follow that header, and the internal streams close, // because a run with a log_path keeps no internal files. A run without a local // log_path carries no lines: its history stays in the internal debug stream, // which this call closes. func (p *prog) switchLogPath(oldLogPath, newLogPath string) { // After processCDFlags, log config may change, so reset mainLog and re-init logging. mainLog.Store(&ctrld.Logger{Logger: zap.NewNop()}) carried := carriedLogLines(oldLogPath, newLogPath) p.initLogging(false) p.carryLogLines(carried) } // carriedLogLines reads the lines of the old log_path file and empties the new // file, so the header of the new file leads it. It drops the header lines of // the old file, because each of them names the old file. func carriedLogLines(oldLogPath, newLogPath string) []byte { buf, err := os.ReadFile(oldLogPath) if err != nil { return nil } if err := os.Remove(newLogPath); err != nil && !os.IsNotExist(err) { mainLog.Load().Warn().Err(err).Msg("could not clear the new log file") return nil } return withoutLogHeaderLines(buf) } // carryLogLines appends the lines of the old log_path file below the header of // the new one. func (p *prog) carryLogLines(lines []byte) { if len(lines) == 0 { return } rf := logPathFile.Load() if rf == nil { return } if _, err := rf.Write(lines); err != nil { p.Warn().Err(err).Msg("Could not copy old log file") } } // withoutLogHeaderLines removes every header line of a log file. func withoutLogHeaderLines(buf []byte) []byte { var kept bytes.Buffer for _, line := range bytes.SplitAfter(buf, []byte("\n")) { if isLogHeaderLine(line) { continue } kept.Write(line) } return kept.Bytes() } // isLogHeaderLine reports whether one line of a log file is a header line. func isLogHeaderLine(line []byte) bool { var parsed struct { Message string `json:"message"` } if err := json.Unmarshal(bytes.TrimSpace(line), &parsed); err != nil { return false } return parsed.Message == logHeaderMessage } // initInternalLogging performs internal logging if there's no log enabled. func (p *prog) initInternalLogging(externalCores []zapcore.Core) { if !p.needInternalLogging() { // A log_path that the API set takes over from the internal files. p.closeInternalLogs() return } headersWritten := false var headerRotations []logRotation p.initInternalLogWriterOnce.Do(func() { // mainLog, not p.logger: a test drives this setup on a bare prog. mainLog.Load().Notice().Msg("Internal logging enabled") p.internalLogWriter = newLogWriter() p.internalJournalWriter = newSmallLogWriter() p.openInternalLogFiles() // A restart appends to the file it finds, so the header marks the // point where this run starts. p.refreshLogHeader() headerRotations = p.writeLogHeaders() headersWritten = true }) lw, jlw := p.internalWriters() // Create zap cores for different writers cores := make([]zapcore.Core, 0, len(externalCores)+2) cores = append(cores, externalCores...) // Run the internal logging at debug level, so we could // have enough information for troubleshooting. The journal core keeps // the lines that survive a restart. cores = append(cores, newHumanReadableZapCore(lw, zapcore.DebugLevel), newJournalCore(jlw)) // Create a multi-core logger mainLog.Store(&ctrld.Logger{Logger: zap.New(zapcore.NewTee(cores...))}) // A header that crossed the budget rotated its file before the logger // reached the files, so its event waits for this logger. for _, rotated := range headerRotations { emitLogRotated(rotated) } if headersWritten { return } // A later call reaches a changed config, so the stored bytes need the new // values. The files keep the header they already hold. p.applyDebugLogBudget(debugLogBudget(&p.cfg.Service)) p.refreshLogHeader() } // applyDebugLogBudget gives the open debug files the limits of the config that // runs now. The files open before the API config arrives, and a managed config // refresh can change the limits with no restart. Only the internal file gets a // prune: ctrld owns its name, while log_path can name a file in a directory // that holds the files of other programs. func (p *prog) applyDebugLogBudget(budget logBudget) { if debugWriter, _ := p.internalWriters(); debugWriter != nil { if rf := debugWriter.rotating(); rf != nil { rf.setBudget(budget) pruneNumberedBackups(rf.currentPath(), budget.backups) } } if rf := logPathFile.Load(); rf != nil { rf.setBudget(budget) } } // openInternalLogFiles persists both internal streams, so they survive a // restart. func (p *prog) openInternalLogFiles() { _, journalBudget := logBudgets() openInternalLogFile(p.internalLogWriter, absHomeDir(logFileName), debugLogBudget(&p.cfg.Service), "internal") openInternalLogFile(p.internalJournalWriter, absHomeDir(journalLogFileName), journalBudget, "journal") } // openInternalLogFile persists one internal stream. A stream whose file cannot // open keeps its lines in memory. Only these files get a prune: ctrld owns // their names, while log_path can name a file in a directory that holds the // files of other programs. func openInternalLogFile(lw *logWriter, path string, budget logBudget, name string) { pruneNumberedBackups(path, budget.backups) if err := lw.setLogFile(path, budget); err != nil { mainLog.Load().Warn().Err(err).Msgf("Could not enable persistent %s logging", name) return } mainLog.Load().Notice().Msgf("%s log file: %s", name, path) } // internalWriters returns the debug stream and the journal stream. Both stay // nil until initInternalLogging opens them, and outside cd mode. func (p *prog) internalWriters() (debugWriter, journalWriter *logWriter) { p.mu.Lock() defer p.mu.Unlock() return p.internalLogWriter, p.internalJournalWriter } // openLogFiles returns the files that this run writes, debug first. A stream // that keeps its lines in memory only has no file, and log_path belongs to // this list although no internal writer owns it. func (p *prog) openLogFiles() []*rotatingFile { debugWriter, journalWriter := p.internalWriters() files := make([]*rotatingFile, 0, 3) for _, writer := range []*logWriter{debugWriter, journalWriter} { if writer == nil { continue } if rf := writer.rotating(); rf != nil { files = append(files, rf) } } if rf := logPathFile.Load(); rf != nil { files = append(files, rf) } return files } // closeInternalLogs closes both internal files, so a stop leaves no open // handle behind. func (p *prog) closeInternalLogs() { debugWriter, journalWriter := p.internalWriters() for _, writer := range []*logWriter{debugWriter, journalWriter} { if writer == nil { continue } writer.closeLogFile() } } // needInternalLogging reports whether prog needs to run internal logging. func (p *prog) needInternalLogging() bool { // Do not run in silent mode: the user explicitly asked for no logging, so // ctrld must not create or write the persisted internal log file (nor reset // the global level back to debug). See https://github.com/Control-D-Inc/ctrld/issues/320. if silent { return false } // Do not run in non-cd mode. if cdUID == "" { return false } // Do not run if there's already log file. if p.cfg.Service.LogPath != "" { return false } return true } // newHumanReadableZapCore creates a zap core optimized for human-readable log output. // // Features: // - Uses development encoder configuration for enhanced readability // - Console encoding with colored log levels for easy visual scanning // - Millisecond precision timestamps in human-friendly format // - Structured field output with clear key-value pairs // - Ideal for development, debugging, and interactive terminal sessions // // Parameters: // - w: The output writer (e.g., os.Stdout, file, buffer) // - level: Minimum log level to capture (e.g., Debug, Info, Warn, Error) // // Returns a zapcore.Core configured for human consumption. func newHumanReadableZapCore(w io.Writer, level zapcore.Level) zapcore.Core { encoderConfig := zap.NewDevelopmentEncoderConfig() encoderConfig.TimeKey = "time" encoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.StampMilli) encoderConfig.EncodeLevel = noticeColorLevelEncoder encoder := zapcore.NewConsoleEncoder(encoderConfig) return zapcore.NewCore(encoder, zapcore.AddSync(w), level) } // newMachineFriendlyZapCore creates a zap core optimized for machine processing and log aggregation. // // Features: // - Uses production encoder configuration for consistent, parseable output // - Console encoding with non-colored log levels for log parsing tools // - Millisecond precision timestamps in ISO-like format // - Structured field output optimized for log aggregation systems // - Ideal for production environments, log shipping, and automated analysis // // Parameters: // - w: The output writer (e.g., os.Stdout, file, buffer) // - level: Minimum log level to capture (e.g., Debug, Info, Warn, Error) // // Returns a zapcore.Core configured for machine consumption and log aggregation. func newMachineFriendlyZapCore(w io.Writer, level zapcore.Level) zapcore.Core { encoderConfig := zap.NewProductionEncoderConfig() encoderConfig.TimeKey = "time" encoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.StampMilli) encoderConfig.EncodeLevel = noticeLevelEncoder encoder := zapcore.NewConsoleEncoder(encoderConfig) return zapcore.NewCore(encoder, zapcore.AddSync(w), level) } // ansiRegex is a regular expression to match ANSI color codes. var ansiRegex = regexp.MustCompile(`\x1b\[[0-9;]*m`) // newLogReader creates a reader for log buffer content with optional ANSI color stripping. // // This function provides flexible log content access by allowing consumers to choose // between raw log data (with ANSI color codes) or stripped content (without color codes). // The color stripping is useful when logs need to be processed by tools that don't // handle ANSI escape sequences properly, or when storing logs in plain text format. // // Parameters: // - buf: The log buffer containing the log data to read // - stripColor: If true, strips ANSI color codes from the log content; // if false, returns raw log content with color codes preserved // // Returns an io.Reader that provides access to the processed log content. func newLogReader(buf *bytes.Buffer, stripColor bool) io.Reader { if stripColor { return newANSIStripReader(strings.NewReader(buf.String())) } return strings.NewReader(buf.String()) }