Skip to content

Commit

Permalink
Include Module Traces in Events (#1122)
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@JacobOaks
JacobOaks committed Oct 17, 2023
1 parent bbb3783 commit 1a5cc04
Show file tree
Hide file tree
Showing 7 changed files with 217 additions and 46 deletions.
3 changes: 2 additions & 1 deletion app.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
trace: []string{fxreflect.CallerStack(1, 2)[0].String()},
}
app.modules = append(app.modules, app.root)

Expand Down
117 changes: 114 additions & 3 deletions app_test.go
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -29,7 +29,9 @@ import (
"log"
"os"
"reflect"
"regexp"
"runtime"
"strings"
"testing"
"time"

Expand Down Expand Up @@ -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(
// Provide/decorate itself, initialized via init.
"^go.uber.org/fx_test.init \\(.*fx/app_test.go:.*\\)\n" +
// ModuleA initialized via init.
"go.uber.org/fx_test.init \\(.*fx/app_test.go:.*\\) \\(ModuleA\\)\n" +
// ModuleB from getModuleB.
"go.uber.org/fx_test.getModuleB \\(.*fx/app_test.go:.*\\) \\(ModuleB\\)\n" +
// ModuleC above.
"go.uber.org/fx_test.TestModuleTrace \\(.*fx/app_test.go:.*\\) \\(ModuleC\\)\n" +
// Top-level app & corresponding module created by NewSpied.
"go.uber.org/fx_test.NewSpied \\(.*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()
Expand Down Expand Up @@ -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()

Expand Down
20 changes: 15 additions & 5 deletions fxevent/console_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand All @@ -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",
},
Expand Down
12 changes: 12 additions & 0 deletions fxevent/event.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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
Expand All @@ -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

Expand All @@ -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

Expand Down
8 changes: 8 additions & 0 deletions fxevent/zap.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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),
)
}
Expand All @@ -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),
Expand All @@ -128,19 +131,22 @@ 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),
)
}
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))
}
Expand All @@ -149,13 +155,15 @@ 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),
)
}
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))
}
Expand Down

0 comments on commit 1a5cc04

Please sign in to comment.