From 0008e021f091c423d8863f38da36aa32a4938817 Mon Sep 17 00:00:00 2001 From: Jacob Oaks Date: Wed, 21 Jun 2023 12:28:45 -0400 Subject: [PATCH] Include Module Traces in Provided/Decorated/Supplied/Replaced Events Currently, the events that the fxevent package emits for provides/decorates/supplies/replaces include stack traces of where the Fx call was made. These stack traces often look something like this: ``` somepkg.init (/path/to/some/distant/package/module.go:14) runtime.doInit1 (/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:6740) runtime.doInit (/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:6707) runtime.main (/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:249) ``` While these do show exactly where the provide/decorate/supply/replace statement lives, for larger codebases where a single app may include a wide variety of modules, each with their own chain of sub-modules, this stack trace does a bad job of answering: "How did this constructor get included in my app in the first place?" This PR proposes module traces, an attempt to alleviate this issue by providing a trace through the module chain by which a provide/decorate/supply/replace found its way to the top-level app declaration. For this example, ``` 9 func getThing() thing { 10 return thing{} 11 } 12 13 var ThingModule = fx.Module( 14 "ThingFx", 15 fx.Provide(getThing), 16 ) 17 18 var ServiceModule = fx.Module( 19 "ServiceFx", 20 ThingModule, 21 ) 22 23 func main() { 24 app := fx.New( 25 ServiceModule, 26 fx.Invoke(useThing), 27 ) 28 } ``` The provide event for `getThing` will include the following module trace: ``` main.run (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:24) main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:18) main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:13) main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:15) ``` Which shows exactly how `getThing` got included in `app` in order: * The app is declared at `main.go:24` * ServiceFx is declared at `main.go:18` * ThingFx is declared at `main.go:13` * getThing is provided at `main.go:15` This makes it more clear to the developer how functions are getting included, especially for large codebase where modules may be distributed all over. --- app.go | 3 +- app_test.go | 117 ++++++++++++++++++++++++++++++++++++++-- fxevent/console_test.go | 20 +++++-- fxevent/event.go | 12 +++++ fxevent/zap.go | 8 +++ fxevent/zap_test.go | 76 ++++++++++++++++---------- module.go | 37 +++++++++---- 7 files changed, 224 insertions(+), 49 deletions(-) diff --git a/app.go b/app.go index d524a5e98..2c5a3c41d 100644 --- a/app.go +++ b/app.go @@ -432,7 +432,8 @@ func New(opts ...Option) *App { // user gave us. For the last case, however, we need to fall // back to what was provided to fx.Logger if fx.WithLogger // fails. - log: logger, + log: logger, + location: fxreflect.CallerStack(1, 0)[0], } app.modules = append(app.modules, app.root) diff --git a/app_test.go b/app_test.go index 8e0bdc681..4c4ee1331 100644 --- a/app_test.go +++ b/app_test.go @@ -1,4 +1,4 @@ -// Copyright (c) 2022 Uber Technologies, Inc. +// Copyright (c) 2023 Uber Technologies, Inc. // // Permission is hereby granted, free of charge, to any person obtaining a copy // of this software and associated documentation files (the "Software"), to deal @@ -29,7 +29,9 @@ import ( "log" "os" "reflect" + "regexp" "runtime" + "strings" "testing" "time" @@ -650,9 +652,114 @@ func TestWithLogger(t *testing.T) { }) } -type errHandlerFunc func(error) +func getInt() int { return 0 } -func (f errHandlerFunc) HandleError(err error) { f(err) } +func decorateInt(i int) int { return i } + +var moduleA = Module( + "ModuleA", + Provide(getInt), + Decorate(decorateInt), + Supply(int64(14)), + Replace("foo"), +) + +func getModuleB() Option { + return Module( + "ModuleB", + moduleA, + ) +} + +func TestModuleTrace(t *testing.T) { + t.Parallel() + + moduleC := Module( + "ModuleC", + getModuleB(), + ) + + app, spy := NewSpied(moduleC) + require.NoError(t, app.Err()) + + wantTrace, err := regexp.Compile( + // Top-level app & corresponding module created by NewSpied. + "^go.uber.org/fx_test.NewSpied (.*fx/app_test.go:.*)\n" + + // ModuleC above. + "go.uber.org/fx_test.TestModuleTrace (.*fx/app_test.go:.*)\n" + + // ModuleB from getModuleB. + "go.uber.org/fx_test.getModuleB (.*fx/app_test.go:.*)\n" + + // ModuleA initialized via init. + "go.uber.org/fx_test.init (.*fx/app_test.go:.*)\n" + + // Provide/decorate itself, also initialized via init. + "go.uber.org/fx_test.init (.*fx/app_test.go:.*)$", + ) + require.NoError(t, err, "test regexp compilation error") + + for _, tt := range []struct { + desc string + getTrace func(t *testing.T) []string + }{ + { + desc: "Provide", + getTrace: func(t *testing.T) []string { + t.Helper() + var event *fxevent.Provided + for _, e := range spy.Events().SelectByTypeName("Provided") { + pe, ok := e.(*fxevent.Provided) + if !ok { + continue + } + + if strings.HasSuffix(pe.ConstructorName, "getInt()") { + event = pe + break + } + } + require.NotNil(t, event, "could not find provide event for getInt()") + return event.ModuleTrace + }, + }, + { + desc: "Decorate", + getTrace: func(t *testing.T) []string { + t.Helper() + events := spy.Events().SelectByTypeName("Decorated") + require.Len(t, events, 1) + event, ok := events[0].(*fxevent.Decorated) + require.True(t, ok) + return event.ModuleTrace + }, + }, + { + desc: "Supply", + getTrace: func(t *testing.T) []string { + t.Helper() + events := spy.Events().SelectByTypeName("Supplied") + require.Len(t, events, 1) + event, ok := events[0].(*fxevent.Supplied) + require.True(t, ok) + return event.ModuleTrace + }, + }, + { + desc: "Replaced", + getTrace: func(t *testing.T) []string { + t.Helper() + events := spy.Events().SelectByTypeName("Replaced") + require.Len(t, events, 1) + event, ok := events[0].(*fxevent.Replaced) + require.True(t, ok) + return event.ModuleTrace + }, + }, + } { + t.Run(tt.desc, func(t *testing.T) { + gotTrace := strings.Join(tt.getTrace(t), "\n") + assert.Regexp(t, wantTrace, gotTrace) + }) + } +} func TestRunEventEmission(t *testing.T) { t.Parallel() @@ -813,6 +920,10 @@ func (e *customError) Unwrap() error { return e.err } +type errHandlerFunc func(error) + +func (f errHandlerFunc) HandleError(err error) { f(err) } + func TestInvokes(t *testing.T) { t.Parallel() diff --git a/fxevent/console_test.go b/fxevent/console_test.go index 2d346dc1e..fcaa41d3d 100644 --- a/fxevent/console_test.go +++ b/fxevent/console_test.go @@ -138,17 +138,19 @@ func TestConsoleLogger(t *testing.T) { { name: "Supplied", give: &Supplied{ - TypeName: "*bytes.Buffer", - StackTrace: []string{"main.main", "runtime.main"}, + TypeName: "*bytes.Buffer", + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, want: "[Fx] SUPPLY *bytes.Buffer\n", }, { name: "Supplied with module", give: &Supplied{ - TypeName: "*bytes.Buffer", - ModuleName: "myModule", - StackTrace: []string{"main.main", "runtime.main"}, + TypeName: "*bytes.Buffer", + ModuleName: "myModule", + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main", "mypackage.GetMyModule"}, }, want: "[Fx] SUPPLY *bytes.Buffer from module \"myModule\"\n", }, @@ -169,6 +171,7 @@ func TestConsoleLogger(t *testing.T) { OutputTypeNames: []string{"*bytes.Buffer"}, Private: false, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer()\n", }, @@ -179,6 +182,7 @@ func TestConsoleLogger(t *testing.T) { OutputTypeNames: []string{"*bytes.Buffer"}, Private: true, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer()\n", }, @@ -190,6 +194,7 @@ func TestConsoleLogger(t *testing.T) { OutputTypeNames: []string{"*bytes.Buffer"}, Private: false, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main", "mypackage.GetMyModule"}, }, want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n", }, @@ -201,6 +206,7 @@ func TestConsoleLogger(t *testing.T) { OutputTypeNames: []string{"*bytes.Buffer"}, Private: true, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main", "mypackage.GetMyModule"}, }, want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n", }, @@ -209,6 +215,7 @@ func TestConsoleLogger(t *testing.T) { give: &Replaced{ OutputTypeNames: []string{"*bytes.Buffer"}, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, want: "[Fx] REPLACE *bytes.Buffer\n", }, @@ -218,6 +225,7 @@ func TestConsoleLogger(t *testing.T) { ModuleName: "myModule", OutputTypeNames: []string{"*bytes.Buffer"}, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main", "mypackage.GetMyModule"}, }, want: "[Fx] REPLACE *bytes.Buffer from module \"myModule\"\n", }, @@ -232,6 +240,7 @@ func TestConsoleLogger(t *testing.T) { DecoratorName: "bytes.NewBuffer()", OutputTypeNames: []string{"*bytes.Buffer"}, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer()\n", }, @@ -242,6 +251,7 @@ func TestConsoleLogger(t *testing.T) { ModuleName: "myModule", OutputTypeNames: []string{"*bytes.Buffer"}, StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main", "mypackage.GetMyModule"}, }, want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n", }, diff --git a/fxevent/event.go b/fxevent/event.go index c87f9a303..7babcd4a0 100644 --- a/fxevent/event.go +++ b/fxevent/event.go @@ -113,6 +113,9 @@ type Supplied struct { // StackTrace is the stack trace of the call to Supply. StackTrace []string + // ModuleTrace contains the module locations through which this value was added. + ModuleTrace []string + // ModuleName is the name of the module in which the value was added to. ModuleName string @@ -129,6 +132,9 @@ type Provided struct { // StackTrace is the stack trace of where the constructor was provided to Fx. StackTrace []string + // ModuleTrace contains the module locations through which this was provided to Fx. + ModuleTrace []string + // OutputTypeNames is a list of names of types that are produced by // this constructor. OutputTypeNames []string @@ -152,6 +158,9 @@ type Replaced struct { // StackTrace is the stack trace of the call to Replace. StackTrace []string + // ModuleTrace contains the module locations through which this value was added. + ModuleTrace []string + // ModuleName is the name of the module in which the value was added to. ModuleName string @@ -168,6 +177,9 @@ type Decorated struct { // StackTrace is the stack trace of where the decorator was given to Fx. StackTrace []string + // ModuleTrace contains the module locations through which this value was added. + ModuleTrace []string + // ModuleName is the name of the module in which the value was added to. ModuleName string diff --git a/fxevent/zap.go b/fxevent/zap.go index c304ea058..613eb8653 100644 --- a/fxevent/zap.go +++ b/fxevent/zap.go @@ -105,12 +105,14 @@ func (l *ZapLogger) LogEvent(event Event) { l.logError("error encountered while applying options", zap.String("type", e.TypeName), zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.Error(e.Err)) } else { l.logEvent("supplied", zap.String("type", e.TypeName), zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), ) } @@ -119,6 +121,7 @@ func (l *ZapLogger) LogEvent(event Event) { l.logEvent("provided", zap.String("constructor", e.ConstructorName), zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.String("type", rtype), maybeBool("private", e.Private), @@ -128,12 +131,14 @@ func (l *ZapLogger) LogEvent(event Event) { l.logError("error encountered while applying options", moduleField(e.ModuleName), zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), zap.Error(e.Err)) } case *Replaced: for _, rtype := range e.OutputTypeNames { l.logEvent("replaced", zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.String("type", rtype), ) @@ -141,6 +146,7 @@ func (l *ZapLogger) LogEvent(event Event) { if e.Err != nil { l.logError("error encountered while replacing", zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.Error(e.Err)) } @@ -149,6 +155,7 @@ func (l *ZapLogger) LogEvent(event Event) { l.logEvent("decorated", zap.String("decorator", e.DecoratorName), zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.String("type", rtype), ) @@ -156,6 +163,7 @@ func (l *ZapLogger) LogEvent(event Event) { if e.Err != nil { l.logError("error encountered while applying options", zap.Strings("stacktrace", e.StackTrace), + zap.Strings("moduletrace", e.ModuleTrace), moduleField(e.ModuleName), zap.Error(e.Err)) } diff --git a/fxevent/zap_test.go b/fxevent/zap_test.go index d23025503..8e7987cba 100644 --- a/fxevent/zap_test.go +++ b/fxevent/zap_test.go @@ -131,27 +131,31 @@ func TestZapLogger(t *testing.T) { { name: "Supplied", give: &Supplied{ - TypeName: "*bytes.Buffer", - StackTrace: []string{"main.main", "runtime.main"}, + TypeName: "*bytes.Buffer", + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, }, wantMessage: "supplied", wantFields: map[string]interface{}{ - "type": "*bytes.Buffer", - "stacktrace": []interface{}{"main.main", "runtime.main"}, + "type": "*bytes.Buffer", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, }, }, { name: "Supplied/Error", give: &Supplied{ - TypeName: "*bytes.Buffer", - StackTrace: []string{"main.main", "runtime.main"}, - Err: someError, + TypeName: "*bytes.Buffer", + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, + Err: someError, }, wantMessage: "error encountered while applying options", wantFields: map[string]interface{}{ - "type": "*bytes.Buffer", - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "error": "some error", + "type": "*bytes.Buffer", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "error": "some error", }, }, { @@ -159,6 +163,7 @@ func TestZapLogger(t *testing.T) { give: &Provided{ ConstructorName: "bytes.NewBuffer()", StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, ModuleName: "myModule", OutputTypeNames: []string{"*bytes.Buffer"}, Private: false, @@ -167,6 +172,7 @@ func TestZapLogger(t *testing.T) { wantFields: map[string]interface{}{ "constructor": "bytes.NewBuffer()", "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, "type": "*bytes.Buffer", "module": "myModule", }, @@ -176,6 +182,7 @@ func TestZapLogger(t *testing.T) { give: &Provided{ ConstructorName: "bytes.NewBuffer()", StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, ModuleName: "myModule", OutputTypeNames: []string{"*bytes.Buffer"}, Private: true, @@ -184,6 +191,7 @@ func TestZapLogger(t *testing.T) { wantFields: map[string]interface{}{ "constructor": "bytes.NewBuffer()", "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, "type": "*bytes.Buffer", "module": "myModule", "private": true, @@ -192,13 +200,15 @@ func TestZapLogger(t *testing.T) { { name: "Provide/Error", give: &Provided{ - StackTrace: []string{"main.main", "runtime.main"}, - Err: someError, + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, + Err: someError, }, wantMessage: "error encountered while applying options", wantFields: map[string]interface{}{ - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "error": "some error", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "error": "some error", }, }, { @@ -206,26 +216,30 @@ func TestZapLogger(t *testing.T) { give: &Replaced{ ModuleName: "myModule", StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, OutputTypeNames: []string{"*bytes.Buffer"}, }, wantMessage: "replaced", wantFields: map[string]interface{}{ - "type": "*bytes.Buffer", - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "module": "myModule", + "type": "*bytes.Buffer", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "module": "myModule", }, }, { name: "Replace/Error", give: &Replaced{ - StackTrace: []string{"main.main", "runtime.main"}, - Err: someError, + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, + Err: someError, }, wantMessage: "error encountered while replacing", wantFields: map[string]interface{}{ - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "error": "some error", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "error": "some error", }, }, { @@ -233,27 +247,31 @@ func TestZapLogger(t *testing.T) { give: &Decorated{ DecoratorName: "bytes.NewBuffer()", StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, ModuleName: "myModule", OutputTypeNames: []string{"*bytes.Buffer"}, }, wantMessage: "decorated", wantFields: map[string]interface{}{ - "decorator": "bytes.NewBuffer()", - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "type": "*bytes.Buffer", - "module": "myModule", + "decorator": "bytes.NewBuffer()", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "type": "*bytes.Buffer", + "module": "myModule", }, }, { name: "Decorate/Error", give: &Decorated{ - StackTrace: []string{"main.main", "runtime.main"}, - Err: someError, + StackTrace: []string{"main.main", "runtime.main"}, + ModuleTrace: []string{"main.main"}, + Err: someError, }, wantMessage: "error encountered while applying options", wantFields: map[string]interface{}{ - "stacktrace": []interface{}{"main.main", "runtime.main"}, - "error": "some error", + "stacktrace": []interface{}{"main.main", "runtime.main"}, + "moduletrace": []interface{}{"main.main"}, + "error": "some error", }, }, { diff --git a/module.go b/module.go index d678c4dc6..667c38522 100644 --- a/module.go +++ b/module.go @@ -45,15 +45,17 @@ type container interface { // place. For more information, see [Decorate], [Replace], or [Invoke]. func Module(name string, opts ...Option) Option { mo := moduleOption{ - name: name, - options: opts, + name: name, + location: fxreflect.CallerStack(1, 0)[0], + options: opts, } return mo } type moduleOption struct { - name string - options []Option + name string + location fxreflect.Frame + options []Option } func (o moduleOption) String() string { @@ -69,9 +71,10 @@ func (o moduleOption) apply(mod *module) { // 2. Apply child Options on the new module. // 3. Append it to the parent module. newModule := &module{ - name: o.name, - parent: mod, - app: mod.app, + name: o.name, + parent: mod, + location: o.location, + app: mod.app, } for _, opt := range o.options { opt.apply(newModule) @@ -82,6 +85,7 @@ func (o moduleOption) apply(mod *module) { type module struct { parent *module name string + location fxreflect.Frame scope scope provides []provide invokes []invoke @@ -131,6 +135,13 @@ func (m *module) build(app *App, root *dig.Container) { } } +func (m *module) getTrace() (trace fxreflect.Stack) { + if m.parent != nil { + trace = m.parent.getTrace() + } + return append(trace, m.location) +} + func (m *module) provideAll() { for _, p := range m.provides { m.provide(p) @@ -177,6 +188,7 @@ func (m *module) provide(p provide) { m.log.LogEvent(&fxevent.Provided{ ConstructorName: funcName, StackTrace: p.Stack.Strings(), + ModuleTrace: append(m.getTrace(), p.Stack[0]).Strings(), ModuleName: m.name, OutputTypeNames: outputNames, Err: m.app.err, @@ -202,10 +214,11 @@ func (m *module) supply(p provide) { } m.log.LogEvent(&fxevent.Supplied{ - TypeName: typeName, - StackTrace: p.Stack.Strings(), - ModuleName: m.name, - Err: m.app.err, + TypeName: typeName, + StackTrace: p.Stack.Strings(), + ModuleTrace: append(m.getTrace(), p.Stack[0]).Strings(), + ModuleName: m.name, + Err: m.app.err, }) } @@ -329,6 +342,7 @@ func (m *module) decorate(d decorator) (err error) { m.log.LogEvent(&fxevent.Decorated{ DecoratorName: funcName, StackTrace: d.Stack.Strings(), + ModuleTrace: append(m.getTrace(), d.Stack[0]).Strings(), ModuleName: m.name, OutputTypeNames: outputNames, Err: err, @@ -354,6 +368,7 @@ func (m *module) replace(d decorator) error { m.log.LogEvent(&fxevent.Replaced{ ModuleName: m.name, StackTrace: d.Stack.Strings(), + ModuleTrace: append(m.getTrace(), d.Stack[0]).Strings(), OutputTypeNames: []string{typeName}, Err: err, })