diff options
Diffstat (limited to 'internal/io')
39 files changed, 5623 insertions, 540 deletions
diff --git a/internal/io/dlog/dlog.go b/internal/io/dlog/dlog.go index 258fb68..e28b442 100644 --- a/internal/io/dlog/dlog.go +++ b/internal/io/dlog/dlog.go @@ -31,36 +31,6 @@ var Common *DLog var mutex sync.Mutex var started bool -// Start logger(s). -func Start(ctx context.Context, wg *sync.WaitGroup, sourceProcess source.Source) { - mutex.Lock() - defer mutex.Unlock() - - if started { - Common.FatalPanic("Logger already started") - } - - Client = new(sourceProcess, source.Client) - Server = new(sourceProcess, source.Server) - Common = Client - if sourceProcess == source.Server { - Common = Server - } - - var wg2 sync.WaitGroup - wg2.Add(2) - go Client.start(ctx, &wg2) - go Server.start(ctx, &wg2) - - go rotation(ctx) - go func() { - wg2.Wait() - wg.Done() - }() - - started = true -} - // DLog is the DTail logger. type DLog struct { logger loggers.Logger @@ -94,62 +64,43 @@ func new(sourceProcess, sourcePackage source.Source) *DLog { } } -func (d *DLog) start(ctx context.Context, wg *sync.WaitGroup) { - defer wg.Done() - var wg2 sync.WaitGroup - wg2.Add(1) - d.logger.Start(ctx, &wg2) - <-ctx.Done() - wg2.Wait() -} +// Start logger(s). +func Start(ctx context.Context, wg *sync.WaitGroup, sourceProcess source.Source) { + mutex.Lock() + defer mutex.Unlock() -func (d *DLog) log(level level, args []interface{}) string { - if d.maxLevel < level { - return "" + if started { + Common.FatalPanic("Logger already started") } - sb := pool.BuilderBuffer.Get().(*strings.Builder) - defer pool.RecycleBuilderBuffer(sb) - now := time.Now() - switch d.sourceProcess { - case source.Client: - sb.WriteString(d.sourcePackage.String()) - sb.WriteString(protocol.FieldDelimiter) - sb.WriteString(d.hostname) - sb.WriteString(protocol.FieldDelimiter) - sb.WriteString(level.String()) - default: - sb.WriteString(level.String()) - sb.WriteString(protocol.FieldDelimiter) - sb.WriteString(now.Format("0102-150405")) + Client = new(sourceProcess, source.Client) + Server = new(sourceProcess, source.Server) + Common = Client + if sourceProcess == source.Server { + Common = Server } - sb.WriteString(protocol.FieldDelimiter) - d.writeArgStrings(sb, args) - message := sb.String() - if !config.Client.TermColorsEnable || !d.logger.SupportsColors() { - d.logger.Log(now, message) - return message - } + var wg2 sync.WaitGroup + wg2.Add(2) + go Client.start(ctx, &wg2) + go Server.start(ctx, &wg2) - d.logger.LogWithColors(now, message, brush.Colorfy(message)) - return message + go rotation(ctx) + go func() { + wg2.Wait() + wg.Done() + }() + + started = true } -func (d *DLog) writeArgStrings(sb *strings.Builder, args []interface{}) { - for i, arg := range args { - if i > 0 { - sb.WriteString(protocol.FieldDelimiter) - } - switch v := arg.(type) { - case string: - sb.WriteString(v) - case error: - sb.WriteString(v.Error()) - default: - sb.WriteString(fmt.Sprintf("%v", v)) - } - } +func (d *DLog) start(ctx context.Context, wg *sync.WaitGroup) { + defer wg.Done() + var wg2 sync.WaitGroup + wg2.Add(1) + d.logger.Start(ctx, &wg2) + <-ctx.Done() + wg2.Wait() } // FatalPanic terminates the process with a fatal error. @@ -192,8 +143,34 @@ func (d *DLog) Debug(args ...interface{}) string { return d.log(Debug, args) } +// TraceEnabled reports whether trace-level logging is currently active. +// +// It performs exactly the same maxLevel comparison as Trace's internal +// early-return (see below), letting callers on per-line hot paths gate the +// whole trace call — the variadic []interface{} slice allocation plus the +// interface boxing of every non-pointer argument (uint64 line counts via +// runtime.convT64, strings via convTstring) — behind one cheap, inlinable, +// allocation-free branch. Without this guard those args are boxed at the call +// site before Trace even runs, so Trace's own early-return cannot save them. +// +// The receiver is nil-safe so call sites need no separate nil check on the +// package-level loggers (Server/Client/Common), which stay nil until Start. +// maxLevel is fixed at logger construction from config.Common.LogLevel, so the +// result mirrors whatever level Trace itself would observe. +func (d *DLog) TraceEnabled() bool { + return d != nil && d.maxLevel >= Trace +} + // Trace logging. func (d *DLog) Trace(args ...interface{}) string { + // Early check to avoid expensive runtime.Caller when trace is disabled + // This is a critical performance optimization for hot paths. Note that on + // per-line hot paths callers should additionally gate with TraceEnabled() + // so the argument boxing never happens; this check only saves runtime.Caller + // and the log formatting, not the caller-side boxing of args. + if d.maxLevel < Trace { + return "" + } _, file, line, _ := runtime.Caller(1) args = append(args, fmt.Sprintf("at %s:%d", file, line)) return d.log(Trace, args) @@ -201,6 +178,10 @@ func (d *DLog) Trace(args ...interface{}) string { // Devel used for development purpose only logging (e.g. "print" debugging). func (d *DLog) Devel(args ...interface{}) string { + // Early check to avoid expensive runtime.Caller when devel is disabled + if d.maxLevel < Devel { + return "" + } _, file, line, _ := runtime.Caller(1) args = append(args, fmt.Sprintf("at %s:%d", file, line)) return d.log(Devel, args) @@ -216,6 +197,46 @@ func (d *DLog) Raw(message string) string { return message } +// payloadFileTeer is the optional capability of a logger that can tee retrieved +// payload into its FILE sink without also writing it to stdout. Only the default +// fout logger implements it; stdout/none loggers have no file sink and are +// skipped via the type assertion in RawPayloadFileTee. +type payloadFileTeer interface { + RawFileOnly(now time.Time, message string) +} + +// RawPayloadFileTee writes retrieved payload to the logger's FILE sink only +// (never stdout), honoring the client's --log-payload / Client.LogPayload +// opt-in. It is used by the serverless direct-output path, which emits payload +// straight to stdout and therefore bypasses the fout logger's own Raw tee. When +// the active logger has no file sink (stdout/none) or payload teeing is +// disabled, this is a no-op. stdout output is unaffected: the caller writes the +// same payload bytes to stdout itself, and this method only adds the file tee. +func (d *DLog) RawPayloadFileTee(message string) { + if teer, ok := d.logger.(payloadFileTeer); ok { + teer.RawFileOnly(time.Now(), message) + } +} + +// RawLog writes a pre-formatted message through the DIAGNOSTIC (Log) sink, so it +// reaches both stdout and — in the default fout logger — the daily log file. +// +// It differs from Raw, which uses the PAYLOAD sink: with the default +// Client.LogPayload=false, Raw is gated out of the file (bulk dcat/dgrep/dtail +// output must not grow the log). RawLog is for audit-worthy, already-formatted +// lines such as server-error reports, which must always be kept in the file like +// other diagnostics rather than being treated as bulk payload. The message is +// written verbatim (no level/hostname prefix); callers pre-format it and must +// NOT append a trailing newline, since the Log sink appends one. +func (d *DLog) RawLog(message string) string { + if !config.Client.TermColorsEnable || !d.logger.SupportsColors() { + d.logger.Log(time.Now(), message) + return message + } + d.logger.LogWithColors(time.Now(), message, brush.Colorfy(message)) + return message +} + // Mapreduce logging. func (d *DLog) Mapreduce(table string, data map[string]interface{}) string { args := make([]interface{}, len(data)+1) @@ -269,3 +290,52 @@ func (d *DLog) Pause() { d.logger.Pause() } // Resume the logging. func (d *DLog) Resume() { d.logger.Resume() } + +func (d *DLog) log(level level, args []interface{}) string { + if d.maxLevel < level { + return "" + } + sb := pool.BuilderBuffer.Get().(*strings.Builder) + defer pool.RecycleBuilderBuffer(sb) + now := time.Now() + + switch d.sourceProcess { + case source.Client: + sb.WriteString(d.sourcePackage.String()) + sb.WriteString(protocol.FieldDelimiter) + sb.WriteString(d.hostname) + sb.WriteString(protocol.FieldDelimiter) + sb.WriteString(level.String()) + default: + sb.WriteString(level.String()) + sb.WriteString(protocol.FieldDelimiter) + sb.WriteString(now.Format("0102-150405")) + } + sb.WriteString(protocol.FieldDelimiter) + d.writeArgStrings(sb, args) + + message := sb.String() + if !config.Client.TermColorsEnable || !d.logger.SupportsColors() { + d.logger.Log(now, message) + return message + } + + d.logger.LogWithColors(now, message, brush.Colorfy(message)) + return message +} + +func (d *DLog) writeArgStrings(sb *strings.Builder, args []interface{}) { + for i, arg := range args { + if i > 0 { + sb.WriteString(protocol.FieldDelimiter) + } + switch v := arg.(type) { + case string: + sb.WriteString(v) + case error: + sb.WriteString(v.Error()) + default: + sb.WriteString(fmt.Sprintf("%v", v)) + } + } +} diff --git a/internal/io/dlog/dlog_test.go b/internal/io/dlog/dlog_test.go new file mode 100644 index 0000000..87e834a --- /dev/null +++ b/internal/io/dlog/dlog_test.go @@ -0,0 +1,54 @@ +package dlog + +import "testing" + +// TestTraceEnabled verifies that TraceEnabled mirrors Trace's internal +// maxLevel < Trace early-return: it must report true exactly when the +// configured level is Trace or higher (Devel/All disable trace? no — the level +// ladder is monotonically increasing, so any level >= Trace enables trace), +// and false for every level below Trace. +func TestTraceEnabled(t *testing.T) { + tests := []struct { + name string + level level + want bool + }{ + {"none", None, false}, + {"fatal", Fatal, false}, + {"error", Error, false}, + {"warn", Warn, false}, + {"info", Info, false}, + {"default", Default, false}, + {"verbose", Verbose, false}, + {"debug", Debug, false}, + {"devel", Devel, false}, + {"trace", Trace, true}, + {"all", All, true}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + d := &DLog{maxLevel: tc.level} + if got := d.TraceEnabled(); got != tc.want { + t.Fatalf("TraceEnabled() at level %v = %v, want %v", + tc.level, got, tc.want) + } + // TraceEnabled must agree with what Trace itself would do: Trace + // returns "" (no work) exactly when trace is disabled. + traceDidWork := d.maxLevel >= Trace + if traceDidWork != tc.want { + t.Fatalf("TraceEnabled() disagrees with Trace's own gate at level %v", tc.level) + } + }) + } +} + +// TestTraceEnabledNilSafe guards the footgun that call sites rely on: +// TraceEnabled is invoked on the package-level loggers (Server/Client/Common), +// which are nil until Start runs. A nil receiver must report false, not panic. +func TestTraceEnabledNilSafe(t *testing.T) { + var d *DLog + if d.TraceEnabled() { + t.Fatal("nil *DLog.TraceEnabled() must be false") + } +} diff --git a/internal/io/dlog/loggers/file.go b/internal/io/dlog/loggers/file.go index 8e567bc..b3b6a10 100644 --- a/internal/io/dlog/loggers/file.go +++ b/internal/io/dlog/loggers/file.go @@ -12,6 +12,26 @@ import ( "github.com/mimecast/dtail/internal/config" ) +const ( + // fileWriterBufSize is the size of the bufio buffer wrapping the log file + // descriptor. A real buffer (instead of the old 1-byte writer that forced a + // write syscall per line) lets bulk payload — e.g. dcat/dgrep tee — batch + // into ~one syscall per bufferful, cutting the client receive-path syscall + // count and CPU by ~5x. bufio auto-flushes when full, so high-throughput + // output never stalls in the buffer. + fileWriterBufSize = 64 * 1024 + // fileIdleFlushInterval bounds how long buffered data may sit unwritten when + // output goes idle (follow/interactive mode trickling a few lines). Without + // it, low-volume output would be stuck behind the buffer until it fills or + // the logger shuts down, so follow/tail would appear frozen on disk. + fileIdleFlushInterval = 100 * time.Millisecond + // fileFlushTimeout bounds how long a synchronous Flush() waits for the + // logger goroutine to acknowledge. It exists purely as a deadlock guard for + // the rare case where the goroutine is paused or already gone (e.g. Flush + // racing shutdown); under normal operation the ack is near-instant. + fileFlushTimeout = 2 * time.Second +) + type fileMessageBuf struct { now time.Time message string @@ -23,7 +43,13 @@ type file struct { pauseCh chan struct{} resumeCh chan struct{} rotateCh chan struct{} - flushCh chan struct{} + // flushCh carries a per-call reply channel so Flush() can block until the + // logger goroutine has actually drained the buffer channel and flushed the + // bufio writer to disk. This makes Flush() synchronous, which the crash path + // (dlog.FatalPanic -> Flush -> panic) relies on: an async signal could let + // the process unwind before the goroutine drains, dropping up to one buffer + // (64KB) of Fatal diagnostics. + flushCh chan chan struct{} fd *os.File writer *bufio.Writer mutex sync.Mutex @@ -32,13 +58,20 @@ type file struct { strategy Strategy } +var _ Logger = (*file)(nil) + func newFile(strategy Strategy) *file { + // Pause/Resume/Rotate use capacity-1, non-blocking coalescing sends so + // callers never block on the logger goroutine (repeated signals collapse + // into one pending notification). flushCh is unbuffered and carries a reply + // channel because Flush() is synchronous: it must wait for the goroutine to + // drain and write before returning. return &file{ bufferCh: make(chan *fileMessageBuf, runtime.NumCPU()*100), - pauseCh: make(chan struct{}), - resumeCh: make(chan struct{}), - rotateCh: make(chan struct{}), - flushCh: make(chan struct{}), + pauseCh: make(chan struct{}, 1), + resumeCh: make(chan struct{}, 1), + rotateCh: make(chan struct{}, 1), + flushCh: make(chan chan struct{}), strategy: strategy, } } @@ -67,17 +100,43 @@ func (f *file) Start(ctx context.Context, wg *sync.WaitGroup) { go func() { defer wg.Done() + // Idle-flush ticker: with a real (64KB) buffer, low-volume output + // (follow/interactive) would otherwise sit in the buffer until it + // fills. The ticker flushes any partial buffer promptly so follow/tail + // output reaches disk within fileIdleFlushInterval. flush() is cheap + // when nothing is buffered. + ticker := time.NewTicker(fileIdleFlushInterval) + defer ticker.Stop() for { select { case m := <-f.bufferCh: f.write(m) + case <-ticker.C: + f.flush() case <-f.pauseCh: + // Flush before pausing so all output produced so far is on + // disk before the caller (e.g. an interactive prompt) writes + // directly to the terminal/file; preserves ordering. + f.flush() pause(ctx) - case <-f.flushCh: + case done := <-f.flushCh: + // Synchronous flush: drain + write, then acknowledge so the + // blocked Flush() caller can proceed (used by FatalPanic). f.flush() + close(done) + case <-f.rotateCh: + // Force re-opening the outfile on the next write. + // Drained here (not only from write()) so that Rotate() + // makes progress even when no log messages arrive. + f.lastFileName = "" case <-ctx.Done(): f.flush() - f.fd.Close() + // f.fd is only populated after the first getWriter() call; + // guard against a nil pointer when the logger is shut down + // before anything has been written. + if f.fd != nil { + f.fd.Close() + } return } } @@ -100,21 +159,43 @@ func (f *file) RawWithColors(now time.Time, message, coloredMessage string) { panic("Colors not supported in file logger") } -func (f *file) Pause() { f.pauseCh <- struct{}{} } -func (f *file) Resume() { f.resumeCh <- struct{}{} } -func (f *file) Flush() { f.flushCh <- struct{}{} } +// signal performs a non-blocking, coalescing send on a capacity-1 control +// channel. If a signal is already pending the new one is dropped, which is +// the desired behaviour for idempotent operations such as Pause/Rotate/Flush. +func signal(ch chan struct{}) { + select { + case ch <- struct{}{}: + default: + } +} -func (f *file) Rotate() { f.rotateCh <- struct{}{} } -func (*file) SupportsColors() bool { return false } +func (f *file) Pause() { signal(f.pauseCh) } +func (f *file) Resume() { signal(f.resumeCh) } +func (f *file) Rotate() { signal(f.rotateCh) } -func (f *file) write(m *fileMessageBuf) { +// Flush synchronously drains any queued messages and writes the bufio buffer to +// disk, blocking until the logger goroutine acknowledges. The crash path +// (dlog.FatalPanic) depends on this: with an async signal the process could +// panic and unwind before the goroutine drained, losing buffered diagnostics. +// A bounded timeout guards against a deadlock when the goroutine is paused or +// has already exited (Flush racing shutdown), in which case the ctx.Done path +// has already flushed or will flush. +func (f *file) Flush() { + done := make(chan struct{}) select { - case <-f.rotateCh: - // Force re-opening the outfile next time in getWriter. - f.lastFileName = "" - default: + case f.flushCh <- done: + case <-time.After(fileFlushTimeout): + return + } + select { + case <-done: + case <-time.After(fileFlushTimeout): } +} + +func (*file) SupportsColors() bool { return false } +func (f *file) write(m *fileMessageBuf) { var writer *bufio.Writer if f.strategy.Rotation == DailyRotation { writer = f.getWriter(m.now.Format("20060102")) @@ -150,9 +231,12 @@ func (f *file) getWriter(name string) *bufio.Writer { f.writer.Flush() f.fd.Close() } - // Set new writer. + // Set new writer. Use a real buffer (fileWriterBufSize) so bulk payload + // batches into few write syscalls instead of one-or-two per line. The + // logger goroutine's idle ticker and the ctx.Done/flush/pause paths keep + // low-volume and shutdown output from being stuck in the buffer. f.fd = newFd - f.writer = bufio.NewWriterSize(f.fd, 1) + f.writer = bufio.NewWriterSize(f.fd, fileWriterBufSize) f.lastFileName = name return f.writer diff --git a/internal/io/dlog/loggers/file_test.go b/internal/io/dlog/loggers/file_test.go new file mode 100644 index 0000000..0436327 --- /dev/null +++ b/internal/io/dlog/loggers/file_test.go @@ -0,0 +1,183 @@ +package loggers + +import ( + "context" + "os" + "path/filepath" + "strconv" + "strings" + "sync" + "testing" + "time" + + "github.com/mimecast/dtail/internal/config" +) + +// withTempLogDir points config.Common.LogDir at a fresh temp dir for the +// duration of a test and restores the previous config afterwards. The file +// logger resolves its output path from config.Common.LogDir at write time. +func withTempLogDir(t *testing.T) string { + t.Helper() + dir := t.TempDir() + prev := config.Common + config.Common = &config.CommonConfig{LogDir: dir} + t.Cleanup(func() { config.Common = prev }) + return dir +} + +// startFileLogger starts f and returns a stop func that cancels the context and +// JOINS the logger goroutine (wg.Wait). Tests must defer stop() so the goroutine +// has fully exited before returning: withTempLogDir's t.Cleanup restores the +// global config.Common, and a still-running goroutine reading config.Common.LogDir +// would otherwise race that restore. For the same reason none of these tests may +// call t.Parallel — they mutate the process-global config.Common. +func startFileLogger(t *testing.T, f *file) func() { + t.Helper() + ctx, cancel := context.WithCancel(context.Background()) + var wg sync.WaitGroup + wg.Add(1) + f.Start(ctx, &wg) + return func() { + cancel() + wg.Wait() + } +} + +func readLogFile(t *testing.T, dir, base string) string { + t.Helper() + data, err := os.ReadFile(filepath.Join(dir, base+".log")) + if err != nil { + if os.IsNotExist(err) { + return "" + } + t.Fatalf("reading log file: %v", err) + } + return string(data) +} + +// TestFileLoggerNothingLostOnClose verifies every logged line reaches disk when +// the context is cancelled (clean shutdown): the goroutine drains the buffer +// channel and flushes the 64KB writer before closing the fd. +func TestFileLoggerNothingLostOnClose(t *testing.T) { + dir := withTempLogDir(t) + base := "close-test" + f := newFile(Strategy{Rotation: SignalRotation, FileBase: base}) + stop := startFileLogger(t, f) + + const n = 500 + var want strings.Builder + for i := 0; i < n; i++ { + line := "line-" + strconv.Itoa(i) + f.Log(time.Now(), line) + want.WriteString(line + "\n") + } + + // stop() cancels the context and joins the goroutine, which flushes and + // closes the fd on the way out — so all output must be on disk afterwards. + stop() + + if got := readLogFile(t, dir, base); got != want.String() { + t.Fatalf("lost output on close: got %d bytes, want %d bytes", + len(got), want.Len()) + } +} + +// TestFileLoggerIdleFlush verifies a single low-volume line (follow/tail style) +// is not stuck behind the 64KB buffer: the idle ticker flushes it to disk +// promptly without any explicit Flush or shutdown. The logger goroutine is +// joined via stop() before returning so it cannot outlive config.Common. +func TestFileLoggerIdleFlush(t *testing.T) { + dir := withTempLogDir(t) + base := "idle-test" + f := newFile(Strategy{Rotation: SignalRotation, FileBase: base}) + stop := startFileLogger(t, f) + defer stop() + + f.Log(time.Now(), "follow-line") + + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) { + if strings.Contains(readLogFile(t, dir, base), "follow-line") { + return + } + time.Sleep(5 * time.Millisecond) + } + t.Fatal("follow-style line stuck behind buffer; idle flush did not emit it") +} + +// TestFileLoggerExplicitFlush verifies Flush() is SYNCHRONOUS: once it returns, +// the buffered data is already on disk (no polling needed). This is the property +// dlog.FatalPanic relies on to not drop Fatal diagnostics before panicking. +func TestFileLoggerExplicitFlush(t *testing.T) { + dir := withTempLogDir(t) + base := "flush-test" + f := newFile(Strategy{Rotation: SignalRotation, FileBase: base}) + stop := startFileLogger(t, f) + defer stop() + + f.Log(time.Now(), "flush-me") + f.Flush() + + if got := readLogFile(t, dir, base); !strings.Contains(got, "flush-me") { + t.Fatalf("synchronous Flush() did not persist data before returning; got %q", got) + } +} + +// TestFileLoggerRotateDoesNotBlockWithoutWrites verifies that Rotate() does +// not deadlock when no log messages have been produced. Previously rotateCh +// was unbuffered and only drained opportunistically from write(), so a SIGHUP +// before any Log() call would block the caller forever. +func TestFileLoggerRotateDoesNotBlockWithoutWrites(t *testing.T) { + f := newFile(Strategy{Rotation: SignalRotation, FileBase: "unit-test"}) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + var wg sync.WaitGroup + wg.Add(1) + f.Start(ctx, &wg) + + done := make(chan struct{}) + go func() { + f.Rotate() + close(done) + }() + + select { + case <-done: + case <-time.After(500 * time.Millisecond): + t.Fatal("Rotate() blocked without any writes; expected prompt return") + } + + cancel() + wg.Wait() +} + +// TestFileLoggerCancelBeforeFirstWriteDoesNotPanic verifies that cancelling +// the context before any write has happened does not panic. Previously the +// goroutine called f.fd.Close() unconditionally, but f.fd is only populated +// by the first getWriter() call, so a ctx cancel with no prior writes +// panicked on a nil pointer. +func TestFileLoggerCancelBeforeFirstWriteDoesNotPanic(t *testing.T) { + f := newFile(Strategy{Rotation: SignalRotation, FileBase: "unit-test"}) + + ctx, cancel := context.WithCancel(context.Background()) + + var wg sync.WaitGroup + wg.Add(1) + f.Start(ctx, &wg) + + cancel() + + doneCh := make(chan struct{}) + go func() { + wg.Wait() + close(doneCh) + }() + + select { + case <-doneCh: + case <-time.After(1 * time.Second): + t.Fatal("file logger goroutine did not exit after ctx cancel") + } +} diff --git a/internal/io/dlog/loggers/fout.go b/internal/io/dlog/loggers/fout.go index 6888d40..0d3fde5 100644 --- a/internal/io/dlog/loggers/fout.go +++ b/internal/io/dlog/loggers/fout.go @@ -4,16 +4,47 @@ import ( "context" "sync" "time" + + "github.com/mimecast/dtail/internal/config" ) +// fout logs to both a file and stdout. It is the default client logger. +// +// The two things a client emits are deliberately split at this seam: +// - Diagnostics (connection INFO/WARN/ERROR/etc.) arrive via Log/LogWithColors +// and are ALWAYS written to both stdout and the file — they are the small, +// useful audit trail the daily log file is meant to keep. +// - Retrieved payload (the bulk dcat/dgrep/dtail output) arrives via +// Raw/RawWithColors. It always reaches stdout/terminal, but it is teed to +// the file only when logPayload is set (opt-in via --log-payload / +// Client.LogPayload). By default the file receives no payload, so a bulk +// dcat no longer silently grows the daily log file by the full payload size. type fout struct { - file *file - stdout *stdout + file Logger + stdout Logger + logPayload bool } -// Logs to both, a file and stdout +// newFout builds the default client logger. Whether retrieved payload is teed +// to the file is decided once at construction from the client config. func newFout(strategy Strategy) *fout { - return &fout{file: newFile(strategy), stdout: newStdout()} + return newFoutWithSinks(newFile(strategy), newStdout(), clientLogPayloadEnabled()) +} + +// newFoutWithSinks builds a fout over injectable sinks and an explicit payload +// switch. Production uses newFout (concrete file+stdout, config-driven switch); +// tests inject fakes to assert that diagnostics always reach the file while +// payload reaches it only when opted in. +func newFoutWithSinks(file, stdout Logger, logPayload bool) *fout { + return &fout{file: file, stdout: stdout, logPayload: logPayload} +} + +// clientLogPayloadEnabled reports whether the client has opted in to teeing the +// full retrieved payload into the daily log file. Default (false) keeps only +// diagnostics in the file. config.Client is nil-guarded because a logger can be +// constructed in early/unit contexts before config.Setup has populated it. +func clientLogPayloadEnabled() bool { + return config.Client != nil && config.Client.LogPayload } func (f *fout) Start(ctx context.Context, wg *sync.WaitGroup) { @@ -35,17 +66,42 @@ func (f *fout) Log(now time.Time, message string) { func (f *fout) LogWithColors(now time.Time, message, colore |