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.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)
main.init (/Users/joaks/go/src/scratch/mod_stacks_scratch/main.go:18)
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.

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)
 

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(
+		// Provide/decorate itself, initialized via init.
+		"^go.uber.org/fx_test.init (.*fx/app_test.go:.*)\n" +
+			// ModuleA initialized via init.
+			"ModuleA: go.uber.org/fx_test.init (.*fx/app_test.go:.*)\n" +
+			// ModuleB from getModuleB.
+			"ModuleB: go.uber.org/fx_test.getModuleB (.*fx/app_test.go:.*)\n" +
+			// ModuleC above.
+			"ModuleC: go.uber.org/fx_test.TestModuleTrace (.*fx/app_test.go:.*)\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()
@@ -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()
 

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",
 		},

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
 

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,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))
 		}
@@ -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))
 		}