{agent, event, log}: Output EmitEvent logs at the trace level (#739)

Author: Flash-LHR

agent/invocation.go

@@ -488,7 +488,7 @@ func EmitEvent(ctx context.Context, inv *Invocation, ch chan<- *event.Event,
 		agentName = inv.AgentName
 		requestID = inv.RunOptions.RequestID
 	}
-	log.Debugf("[agent.EmitEvent]queue monitoring:RequestID: %s channel capacity: %d, current length: %d, branch: %s, agent name:%s",
+	log.Tracef("[agent.EmitEvent]queue monitoring:RequestID: %s channel capacity: %d, current length: %d, branch: %s, agent name:%s",
 		requestID, cap(ch), len(ch), e.Branch, agentName)
 	return event.EmitEvent(ctx, ch, e)
 }

event/event.go

@@ -255,13 +255,13 @@ func EmitEventWithTimeout(ctx context.Context, ch chan<- *Event,
 		return err
 	}
 
-	log.Debugf("[EmitEventWithTimeout]queue monitoring: RequestID: %s, channel capacity: %d, current length: %d, branch: %s",
+	log.Tracef("[EmitEventWithTimeout]queue monitoring: RequestID: %s, channel capacity: %d, current length: %d, branch: %s",
 		e.RequestID, cap(ch), len(ch), e.Branch)
 
 	if timeout == EmitWithoutTimeout {
 		select {
 		case ch <- e:
-			log.Debugf("EmitEventWithTimeout: event sent, event: %+v", *e)
+			log.Tracef("EmitEventWithTimeout: event sent, event: %+v", *e)
 		case <-ctx.Done():
 			log.Warnf("EmitEventWithTimeout: context cancelled, event: %+v", *e)
 			return ctx.Err()
@@ -271,7 +271,7 @@ func EmitEventWithTimeout(ctx context.Context, ch chan<- *Event,
 
 	select {
 	case ch <- e:
-		log.Debugf("EmitEventWithTimeout: event sent, event: %+v", *e)
+		log.Tracef("EmitEventWithTimeout: event sent, event: %+v", *e)
 	case <-ctx.Done():
 		log.Warnf("EmitEventWithTimeout: context cancelled, event: %+v", *e)
 		return ctx.Err()

log/level_test.go

@@ -12,6 +12,7 @@ package log
 // ... existing code ...
 
 import (
+	"strings"
 	"testing"
 
 	"go.uber.org/zap/zapcore"
@@ -42,26 +43,47 @@ func TestSetLevel(t *testing.T) {
 	}
 }
 
-// TestTracef makes sure Tracef forwards the call to the underlying
-// logger at the debug level. The test installs a stub logger that
-// records the last format string received and asserts that Tracef
-// prefixes the message with the required tag.
-func TestTracef(t *testing.T) {
-	var recorded string
-	stub := &stubLogger{debugf: func(format string, _ ...any) {
-		recorded = format
-	}}
+// TestTraceDisabledByDefault ensures trace logging starts disabled and Tracef is a no-op.
+func TestTraceDisabledByDefault(t *testing.T) {
+	stub := &stubLogger{}
+	oldDefault := Default
+	oldTrace := traceEnabled
+	Default = stub
+	t.Cleanup(func() {
+		Default = oldDefault
+		traceEnabled = oldTrace
+	})
+
+	if traceEnabled {
+		t.Fatalf("traceEnabled should be false by default")
+	}
+
+	Tracef("hello %s", "world")
 
-	// Replace Default logger with stub and restore afterwards.
-	old := Default
+	if stub.debugfCalls != 0 {
+		t.Fatalf("Tracef should not log when trace is disabled; got %d calls", stub.debugfCalls)
+	}
+}
+
+// TestTracefEnabled makes sure Tracef forwards the call when trace is enabled.
+func TestTracefEnabled(t *testing.T) {
+	stub := &stubLogger{}
+	oldDefault := Default
+	oldTrace := traceEnabled
 	Default = stub
-	defer func() { Default = old }()
+	SetTraceEnabled(true)
+	t.Cleanup(func() {
+		Default = oldDefault
+		traceEnabled = oldTrace
+	})
 
 	Tracef("hello %s", "world")
 
-	wantPrefix := "[TRACE] "
-	if recorded == "" || recorded[:len(wantPrefix)] != wantPrefix {
-		t.Fatalf("Tracef did not prefix message with %q: got %q", wantPrefix, recorded)
+	if stub.debugfCalls != 1 {
+		t.Fatalf("Tracef should log once when trace is enabled; got %d calls", stub.debugfCalls)
+	}
+	if !strings.HasPrefix(stub.lastFormat, "[TRACE] ") {
+		t.Fatalf("Tracef did not prefix message with \"[TRACE] \": got %q", stub.lastFormat)
 	}
 }
 
@@ -70,11 +92,15 @@ func TestTracef(t *testing.T) {
 // Only the methods required by the tests are implemented; the rest
 // are no-ops to satisfy the interface.
 type stubLogger struct {
-	debugf func(format string, args ...any)
+	lastFormat  string
+	debugfCalls int
 }
 
-func (s *stubLogger) Debug(args ...any)                 {}
-func (s *stubLogger) Debugf(format string, args ...any) { s.debugf(format, args...) }
+func (s *stubLogger) Debug(args ...any) {}
+func (s *stubLogger) Debugf(format string, args ...any) {
+	s.debugfCalls++
+	s.lastFormat = format
+}
 func (s *stubLogger) Info(args ...any)                  {}
 func (s *stubLogger) Infof(format string, args ...any)  {}
 func (s *stubLogger) Warn(args ...any)                  {}

log/log.go

@@ -31,7 +31,10 @@ const (
 	LevelFatal = "fatal"
 )
 
-var zapLevel = zap.NewAtomicLevelAt(zapcore.InfoLevel)
+var (
+	zapLevel     = zap.NewAtomicLevelAt(zapcore.InfoLevel)
+	traceEnabled = false
+)
 
 // Default borrows logging utilities from zap.
 // You may replace it with whatever logger you like as long as it implements log.Logger interface.
@@ -155,7 +158,13 @@ func Fatalf(format string, args ...any) {
 
 // Tracef logs a message at the trace level with formatting.
 func Tracef(format string, args ...any) {
-	// Trace is more detailed than debug, so we'll log it at debug level
-	// until we have proper trace level support in the underlying logger
+	if !traceEnabled {
+		return
+	}
 	Default.Debugf("[TRACE] "+format, args...)
 }
+
+// SetTraceEnabled sets the trace enabled flag.
+func SetTraceEnabled(enabled bool) {
+	traceEnabled = enabled
+}