Skip to content

Commit 1a5cc04

Browse files
JacobOaksJacobOaks
authored
Include Module Traces in Events (#1122)
Currently, the events that the [fxevent package](https://pkg.go.dev/go.uber.org/fx/fxevent) emits for [provides](https://pkg.go.dev/go.uber.org/fx/fxevent#Provided)/[decorates](https://pkg.go.dev/go.uber.org/fx/fxevent#Decorated)/[supplies](https://pkg.go.dev/go.uber.org/fx/fxevent#Supplied)/[replaces](https://pkg.go.dev/go.uber.org/fx/fxevent#Replaced) 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.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:15) main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:13) (ThingFx) main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:18) (ServiceFx) main.run (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:24) ``` Which shows exactly how `getThing` got included in `app` in order: * getThing is provided at `main.go:15` * ThingFx is declared at `main.go:13` * ServiceFx is declared at `main.go:18` * The app is declared at `main.go:24` This makes it more clear to the developer how functions are getting included, especially for large codebase where modules may be distributed all over.
1 parent bbb3783 commit 1a5cc04

7 files changed

Lines changed: 217 additions & 46 deletions

File tree

‎app.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -432,7 +432,8 @@ func New(opts ...Option) *App {
432432
// user gave us. For the last case, however, we need to fall
433433
// back to what was provided to fx.Logger if fx.WithLogger
434434
// fails.
435-
log: logger,
435+
log: logger,
436+
trace: []string{fxreflect.CallerStack(1, 2)[0].String()},
436437
}
437438
app.modules = append(app.modules, app.root)
438439

‎app_test.go‎

Lines changed: 114 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
// Copyright (c) 2022 Uber Technologies, Inc.
1+
// Copyright (c) 2023 Uber Technologies, Inc.
22
//
33
// Permission is hereby granted, free of charge, to any person obtaining a copy
44
// of this software and associated documentation files (the "Software"), to deal
@@ -29,7 +29,9 @@ import (
2929
"log"
3030
"os"
3131
"reflect"
32+
"regexp"
3233
"runtime"
34+
"strings"
3335
"testing"
3436
"time"
3537

@@ -650,9 +652,114 @@ func TestWithLogger(t *testing.T) {
650652
})
651653
}
652654

653-
type errHandlerFunc func(error)
655+
func getInt() int { return 0 }
654656

655-
func (f errHandlerFunc) HandleError(err error) { f(err) }
657+
func decorateInt(i int) int { return i }
658+
659+
var moduleA = Module(
660+
"ModuleA",
661+
Provide(getInt),
662+
Decorate(decorateInt),
663+
Supply(int64(14)),
664+
Replace("foo"),
665+
)
666+
667+
func getModuleB() Option {
668+
return Module(
669+
"ModuleB",
670+
moduleA,
671+
)
672+
}
673+
674+
func TestModuleTrace(t *testing.T) {
675+
t.Parallel()
676+
677+
moduleC := Module(
678+
"ModuleC",
679+
getModuleB(),
680+
)
681+
682+
app, spy := NewSpied(moduleC)
683+
require.NoError(t, app.Err())
684+
685+
wantTrace, err := regexp.Compile(
686+
// Provide/decorate itself, initialized via init.
687+
"^go.uber.org/fx_test.init \\(.*fx/app_test.go:.*\\)\n" +
688+
// ModuleA initialized via init.
689+
"go.uber.org/fx_test.init \\(.*fx/app_test.go:.*\\) \\(ModuleA\\)\n" +
690+
// ModuleB from getModuleB.
691+
"go.uber.org/fx_test.getModuleB \\(.*fx/app_test.go:.*\\) \\(ModuleB\\)\n" +
692+
// ModuleC above.
693+
"go.uber.org/fx_test.TestModuleTrace \\(.*fx/app_test.go:.*\\) \\(ModuleC\\)\n" +
694+
// Top-level app & corresponding module created by NewSpied.
695+
"go.uber.org/fx_test.NewSpied \\(.*fx/app_test.go:.*\\)$",
696+
)
697+
require.NoError(t, err, "test regexp compilation error")
698+
699+
for _, tt := range []struct {
700+
desc string
701+
getTrace func(t *testing.T) []string
702+
}{
703+
{
704+
desc: "Provide",
705+
getTrace: func(t *testing.T) []string {
706+
t.Helper()
707+
var event *fxevent.Provided
708+
for _, e := range spy.Events().SelectByTypeName("Provided") {
709+
pe, ok := e.(*fxevent.Provided)
710+
if !ok {
711+
continue
712+
}
713+
714+
if strings.HasSuffix(pe.ConstructorName, "getInt()") {
715+
event = pe
716+
break
717+
}
718+
}
719+
require.NotNil(t, event, "could not find provide event for getInt()")
720+
return event.ModuleTrace
721+
},
722+
},
723+
{
724+
desc: "Decorate",
725+
getTrace: func(t *testing.T) []string {
726+
t.Helper()
727+
events := spy.Events().SelectByTypeName("Decorated")
728+
require.Len(t, events, 1)
729+
event, ok := events[0].(*fxevent.Decorated)
730+
require.True(t, ok)
731+
return event.ModuleTrace
732+
},
733+
},
734+
{
735+
desc: "Supply",
736+
getTrace: func(t *testing.T) []string {
737+
t.Helper()
738+
events := spy.Events().SelectByTypeName("Supplied")
739+
require.Len(t, events, 1)
740+
event, ok := events[0].(*fxevent.Supplied)
741+
require.True(t, ok)
742+
return event.ModuleTrace
743+
},
744+
},
745+
{
746+
desc: "Replaced",
747+
getTrace: func(t *testing.T) []string {
748+
t.Helper()
749+
events := spy.Events().SelectByTypeName("Replaced")
750+
require.Len(t, events, 1)
751+
event, ok := events[0].(*fxevent.Replaced)
752+
require.True(t, ok)
753+
return event.ModuleTrace
754+
},
755+
},
756+
} {
757+
t.Run(tt.desc, func(t *testing.T) {
758+
gotTrace := strings.Join(tt.getTrace(t), "\n")
759+
assert.Regexp(t, wantTrace, gotTrace)
760+
})
761+
}
762+
}
656763

657764
func TestRunEventEmission(t *testing.T) {
658765
t.Parallel()
@@ -813,6 +920,10 @@ func (e *customError) Unwrap() error {
813920
return e.err
814921
}
815922

923+
type errHandlerFunc func(error)
924+
925+
func (f errHandlerFunc) HandleError(err error) { f(err) }
926+
816927
func TestInvokes(t *testing.T) {
817928
t.Parallel()
818929

‎fxevent/console_test.go‎

Lines changed: 15 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -138,17 +138,19 @@ func TestConsoleLogger(t *testing.T) {
138138
{
139139
name: "Supplied",
140140
give: &Supplied{
141-
TypeName: "*bytes.Buffer",
142-
StackTrace: []string{"main.main", "runtime.main"},
141+
TypeName: "*bytes.Buffer",
142+
StackTrace: []string{"main.main", "runtime.main"},
143+
ModuleTrace: []string{"main.main"},
143144
},
144145
want: "[Fx] SUPPLY *bytes.Buffer\n",
145146
},
146147
{
147148
name: "Supplied with module",
148149
give: &Supplied{
149-
TypeName: "*bytes.Buffer",
150-
ModuleName: "myModule",
151-
StackTrace: []string{"main.main", "runtime.main"},
150+
TypeName: "*bytes.Buffer",
151+
ModuleName: "myModule",
152+
StackTrace: []string{"main.main", "runtime.main"},
153+
ModuleTrace: []string{"main.main", "mypackage.GetMyModule"},
152154
},
153155
want: "[Fx] SUPPLY *bytes.Buffer from module \"myModule\"\n",
154156
},
@@ -169,6 +171,7 @@ func TestConsoleLogger(t *testing.T) {
169171
OutputTypeNames: []string{"*bytes.Buffer"},
170172
Private: false,
171173
StackTrace: []string{"main.main", "runtime.main"},
174+
ModuleTrace: []string{"main.main"},
172175
},
173176
want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer()\n",
174177
},
@@ -179,6 +182,7 @@ func TestConsoleLogger(t *testing.T) {
179182
OutputTypeNames: []string{"*bytes.Buffer"},
180183
Private: true,
181184
StackTrace: []string{"main.main", "runtime.main"},
185+
ModuleTrace: []string{"main.main"},
182186
},
183187
want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer()\n",
184188
},
@@ -190,6 +194,7 @@ func TestConsoleLogger(t *testing.T) {
190194
OutputTypeNames: []string{"*bytes.Buffer"},
191195
Private: false,
192196
StackTrace: []string{"main.main", "runtime.main"},
197+
ModuleTrace: []string{"main.main", "mypackage.GetMyModule"},
193198
},
194199
want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
195200
},
@@ -201,6 +206,7 @@ func TestConsoleLogger(t *testing.T) {
201206
OutputTypeNames: []string{"*bytes.Buffer"},
202207
Private: true,
203208
StackTrace: []string{"main.main", "runtime.main"},
209+
ModuleTrace: []string{"main.main", "mypackage.GetMyModule"},
204210
},
205211
want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
206212
},
@@ -209,6 +215,7 @@ func TestConsoleLogger(t *testing.T) {
209215
give: &Replaced{
210216
OutputTypeNames: []string{"*bytes.Buffer"},
211217
StackTrace: []string{"main.main", "runtime.main"},
218+
ModuleTrace: []string{"main.main"},
212219
},
213220
want: "[Fx] REPLACE *bytes.Buffer\n",
214221
},
@@ -218,6 +225,7 @@ func TestConsoleLogger(t *testing.T) {
218225
ModuleName: "myModule",
219226
OutputTypeNames: []string{"*bytes.Buffer"},
220227
StackTrace: []string{"main.main", "runtime.main"},
228+
ModuleTrace: []string{"main.main", "mypackage.GetMyModule"},
221229
},
222230
want: "[Fx] REPLACE *bytes.Buffer from module \"myModule\"\n",
223231
},
@@ -232,6 +240,7 @@ func TestConsoleLogger(t *testing.T) {
232240
DecoratorName: "bytes.NewBuffer()",
233241
OutputTypeNames: []string{"*bytes.Buffer"},
234242
StackTrace: []string{"main.main", "runtime.main"},
243+
ModuleTrace: []string{"main.main"},
235244
},
236245
want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer()\n",
237246
},
@@ -242,6 +251,7 @@ func TestConsoleLogger(t *testing.T) {
242251
ModuleName: "myModule",
243252
OutputTypeNames: []string{"*bytes.Buffer"},
244253
StackTrace: []string{"main.main", "runtime.main"},
254+
ModuleTrace: []string{"main.main", "mypackage.GetMyModule"},
245255
},
246256
want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
247257
},

