diff --git a/.gitignore b/.gitignore index e9121bf..290ea92 100644 --- a/.gitignore +++ b/.gitignore @@ -18,3 +18,4 @@ ctrld.exe # Local planning artifacts - never commit /SPEC.md /tasks/ +/SPEC-*.md diff --git a/cmd/cli/cli.go b/cmd/cli/cli.go index 870d5be..7e86915 100644 --- a/cmd/cli/cli.go +++ b/cmd/cli/cli.go @@ -49,7 +49,6 @@ const selfCheckInternalTestDomain = "ctrld" + loopTestDomain const ( windowsForwardersFilename = ".forwarders.txt" oldBinSuffix = "_previous" - oldLogSuffix = ".1" msgExit = "$$EXIT$$" ) @@ -1497,6 +1496,8 @@ func fieldErrorMsg(fe validator.FieldError) string { return fmt.Sprintf("minimum len: %q", fe.Param()) case "gte": return fmt.Sprintf("must be greater than or equal to: %s", fe.Param()) + case "lte": + return fmt.Sprintf("must be less than or equal to: %s", fe.Param()) case "cidr": return fmt.Sprintf("invalid value: %s", fe.Value()) case "required_unless", "required": diff --git a/cmd/cli/commands.go b/cmd/cli/commands.go index 9b057b4..5eee98f 100644 --- a/cmd/cli/commands.go +++ b/cmd/cli/commands.go @@ -36,11 +36,52 @@ import ( // dialSocketControlServerTimeout is the default timeout to wait when ping control server. const dialSocketControlServerTimeout = 30 * time.Second +// logRequestPath adds the query that makes the control server read every log +// file, not only the newest debug bytes. +func logRequestPath(path string, full bool) string { + if !full { + return path + } + return path + "?full=1" +} + +// removeLogFiles deletes the log files of this installation and returns what +// it could not remove. A missing file is not an error. +func removeLogFiles(logPath string, backups int, internalPaths []string) []error { + for _, path := range internalPaths { + pruneNumberedBackups(path, 0) + } + var errs []error + for _, path := range logFilesToRemove(logPath, backups, internalPaths) { + if err := os.Remove(path); err != nil && !os.IsNotExist(err) { + errs = append(errs, fmt.Errorf("remove %s: %w", path, err)) + } + } + return errs +} + +// logFilesToRemove names the log files of this installation. The log_path +// backups come from the configured count, because log_path can name a file in +// a directory that holds the files of other programs, and a scan of that +// directory would take their files too. An empty logPath leaves the internal +// files alone. +func logFilesToRemove(logPath string, backups int, internalPaths []string) []string { + var paths []string + if logPath != "" { + paths = append(paths, logPath) + for index := 1; index <= backups; index++ { + paths = append(paths, fmt.Sprintf("%s.%d", logPath, index)) + } + } + return append(paths, internalPaths...) +} + func initLogCmd() *cobra.Command { warnRuntimeLoggingNotEnabled := func() { mainLog.Load().Warn().Msg("runtime debug logging is not enabled") mainLog.Load().Warn().Msg(`ctrld may be running without "--cd" flag or logging is already enabled`) } + var sendFullLogs bool logSendCmd := &cobra.Command{ Use: "send", Short: "Send runtime debug logs to ControlD", @@ -68,7 +109,7 @@ func initLogCmd() *cobra.Command { mainLog.Load().Fatal().Err(err).Msg("failed to find ctrld home dir") } cc := newControlClient(filepath.Join(dir, ctrldControlUnixSock)) - resp, err := cc.post(sendLogsPath, nil) + resp, err := cc.post(logRequestPath(sendLogsPath, sendFullLogs), nil) if err != nil { mainLog.Load().Fatal().Err(err).Msg("failed to send logs") } @@ -94,6 +135,9 @@ func initLogCmd() *cobra.Command { } }, } + logSendCmd.Flags().BoolVar(&sendFullLogs, "full", false, "Send every log file, not only the newest 10 MB of debug") + + var viewFullLogs bool logViewCmd := &cobra.Command{ Use: "view", Short: "View current runtime debug logs", @@ -121,7 +165,7 @@ func initLogCmd() *cobra.Command { mainLog.Load().Fatal().Err(err).Msg("failed to find ctrld home dir") } cc := newControlClient(filepath.Join(dir, ctrldControlUnixSock)) - resp, err := cc.post(viewLogsPath, nil) + resp, err := cc.post(logRequestPath(viewLogsPath, viewFullLogs), nil) if err != nil { mainLog.Load().Fatal().Err(err).Msg("failed to get logs") } @@ -148,6 +192,8 @@ func initLogCmd() *cobra.Command { fmt.Println(logs.Data) }, } + logViewCmd.Flags().BoolVar(&viewFullLogs, "full", false, "Show every log file, not only the newest 10 MB of debug") + var tailLines int logTailCmd := &cobra.Command{ Use: "tail", @@ -1247,14 +1293,16 @@ NOTE: Uninstalling will set DNS to values provided by DHCP.`, var files []string // Config file. files = append(files, v.ConfigFileUsed()) - // Log file and backup log file. - // For safety, only process if log file path is absolute. - if logFile := normalizeLogFilePath(cfg.Service.LogPath); filepath.IsAbs(logFile) { - files = append(files, logFile) - oldLogFile := logFile + oldLogSuffix - if _, err := os.Stat(oldLogFile); err == nil { - files = append(files, oldLogFile) - } + // Log files. For safety, only remove the log_path chain if + // that path is absolute. + logFile := normalizeLogFilePath(cfg.Service.LogPath) + if !filepath.IsAbs(logFile) { + logFile = "" + } + backups := debugLogBudget(&cfg.Service, router.Name() != "").backups + internalLogs := []string{absHomeDir(logFileName), absHomeDir(journalLogFileName)} + for _, err := range removeLogFiles(logFile, backups, internalLogs) { + mainLog.Load().Warn().Err(err).Msg("failed to remove log file") } // Socket files. if dir, _ := socketDir(); dir != "" { diff --git a/cmd/cli/commands_cleanup_test.go b/cmd/cli/commands_cleanup_test.go new file mode 100644 index 0000000..36b50ab --- /dev/null +++ b/cmd/cli/commands_cleanup_test.go @@ -0,0 +1,71 @@ +package cli + +import ( + "os" + "path/filepath" + "testing" +) + +// writeCleanupTestFile creates a file that a cleanup test can watch. +func writeCleanupTestFile(t *testing.T, path string) string { + t.Helper() + if err := os.WriteFile(path, []byte("line\n"), 0600); err != nil { + t.Fatalf("write %s: %v", path, err) + } + return path +} + +func assertRemoved(t *testing.T, paths []string) { + t.Helper() + for _, path := range paths { + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("%s is still there: %v", path, err) + } + } +} + +func Test_removeLogFiles(t *testing.T) { + dir := t.TempDir() + logPath := writeCleanupTestFile(t, filepath.Join(dir, "syslog")) + chain := []string{ + writeCleanupTestFile(t, filepath.Join(dir, "syslog.1")), + writeCleanupTestFile(t, filepath.Join(dir, "syslog.2")), + } + // A log_path can name a file in a directory of another program, so a + // number above the configured count belongs to that program. + foreign := writeCleanupTestFile(t, filepath.Join(dir, "syslog.5")) + home := t.TempDir() + internal := []string{ + writeCleanupTestFile(t, filepath.Join(home, logFileName)), + writeCleanupTestFile(t, filepath.Join(home, journalLogFileName)), + } + internalBackups := []string{ + writeCleanupTestFile(t, filepath.Join(home, logFileName+".3")), + writeCleanupTestFile(t, filepath.Join(home, journalLogFileName+".1")), + } + + if errs := removeLogFiles(logPath, len(chain), internal); len(errs) > 0 { + t.Fatalf("removeLogFiles: %v", errs) + } + + assertRemoved(t, append([]string{logPath}, chain...)) + assertRemoved(t, append(internal, internalBackups...)) + if _, err := os.Stat(foreign); err != nil { + t.Fatalf("the cleanup removed %s, which sits above the backup count: %v", foreign, err) + } +} + +func Test_removeLogFilesWithoutALogPath(t *testing.T) { + home := t.TempDir() + internal := []string{writeCleanupTestFile(t, filepath.Join(home, logFileName))} + kept := writeCleanupTestFile(t, filepath.Join(home, "other.log")) + + if errs := removeLogFiles("", 4, internal); len(errs) > 0 { + t.Fatalf("removeLogFiles: %v", errs) + } + + assertRemoved(t, internal) + if _, err := os.Stat(kept); err != nil { + t.Fatalf("the cleanup removed %s, which is not a ctrld log: %v", kept, err) + } +} diff --git a/cmd/cli/control_client.go b/cmd/cli/control_client.go index 0e3f90f..61c8baa 100644 --- a/cmd/cli/control_client.go +++ b/cmd/cli/control_client.go @@ -5,6 +5,8 @@ import ( "io" "net" "net/http" + "net/url" + "strings" "time" ) @@ -25,13 +27,25 @@ func newControlClient(addr string) *controlClient { } func (c *controlClient) post(path string, data io.Reader) (*http.Response, error) { - // for log/send, set the timeout to 5 minutes - if path == sendLogsPath { + // A log send uploads many megabytes, so it needs more time than the other + // calls. + if isSendLogsPath(path) { c.c.Timeout = time.Minute * 5 } return c.c.Post("http://unix"+path, contentTypeJson, data) } +// isSendLogsPath reports whether path addresses the log send handler. The path +// can carry a query, so the comparison takes the path alone. A path that does +// not parse keeps the prefix rule, because it still reaches that handler. +func isSendLogsPath(path string) bool { + parsed, err := url.Parse(path) + if err != nil { + return strings.HasPrefix(path, sendLogsPath) + } + return parsed.Path == sendLogsPath +} + // postStream sends a POST request with no timeout, suitable for long-lived streaming connections. func (c *controlClient) postStream(path string, data io.Reader) (*http.Response, error) { c.c.Timeout = 0 diff --git a/cmd/cli/control_server.go b/cmd/cli/control_server.go index 5606521..c6ba7f9 100644 --- a/cmd/cli/control_server.go +++ b/cmd/cli/control_server.go @@ -309,34 +309,13 @@ func (p *prog) registerControlServerHandler() { return } })) - p.cs.register(viewLogsPath, http.HandlerFunc(func(w http.ResponseWriter, request *http.Request) { - lr, err := p.logReader() - if err != nil { - http.Error(w, err.Error(), http.StatusBadRequest) - return - } - defer lr.r.Close() - if lr.size == 0 { - w.WriteHeader(http.StatusMovedPermanently) - return - } - data, err := io.ReadAll(lr.r) - if err != nil { - http.Error(w, fmt.Sprintf("could not read log: %v", err), http.StatusInternalServerError) - return - } - if err := json.NewEncoder(w).Encode(&logViewResponse{Data: string(data)}); err != nil { - http.Error(w, err.Error(), http.StatusInternalServerError) - http.Error(w, fmt.Sprintf("could not marshal log data: %v", err), http.StatusInternalServerError) - return - } - })) + p.cs.register(viewLogsPath, http.HandlerFunc(p.handleLogView)) p.cs.register(sendLogsPath, http.HandlerFunc(func(w http.ResponseWriter, request *http.Request) { if time.Since(p.internalLogSent) < logWriterSentInterval { w.WriteHeader(http.StatusServiceUnavailable) return } - r, err := p.logReader() + r, err := p.logReader(wantFullLogs(request)) if err != nil { http.Error(w, err.Error(), http.StatusBadRequest) return @@ -430,50 +409,115 @@ func (p *prog) registerControlServerHandler() { } } else { // File-based logging mode: tail the log file. - logFile := normalizeLogFilePath(p.cfg.Service.LogPath) - f, err := os.Open(logFile) - if err != nil { - // Already committed 200, just return. - return - } - defer f.Close() - - // Seek to show last N lines. - if numLines > 0 { - if tail := tailFileLastLines(f, numLines); len(tail) > 0 { - w.Write(tail) - flusher.Flush() - } - } else { - // Seek to end. - f.Seek(0, io.SeekEnd) - } - - // Poll for new data. - buf := make([]byte, 4096) - ticker := time.NewTicker(200 * time.Millisecond) - defer ticker.Stop() - for { - select { - case <-ticker.C: - n, err := f.Read(buf) - if n > 0 { - if _, werr := w.Write(buf[:n]); werr != nil { - return - } - flusher.Flush() - } - if err != nil && err != io.EOF { - return - } - case <-request.Context().Done(): - return - } - } + followLogFile(request.Context(), w, flusher, normalizeLogFilePath(p.cfg.Service.LogPath), numLines) } })) } +// jsonStringChunkSize bounds the memory that one log view answer needs. A log +// of tens of megabytes must not get a second copy in the answer. +const jsonStringChunkSize = 32 * 1024 + +// wantFullLogs reports whether the request asks for every log file instead of +// the newest debug bytes. +func wantFullLogs(r *http.Request) bool { + return r.URL.Query().Get("full") == "1" +} + +// handleLogView answers with the log bytes in the data field. It writes the +// body while it reads the log, so the answer needs no copy of the whole log. +func (p *prog) handleLogView(w http.ResponseWriter, r *http.Request) { + lr, err := p.logReader(wantFullLogs(r)) + if err != nil { + http.Error(w, err.Error(), http.StatusBadRequest) + return + } + defer lr.r.Close() + if lr.size == 0 { + w.WriteHeader(http.StatusMovedPermanently) + return + } + w.Header().Set("Content-Type", contentTypeJson) + if _, err := io.WriteString(w, `{"data":`); err != nil { + return + } + if err := writeJSONString(w, lr.r); err != nil { + // The answer is on its way, so it can only end short. This line tells + // the operator why. + mainLog.Load().Error().Err(err).Msg("could not send log view answer") + return + } + _, _ = io.WriteString(w, `}`) +} + +// writeJSONString writes what r yields as one JSON string, in chunks. +func writeJSONString(w io.Writer, r io.Reader) error { + if _, err := io.WriteString(w, `"`); err != nil { + return err + } + chunk := make([]byte, jsonStringChunkSize) + for { + n, readErr := r.Read(chunk) + if n > 0 { + if err := writeJSONStringChunk(w, chunk[:n]); err != nil { + return err + } + } + if readErr == io.EOF { + break + } + if readErr != nil { + return readErr + } + } + _, err := io.WriteString(w, `"`) + return err +} + +// writeJSONStringChunk writes one chunk and escapes the bytes that a JSON +// string cannot carry. It writes the bytes between two escapes in one call. +func writeJSONStringChunk(w io.Writer, chunk []byte) error { + start := 0 + for i, b := range chunk { + escaped := jsonStringEscape(b) + if escaped == "" { + continue + } + if _, err := w.Write(chunk[start:i]); err != nil { + return err + } + if _, err := io.WriteString(w, escaped); err != nil { + return err + } + start = i + 1 + } + _, err := w.Write(chunk[start:]) + return err +} + +// jsonStringEscape returns the escape of one byte, or an empty string for a +// byte that a JSON string carries as it is. Every byte of a multi-byte +// character is above 0x1f, so a chunk that ends inside a character still +// writes the character whole. +func jsonStringEscape(b byte) string { + switch b { + case '"': + return `\"` + case '\\': + return `\\` + case '\n': + return `\n` + case '\r': + return `\r` + case '\t': + return `\t` + } + if b < 0x20 { + return fmt.Sprintf(`\u%04x`, b) + } + return "" +} + // tailFileLastLines reads the last n lines from a file and returns them. // The file position is left at the end of the file after this call. func tailFileLastLines(f *os.File, n int) []byte { diff --git a/cmd/cli/control_server_tail_test.go b/cmd/cli/control_server_tail_test.go new file mode 100644 index 0000000..ec678e5 --- /dev/null +++ b/cmd/cli/control_server_tail_test.go @@ -0,0 +1,104 @@ +package cli + +import ( + "context" + "net/http" + "net/http/httptest" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "github.com/Control-D-Inc/ctrld" +) + +// streamRecorder collects a streamed response under a lock, because the +// handler writes from its own goroutine while the test reads. +type streamRecorder struct { + mu sync.Mutex + header http.Header + body strings.Builder +} + +func (r *streamRecorder) Header() http.Header { return r.header } + +func (r *streamRecorder) Write(p []byte) (int, error) { + r.mu.Lock() + defer r.mu.Unlock() + return r.body.Write(p) +} + +func (r *streamRecorder) WriteHeader(int) {} + +func (r *streamRecorder) Flush() {} + +func (r *streamRecorder) String() string { + r.mu.Lock() + defer r.mu.Unlock() + return r.body.String() +} + +// waitForText polls the recorder until want arrives or the deadline passes. +func waitForText(rec *streamRecorder, want string, timeout time.Duration) bool { + deadline := time.Now().Add(timeout) + for time.Now().Before(deadline) { + if strings.Contains(rec.String(), want) { + return true + } + time.Sleep(20 * time.Millisecond) + } + return false +} + +// Test_logTailFollowsTheRotatedLogPath keeps one tail request open while the +// log_path file rotates. The lines after the rotation must reach the client. +func Test_logTailFollowsTheRotatedLogPath(t *testing.T) { + origUID := cdUID + cdUID = "" + t.Cleanup(func() { cdUID = origUID }) + + path := filepath.Join(t.TempDir(), "ctrld.log") + rf, err := newRotatingFile(path, logBudget{maxSize: 64, backups: 1}, nil) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + t.Cleanup(func() { _ = rf.close() }) + if _, err := rf.Write([]byte("before rotation\n")); err != nil { + t.Fatal(err) + } + + p := &prog{ + cfg: &ctrld.Config{Service: ctrld.ServiceConfig{LogPath: path}}, + cs: &controlServer{mux: http.NewServeMux()}, + } + p.registerControlServerHandler() + + ctx, cancel := context.WithCancel(context.Background()) + req := httptest.NewRequest(http.MethodGet, tailLogsPath+"?lines=1", nil).WithContext(ctx) + rec := &streamRecorder{header: http.Header{}} + done := make(chan struct{}) + go func() { + defer close(done) + p.cs.mux.ServeHTTP(rec, req) + }() + t.Cleanup(func() { + cancel() + <-done + }) + + if !waitForText(rec, "before rotation", 2*time.Second) { + t.Fatalf("the first line did not arrive: %q", rec.String()) + } + for i := 0; i < 4; i++ { + if _, err := rf.Write([]byte("filler line that crosses the budget\n")); err != nil { + t.Fatal(err) + } + } + if _, err := rf.Write([]byte("after rotation sentinel\n")); err != nil { + t.Fatal(err) + } + if !waitForText(rec, "after rotation sentinel", 3*time.Second) { + t.Fatalf("the sentinel did not arrive after the rotation: %q", rec.String()) + } +} diff --git a/cmd/cli/control_server_test.go b/cmd/cli/control_server_test.go index 297b37d..bdafe7b 100644 --- a/cmd/cli/control_server_test.go +++ b/cmd/cli/control_server_test.go @@ -2,10 +2,14 @@ package cli import ( "bytes" + "encoding/json" "io" "net/http" "os" + "strings" "testing" + + "github.com/Control-D-Inc/ctrld" ) func TestControlServer(t *testing.T) { @@ -52,3 +56,107 @@ func TestControlServer(t *testing.T) { t.Fatal(err) } } + +// jsonStringTestPayload holds every byte class that a JSON string must escape +// and splits a multi-byte character across the chunk boundary, so a chunk that +// ends inside a character is covered. +func jsonStringTestPayload() []byte { + var payload bytes.Buffer + payload.WriteString("quotes \" backslash \\ tab\t return\r newline\n") + payload.Write([]byte{0x00, 0x01, 0x1f}) + for payload.Len() < jsonStringChunkSize-1 { + payload.WriteByte('x') + } + payload.WriteString("é日本語 and an emoji 🙂\n") + payload.WriteString("the tail after the boundary\n") + return payload.Bytes() +} + +func Test_writeJSONString(t *testing.T) { + payload := jsonStringTestPayload() + var written bytes.Buffer + + if err := writeJSONString(&written, bytes.NewReader(payload)); err != nil { + t.Fatalf("writeJSONString: %v", err) + } + + var got string + if err := json.Unmarshal(written.Bytes(), &got); err != nil { + t.Fatalf("unmarshal %d bytes: %v", written.Len(), err) + } + if got != string(payload) { + t.Fatalf("the round trip returned %d bytes, want the %d bytes of the payload", len(got), len(payload)) + } +} + +// newLogViewTestServer serves the log view handler of p on a temporary socket +// and returns a client of it. +func newLogViewTestServer(t *testing.T, p *prog) *controlClient { + t.Helper() + f, err := os.CreateTemp("", "") + if err != nil { + t.Fatalf("temporary socket: %v", err) + } + f.Close() + t.Cleanup(func() { os.Remove(f.Name()) }) + s, err := newControlServer(f.Name()) + if err != nil { + t.Fatalf("newControlServer: %v", err) + } + s.register(viewLogsPath, http.HandlerFunc(p.handleLogView)) + if err := s.start(); err != nil { + t.Fatalf("start: %v", err) + } + t.Cleanup(func() { _ = s.stop() }) + return newControlClient(f.Name()) +} + +func Test_logViewHandler(t *testing.T) { + t.Run("answers the log as one JSON string", func(t *testing.T) { + p := setupMemoryLogReaderTest(t) + line := "a line with \"quotes\", a tab\there and 日本語\n" + if _, err := p.internalLogWriter.Write([]byte(line)); err != nil { + t.Fatalf("write the debug buffer: %v", err) + } + + resp, err := newLogViewTestServer(t, p).post(viewLogsPath, nil) + + if err != nil { + t.Fatalf("post: %v", err) + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusOK { + t.Fatalf("status = %d, want %d", resp.StatusCode, http.StatusOK) + } + if ct := resp.Header.Get("content-type"); ct != contentTypeJson { + t.Fatalf("content type = %s, want %s", ct, contentTypeJson) + } + var view logViewResponse + if err := json.NewDecoder(resp.Body).Decode(&view); err != nil { + t.Fatalf("decode the answer: %v", err) + } + if !strings.Contains(view.Data, line) { + t.Fatalf("the answer holds %.64q, want the line %q in it", view.Data, line) + } + if !strings.Contains(view.Data, logWriterLogEndMarker) { + t.Fatalf("the answer holds no log end marker: %.64q", view.Data) + } + }) + + t.Run("answers 301 without a log", func(t *testing.T) { + origSilent, origCdUID := silent, cdUID + t.Cleanup(func() { silent, cdUID = origSilent, origCdUID }) + silent, cdUID = false, "" + p := &prog{cfg: &ctrld.Config{}} + + resp, err := newLogViewTestServer(t, p).post(viewLogsPath, nil) + + if err != nil { + t.Fatalf("post: %v", err) + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusMovedPermanently { + t.Fatalf("status = %d, want %d", resp.StatusCode, http.StatusMovedPermanently) + } + }) +} diff --git a/cmd/cli/dns_proxy.go b/cmd/cli/dns_proxy.go index dc8b844..3be5cfc 100644 --- a/cmd/cli/dns_proxy.go +++ b/cmd/cli/dns_proxy.go @@ -270,7 +270,7 @@ func (p *prog) serveDNS(listenerNum string) error { p.forceFetchingAPI(domain) }() if err := w.WriteMsg(answer); err != nil { - ctrld.Log(ctx, mainLog.Load().Error().Err(err), "serveDNS: failed to send DNS response to client") + ctrld.Log(ctx, p.querySampler.event(sampleClassSendResponseFailed, "").Err(err), "serveDNS: failed to send DNS response to client") } }) @@ -842,26 +842,25 @@ func (p *prog) proxy(ctx context.Context, req *proxyRequest) *proxyResponse { ctx = context.WithValue(ctx, ctrld.ClientInfoCtxKey{}, req.ci) } answer, err := resolve1(upstream, upstreamConfig, msg) - // if we have an answer, we should reset the failure count - // we dont use reset here since we dont want to prevent failure counts from being incremented + + // reset is not used here, because it also stops the failure count for + // one second, and the failures already in flight must still count. if answer != nil { - p.um.mu.Lock() - p.um.failureReq[upstream] = 0 - p.um.down[upstream] = false - p.um.mu.Unlock() + p.um.noteSuccess(upstream) return answer } + // A failing minute must not push the state events out of the retained log. // A transport error names the endpoint it failed to reach, which for a // generated Internal Domain upstream is the organization's private - // resolver address. Report the classification at error level and keep - // the address-bearing error at debug. + // resolver address. Report the classification through the sampler and + // keep the address-bearing error at debug. if isInternalDomainUpstream(upstream) { ctrld.Log(ctx, mainLog.Load().Debug().Err(err), "failed to resolve query") - ctrld.Log(ctx, mainLog.Load().Error().Str("failure", internalDomainFailureReason(err)), + ctrld.Log(ctx, p.querySampler.event(sampleClassResolveFailed, upstream).Str("failure", internalDomainFailureReason(err)), "failed to resolve query using an Internal Domain resolver") } else { - ctrld.Log(ctx, mainLog.Load().Error().Err(err), "failed to resolve query") + ctrld.Log(ctx, p.querySampler.event(sampleClassResolveFailed, upstream).Err(err), "failed to resolve query") } // increase failure count when there is no answer @@ -973,7 +972,7 @@ func (p *prog) proxy(ctx context.Context, req *proxyRequest) *proxyResponse { res.upstream = upstreamConfig.Endpoint return res } - ctrld.Log(ctx, mainLog.Load().Error(), "all %v endpoints failed", upstreams) + ctrld.Log(ctx, p.querySampler.event(sampleClassAllEndpointsFailed, ""), "all %v endpoints failed", upstreams) // An Internal Domain with explicit resolvers is served only by the // configured resolvers. When all of them are unreachable the query fails @@ -1713,6 +1712,7 @@ func (p *prog) handleNetworkChange(delta *netmon.ChangeDelta, isMajorChange bool validateDefaultLocalIPsFromDelta(sourceState, transitionID) after4, after6 := ctrld.GetDefaultLocalIPv4(), ctrld.GetDefaultLocalIPv6() p.networkSourceMu.Unlock() + p.noteNetworkState(currentState) p.handleDNS64NetworkChange(delta, isMajorChange) validIfaces := networkChangeValidInterfacesFn() @@ -2055,9 +2055,26 @@ func interfaceIPsEqual(a, b []netip.Prefix) bool { var errOsHealthcheckSuppressed = errors.New("upstream os health check suppressed") +// upstreamFailureLog keeps one error line for each upstream of one recovery +// pass. The pass retries every two seconds until the upstream answers, and the +// first line already names the fault, so the failures that follow it go to +// debug. +type upstreamFailureLog struct{ reported bool } + +// report logs one failed check of upstream. +func (l *upstreamFailureLog) report(upstream string, uc *ctrld.UpstreamConfig, err error, duration time.Duration) { + level := mainLog.Load().Error + if l.reported { + level = mainLog.Load().Debug + } + l.reported = true + logUpstreamProbeFailure(isGeneratedInternalDomainUpstreamRef(upstream, uc), uc, err, level, + "Upstream %s check failed after %v", upstream, duration) +} + // checkUpstreamOnce sends a test query to the specified upstream. // Returns nil if the upstream responds successfully. -func (p *prog) checkUpstreamOnce(upstream string, uc *ctrld.UpstreamConfig) error { +func (p *prog) checkUpstreamOnce(upstream string, uc *ctrld.UpstreamConfig, failures *upstreamFailureLog) error { mainLog.Load().Debug().Msgf("Starting check for upstream: %s", upstream) resolver, err := ctrld.NewResolver(uc) @@ -2102,8 +2119,7 @@ func (p *prog) checkUpstreamOnce(upstream string, uc *ctrld.UpstreamConfig) erro mainLog.Load().Debug().Err(err).Msgf("Upstream %s check failed after %v (network unreachable)", upstream, duration) return err } - logUpstreamProbeFailure(isGeneratedInternalDomainUpstreamRef(upstream, uc), uc, err, - mainLog.Load().Error, "Upstream %s check failed after %v", upstream, duration) + failures.report(upstream, uc, err, duration) return err } mainLog.Load().Debug().Msgf("Upstream %s responded successfully in %v", upstream, duration) @@ -2339,6 +2355,7 @@ func (p *prog) waitForUpstreamRecovery(ctx context.Context, upstreams map[string mainLog.Load().Debug().Msgf("Starting recovery check loop for upstream: %s", name) attempts := 0 unreachableStreak := 0 + var failures upstreamFailureLog for { select { case <-recoveryCtx.Done(): @@ -2347,7 +2364,7 @@ func (p *prog) waitForUpstreamRecovery(ctx context.Context, upstreams map[string default: attempts++ // checkUpstreamOnce will reset any failure counters on success. - err := p.checkUpstreamOnce(name, uc) + err := p.checkUpstreamOnce(name, uc, &failures) if err == nil || errors.Is(err, errOsHealthcheckSuppressed) { mainLog.Load().Debug().Msgf("Upstream %s recovered successfully", name) select { diff --git a/cmd/cli/dns_proxy_sampling_test.go b/cmd/cli/dns_proxy_sampling_test.go new file mode 100644 index 0000000..0017446 --- /dev/null +++ b/cmd/cli/dns_proxy_sampling_test.go @@ -0,0 +1,124 @@ +package cli + +import ( + "context" + "strings" + "testing" + "time" + + "github.com/miekg/dns" + + "github.com/Control-D-Inc/ctrld" +) + +// deadUpstreamEndpoint is a port that nothing listens on, so every query to it +// fails at once. +const deadUpstreamEndpoint = "127.0.0.1:1" + +// countSamplingLines counts the captured lines of one level whose message +// starts with the given text. A request id rides in front of the message. +func countSamplingLines(t *testing.T, logs *syncBuffer, level, message string) int { + t.Helper() + count := 0 + for _, event := range jsonLogEvents(t, logs, "") { + text, _ := event["message"].(string) + if !strings.HasPrefix(text, message) || event["level"] != level { + continue + } + count++ + } + return count +} + +func Test_querySamplingBoundsPerQueryErrors(t *testing.T) { + logs := captureDebugMainLog(t) + p := &prog{} + // The zero value sampler arms a real timer. Close its window after the + // assertions, so no late summary line reaches another test. + t.Cleanup(func() { p.querySampler.closeExpired(time.Now().Add(querySampleWindow)) }) + + for i := 0; i < querySampleLimit+1; i++ { + ctrld.Log(context.Background(), p.querySampler.event(sampleClassResolveFailed, "upstream.0"), samplerTestMessage) + } + + if got := countSamplingLines(t, logs, "error", samplerTestMessage); got != querySampleLimit { + t.Fatalf("error lines: got %d, want %d", got, querySampleLimit) + } + if got := countSamplingLines(t, logs, "debug", samplerTestMessage); got != 1 { + t.Fatalf("debug lines: got %d, want 1", got) + } +} + +// askThroughProxy sends one query through the real proxy path and returns the +// answer. +func askThroughProxy(t *testing.T, p *prog, ctx context.Context) *dns.Msg { + t.Helper() + msg := new(dns.Msg) + msg.SetQuestion("sampling.test.", dns.TypeA) + res := p.proxy(ctx, &proxyRequest{msg: msg, ufr: &upstreamForResult{srcAddr: "192.168.0.1:1234"}}) + if res == nil || res.answer == nil { + t.Fatal("the proxy returned no answer") + } + return res.answer +} + +// Test_querySamplingOnTheQueryPath drives the real query path with an upstream +// that answers nothing: the flood keeps its request id, the sampler bounds it, +// and one state event brackets each end of the outage. +func Test_querySamplingOnTheQueryPath(t *testing.T) { + logs := captureDebugMainLog(t) + cfg := &ctrld.Config{} + cfg.Service.LeakOnUpstreamFailure = func(v bool) *bool { return &v }(false) + p := &prog{cfg: cfg, um: newUpstreamMonitor(cfg)} + // A new monitor holds back the failure counts for one second. The test + // clears the flag instead of waiting for that timer. + p.um.clearRecovered(upstreamOS) + var armed []func() + p.um.after = func(_ time.Duration, fn func()) { armed = append(armed, fn) } + // The zero value sampler arms a real timer. Close its window after the + // assertions, so no late summary line reaches another test. + t.Cleanup(func() { p.querySampler.closeExpired(time.Now().Add(querySampleWindow)) }) + + origOSUpstream := osUpstreamConfig + t.Cleanup(func() { osUpstreamConfig = origOSUpstream }) + osUpstreamConfig = &ctrld.UpstreamConfig{ + Name: "dead resolver", + Type: ctrld.ResolverTypeLegacy, + Endpoint: deadUpstreamEndpoint, + Timeout: 500, + } + + ctx := context.WithValue(context.Background(), ctrld.ReqIdCtxKey{}, "r1") + for i := 0; i < querySampleLimit+2; i++ { + if rcode := askThroughProxy(t, p, ctx).Rcode; rcode != dns.RcodeServerFailure { + t.Fatalf("query %d: rcode %s, want SERVFAIL", i+1, dns.RcodeToString[rcode]) + } + } + + const failedMessage = "[r1] " + samplerTestMessage + if got := countSamplingLines(t, logs, "error", failedMessage); got != querySampleLimit { + t.Fatalf("error lines: got %d, want %d", got, querySampleLimit) + } + if got := countSamplingLines(t, logs, "debug", failedMessage); got != 2 { + t.Fatalf("debug lines: got %d, want 2", got) + } + + if len(armed) != 1 { + t.Fatalf("armed timers: got %d, want 1", len(armed)) + } + armed[0]() + startOSResolverStub(t) + if rcode := askThroughProxy(t, p, ctx).Rcode; rcode != dns.RcodeSuccess { + t.Fatalf("the answered query returned %s, want NOERROR", dns.RcodeToString[rcode]) + } + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 2 { + t.Fatalf("state events: got %d, want 2", len(events)) + } + wantField(t, events[0], "upstream", upstreamOS) + wantField(t, events[0], "state", "down") + wantField(t, events[0], "reason", "timer") + wantField(t, events[1], "upstream", upstreamOS) + wantField(t, events[1], "state", "up") +} diff --git a/cmd/cli/internal_domains_review_test.go b/cmd/cli/internal_domains_review_test.go index f26e9cb..d2ece04 100644 --- a/cmd/cli/internal_domains_review_test.go +++ b/cmd/cli/internal_domains_review_test.go @@ -592,7 +592,7 @@ func TestInternalDomainsRecoveryCheckHidesResolverAddress(t *testing.T) { } mark := len(logOutput.String()) - if err := p.checkUpstreamOnce("upstream.internal_0", uc); err == nil { + if err := p.checkUpstreamOnce("upstream.internal_0", uc, &upstreamFailureLog{}); err == nil { t.Fatal("expected the probe to fail") } above := logLinesAboveDebug(mark) diff --git a/cmd/cli/log_budget.go b/cmd/cli/log_budget.go new file mode 100644 index 0000000..19c0405 --- /dev/null +++ b/cmd/cli/log_budget.go @@ -0,0 +1,45 @@ +package cli + +import ( + "github.com/Control-D-Inc/ctrld" +) + +// journalLogFileName is the journal file next to the debug log in the ctrld +// home directory. +const journalLogFileName = "ctrld-journal.log" + +// logBudgets splits the disk space by platform. A router keeps the 10 MB total +// that QA measured on an EdgeRouter-X, because its flash is small. A desktop +// holds more, so a log covers more days. +func logBudgets(isRouter bool) (debug, journal logBudget) { + if isRouter { + return logBudget{maxSize: 5 << 20, backups: 1}, logBudget{maxSize: 1 << 20, backups: 1} + } + return logBudget{maxSize: 10 << 20, backups: 4}, logBudget{maxSize: 2 << 20, backups: 2} +} + +const ( + // logMaxSizeMBLimit and logMaxBackupsLimit bound the two keys. The log + // file opens before ctrld validates its configuration, so a key outside + // these bounds reaches this code: a size near the largest integer never + // rotates, and a count of one million backups renames one million files. + // The validation rules are the first line of defense, and these bounds + // are the second. + logMaxSizeMBLimit = 1024 + logMaxBackupsLimit = 64 +) + +// debugLogBudget starts from the platform default, so a router keeps its small +// total until an operator asks for more. The two keys size the debug stream +// only. The journal budget stays fixed. A key outside its bounds keeps the +// default. +func debugLogBudget(svc *ctrld.ServiceConfig, isRouter bool) logBudget { + budget, _ := logBudgets(isRouter) + if mb := svc.LogMaxSizeMB; mb >= 1 && mb <= logMaxSizeMBLimit { + budget.maxSize = int64(mb) << 20 + } + if count := svc.LogMaxBackups; count != nil && *count >= 0 && *count <= logMaxBackupsLimit { + budget.backups = *count + } + return budget +} diff --git a/cmd/cli/log_budget_test.go b/cmd/cli/log_budget_test.go new file mode 100644 index 0000000..e278ff3 --- /dev/null +++ b/cmd/cli/log_budget_test.go @@ -0,0 +1,60 @@ +package cli + +import ( + "testing" + + "github.com/Control-D-Inc/ctrld" +) + +func Test_logBudgets(t *testing.T) { + for _, tc := range []struct { + name string + isRouter bool + wantDebug logBudget + wantJournal logBudget + }{ + {"desktop", false, logBudget{maxSize: 10 << 20, backups: 4}, logBudget{maxSize: 2 << 20, backups: 2}}, + {"router", true, logBudget{maxSize: 5 << 20, backups: 1}, logBudget{maxSize: 1 << 20, backups: 1}}, + } { + t.Run(tc.name, func(t *testing.T) { + debug, journalStream := logBudgets(tc.isRouter) + if debug != tc.wantDebug { + t.Errorf("debug budget = %+v, want %+v", debug, tc.wantDebug) + } + if journalStream != tc.wantJournal { + t.Errorf("journal budget = %+v, want %+v", journalStream, tc.wantJournal) + } + }) + } +} + +func Test_debugLogBudget(t *testing.T) { + noBackup, oneBackup := 0, 1 + negativeBackups, tooManyBackups, mostBackups := -1, logMaxBackupsLimit+1, logMaxBackupsLimit + for _, tc := range []struct { + name string + svc ctrld.ServiceConfig + isRouter bool + want logBudget + }{ + {"both keys set", ctrld.ServiceConfig{LogMaxSizeMB: 20, LogMaxBackups: &oneBackup}, false, logBudget{maxSize: 20 << 20, backups: 1}}, + {"size zero keeps the default size", ctrld.ServiceConfig{LogMaxBackups: &oneBackup}, false, logBudget{maxSize: 10 << 20, backups: 1}}, + {"absent backups keep the default count", ctrld.ServiceConfig{LogMaxSizeMB: 20}, false, logBudget{maxSize: 20 << 20, backups: 4}}, + {"zero backups keep no backup file", ctrld.ServiceConfig{LogMaxBackups: &noBackup}, false, logBudget{maxSize: 10 << 20, backups: 0}}, + {"empty config on a desktop", ctrld.ServiceConfig{}, false, logBudget{maxSize: 10 << 20, backups: 4}}, + {"empty config on a router", ctrld.ServiceConfig{}, true, logBudget{maxSize: 5 << 20, backups: 1}}, + {"keys win on a router", ctrld.ServiceConfig{LogMaxSizeMB: 20, LogMaxBackups: &noBackup}, true, logBudget{maxSize: 20 << 20, backups: 0}}, + {"negative size keeps the default size", ctrld.ServiceConfig{LogMaxSizeMB: -1}, false, logBudget{maxSize: 10 << 20, backups: 4}}, + {"size above the limit keeps the default size", ctrld.ServiceConfig{LogMaxSizeMB: logMaxSizeMBLimit + 1}, false, logBudget{maxSize: 10 << 20, backups: 4}}, + {"the largest size the key takes", ctrld.ServiceConfig{LogMaxSizeMB: logMaxSizeMBLimit}, false, logBudget{maxSize: logMaxSizeMBLimit << 20, backups: 4}}, + {"negative backups keep the default count", ctrld.ServiceConfig{LogMaxBackups: &negativeBackups}, false, logBudget{maxSize: 10 << 20, backups: 4}}, + {"backups above the limit keep the default count", ctrld.ServiceConfig{LogMaxBackups: &tooManyBackups}, false, logBudget{maxSize: 10 << 20, backups: 4}}, + {"the largest backup count the key takes", ctrld.ServiceConfig{LogMaxBackups: &mostBackups}, false, logBudget{maxSize: 10 << 20, backups: logMaxBackupsLimit}}, + } { + t.Run(tc.name, func(t *testing.T) { + if got := debugLogBudget(&tc.svc, tc.isRouter); got != tc.want { + t.Errorf("debug budget = %+v, want %+v", got, tc.want) + } + }) + } +} diff --git a/cmd/cli/log_file.go b/cmd/cli/log_file.go new file mode 100644 index 0000000..dee26e7 --- /dev/null +++ b/cmd/cli/log_file.go @@ -0,0 +1,416 @@ +package cli + +import ( + "errors" + "fmt" + "os" + "path/filepath" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" +) + +// errLogFileNotOpen tells a caller that the file is closed, so a write that +// returns no bytes never looks like a success. +var errLogFileNotOpen = errors.New("log file is not open") + +// retryOpenInterval is the wait between two attempts to open a log file that +// could not open. A file error is often short-lived, and one attempt for each +// line would cost a system call for every line. +var retryOpenInterval = time.Minute + +// logBudget is the disk space of one log stream: the size of the current +// file and the number of numbered backups that follow it. +type logBudget struct { + maxSize int64 + backups int +} + +// logRotation describes the file that a rotation moved away. A set err means +// that the file could not move, so the stream continues in the same file. +type logRotation struct { + file string + bytesWritten int64 + firstWrite time.Time + lastWrite time.Time + backups int + err error +} + +// rotatingFile writes one log file and rotates it by size with numbered +// backups. It holds the header bytes, so every file it opens starts with +// the header, and it records the write times that the rotation event needs. +type rotatingFile struct { + mu sync.Mutex + path string + budget logBudget + open func(string, int) (*os.File, error) + rename func(oldpath, newpath string) error + f *os.File + size int64 + firstWrite time.Time + lastWrite time.Time + header []byte + openErr error + onRotate func(logRotation) + // headerWritten tells whether the file that is open now already holds the + // header. A start wires its logging more than once, and each file takes + // one header. + headerWritten bool + // rotateFailedAt is the size at which a rotation could not move the file. + // The next try waits for another budget of data, so a directory that + // refuses the move does not cost one attempt per line. + rotateFailedAt int64 + // retryOpenAt is the time from which a closed file may open again. + retryOpenAt time.Time + // rotatedInFlight keeps onRotate from reporting a rotation that the + // rotation event itself caused. + rotatedInFlight atomic.Bool +} + +// newRotatingFile opens path in append mode and counts what it already holds, +// so a restart continues the current file instead of starting a new one. +func newRotatingFile(path string, budget logBudget, open func(string, int) (*os.File, error)) (*rotatingFile, error) { + if err := os.MkdirAll(filepath.Dir(path), 0750); err != nil { + return nil, fmt.Errorf("creating log directory: %w", err) + } + rf := &rotatingFile{path: path, budget: budget, open: open} + f, err := rf.openFile(os.O_CREATE | os.O_RDWR | os.O_APPEND) + if err != nil { + return nil, fmt.Errorf("opening log file: %w", err) + } + st, err := f.Stat() + if err != nil { + f.Close() + return nil, fmt.Errorf("stat log file: %w", err) + } + rf.f = f + rf.size = st.Size() + return rf, nil +} + +// openFile opens the file through the platform helper, which holds the flags +// that each platform needs: a share mode on Windows, and a refusal to follow +// a symlink elsewhere. +func (rf *rotatingFile) openFile(flags int) (*os.File, error) { + if rf.open == nil { + return openLogFile(rf.path, flags) + } + return rf.open(rf.path, flags) +} + +func (rf *rotatingFile) renameFile(oldpath, newpath string) error { + if rf.rename == nil { + return os.Rename(oldpath, newpath) + } + return rf.rename(oldpath, newpath) +} + +// writeReporting appends p and reports a rotation that happened first. It +// never calls onRotate, because the caller must log the rotation outside of +// the lock. +func (rf *rotatingFile) writeReporting(p []byte) (int, *logRotation, error) { + rf.mu.Lock() + defer rf.mu.Unlock() + + var rotated *logRotation + if rf.needsRotation(len(p)) { + var err error + if rotated, err = rf.rotateLocked(); err != nil { + return 0, rotated, err + } + } + n, err := rf.writeLocked(p) + if err != nil { + return n, rotated, err + } + rf.noteEventWrite() + return n, rotated, nil +} + +// Write makes the file an io.Writer for the logger. It reports the rotation +// after the lock is free, so the rotation event can go back into this file. +func (rf *rotatingFile) Write(p []byte) (int, error) { + n, rotated, err := rf.writeReporting(p) + if rotated == nil || !rf.rotatedInFlight.CompareAndSwap(false, true) { + return n, err + } + defer rf.rotatedInFlight.Store(false) + rf.mu.Lock() + onRotate := rf.onRotate + rf.mu.Unlock() + if onRotate != nil { + onRotate(*rotated) + } + return n, err +} + +// setHeader stores a copy of the header bytes for the next file. +func (rf *rotatingFile) setHeader(b []byte) { + header := make([]byte, len(b)) + copy(header, b) + rf.mu.Lock() + defer rf.mu.Unlock() + rf.header = header +} + +// writeHeader appends the stored header to the current file, once for each +// file that the writer opens. A restart uses it to mark the point where the +// new run continues an old file. +func (rf *rotatingFile) writeHeader() error { + rf.mu.Lock() + defer rf.mu.Unlock() + if rf.headerWritten { + return nil + } + return rf.writeHeaderLocked() +} + +// setBudget takes the disk space of a later config. The file stays open, so a +// changed key costs no second header. +func (rf *rotatingFile) setBudget(budget logBudget) { + rf.mu.Lock() + defer rf.mu.Unlock() + rf.budget = budget +} + +// rotateNow rotates the file although the budget is not spent. +func (rf *rotatingFile) rotateNow() (*logRotation, error) { + rf.mu.Lock() + defer rf.mu.Unlock() + return rf.rotateLocked() +} + +// paths returns the files that exist, oldest first, for the log readers. +func (rf *rotatingFile) paths() []string { + rf.mu.Lock() + defer rf.mu.Unlock() + files := make([]string, 0, rf.budget.backups+1) + for i := rf.budget.backups; i >= 1; i-- { + backup := rf.backupPath(i) + if _, err := os.Stat(backup); err == nil { + files = append(files, backup) + } + } + if _, err := os.Stat(rf.path); err == nil { + files = append(files, rf.path) + } + return files +} + +func (rf *rotatingFile) currentPath() string { + return rf.path +} + +func (rf *rotatingFile) close() error { + rf.mu.Lock() + defer rf.mu.Unlock() + if rf.f == nil { + return nil + } + err := rf.f.Close() + rf.f = nil + return err +} + +func (rf *rotatingFile) backupPath(index int) string { + return fmt.Sprintf("%s.%d", rf.path, index) +} + +// rotatingSuffix marks the file that a rotation with no backup moves away +// before it opens the new file. The old bytes stay behind the readers that +// hold them open, and the file goes as soon as the new file is open. +const rotatingSuffix = ".rotating" + +func (rf *rotatingFile) rotatingPath() string { + return rf.path + rotatingSuffix +} + +// rotatedPath names the file that the next rotation leaves behind. +func (rf *rotatingFile) rotatedPath() string { + if rf.budget.backups == 0 { + return rf.path + } + return rf.backupPath(1) +} + +// needsRotation reports whether p makes the file cross its budget. A closed +// file never rotates, because a rotation would shift the backups away for a +// write that cannot land. +func (rf *rotatingFile) needsRotation(n int) bool { + if rf.f == nil || rf.budget.maxSize <= 0 { + return false + } + return rf.size+int64(n) > rf.rotateFailedAt+rf.budget.maxSize +} + +// rotateLocked moves the current file away and opens an empty one in its +// place. It must run with rf.mu held. +func (rf *rotatingFile) rotateLocked() (*logRotation, error) { + record := &logRotation{ + file: rf.rotatedPath(), + bytesWritten: rf.size, + firstWrite: rf.firstWrite, + lastWrite: rf.lastWrite, + backups: rf.budget.backups, + } + if rf.f != nil { + rf.f.Close() + rf.f = nil + } + if err := rf.shiftBackups(); err != nil { + record.err = err + return record, rf.keepFileAfterFailedShift() + } + + f, err := rf.openFile(os.O_CREATE | os.O_RDWR | os.O_TRUNC) + if err != nil { + rf.size = 0 + return record, rf.noteOpenFailure(err) + } + if rf.budget.backups == 0 { + // The readers that hold the old file keep their bytes; the name goes. + _ = os.Remove(rf.rotatingPath()) + } + rf.f = f + rf.openErr = nil + rf.size = 0 + rf.rotateFailedAt = 0 + rf.firstWrite = time.Time{} + rf.lastWrite = time.Time{} + rf.headerWritten = false + return record, rf.writeHeaderLocked() +} + +// keepFileAfterFailedShift opens the file that could not move. The append flag +// keeps the lines that are already in it, which a truncating open would drop +// although no backup holds them. It must run with rf.mu held. +func (rf *rotatingFile) keepFileAfterFailedShift() error { + f, err := rf.openFile(os.O_CREATE | os.O_RDWR | os.O_APPEND) + if err != nil { + rf.size = 0 + return rf.noteOpenFailure(err) + } + rf.f = f + rf.openErr = nil + rf.rotateFailedAt = rf.size + return nil +} + +// noteOpenFailure keeps the error of a failed open and holds the next attempt +// back. It must run with rf.mu held. +func (rf *rotatingFile) noteOpenFailure(err error) error { + rf.openErr = fmt.Errorf("reopening log file: %w", err) + rf.retryOpenAt = time.Now().Add(retryOpenInterval) + return rf.openErr +} + +// shiftBackups moves each backup one number up and drops the oldest one. A +// missing backup is normal here, so those moves are best effort: a rotation +// must continue even when one backup cannot move. The move of the current +// file decides the rotation, so its error goes back to the caller. With no +// backup allowed, the current file still moves away, because a truncating +// reopen would change the bytes under an open upload reader. +func (rf *rotatingFile) shiftBackups() error { + if rf.budget.backups == 0 { + return rf.moveCurrentFile(rf.rotatingPath()) + } + for i := rf.budget.backups - 1; i >= 1; i-- { + _ = rf.renameFile(rf.backupPath(i), rf.backupPath(i+1)) + } + return rf.moveCurrentFile(rf.backupPath(1)) +} + +// moveCurrentFile renames the current file. A file that is not there is not +// an error, because a fresh path has nothing to move. +func (rf *rotatingFile) moveCurrentFile(to string) error { + if err := rf.renameFile(rf.path, to); err != nil && !os.IsNotExist(err) { + return err + } + return nil +} + +// pruneNumberedBackups removes the backups of path above keep. A lowered +// log_max_backups would otherwise leave old files that no reader lists. It +// reads the directory, because the numbers can have gaps. Only a name with an +// exact number after the path goes, because the directory can hold the files +// of another writer. +func pruneNumberedBackups(path string, keep int) { + dir := filepath.Dir(path) + entries, err := os.ReadDir(dir) + if err != nil { + return + } + prefix := filepath.Base(path) + "." + for _, entry := range entries { + suffix, found := strings.CutPrefix(entry.Name(), prefix) + if !found { + continue + } + index, err := strconv.Atoi(suffix) + if err != nil || index <= keep { + continue + } + os.Remove(filepath.Join(dir, entry.Name())) + } +} + +// writeHeaderLocked must run with rf.mu held. +func (rf *rotatingFile) writeHeaderLocked() error { + if len(rf.header) == 0 { + return nil + } + rf.headerWritten = true + _, err := rf.writeLocked(rf.header) + return err +} + +// writeLocked appends to the open file and counts the bytes. It must run +// with rf.mu held. +func (rf *rotatingFile) writeLocked(p []byte) (int, error) { + if rf.f == nil { + if rf.openErr == nil { + return 0, errLogFileNotOpen + } + if err := rf.retryOpenLocked(); err != nil { + return 0, err + } + } + n, err := rf.f.Write(p) + rf.size += int64(n) + return n, err +} + +// retryOpenLocked opens a file again that could not open. A file whose open +// failed once must not stay closed for the life of the process, because the +// cause is often a full disk or a directory that comes back. It must run with +// rf.mu held. +func (rf *rotatingFile) retryOpenLocked() error { + if time.Now().Before(rf.retryOpenAt) { + return rf.openErr + } + f, err := rf.openFile(os.O_CREATE | os.O_RDWR | os.O_APPEND) + if err != nil { + return rf.noteOpenFailure(err) + } + rf.f = f + rf.openErr = nil + rf.size = 0 + if st, err := f.Stat(); err == nil { + rf.size = st.Size() + } + rf.headerWritten = false + return rf.writeHeaderLocked() +} + +// noteEventWrite keeps the times that the rotation event reports. A header +// is not an event, so it does not move these times. +func (rf *rotatingFile) noteEventWrite() { + now := time.Now() + if rf.firstWrite.IsZero() { + rf.firstWrite = now + } + rf.lastWrite = now +} diff --git a/cmd/cli/log_file_test.go b/cmd/cli/log_file_test.go new file mode 100644 index 0000000..428be98 --- /dev/null +++ b/cmd/cli/log_file_test.go @@ -0,0 +1,553 @@ +package cli + +import ( + "errors" + "fmt" + "io" + "os" + "path/filepath" + "runtime" + "slices" + "strings" + "sync/atomic" + "testing" + "time" +) + +const rotatingFileTestLineSize = 1024 + +// rotatingFileTestLine returns a line of a fixed size that names its +// generation, so a test can tell the content of one file from another. +func rotatingFileTestLine(generation, seq int) []byte { + head := fmt.Sprintf("gen=%d seq=%d ", generation, seq) + return []byte(head + strings.Repeat("x", rotatingFileTestLineSize-len(head)-1) + "\n") +} + +func newTestRotatingFile(t *testing.T, budget logBudget) *rotatingFile { + t.Helper() + path := filepath.Join(t.TempDir(), "ctrld.log") + rf, err := newRotatingFile(path, budget, nil) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + t.Cleanup(func() { _ = rf.close() }) + return rf +} + +func rotatingFileTestContent(t *testing.T, path string) string { + t.Helper() + b, err := os.ReadFile(path) + if err != nil { + t.Fatalf("read %s: %v", path, err) + } + return string(b) +} + +func writeRotatingFileTestLine(t *testing.T, rf *rotatingFile, generation, seq int) *logRotation { + t.Helper() + line := rotatingFileTestLine(generation, seq) + n, rotated, err := rf.writeReporting(line) + if err != nil { + t.Fatalf("write gen=%d seq=%d: %v", generation, seq, err) + } + if n != len(line) { + t.Fatalf("write gen=%d seq=%d wrote %d bytes, want %d", generation, seq, n, len(line)) + } + return rotated +} + +func Test_rotatingFileKeepsNumberedBackups(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 4096, backups: 4}) + rotations := 0 + for generation := 1; generation <= 7; generation++ { + for seq := 1; seq <= 4; seq++ { + if writeRotatingFileTestLine(t, rf, generation, seq) != nil { + rotations++ + } + } + } + if rotations != 6 { + t.Fatalf("rotations = %d, want 6", rotations) + } + + generationOf := map[string]int{"": 7, ".1": 6, ".2": 5, ".3": 4, ".4": 3} + for suffix, generation := range generationOf { + content := rotatingFileTestContent(t, rf.path+suffix) + if want := fmt.Sprintf("gen=%d seq=1 ", generation); !strings.HasPrefix(content, want) { + t.Fatalf("file %q starts with %.16q, want %q", rf.path+suffix, content, want) + } + if newer := fmt.Sprintf("gen=%d ", generation+1); strings.Contains(content, newer) { + t.Fatalf("file %q holds %q", rf.path+suffix, newer) + } + } + if _, err := os.Stat(rf.path + ".5"); !os.IsNotExist(err) { + t.Fatalf("stat %s.5 = %v, want a not exist error", rf.path, err) + } +} + +func Test_rotatingFileHeaderStartsEveryFile(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 4096, backups: 1}) + header := []byte(`{"level":"info","journal":true,"message":"Log header"}` + "\n") + rf.setHeader(header) + if err := rf.writeHeader(); err != nil { + t.Fatalf("writeHeader: %v", err) + } + if rf.size != int64(len(header)) { + t.Fatalf("size = %d, want %d", rf.size, len(header)) + } + if got := strings.Count(rotatingFileTestContent(t, rf.path), string(header)); got != 1 { + t.Fatalf("header count in the first file = %d, want 1", got) + } + + rotations := 0 + for seq := 1; seq <= 5; seq++ { + if writeRotatingFileTestLine(t, rf, 1, seq) != nil { + rotations++ + } + } + if rotations != 1 { + t.Fatalf("rotations = %d, want 1", rotations) + } + if !strings.HasPrefix(rotatingFileTestContent(t, rf.path+".1"), string(header)) { + t.Fatal("the backup file does not start with the header") + } + content := rotatingFileTestContent(t, rf.path) + if !strings.HasPrefix(content, string(header)) { + t.Fatal("the new file does not start with the header") + } + if got := strings.Count(content, string(header)); got != 1 { + t.Fatalf("header count in the new file = %d, want 1", got) + } + if want := int64(len(header) + 2*rotatingFileTestLineSize); rf.size != want { + t.Fatalf("size = %d, want %d", rf.size, want) + } +} + +func Test_rotatingFileRotationRecord(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 4096, backups: 2}) + if rf.currentPath() != rf.path { + t.Fatalf("currentPath = %q, want %q", rf.currentPath(), rf.path) + } + start := time.Now() + for seq := 1; seq <= 3; seq++ { + writeRotatingFileTestLine(t, rf, 1, seq) + } + sizeBeforeRotation := rf.size + + record, err := rf.rotateNow() + if err != nil { + t.Fatalf("rotateNow: %v", err) + } + if record == nil { + t.Fatal("rotateNow returned no record") + } + if want := rf.path + ".1"; record.file != want { + t.Fatalf("record.file = %q, want %q", record.file, want) + } + if record.backups != 2 { + t.Fatalf("record.backups = %d, want 2", record.backups) + } + if record.bytesWritten != sizeBeforeRotation { + t.Fatalf("record.bytesWritten = %d, want %d", record.bytesWritten, sizeBeforeRotation) + } + st, err := os.Stat(record.file) + if err != nil { + t.Fatalf("stat %s: %v", record.file, err) + } + if st.Size() != record.bytesWritten { + t.Fatalf("%s holds %d bytes, record.bytesWritten = %d", record.file, st.Size(), record.bytesWritten) + } + if record.firstWrite.Before(start) { + t.Fatalf("record.firstWrite = %v, want at or after %v", record.firstWrite, start) + } + if record.lastWrite.Before(record.firstWrite) { + t.Fatalf("record.lastWrite = %v is before record.firstWrite = %v", record.lastWrite, record.firstWrite) + } + + want := []string{rf.path + ".1", rf.path} + if got := rf.paths(); !slices.Equal(got, want) { + t.Fatalf("paths = %v, want %v", got, want) + } + writeRotatingFileTestLine(t, rf, 2, 1) + if _, err := rf.rotateNow(); err != nil { + t.Fatalf("second rotateNow: %v", err) + } + want = []string{rf.path + ".2", rf.path + ".1", rf.path} + if got := rf.paths(); !slices.Equal(got, want) { + t.Fatalf("paths after two rotations = %v, want %v", got, want) + } +} + +func Test_rotatingFileZeroBackupsTruncatesInPlace(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 2048, backups: 0}) + var record *logRotation + for seq := 1; seq <= 3; seq++ { + if rotated := writeRotatingFileTestLine(t, rf, 1, seq); rotated != nil { + record = rotated + } + } + if record == nil { + t.Fatal("no rotation happened") + } + if record.file != rf.path { + t.Fatalf("record.file = %q, want %q", record.file, rf.path) + } + if record.backups != 0 { + t.Fatalf("record.backups = %d, want 0", record.backups) + } + if want := int64(2 * rotatingFileTestLineSize); record.bytesWritten != want { + t.Fatalf("record.bytesWritten = %d, want %d", record.bytesWritten, want) + } + if _, err := os.Stat(rf.path + ".1"); !os.IsNotExist(err) { + t.Fatalf("stat %s.1 = %v, want a not exist error", rf.path, err) + } + if content := rotatingFileTestContent(t, rf.path); strings.Contains(content, "seq=1 ") { + t.Fatal("the truncated file still holds the old content") + } + if got, want := rf.paths(), []string{rf.path}; !slices.Equal(got, want) { + t.Fatalf("paths = %v, want %v", got, want) + } +} + +func Test_rotatingFileWriteCallsOnRotate(t *testing.T) { + t.Run("one call per rotation", func(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 4096, backups: 4}) + var rotations atomic.Int64 + rf.onRotate = func(logRotation) { rotations.Add(1) } + for generation := 1; generation <= 7; generation++ { + for seq := 1; seq <= 4; seq++ { + if _, err := rf.Write(rotatingFileTestLine(generation, seq)); err != nil { + t.Fatalf("Write: %v", err) + } + } + } + if got := rotations.Load(); got != 6 { + t.Fatalf("onRotate calls = %d, want 6", got) + } + }) + + t.Run("reentrant callback does not deadlock", func(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 4096, backups: 1}) + const reentrantLine = "written from onRotate\n" + var rotations atomic.Int64 + rf.onRotate = func(logRotation) { + rotations.Add(1) + if _, err := rf.Write([]byte(reentrantLine)); err != nil { + t.Errorf("reentrant Write: %v", err) + } + } + done := make(chan struct{}) + go func() { + defer close(done) + for seq := 1; seq <= 5; seq++ { + if _, err := rf.Write(rotatingFileTestLine(1, seq)); err != nil { + t.Errorf("Write: %v", err) + return + } + } + }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("Write did not return, a reentrant onRotate deadlocks it") + } + if got := rotations.Load(); got != 1 { + t.Fatalf("onRotate calls = %d, want 1", got) + } + if !strings.Contains(rotatingFileTestContent(t, rf.path), reentrantLine) { + t.Fatal("the new file does not hold the reentrant line") + } + }) +} + +func Test_rotatingFileCountsExistingSize(t *testing.T) { + path := filepath.Join(t.TempDir(), "logs", "ctrld.log") + budget := logBudget{maxSize: 8192, backups: 1} + rf, err := newRotatingFile(path, budget, nil) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + for seq := 1; seq <= 3; seq++ { + writeRotatingFileTestLine(t, rf, 1, seq) + } + if err := rf.close(); err != nil { + t.Fatalf("close: %v", err) + } + + reopened, err := newRotatingFile(path, budget, nil) + if err != nil { + t.Fatalf("newRotatingFile on an existing file: %v", err) + } + t.Cleanup(func() { _ = reopened.close() }) + if want := int64(3 * rotatingFileTestLineSize); reopened.size != want { + t.Fatalf("size = %d, want %d", reopened.size, want) + } + record, err := reopened.rotateNow() + if err != nil { + t.Fatalf("rotateNow: %v", err) + } + if want := int64(3 * rotatingFileTestLineSize); record.bytesWritten != want { + t.Fatalf("record.bytesWritten = %d, want %d", record.bytesWritten, want) + } + st, err := os.Stat(path) + if err != nil { + t.Fatalf("stat %s: %v", path, err) + } + if st.Size() != 0 { + t.Fatalf("the new file holds %d bytes, want 0", st.Size()) + } +} + +func Test_rotatingFileKeepsReopenError(t *testing.T) { + reopenErr := errors.New("reopen refused") + var opens atomic.Int64 + open := func(path string, flags int) (*os.File, error) { + if opens.Add(1) > 1 { + return nil, reopenErr + } + return os.OpenFile(path, flags, 0600) + } + path := filepath.Join(t.TempDir(), "ctrld.log") + rf, err := newRotatingFile(path, logBudget{maxSize: 1024, backups: 1}, open) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + t.Cleanup(func() { _ = rf.close() }) + + writeRotatingFileTestLine(t, rf, 1, 1) + if _, _, err := rf.writeReporting(rotatingFileTestLine(1, 2)); !errors.Is(err, reopenErr) { + t.Fatalf("write after a failed reopen = %v, want %v", err, reopenErr) + } + if rf.f != nil { + t.Fatal("the file is still open after a failed reopen") + } + if _, _, err := rf.writeReporting(rotatingFileTestLine(1, 3)); !errors.Is(err, reopenErr) { + t.Fatalf("later write = %v, want %v", err, reopenErr) + } + + oversized := make([]byte, 2*rotatingFileTestLineSize) + _, rotated, err := rf.writeReporting(oversized) + if !errors.Is(err, reopenErr) { + t.Fatalf("oversized write = %v, want %v", err, reopenErr) + } + if rotated != nil { + t.Fatalf("a closed file reported a rotation of %q", rotated.file) + } + if _, err := os.Stat(path + ".2"); !os.IsNotExist(err) { + t.Fatalf("stat %s.2 = %v, want a not exist error: a closed file shifted the backups", path, err) + } +} + +func Test_rotatingFileRetriesAFailedOpen(t *testing.T) { + origInterval := retryOpenInterval + retryOpenInterval = 10 * time.Millisecond + t.Cleanup(func() { retryOpenInterval = origInterval }) + + openErr := errors.New("open refused") + opens := 0 + open := func(path string, flags int) (*os.File, error) { + opens++ + if opens == 2 { + return nil, openErr + } + return os.OpenFile(path, flags, 0600) + } + path := filepath.Join(t.TempDir(), "ctrld.log") + rf, err := newRotatingFile(path, logBudget{maxSize: rotatingFileTestLineSize, backups: 1}, open) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + t.Cleanup(func() { _ = rf.close() }) + header := []byte(`{"level":"info","journal":true,"message":"Log header"}` + "\n") + rf.setHeader(header) + + writeRotatingFileTestLine(t, rf, 1, 1) + if _, _, err := rf.writeReporting(rotatingFileTestLine(1, 2)); !errors.Is(err, openErr) { + t.Fatalf("write after a failed reopen = %v, want %v", err, openErr) + } + if _, _, err := rf.writeReporting(rotatingFileTestLine(1, 3)); !errors.Is(err, openErr) { + t.Fatalf("write inside the retry interval = %v, want %v", err, openErr) + } + if opens != 2 { + t.Fatalf("opens = %d, want 2: a write inside the retry interval opened the file again", opens) + } + + time.Sleep(2 * retryOpenInterval) + writeRotatingFileTestLine(t, rf, 1, 4) + + content := rotatingFileTestContent(t, path) + if !strings.HasPrefix(content, string(header)) { + t.Fatalf("the reopened file starts with %.40q, want the header", content) + } + if !strings.Contains(content, "gen=1 seq=4 ") { + t.Fatalf("the reopened file misses the line that followed the retry: %.80q", content) + } +} + +func Test_pruneNumberedBackups(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, logFileName) + numbered := []string{path + ".1", path + ".2", path + ".3", path + ".4"} + // A prune must keep every file that another writer owns, because log_path + // can name a file in a directory full of them. + foreign := []string{path + ".bak", filepath.Join(dir, journalLogFileName+".3"), filepath.Join(dir, "syslog.5")} + for _, name := range append(slices.Clone(numbered), foreign...) { + if err := os.WriteFile(name, []byte("old\n"), 0600); err != nil { + t.Fatalf("write %s: %v", name, err) + } + } + + pruneNumberedBackups(path, 1) + + if _, err := os.Stat(numbered[0]); err != nil { + t.Fatalf("the backup inside the count went away: %v", err) + } + for _, name := range numbered[1:] { + if _, err := os.Stat(name); !os.IsNotExist(err) { + t.Fatalf("%s still exists after a prune that keeps one backup (err %v)", name, err) + } + } + for _, name := range foreign { + if _, err := os.Stat(name); err != nil { + t.Fatalf("the prune removed %s, which it does not own: %v", name, err) + } + } +} + +func Test_rotatingFileKeepsFilesAboveTheCount(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 2 * rotatingFileTestLineSize, backups: 1}) + late := rf.backupPath(3) + if err := os.WriteFile(late, []byte("late\n"), 0600); err != nil { + t.Fatalf("write the late backup: %v", err) + } + + for seq := 1; seq <= 3; seq++ { + if _, err := rf.Write(rotatingFileTestLine(1, seq)); err != nil { + t.Fatalf("write %d: %v", seq, err) + } + } + + if _, err := os.Stat(late); err != nil { + t.Fatalf("a rotation removed %s, which sits above the backup count: %v", late, err) + } + if _, err := os.Stat(rf.backupPath(1)); err != nil { + t.Fatalf("the rotation left no .1 file: %v", err) + } +} + +func Test_rotatingFileDoesNotFollowASymlink(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("the Windows opener takes no symlink flag") + } + dir := t.TempDir() + planted := filepath.Join(dir, "planted.log") + if err := os.WriteFile(planted, []byte("planted\n"), 0600); err != nil { + t.Fatalf("write the planted file: %v", err) + } + path := filepath.Join(dir, "ctrld.log") + if err := os.Symlink(planted, path); err != nil { + t.Fatalf("symlink: %v", err) + } + + rf, err := newRotatingFile(path, logBudget{maxSize: 4096, backups: 1}, nil) + + if err == nil { + _ = rf.close() + t.Fatal("newRotatingFile followed the symlink") + } + if got := rotatingFileTestContent(t, planted); got != "planted\n" { + t.Fatalf("the planted file = %q, want it untouched", got) + } +} + +func Test_rotatingFileKeepsContentWhenRenameFails(t *testing.T) { + renameErr := errors.New("rename refused") + renameFails := true + path := filepath.Join(t.TempDir(), "ctrld.log") + rf, err := newRotatingFile(path, logBudget{maxSize: 2 * rotatingFileTestLineSize, backups: 1}, nil) + if err != nil { + t.Fatalf("newRotatingFile: %v", err) + } + t.Cleanup(func() { _ = rf.close() }) + rf.rename = func(oldpath, newpath string) error { + if renameFails { + return renameErr + } + return os.Rename(oldpath, newpath) + } + + for seq := 1; seq <= 2; seq++ { + writeRotatingFileTestLine(t, rf, 1, seq) + } + record := writeRotatingFileTestLine(t, rf, 1, 3) + if record == nil { + t.Fatal("the write past the budget reported no rotation") + } + if !errors.Is(record.err, renameErr) { + t.Fatalf("record.err = %v, want %v", record.err, renameErr) + } + content := rotatingFileTestContent(t, path) + for seq := 1; seq <= 3; seq++ { + if want := fmt.Sprintf("gen=1 seq=%d ", seq); !strings.Contains(content, want) { + t.Fatalf("the file lost %q after a failed rename", want) + } + } + if _, err := os.Stat(path + ".1"); !os.IsNotExist(err) { + t.Fatalf("stat %s.1 = %v, want a not exist error", path, err) + } + if writeRotatingFileTestLine(t, rf, 1, 4) != nil { + t.Fatal("the next write rotated again instead of waiting for another budget") + } + + renameFails = false + var second *logRotation + for seq := 5; seq <= 6; seq++ { + if rotated := writeRotatingFileTestLine(t, rf, 1, seq); rotated != nil { + second = rotated + } + } + if second == nil { + t.Fatal("no rotation happened after the rename worked again") + } + if second.err != nil { + t.Fatalf("record.err = %v, want no error", second.err) + } + if _, err := os.Stat(path + ".1"); err != nil { + t.Fatalf("stat %s.1 after a working rename: %v", path, err) + } +} + +// Test_zeroBackupRotationKeepsTheOpenReader opens an upload reader over the +// current file, then rotates with no backup. The reader must return the bytes +// and the size that it advertised, and the current file holds the new +// generation only. +func Test_zeroBackupRotationKeepsTheOpenReader(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 1 << 20, backups: 0}) + if _, err := rf.Write([]byte("old generation!\n")); err != nil { + t.Fatal(err) + } + var upload logParts + upload.addBoundedFiles(rf.paths(), 0) + t.Cleanup(upload.close) + + if _, err := rf.rotateNow(); err != nil { + t.Fatalf("rotate: %v", err) + } + if _, err := rf.Write([]byte("new\n")); err != nil { + t.Fatal(err) + } + + got, err := io.ReadAll(io.MultiReader(upload.readers...)) + if err != nil { + t.Fatal(err) + } + if upload.size != 16 || string(got) != "old generation!\n" { + t.Fatalf("reader gave %q (%d bytes advertised), want the old generation of 16 bytes", got, upload.size) + } + if content := rotatingFileTestContent(t, rf.currentPath()); content != "new\n" { + t.Fatalf("current file = %q, want the new generation only", content) + } + if _, err := os.Stat(rf.currentPath() + rotatingSuffix); !os.IsNotExist(err) { + t.Fatalf("the moved file is still on disk: %v", err) + } +} diff --git a/cmd/cli/log_header.go b/cmd/cli/log_header.go new file mode 100644 index 0000000..f9a58f6 --- /dev/null +++ b/cmd/cli/log_header.go @@ -0,0 +1,339 @@ +package cli + +import ( + "bytes" + "cmp" + "net" + "net/netip" + "os" + "runtime" + "slices" + "strconv" + "sync" + "time" + + "github.com/rs/zerolog" + "github.com/Control-D-Inc/ctrld" + "tailscale.com/net/netmon" +) + +// processStartTime is the time this process started. A reader compares it with +// the time of the header line to tell a restart from a rotation. +var processStartTime = time.Now() + +const ( + // logHeaderMessage is the message of the header line. Log tools select the + // header by this message. + logHeaderMessage = "Log header" + + // interceptModeOff is the mode word for a ctrld that does not intercept. + interceptModeOff = "off" + + // logHeaderTriggerSend marks the header that a log request renders. It + // tells a reader that the line came from an upload, not from a file open. + logHeaderTriggerSend = "send" + + // upstreamTypeUnspecified names an upstream that has no type in the config. + // ctrld resolves the type at start, so the header must not claim one. + upstreamTypeUnspecified = "unspecified" +) + +// headerOSVersion reads the OS version once. The read starts a subprocess on +// macOS, and a header refresh follows every network change. +var headerOSVersion = sync.OnceValue(osVersion) + +// logHeaderInterface is one interface of the header network snapshot. +type logHeaderInterface struct { + Name string + Up bool + IPs []string +} + +// logHeaderNetwork is the minimal network snapshot of a header line. +type logHeaderNetwork struct { + DefaultRouteInterface string + HaveV4 bool + HaveV6 bool + Interfaces []logHeaderInterface +} + +// logHeaderInput holds every value of a header line. The caller collects the +// values, so the renderer stays free of locks and of system calls. +type logHeaderInput struct { + Version string + Commit string + OS string + Arch string + PID int + StartTime time.Time + InterceptMode string + Listeners []string + UpstreamCount int + UpstreamTypes []string + ResolverUID string + LogFiles []string + Network logHeaderNetwork + Trigger string +} + +// renderLogHeader renders the header as one log line. A file writer stores the +// bytes and writes them itself, so the header reaches a file that the logger +// never fills. +func renderLogHeader(in logHeaderInput) []byte { + var buf bytes.Buffer + logger := zerolog.New(&buf).With().Timestamp().Logger() + event := journal(logHeaderEvent(&logger)). + Str("version", in.Version). + Str("commit", in.Commit). + Str("os", in.OS). + Str("arch", in.Arch). + Int("pid", in.PID). + Str("start_time", in.StartTime.Format(time.RFC3339)). + Str("intercept_mode", in.InterceptMode). + Strs("listeners", in.Listeners). + Int("upstream_count", in.UpstreamCount). + Strs("upstream_types", in.UpstreamTypes). + Str("resolver_uid", in.ResolverUID). + Strs("log_files", in.LogFiles). + Dict("network", logHeaderNetworkDict(in.Network)) + if in.Trigger != "" { + event = event.Str("trigger", in.Trigger) + } + event.Msg(logHeaderMessage) + + // The header is the first line of every file and of every upload, and it + // bypasses the writers, so it passes the journal redaction here. + return redactRetainedLine(buf.Bytes()) +} + +// logHeaderEvent starts the header event at info level. The global level sits +// above info on a default start, and a log file must hold its header at every +// level, so the event names its level itself. +func logHeaderEvent(logger *zerolog.Logger) *zerolog.Event { + return logger.Log().Str(zerolog.LevelFieldName, zerolog.LevelInfoValue) +} + +func logHeaderNetworkDict(network logHeaderNetwork) *zerolog.Event { + interfaces := zerolog.Arr() + for _, iface := range network.Interfaces { + interfaces = interfaces.Dict(zerolog.Dict(). + Str("name", iface.Name). + Bool("up", iface.Up). + Strs("ips", iface.IPs)) + } + return zerolog.Dict(). + Str("default_route_interface", network.DefaultRouteInterface). + Bool("have_v4", network.HaveV4). + Bool("have_v6", network.HaveV6). + Array("interfaces", interfaces) +} + +// logHeaderNetworkFromState makes the header snapshot from a netmon state. +func logHeaderNetworkFromState(st *netmon.State) logHeaderNetwork { + if st == nil { + return logHeaderNetwork{} + } + network := logHeaderNetwork{ + DefaultRouteInterface: st.DefaultRouteInterface, + HaveV4: st.HaveV4, + HaveV6: st.HaveV6, + } + for name, iface := range st.Interface { + network.Interfaces = append(network.Interfaces, logHeaderInterface{ + Name: name, + Up: iface.Interface != nil && iface.IsUp(), + IPs: prefixStrings(st.InterfaceIPs[name]), + }) + } + slices.SortFunc(network.Interfaces, func(a, b logHeaderInterface) int { + return cmp.Compare(a.Name, b.Name) + }) + return network +} + +// logHeaderNetworkFresh reads the network now. A header that no network +// callback reached yet, and the header of an upload, need the live picture. +func logHeaderNetworkFresh() logHeaderNetwork { + state, err := readNetworkSourceStateFn() + if err != nil { + state = nil + } + network := logHeaderNetworkFromState(state) + if route, err := netmon.DefaultRouteInterface(); err == nil { + network.DefaultRouteInterface = route + } + network.HaveV4, network.HaveV6 = globalAddressFamilies(state) + return network +} + +// globalAddressFamilies reports which families the host can reach. A loopback +// or a link-local address reaches no other host, so it proves nothing. +func globalAddressFamilies(st *netmon.State) (haveV4, haveV6 bool) { + if st == nil { + return false, false + } + for name, iface := range st.Interface { + if iface.Interface == nil || !iface.IsUp() { + continue + } + for _, prefix := range st.InterfaceIPs[name] { + addr := prefix.Addr().Unmap() + if !addr.IsGlobalUnicast() || addr.IsLoopback() || addr.IsLinkLocalUnicast() { + continue + } + if addr.Is4() { + haveV4 = true + continue + } + haveV6 = true + } + } + return haveV4, haveV6 +} + +// logHeaderInput collects every header value of the running program. +func (p *prog) logHeaderInput() logHeaderInput { + in := logHeaderInput{ + Version: curVersion(), + Commit: commit, + OS: headerOSVersion(), + Arch: runtime.GOARCH, + PID: os.Getpid(), + StartTime: processStartTime, + // The resolver UID is a secret that the provisioning code strips from + // every artifact, so the header keeps its first characters only. + ResolverUID: redactToken(cdUID), + LogFiles: p.logHeaderFiles(), + Network: p.logHeaderNetwork(), + } + p.headerConfigInto(&in) + return in +} + +// headerConfigInto reads the config under p.mu, because a reload replaces the +// config under that lock while log view and log send render a header. +func (p *prog) headerConfigInto(in *logHeaderInput) { + p.mu.Lock() + defer p.mu.Unlock() + logHeaderFromConfig(p.cfg, in) +} + +// sendLogHeader renders the header that leads one upload. +func (p *prog) sendLogHeader() []byte { + in := p.logHeaderInput() + // The stored state can be older than the request, and support reads this + // line to learn the network of the moment the user asked. + in.Network = logHeaderNetworkFresh() + in.Trigger = logHeaderTriggerSend + return renderLogHeader(in) +} + +// noteNetworkState keeps the newest network that ctrld saw and puts it in the +// header bytes of every open log file. The caller must hold no lock, because +// the render reads the config and the network. +func (p *prog) noteNetworkState(st *netmon.State) { + if st != nil { + p.lastNetworkState.Store(st) + } + p.refreshLogHeader() +} + +// logHeaderNetwork takes the network that the last monitor callback reported. +func (p *prog) logHeaderNetwork() logHeaderNetwork { + state := p.lastNetworkState.Load() + if state == nil { + return logHeaderNetworkFresh() + } + return logHeaderNetworkFromState(state) +} + +// logHeaderFiles names the files that this run writes, debug first. +func (p *prog) logHeaderFiles() []string { + files := make([]string, 0, 3) + for _, rf := range p.openLogFiles() { + files = append(files, rf.currentPath()) + } + return files +} + +// refreshLogHeader renders the header and hands the bytes to every open file. +// The caller must hold no writer lock, because the render reads the config +// and the network. +func (p *prog) refreshLogHeader() { + header := renderLogHeader(p.logHeaderInput()) + for _, rf := range p.openLogFiles() { + rf.setHeader(header) + } +} + +// writeLogHeaders puts the header at the append point of each open file. A +// header that cannot land leaves the file usable, so the error only earns a +// warning. +func (p *prog) writeLogHeaders() { + for _, rf := range p.openLogFiles() { + if err := rf.writeHeader(); err != nil { + mainLog.Load().Warn().Err(err).Msg("could not write log header") + } + } +} + +func prefixStrings(prefixes []netip.Prefix) []string { + ips := make([]string, 0, len(prefixes)) + for _, prefix := range prefixes { + ips = append(ips, prefix.String()) + } + return ips +} + +// logHeaderFromConfig fills the header fields that the config holds. It keeps +// every upstream endpoint, name, and bootstrap IP out of them, because a token +// can hide in each of them. +func logHeaderFromConfig(cfg *ctrld.Config, in *logHeaderInput) { + if cfg == nil { + in.InterceptMode = interceptModeOff + return + } + in.InterceptMode = headerInterceptMode(cfg) + in.Listeners = listenerAddresses(cfg) + in.UpstreamCount = len(cfg.Upstream) + in.UpstreamTypes = upstreamTypeWords(cfg) +} + +// headerInterceptMode names the mode for the header. An unset mode means that +// ctrld does not intercept, which reads as off. +func headerInterceptMode(cfg *ctrld.Config) string { + if mode := listenerInterceptMode(cfg); mode != "" { + return mode + } + return interceptModeOff +} + +func listenerAddresses(cfg *ctrld.Config) []string { + addresses := make([]string, 0, len(cfg.Listener)) + for _, listener := range cfg.Listener { + if listener == nil { + continue + } + addresses = append(addresses, net.JoinHostPort(listener.IP, strconv.Itoa(listener.Port))) + } + slices.Sort(addresses) + return addresses +} + +func upstreamTypeWords(cfg *ctrld.Config) []string { + words := make([]string, 0, len(cfg.Upstream)) + for _, upstream := range cfg.Upstream { + if upstream == nil { + continue + } + word := upstream.Type + if word == "" { + word = upstreamTypeUnspecified + } + if !slices.Contains(words, word) { + words = append(words, word) + } + } + slices.Sort(words) + return words +} diff --git a/cmd/cli/log_header_test.go b/cmd/cli/log_header_test.go new file mode 100644 index 0000000..48d4968 --- /dev/null +++ b/cmd/cli/log_header_test.go @@ -0,0 +1,617 @@ +package cli + +import ( + "encoding/json" + "io" + "net" + "net/netip" + "os" + "path/filepath" + "reflect" + "strings" + "testing" + "time" + + "github.com/rs/zerolog" + "github.com/Control-D-Inc/ctrld" + "tailscale.com/net/netmon" +) + +// logHeaderTestSecret is the string that must never reach a header line. +const logHeaderTestSecret = "secret-token" + +// logHeaderTestLine is the parsed form of a header line. The json tags name +// the fields that a log tool reads, so a renamed field fails the test. +type logHeaderTestLine struct { + Level string `json:"level"` + Time string `json:"time"` + Journal bool `json:"journal"` + Message string `json:"message"` + Version string `json:"version"` + Commit string `json:"commit"` + OS string `json:"os"` + Arch string `json:"arch"` + PID int `json:"pid"` + StartTime string `json:"start_time"` + InterceptMode string `json:"intercept_mode"` + Listeners []string `json:"listeners"` + UpstreamCount int `json:"upstream_count"` + UpstreamTypes []string `json:"upstream_types"` + ResolverUID string `json:"resolver_uid"` + LogFiles []string `json:"log_files"` + Network struct { + DefaultRouteInterface string `json:"default_route_interface"` + HaveV4 bool `json:"have_v4"` + HaveV6 bool `json:"have_v6"` + Interfaces []struct { + Name string `json:"name"` + Up bool `json:"up"` + IPs []string `json:"ips"` + } `json:"interfaces"` + } `json:"network"` + Trigger string `json:"trigger"` +} + +func logHeaderTestInput() logHeaderInput { + return logHeaderInput{ + Version: "1.5.8", + Commit: "abc1234", + OS: "darwin 15.6", + Arch: "arm64", + PID: 4242, + StartTime: time.Date(2026, 9, 16, 12, 0, 0, 0, time.UTC), + InterceptMode: "dns", + Listeners: []string{"127.0.0.1:53", "127.0.0.1:5354"}, + UpstreamCount: 2, + UpstreamTypes: []string{"doh", "os"}, + ResolverUID: redactToken("abcd1234"), + LogFiles: []string{"/tmp/ctrld.log", "/tmp/ctrld-journal.log"}, + Network: logHeaderNetwork{ + DefaultRouteInterface: "en0", + HaveV4: true, + Interfaces: []logHeaderInterface{ + {Name: "en0", Up: true, IPs: []string{"192.0.2.10/24"}}, + }, + }, + } +} + +// parseLogHeader checks that the render is one line and returns it twice: as +// values, and as raw fields for the tests that ask whether a field is there. +func parseLogHeader(t *testing.T, line []byte) (logHeaderTestLine, map[string]json.RawMessage) { + t.Helper() + if len(line) == 0 { + t.Fatal("renderLogHeader returned no bytes") + } + if line[len(line)-1] != '\n' { + t.Fatalf("header does not end with a newline: %q", line) + } + if count := strings.Count(string(line), "\n"); count != 1 { + t.Fatalf("header holds %d newlines, want 1: %q", count, line) + } + var parsed logHeaderTestLine + if err := json.Unmarshal(line, &parsed); err != nil { + t.Fatalf("parse header %q: %v", line, err) + } + fields := map[string]json.RawMessage{} + if err := json.Unmarshal(line, &fields); err != nil { + t.Fatalf("parse header fields %q: %v", line, err) + } + return parsed, fields +} + +func setLogHeaderTestGlobalLevel(t *testing.T, level zerolog.Level) { + t.Helper() + old := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(level) + t.Cleanup(func() { zerolog.SetGlobalLevel(old) }) +} + +func Test_renderLogHeaderHoldsEveryField(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + in := logHeaderTestInput() + + parsed, fields := parseLogHeader(t, renderLogHeader(in)) + + checks := []struct { + field string + got any + want any + }{ + {"level", parsed.Level, "info"}, + {"journal", parsed.Journal, true}, + {"message", parsed.Message, "Log header"}, + {"version", parsed.Version, in.Version}, + {"commit", parsed.Commit, in.Commit}, + {"os", parsed.OS, in.OS}, + {"arch", parsed.Arch, in.Arch}, + {"pid", parsed.PID, in.PID}, + {"start_time", parsed.StartTime, in.StartTime.Format(time.RFC3339)}, + {"intercept_mode", parsed.InterceptMode, in.InterceptMode}, + {"listeners", parsed.Listeners, in.Listeners}, + {"upstream_count", parsed.UpstreamCount, in.UpstreamCount}, + {"upstream_types", parsed.UpstreamTypes, in.UpstreamTypes}, + // The resolver UID is a secret, so the header keeps the first four + // characters only. + {"resolver_uid", parsed.ResolverUID, "abcd***"}, + {"log_files", parsed.LogFiles, in.LogFiles}, + {"network.default_route_interface", parsed.Network.DefaultRouteInterface, in.Network.DefaultRouteInterface}, + {"network.have_v4", parsed.Network.HaveV4, in.Network.HaveV4}, + {"network.have_v6", parsed.Network.HaveV6, in.Network.HaveV6}, + } + for _, c := range checks { + if !reflect.DeepEqual(c.got, c.want) { + t.Errorf("%s = %v, want %v", c.field, c.got, c.want) + } + } + + if len(parsed.Network.Interfaces) != 1 { + t.Fatalf("network.interfaces holds %d entries, want 1", len(parsed.Network.Interfaces)) + } + iface := parsed.Network.Interfaces[0] + if iface.Name != "en0" || !iface.Up || !reflect.DeepEqual(iface.IPs, []string{"192.0.2.10/24"}) { + t.Errorf("network.interfaces[0] = %+v, want en0 up with 192.0.2.10/24", iface) + } + if parsed.Time == "" { + t.Error("time is empty") + } + if _, ok := fields["trigger"]; ok { + t.Errorf("trigger is present for an empty Trigger: %s", fields["trigger"]) + } +} + +func Test_renderLogHeaderAddsTriggerWhenSet(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + in := logHeaderTestInput() + in.Trigger = "send" + + parsed, _ := parseLogHeader(t, renderLogHeader(in)) + + if parsed.Trigger != "send" { + t.Errorf("trigger = %q, want %q", parsed.Trigger, "send") + } +} + +// Test_renderLogHeaderIgnoresGlobalLevel guards the promise that every log file +// starts with a header. The global level sits above info on a default start. +func Test_renderLogHeaderIgnoresGlobalLevel(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.WarnLevel) + + parsed, _ := parseLogHeader(t, renderLogHeader(logHeaderTestInput())) + + if parsed.Level != "info" { + t.Errorf("level = %q, want %q", parsed.Level, "info") + } + if parsed.Message != "Log header" { + t.Errorf("message = %q, want %q", parsed.Message, "Log header") + } +} + +func Test_logHeaderFromConfigKeepsUpstreamSecretsOut(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + old := interceptMode + t.Cleanup(func() { interceptMode = old }) + interceptMode = "" + + cfg := &ctrld.Config{ + Listener: map[string]*ctrld.ListenerConfig{ + "0": {IP: "127.0.0.1", Port: 53}, + logHeaderTestSecret + "-l": {IP: "10.0.0.1", Port: 5354}, + }, + Upstream: map[string]*ctrld.UpstreamConfig{ + "0": { + Name: logHeaderTestSecret + "-name", + Type: "doh", + Endpoint: "https://dns.example/" + logHeaderTestSecret, + BootstrapIP: "192.0.2.53", + }, + "1": {Endpoint: "https://dns.example/" + logHeaderTestSecret}, + }, + } + cfg.Service.InterceptMode = "dns" + + in := logHeaderTestInput() + logHeaderFromConfig(cfg, &in) + + if in.InterceptMode != "dns" { + t.Errorf("intercept mode = %q, want %q", in.InterceptMode, "dns") + } + if want := []string{"10.0.0.1:5354", "127.0.0.1:53"}; !reflect.DeepEqual(in.Listeners, want) { + t.Errorf("listeners = %v, want %v", in.Listeners, want) + } + if in.UpstreamCount != 2 { + t.Errorf("upstream count = %d, want 2", in.UpstreamCount) + } + if want := []string{"doh", "unspecified"}; !reflect.DeepEqual(in.UpstreamTypes, want) { + t.Errorf("upstream types = %v, want %v", in.UpstreamTypes, want) + } + + line := renderLogHeader(in) + if strings.Contains(string(line), logHeaderTestSecret) { + t.Errorf("header holds %q: %s", logHeaderTestSecret, line) + } +} + +func Test_logHeaderFromConfigReportsOffWhenUnset(t *testing.T) { + old := interceptMode + t.Cleanup(func() { interceptMode = old }) + interceptMode = "" + + var in logHeaderInput + logHeaderFromConfig(&ctrld.Config{}, &in) + + if in.InterceptMode != "off" { + t.Errorf("intercept mode = %q, want %q", in.InterceptMode, "off") + } +} + +func Test_logHeaderNetworkFromState(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + state := &netmon.State{ + DefaultRouteInterface: "en0", + HaveV4: true, + Interface: map[string]netmon.Interface{ + "en0": {Interface: &net.Interface{Name: "en0", Flags: net.FlagUp}}, + "awdl0": {Interface: &net.Interface{Name: "awdl0"}}, + }, + InterfaceIPs: map[string][]netip.Prefix{ + "en0": {netip.MustParsePrefix("192.0.2.10/24"), netip.MustParsePrefix("2001:db8::1/64")}, + }, + } + + network := logHeaderNetworkFromState(state) + + want := logHeaderNetwork{ + DefaultRouteInterface: "en0", + HaveV4: true, + Interfaces: []logHeaderInterface{ + {Name: "awdl0", Up: false, IPs: []string{}}, + {Name: "en0", Up: true, IPs: []string{"192.0.2.10/24", "2001:db8::1/64"}}, + }, + } + if !reflect.DeepEqual(network, want) { + t.Fatalf("network = %+v, want %+v", network, want) + } + + in := logHeaderTestInput() + in.Network = network + parsed, _ := parseLogHeader(t, renderLogHeader(in)) + if parsed.Network.DefaultRouteInterface != "en0" { + t.Errorf("network.default_route_interface = %q, want %q", parsed.Network.DefaultRouteInterface, "en0") + } + if len(parsed.Network.Interfaces) != 2 { + t.Fatalf("network.interfaces holds %d entries, want 2", len(parsed.Network.Interfaces)) + } + if parsed.Network.Interfaces[0].Name != "awdl0" || parsed.Network.Interfaces[0].Up { + t.Errorf("network.interfaces[0] = %+v, want awdl0 down", parsed.Network.Interfaces[0]) + } + if got := parsed.Network.Interfaces[1].IPs; !reflect.DeepEqual(got, []string{"192.0.2.10/24", "2001:db8::1/64"}) { + t.Errorf("network.interfaces[1].ips = %v", got) + } +} + +func Test_logHeaderNetworkFromStateWithoutState(t *testing.T) { + if network := logHeaderNetworkFromState(nil); !reflect.DeepEqual(network, logHeaderNetwork{}) { + t.Errorf("network = %+v, want the zero value", network) + } +} + +// setupLogHeaderWiringTest puts ctrld in cd mode with a temporary home +// directory, so initInternalLogging writes its files there. Every global that +// the logging setup touches goes back when the test ends. +func setupLogHeaderWiringTest(t *testing.T) string { + t.Helper() + origSilent, origCdUID, origHomedir, origVerbose := silent, cdUID, homedir, verbose + origMainLog, origProxyLogger := mainLog.Load(), ctrld.ProxyLogger.Load() + origLevel := zerolog.GlobalLevel() + origLogPathFile := logPathFile.Load() + t.Cleanup(func() { + silent, cdUID, homedir, verbose = origSilent, origCdUID, origHomedir, origVerbose + mainLog.Store(origMainLog) + ctrld.ProxyLogger.Store(origProxyLogger) + zerolog.SetGlobalLevel(origLevel) + logPathFile.Store(origLogPathFile) + }) + + homedir = t.TempDir() + cdUID = "header-wiring-uid" + silent, verbose = false, 0 + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + logPathFile.Store(nil) + return homedir +} + +// startLogHeaderWiringProg runs the internal logging setup and closes both +// files when the test ends. +func startLogHeaderWiringProg(t *testing.T) *prog { + t.Helper() + p := &prog{cfg: &ctrld.Config{}} + p.initInternalLogging(nil) + t.Cleanup(func() { + p.internalLogWriter.closeLogFile() + p.internalJournalWriter.closeLogFile() + }) + return p +} + +// logHeaderFileLines parses every line of a log file. It returns line 1 and +// the number of header lines, so a test can tell a missing header from a +// repeated one. +func logHeaderFileLines(t *testing.T, path string) (logHeaderTestLine, int) { + t.Helper() + content := strings.TrimRight(rotatingFileTestContent(t, path), "\n") + if content == "" { + t.Fatalf("%s is empty", path) + } + var firstLine logHeaderTestLine + headers := 0 + for i, line := range strings.Split(content, "\n") { + var parsed logHeaderTestLine + if err := json.Unmarshal([]byte(line), &parsed); err != nil { + t.Fatalf("parse line %d of %s (%q): %v", i+1, path, line, err) + } + if i == 0 { + firstLine = parsed + } + if parsed.Message == logHeaderMessage { + headers++ + } + } + return firstLine, headers +} + +func Test_logHeaderWiring_writesHeaderOnStart(t *testing.T) { + dir := setupLogHeaderWiringTest(t) + + startLogHeaderWiringProg(t) + + for _, name := range []string{logFileName, journalLogFileName} { + path := filepath.Join(dir, name) + firstLine, headers := logHeaderFileLines(t, path) + if firstLine.Message != logHeaderMessage { + t.Errorf("line 1 of %s = %q, want %q", path, firstLine.Message, logHeaderMessage) + } + if !firstLine.Journal { + t.Errorf("line 1 of %s carries no journal marker", path) + } + if want := redactToken(cdUID); firstLine.ResolverUID != want { + t.Errorf("resolver_uid in %s = %q, want %q", path, firstLine.ResolverUID, want) + } + if headers != 1 { + t.Errorf("%s holds %d header lines, want 1", path, headers) + } + } +} + +func Test_logHeaderInput_keepsSecretsOut(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + dir := setupLogHeaderWiringTest(t) + origInterceptMode := interceptMode + t.Cleanup(func() { interceptMode = origInterceptMode }) + interceptMode = "" + p := &prog{cfg: &ctrld.Config{ + Listener: map[string]*ctrld.ListenerConfig{ + logHeaderTestSecret + "-listener": {IP: "127.0.0.1", Port: 53}, + }, + Upstream: map[string]*ctrld.UpstreamConfig{ + "0": { + Name: logHeaderTestSecret + "-name", + Type: "doh", + Endpoint: "https://dns.example/" + logHeaderTestSecret, + BootstrapIP: "192.0.2.53", + Domain: logHeaderTestSecret + ".example", + }, + }, + }} + p.initInternalLogging(nil) + t.Cleanup(func() { + p.internalLogWriter.closeLogFile() + p.internalJournalWriter.closeLogFile() + }) + + if line := renderLogHeader(p.logHeaderInput()); strings.Contains(string(line), logHeaderTestSecret) { + t.Errorf("the header holds %q: %s", logHeaderTestSecret, line) + } + + for _, name := range []string{logFileName, journalLogFileName} { + path := filepath.Join(dir, name) + if content := rotatingFileTestContent(t, path); strings.Contains(content, logHeaderTestSecret) { + t.Errorf("%s holds %q: %s", path, logHeaderTestSecret, content) + } + } +} + +func Test_logHeaderWiring_secondInitAddsNoHeader(t *testing.T) { + dir := setupLogHeaderWiringTest(t) + p := startLogHeaderWiringProg(t) + + p.initInternalLogging(nil) + + for _, name := range []string{logFileName, journalLogFileName} { + path := filepath.Join(dir, name) + if _, headers := logHeaderFileLines(t, path); headers != 1 { + t.Errorf("%s holds %d header lines after a second start, want 1", path, headers) + } + } +} + +func Test_logHeaderWiring_headerLeadsRotatedFile(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + captureMainLog(t) + lw, path := newTestFileLogWriter(t, testLogWriterBudget) + header := string(renderLogHeader(logHeaderInput{Version: "v1"})) + + rf := lw.rotating() + rf.setHeader([]byte(header)) + if err := rf.writeHeader(); err != nil { + t.Fatalf("writeHeader: %v", err) + } + linesPerFile := int(testLogWriterBudget.maxSize) / rotatingFileTestLineSize + for seq := 1; seq <= linesPerFile+1; seq++ { + if _, err := lw.Write(rotatingFileTestLine(1, seq)); err != nil { + t.Fatalf("write line %d: %v", seq, err) + } + } + + for _, name := range []string{path + ".1", path} { + if content := rotatingFileTestContent(t, name); !strings.HasPrefix(content, header) { + t.Errorf("%s starts with %q, want the header", name, strings.SplitN(content, "\n", 2)[0]) + } + } +} + +func Test_logHeaderWiring_restartAppendsHeader(t *testing.T) { + dir := setupLogHeaderWiringTest(t) + path := filepath.Join(dir, logFileName) + const seed = `{"level":"info","message":"line of the run before"}` + if err := os.WriteFile(path, []byte(seed+"\n"), 0o600); err != nil { + t.Fatalf("seed %s: %v", path, err) + } + + startLogHeaderWiringProg(t) + + lines := strings.Split(strings.TrimRight(rotatingFileTestContent(t, path), "\n"), "\n") + if len(lines) < 2 { + t.Fatalf("%s holds %d lines, want the seed line and the header", path, len(lines)) + } + if lines[0] != seed { + t.Errorf("line 1 of %s = %q, want the seed line", path, lines[0]) + } + var header logHeaderTestLine + if err := json.Unmarshal([]byte(lines[1]), &header); err != nil { + t.Fatalf("parse line 2 of %s (%q): %v", path, lines[1], err) + } + if header.Message != logHeaderMessage { + t.Errorf("line 2 of %s = %q, want %q", path, header.Message, logHeaderMessage) + } + if _, headers := logHeaderFileLines(t, path); headers != 1 { + t.Errorf("%s holds %d header lines, want 1", path, headers) + } +} + +func Test_logHeaderWiring_usesLastNetworkState(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + origRead := readNetworkSourceStateFn + t.Cleanup(func() { readNetworkSourceStateFn = origRead }) + p := &prog{cfg: &ctrld.Config{}} + + p.lastNetworkState.Store(&netmon.State{DefaultRouteInterface: "en7"}) + + if got := p.logHeaderInput().Network.DefaultRouteInterface; got != "en7" { + t.Errorf("default_route_interface = %q, want %q", got, "en7") + } + + p.lastNetworkState.Store(nil) + readNetworkSourceStateFn = func() (*netmon.State, error) { + return &netmon.State{ + Interface: map[string]netmon.Interface{"en9": {Interface: &net.Interface{Name: "en9", Flags: net.FlagUp}}}, + InterfaceIPs: map[string][]netip.Prefix{"en9": {netip.MustParsePrefix("192.0.2.9/24")}}, + }, nil + } + + network := p.logHeaderInput().Network + if len(network.Interfaces) != 1 || network.Interfaces[0].Name != "en9" || !network.Interfaces[0].Up { + t.Fatalf("interfaces = %+v, want one up en9", network.Interfaces) + } + if !network.HaveV4 { + t.Error("have_v4 = false, want true for a global unicast v4 address") + } + if network.HaveV6 { + t.Error("have_v6 = true, want false without a v6 address") + } +} + +// stubLogHeaderNetworkRead makes the fresh network read return one up +// interface, so a header test never depends on the host network. +func stubLogHeaderNetworkRead(t *testing.T, name string) { + t.Helper() + origRead := readNetworkSourceStateFn + t.Cleanup(func() { readNetworkSourceStateFn = origRead }) + readNetworkSourceStateFn = func() (*netmon.State, error) { + return &netmon.State{ + Interface: map[string]netmon.Interface{name: {Interface: &net.Interface{Name: name, Flags: net.FlagUp}}}, + InterfaceIPs: map[string][]netip.Prefix{name: {netip.MustParsePrefix("192.0.2.9/24")}}, + }, nil + } +} + +func Test_sendLogHeader_usesFreshNetworkAndTrigger(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + stubLogHeaderNetworkRead(t, "en9") + p := &prog{cfg: &ctrld.Config{}} + p.lastNetworkState.Store(&netmon.State{ + DefaultRouteInterface: "en7", + Interface: map[string]netmon.Interface{"en7": {Interface: &net.Interface{Name: "en7", Flags: net.FlagUp}}}, + InterfaceIPs: map[string][]netip.Prefix{"en7": {netip.MustParsePrefix("192.0.2.7/24")}}, + }) + + parsed, _ := parseLogHeader(t, p.sendLogHeader()) + + if parsed.Trigger != "send" { + t.Errorf("trigger = %q, want %q", parsed.Trigger, "send") + } + if parsed.Message != logHeaderMessage { + t.Errorf("message = %q, want %q", parsed.Message, logHeaderMessage) + } + names := make([]string, 0, len(parsed.Network.Interfaces)) + for _, iface := range parsed.Network.Interfaces { + names = append(names, iface.Name) + } + if want := []string{"en9"}; !reflect.DeepEqual(names, want) { + t.Fatalf("network.interfaces = %v, want %v from the fresh read", names, want) + } +} + +// Test_logHeaderInputReadsTheConfigUnderTheLock renders headers beside the +// config swap of a reload. The race detector fails the test when the render +// reads the config outside the lock. +func Test_logHeaderInputReadsTheConfigUnderTheLock(t *testing.T) { + stubLogHeaderNetworkRead(t, "en0") + p := &prog{cfg: &ctrld.Config{ + Listener: map[string]*ctrld.ListenerConfig{"0": {IP: "127.0.0.1", Port: 53}}, + Upstream: map[string]*ctrld.UpstreamConfig{"0": {Type: "doh"}}, + }} + reloaded := &ctrld.Config{ + Listener: map[string]*ctrld.ListenerConfig{"0": {IP: "127.0.0.1", Port: 5354}}, + Upstream: map[string]*ctrld.UpstreamConfig{"0": {Type: "doq"}, "1": {Type: "legacy"}}, + } + + stop := make(chan struct{}) + done := make(chan struct{}) + go func() { + defer close(done) + for { + select { + case <-stop: + return + default: + } + p.mu.Lock() + *p.cfg = *reloaded + p.mu.Unlock() + } + }() + for i := 0; i < 300; i++ { + if in := p.logHeaderInput(); len(in.Listeners) != 1 { + t.Fatalf("listeners = %v, want one", in.Listeners) + } + } + close(stop) + <-done +} + +// Test_renderLogHeaderPassesTheSink puts a provisioning secret where the +// header does not expect one. The header is the first line of every file and +// of every upload, so it must pass the same redaction as every other line. +func Test_renderLogHeaderPassesTheSink(t *testing.T) { + origUID := cdUID + cdUID = "abcd1234SECRETUID" + t.Cleanup(func() { cdUID = origUID }) + + line := string(renderLogHeader(logHeaderInput{Version: "1.0", LogFiles: []string{"/var/log/" + cdUID + "/ctrld.log"}})) + + if strings.Contains(line, cdUID) { + t.Fatalf("the header holds the secret: %s", line) + } +} diff --git a/cmd/cli/log_journal.go b/cmd/cli/log_journal.go new file mode 100644 index 0000000..0f851be --- /dev/null +++ b/cmd/cli/log_journal.go @@ -0,0 +1,68 @@ +package cli + +import ( + "bytes" + "io" + "regexp" + + "github.com/rs/zerolog" +) + +// journalField marks an event for the retained journal stream. +const journalField = "journal" + +// journalMarker is the serialized form of the journal field. The journal +// writer keeps a line below warn level only when the line contains it. +var journalMarker = []byte(`"` + journalField + `":true`) + +// retainedURLPath matches the part of a URL that follows the host. The class +// stops the match at the characters that end a value inside a JSON line. +var retainedURLPath = regexp.MustCompile(`(https?://[^/?"\\\s]+)[/?][^"\\\s]*`) + +// redactRetainedLine strips the secrets of one line that the journal keeps. +// Support downloads the journal whole, and any error text can carry a DoH URL +// with the resolver path and the packed query of the user. +func redactRetainedLine(p []byte) []byte { + stripped := retainedURLPath.ReplaceAll(p, []byte(`${1}/[redacted]`)) + return []byte(redactSecrets(string(stripped), provisionSecrets()...)) +} + +// journal marks an event for the retained journal stream. The event keeps +// its own level, so an info event stays info on the console. +func journal(e *zerolog.Event) *zerolog.Event { + return e.Bool(journalField, true) +} + +// journalLevelWriter passes on the lines that the journal keeps and drops the +// rest, so the journal holds a small history that survives a restart. +type journalLevelWriter struct { + w io.Writer +} + +var _ zerolog.LevelWriter = (*journalLevelWriter)(nil) + +func newJournalLevelWriter(w io.Writer) *journalLevelWriter { + return &journalLevelWriter{w: w} +} + +// WriteLevel reads the level first, because a compare costs less than a scan +// of the serialized line. +func (j *journalLevelWriter) WriteLevel(l zerolog.Level, p []byte) (int, error) { + if l < zerolog.WarnLevel && !bytes.Contains(p, journalMarker) { + // A dropped line reports a full write, because zerolog.MultiLevelWriter + // turns a short write into an error for the whole group of writers. + return len(p), nil + } + if _, err := j.w.Write(redactRetainedLine(p)); err != nil { + return 0, err + } + // The redacted line is shorter than the line the logger handed over, and a + // short write is an error for the whole group of writers. + return len(p), nil +} + +// Write has no level to read, so the marker alone decides. Every level below +// warn takes that path. +func (j *journalLevelWriter) Write(p []byte) (int, error) { + return j.WriteLevel(zerolog.DebugLevel, p) +} diff --git a/cmd/cli/log_journal_test.go b/cmd/cli/log_journal_test.go new file mode 100644 index 0000000..ff6fd49 --- /dev/null +++ b/cmd/cli/log_journal_test.go @@ -0,0 +1,255 @@ +package cli + +import ( + "bytes" + "io" + "path/filepath" + "strings" + "testing" + + "github.com/rs/zerolog" + + "github.com/Control-D-Inc/ctrld" +) + +func Test_journalSetsMarker(t *testing.T) { + var buf bytes.Buffer + logger := zerolog.New(&buf) + journal(logger.Info()).Msg("marked") + if !bytes.Contains(buf.Bytes(), journalMarker) { + t.Fatalf("journal event lacks the marker: %s", buf.String()) + } + if !bytes.Contains(buf.Bytes(), []byte(`"level":"info"`)) { + t.Fatalf("journal event changed its level: %s", buf.String()) + } +} + +// journalTestLine has the shape of a serialized event, so the direct write +// path sees the marker where zerolog puts it. +func journalTestLine(marked bool) []byte { + if marked { + return []byte(`{"level":"info","` + journalField + `":true,"message":"state"}` + "\n") + } + return []byte(`{"level":"info","message":"state"}` + "\n") +} + +func Test_journalLevelWriterKeepsWarningsAndMarkedLines(t *testing.T) { + level := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(zerolog.DebugLevel) + t.Cleanup(func() { zerolog.SetGlobalLevel(level) }) + + for _, tc := range []struct { + name string + log func(logger zerolog.Logger) + kept bool + }{ + {"info with the marker", func(logger zerolog.Logger) { journal(logger.Info()).Msg("state") }, true}, + {"info without the marker", func(logger zerolog.Logger) { logger.Info().Msg("state") }, false}, + {"warn without the marker", func(logger zerolog.Logger) { logger.Warn().Msg("slow") }, true}, + {"debug with the marker", func(logger zerolog.Logger) { journal(logger.Debug()).Msg("state") }, true}, + {"notice without the marker", func(logger zerolog.Logger) { logger.Notice().Msg("note") }, false}, + {"error without the marker", func(logger zerolog.Logger) { logger.Error().Msg("failed") }, true}, + } { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + tc.log(zerolog.New(zerolog.MultiLevelWriter(newJournalLevelWriter(&buf)))) + if kept := buf.Len() > 0; kept != tc.kept { + t.Fatalf("kept = %v, want %v, line: %q", kept, tc.kept, buf.String()) + } + }) + } +} + +func Test_journalLevelWriterWriteKeepsMarkedLineOnly(t *testing.T) { + var buf bytes.Buffer + writer := newJournalLevelWriter(&buf) + + marked := journalTestLine(true) + n, err := writer.Write(marked) + if err != nil || n != len(marked) { + t.Fatalf("write of a marked line = (%d, %v), want (%d, nil)", n, err, len(marked)) + } + if buf.String() != string(marked) { + t.Fatalf("journal holds %q, want %q", buf.String(), marked) + } + + plain := journalTestLine(false) + n, err = writer.Write(plain) + if err != nil || n != len(plain) { + t.Fatalf("write of a plain line = (%d, %v), want (%d, nil)", n, err, len(plain)) + } + if buf.String() != string(marked) { + t.Fatalf("journal kept an unmarked line: %q", buf.String()) + } +} + +// journalDoHError has the shape of a resolver error text: the DoH URL carries +// the resolver path and the packed query. +const journalDoHError = `Get "https://dns.example/org-v1-SECRET0123?dns=pOgBAAAB": dial tcp` + +// journalRedactedURL is what the sink keeps of journalDoHError. +const journalRedactedURL = "https://dns.example/[redacted]" + +// journalTestLogger returns a logger that writes through the journal sink. +func journalTestLogger(t *testing.T) (*bytes.Buffer, zerolog.Logger) { + t.Helper() + level := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(zerolog.DebugLevel) + t.Cleanup(func() { zerolog.SetGlobalLevel(level) }) + var buf bytes.Buffer + return &buf, zerolog.New(zerolog.MultiLevelWriter(newJournalLevelWriter(&buf))) +} + +func Test_journalLevelWriterRedactsAKeptLine(t *testing.T) { + buf, logger := journalTestLogger(t) + + logger.Warn().Str("error", journalDoHError).Msg("upstream failed") + + line := buf.String() + if !strings.Contains(line, journalRedactedURL) { + t.Fatalf("the sink kept the URL path: %s", line) + } + for _, secret := range []string{"SECRET0123", "pOgBAAAB"} { + if strings.Contains(line, secret) { + t.Fatalf("the sink kept %q: %s", secret, line) + } + } +} + +func Test_journalLevelWriterRedactsTheProvisionSecrets(t *testing.T) { + origCdUID := cdUID + t.Cleanup(func() { cdUID = origCdUID }) + cdUID = "org-v1-uidofthisdevice" + buf, logger := journalTestLogger(t) + + logger.Warn().Str("detail", "device "+cdUID+" is gone").Msg("provision failed") + + line := buf.String() + if strings.Contains(line, cdUID) { + t.Fatalf("the sink kept the resolver uid: %s", line) + } + if !strings.Contains(line, "[redacted]") { + t.Fatalf("the sink wrote no redaction mark: %s", line) + } +} + +func Test_journalLevelWriterDropsADebugLineWithAURL(t *testing.T) { + buf, logger := journalTestLogger(t) + + logger.Debug().Str("error", journalDoHError).Msg("upstream failed") + + if buf.Len() != 0 { + t.Fatalf("the sink kept a debug line: %s", buf.String()) + } +} + +func Test_journalLevelWriterRedactsAMarkedInfoLine(t *testing.T) { + buf, logger := journalTestLogger(t) + + journal(logger.Info()).Str("error", journalDoHError).Msg("upstream failed") + + line := buf.String() + if !strings.Contains(line, journalRedactedURL) { + t.Fatalf("the sink kept the URL path: %s", line) + } + if !strings.Contains(line, `"level":"info"`) { + t.Fatalf("the sink changed the level: %s", line) + } +} + +func Test_journalLevelWriterReportsTheOriginalLength(t *testing.T) { + var buf bytes.Buffer + writer := newJournalLevelWriter(&buf) + line := []byte(`{"level":"warn","error":"https://dns.example/org-v1-SECRET0123","message":"state"}` + "\n") + + n, err := writer.WriteLevel(zerolog.WarnLevel, line) + + if err != nil || n != len(line) { + t.Fatalf("write of a kept line = (%d, %v), want (%d, nil)", n, err, len(line)) + } + if buf.Len() >= len(line) { + t.Fatalf("the sink wrote no shorter line: %s", buf.String()) + } +} + +// startInternalLogging drives the real cd mode setup and returns the program +// and the directory that holds the debug file and the journal file. +func startInternalLogging(t *testing.T) (*prog, string) { + t.Helper() + origSilent, origCdUID, origHomedir, origVerbose := silent, cdUID, homedir, verbose + origMainLog, origProxyLog := mainLog.Load(), ctrld.ProxyLogger.Load() + origLevel := zerolog.GlobalLevel() + t.Cleanup(func() { + silent, cdUID, homedir, verbose = origSilent, origCdUID, origHomedir, origVerbose + mainLog.Store(origMainLog) + ctrld.ProxyLogger.Store(origProxyLog) + zerolog.SetGlobalLevel(origLevel) + }) + if origMainLog == nil { + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + } + + dir := t.TempDir() + homedir = dir + cdUID = "test-uid" + silent = false + verbose = 0 + + p := &prog{cfg: &ctrld.Config{}} + p.initInternalLogging(nil) + t.Cleanup(p.closeInternalLogs) + return p, dir +} + +// Test_initInternalLogging_redactsTheJournalFile drives a cd mode run: support +// downloads the journal file, so it holds the redacted URL, while the debug +// file stays raw for the developer who reads it on the host. +func Test_initInternalLogging_redactsTheJournalFile(t *testing.T) { + _, dir := startInternalLogging(t) + + mainLog.Load().Warn().Str("error", journalDoHError).Msg("upstream failed") + + journalText := rotatingFileTestContent(t, filepath.Join(dir, journalLogFileName)) + if !strings.Contains(journalText, journalRedactedURL) { + t.Fatalf("journal file misses the redacted URL: %s", journalText) + } + if strings.Contains(journalText, "SECRET0123") { + t.Fatalf("journal file kept the resolver path: %s", journalText) + } + + debugText := rotatingFileTestContent(t, filepath.Join(dir, logFileName)) + if !strings.Contains(debugText, "org-v1-SECRET0123?dns=pOgBAAAB") { + t.Fatalf("debug file lost the raw URL: %s", debugText) + } +} + +// Test_stopClosesTheInternalLogFiles proves that a stopped service leaves no +// open handle on the debug file and the journal file. +func Test_stopClosesTheInternalLogFiles(t *testing.T) { + origPin := cdDeactivationPin.Load() + t.Cleanup(func() { cdDeactivationPin.Store(origPin) }) + cdDeactivationPin.Store(defaultDeactivationPin) + + p, _ := startInternalLogging(t) + p.stopCh = make(chan struct{}) + p.dnsWatcherStopCh = make(chan struct{}) + for _, writer := range []*logWriter{p.internalLogWriter, p.internalJournalWriter} { + if writer.rotating() == nil { + t.Fatal("the setup opened no file") + } + } + + if err := p.Stop(nil); err != nil { + t.Fatalf("Stop: %v", err) + } + + for name, writer := range map[string]*logWriter{ + logFileName: p.internalLogWriter, + journalLogFileName: p.internalJournalWriter, + } { + if writer.rotating() != nil { + t.Fatalf("%s stayed open after the stop", name) + } + } +} diff --git a/cmd/cli/log_path.go b/cmd/cli/log_path.go new file mode 100644 index 0000000..b4eb6c4 --- /dev/null +++ b/cmd/cli/log_path.go @@ -0,0 +1,73 @@ +package cli + +import ( + "os" + "sync/atomic" + + "github.com/Control-D-Inc/ctrld/internal/router" +) + +// logPathFile is the open log_path file. The header renderer and the log +// readers need it, and both run outside this file. +var logPathFile atomic.Pointer[rotatingFile] + +// pendingLogPathRotation holds the rotation of a start-time backup. The +// logger reaches no file at that point, so initLogging reports it later. +var pendingLogPathRotation atomic.Pointer[logRotation] + +// openLogPathWriter opens the log_path file of this run and stores it for the +// header renderer and the log readers. It returns nil when no log_path is set. +// A start calls it more than once, so a call for the file that is already open +// keeps that file: a second open would put a second header in it. +func openLogPathWriter(doBackup bool) *rotatingFile { + logFilePath := normalizeLogFilePath(cfg.Service.LogPath) + if logFilePath == "" { + return nil + } + budget := debugLogBudget(&cfg.Service, router.Name() != "") + rf := logPathFile.Load() + if rf == nil || rf.currentPath() != logFilePath { + rf = newLogPathFile(logFilePath, budget) + } else { + rf.setBudget(budget) + } + if doBackup { + backupLogPathFile(rf) + } + return rf +} + +// newLogPathFile opens path and puts it in place of the file of an earlier +// call. A ctrld that cannot write the log file its operator asked for leaves +// no record of the run, so the open failure ends the process. +func newLogPathFile(path string, budget logBudget) *rotatingFile { + rf, err := newRotatingFile(path, budget, nil) + if err != nil { + mainLog.Load().Error().Msgf("failed to create log file: %v", err) + os.Exit(1) + } + rf.onRotate = emitLogRotated + if old := logPathFile.Swap(rf); old != nil { + _ = old.close() + } + return rf +} + +// backupLogPathFile moves the file of an earlier run away, so no run +// overwrites another. +func backupLogPathFile(rf *rotatingFile) { + if !logFileHasContent(rf.currentPath()) { + return + } + record, err := rf.rotateNow() + if err != nil { + mainLog.Load().Error().Msgf("could not backup old log file: %v", err) + return + } + pendingLogPathRotation.Store(record) +} + +func logFileHasContent(path string) bool { + st, err := os.Stat(path) + return err == nil && st.Size() > 0 +} diff --git a/cmd/cli/log_path_rotation_test.go b/cmd/cli/log_path_rotation_test.go new file mode 100644 index 0000000..aad30de --- /dev/null +++ b/cmd/cli/log_path_rotation_test.go @@ -0,0 +1,187 @@ +package cli + +import ( + "encoding/json" + "io" + "os" + "path/filepath" + "slices" + "strings" + "testing" + + "github.com/rs/zerolog" + + "github.com/Control-D-Inc/ctrld" +) + +const ( + logPathTestBackups = 2 + logPathTestBudgetMB = 1 + logPathTestLineSize = 4 * 1024 + logPathTestLineCount = 300 +) + +// setupLogPathTest points log_path at a temporary file and puts every global +// that initLoggingWithBackup touches back when the test ends. The globals are +// the reason why no test of this package calls t.Parallel. +// +// The temporary directory comes first: its own cleanup removes the directory, +// and a cleanup runs before every cleanup that was added earlier, so the file +// must close before that. +func setupLogPathTest(t *testing.T) string { + t.Helper() + dir := t.TempDir() + origLogPath, origLogLevel := cfg.Service.LogPath, cfg.Service.LogLevel + origMaxSizeMB, origMaxBackups := cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups + origSilent, origVerbose := silent, verbose + origConsoleWriter := consoleWriter + origMainLog, origProxyLogger := mainLog.Load(), ctrld.ProxyLogger.Load() + origLevel, origTimeFormat := zerolog.GlobalLevel(), zerolog.TimeFieldFormat + origLogPathFile, origPendingRotation := logPathFile.Load(), pendingLogPathRotation.Load() + t.Cleanup(func() { + if rf := logPathFile.Load(); rf != nil && rf != origLogPathFile { + _ = rf.close() + } + logPathFile.Store(origLogPathFile) + pendingLogPathRotation.Store(origPendingRotation) + cfg.Service.LogPath, cfg.Service.LogLevel = origLogPath, origLogLevel + cfg.Service.LogMaxSizeMB, cfg.Service.LogMaxBackups = origMaxSizeMB, origMaxBackups + silent, verbose = origSilent, origVerbose + consoleWriter = origConsoleWriter + mainLog.Store(origMainLog) + ctrld.ProxyLogger.Store(origProxyLogger) + zerolog.SetGlobalLevel(origLevel) + zerolog.TimeFieldFormat = origTimeFormat + }) + + backups := logPathTestBackups + cfg.Service.LogPath = filepath.Join(dir, "ctrld.log") + cfg.Service.LogLevel = "info" + cfg.Service.LogMaxSizeMB = logPathTestBudgetMB + cfg.Service.LogMaxBackups = &backups + silent, verbose = false, 0 + consoleWriter = zerolog.NewConsoleWriter(func(w *zerolog.ConsoleWriter) { w.Out = io.Discard }) + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + logPathFile.Store(nil) + pendingLogPathRotation.Store(nil) + return cfg.Service.LogPath +} + +func Test_logPathBackupChainOnStart(t *testing.T) { + path := setupLogPathTest(t) + if err := os.WriteFile(path, []byte("run1\n"), 0o600); err != nil { + t.Fatalf("seed log file: %v", err) + } + + initLoggingWithBackup(true) + if _, err := logPathFile.Load().Write([]byte("run2\n")); err != nil { + t.Fatalf("write run2: %v", err) + } + initLoggingWithBackup(true) + + newest := rotatingFileTestContent(t, path+".1") + if !strings.Contains(newest, "run2") { + t.Fatalf("%s.1 = %q, want the run2 line", path, newest) + } + if strings.Contains(newest, "run1") { + t.Fatalf("%s.1 = %q, want no run1 line", path, newest) + } + oldest := rotatingFileTestContent(t, path+".2") + if !strings.Contains(oldest, "run1") { + t.Fatalf("%s.2 = %q, want the run1 line", path, oldest) + } + current := rotatingFileTestContent(t, path) + if strings.Contains(current, "run1") || strings.Contains(current, "run2") { + t.Fatalf("%s = %q, want neither run line", path, current) + } +} + +func Test_logPathRotatesBySize(t *testing.T) { + path := setupLogPathTest(t) + initLoggingWithBackup(false) + + line := strings.Repeat("x", logPathTestLineSize) + for i := 0; i < logPathTestLineCount; i++ { + mainLog.Load().Info().Msg(line) + } + + if _, err := os.Stat(path + ".2"); !os.IsNotExist(err) { + t.Fatalf("%s.2 exists although the lines fill one backup (stat err = %v)", path, err) + } + want := []string{path + ".1", path} + if got := logPathFile.Load().paths(); !slices.Equal(got, want) { + t.Fatalf("paths() = %v, want %v", got, want) + } + + rotatedLines := 0 + for _, logLine := range strings.Split(rotatingFileTestContent(t, path), "\n") { + if !strings.Contains(logLine, "Log rotated") { + continue + } + rotatedLines++ + if !strings.Contains(logLine, string(journalMarker)) { + t.Fatalf("Log rotated line %q carries no journal marker", logLine) + } + } + if rotatedLines != 1 { + t.Fatalf("Log rotated lines in %s = %d, want 1", path, rotatedLines) + } +} + +func Test_logPathHeaderLeadsEveryFile(t *testing.T) { + path := setupLogPathTest(t) + stubLogHeaderNetworkRead(t, "en0") + p := &prog{cfg: &cfg} + + // A start wires its logging twice: once for the config it reads from + // disk, and once more for the config that the API sends. + p.initLogging(true) + p.initLogging(false) + + line := strings.Repeat("x", logPathTestLineSize) + for i := 0; i < logPathTestLineCount; i++ { + mainLog.Load().Info().Msg(line) + } + + for _, name := range []string{path + ".1", path} { + firstLine, headers := logHeaderFileLines(t, name) + if firstLine.Message != logHeaderMessage { + t.Errorf("line 1 of %s = %q, want %q", name, firstLine.Message, logHeaderMessage) + } + if headers != 1 { + t.Errorf("%s holds %d header lines, want 1", name, headers) + } + } +} + +func Test_logPathStartBackupLogsRotation(t *testing.T) { + path := setupLogPathTest(t) + stubLogHeaderNetworkRead(t, "en0") + if err := os.WriteFile(path, []byte(`{"level":"info","message":"run1"}`+"\n"), 0o600); err != nil { + t.Fatalf("seed log file: %v", err) + } + p := &prog{cfg: &cfg} + + p.initLogging(true) + + rotatedLines := 0 + for _, logLine := range strings.Split(rotatingFileTestContent(t, path), "\n") { + if !strings.Contains(logLine, "Log rotated") { + continue + } + rotatedLines++ + var event struct { + File string `json:"file"` + } + if err := json.Unmarshal([]byte(logLine), &event); err != nil { + t.Fatalf("parse %q: %v", logLine, err) + } + if event.File != path+".1" { + t.Errorf("file = %q, want %q", event.File, path+".1") + } + } + if rotatedLines != 1 { + t.Fatalf("Log rotated lines in %s = %d, want 1", path, rotatedLines) + } +} diff --git a/cmd/cli/log_reader.go b/cmd/cli/log_reader.go new file mode 100644 index 0000000..fd0ce40 --- /dev/null +++ b/cmd/cli/log_reader.go @@ -0,0 +1,291 @@ +package cli + +import ( + "bytes" + "errors" + "io" + "os" + "strings" +) + +// logSendDebugBudget bounds the debug bytes of one upload. The journal is +// always whole, so an upload stays small and keeps the retained stream. A test +// lowers it, because a few small files must cross it. +var logSendDebugBudget int64 = 10 << 20 + +// lineScanBufferSize bounds the memory that the search for a line boundary +// needs, whatever the length of the line. +const lineScanBufferSize = 32 * 1024 + +var ( + errInternalLogEmpty = errors.New("internal log is empty") + errLogFileEmpty = errors.New("log file is empty") +) + +type logReader struct { + r io.ReadCloser + size int64 +} + +// logFilePart is the part of one open log file that an upload carries. An +// offset of 0 means the whole file. size is the size at the open, so a write +// after the selection stays out of the upload and the budget holds. +type logFilePart struct { + path string + f *os.File + offset int64 + size int64 +} + +// logReader composes the upload of the current logging mode and leads it with +// the header of this request. full lifts the bound on the debug bytes. +func (p *prog) logReader(full bool) (*logReader, error) { + lr, err := p.modeLogReader(full) + if err != nil { + return nil, err + } + // An empty upload must stay empty, because the handlers answer 301 on a + // size of 0. + if lr.size == 0 { + return lr, nil + } + header := p.sendLogHeader() + return &logReader{ + r: &multiCloser{ + Reader: io.MultiReader(bytes.NewReader(header), lr.r), + closers: []io.Closer{lr.r}, + }, + size: lr.size + int64(len(header)), + }, nil +} + +// modeLogReader composes the body of the current logging mode. +func (p *prog) modeLogReader(full bool) (*logReader, error) { + if p.needInternalLogging() { + return p.internalLogReader(full) + } + return p.logPathReader(full) +} + +// internalLogReader puts the newest debug bytes first, then the marker, then +// the journal, so a support reader finds the retained stream after the marker. +func (p *prog) internalLogReader(full bool) (*logReader, error) { + lw, jlw := p.internalWriters() + if lw == nil { + return nil, errors.New("nil internal log writer") + } + if jlw == nil { + return nil, errors.New("nil internal journal writer") + } + + var upload logParts + debugBytes := upload.addStream(lw, logSendBudget(full)) + upload.addBytes([]byte(logWriterLogEndMarker)) + journalBytes := upload.addStream(jlw, 0) + // The marker alone is not a log, and the handlers answer 301 on an empty + // upload. + if debugBytes+journalBytes == 0 { + upload.close() + return nil, errInternalLogEmpty + } + return upload.reader(errInternalLogEmpty) +} + +// logPathReader composes the upload of the log_path stream. The journal needs +// internal logging, so this upload holds the debug files alone. A run that +// opened no log_path file has nothing to send. +func (p *prog) logPathReader(full bool) (*logReader, error) { + rf := logPathFile.Load() + if p.cfg.Service.LogPath == "" || rf == nil { + return emptyLogReader(), nil + } + var upload logParts + upload.addBoundedFiles(rf.paths(), logSendBudget(full)) + return upload.reader(errLogFileEmpty) +} + +// emptyLogReader yields no bytes, so the handlers answer 301 instead of +// sending an upload without a line. +func emptyLogReader() *logReader { + return &logReader{r: io.NopCloser(strings.NewReader(""))} +} + +// logSendBudget reports the debug bytes that one upload may carry. Zero means +// every file. +func logSendBudget(full bool) int64 { + if full { + return 0 + } + return logSendDebugBudget +} + +// boundedLogFiles opens the files, reads each size once, and picks the newest +// bytes that fit in budget. files come oldest first, and so do the parts. The +// oldest part starts at a line boundary, so the upload holds whole lines only. +// A budget of 0 or less takes every file. The files that fall out of the +// budget close here; the parts own the files they hold. +func boundedLogFiles(files []string, budget int64) []logFilePart { + parts := openLogParts(files) + remaining := budget + first := len(parts) + for first > 0 { + part := &parts[first-1] + if budget <= 0 || part.size <= remaining { + remaining -= part.size + first-- + continue + } + if offset, ok := lineStartAt(part.f, part.size-remaining); ok { + part.offset = offset + first-- + } + // Without a line boundary in the tail, the upload would start inside a + // line, so the file stays out. + break + } + for _, part := range parts[:first] { + part.f.Close() + } + return parts[first:] +} + +// openLogParts opens each file through the platform opener, whose share flags +// let a rotation move the file away while Windows reads it. A rotation can +// also move a file away between the listing and the open, so a file that does +// not open must not stop the rest. +func openLogParts(files []string) []logFilePart { + parts := make([]logFilePart, 0, len(files)) + for _, path := range files { + f, err := openLogFile(path, os.O_RDONLY) + if err != nil { + continue + } + st, err := f.Stat() + if err != nil { + f.Close() + continue + } + parts = append(parts, logFilePart{path: path, f: f, size: st.Size()}) + } + return parts +} + +// lineStartAt returns the offset where a whole line starts at or after from. +// A cut that already lands on a line start keeps the line that follows it. It +// reports false when no newline follows. +func lineStartAt(f *os.File, from int64) (int64, bool) { + if startsLine(f, from) { + return from, true + } + if _, err := f.Seek(from, io.SeekStart); err != nil { + return 0, false + } + buf := make([]byte, lineScanBufferSize) + offset := from + for { + n, readErr := f.Read(buf) + if index := bytes.IndexByte(buf[:n], '\n'); index >= 0 { + return offset + int64(index) + 1, true + } + offset += int64(n) + if readErr != nil { + return 0, false + } + } +} + +// startsLine reports whether from is the first byte of a line. +func startsLine(f *os.File, from int64) bool { + if from == 0 { + return true + } + var previous [1]byte + if _, err := f.ReadAt(previous[:], from-1); err != nil { + return false + } + return previous[0] == '\n' +} + +// logParts collects the readers of one upload and the files it must close. +type logParts struct { + readers []io.Reader + closers []io.Closer + size int64 +} + +func (lp *logParts) addBytes(b []byte) { + if len(b) == 0 { + return + } + lp.readers = append(lp.readers, bytes.NewReader(b)) + lp.size += int64(len(b)) +} + +// addFiles takes the open parts. Each reader ends at the size of the open, so +// the bytes that a writer adds later stay out of this upload. +func (lp *logParts) addFiles(parts []logFilePart) { + for _, part := range parts { + length := part.size - part.offset + if length <= 0 { + part.f.Close() + continue + } + lp.readers = append(lp.readers, io.NewSectionReader(part.f, part.offset, length)) + lp.closers = append(lp.closers, part.f) + lp.size += length + } +} + +// addBoundedFiles adds the newest bytes of files that fit in budget. A budget +// of 0 or less takes every file. +func (lp *logParts) addBoundedFiles(files []string, budget int64) { + lp.addFiles(boundedLogFiles(files, budget)) +} + +// addStream adds the bytes of one stream and reports how many it added. A +// stream that has a file takes its files, and a stream that keeps its lines in +// memory takes its buffer, so one failed file never hides the other stream. +func (lp *logParts) addStream(lw *logWriter, budget int64) int64 { + before := lp.size + if rf := lw.rotating(); rf != nil { + lp.addBoundedFiles(rf.paths(), budget) + return lp.size - before + } + lp.addBytes(lw.bufferedBytes()) + return lp.size - before +} + +// reader joins the parts. The size is the number of bytes that the reader +// yields, so the caller reports what it uploads. +func (lp *logParts) reader(empty error) (*logReader, error) { + if lp.size == 0 { + lp.close() + return nil, empty + } + return &logReader{ + r: &multiCloser{Reader: io.MultiReader(lp.readers...), closers: lp.closers}, + size: lp.size, + }, nil +} + +func (lp *logParts) close() { + for _, c := range lp.closers { + c.Close() + } +} + +// 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_reader_test.go b/cmd/cli/log_reader_test.go new file mode 100644 index 0000000..369401a --- /dev/null +++ b/cmd/cli/log_reader_test.go @@ -0,0 +1,572 @@ +package cli + +import ( + "bytes" + "errors" + "fmt" + "io" + "os" + "path/filepath" + "runtime" + "slices" + "strings" + "testing" + "time" + + "github.com/rs/zerolog" + + "github.com/Control-D-Inc/ctrld" +) + +const ( + boundedLogTestLineSize = 100 + boundedLogTestLineCount = 30 + boundedLogTestFileCount = 5 + boundedLogTestBudget = 10000 +) + +// boundedLogTestLine returns a line of a fixed size that names its file, so a +// test can tell one part from another. +func boundedLogTestLine(file, line int) []byte { + head := fmt.Sprintf("file=%d line=%d ", file, line) + return []byte(head + strings.Repeat("x", boundedLogTestLineSize-len(head)-1) + "\n") +} + +// writeBoundedLogTestFiles creates the log files of one stream, oldest first. +func writeBoundedLogTestFiles(t *testing.T) []string { + t.Helper() + dir := t.TempDir() + files := make([]string, 0, boundedLogTestFileCount) + for file := 0; file < boundedLogTestFileCount; file++ { + var content bytes.Buffer + for line := 0; line < boundedLogTestLineCount; line++ { + content.Write(boundedLogTestLine(file, line)) + } + path := filepath.Join(dir, fmt.Sprintf("ctrld.log.%d", boundedLogTestFileCount-file)) + if err := os.WriteFile(path, content.Bytes(), 0o600); err != nil { + t.Fatalf("write %s: %v", path, err) + } + files = append(files, path) + } + return files +} + +func logFilesContent(t *testing.T, files []string) []byte { + t.Helper() + var joined []byte + for _, path := range files { + joined = append(joined, []byte(rotatingFileTestContent(t, path))...) + } + return joined +} + +// boundedLogTestFileSize is the size of each file that the bounded reader +// tests select from. +const boundedLogTestFileSize = int64(boundedLogTestLineCount * boundedLogTestLineSize) + +// wantTailLine reports the first line that fits in budget, for a budget that +// ends inside the fourth newest file. A cut that lands on a line start keeps +// that line. +func wantTailLine(budget int64) int { + cut := boundedLogTestFileSize - (budget - 3*boundedLogTestFileSize) + line := cut / boundedLogTestLineSize + if cut%boundedLogTestLineSize != 0 { + line++ + } + return int(line) +} + +// assertTailPart checks that a part starts at a line boundary and that it +// starts with the expected whole line. +func assertTailPart(t *testing.T, part logFilePart, file, line int) { + t.Helper() + content := []byte(rotatingFileTestContent(t, part.path)) + if part.offset <= 0 || part.offset >= int64(len(content)) { + t.Fatalf("offset = %d, want a position inside %s", part.offset, part.path) + } + if content[part.offset-1] != '\n' { + t.Fatalf("offset %d in %s does not follow a newline", part.offset, part.path) + } + if want := boundedLogTestLine(file, line); !bytes.HasPrefix(content[part.offset:], want) { + t.Fatalf("tail of %s starts with %.24q, want %.24q", part.path, content[part.offset:], want) + } +} + +// closeLogParts closes the files of parts that no upload took. +func closeLogParts(parts []logFilePart) { + for _, part := range parts { + part.f.Close() + } +} + +// partsSize reports the bytes that the parts hold on disk. +func partsSize(t *testing.T, parts []logFilePart) int64 { + t.Helper() + var size int64 + for _, part := range parts { + content := rotatingFileTestContent(t, part.path) + size += int64(len(content)) - part.offset + } + return size +} + +// assertBoundedParts checks the shape that every bounded selection shares: +// the newest three files whole, oldest first, after the tail of the fourth. +func assertBoundedParts(t *testing.T, files []string, parts []logFilePart, tailLine int) { + t.Helper() + wantPaths := files[1:] + if len(parts) != len(wantPaths) { + t.Fatalf("parts = %d, want %d", len(parts), len(wantPaths)) + } + for i, part := range parts { + if part.path != wantPaths[i] { + t.Fatalf("parts[%d].path = %s, want %s", i, part.path, wantPaths[i]) + } + } + assertTailPart(t, parts[0], 1, tailLine) + for i, part := range parts[1:] { + if part.offset != 0 { + t.Fatalf("parts[%d].offset = %d, want the whole file", i+1, part.offset) + } + } +} + +func Test_boundedLogFiles(t *testing.T) { + files := writeBoundedLogTestFiles(t) + + t.Run("budget ends at a line boundary", func(t *testing.T) { + parts := boundedLogFiles(files, boundedLogTestBudget) + t.Cleanup(func() { closeLogParts(parts) }) + + assertBoundedParts(t, files, parts, wantTailLine(boundedLogTestBudget)) + // The cut lands on a line start, so the tail begins at the cut and the + // parts fill the budget exactly. + if size := partsSize(t, parts); size != boundedLogTestBudget { + t.Fatalf("size = %d, want the whole budget of %d", size, boundedLogTestBudget) + } + }) + + t.Run("budget ends inside a line", func(t *testing.T) { + const budget = boundedLogTestBudget + boundedLogTestLineSize/2 + parts := boundedLogFiles(files, budget) + t.Cleanup(func() { closeLogParts(parts) }) + + assertBoundedParts(t, files, parts, wantTailLine(budget)) + if size := partsSize(t, parts); size > budget { + t.Fatalf("size = %d, want at most %d", size, budget) + } + }) + + t.Run("no budget keeps every file", func(t *testing.T) { + parts := boundedLogFiles(files, 0) + t.Cleanup(func() { closeLogParts(parts) }) + + if len(parts) != len(files) { + t.Fatalf("parts = %d, want %d", len(parts), len(files)) + } + for i, part := range parts { + if part.path != files[i] || part.offset != 0 { + t.Fatalf("parts[%d] = %+v, want %s whole", i, part, files[i]) + } + } + want := int64(boundedLogTestFileCount) * boundedLogTestFileSize + if size := partsSize(t, parts); size != want { + t.Fatalf("size = %d, want %d", size, want) + } + }) +} + +// Test_logReaderDoesNotFollowASymlink covers the one open of the reader. A +// symlink in place of a log file points at a file of another owner, and the +// writer refuses it in the same way. +func Test_logReaderDoesNotFollowASymlink(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("the Windows opener takes no symlink flag") + } + dir := t.TempDir() + planted := filepath.Join(dir, "planted.log") + if err := os.WriteFile(planted, []byte("planted line\n"), 0600); err != nil { + t.Fatalf("write the planted file: %v", err) + } + path := filepath.Join(dir, "ctrld.log") + if err := os.Symlink(planted, path); err != nil { + t.Fatalf("symlink: %v", err) + } + + parts := boundedLogFiles([]string{path}, 4) + if len(parts) != 0 { + t.Fatalf("the selection opened a symlink: %+v", parts) + } + var upload logParts + upload.addFiles(parts) + if upload.size != 0 { + t.Fatalf("the upload holds %d bytes of a symlink, want none", upload.size) + } +} + +// internalLogReaderTestBudget keeps the files small: four lines fill one file, +// so a few writes build the whole backup chain. +var internalLogReaderTestBudget = logBudget{maxSize: 4 * rotatingFileTestLineSize, backups: 2} + +const internalLogReaderTestLines = 12 + +// newTestStreamWriter opens one persisted stream in the temporary home +// directory. +func newTestStreamWriter(t *testing.T, name string) *logWriter { + t.Helper() + lw := newLogWriterWithSize(logWriterSize) + if err := lw.setLogFile(absHomeDir(name), internalLogReaderTestBudget); err != nil { + t.Fatalf("setLogFile %s: %v", name, err) + } + t.Cleanup(lw.closeLogFile) + return lw +} + +// internalLogReaderTestSendBudget holds one debug file and a half, so the +// default upload cuts inside the oldest of the three files. +var internalLogReaderTestSendBudget = internalLogReaderTestBudget.maxSize * 3 / 2 + +// useTestSendBudget lowers the bound on the debug bytes of one upload, so a +// few small files cross it. +func useTestSendBudget(t *testing.T, budget int64) { + t.Helper() + origBudget := logSendDebugBudget + t.Cleanup(func() { logSendDebugBudget = origBudget }) + logSendDebugBudget = budget +} + +// setupInternalLogReaderTest returns a cd mode prog whose debug stream and +// journal stream both hold a full backup chain on disk. +func setupInternalLogReaderTest(t *testing.T) *prog { + t.Helper() + origSilent, origCdUID, origHomedir := silent, cdUID, homedir + t.Cleanup(func() { silent, cdUID, homedir = origSilent, origCdUID, origHomedir }) + captureMainLog(t) + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + stubLogHeaderNetworkRead(t, "en9") + silent, cdUID, homedir = false, "test-uid", t.TempDir() + + p := &prog{cfg: &ctrld.Config{}} + p.internalLogWriter = newTestStreamWriter(t, logFileName) + p.internalJournalWriter = newTestStreamWriter(t, journalLogFileName) + for seq := 1; seq <= internalLogReaderTestLines; seq++ { + if _, err := p.internalLogWriter.Write(rotatingFileTestLine(1, seq)); err != nil { + t.Fatalf("write debug line %d: %v", seq, err) + } + if _, err := p.internalJournalWriter.Write(rotatingFileTestLine(2, seq)); err != nil { + t.Fatalf("write journal line %d: %v", seq, err) + } + } + return p +} + +// readLogReader reads one upload and checks that the reported size is the +// number of bytes it yields. +func readLogReader(t *testing.T, p *prog, full bool) []byte { + t.Helper() + lr, err := p.logReader(full) + if err != nil { + t.Fatalf("logReader(%v): %v", full, err) + } + defer lr.r.Close() + data, err := io.ReadAll(lr.r) + if err != nil { + t.Fatalf("read upload: %v", err) + } + if lr.size != int64(len(data)) { + t.Fatalf("size = %d, want %d", lr.size, len(data)) + } + return data +} + +// splitSendHeader takes the header line off the front of an upload and checks +// that it names this request. It returns the rest of the upload. +func splitSendHeader(t *testing.T, upload []byte, since time.Time) []byte { + t.Helper() + end := bytes.IndexByte(upload, '\n') + if end < 0 { + t.Fatalf("upload holds no header line: %.64q", upload) + } + parsed, _ := parseLogHeader(t, upload[:end+1]) + if parsed.Message != logHeaderMessage { + t.Fatalf("line 1 of the upload = %q, want %q", parsed.Message, logHeaderMessage) + } + if parsed.Trigger != "send" { + t.Fatalf("trigger = %q, want %q", parsed.Trigger, "send") + } + rendered, err := time.Parse(time.RFC3339, parsed.Time) + if err != nil { + t.Fatalf("parse header time %q: %v", parsed.Time, err) + } + // The header format drops the fraction of a second, so the window starts + // at the second that holds since. + if rendered.Before(since.Truncate(time.Second)) || rendered.After(time.Now().Add(time.Second)) { + t.Fatalf("header time = %s, want a time between %s and now", rendered, since) + } + return upload[end+1:] +} + +// splitUpload takes the header off an upload and cuts the rest at the log end +// marker, which parts the debug bytes from the journal bytes. +func splitUpload(t *testing.T, upload []byte, since time.Time) (debugPart, journalPart []byte) { + t.Helper() + body := splitSendHeader(t, upload, since) + debugPart, journalPart, found := bytes.Cut(body, []byte(logWriterLogEndMarker)) + if !found { + t.Fatalf("upload holds no log end marker: %.64q", body) + } + return debugPart, journalPart +} + +func Test_logRequestPath(t *testing.T) { + if got := logRequestPath(sendLogsPath, false); got != sendLogsPath { + t.Fatalf("logRequestPath(%q, false) = %q, want the path itself", sendLogsPath, got) + } + want := viewLogsPath + "?full=1" + if got := logRequestPath(viewLogsPath, true); got != want { + t.Fatalf("logRequestPath(%q, true) = %q, want %q", viewLogsPath, got, want) + } +} + +func Test_logReader_internalComposition(t *testing.T) { + p := setupInternalLogReaderTest(t) + useTestSendBudget(t, internalLogReaderTestSendBudget) + + debugFiles := p.internalLogWriter.rotating().paths() + journalFiles := p.internalJournalWriter.rotating().paths() + wantFiles := internalLogReaderTestBudget.backups + 1 + if len(debugFiles) != wantFiles || len(journalFiles) != wantFiles { + t.Fatalf("files: debug %v, journal %v, want %d of each", debugFiles, journalFiles, wantFiles) + } + wholeDebug := logFilesContent(t, debugFiles) + wholeJournal := logFilesContent(t, journalFiles) + + start := time.Now() + debugPart, journalPart := splitUpload(t, readLogReader(t, p, false), start) + + if int64(len(debugPart)) > logSendDebugBudget { + t.Fatalf("debug part = %d bytes, want at most the budget of %d", len(debugPart), logSendDebugBudget) + } + if len(debugPart) >= len(wholeDebug) { + t.Fatalf("debug part = %d bytes, want fewer than the %d bytes of %v", len(debugPart), len(wholeDebug), debugFiles) + } + if !bytes.HasSuffix(wholeDebug, debugPart) { + t.Fatalf("debug part = %.24q, want the newest %d bytes of %v", debugPart, len(debugPart), debugFiles) + } + cut := len(wholeDebug) - len(debugPart) + if wholeDebug[cut-1] != '\n' { + t.Fatalf("the debug part starts at %d, which does not follow a newline", cut) + } + if !bytes.Equal(journalPart, wholeJournal) { + t.Fatalf("journal part = %d bytes, want the %d bytes of %v", len(journalPart), len(wholeJournal), journalFiles) + } + + // The full upload lifts the bound, so it holds every debug file. + fullDebug, fullJournal := splitUpload(t, readLogReader(t, p, true), start) + if !bytes.Equal(fullDebug, wholeDebug) { + t.Fatalf("full debug part = %d bytes, want the %d bytes of %v", len(fullDebug), len(wholeDebug), debugFiles) + } + if !bytes.Equal(fullJournal, wholeJournal) { + t.Fatalf("full journal part = %d bytes, want the %d bytes of %v", len(fullJournal), len(wholeJournal), journalFiles) + } +} + +func Test_logReader_logPathComposition(t *testing.T) { + path := setupLogPathTest(t) + stubLogHeaderNetworkRead(t, "en9") + initLoggingWithBackup(false) + + line := strings.Repeat("x", logPathTestLineSize) + for i := 0; i < logPathTestLineCount; i++ { + mainLog.Load().Info().Msg(line) + } + + files := logPathFile.Load().paths() + if want := []string{path + ".1", path}; !slices.Equal(files, want) { + t.Fatalf("paths() = %v, want %v", files, want) + } + + p := &prog{cfg: &cfg} + start := time.Now() + got := splitSendHeader(t, readLogReader(t, p, false), start) + if want := logFilesContent(t, files); !bytes.Equal(got, want) { + t.Fatalf("upload = %d bytes, want the %d bytes of %v", len(got), len(want), files) + } + if bytes.Contains(got, []byte(logWriterLogEndMarker)) { + t.Fatalf("log_path upload holds the log end marker") + } +} + +// setupMemoryLogReaderTest returns a cd mode prog whose streams keep their +// lines in memory, because no file is open. +func setupMemoryLogReaderTest(t *testing.T) *prog { + t.Helper() + origSilent, origCdUID := silent, cdUID + t.Cleanup(func() { silent, cdUID = origSilent, origCdUID }) + captureMainLog(t) + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + stubLogHeaderNetworkRead(t, "en9") + silent, cdUID = false, "test-uid" + + p := &prog{cfg: &ctrld.Config{}} + p.internalLogWriter = newLogWriterWithSize(logWriterSize) + p.internalJournalWriter = newLogWriterWithSize(logWriterSize) + return p +} + +func Test_logReader_memoryFallbackStartsWithHeader(t *testing.T) { + p := setupMemoryLogReaderTest(t) + debugLine := []byte("debug line\n") + journalLine := []byte("journal line\n") + if _, err := p.internalLogWriter.Write(debugLine); err != nil { + t.Fatalf("write the debug buffer: %v", err) + } + if _, err := p.internalJournalWriter.Write(journalLine); err != nil { + t.Fatalf("write the journal buffer: %v", err) + } + + start := time.Now() + got := splitSendHeader(t, readLogReader(t, p, false), start) + + var want []byte + want = append(want, debugLine...) + want = append(want, []byte(logWriterLogEndMarker)...) + want = append(want, journalLine...) + if !bytes.Equal(got, want) { + t.Fatalf("upload after the header = %q, want %q", got, want) + } +} + +// useTestHomeDir points the ctrld home directory at a temporary directory, so +// the internal log files of a test never reach the real one. +func useTestHomeDir(t *testing.T) { + t.Helper() + origHomedir := homedir + t.Cleanup(func() { homedir = origHomedir }) + homedir = t.TempDir() +} + +// newSeededJournalWriter writes the journal files of an earlier run and +// returns a new writer over them. Its memory buffer is empty, which is what a +// restart finds, so a rule that reads the buffer loses these lines. +func newSeededJournalWriter(t *testing.T, lines int) *logWriter { + t.Helper() + previous := newTestStreamWriter(t, journalLogFileName) + for seq := 1; seq <= lines; seq++ { + if _, err := previous.Write(rotatingFileTestLine(2, seq)); err != nil { + t.Fatalf("write journal line %d: %v", seq, err) + } + } + previous.closeLogFile() + return newTestStreamWriter(t, journalLogFileName) +} + +// mixedStreamJournalLines fill two journal files, because four lines fill one. +const mixedStreamJournalLines = 6 + +func Test_logReader_mixedStreams(t *testing.T) { + p := setupMemoryLogReaderTest(t) + useTestHomeDir(t) + p.internalJournalWriter = newSeededJournalWriter(t, mixedStreamJournalLines) + debugLine := []byte("debug line\n") + if _, err := p.internalLogWriter.Write(debugLine); err != nil { + t.Fatalf("write the debug buffer: %v", err) + } + journalFiles := p.internalJournalWriter.rotating().paths() + if len(journalFiles) != 2 { + t.Fatalf("journal files = %v, want two", journalFiles) + } + + start := time.Now() + got := splitSendHeader(t, readLogReader(t, p, false), start) + + var want []byte + want = append(want, debugLine...) + want = append(want, []byte(logWriterLogEndMarker)...) + want = append(want, logFilesContent(t, journalFiles)...) + if !bytes.Equal(got, want) { + t.Fatalf("upload after the header = %d bytes, want the %d bytes of the debug buffer, the marker and %v", len(got), len(want), journalFiles) + } +} + +func Test_logReader_emptyStaysEmpty(t *testing.T) { + t.Run("internal mode without a line", func(t *testing.T) { + p := setupMemoryLogReaderTest(t) + + lr, err := p.logReader(false) + + if !errors.Is(err, errInternalLogEmpty) { + t.Fatalf("logReader error = %v, want %v", err, errInternalLogEmpty) + } + if lr != nil { + t.Fatalf("logReader = %+v, want no reader", lr) + } + }) + + t.Run("internal mode with empty files", func(t *testing.T) { + p := setupMemoryLogReaderTest(t) + useTestHomeDir(t) + p.internalLogWriter = newTestStreamWriter(t, logFileName) + p.internalJournalWriter = newTestStreamWriter(t, journalLogFileName) + + lr, err := p.logReader(false) + + if !errors.Is(err, errInternalLogEmpty) { + t.Fatalf("logReader error = %v, want %v", err, errInternalLogEmpty) + } + if lr != nil { + t.Fatalf("logReader = %+v, want no reader", lr) + } + }) + + t.Run("no log_path to read", func(t *testing.T) { + origSilent, origCdUID := silent, cdUID + t.Cleanup(func() { silent, cdUID = origSilent, origCdUID }) + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + stubLogHeaderNetworkRead(t, "en9") + silent, cdUID = false, "" + + p := &prog{cfg: &ctrld.Config{}} + lr, err := p.logReader(false) + if err != nil { + t.Fatalf("logReader: %v", err) + } + defer lr.r.Close() + + if lr.size != 0 { + t.Fatalf("size = %d, want 0 so the handler answers 301", lr.size) + } + data, err := io.ReadAll(lr.r) + if err != nil { + t.Fatalf("read the upload: %v", err) + } + if len(data) != 0 { + t.Fatalf("upload = %q, want no bytes", data) + } + }) +} + +// Test_boundedLogFilesFixTheSizeAtSelection appends through the real writer +// between the selection and the reader creation. The upload must hold the +// bytes that the selection counted, so the budget holds under a live writer. +func Test_boundedLogFilesFixTheSizeAtSelection(t *testing.T) { + rf := newTestRotatingFile(t, logBudget{maxSize: 1 << 20, backups: 1}) + if _, err := rf.Write([]byte("one\n")); err != nil { + t.Fatal(err) + } + parts := boundedLogFiles(rf.paths(), 4) + if _, err := rf.Write([]byte("two\n")); err != nil { + t.Fatal(err) + } + + var upload logParts + upload.addFiles(parts) + t.Cleanup(upload.close) + got, err := io.ReadAll(io.MultiReader(upload.readers...)) + if err != nil { + t.Fatal(err) + } + if upload.size != 4 || string(got) != "one\n" { + t.Fatalf("upload = %q (%d bytes), want %q within the budget of 4", got, upload.size, "one\n") + } +} diff --git a/cmd/cli/log_tail_follow.go b/cmd/cli/log_tail_follow.go new file mode 100644 index 0000000..045b4e1 --- /dev/null +++ b/cmd/cli/log_tail_follow.go @@ -0,0 +1,80 @@ +package cli + +import ( + "context" + "io" + "net/http" + "os" + "time" +) + +// logTailPollInterval is the time between two reads of a tailed log file. +const logTailPollInterval = 200 * time.Millisecond + +// followLogFile streams the lines of path until ctx ends. It first sends the +// last numLines lines, or starts at the end when numLines is 0. A rotation +// moves the file away or truncates it, so the poll reopens the path when the +// file behind it changes or shrinks. +func followLogFile(ctx context.Context, w io.Writer, flusher http.Flusher, path string, numLines int) { + f, err := os.Open(path) + if err != nil { + return + } + defer func() { f.Close() }() + + if numLines > 0 { + if tail := tailFileLastLines(f, numLines); len(tail) > 0 { + w.Write(tail) + flusher.Flush() + } + } else { + f.Seek(0, io.SeekEnd) + } + + buf := make([]byte, 4096) + ticker := time.NewTicker(logTailPollInterval) + defer ticker.Stop() + for { + select { + case <-ticker.C: + n, err := f.Read(buf) + if n > 0 { + if _, werr := w.Write(buf[:n]); werr != nil { + return + } + flusher.Flush() + } + if err != nil && err != io.EOF { + return + } + if n == 0 && logFileReplaced(f, path) { + reopened, err := os.Open(path) + if err != nil { + continue + } + f.Close() + f = reopened + } + case <-ctx.Done(): + return + } + } +} + +// logFileReplaced reports whether path names another file than f, or a file +// shorter than the read position. Both mean that a rotation happened. +func logFileReplaced(f *os.File, path string) bool { + current, err := os.Stat(path) + if err != nil { + return false + } + open, err := f.Stat() + if err != nil { + return true + } + if !os.SameFile(current, open) { + return true + } + position, err := f.Seek(0, io.SeekCurrent) + return err == nil && current.Size() < position +} diff --git a/cmd/cli/log_writer.go b/cmd/cli/log_writer.go index 201968a..73b7f30 100644 --- a/cmd/cli/log_writer.go +++ b/cmd/cli/log_writer.go @@ -2,18 +2,14 @@ package cli import ( "bytes" - "errors" - "fmt" "io" - "os" - "path/filepath" - "strings" "sync" "time" "github.com/rs/zerolog" "github.com/Control-D-Inc/ctrld" + "github.com/Control-D-Inc/ctrld/internal/router" ) const ( @@ -24,8 +20,7 @@ const ( logWriterInitEndMarker = "\n\n=== INIT_END ===\n\n" logWriterLogEndMarker = "\n\n=== LOG_END ===\n\n" - logFileName = "ctrld.log" - logFileMaxSize = 1024 * 1024 * 5 // 5 MB + logFileName = "ctrld.log" ) type logViewResponse struct { @@ -37,29 +32,21 @@ type logSentResponse struct { Error string `json:"error"` } -type logReader struct { - r io.ReadCloser - size int64 -} - // 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 path is configured via setLogFile, writes are also persisted to -// a rotated file on disk (max logFileMaxSize, 1 backup) so logs survive restarts. +// 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 persistence fields. - logFile *os.File - logFilePath string - logFileSize int64 + file *rotatingFile } // newLogWriter creates an internal log writer. @@ -74,82 +61,50 @@ func newSmallLogWriter() *logWriter { // newLogWriterWithSize creates an internal log writer with a given buffer size. func newLogWriterWithSize(size int) *logWriter { - lw := &logWriter{size: size} - return lw + return &logWriter{size: size} } -// 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) +// 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 fmt.Errorf("opening log file: %w", err) - } - st, err := f.Stat() - if err != nil { - f.Close() - return fmt.Errorf("stat log file: %w", err) + return err } + rf.onRotate = emitLogRotated lw.mu.Lock() defer lw.mu.Unlock() - lw.logFile = f - lw.logFilePath = path - lw.logFileSize = st.Size() + lw.file = rf 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 + if lw.file == nil { + return } + lw.file.close() + lw.file = 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) { +// 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() - if lw.logFilePath == "" { - return "", "" - } - current = lw.logFilePath - bp := lw.logFilePath + ".1" - if _, err := os.Stat(bp); err == nil { - backup = bp - } - return current, backup + 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, @@ -200,6 +155,18 @@ func (lw *logWriter) tailLastLines(n int) []byte { } 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. +func (lw *logWriter) writeStreams(p []byte) (int, error) { lw.mu.Lock() defer lw.mu.Unlock() @@ -216,16 +183,6 @@ 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() @@ -254,6 +211,29 @@ func (lw *logWriter) Write(p []byte) (int, error) { 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) { zerolog.TimeFieldFormat = time.RFC3339 + ".000" @@ -261,12 +241,18 @@ func (p *prog) initLogging(backup bool) { // Initializing internal logging after global logging. 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) + if rf := logPathFile.Load(); rf != nil { + p.refreshLogHeader() + if err := rf.writeHeader(); err != nil { + mainLog.Load().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) + } } // initInternalLogging performs internal logging if there's no log enabled. @@ -274,46 +260,112 @@ func (p *prog) initInternalLogging(writers []io.Writer) { if !p.needInternalLogging() { return } + headersWritten := false p.initInternalLogWriterOnce.Do(func() { mainLog.Load().Notice().Msg("internal logging enabled") 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.internalJournalWriter = newSmallLogWriter() + p.openInternalLogFiles() + // A restart appends to the file it finds, so the header marks the + // point where this run starts. + p.refreshLogHeader() + p.writeLogHeaders() + headersWritten = true }) - p.mu.Lock() - lw := p.internalLogWriter - wlw := p.internalWarnLogWriter - p.mu.Unlock() + lw, jlw := p.internalWriters() // If ctrld was run without explicit verbose level, // run the internal logging at debug level, so we could // have enough information for troubleshooting. if verbose == 0 { - for i := range writers { - w := &zerolog.FilteredLevelWriter{ - Writer: zerolog.LevelWriterAdapter{Writer: writers[i]}, - Level: zerolog.NoticeLevel, - } - writers[i] = w - } + wrapConsoleWritersAtNotice(writers) zerolog.SetGlobalLevel(zerolog.DebugLevel) } - writers = append(writers, lw) - writers = append(writers, &zerolog.FilteredLevelWriter{ - Writer: zerolog.LevelWriterAdapter{Writer: wlw}, - Level: zerolog.WarnLevel, - }) + writers = append(writers, lw, newJournalLevelWriter(jlw)) multi := zerolog.MultiLevelWriter(writers...) l := mainLog.Load().Output(multi).With().Logger() mainLog.Store(&l) ctrld.ProxyLogger.Store(&l) + 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.refreshLogHeader() +} + +// wrapConsoleWritersAtNotice holds the console at notice level while the files +// take every level. A run without -v needs the detail for troubleshooting, and +// the same detail on the console is noise. +func wrapConsoleWritersAtNotice(writers []io.Writer) { + for i := range writers { + writers[i] = &zerolog.FilteredLevelWriter{ + Writer: zerolog.LevelWriterAdapter{Writer: writers[i]}, + Level: zerolog.NoticeLevel, + } + } +} + +// openInternalLogFiles persists both internal streams, so they survive a +// restart. +func (p *prog) openInternalLogFiles() { + isRouter := router.Name() != "" + _, journalBudget := logBudgets(isRouter) + openInternalLogFile(p.internalLogWriter, absHomeDir(logFileName), debugLogBudget(&p.cfg.Service, isRouter), "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. @@ -334,140 +386,3 @@ func (p *prog) needInternalLogging() bool { } return true } - -func (p *prog) logReader() (*logReader, error) { - if p.needInternalLogging() { - p.mu.Lock() - lw := p.internalLogWriter - wlw := p.internalWarnLogWriter - p.mu.Unlock() - if lw == nil { - return nil, errors.New("nil internal log writer") - } - if wlw == nil { - return nil, errors.New("nil internal warn log writer") - } - - // 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() - lw.mu.Unlock() - // Warn log content. - wlw.mu.Lock() - wlwReader := bytes.NewReader(wlw.buf.Bytes()) - wlwSize := wlw.buf.Len() - wlw.mu.Unlock() - reader := io.MultiReader(lwReader, bytes.NewReader([]byte(logWriterLogEndMarker)), wlwReader) - lr := &logReader{r: io.NopCloser(reader)} - lr.size = int64(lwSize + wlwSize) - if lr.size == 0 { - return nil, errors.New("internal log is empty") - } - return lr, nil - } - if p.cfg.Service.LogPath == "" { - return &logReader{r: io.NopCloser(strings.NewReader(""))}, nil - } - f, err := os.Open(normalizeLogFilePath(p.cfg.Service.LogPath)) - if err != nil { - return nil, err - } - lr := &logReader{r: f} - if st, err := f.Stat(); err == nil { - lr.size = st.Size() - } else { - return nil, fmt.Errorf("f.Stat: %w", err) - } - if lr.size == 0 { - return nil, errors.New("log file is empty") - } - 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_silent_test.go b/cmd/cli/log_writer_silent_test.go index e40f779..70eddb3 100644 --- a/cmd/cli/log_writer_silent_test.go +++ b/cmd/cli/log_writer_silent_test.go @@ -1,10 +1,14 @@ package cli import ( + "io" "os" "path/filepath" + "strings" "testing" + "github.com/rs/zerolog" + "github.com/Control-D-Inc/ctrld" ) @@ -59,8 +63,77 @@ func Test_initInternalLogging_silentCreatesNoFile(t *testing.T) { p := &prog{cfg: &ctrld.Config{}} p.initInternalLogging(nil) - logPath := filepath.Join(dir, logFileName) - if _, err := os.Stat(logPath); !os.IsNotExist(err) { - t.Fatalf("silent mode must not create %s (stat err = %v)", logPath, err) + for _, name := range []string{logFileName, journalLogFileName} { + path := filepath.Join(dir, name) + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("silent mode must not create %s (stat err = %v)", path, err) + } + } +} + +// Test_initInternalLogging_createsJournalFile drives a cd mode run and asserts +// that the journal file holds the retained lines only, while the debug file +// holds every line. +func Test_initInternalLogging_createsJournalFile(t *testing.T) { + origSilent, origCdUID, origHomedir, origVerbose := silent, cdUID, homedir, verbose + origMainLog, origProxyLog := mainLog.Load(), ctrld.ProxyLogger.Load() + origLevel := zerolog.GlobalLevel() + t.Cleanup(func() { + silent, cdUID, homedir, verbose = origSilent, origCdUID, origHomedir, origVerbose + mainLog.Store(origMainLog) + ctrld.ProxyLogger.Store(origProxyLog) + zerolog.SetGlobalLevel(origLevel) + }) + if origMainLog == nil { + discard := zerolog.New(io.Discard) + mainLog.Store(&discard) + } + + dir := t.TempDir() + homedir = dir + cdUID = "test-uid" + silent = false + verbose = 0 + + p := &prog{cfg: &ctrld.Config{}} + p.initInternalLogging(nil) + t.Cleanup(func() { + p.internalLogWriter.closeLogFile() + p.internalJournalWriter.closeLogFile() + }) + + debugPath := filepath.Join(dir, logFileName) + journalPath := filepath.Join(dir, journalLogFileName) + for _, path := range []string{debugPath, journalPath} { + if _, err := os.Stat(path); err != nil { + t.Fatalf("stat %s: %v", path, err) + } + } + + const ( + warnMsg = "retained warn line" + markedMsg = "retained marked info line" + plainMsg = "dropped plain info line" + ) + logger := mainLog.Load() + logger.Warn().Msg(warnMsg) + journal(logger.Info()).Msg(markedMsg) + logger.Info().Msg(plainMsg) + + journalText := rotatingFileTestContent(t, journalPath) + for _, msg := range []string{warnMsg, markedMsg} { + if !strings.Contains(journalText, msg) { + t.Fatalf("journal file misses %q: %s", msg, journalText) + } + } + if strings.Contains(journalText, plainMsg) { + t.Fatalf("journal file kept %q: %s", plainMsg, journalText) + } + + debugText := rotatingFileTestContent(t, debugPath) + for _, msg := range []string{warnMsg, markedMsg, plainMsg} { + if !strings.Contains(debugText, msg) { + t.Fatalf("debug file misses %q: %s", msg, debugText) + } } } diff --git a/cmd/cli/log_writer_test.go b/cmd/cli/log_writer_test.go index f6d1f94..24b268b 100644 --- a/cmd/cli/log_writer_test.go +++ b/cmd/cli/log_writer_test.go @@ -1,11 +1,17 @@ package cli import ( + "encoding/json" + "errors" "os" "path/filepath" + "slices" "strings" "sync" "testing" + "time" + + "github.com/rs/zerolog" ) func Test_logWriter_Write(t *testing.T) { @@ -86,14 +92,23 @@ func Test_logWriter_MarkerInitEnd(t *testing.T) { } } -func Test_logWriter_SetLogFile(t *testing.T) { - dir := t.TempDir() - path := filepath.Join(dir, "test.log") +// testLogWriterBudget keeps the rotation tests small: four lines fill the +// current file. +var testLogWriterBudget = logBudget{maxSize: 4 * rotatingFileTestLineSize, backups: 2} + +func newTestFileLogWriter(t *testing.T, budget logBudget) (*logWriter, string) { + t.Helper() + path := filepath.Join(t.TempDir(), "test.log") lw := newLogWriterWithSize(logWriterSize) - if err := lw.setLogFile(path); err != nil { + if err := lw.setLogFile(path, budget); err != nil { t.Fatalf("setLogFile: %v", err) } - defer lw.closeLogFile() + t.Cleanup(lw.closeLogFile) + return lw, path +} + +func Test_logWriter_SetLogFile(t *testing.T) { + lw, path := newTestFileLogWriter(t, testLogWriterBudget) msg := "hello file\n" lw.Write([]byte(msg)) @@ -113,69 +128,49 @@ func Test_logWriter_SetLogFile(t *testing.T) { } 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() + lw, path := newTestFileLogWriter(t, testLogWriterBudget) - // Write enough to exceed logFileMaxSize. - chunk := strings.Repeat("X", 1024) + "\n" - written := 0 - for written < logFileMaxSize+1024 { - lw.Write([]byte(chunk)) - written += len(chunk) + // Three rotations: each file takes four lines. + for seq := 1; seq <= 16; seq++ { + lw.Write(rotatingFileTestLine(1, seq)) } - // Backup file should exist. - backupPath := path + ".1" - if _, err := os.Stat(backupPath); os.IsNotExist(err) { - t.Fatal("expected backup file to exist after rotation") + for _, suffix := range []string{".1", ".2"} { + if _, err := os.Stat(path + suffix); err != nil { + t.Fatalf("stat %s: %v", path+suffix, err) + } + } + if _, err := os.Stat(path + ".3"); !os.IsNotExist(err) { + t.Fatalf("stat %s.3 = %v, want a not exist error", path, err) } - // 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()) + if want := testLogWriterBudget.maxSize + rotatingFileTestLineSize; st.Size() > want { + t.Fatalf("current file holds %d bytes after rotation, want at most %d", st.Size(), want) } } -func Test_logWriter_FilePaths(t *testing.T) { - dir := t.TempDir() - path := filepath.Join(dir, "test.log") +func Test_logWriter_RotatingPaths(t *testing.T) { lw := newLogWriterWithSize(logWriterSize) - - // No file configured. - c, b := lw.logFilePaths() - if c != "" || b != "" { - t.Fatalf("expected empty paths, got %q %q", c, b) + if lw.rotating() != nil { + t.Fatal("a writer without a file has a rotating file, want none") } - 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) + lw, path := newTestFileLogWriter(t, testLogWriterBudget) + if got, want := lw.rotating().paths(), []string{path}; !slices.Equal(got, want) { + t.Fatalf("paths = %v, want %v", got, want) } - // 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") + // Two rotations, so both backups exist. + for seq := 1; seq <= 9; seq++ { + lw.Write(rotatingFileTestLine(1, seq)) + } + want := []string{path + ".2", path + ".1", path} + if got := lw.rotating().paths(); !slices.Equal(got, want) { + t.Fatalf("paths = %v, want %v", got, want) } } @@ -185,7 +180,7 @@ func Test_logWriter_FileAppendOnRestart(t *testing.T) { // Simulate first run. lw1 := newLogWriterWithSize(logWriterSize) - if err := lw1.setLogFile(path); err != nil { + if err := lw1.setLogFile(path, testLogWriterBudget); err != nil { t.Fatalf("setLogFile: %v", err) } lw1.Write([]byte("run1\n")) @@ -193,7 +188,7 @@ func Test_logWriter_FileAppendOnRestart(t *testing.T) { // Simulate second run (restart) — file should be appended. lw2 := newLogWriterWithSize(logWriterSize) - if err := lw2.setLogFile(path); err != nil { + if err := lw2.setLogFile(path, testLogWriterBudget); err != nil { t.Fatalf("setLogFile: %v", err) } lw2.Write([]byte("run2\n")) @@ -208,3 +203,169 @@ func Test_logWriter_FileAppendOnRestart(t *testing.T) { t.Fatalf("file: got %q, want %q", data, want) } } + +func Test_logWriter_EmitsLogRotated(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + lw, path := newTestFileLogWriter(t, testLogWriterBudget) + + // The logger writes back into the writer that rotates, which is the case + // that deadlocks when the writer still holds its lock. + buf := &syncBuffer{} + logger := zerolog.New(zerolog.MultiLevelWriter(lw, buf)) + old := mainLog.Load() + mainLog.Store(&logger) + t.Cleanup(func() { mainLog.Store(old) }) + + done := make(chan struct{}) + go func() { + defer close(done) + for seq := 1; seq <= 5; seq++ { + lw.Write(rotatingFileTestLine(1, seq)) + } + }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("the writer did not return: the rotation event blocked on the writer lock") + } + + st, err := os.Stat(path + ".1") + if err != nil { + t.Fatalf("stat %s.1: %v", path, err) + } + + var rotatedLines []string + for _, line := range strings.Split(buf.String(), "\n") { + if strings.Contains(line, "Log rotated") { + rotatedLines = append(rotatedLines, line) + } + } + if len(rotatedLines) != 1 { + t.Fatalf("got %d Log rotated events, want 1: %q", len(rotatedLines), buf.String()) + } + if !strings.Contains(rotatedLines[0], string(journalMarker)) { + t.Fatalf("the event is not marked for the journal: %s", rotatedLines[0]) + } + var event struct { + File string `json:"file"` + BytesWritten int64 `json:"bytes_written"` + } + if err := json.Unmarshal([]byte(rotatedLines[0]), &event); err != nil { + t.Fatalf("unmarshal %s: %v", rotatedLines[0], err) + } + if event.File != path+".1" { + t.Fatalf("file = %q, want %q", event.File, path+".1") + } + if event.BytesWritten != st.Size() { + t.Fatalf("bytes_written = %d, want %d", event.BytesWritten, st.Size()) + } +} + +func Test_logWriter_NestedRotationStillEmitsEvent(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + debugLog, debugPath := newTestFileLogWriter(t, testLogWriterBudget) + journalLog, journalPath := newTestFileLogWriter(t, logBudget{maxSize: 2 * rotatingFileTestLineSize, backups: 1}) + + buf := &syncBuffer{} + logger := zerolog.New(zerolog.MultiLevelWriter(debugLog, journalLog, buf)) + old := mainLog.Load() + mainLog.Store(&logger) + t.Cleanup(func() { mainLog.Store(old) }) + + // Fill the journal, so the rotation event of the debug file is the line + // that rotates the journal. That nested rotation needs its own event. + journalLog.Write(rotatingFileTestLine(1, 1)) + journalLog.Write(rotatingFileTestLine(1, 2)) + for seq := 1; seq <= 5; seq++ { + debugLog.Write(rotatingFileTestLine(1, seq)) + } + + rotatedFiles := map[string]bool{} + for _, line := range strings.Split(buf.String(), "\n") { + if !strings.Contains(line, "Log rotated") { + continue + } + var event struct { + File string `json:"file"` + } + if err := json.Unmarshal([]byte(line), &event); err != nil { + t.Fatalf("parse %q: %v", line, err) + } + rotatedFiles[event.File] = true + } + for _, want := range []string{debugPath + ".1", journalPath + ".1"} { + if !rotatedFiles[want] { + t.Fatalf("no Log rotated event for %s; events: %v", want, rotatedFiles) + } + } + if len(rotatedFiles) != 2 { + t.Fatalf("got %d rotated files, want 2: %v", len(rotatedFiles), rotatedFiles) + } +} + +// rotationEventFields parses one log line into its raw fields, so a test can +// ask whether a field is there at all. +func rotationEventFields(t *testing.T, line string) map[string]json.RawMessage { + t.Helper() + fields := map[string]json.RawMessage{} + if err := json.Unmarshal([]byte(strings.TrimSpace(line)), &fields); err != nil { + t.Fatalf("unmarshal %q: %v", line, err) + } + return fields +} + +func Test_emitLogRotated_eventTimes(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + + t.Run("a file with no event names no time", func(t *testing.T) { + buf := captureMainLog(t) + + emitLogRotated(logRotation{file: "/tmp/ctrld.log.1", backups: 1}) + + fields := rotationEventFields(t, buf.String()) + for _, name := range []string{"first_event_at", "last_event_at"} { + if raw, ok := fields[name]; ok { + t.Errorf("%s = %s, want no field for a file with no event", name, raw) + } + } + }) + + t.Run("a file with events names both times", func(t *testing.T) { + buf := captureMainLog(t) + now := time.Now() + + emitLogRotated(logRotation{file: "/tmp/ctrld.log.1", backups: 1, firstWrite: now, lastWrite: now}) + + fields := rotationEventFields(t, buf.String()) + for _, name := range []string{"first_event_at", "last_event_at"} { + if _, ok := fields[name]; !ok { + t.Errorf("%s is missing: %v", name, fields) + } + } + }) +} + +func Test_emitLogRotated_reportsAFailedRotation(t *testing.T) { + setLogHeaderTestGlobalLevel(t, zerolog.DebugLevel) + buf := captureMainLog(t) + + emitLogRotated(logRotation{file: "/tmp/ctrld.log.1", err: errors.New("rename refused")}) + + var event struct { + Level string `json:"level"` + Message string `json:"message"` + Error string `json:"error"` + } + if err := json.Unmarshal([]byte(strings.TrimSpace(buf.String())), &event); err != nil { + t.Fatalf("unmarshal %q: %v", buf.String(), err) + } + if event.Message != "Log rotation failed" { + t.Errorf("message = %q, want %q", event.Message, "Log rotation failed") + } + if event.Level != "warn" { + t.Errorf("level = %q, want %q", event.Level, "warn") + } + if event.Error != "rename refused" { + t.Errorf("error = %q, want %q", event.Error, "rename refused") + } +} diff --git a/cmd/cli/main.go b/cmd/cli/main.go index d372e8d..24f47ce 100644 --- a/cmd/cli/main.go +++ b/cmd/cli/main.go @@ -143,30 +143,8 @@ func initInteractiveLogging() { // wrapper instead of calling this function directly. func initLoggingWithBackup(doBackup bool) []io.Writer { var writers []io.Writer - if logFilePath := normalizeLogFilePath(cfg.Service.LogPath); logFilePath != "" { - // Create parent directory if necessary. - if err := os.MkdirAll(filepath.Dir(logFilePath), 0750); err != nil { - mainLog.Load().Error().Msgf("failed to create log path: %v", err) - os.Exit(1) - } - - // Default open log file in append mode. - flags := os.O_CREATE | os.O_RDWR | os.O_APPEND - if doBackup { - // Backup old log file with .1 suffix. - if err := os.Rename(logFilePath, logFilePath+oldLogSuffix); err != nil && !os.IsNotExist(err) { - mainLog.Load().Error().Msgf("could not backup old log file: %v", err) - } else { - // Backup was created, set flags for truncating old log file. - flags = os.O_CREATE | os.O_RDWR - } - } - logFile, err := openLogFile(logFilePath, flags) - if err != nil { - mainLog.Load().Error().Msgf("failed to create log file: %v", err) - os.Exit(1) - } - writers = append(writers, logFile) + if rf := openLogPathWriter(doBackup); rf != nil { + writers = append(writers, rf) } writers = append(writers, consoleWriter) multi := zerolog.MultiLevelWriter(writers...) diff --git a/cmd/cli/network_transition_test.go b/cmd/cli/network_transition_test.go index 5db1779..eb68d7a 100644 --- a/cmd/cli/network_transition_test.go +++ b/cmd/cli/network_transition_test.go @@ -250,11 +250,14 @@ func TestRecoveryDebouncePreservesTransitionID(t *testing.T) { func TestTransitionWarningsSurviveDebugRotation(t *testing.T) { sourceTestGlobals(t) + level := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(zerolog.DebugLevel) + t.Cleanup(func() { zerolog.SetGlobalLevel(level) }) old := mainLog.Load() debug, warnings := newLogWriterWithSize(2048), newSmallLogWriter() // Runtime summaries occur after initialization, outside the preserved prefix. debug.Write([]byte(logWriterInitEndMarker)) - logger := zerolog.New(zerolog.MultiLevelWriter(debug, &zerolog.FilteredLevelWriter{Writer: zerolog.LevelWriterAdapter{Writer: warnings}, Level: zerolog.WarnLevel})) + logger := zerolog.New(zerolog.MultiLevelWriter(debug, newJournalLevelWriter(warnings))) mainLog.Store(&logger) t.Cleanup(func() { mainLog.Store(old) }) ctrld.SetDefaultLocalIPv4(net.ParseIP("192.0.2.10")) @@ -272,6 +275,8 @@ func TestTransitionWarningsSurviveDebugRotation(t *testing.T) { wg.Wait() d.end("completed") (&recoveryDiagnostic{transitionID: 8, generation: 10, started: time.Now()}).end("completed") + journal(logger.Info()).Str("interface", "en0").Msg("Network snapshot") + logger.Info().Msg("plain info line") for range 100 { logger.Debug().Msg(strings.Repeat("noise", 100)) } @@ -290,6 +295,12 @@ func TestTransitionWarningsSurviveDebugRotation(t *testing.T) { if strings.Contains(text, "private.customer") || strings.Contains(text, "secret payload") { t.Fatalf("raw payload or normal debug elevated: %s", text) } + if strings.Count(text, "Network snapshot") != 1 { + t.Fatalf("expected one retained marked info line: %s", text) + } + if strings.Contains(text, "plain info line") { + t.Fatalf("unmarked info line must not be retained: %s", text) + } } func TestRecoveryWaitLogsFirstFailure(t *testing.T) { diff --git a/cmd/cli/prog.go b/cmd/cli/prog.go index 60913dc..487ca31 100644 --- a/cmd/cli/prog.go +++ b/cmd/cli/prog.go @@ -137,7 +137,9 @@ type prog struct { queryFromSelfMap sync.Map initInternalLogWriterOnce sync.Once internalLogWriter *logWriter - internalWarnLogWriter *logWriter + internalJournalWriter *logWriter + querySampler errorSampler + lastNetworkState atomic.Pointer[netmon.State] internalLogSent time.Time runningIface string requiredMultiNICsConfig bool @@ -427,6 +429,10 @@ func (p *prog) runWait() { } p.mu.Unlock() + // The header names the mode, the listeners, and the upstreams, so the + // open files take the values of the config that now runs. + p.refreshLogHeader() + logger.Notice().Msg("reloading config successfully") select { @@ -764,6 +770,12 @@ func (p *prog) run(reload bool, reloadCh chan struct{}) { } } + // The new monitor starts with every upstream up, so the old one closes its + // open outages first. Without this the journal holds a down event that no + // up event ever follows. + if p.um != nil { + p.um.retire() + } p.um = newUpstreamMonitor(p.cfg) if !reload { @@ -908,6 +920,8 @@ func (p *prog) Stop(s service.Service) error { mainLog.Load().Debug().Msg("finish running onStopped functions") defer func() { mainLog.Load().Info().Msg("Service stopped") + // The files take the last line of this run before they close. + p.closeInternalLogs() }() if err := p.deAllocateIP(); err != nil { mainLog.Load().Error().Err(err).Msg("de-allocate ip failed") diff --git a/cmd/cli/query_error_sampler.go b/cmd/cli/query_error_sampler.go new file mode 100644 index 0000000..78d017b --- /dev/null +++ b/cmd/cli/query_error_sampler.go @@ -0,0 +1,166 @@ +package cli + +import ( + "sync" + "time" + + "github.com/rs/zerolog" +) + +// Classes of per-query errors. Each class keeps its own budget per upstream. +const ( + sampleClassResolveFailed = "resolve_failed" + sampleClassAllEndpointsFailed = "all_endpoints_failed" + sampleClassSendResponseFailed = "send_response_failed" +) + +const ( + // querySampleLimit is the number of lines that stay at error level in one window. + querySampleLimit = 5 + // querySampleWindow is the length of a window. It starts at the first error of the window. + querySampleWindow = 60 * time.Second +) + +// sampleKey identifies one budget. +type sampleKey struct { + class string + upstream string +} + +// sampleWindow counts the events of one budget between its start and its end. +type sampleWindow struct { + start time.Time + count int + suppressed int + timer *time.Timer +} + +// ended reports whether the window closed at or before now. +func (w *sampleWindow) ended(now time.Time) bool { + return !now.Before(w.start.Add(querySampleWindow)) +} + +// sampleSummary holds what one closed window reports. +type sampleSummary struct { + key sampleKey + count int + suppressed int +} + +// errorSampler bounds the noise of a repeated per-query error. It lowers the +// level of a line, never its presence, so the debug stream stays complete. A +// run with -v holds every stream at info, and the lowered lines fall below it. +// The zero value is ready to use. +type errorSampler struct { + mu sync.Mutex + windows map[sampleKey]*sampleWindow + now func() time.Time + after func(time.Duration, func()) *time.Timer +} + +// event returns the event a call site logs with. The first querySampleLimit +// events of a window come back at error level, the later ones at debug level. +// The caller adds its own fields and the message. +func (s *errorSampler) event(class, upstream string) *zerolog.Event { + key := sampleKey{class: class, upstream: upstream} + + s.mu.Lock() + now := s.clock() + var summaries []sampleSummary + window := s.windows[key] + if window != nil && window.ended(now) { + summaries = appendWindowSummary(summaries, key, window) + s.dropWindow(key, window) + window = nil + } + if window == nil { + window = s.startWindow(key, now) + } + window.count++ + suppressed := window.count > querySampleLimit + if suppressed { + window.suppressed++ + } + s.mu.Unlock() + + s.logSummaries(summaries) + + if suppressed { + return mainLog.Load().Debug() + } + return mainLog.Load().Error() +} + +// closeExpired closes every window that ended at or before now. The window +// timer calls it, so an idle window reports without a new event. +func (s *errorSampler) closeExpired(now time.Time) { + s.mu.Lock() + var summaries []sampleSummary + for key, window := range s.windows { + if !window.ended(now) { + continue + } + summaries = appendWindowSummary(summaries, key, window) + s.dropWindow(key, window) + } + s.mu.Unlock() + + s.logSummaries(summaries) +} + +// startWindow opens a window and arms the timer that closes it. The caller holds the lock. +func (s *errorSampler) startWindow(key sampleKey, start time.Time) *sampleWindow { + if s.windows == nil { + s.windows = make(map[sampleKey]*sampleWindow) + } + window := &sampleWindow{start: start} + s.windows[key] = window + window.timer = s.afterFunc()(querySampleWindow, func() { s.closeExpired(s.clock()) }) + return window +} + +// dropWindow forgets a window and stops its timer. The caller holds the lock. +func (s *errorSampler) dropWindow(key sampleKey, window *sampleWindow) { + if window.timer != nil { + window.timer.Stop() + } + delete(s.windows, key) +} + +// logSummaries reports the closed windows. The caller released the lock first, +// because the logger writes back through code that can take it again. +func (s *errorSampler) logSummaries(summaries []sampleSummary) { + for _, summary := range summaries { + mainLog.Load().Error(). + Str("class", summary.key.class). + Str("upstream", summary.key.upstream). + Int("count", summary.count). + Int("suppressed", summary.suppressed). + Int("window_s", int(querySampleWindow/time.Second)). + Msg("Per-query errors sampled") + } +} + +// clock reads the time of the sampler. A test sets its own clock, so a window +// closes without a wait. +func (s *errorSampler) clock() time.Time { + if s.now != nil { + return s.now() + } + return time.Now() +} + +func (s *errorSampler) afterFunc() func(time.Duration, func()) *time.Timer { + if s.after != nil { + return s.after + } + return time.AfterFunc +} + +// appendWindowSummary keeps the windows that suppressed at least one line. +func appendWindowSummary(summaries []sampleSummary, key sampleKey, window *sampleWindow) []sampleSummary { + if window.suppressed == 0 { + return summaries + } + return append(summaries, sampleSummary{key: key, count: window.count, suppressed: window.suppressed}) +} diff --git a/cmd/cli/query_error_sampler_test.go b/cmd/cli/query_error_sampler_test.go new file mode 100644 index 0000000..57eaa32 --- /dev/null +++ b/cmd/cli/query_error_sampler_test.go @@ -0,0 +1,260 @@ +package cli + +import ( + "encoding/json" + "strings" + "testing" + "time" + + "github.com/rs/zerolog" +) + +// samplerTestMessage is the message the fake call site writes on every sampled event. +const samplerTestMessage = "failed to resolve query" + +// samplerSummaryMessage is the message of the window summary. +const samplerSummaryMessage = "Per-query errors sampled" + +// captureDebugMainLog sends mainLog into a buffer and lowers the global level, +// so the test also sees the lines that the code under test drops to debug. It +// swaps two globals, so no test of this package runs in parallel. +func captureDebugMainLog(t *testing.T) *syncBuffer { + t.Helper() + level := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(zerolog.DebugLevel) + t.Cleanup(func() { zerolog.SetGlobalLevel(level) }) + return captureMainLog(t) +} + +// jsonLogEvents parses the captured lines as JSON events, in order. An empty +// message takes every line. +func jsonLogEvents(t *testing.T, logs *syncBuffer, message string) []map[string]any { + t.Helper() + var events []map[string]any + for _, line := range strings.Split(logs.String(), "\n") { + if strings.TrimSpace(line) == "" { + continue + } + event := map[string]any{} + if err := json.Unmarshal([]byte(line), &event); err != nil { + t.Fatalf("log line is not JSON: %q: %v", line, err) + } + if message != "" && event["message"] != message { + continue + } + events = append(events, event) + } + return events +} + +// samplerHarness drives an errorSampler on a clock and a timer queue the test owns. +type samplerHarness struct { + sampler *errorSampler + logs *syncBuffer + now time.Time + pending []func() +} + +func newSamplerHarness(t *testing.T) *samplerHarness { + t.Helper() + h := &samplerHarness{ + logs: captureDebugMainLog(t), + now: time.Date(2026, 9, 16, 12, 0, 0, 0, time.UTC), + } + h.sampler = &errorSampler{ + now: func() time.Time { return h.now }, + after: func(_ time.Duration, fn func()) *time.Timer { + h.pending = append(h.pending, fn) + return nil + }, + } + return h +} + +// emit plays a call site: it takes an event from the sampler and adds its own fields. +func (h *samplerHarness) emit(class, upstream string) { + h.sampler.event(class, upstream).Str("class", class).Str("upstream", upstream).Msg(samplerTestMessage) +} + +func (h *samplerHarness) advance(d time.Duration) { + h.now = h.now.Add(d) +} + +func (h *samplerHarness) events(t *testing.T) []map[string]any { + t.Helper() + return jsonLogEvents(t, h.logs, "") +} + +func countSampled(events []map[string]any, level, upstream string) int { + count := 0 + for _, event := range events { + if event["message"] != samplerTestMessage { + continue + } + if event["level"] != level || event["upstream"] != upstream { + continue + } + count++ + } + return count +} + +func samplerSummaries(events []map[string]any) []map[string]any { + var summaries []map[string]any + for _, event := range events { + if event["message"] == samplerSummaryMessage { + summaries = append(summaries, event) + } + } + return summaries +} + +func wantField(t *testing.T, event map[string]any, field string, want any) { + t.Helper() + if got := event[field]; got != want { + t.Fatalf("field %q: got %v, want %v", field, got, want) + } +} + +func Test_errorSamplerLimitsWindowAndSummarizes(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+2; i++ { + h.emit(sampleClassResolveFailed, "upstream.0") + } + + events := h.events(t) + if got := countSampled(events, "error", "upstream.0"); got != querySampleLimit { + t.Fatalf("error lines: got %d, want %d", got, querySampleLimit) + } + if got := countSampled(events, "debug", "upstream.0"); got != 2 { + t.Fatalf("debug lines: got %d, want 2", got) + } + if got := len(samplerSummaries(events)); got != 0 { + t.Fatalf("summaries before the window closed: got %d, want 0", got) + } + + h.advance(querySampleWindow) + h.emit(sampleClassResolveFailed, "upstream.0") + + events = h.events(t) + summaries := samplerSummaries(events) + if len(summaries) != 1 { + t.Fatalf("summaries after the window closed: got %d, want 1", len(summaries)) + } + summary := summaries[0] + wantField(t, summary, "level", "error") + wantField(t, summary, "class", sampleClassResolveFailed) + wantField(t, summary, "upstream", "upstream.0") + wantField(t, summary, "count", float64(7)) + wantField(t, summary, "suppressed", float64(2)) + wantField(t, summary, "window_s", float64(60)) + + last := events[len(events)-1] + wantField(t, last, "message", samplerTestMessage) + wantField(t, last, "level", "error") +} + +func Test_errorSamplerKeepsBudgetPerUpstream(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+1; i++ { + h.emit(sampleClassResolveFailed, "upstream.0") + } + for i := 0; i < querySampleLimit; i++ { + h.emit(sampleClassResolveFailed, "upstream.1") + } + + events := h.events(t) + if got := countSampled(events, "error", "upstream.1"); got != querySampleLimit { + t.Fatalf("error lines for the second upstream: got %d, want %d", got, querySampleLimit) + } + if got := countSampled(events, "debug", "upstream.1"); got != 0 { + t.Fatalf("debug lines for the second upstream: got %d, want 0", got) + } + if got := countSampled(events, "debug", "upstream.0"); got != 1 { + t.Fatalf("debug lines for the first upstream: got %d, want 1", got) + } +} + +func Test_errorSamplerKeepsQuietWindowSilent(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < 3; i++ { + h.emit(sampleClassAllEndpointsFailed, "") + } + + h.advance(querySampleWindow) + h.sampler.closeExpired(h.now) + + if got := len(samplerSummaries(h.events(t))); got != 0 { + t.Fatalf("summaries for a window without suppressed lines: got %d, want 0", got) + } +} + +func Test_errorSamplerCloseExpiredSummarizesOnce(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+2; i++ { + h.emit(sampleClassSendResponseFailed, "") + } + sampled := len(h.events(t)) + + h.advance(querySampleWindow) + h.sampler.closeExpired(h.now) + + events := h.events(t) + if len(events) != sampled+1 { + t.Fatalf("lines after closeExpired: got %d, want %d", len(events), sampled+1) + } + summaries := samplerSummaries(events) + if len(summaries) != 1 { + t.Fatalf("summaries after closeExpired: got %d, want 1", len(summaries)) + } + wantField(t, summaries[0], "class", sampleClassSendResponseFailed) + wantField(t, summaries[0], "suppressed", float64(2)) + + h.sampler.closeExpired(h.now.Add(querySampleWindow)) + + if got := len(h.events(t)); got != sampled+1 { + t.Fatalf("lines after the second closeExpired: got %d, want %d", got, sampled+1) + } +} + +func Test_errorSamplerTimerClosesIdleWindow(t *testing.T) { + h := newSamplerHarness(t) + + for i := 0; i < querySampleLimit+1; i++ { + h.emit(sampleClassResolveFailed, "upstream.0") + } + if len(h.pending) != 1 { + t.Fatalf("window timers: got %d, want 1", len(h.pending)) + } + + h.advance(querySampleWindow) + h.pending[0]() + + summaries := samplerSummaries(h.events(t)) + if len(summaries) != 1 { + t.Fatalf("summaries after the timer fired: got %d, want 1", len(summaries)) + } + wantField(t, summaries[0], "suppressed", float64(1)) + wantField(t, summaries[0], "count", float64(6)) +} + +func Test_errorSamplerZeroValueWorks(t *testing.T) { + buf := captureDebugMainLog(t) + + var sampler errorSampler + // The zero value arms a real timer. Close its window after the assertions, + // so no late summary line reaches another test. + t.Cleanup(func() { sampler.closeExpired(time.Now().Add(querySampleWindow)) }) + sampler.event(sampleClassResolveFailed, "upstream.0").Msg(samplerTestMessage) + + if got := strings.Count(buf.String(), samplerTestMessage); got != 1 { + t.Fatalf("lines from the zero value sampler: got %d, want 1", got) + } + if !strings.Contains(buf.String(), `"level":"error"`) { + t.Fatalf("first line of a window is not at error level: %s", buf.String()) + } +} diff --git a/cmd/cli/service_others.go b/cmd/cli/service_others.go index 954b228..1700408 100644 --- a/cmd/cli/service_others.go +++ b/cmd/cli/service_others.go @@ -4,14 +4,17 @@ package cli import ( "os" + "syscall" ) func hasElevatedPrivilege() (bool, error) { return os.Geteuid() == 0, nil } +// openLogFile opens a log file. It refuses a symlink, because ctrld often +// writes its logs as root into a directory that other users can write. func openLogFile(path string, flags int) (*os.File, error) { - return os.OpenFile(path, flags, os.FileMode(0o600)) + return os.OpenFile(path, flags|syscall.O_NOFOLLOW, os.FileMode(0o600)) } // hasLocalDnsServerRunning reports whether we are on Windows and having Dns server running. diff --git a/cmd/cli/upstream_monitor.go b/cmd/cli/upstream_monitor.go index 3eeb24b..432d611 100644 --- a/cmd/cli/upstream_monitor.go +++ b/cmd/cli/upstream_monitor.go @@ -1,6 +1,7 @@ package cli import ( + "strings" "sync" "time" @@ -17,6 +18,12 @@ const ( // the backoff so an unroutable endpoint is still re-probed periodically and // recovers once the route returns. checkUpstreamUnreachableBackoffMax = 60 * time.Second + // upstreamDownDelay is the time that the failures of an upstream must last + // before the monitor marks it down. + upstreamDownDelay = 10 * time.Second + // upstreamRecoveredDelay is the time that a reset holds back the failure + // counts of an upstream. + upstreamRecoveredDelay = 1 * time.Second ) // unreachableRecoveryBackoff returns the retry interval for the given streak of @@ -33,28 +40,55 @@ func unreachableRecoveryBackoff(streak int) time.Duration { return d } +// upstreamDownState remembers when an upstream went down and how many +// failures put it there, so the up event can report the outage. +type upstreamDownState struct { + since time.Time + failures uint64 +} + // upstreamMonitor performs monitoring upstreams health. type upstreamMonitor struct { cfg *ctrld.Config - mu sync.RWMutex + mu sync.RWMutex + // down holds one entry for each upstream that is down now. + down map[string]upstreamDownState checking map[string]bool - down map[string]bool failureReq map[string]uint64 recovered map[string]bool // failureTimerActive tracks if a timer is already running for a given upstream. failureTimerActive map[string]bool + // retired is set when a reload replaced this monitor. A timer that was + // armed before the reload must not open an outage that nothing closes. + retired bool + + // now is a seam, so a test can set the reported down time. + now func() time.Time + // after arms a one-shot timer, so a test fires the check itself instead of + // waiting for it. nil means time.AfterFunc. + after func(time.Duration, func()) +} + +// afterFunc returns the timer seam. A real timer drops its handle, because +// nothing stops these checks. +func (um *upstreamMonitor) afterFunc() func(time.Duration, func()) { + if um.after != nil { + return um.after + } + return func(d time.Duration, fn func()) { time.AfterFunc(d, fn) } } func newUpstreamMonitor(cfg *ctrld.Config) *upstreamMonitor { um := &upstreamMonitor{ cfg: cfg, checking: make(map[string]bool), - down: make(map[string]bool), + down: make(map[string]upstreamDownState), failureReq: make(map[string]uint64), recovered: make(map[string]bool), failureTimerActive: make(map[string]bool), + now: time.Now, } for n := range cfg.Upstream { upstream := upstreamPrefix + n @@ -71,6 +105,9 @@ func (um *upstreamMonitor) increaseFailureCount(upstream string) { um.mu.Lock() defer um.mu.Unlock() + if um.retired { + return + } if um.recovered[upstream] { mainLog.Load().Debug().Msgf("upstream %q is recovered, skipping failure count increase", upstream) return @@ -82,53 +119,142 @@ func (um *upstreamMonitor) increaseFailureCount(upstream string) { // Log the updated failure count. mainLog.Load().Debug().Msgf("upstream %q failure count updated to %d", upstream, failedCount) - // If this is the first failure and no timer is running, start a 10-second timer. + // If this is the first failure and no timer is running, start the timer. if failedCount == 1 && !um.failureTimerActive[upstream] { um.failureTimerActive[upstream] = true - go func(upstream string) { - time.Sleep(10 * time.Second) - um.mu.Lock() - defer um.mu.Unlock() - // If no success occurred during the 10-second window (i.e. counter remains > 0) - // and the upstream is not in a recovered state, mark it as down. - if um.failureReq[upstream] > 0 && !um.recovered[upstream] { - um.down[upstream] = true - mainLog.Load().Warn().Msgf("upstream %q marked as down after 10 seconds (failure count: %d)", upstream, um.failureReq[upstream]) - } - // Reset the timer flag so that a new timer can be spawned if needed. - um.failureTimerActive[upstream] = false - }(upstream) + um.afterFunc()(upstreamDownDelay, func() { um.markDownAfterDelay(upstream) }) } // If the failure count quickly reaches the threshold, mark the upstream as down immediately. if failedCount >= maxFailureRequest { - um.down[upstream] = true - mainLog.Load().Warn().Msgf("upstream %q marked as down immediately (failure count: %d)", upstream, failedCount) + um.markDown(upstream, failedCount, "immediate") } } +// markDownAfterDelay marks an upstream down when its failures did not clear +// while the timer ran. A success during that time leaves the count at zero. +func (um *upstreamMonitor) markDownAfterDelay(upstream string) { + um.mu.Lock() + defer um.mu.Unlock() + if um.retired { + return + } + if um.failureReq[upstream] > 0 && !um.recovered[upstream] { + um.markDown(upstream, um.failureReq[upstream], "timer") + } + // The next failure of this upstream can arm a new timer. + um.failureTimerActive[upstream] = false +} + +// markDown marks an upstream as down and logs the transition once. The caller holds the lock. +func (um *upstreamMonitor) markDown(upstream string, failures uint64, reason string) { + if um.retired { + return + } + if _, down := um.down[upstream]; down { + return + } + um.down[upstream] = upstreamDownState{since: um.now(), failures: failures} + journal(mainLog.Load().Warn()). + Str("upstream", journalUpstreamName(upstream)). + Str("state", "down"). + Uint64("failure_count", failures). + Str("reason", reason). + Msg("Upstream state changed") +} + +// markUp marks an upstream as up and logs the transition once. The caller holds the lock. +func (um *upstreamMonitor) markUp(upstream, reason string) { + state, down := um.down[upstream] + if !down { + return + } + delete(um.down, upstream) + journal(mainLog.Load().Info()). + Str("upstream", journalUpstreamName(upstream)). + Str("state", "up"). + Str("reason", reason). + Int64("down_for_ms", um.now().Sub(state.since).Milliseconds()). + Uint64("failure_count", state.failures). + Msg("Upstream state changed") +} + +// journalUpstreamName bounds the upstream name that a journal event carries. +// ctrld generates upstream.os, upstream., and upstream.internal_; every +// other key is operator text that can hold a token, so it reads as +// upstream.custom. +func journalUpstreamName(upstream string) string { + if upstream == upstreamOS || generatedUpstreamKey(strings.TrimPrefix(upstream, upstreamPrefix)) { + return upstream + } + return upstreamPrefix + "custom" +} + +// generatedUpstreamKey reports whether key is a number, or internal_ and a +// number, the two shapes that ctrld writes itself. +func generatedUpstreamKey(key string) bool { + digits := strings.TrimPrefix(key, internalDomainUpstreamPrefix) + if digits == "" { + return false + } + for _, r := range digits { + if r < '0' || r > '9' { + return false + } + } + return true +} + +// retire closes the outage of every upstream that is still down and stops +// every later state change. A reload builds a new monitor, so the journal ends +// the outages of the old one, and the old timers must not open new ones. +func (um *upstreamMonitor) retire() { + um.mu.Lock() + defer um.mu.Unlock() + for upstream := range um.down { + um.markUp(upstream, "reload") + } + um.retired = true + clear(um.failureReq) + clear(um.failureTimerActive) +} + +// noteSuccess records an answer from an upstream. It does not set the recovered +// flag, because that flag stops failure counts for one second and an answer +// must not hide the failures that follow it. +func (um *upstreamMonitor) noteSuccess(upstream string) { + um.mu.Lock() + defer um.mu.Unlock() + + um.failureReq[upstream] = 0 + um.markUp(upstream, "recovered") +} + // isDown reports whether the given upstream is being marked as down. func (um *upstreamMonitor) isDown(upstream string) bool { um.mu.Lock() defer um.mu.Unlock() - return um.down[upstream] + _, down := um.down[upstream] + return down } // reset marks an upstream as up and set failed queries counter to zero. func (um *upstreamMonitor) reset(upstream string) { um.mu.Lock() um.failureReq[upstream] = 0 - um.down[upstream] = false + um.markUp(upstream, "recovered") um.recovered[upstream] = true um.mu.Unlock() - go func() { - // debounce the recovery to avoid incrementing failure counts already in flight - time.Sleep(1 * time.Second) - um.mu.Lock() - um.recovered[upstream] = false - um.mu.Unlock() - }() + // The flag holds back the failure counts that are already in flight. + um.afterFunc()(upstreamRecoveredDelay, func() { um.clearRecovered(upstream) }) +} + +// clearRecovered lets the failures of an upstream count again. +func (um *upstreamMonitor) clearRecovered(upstream string) { + um.mu.Lock() + defer um.mu.Unlock() + um.recovered[upstream] = false } // countHealthy returns the number of upstreams in the provided map that are considered healthy. @@ -136,7 +262,7 @@ func (um *upstreamMonitor) countHealthy(upstreams []string) int { var count int um.mu.RLock() for _, upstream := range upstreams { - if !um.down[upstream] { + if _, down := um.down[upstream]; !down { count++ } } diff --git a/cmd/cli/upstream_monitor_test.go b/cmd/cli/upstream_monitor_test.go new file mode 100644 index 0000000..c45b4e2 --- /dev/null +++ b/cmd/cli/upstream_monitor_test.go @@ -0,0 +1,231 @@ +package cli + +import ( + "testing" + "time" + + "github.com/Control-D-Inc/ctrld" +) + +// upstreamStateMessage is the message of every upstream transition event. +const upstreamStateMessage = "Upstream state changed" + +// downMonitor returns a monitor on a clock the test owns, with the upstream down. +func downMonitor(t *testing.T, upstream string) (*upstreamMonitor, *syncBuffer, *time.Time) { + t.Helper() + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + now := time.Date(2026, 9, 16, 12, 0, 0, 0, time.UTC) + um.now = func() time.Time { return now } + for i := 0; i < maxFailureRequest; i++ { + um.increaseFailureCount(upstream) + } + if got := len(jsonLogEvents(t, logs, upstreamStateMessage)); got != 1 { + t.Fatalf("state events after the failures: got %d, want 1", got) + } + return um, logs, &now +} + +func Test_upstreamMonitorLogsOneDownEvent(t *testing.T) { + const upstream = upstreamPrefix + "0" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + + for i := 0; i < 633; i++ { + um.increaseFailureCount(upstream) + } + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 1 { + t.Fatalf("state events: got %d, want 1", len(events)) + } + wantField(t, events[0], "level", "warn") + wantField(t, events[0], "journal", true) + wantField(t, events[0], "upstream", upstream) + wantField(t, events[0], "state", "down") + wantField(t, events[0], "reason", "immediate") + wantField(t, events[0], "failure_count", float64(maxFailureRequest)) +} + +func Test_upstreamMonitorTimerLogsDownEvent(t *testing.T) { + const upstream = upstreamPrefix + "0" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + var armed []func() + um.after = func(_ time.Duration, fn func()) { armed = append(armed, fn) } + + um.increaseFailureCount(upstream) + if len(armed) != 1 { + t.Fatalf("armed timers: got %d, want 1", len(armed)) + } + armed[0]() + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 1 { + t.Fatalf("state events: got %d, want 1", len(events)) + } + wantField(t, events[0], "state", "down") + wantField(t, events[0], "reason", "timer") + wantField(t, events[0], "failure_count", float64(1)) +} + +func Test_upstreamMonitorResetLogsOneUpEvent(t *testing.T) { + const upstream = upstreamPrefix + "0" + um, logs, now := downMonitor(t, upstream) + + *now = now.Add(1500 * time.Millisecond) + um.reset(upstream) + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 2 { + t.Fatalf("state events: got %d, want 2", len(events)) + } + up := events[1] + wantField(t, up, "level", "info") + wantField(t, up, "journal", true) + wantField(t, up, "upstream", upstream) + wantField(t, up, "state", "up") + wantField(t, up, "reason", "recovered") + wantField(t, up, "down_for_ms", float64(1500)) + wantField(t, up, "failure_count", float64(maxFailureRequest)) +} + +func Test_upstreamMonitorRetireLogsTheOpenOutage(t *testing.T) { + const upstream = upstreamPrefix + "0" + um, logs, now := downMonitor(t, upstream) + + *now = now.Add(3 * time.Second) + um.retire() + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 2 { + t.Fatalf("state events: got %d, want 2", len(events)) + } + up := events[1] + wantField(t, up, "upstream", upstream) + wantField(t, up, "state", "up") + wantField(t, up, "reason", "reload") + wantField(t, up, "down_for_ms", float64(3000)) + + um.retire() + + if got := len(jsonLogEvents(t, logs, upstreamStateMessage)); got != 2 { + t.Fatalf("state events after the second retire: got %d, want 2", got) + } +} + +func Test_upstreamMonitorNoteSuccessLogsOneUpEvent(t *testing.T) { + const upstream = upstreamPrefix + "0" + um, logs, now := downMonitor(t, upstream) + + *now = now.Add(2 * time.Second) + um.noteSuccess(upstream) + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 2 { + t.Fatalf("state events: got %d, want 2", len(events)) + } + up := events[1] + wantField(t, up, "state", "up") + wantField(t, up, "reason", "recovered") + wantField(t, up, "down_for_ms", float64(2000)) + wantField(t, up, "failure_count", float64(maxFailureRequest)) + if got := um.failureReq[upstream]; got != 0 { + t.Fatalf("failure count after the answer: got %d, want 0", got) + } +} + +func Test_upstreamMonitorNoteSuccessOnUpUpstreamIsQuiet(t *testing.T) { + const upstream = upstreamPrefix + "0" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + + um.noteSuccess(upstream) + um.noteSuccess(upstream) + + if got := len(jsonLogEvents(t, logs, upstreamStateMessage)); got != 0 { + t.Fatalf("state events: got %d, want 0", got) + } +} + +// Test_upstreamMonitorRetiredTimerStaysSilent fires the down timer that a +// failure armed before the reload retired the monitor. A retired monitor +// owns no outage, so the timer must add no event. +func Test_upstreamMonitorRetiredTimerStaysSilent(t *testing.T) { + const upstream = upstreamPrefix + "0" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + var armed []func() + um.after = func(_ time.Duration, fn func()) { armed = append(armed, fn) } + + um.increaseFailureCount(upstream) + um.retire() + for _, fire := range armed { + fire() + } + + if got := len(jsonLogEvents(t, logs, upstreamStateMessage)); got != 0 { + t.Fatalf("state events from the retired monitor: got %d, want 0: %s", got, logs.String()) + } + if um.isDown(upstream) { + t.Fatal("the retired monitor marked the upstream down") + } +} + +// Test_upstreamMonitorRetiredAfterImmediateDownStaysSilent retires a monitor +// that already reported an outage. The armed timer and a late failure must +// add no event after the closing up event. +func Test_upstreamMonitorRetiredAfterImmediateDownStaysSilent(t *testing.T) { + const upstream = upstreamPrefix + "0" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + var armed []func() + um.after = func(_ time.Duration, fn func()) { armed = append(armed, fn) } + + for i := 0; i < maxFailureRequest; i++ { + um.increaseFailureCount(upstream) + } + um.retire() + before := jsonLogEvents(t, logs, upstreamStateMessage) + if len(before) != 2 { + t.Fatalf("state events after the retire: got %d, want down and up", len(before)) + } + for _, fire := range armed { + fire() + } + um.increaseFailureCount(upstream) + + if got := len(jsonLogEvents(t, logs, upstreamStateMessage)); got != 2 { + t.Fatalf("state events after the retired timer fired: got %d, want 2: %s", got, logs.String()) + } + if um.isDown(upstream) { + t.Fatal("the retired monitor marked the upstream down again") + } +} + +// Test_upstreamMonitorKeepsACustomNameOutOfTheJournal marks an upstream with +// an operator-chosen key down. The key can hold a token, so the event names +// the upstream by a bounded name. +func Test_upstreamMonitorKeepsACustomNameOutOfTheJournal(t *testing.T) { + const upstream = upstreamPrefix + "dns.controld.com/org-v1-SECRET0123" + logs := captureDebugMainLog(t) + um := newUpstreamMonitor(&ctrld.Config{}) + + for i := 0; i < maxFailureRequest; i++ { + um.increaseFailureCount(upstream) + } + um.noteSuccess(upstream) + + events := jsonLogEvents(t, logs, upstreamStateMessage) + if len(events) != 2 { + t.Fatalf("state events: got %d, want down and up", len(events)) + } + for _, event := range events { + wantField(t, event, "upstream", upstreamPrefix+"custom") + } + for _, generated := range []string{upstreamOS, upstreamPrefix + "0", upstreamPrefix + "internal_3"} { + if got := journalUpstreamName(generated); got != generated { + t.Fatalf("journalUpstreamName(%q) = %q, want the name itself", generated, got) + } + } +} diff --git a/config.go b/config.go index fd94675..9036325 100644 --- a/config.go +++ b/config.go @@ -218,6 +218,8 @@ func (c *Config) FirstUpstream() *UpstreamConfig { type ServiceConfig struct { LogLevel string `mapstructure:"log_level" toml:"log_level,omitempty"` LogPath string `mapstructure:"log_path" toml:"log_path,omitempty"` + LogMaxSizeMB int `mapstructure:"log_max_size_mb" toml:"log_max_size_mb,omitempty" validate:"omitempty,gte=1,lte=1024"` + LogMaxBackups *int `mapstructure:"log_max_backups" toml:"log_max_backups,omitempty" validate:"omitempty,gte=0,lte=64"` CacheEnable bool `mapstructure:"cache_enable" toml:"cache_enable,omitempty"` CacheSize int `mapstructure:"cache_size" toml:"cache_size,omitempty"` CacheTTLOverride int `mapstructure:"cache_ttl_override" toml:"cache_ttl_override,omitempty"` diff --git a/config_test.go b/config_test.go index cd392d5..bb2c7b2 100644 --- a/config_test.go +++ b/config_test.go @@ -169,6 +169,72 @@ discover_ptr = false require.False(t, *cfg.Service.DiscoverPtr) } +func TestLogMaxKeys(t *testing.T) { + tests := []struct { + name string + serviceKeys string + wantSize int + wantBackups *int + }{ + {"size and backups set", "log_max_size_mb = 20\nlog_max_backups = 1", 20, intPtr(1)}, + {"size zero, backups absent", "log_max_size_mb = 0", 0, nil}, + {"backups zero", "log_max_backups = 0", 0, intPtr(0)}, + {"the largest values the keys take", "log_max_size_mb = 1024\nlog_max_backups = 64", 1024, intPtr(64)}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + cfg := configWithServiceKeys(t, tc.serviceKeys) + validate := validator.New() + require.NoError(t, ctrld.ValidateConfig(validate, cfg)) + require.Equal(t, tc.wantSize, cfg.Service.LogMaxSizeMB) + if tc.wantBackups == nil { + require.Nil(t, cfg.Service.LogMaxBackups) + return + } + require.NotNil(t, cfg.Service.LogMaxBackups) + require.Equal(t, *tc.wantBackups, *cfg.Service.LogMaxBackups) + }) + } +} + +func TestLogMaxKeysOutOfRange(t *testing.T) { + tests := []struct { + name string + serviceKeys string + wantField string + }{ + {"negative size", "log_max_size_mb = -1", "LogMaxSizeMB"}, + {"negative backups", "log_max_backups = -1", "LogMaxBackups"}, + {"size above the limit", "log_max_size_mb = 1025", "LogMaxSizeMB"}, + {"backups above the limit", "log_max_backups = 65", "LogMaxBackups"}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + cfg := configWithServiceKeys(t, tc.serviceKeys) + validate := validator.New() + err := ctrld.ValidateConfig(validate, cfg) + require.ErrorContains(t, err, tc.wantField) + }) + } +} + +func configWithServiceKeys(t *testing.T, serviceKeys string) *ctrld.Config { + t.Helper() + v := viper.NewWithOptions(viper.KeyDelimiter("::")) + ctrld.InitConfig(v, "test_log_max_keys") + v.SetConfigType("toml") + require.NoError(t, v.ReadConfig(strings.NewReader("[service]\n"+serviceKeys+"\n"))) + var cfg ctrld.Config + require.NoError(t, v.Unmarshal(&cfg)) + return &cfg +} + +func intPtr(n int) *int { + return &n +} + func defaultConfig(t *testing.T) *ctrld.Config { v := viper.New() ctrld.InitConfig(v, "test_load_default_config") diff --git a/docs/config.md b/docs/config.md index 8f21a4c..17beb7c 100644 --- a/docs/config.md +++ b/docs/config.md @@ -121,10 +121,28 @@ Logging level you wish to enable. ### log_path Relative or absolute path of the log file. +Point `log_path` at a file that no other program rotates. ctrld renames `.1` to `.N` and uploads these files. A lower `log_max_backups` leaves the older numbered `log_path` files in place, but ctrld removes the extra numbered files of its internal logs. + - Type: string - Required: no - Default: "" +### log_max_size_mb +Maximum size of the debug log file in MB. When the file reaches this size, ctrld rotates it. This limit also applies to the `log_path` file. + +- Type: integer +- Required: no +- Valid values: 1 to 1024 +- Default: 10 on desktop platforms, 5 on routers + +### log_max_backups +Number of rotated debug log files that ctrld keeps. If the value is 0, ctrld keeps no rotated file. This number also applies to the `log_path` file. + +- Type: integer +- Required: no +- Valid values: 0 to 64 +- Default: 4 on desktop platforms, 1 on routers + ### cache_enable When `cache_enable = true`, all resolved DNS query responses will be cached for duration of the upstream record TTLs. diff --git a/docs/internal-domains.md b/docs/internal-domains.md index 44caad6..1630b8d 100644 --- a/docs/internal-domains.md +++ b/docs/internal-domains.md @@ -153,7 +153,10 @@ removed domain leaves no rule and no `internal_*` upstream behind. Generated `internal_*` upstreams carry the organization's private resolver addresses, so anything naming one stays at debug, and the level above it carries only a classification (`timeout`, `refused`, `unreachable`, `source_unavailable`, -`error`). That covers every consumer, not just query handling: +`error`). The per-query error sampler applies to the classification line as +well. After 5 lines in one minute for the same upstream and class, the next +classification lines go to debug, and one `Per-query errors sampled` line gives +the count. That covers every consumer, not just query handling: - the bootstrap-IP line in `setupUpstream`; - the transport error from a failed query, which names the endpoint; diff --git a/docs/network-recovery-diagnostics.md b/docs/network-recovery-diagnostics.md index e7c18c6..856c679 100644 --- a/docs/network-recovery-diagnostics.md +++ b/docs/network-recovery-diagnostics.md @@ -1,9 +1,12 @@ # Network-recovery diagnostics -Use continuous `ctrld log tail` capture during a reproduction. Internal logs rotate by size. -A later `log send` can contain recent debug events and older warnings. -Match timestamps and IDs. The last retained error does not necessarily describe the current network. -Issue #604 tracks upload-time device and version headers separately. +The retained stream is the journal, the file `ctrld-journal.log` in the ctrld home directory. +It keeps every warning and every error, plus every event marked `journal=true`. +The journal is on disk, so it keeps these events across a restart and a self-upgrade. +Its budget is 2 MB with 2 backup files on a desktop, and 1 MB with 1 backup file on a router. +Every `ctrld log send` upload holds the whole journal, so a reproduction does not need a continuous `ctrld log tail` capture. +Match timestamps and IDs. The last retained error does not describe the current network in every case. +Each upload starts with a header line that names the build, the intercept mode, and the network at send time. ## Transitions and recovery @@ -16,10 +19,10 @@ For minor callbacks and late major callbacks in that epoch, ctrld reads current This read does not change host DNS. A failed read defers source writes, but reconciliation continues. `Removed stale resolver source` is a warning only when ctrld removes an invalid address. -The warning gives the reason and survives debug rotation. +The warning gives the reason. Every warning enters the journal, so it stays on disk after a debug rotation and after a restart. `Recovery begin` and `Recovery end` connect the transition to a `recovery_generation`, reason, outcome, and elapsed time. Only the first upstream failure in each recovery produces a bounded summary. -If a recovery encounters a failure, its final outcome also enters the warning stream. +If a recovery encounters a failure, its final outcome also enters the journal. Normal successful recovery stays at debug level. These summaries exclude upstream URLs and queried names. @@ -43,9 +46,9 @@ The cancellation event alone does not prove that interface DNS remains removed. A changed unsuccessful condition produces a warning. The condition consists of the stage, error code, outcome, and target. Equal results stay at debug level. The next changed condition includes the preceding repeat count. -The first restored receipt also produces a warning-stream event. This event prevents an older failure from appearing current. +The first restored receipt also produces a warning, which enters the journal. This event prevents an older failure from appearing current. Normal receipts and shutdown cancellation stay at debug level. -The warning buffer is finite. These events do not guarantee indefinite retention. +The journal budget is finite and the journal rotates by size. It does not keep these events without a limit. The outcomes have these meanings: diff --git a/docs/runtime-internal-logging.md b/docs/runtime-internal-logging.md index 982632c..8a52cad 100644 --- a/docs/runtime-internal-logging.md +++ b/docs/runtime-internal-logging.md @@ -1,46 +1,94 @@ -# Runtime Internal Logging - -When no logging is configured (i.e., `log_path` is not set), ctrld automatically enables an internal logging system. This system stores logs in memory to provide troubleshooting information when problems occur. +# Runtime internal logging ## Purpose -The runtime internal logging system is designed primarily for **ctrld developers**, not end users. It captures detailed diagnostic information that can be useful for troubleshooting issues when they arise, especially in production environments where explicit logging may not be configured. +ctrld writes its own log when the configuration sets no log file. The log gives Control D support and ctrld developers the evidence they need after a problem. Two of the three streams are files on disk. They keep their content across a restart and a self-upgrade. -## When It's Enabled +## When it is on -Internal logging is automatically enabled when: +Internal logging is on when these three conditions are true at the same time: -- ctrld is running in Control D mode (i.e., `--cd` flag is provided) -- No log file is configured (i.e., `log_path` is empty or not set) +- ctrld runs in Control D mode, with the `--cd` flag +- The configuration sets no `log_path` +- Silent mode is off -If a log file is explicitly configured via `log_path`, internal logging will **not** be enabled, as the configured log file serves the logging purpose. +When `log_path` is set, ctrld writes that file and starts no internal stream. The journal needs internal logging, so `log_path` mode has no journal. -## How It Works +## Streams and files -The internal logging system: +ctrld writes three streams. The debug file and the journal file live in the ctrld home directory, next to each other. -- Stores logs in **in-memory buffers** (not written to disk) -- Captures logs at **debug level** for normal operations and **warn level** for warnings -- Maintains separate buffers for normal logs and warning logs -- Automatically manages buffer size to prevent unbounded memory growth -- Preserves initialization logs even when buffers overflow +| Stream | Level filter | File | Desktop budget | Router budget | Survives a restart | +|---|---|---|---|---|---| +| Console | Notice and above. The `-v` flag adds the lower levels | none | none | none | No | +| Debug | Every level | `ctrld.log` | 10 MB, 4 backup files | 5 MB, 1 backup file | Yes | +| Journal | Warning and above, plus every event with `journal=true` | `ctrld-journal.log` | 2 MB, 2 backup files | 1 MB, 1 backup file | Yes | -## Configuration +The `-v` flag changes the level of every stream, the files included. Without the flag, ctrld sets the level to debug and holds the console at notice. With `-v` the level is info, so no debug line reaches the debug file. With `-vv` the level is debug again, and the console shows every line. -**Important**: The `log_level` configuration option does **not** affect the internal logging system. Internal logging always operates at debug level for normal logs and warn level for warnings, regardless of the `log_level` setting in the configuration file. +A backup file carries a number suffix. On a desktop the debug backup files are `ctrld.log.1` to `ctrld.log.4`, and `ctrld.log.1` holds the newest rotated content. The journal backup files are `ctrld-journal.log.1` and `ctrld-journal.log.2`. -The `log_level` setting only affects: -- Console output (when running interactively) -- File-based logging (when `log_path` is configured) +Rotation is by size. A write that crosses the size limit rotates the file first. ctrld deletes the file beyond the backup count. -## Accessing Internal Logs +Each stream also keeps a memory buffer: 5 MB for the debug stream and 1 MB for the journal. These buffers serve `ctrld log tail` and the fallback path when a file cannot open. The files hold the history. -Internal logs can be accessed through the control server API endpoints. This functionality is intended for developers and support personnel who need to diagnose issues. +A restart deletes the memory buffers and keeps the files. The new process appends a header line, which marks the restart point inside each file. + +## Header and rotation events + +Every debug file and every journal file starts with one JSON line, the header. ctrld writes the header when it opens a file at start and after every rotation. On an existing file at start, ctrld appends the header. + +The message of the line is `Log header`. The line carries these fields: + +- Build: `version` and `commit` +- Host: `os`, `arch`, `pid`, and `start_time` +- Mode: `intercept_mode`, `listeners`, `upstream_count`, and `upstream_types` +- Identity: `resolver_uid` +- Files: `log_files` +- Network: `network` with `default_route_interface`, `have_v4`, `have_v6`, and `interfaces` + +The header holds no provisioning token, no upstream endpoint URL, and no query name. `upstream_types` holds the type words, for example `doh` or `os`. `listeners` holds the listen addresses. + +After each rotation ctrld logs one `Log rotated` event at info level, with the fields `file`, `bytes_written`, `first_event_at`, `last_event_at`, and `backups`. This event is a journal event, so it lands in the debug stream and in the journal. + +## Sampling of per-query errors + +A broken network produces one error line per query. ctrld bounds this flood for each error class and each upstream. The first 5 lines in a 60 s window stay at error level. Later lines in the same window drop to debug level, so the debug stream stays complete. A run with `-v` holds every stream at info, and the debug stream then loses these lines. + +When a window closes, ctrld logs one `Per-query errors sampled` summary at error level. The summary carries `class`, `upstream`, `count`, `suppressed`, and `window_s`. ctrld logs the summary only when the window suppressed at least one line. + +An upstream logs one `Upstream state changed` event per transition. The down event is at warn level and carries `state` `down`, `failure_count`, and `reason`. The up event is at info level and carries `state` `up`, `down_for_ms`, and `failure_count`. Both are journal events. + +## Configuration keys + +The `log_level` key does not change the internal streams. The debug file keeps every level, and the journal keeps the warnings, the errors, and the journal events. The `log_level` key changes the console output and the `log_path` file. The `-v` flag changes every stream, as the section "Streams and files" explains. + +Two keys in the `[service]` section size the debug stream: + +- The key `log_max_size_mb` sets the size limit of `ctrld.log` in MB. The default is 10 on a desktop and 5 on a router. +- The key `log_max_backups` sets the number of backup files. The default is 4 on a desktop and 1 on a router. The value 0 keeps no backup file. + +Both keys also apply to the `log_path` file, which rotates the same way. The journal budget is fixed per platform. + +## Uploads + +`ctrld log send` uploads the log to Control D. The body holds these parts, in this order: + +- One header line rendered at send time, with the field `trigger` set to `send` +- The newest 10 MB of the debug files, oldest file first, cut at a line boundary +- The marker `=== LOG_END ===` +- Every journal file, oldest first + +The `network` object of the send-time header comes from a fresh read of the interfaces and the default route. `ctrld log send --full` sends every debug file in place of the newest 10 MB. The reported size equals the number of bytes uploaded. + +`ctrld log view` prints the same composition on the terminal and takes the same `--full` flag. ctrld accepts one upload per minute. The body is plain text without gzip. + +In `log_path` mode the body holds the send-time header, then the `log_path` file and its backup files, oldest first. This body has no marker and no journal. + +`ctrld log tail` follows the live debug stream and prints each new line, journal events included. ## Notes -- Internal logging is **not** a replacement for proper log file configuration in production environments -- For production deployments, it is recommended to configure `log_path` to enable persistent file-based logging -- Internal logs are stored in memory and will be lost if the process terminates unexpectedly -- The internal logging system is automatically disabled when explicit logging is configured - +- Internal logging is not a replacement for a configured `log_path` file in production. +- The journal is small on purpose. It keeps the events that describe a problem, not the events of each query. +- Support reads the upload without access to the host. The header line names the build, the mode, and the network, so support does not have to ask for them.