Skip to content

Commit 9ca7fc1

Browse files
mpywclaude
andauthored
fix: Improve SSA tracing for Alloc, nil Phi, and method values (#9)
* fix: Add Alloc tracing and nil Phi edge skipping (#8) Improves SSA value tracing to handle more patterns correctly: ## Alloc Tracing - Add `traceAlloc` to find values stored in local variables - Fixes false positive for `log.Ctx(ctx).With()...Logger()` pattern - Enables tracking through variable assignments in closures ## Nil Phi Edge Skipping - Skip nil constant edges in Phi nodes during tracing - Nil pointers can't have methods called on them, so they're irrelevant - Fixes false positive for `var e *Event; if cond { e = ... }; if e != nil { e.Msg() }` ## Test Updates - Remove outdated LIMITATION comments for now-working patterns - Add test cases for nil Phi edge handling with mixed branches 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com> * feat: Add method value (bound method) detection Detect zerolog terminators called via method values: e := logger.Info() msg := e.Msg // MakeClosure with receiver in Bindings[0] msg("text") // Now detected as terminator Implementation: - Check if call value is MakeClosure in checkTerminatorCall - Extract receiver from MakeClosure.Bindings[0] - Trace receiver to check for context This was previously documented as a LIMITATION but is now fully supported. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com> * docs: Update KNOWN LIMITATIONS in evil_ssa.go Remove fixed items: - Method values (now supported) - Phi node with nil (now handled) 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.5 <noreply@anthropic.com>
1 parent bb834f0 commit 9ca7fc1

File tree

5 files changed

+154
-30
lines changed

5 files changed

+154
-30
lines changed

internal/analyzer.go

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,6 +192,14 @@ func (c *checker) checkTerminatorCall(call *ssa.Call) {
192192
return
193193
}
194194

195+
// Check if this is a bound method call (method value)
196+
// e.g., msg := e.Msg; msg("text")
197+
// In this case, callee is the wrapper (*Event).Msg$bound and recv is nil
198+
if mc, ok := call.Call.Value.(*ssa.MakeClosure); ok {
199+
c.checkBoundMethodTerminator(call, mc, callee)
200+
return
201+
}
202+
195203
// Must be on zerolog.Event and return void (terminators: Msg, Msgf, MsgFunc, Send)
196204
recv := call.Call.Signature().Recv()
197205
if recv == nil || !isEvent(recv.Type()) || !returnsVoid(callee) {
@@ -206,6 +214,34 @@ func (c *checker) checkTerminatorCall(call *ssa.Call) {
206214
c.report(call.Pos())
207215
}
208216

217+
// checkBoundMethodTerminator checks if a bound method call (method value) is a terminator
218+
// without context. Bound methods are created when a method is extracted as a value:
219+
//
220+
// msg := e.Msg // Creates MakeClosure with receiver in Bindings[0]
221+
// msg("text") // Calls the bound method wrapper (*Event).Msg$bound
222+
func (c *checker) checkBoundMethodTerminator(call *ssa.Call, mc *ssa.MakeClosure, callee *ssa.Function) {
223+
// Check if it returns void (terminators return void)
224+
if !returnsVoid(callee) {
225+
return
226+
}
227+
228+
// Check if receiver (in Bindings[0]) is *zerolog.Event
229+
if len(mc.Bindings) == 0 {
230+
return
231+
}
232+
recvType := mc.Bindings[0].Type()
233+
if !isEvent(recvType) {
234+
return
235+
}
236+
237+
// Trace the receiver to find if context was set
238+
if c.eventChainHasCtx(mc.Bindings[0]) {
239+
return
240+
}
241+
242+
c.report(call.Pos())
243+
}
244+
209245
// checkDirectLoggingCall checks for direct logging calls that bypass the Event chain
210246
// (Logger.Print, Logger.Printf, log.Print, log.Printf).
211247
// These calls cannot propagate context and should be reported.

internal/tracing.go

Lines changed: 71 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,11 @@ func (c *checker) traceValue(v ssa.Value, tracer tracer, visited map[ssa.Value]b
7676

7777
callee := call.Call.StaticCallee()
7878
if callee == nil {
79+
// Check if this is a call to a bound method (method value)
80+
// e.g., msg := e.Msg; msg("text") - the receiver is in MakeClosure.Bindings
81+
if mc, ok := call.Call.Value.(*ssa.MakeClosure); ok {
82+
return c.traceBoundMethod(mc, visited, tracer)
83+
}
7984
return c.traceReceiver(call, visited, tracer)
8085
}
8186

@@ -114,6 +119,8 @@ func (c *checker) traceCommon(v ssa.Value, visited map[ssa.Value]bool, tracer tr
114119
return c.traceValue(val.Tuple, tracer, visited)
115120
case *ssa.UnOp:
116121
return c.traceUnOp(val, visited, tracer)
122+
case *ssa.Alloc:
123+
return c.traceAlloc(val, visited, tracer)
117124
case *ssa.ChangeType:
118125
return c.traceValue(val.X, tracer, visited)
119126
case *ssa.MakeInterface:
@@ -141,21 +148,35 @@ func (c *checker) traceCommon(v ssa.Value, visited map[ssa.Value]bool, tracer tr
141148
// =============================================================================
142149

143150
// tracePhi handles SSA Phi nodes where multiple control flow paths merge.
144-
// For context tracking, ALL non-cyclic edges must have context set.
145-
// Cyclic edges (loop back-edges) are skipped as they depend on the
146-
// initial value (e.g., loops like: x := init; for { x = f(x) }).
151+
// For context tracking, ALL non-cyclic, non-nil edges must have context set.
152+
//
153+
// Skipped edges:
154+
// - Cyclic edges (loop back-edges) depend on the initial value
155+
// - Nil constant edges can never reach method calls (would panic)
156+
//
157+
// Example:
158+
//
159+
// var e *zerolog.Event
160+
// if cond { e = logger.Info().Ctx(ctx) }
161+
// if e != nil { e.Msg("...") } // Only non-nil edge matters
147162
func (c *checker) tracePhi(phi *ssa.Phi, visited map[ssa.Value]bool, tracer tracer) bool {
148163
if len(phi.Edges) == 0 {
149164
return false
150165
}
151166

152-
hasNonCyclicEdge := false
167+
hasValidEdge := false
153168
for _, edge := range phi.Edges {
154169
// Skip edges that would cycle back to this Phi
155170
if edgeLeadsTo(edge, phi, visited) {
156171
continue
157172
}
158-
hasNonCyclicEdge = true
173+
174+
// Skip nil constant edges - nil pointers can't have methods called on them
175+
if isNilConst(edge) {
176+
continue
177+
}
178+
179+
hasValidEdge = true
159180

160181
// Clone visited for independent tracing of each branch
161182
edgeVisited := make(map[ssa.Value]bool)
@@ -166,8 +187,20 @@ func (c *checker) tracePhi(phi *ssa.Phi, visited map[ssa.Value]bool, tracer trac
166187
}
167188
}
168189

169-
// If all edges are cyclic, we need at least one valid edge to check
170-
return hasNonCyclicEdge
190+
// Need at least one valid (non-cyclic, non-nil) edge to check
191+
return hasValidEdge
192+
}
193+
194+
// isNilConst checks if a value is a nil constant.
195+
// Nil pointers cannot have methods called on them, so they are safe to skip
196+
// when tracing Phi nodes (the nil path would panic before reaching the call).
197+
func isNilConst(v ssa.Value) bool {
198+
c, ok := v.(*ssa.Const)
199+
if !ok {
200+
return false
201+
}
202+
// For nil pointer constants, Value is nil
203+
return c.Value == nil
171204
}
172205

173206
// edgeLeadsTo checks if tracing this edge would eventually lead back to target.
@@ -224,6 +257,21 @@ func (c *checker) traceUnOp(unop *ssa.UnOp, visited map[ssa.Value]bool, tracer t
224257
return c.traceValue(unop.X, tracer, visited)
225258
}
226259

260+
// traceAlloc handles SSA Alloc nodes (local variable allocation).
261+
// When a variable is used as a receiver (e.g., logger.Info()), we need to
262+
// find what value was stored into that variable.
263+
//
264+
// Example:
265+
//
266+
// logger := log.Ctx(ctx).With().Logger() // t0 = new Logger; *t0 = result
267+
// logger.Info().Msg("test") // uses t0 (address of logger)
268+
func (c *checker) traceAlloc(alloc *ssa.Alloc, visited map[ssa.Value]bool, tracer tracer) bool {
269+
if stored := findStoredValue(alloc); stored != nil {
270+
return c.traceValue(stored, tracer, visited)
271+
}
272+
return false
273+
}
274+
227275
// traceFreeVar traces a FreeVar back to the value bound in MakeClosure.
228276
// FreeVars are variables captured from an enclosing function scope.
229277
func (c *checker) traceFreeVar(fv *ssa.FreeVar, visited map[ssa.Value]bool, tracer tracer) bool {
@@ -280,6 +328,22 @@ func (c *checker) traceReceiver(call *ssa.Call, visited map[ssa.Value]bool, trac
280328
return false
281329
}
282330

331+
// traceBoundMethod traces a bound method (method value) call.
332+
// When a method is extracted as a value (e.g., msg := e.Msg), SSA creates
333+
// a MakeClosure with the receiver in Bindings[0].
334+
//
335+
// Example:
336+
//
337+
// e := logger.Info().Ctx(ctx)
338+
// msg := e.Msg // MakeClosure with Bindings[0] = e
339+
// msg("text") // Call to the closure
340+
func (c *checker) traceBoundMethod(mc *ssa.MakeClosure, visited map[ssa.Value]bool, tracer tracer) bool {
341+
if len(mc.Bindings) > 0 {
342+
return c.traceValue(mc.Bindings[0], tracer, visited)
343+
}
344+
return false
345+
}
346+
283347
// =============================================================================
284348
// Store Tracking
285349
// =============================================================================

testdata/src/zerolog/evil.go

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -58,10 +58,7 @@ func evilClosureCapturingDerivedLogger(ctx context.Context, logger zerolog.Logge
5858
func evilClosureCapturingDerivedLoggerWithCtx(ctx context.Context, logger zerolog.Logger) {
5959
derived := logger.With().Ctx(ctx).Logger()
6060
doSomething := func() {
61-
// NOTE: In test stubs, SSA optimizes away the receiver for method calls
62-
// on zero-value structs with empty implementations. In production code
63-
// with real zerolog, FreeVar tracing through MakeClosure bindings works.
64-
derived.Info().Msg("captured derived with ctx") // want `zerolog call chain missing .Ctx\(ctx\)`
61+
derived.Info().Msg("captured derived with ctx") // OK - ctx set via With().Ctx(ctx)
6562
}
6663
doSomething()
6764
}

testdata/src/zerolog/evil_logger.go

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -185,9 +185,7 @@ func badGoroutineWithDerivedLogger(ctx context.Context, logger zerolog.Logger) {
185185
func goodGoroutineWithDerivedLoggerCtx(ctx context.Context, logger zerolog.Logger) {
186186
derived := logger.With().Ctx(ctx).Logger()
187187
go func() {
188-
// LIMITATION: FreeVar tracking through MakeClosure not working in test stubs
189-
// In production, this would be OK since derived has ctx
190-
derived.Info().Msg("goroutine derived with ctx") // want `zerolog call chain missing .Ctx\(ctx\)`
188+
derived.Info().Msg("goroutine derived with ctx") // OK - ctx set via With().Ctx(ctx)
191189
}()
192190
}
193191

testdata/src/zerolog/evil_ssa.go

Lines changed: 45 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -8,15 +8,13 @@
88
//
99
// False Negatives (should report but doesn't):
1010
// - IIFE/Helper returns: Cross-function tracking not supported
11-
// - Method values: `msg := e.Msg; msg("test")`
1211
// - Deep FreeVar: Triple-nested closures
1312
//
1413
// False Positives (reports when shouldn't):
1514
// - Channel send/receive: Can't trace through channels
1615
// - sync.Pool: Can't trace through Get/Put
1716
// - Embedded struct: `h.Msg()` where h embeds *Event
1817
// - Closure-modified capture: Closure writes to outer var
19-
// - Phi node with nil: `var e; if cond { e = ... }; e.Msg()`
2018
package zerolog
2119

2220
import (
@@ -168,11 +166,10 @@ func badClosureCaptureDeep(ctx context.Context, logger zerolog.Logger) {
168166
fn()
169167
}
170168

171-
func limitationClosureCaptureWithCtx(ctx context.Context, logger zerolog.Logger) {
172-
// LIMITATION: SSA doesn't track .Ctx() on captured variables used in closures
169+
func goodClosureCaptureWithCtx(ctx context.Context, logger zerolog.Logger) {
173170
e := logger.Info().Ctx(ctx)
174171
fn := func() {
175-
e.Msg("captured with ctx") // want `zerolog call chain missing .Ctx\(ctx\)`
172+
e.Msg("captured with ctx") // OK - ctx set via .Ctx(ctx)
176173
}
177174
fn()
178175
}
@@ -557,26 +554,31 @@ func badTripleNestedClosure(ctx context.Context, logger zerolog.Logger) {
557554
}()
558555
}
559556

560-
func limitationTripleNestedClosureWithCtx(ctx context.Context, logger zerolog.Logger) {
561-
// LIMITATION: Deep FreeVar tracking through multiple closure levels
557+
func goodTripleNestedClosureWithCtx(ctx context.Context, logger zerolog.Logger) {
562558
e := logger.Info().Ctx(ctx)
563559
func() {
564560
func() {
565561
func() {
566-
e.Msg("triple nested with ctx") // want `zerolog call chain missing .Ctx\(ctx\)`
562+
e.Msg("triple nested with ctx") // OK - ctx set via .Ctx(ctx)
567563
}()
568564
}()
569565
}()
570566
}
571567

572568
// ===== METHOD VALUE =====
573569

574-
// LIMITATION: Method values extract the function from the receiver, creating a different
575-
// SSA pattern. The analyzer cannot trace through method value extraction.
576-
func limitationMethodValue(ctx context.Context, logger zerolog.Logger) {
570+
// Method values extract the method from the receiver, creating a MakeClosure.
571+
// The analyzer traces through the closure bindings to find the receiver.
572+
func badMethodValue(ctx context.Context, logger zerolog.Logger) {
577573
e := logger.Info()
578574
msg := e.Msg
579-
msg("method value") // LIMITATION: should report but doesn't due to method value extraction
575+
msg("method value") // want `zerolog call chain missing .Ctx\(ctx\)`
576+
}
577+
578+
func goodMethodValueWithCtx(ctx context.Context, logger zerolog.Logger) {
579+
e := logger.Info().Ctx(ctx)
580+
msg := e.Msg
581+
msg("method value with ctx") // OK - ctx set via .Ctx(ctx)
580582
}
581583

582584
// ===== STRUCT WITH MULTIPLE EVENT FIELDS =====
@@ -941,15 +943,42 @@ func badNilCheckBeforeUse(ctx context.Context, logger zerolog.Logger) {
941943
}
942944
}
943945

944-
// LIMITATION (false positive): Phi node sees potential nil from else branch.
945-
// Even with `if true`, SSA still models an else path where e is nil (zero value).
946-
func limitationNilCheckWithCtx(ctx context.Context, logger zerolog.Logger) {
946+
// Phi node with nil edge from uninitialized variable.
947+
// The nil edge is skipped because nil pointers can't have methods called on them.
948+
func goodNilCheckWithCtx(ctx context.Context, logger zerolog.Logger) {
947949
var e *zerolog.Event
948950
if true {
949951
e = logger.Info().Ctx(ctx)
950952
}
951953
if e != nil {
952-
e.Msg("nil checked with ctx") // want `zerolog call chain missing .Ctx\(ctx\)`
954+
e.Msg("nil checked with ctx") // OK - nil edge skipped, ctx edge has context
955+
}
956+
}
957+
958+
// Phi node with nil + multiple non-nil edges.
959+
// All non-nil edges must have context.
960+
func badNilCheckMixedEdges(ctx context.Context, logger zerolog.Logger, cond1, cond2 bool) {
961+
var e *zerolog.Event
962+
if cond1 {
963+
e = logger.Info().Ctx(ctx) // has ctx
964+
} else if cond2 {
965+
e = logger.Info() // no ctx
966+
}
967+
if e != nil {
968+
e.Msg("mixed edges") // want `zerolog call chain missing .Ctx\(ctx\)`
969+
}
970+
}
971+
972+
// Phi node where all non-nil edges have context.
973+
func goodNilCheckAllEdgesWithCtx(ctx context.Context, logger zerolog.Logger, cond1, cond2 bool) {
974+
var e *zerolog.Event
975+
if cond1 {
976+
e = logger.Info().Ctx(ctx)
977+
} else if cond2 {
978+
e = logger.Debug().Ctx(ctx)
979+
}
980+
if e != nil {
981+
e.Msg("all edges with ctx") // OK - nil skipped, all non-nil have ctx
953982
}
954983
}
955984

0 commit comments

Comments
 (0)