Use Dig Callbacks to Emit Run Events (#1077)

Folks have been asking for additional observability into what
constructors/decorators they give to Fx actually get invoked. With
uber-go/dig#377 being merged, we can use Dig
callbacks to provide this observability point. This PR does this by
registering callbacks with Dig that generate a new
[fxevent](https://pkg.go.dev/go.uber.org/fx/fxevent#Event) called
`fxevent.Run`, containing information about the provided/decorated
function that was invoked by Dig:

```go
// Run is emitted after a constructor, decorator, or supply/replace stub is run by Fx.
type Run struct {
	// Name is the name of the function that was run.
	Name string

	// Kind indicates which Fx option was used to pass along the function.
	// It is either "provide", "decorate", "supply", or "replace".
	Kind string

	// ModuleName is the name of the module in which the function belongs.
	ModuleName string

	// Err is non-nil if the function returned an error.
	// If fx.RecoverFromPanics is used, this will include panics.
	Err error
}
```

The default
[fxevent.Logger](https://pkg.go.dev/go.uber.org/fx/fxevent#Logger)s have
been updated to print to the console/log with Zap accordingly. Folks can
use custom `fxevent.Logger`s to respond to these events as they would
any other event:

```go
type myLogger struct{ /* ... */ }

func (l *myLogger) LogEvent(event fxevent.Event) {
    switch e := event.(type) {
    // ...
    case *fxevent.Run:
        // can access e.Name, e.Kind, e.ModuleName, and e.Err
        // ...
    }
}

func main() {
    app := fx.New(
            fx.WithLogger(func() fxevent.Logger { return &myLogger{} } ),
        // ...
    )
}
```
I wrote a small demo showing a custom logger like this can be used to
identify "dead functions" within Fx:
https:/JacobOaks/fx_dead_code_demo.

This PR also adds stack trace information into the `Provided`,
`Decorated`, `Supplied`, and `Decorated` fxevents to aid folks with
larger codebases that consume many modules, who might otherwise have a
hard time finding where exactly a "dead function" is being given to Fx
with just the `name` and `ModuleName` fields of the `Run` event. Fx was
already keeping track of this information, so I don't think this
addition incurs too much additional overhead for Fx, but if folks
disagree we can remove this addition or perhaps make it opt-in by gating
it behind a new option `fx.ReportStackTraces()` or something.

app.go

@@ -482,7 +482,7 @@ func New(opts ...Option) *App {
 
  // Run decorators before executing any Invokes -- including the one
  // inside constructCustomLogger.
- app.err = multierr.Append(app.err, app.root.decorate())
+ app.err = multierr.Append(app.err, app.root.decorateAll())
 
  // If you are thinking about returning here after provides: do not (just yet)!
  // If a custom logger was being used, we're still buffering messages.

app_test.go

@@ -357,7 +357,7 @@ func TestNewApp(t *testing.T) {
  defer app.RequireStart().RequireStop()
 
  require.Equal(t,
- []string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "Invoked", "Started"},
+ []string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "Run", "Run", "Invoked", "Started"},
  spy.EventTypes())
  })
 
@@ -573,7 +573,7 @@ func TestWithLogger(t *testing.T) {
  )
 
  assert.Equal(t, []string{
- "Supplied", "Provided", "Provided", "Provided", "LoggerInitialized",
+ "Supplied", "Provided", "Provided", "Provided", "Run", "LoggerInitialized",
  }, spy.EventTypes())
 
  spy.Reset()
@@ -603,7 +603,7 @@ func TestWithLogger(t *testing.T) {
  "must provide constructor function, got (type *bytes.Buffer)",
  )
 
- assert.Equal(t, []string{"Supplied", "Provided", "LoggerInitialized"}, spy.EventTypes())
+ assert.Equal(t, []string{"Supplied", "Provided", "Run", "LoggerInitialized"}, spy.EventTypes())
  })
 
  t.Run("logger failed to build", func(t *testing.T) {
@@ -654,6 +654,153 @@ type errHandlerFunc func(error)
 
 func (f errHandlerFunc) HandleError(err error) { f(err) }
 
+func TestRunEventEmission(t *testing.T) {
+ t.Parallel()
+
+ for _, tt := range []struct {
+ desc string
+ giveOpts []Option
+ wantRunEvents []fxevent.Run
+ wantErr string
+ }{
+ {
+ desc: "Simple Provide And Decorate",
+ giveOpts: []Option{
+ Provide(func() int { return 5 }),
+ Decorate(func(int) int { return 6 }),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func1()",
+ Kind: "provide",
+ },
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func2()",
+ Kind: "decorate",
+ },
+ },
+ },
+ {
+ desc: "Supply and Decorator Error",
+ giveOpts: []Option{
+ Supply(5),
+ Decorate(func(int) (int, error) {
+ return 0, errors.New("humongous despair")
+ }),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "stub(int)",
+ Kind: "supply",
+ },
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func4()",
+ Kind: "decorate",
+ },
+ },
+ wantErr: "humongous despair",
+ },
+ {
+ desc: "Replace",
+ giveOpts: []Option{
+ Provide(func() int { return 5 }),
+ Replace(6),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "stub(int)",
+ Kind: "replace",
+ },
+ },
+ },
+ {
+ desc: "Provide Error",
+ giveOpts: []Option{
+ Provide(func() (int, error) {
+ return 0, errors.New("terrible sadness")
+ }),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func8()",
+ Kind: "provide",
+ },
+ },
+ wantErr: "terrible sadness",
+ },
+ {
+ desc: "Provide Panic",
+ giveOpts: []Option{
+ Provide(func() int {
+ panic("bad provide")
+ }),
+ RecoverFromPanics(),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func10()",
+ Kind: "provide",
+ },
+ },
+ wantErr: `panic: "bad provide"`,
+ },
+ {
+ desc: "Decorate Panic",
+ giveOpts: []Option{
+ Supply(5),
+ Decorate(func(int) int {
+ panic("bad decorate")
+ }),
+ RecoverFromPanics(),
+ Invoke(func(int) {}),
+ },
+ wantRunEvents: []fxevent.Run{
+ {
+ Name: "stub(int)",
+ Kind: "supply",
+ },
+ {
+ Name: "go.uber.org/fx_test.TestRunEventEmission.func12()",
+ Kind: "decorate",
+ },
+ },
+ wantErr: `panic: "bad decorate"`,
+ },
+ } {
+ tt := tt
+ t.Run(tt.desc, func(t *testing.T) {
+ t.Parallel()
+
+ app, spy := NewSpied(tt.giveOpts...)
+ if tt.wantErr != "" {
+ assert.ErrorContains(t, app.Err(), tt.wantErr)
+ } else {
+ assert.NoError(t, app.Err())
+ }
+
+ gotEvents := spy.Events().SelectByTypeName("Run")
+ require.Len(t, gotEvents, len(tt.wantRunEvents))
+ for i, event := range gotEvents {
+ rEvent, ok := event.(*fxevent.Run)
+ require.True(t, ok)
+
+ assert.Equal(t, tt.wantRunEvents[i].Name, rEvent.Name)
+ assert.Equal(t, tt.wantRunEvents[i].Kind, rEvent.Kind)
+ if tt.wantErr != "" && i == len(gotEvents)-1 {
+ assert.ErrorContains(t, rEvent.Err, tt.wantErr)
+ } else {
+ assert.NoError(t, rEvent.Err)
+ }
+ }
+ })
+ }
+}
+
 type customError struct {
  err error
 }