‎fxevent/event.go‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -113,6 +113,9 @@ type Supplied struct {
113113
// StackTrace is the stack trace of the call to Supply.
114114
StackTrace []string
115115

116+
// ModuleTrace contains the module locations through which this value was added.
117+
ModuleTrace []string
118+
116119
// ModuleName is the name of the module in which the value was added to.
117120
ModuleName string
118121

@@ -129,6 +132,9 @@ type Provided struct {
129132
// StackTrace is the stack trace of where the constructor was provided to Fx.
130133
StackTrace []string
131134

135+
// ModuleTrace contains the module locations through which this was provided to Fx.
136+
ModuleTrace []string
137+
132138
// OutputTypeNames is a list of names of types that are produced by
133139
// this constructor.
134140
OutputTypeNames []string
@@ -152,6 +158,9 @@ type Replaced struct {
152158
// StackTrace is the stack trace of the call to Replace.
153159
StackTrace []string
154160

161+
// ModuleTrace contains the module locations through which this value was added.
162+
ModuleTrace []string
163+
155164
// ModuleName is the name of the module in which the value was added to.
156165
ModuleName string
157166

@@ -168,6 +177,9 @@ type Decorated struct {
168177
// StackTrace is the stack trace of where the decorator was given to Fx.
169178
StackTrace []string
170179

180+
// ModuleTrace contains the module locations through which this value was added.
181+
ModuleTrace []string
182+
171183
// ModuleName is the name of the module in which the value was added to.
172184
ModuleName string
173185

‎fxevent/zap.go‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -105,12 +105,14 @@ func (l *ZapLogger) LogEvent(event Event) {
105105
l.logError("error encountered while applying options",
106106
zap.String("type", e.TypeName),
107107
zap.Strings("stacktrace", e.StackTrace),
108+
zap.Strings("moduletrace", e.ModuleTrace),
108109
moduleField(e.ModuleName),
109110
zap.Error(e.Err))
110111
} else {
111112
l.logEvent("supplied",
112113
zap.String("type", e.TypeName),
113114
zap.Strings("stacktrace", e.StackTrace),
115+
zap.Strings("moduletrace", e.ModuleTrace),
114116
moduleField(e.ModuleName),
115117
)
116118
}
@@ -119,6 +121,7 @@ func (l *ZapLogger) LogEvent(event Event) {
119121
l.logEvent("provided",
120122
zap.String("constructor", e.ConstructorName),
121123
zap.Strings("stacktrace", e.StackTrace),
124+
zap.Strings("moduletrace", e.ModuleTrace),
122125
moduleField(e.ModuleName),
123126
zap.String("type", rtype),
124127
maybeBool("private", e.Private),
@@ -128,19 +131,22 @@ func (l *ZapLogger) LogEvent(event Event) {
128131
l.logError("error encountered while applying options",
129132
moduleField(e.ModuleName),
130133
zap.Strings("stacktrace", e.StackTrace),
134+
zap.Strings("moduletrace", e.ModuleTrace),
131135
zap.Error(e.Err))
132136
}
133137
case *Replaced:
134138
for _, rtype := range e.OutputTypeNames {
135139
l.logEvent("replaced",
136140
zap.Strings("stacktrace", e.StackTrace),
141+
zap.Strings("moduletrace", e.ModuleTrace),
137142
moduleField(e.ModuleName),
138143
zap.String("type", rtype),
139144
)
140145
}
141146
if e.Err != nil {
142147
l.logError("error encountered while replacing",
143148
zap.Strings("stacktrace", e.StackTrace),
149+
zap.Strings("moduletrace", e.ModuleTrace),
144150
moduleField(e.ModuleName),
145151
zap.Error(e.Err))
146152
}
@@ -149,13 +155,15 @@ func (l *ZapLogger) LogEvent(event Event) {
149155
l.logEvent("decorated",
150156
zap.String("decorator", e.DecoratorName),
151157
zap.Strings("stacktrace", e.StackTrace),
158+
zap.Strings("moduletrace", e.ModuleTrace),
152159
moduleField(e.ModuleName),
153160
zap.String("type", rtype),
154161
)
155162
}
156163
if e.Err != nil {
157164
l.logError("error encountered while applying options",
158165
zap.Strings("stacktrace", e.StackTrace),
166+
zap.Strings("moduletrace", e.ModuleTrace),
159167
moduleField(e.ModuleName),
160168
zap.Error(e.Err))
161169
}

0 commit comments

Comments
 (0)