Adding a before-call-begins fxevent, to help with troubleshooting

app_test.go

@@ -365,7 +365,7 @@ func TestNewApp(t *testing.T) {
 		defer app.RequireStart().RequireStop()
 
 		require.Equal(t,
-			[]string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "Run", "Run", "Invoked", "Started"},
+			[]string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "BeforeRun", "Run", "BeforeRun", "Run", "Invoked", "Started"},
 			spy.EventTypes())
 	})
 
@@ -674,7 +674,7 @@ func TestWithLogger(t *testing.T) {
 		)
 
 		assert.Equal(t, []string{
-			"Provided", "Provided", "Provided", "Supplied", "Run", "LoggerInitialized",
+			"Provided", "Provided", "Provided", "Supplied", "BeforeRun", "Run", "LoggerInitialized",
 		}, spy.EventTypes())
 
 		spy.Reset()
@@ -704,7 +704,7 @@ func TestWithLogger(t *testing.T) {
 			"must provide constructor function, got  (type *bytes.Buffer)",
 		)
 
-		assert.Equal(t, []string{"Provided", "Provided", "Provided", "Supplied", "Provided", "Run", "LoggerInitialized"}, spy.EventTypes())
+		assert.Equal(t, []string{"Provided", "Provided", "Provided", "Supplied", "Provided", "BeforeRun", "Run", "LoggerInitialized"}, spy.EventTypes())
 	})
 
 	t.Run("logger failed to build", func(t *testing.T) {
@@ -989,8 +989,18 @@ func TestRunEventEmission(t *testing.T) {
 				assert.NoError(t, app.Err())
 			}
 
+			gotBeforeEvents := spy.Events().SelectByTypeName("BeforeRun")
 			gotEvents := spy.Events().SelectByTypeName("Run")
-			require.Len(t, gotEvents, len(tt.wantRunEvents))
+			require.Len(t, gotBeforeEvents, len(tt.wantRunEvents), "wrong number of before-run events")
+			require.Len(t, gotEvents, len(tt.wantRunEvents), "wrong number of run events")
+			// BeforeRun events are just a reduced-field version of Run events
+			for i, event := range gotBeforeEvents {
+				rEvent, ok := event.(*fxevent.BeforeRun)
+				require.True(t, ok)
+
+				assert.Equal(t, tt.wantRunEvents[i].Name, rEvent.Name)
+				assert.Equal(t, tt.wantRunEvents[i].Kind, rEvent.Kind)
+			}
 			for i, event := range gotEvents {
 				rEvent, ok := event.(*fxevent.Run)
 				require.True(t, ok)
@@ -1627,12 +1637,12 @@ func TestAppStart(t *testing.T) {
 		)
 
 		go func() {
-			app.Start(context.Background())
+			assert.NoError(t, app.Start(context.Background()))
 			close(startReturn)
 		}()
 
 		<-secondStart
-		app.Stop(context.Background())
+		assert.NoError(t, app.Stop(context.Background()))
 		assert.True(t, stop1Run)
 	})
 
@@ -1696,7 +1706,9 @@ func TestAppStart(t *testing.T) {
 			"Provided", "Provided", "Provided", "Provided",
 			"LoggerInitialized",
 			"Invoking",
+			"BeforeRun",
 			"Run",
+			"BeforeRun",
 			"Run",
 			"Invoked",
 			"OnStartExecuting", "OnStartExecuted",
@@ -1734,7 +1746,9 @@ func TestAppStart(t *testing.T) {
 			"Provided", "Provided", "Provided", "Provided",
 			"LoggerInitialized",
 			"Invoking",
+			"BeforeRun",
 			"Run",
+			"BeforeRun",
 			"Run",
 			"Invoked",
 			"OnStartExecuting", "OnStartExecuted",
@@ -2471,6 +2485,7 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
 		"Provided",
 		"Provided",
 		"Provided",
+		"BeforeRun",
 		"Run",
 		"LoggerInitialized",
 		"OnStartExecuting", "OnStartExecuted",

docs/go.mod

@@ -11,7 +11,7 @@ require (
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	go.uber.org/dig v1.18.0 // indirect
+	go.uber.org/dig v1.19.0 // indirect
 	go.uber.org/multierr v1.10.0 // indirect
 	golang.org/x/sys v0.0.0-20220412211240-33da011f77ad // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect

docs/go.sum

@@ -10,8 +10,8 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
-go.uber.org/dig v1.18.0 h1:imUL1UiY0Mg4bqbFfsRQO5G4CGRBec/ZujWTvSVp3pw=
-go.uber.org/dig v1.18.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
+go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
 go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
 go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
 go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=

fxevent/console.go

@@ -104,6 +104,12 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		if e.Err != nil {
 			l.logf("Error after options were applied: %+v", e.Err)
 		}
+	case *BeforeRun:
+		var moduleStr string
+		if e.ModuleName != "" {
+			moduleStr = fmt.Sprintf(" from module %q", e.ModuleName)
+		}
+		l.logf("BEFORE RUN\t%s: %s%s", e.Kind, e.Name, moduleStr)
 	case *Run:
 		var moduleStr string
 		if e.ModuleName != "" {

fxevent/event.go

@@ -39,6 +39,7 @@ func (*Supplied) event()          {}
 func (*Provided) event()          {}
 func (*Replaced) event()          {}
 func (*Decorated) event()         {}
+func (*BeforeRun) event()         {}
 func (*Run) event()               {}
 func (*Invoking) event()          {}
 func (*Invoked) event()           {}
@@ -191,6 +192,20 @@ type Decorated struct {
 	Err error
 }
 
+// BeforeRun is emitted before a constructor, decorator, or supply/replace stub is run by Fx.
+// When complete, a Run will be emitted.
+type BeforeRun struct {
+	// Name is the name of the function that will be 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
+}
+
 // 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.

fxevent/event_test.go

@@ -39,6 +39,7 @@ func TestForCoverage(t *testing.T) {
 		&Provided{},
 		&Replaced{},
 		&Decorated{},
+		&BeforeRun{},
 		&Run{},
 		&Invoking{},
 		&Invoked{},

fxevent/slog.go

@@ -192,6 +192,12 @@ func (l *SlogLogger) LogEvent(event Event) {
 				slogMaybeModuleField(e.ModuleName),
 				slogErr(e.Err))
 		}
+	case *BeforeRun:
+		l.logEvent("before run",
+			slog.String("name", e.Name),
+			slog.String("kind", e.Kind),
+			slogMaybeModuleField(e.ModuleName),
+		)
 	case *Run:
 		if e.Err != nil {
 			l.logError("error returned",

fxevent/slog_test.go

@@ -340,6 +340,15 @@ func TestSlogLogger(t *testing.T) {
 				"error":       "some error",
 			},
 		},
+		{
+			name:        "BeforeRun",
+			give:        &BeforeRun{Name: "bytes.NewBuffer()", Kind: "constructor"},
+			wantMessage: "before run",
+			wantFields: map[string]interface{}{
+				"name": "bytes.NewBuffer()",
+				"kind": "constructor",
+			},
+		},
 		{
 			name:        "Run",
 			give:        &Run{Name: "bytes.NewBuffer()", Kind: "constructor", Runtime: 3 * time.Millisecond},

fxevent/zap.go

@@ -167,6 +167,12 @@ func (l *ZapLogger) LogEvent(event Event) {
 				moduleField(e.ModuleName),
 				zap.Error(e.Err))
 		}
+	case *BeforeRun:
+		l.logEvent("before run",
+			zap.String("name", e.Name),
+			zap.String("kind", e.Kind),
+			moduleField(e.ModuleName),
+		)
 	case *Run:
 		if e.Err != nil {
 			l.logError("error returned",

go.mod

@@ -4,7 +4,7 @@ go 1.22
 
 require (
 	github.com/stretchr/testify v1.8.1
-	go.uber.org/dig v1.18.0
+	go.uber.org/dig v1.19.0
 	go.uber.org/goleak v1.2.0
 	go.uber.org/multierr v1.10.0
 	go.uber.org/zap v1.26.0

go.sum

@@ -14,8 +14,8 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
-go.uber.org/dig v1.18.0 h1:imUL1UiY0Mg4bqbFfsRQO5G4CGRBec/ZujWTvSVp3pw=
-go.uber.org/dig v1.18.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
+go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
 go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
 go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
 go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=

internal/e2e/go.mod

@@ -10,7 +10,7 @@ require (
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	go.uber.org/dig v1.18.0 // indirect
+	go.uber.org/dig v1.19.0 // indirect
 	go.uber.org/multierr v1.10.0 // indirect
 	go.uber.org/zap v1.26.0 // indirect
 	golang.org/x/sys v0.0.0-20220412211240-33da011f77ad // indirect

internal/e2e/go.sum

@@ -10,8 +10,8 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.2 h1:+h33VjcLVPDHtOdpUCuF+7gSuG3yGIftsP1YvFihtJ8=
 github.com/stretchr/testify v1.8.2/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
-go.uber.org/dig v1.18.0 h1:imUL1UiY0Mg4bqbFfsRQO5G4CGRBec/ZujWTvSVp3pw=
-go.uber.org/dig v1.18.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
+go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
 go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
 go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
 go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=

module.go

@@ -195,6 +195,13 @@ func (m *module) provide(p provide) {
 	opts := []dig.ProvideOption{
 		dig.FillProvideInfo(&info),
 		dig.Export(!p.Private),
+		dig.WithProviderBeforeCallback(func(bci dig.BeforeCallbackInfo) {
+			m.log.LogEvent(&fxevent.BeforeRun{
+				Name:       funcName,
+				Kind:       "provide",
+				ModuleName: m.name,
+			})
+		}),
 		dig.WithProviderCallback(func(ci dig.CallbackInfo) {
 			m.log.LogEvent(&fxevent.Run{
 				Name:       funcName,
@@ -229,6 +236,13 @@ func (m *module) supply(p provide) {
 	typeName := p.SupplyType.String()
 	opts := []dig.ProvideOption{
 		dig.Export(!p.Private),
+		dig.WithProviderBeforeCallback(func(bci dig.BeforeCallbackInfo) {
+			m.log.LogEvent(&fxevent.BeforeRun{
+				Name:       fmt.Sprintf("stub(%v)", typeName),
+				Kind:       "supply",
+				ModuleName: m.name,
+			})
+		}),
 		dig.WithProviderCallback(func(ci dig.CallbackInfo) {
 			m.log.LogEvent(&fxevent.Run{
 				Name:       fmt.Sprintf("stub(%v)", typeName),
@@ -352,6 +366,13 @@ func (m *module) decorate(d decorator) (err error) {
 	var info dig.DecorateInfo
 	opts := []dig.DecorateOption{
 		dig.FillDecorateInfo(&info),
+		dig.WithDecoratorBeforeCallback(func(bci dig.BeforeCallbackInfo) {
+			m.log.LogEvent(&fxevent.BeforeRun{
+				Name:       funcName,
+				Kind:       "decorate",
+				ModuleName: m.name,
+			})
+		}),
 		dig.WithDecoratorCallback(func(ci dig.CallbackInfo) {
 			m.log.LogEvent(&fxevent.Run{
 				Name:       funcName,
@@ -384,6 +405,13 @@ func (m *module) decorate(d decorator) (err error) {
 func (m *module) replace(d decorator) error {
 	typeName := d.ReplaceType.String()
 	opts := []dig.DecorateOption{
+		dig.WithDecoratorBeforeCallback(func(bci dig.BeforeCallbackInfo) {
+			m.log.LogEvent(&fxevent.BeforeRun{
+				Name:       fmt.Sprintf("stub(%v)", typeName),
+				Kind:       "replace",
+				ModuleName: m.name,
+			})
+		}),
 		dig.WithDecoratorCallback(func(ci dig.CallbackInfo) {
 			m.log.LogEvent(&fxevent.Run{
 				Name:       fmt.Sprintf("stub(%v)", typeName),

module_test.go

@@ -262,15 +262,15 @@ func TestModuleSuccess(t *testing.T) {
 				giveWithLogger: fx.NopLogger,
 				wantEvents: []string{
 					"Provided", "Provided", "Provided", "Supplied",
-					"Run", "LoggerInitialized", "Invoking", "Invoked",
+					"BeforeRun", "Run", "LoggerInitialized", "Invoking", "Invoked",
 				},
 			},
 			{
 				desc:           "Not using a custom logger for module defaults to app logger",
 				giveWithLogger: fx.Options(),
 				wantEvents: []string{
-					"Provided", "Provided", "Provided", "Supplied", "Provided", "Run",
-					"LoggerInitialized", "Invoking", "Run", "Invoked", "Invoking", "Invoked",
+					"Provided", "Provided", "Provided", "Supplied", "Provided", "BeforeRun", "Run",
+					"LoggerInitialized", "Invoking", "BeforeRun", "Run", "Invoked", "Invoking", "Invoked",
 				},
 			},
 		}
@@ -353,8 +353,8 @@ func TestModuleSuccess(t *testing.T) {
 		)
 
 		assert.Equal(t, []string{
-			"Provided", "Supplied", "Replaced", "Run", "Run",
-			"LoggerInitialized", "Invoking", "Run", "Invoked",
+			"Provided", "Supplied", "Replaced", "BeforeRun", "Run", "BeforeRun", "Run",
+			"LoggerInitialized", "Invoking", "BeforeRun", "Run", "Invoked",
 		}, moduleSpy.EventTypes())
 
 		assert.Equal(t, []string{
@@ -413,9 +413,9 @@ func TestModuleSuccess(t *testing.T) {
 		)
 
 		assert.Equal(t, []string{
-			"Supplied", "Provided", "Replaced", "Run", "Run", "LoggerInitialized",
+			"Supplied", "Provided", "Replaced", "BeforeRun", "Run", "BeforeRun", "Run", "LoggerInitialized",
 			// Invoke logged twice, once from child and another from grandchild
-			"Invoking", "Run", "Invoked", "Invoking", "Invoked",
+			"Invoking", "BeforeRun", "Run", "Invoked", "Invoking", "Invoked",
 		}, childSpy.EventTypes(), "events from grandchild also logged in child logger")
 
 		assert.Equal(t, []string{
@@ -649,7 +649,7 @@ func TestModuleFailures(t *testing.T) {
 					"must provide constructor function, got  (type *bytes.Buffer)",
 				},
 				wantEvents: []string{
-					"Supplied", "Provided", "Run", "LoggerInitialized",
+					"Supplied", "Provided", "BeforeRun", "Run", "LoggerInitialized",
 				},
 			},
 			{
@@ -660,7 +660,7 @@ func TestModuleFailures(t *testing.T) {
 				giveAppOpts:     spyAsLogger,
 				wantErrContains: []string{"error building logger"},
 				wantEvents: []string{
-					"Provided", "Provided", "Provided", "Supplied", "Run",
+					"Provided", "Provided", "Provided", "Supplied", "BeforeRun", "Run",
 					"LoggerInitialized", "Provided", "LoggerInitialized",
 				},
 			},
@@ -678,8 +678,8 @@ func TestModuleFailures(t *testing.T) {
 				giveAppOpts:     spyAsLogger,
 				wantErrContains: []string{"error building logger dependency"},
 				wantEvents: []string{
-					"Provided", "Provided", "Provided", "Supplied", "Run",
-					"LoggerInitialized", "Provided", "Provided", "Run", "LoggerInitialized",
+					"Provided", "Provided", "Provided", "Supplied", "BeforeRun", "Run",
+					"LoggerInitialized", "Provided", "Provided", "BeforeRun", "Run", "LoggerInitialized",
 				},
 			},
 			{
@@ -690,7 +690,7 @@ func TestModuleFailures(t *testing.T) {
 					"fx.WithLogger", "from:", "Failed",
 				},
 				wantEvents: []string{
-					"Provided", "Provided", "Provided", "Supplied", "Run",
+					"Provided", "Provided", "Provided", "Supplied", "BeforeRun", "Run",
 					"LoggerInitialized", "Provided", "LoggerInitialized",
 				},
 			},