@@ -1338,6 +1485,8 @@ func TestAppStart(t *testing.T) {
  "Provided", "Provided", "Provided", "Provided",
  "LoggerInitialized",
  "Invoking",
+ "Run",
+ "Run",
  "Invoked",
  "OnStartExecuting", "OnStartExecuted",
  "RollingBack",
@@ -1374,6 +1523,8 @@ func TestAppStart(t *testing.T) {
  "Provided", "Provided", "Provided", "Provided",
  "LoggerInitialized",
  "Invoking",
+ "Run",
+ "Run",
  "Invoked",
  "OnStartExecuting", "OnStartExecuted",
  "OnStartExecuting", "OnStartExecuted",
@@ -2066,6 +2217,7 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
  "Provided",
  "Provided",
  "Provided",
+ "Run",
  "LoggerInitialized",
  "OnStartExecuting", "OnStartExecuted",
  "Started",

decorate.go

@@ -22,6 +22,7 @@ package fx
 
 import (
  "fmt"
+ "reflect"
  "strings"
 
  "go.uber.org/dig"
@@ -207,7 +208,8 @@ type decorator struct {
  Stack fxreflect.Stack
 
  // Whether this decorator was specified via fx.Replace
- IsReplace bool
+ IsReplace bool
+ ReplaceType reflect.Type // set only if IsReplace
 }
 
 func runDecorator(c container, d decorator, opts ...dig.DecorateOption) (err error) {

fxevent/console.go

@@ -82,7 +82,6 @@ func (l *ConsoleLogger) LogEvent(event Event) {
  if e.Err != nil {
  l.logf("Error after options were applied: %+v", e.Err)
  }
-
  case *Replaced:
  for _, rtype := range e.OutputTypeNames {
  if e.ModuleName != "" {
@@ -105,6 +104,16 @@ func (l *ConsoleLogger) LogEvent(event Event) {
  if e.Err != nil {
  l.logf("Error after options were applied: %+v", e.Err)
  }
+ case *Run:
+ var moduleStr string
+ if e.ModuleName != "" {
+ moduleStr = fmt.Sprintf(" from module %q", e.ModuleName)
+ }
+ l.logf("RUN\t%v: %v%v", e.Kind, e.Name, moduleStr)
+ if e.Err != nil {
+ l.logf("Error returned: %+v", e.Err)
+ }
+
  case *Invoking:
  if e.ModuleName != "" {
  l.logf("INVOKE\t\t%s from module %q", e.FunctionName, e.ModuleName)

fxevent/console_test.go

@@ -137,12 +137,19 @@ func TestConsoleLogger(t *testing.T) {
  },
  {
  name: "Supplied",
- give: &Supplied{TypeName: "*bytes.Buffer"},
+ give: &Supplied{
+ TypeName: "*bytes.Buffer",
+ StackTrace: []string{"main.main", "runtime.main"},
+ },
  want: "[Fx] SUPPLY *bytes.Buffer\n",
  },
  {
  name: "Supplied with module",
- give: &Supplied{TypeName: "*bytes.Buffer", ModuleName: "myModule"},
+ give: &Supplied{
+ TypeName: "*bytes.Buffer",
+ ModuleName: "myModule",
+ StackTrace: []string{"main.main", "runtime.main"},
+ },
  want: "[Fx] SUPPLY *bytes.Buffer from module \"myModule\"\n",
  },
  {
@@ -161,6 +168,7 @@ func TestConsoleLogger(t *testing.T) {
  ConstructorName: "bytes.NewBuffer()",
  OutputTypeNames: []string{"*bytes.Buffer"},
  Private: false,
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer()\n",
  },
@@ -170,6 +178,7 @@ func TestConsoleLogger(t *testing.T) {
  ConstructorName: "bytes.NewBuffer()",
  OutputTypeNames: []string{"*bytes.Buffer"},
  Private: true,
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer()\n",
  },
@@ -180,6 +189,7 @@ func TestConsoleLogger(t *testing.T) {
  ModuleName: "myModule",
  OutputTypeNames: []string{"*bytes.Buffer"},
  Private: false,
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] PROVIDE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
  },
@@ -190,13 +200,15 @@ func TestConsoleLogger(t *testing.T) {
  ModuleName: "myModule",
  OutputTypeNames: []string{"*bytes.Buffer"},
  Private: true,
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] PROVIDE (PRIVATE) *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
  },
  {
  name: "Replaced",
  give: &Replaced{
  OutputTypeNames: []string{"*bytes.Buffer"},
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] REPLACE *bytes.Buffer\n",
  },
@@ -205,6 +217,7 @@ func TestConsoleLogger(t *testing.T) {
  give: &Replaced{
  ModuleName: "myModule",
  OutputTypeNames: []string{"*bytes.Buffer"},
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] REPLACE *bytes.Buffer from module \"myModule\"\n",
  },
@@ -218,6 +231,7 @@ func TestConsoleLogger(t *testing.T) {
  give: &Decorated{
  DecoratorName: "bytes.NewBuffer()",
  OutputTypeNames: []string{"*bytes.Buffer"},
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer()\n",
  },
@@ -227,6 +241,7 @@ func TestConsoleLogger(t *testing.T) {
  DecoratorName: "bytes.NewBuffer()",
  ModuleName: "myModule",
  OutputTypeNames: []string{"*bytes.Buffer"},
+ StackTrace: []string{"main.main", "runtime.main"},
  },
  want: "[Fx] DECORATE *bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
  },
@@ -240,6 +255,32 @@ func TestConsoleLogger(t *testing.T) {
  give: &Decorated{Err: &richError{}},
  want: "[Fx] Error after options were applied: rich error\n",
  },
+ {
+ name: "Run",
+ give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor"},
+ want: "[Fx] RUN\tconstructor: bytes.NewBuffer()\n",
+ },
+ {
+ name: "Run with module",
+ give: &Run{
+ Name: "bytes.NewBuffer()",
+ Kind: "constructor",
+ ModuleName: "myModule",
+ },
+ want: "[Fx] RUN\tconstructor: bytes.NewBuffer() from module \"myModule\"\n",
+ },
+ {
+ name: "RunError",
+ give: &Run{
+ Name: "bytes.NewBuffer()",
+ Kind: "constructor",
+ Err: errors.New("terrible constructor error"),
+ },
+ want: joinLines(
+ "[Fx] RUN\tconstructor: bytes.NewBuffer()",
+ "[Fx] Error returned: terrible constructor error",
+ ),
+ },
  {
  name: "Invoking",
  give: &Invoking{FunctionName: "bytes.NewBuffer()"},