Repository: uber-go/fx
Pull request #761 (2021-07-21 06:30:42)

Introduce Invoking and rename other event types
Follow up to #756 where we introduce a new `Invoking` event to be emitted before an `fx.Invoke`, rename `Invoke` to `Invoked`.

Additionally, `Provide` event will have access to constructor field in case it's emitted as a result of an error.

Ref GO-743

codecov[bot]: # [Codecov](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) Report
> Merging [#761](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (4689839) into [master](https://codecov.io/gh/uber-go/fx/commit/542934ad0994861388f6586e04c5b39b679d5a13?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (542934a) will **increase** coverage by `0.00%`.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/uber-go/fx/pull/761/graphs/tree.svg?width=650&height=150&src=pr&token=PYY9PSfaC6&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go)](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go)

```diff
@@           Coverage Diff           @@
##           master     #761   +/-   ##
=======================================
  Coverage   98.22%   98.23%           
=======================================
  Files          24       24           
  Lines         734      735    +1     
=======================================
+ Hits          721      722    +1     
  Misses         10       10           
  Partials        3        3           
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) | Coverage Δ | |
|---|---|---|
| [app.go](https://codecov.io/gh/uber-go/fx/pull/761/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-YXBwLmdv) | `96.94% <100.00%> (+0.02%)` | :arrow_up: |
| [fxevent/console.go](https://codecov.io/gh/uber-go/fx/pull/761/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC9jb25zb2xlLmdv) | `100.00% <100.00%> (ø)` | |
| [fxevent/event.go](https://codecov.io/gh/uber-go/fx/pull/761/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC9ldmVudC5nbw==) | `100.00% <100.00%> (ø)` | |
| [fxevent/zap.go](https://codecov.io/gh/uber-go/fx/pull/761/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC96YXAuZ28=) | `100.00% <100.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go). Last update [542934a...4689839](https://codecov.io/gh/uber-go/fx/pull/761?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go).


Patch:
diff --git a/app.go b/app.go
index 77e6451..eb87527 100644
--- a/app.go
+++ b/app.go
@@ -561,12 +561,9 @@ func New(opts ...Option) *App {
 	app.provide(provide{Target: app.shutdowner, Stack: frames})
 	app.provide(provide{Target: app.dotGraph, Stack: frames})
 
-	if app.err != nil {
-		app.log.LogEvent(&fxevent.Provide{Err: app.err})
-		// Don't return yet. If a custom logger was being used,
-		// we're still buffering messages. We'll want to flush them to
-		// the logger.
-	}
+	// 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.
+	// We'll want to flush them to the logger.
 
 	// If WithLogger and Printer are both provided, WithLogger takes
 	// precedence.
@@ -577,13 +574,16 @@ func New(opts ...Option) *App {
 			app.err = multierr.Append(app.err, err)
 			app.log = fallbackLogger
 			bufferLogger.Connect(fallbackLogger)
-			app.log.LogEvent(&fxevent.CustomLogger{Err: err})
+			app.log.LogEvent(&fxevent.LoggerInitialized{
+				Err:         err,
+				Constructor: app.logConstructor,
+			})
 			return app
 		}
-		app.log.LogEvent(&fxevent.CustomLogger{Function: app.logConstructor})
+		app.log.LogEvent(&fxevent.LoggerInitialized{Constructor: app.logConstructor})
 	}
 
-	// This error might have come from the provide looop above. We've
+	// This error might have come from the provide loop above. We've
 	// already flushed to the custom logger, so we can return.
 	if app.err != nil {
 		return app
@@ -765,6 +765,10 @@ func (app *App) provide(p provide) {
 	}
 	defer func() {
 		if app.err != nil {
+			app.log.LogEvent(&fxevent.Provide{
+				Err:         app.err,
+				Constructor: constructor,
+			})
 			return
 		}
 
@@ -832,7 +836,7 @@ func (app *App) executeInvokes() error {
 
 	for _, i := range app.invokes {
 		fn := i.Target
-		app.log.LogEvent(&fxevent.Invoke{Function: fn})
+		app.log.LogEvent(&fxevent.Invoking{Function: fn})
 
 		var err error
 		if _, ok := fn.(Option); ok {
@@ -844,7 +848,7 @@ func (app *App) executeInvokes() error {
 		}
 
 		if err != nil {
-			app.log.LogEvent(&fxevent.Invoke{
+			app.log.LogEvent(&fxevent.Invoked{
 				Function:   fn,
 				Err:        err,
 				Stacktrace: fmt.Sprintf("%+v", i.Stack), // format stack trace as multi-line
diff --git a/fxevent/console.go b/fxevent/console.go
index c8775e1..6f7900d 100644
--- a/fxevent/console.go
+++ b/fxevent/console.go
@@ -62,13 +62,11 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		if e.Err != nil {
 			l.logf("Error after options were applied: %v", e.Err)
 		}
-	case *Invoke:
-		if e.Err != nil {
-			l.logf("fx.Invoke(%v) called from:\n%+vFailed: %v",
-				fxreflect.FuncName(e.Function), e.Stacktrace, e.Err)
-		} else {
-			l.logf("INVOKE\t\t%s", fxreflect.FuncName(e.Function))
-		}
+	case *Invoking:
+		l.logf("INVOKE\t\t%s", fxreflect.FuncName(e.Function))
+	case *Invoked:
+		l.logf("fx.Invoke(%v) called from:\n%+vFailed: %v",
+			fxreflect.FuncName(e.Function), e.Stacktrace, e.Err)
 	case *Stop:
 		if e.Err != nil {
 			l.logf("ERROR\t\tFailed to stop cleanly: %v", e.Err)
@@ -87,11 +85,11 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		} else {
 			l.logf("RUNNING")
 		}
-	case *CustomLogger:
+	case *LoggerInitialized:
 		if e.Err != nil {
-			l.logf("ERROR\t\tFailed to construct custom logger: %v", e.Err)
+			l.logf("ERROR\t\tFailed to initialize custom logger: %v", e.Err)
 		} else {
-			l.logf("LOGGER\tSetting up custom logger from %v", fxreflect.FuncName(e.Function))
+			l.logf("LOGGER\tInitialized custom logger from %v", fxreflect.FuncName(e.Constructor))
 		}
 	}
 }
diff --git a/fxevent/event.go b/fxevent/event.go
index 3093f0a..e7002a8 100644
--- a/fxevent/event.go
+++ b/fxevent/event.go
@@ -35,11 +35,12 @@ func (*LifecycleHookExecuting) event() {}
 func (*LifecycleHookExecuted) event()  {}
 func (*Supplied) event()               {}
 func (*Provide) event()                {}
-func (*Invoke) event()                 {}
+func (*Invoking) event()               {}
+func (*Invoked) event()                {}
 func (*Stop) event()                   {}
 func (*Rollback) event()               {}
 func (*Started) event()                {}
-func (*CustomLogger) event()           {}
+func (*LoggerInitialized) event()      {}
 
 // LifecycleHookExecuting is emitted before an OnStart hook is about to be executed.
 type LifecycleHookExecuting struct {
@@ -78,8 +79,13 @@ type Provide struct {
 	Err error
 }
 
-// Invoke is emitted whenever a function is being invoked and/or it errored.
-type Invoke struct {
+// Invoking is emitted whenever a function is being invoked.
+type Invoking struct {
+	Function interface{}
+}
+
+// Invoked is emitted whenever a function being invoked errored.
+type Invoked struct {
 	Function   interface{}
 	Err        error
 	Stacktrace string
@@ -103,8 +109,8 @@ type Rollback struct {
 	Err      error
 }
 
-// CustomLogger is emitted whenever a custom logger is set or produces an error.
-type CustomLogger struct {
-	Function interface{}
-	Err      error
+// LoggerInitialized is emitted whenever a custom logger is set or produces an error.
+type LoggerInitialized struct {
+	Constructor interface{}
+	Err         error
 }
diff --git a/fxevent/zap.go b/fxevent/zap.go
index 3d84a86..8f03c51 100644
--- a/fxevent/zap.go
+++ b/fxevent/zap.go
@@ -72,16 +72,14 @@ func (l *ZapLogger) LogEvent(event Event) {
 			l.Logger.Error("error encountered while applying options",
 				zap.Error(e.Err))
 		}
-	case *Invoke:
-		if e.Err != nil {
-			l.Logger.Error("invoke failed",
-				zap.Error(e.Err),
-				zap.String("stack", e.Stacktrace),
-				zap.String("function", fxreflect.FuncName(e.Function)))
-		} else {
-			l.Logger.Info("invoked",
-				zap.String("function", fxreflect.FuncName(e.Function)))
-		}
+	case *Invoking:
+		l.Logger.Info("invoked",
+			zap.String("function", fxreflect.FuncName(e.Function)))
+	case *Invoked:
+		l.Logger.Error("invoke failed",
+			zap.Error(e.Err),
+			zap.String("stack", e.Stacktrace),
+			zap.String("function", fxreflect.FuncName(e.Function)))
 	case *Stop:
 		if e.Err != nil {
 			l.Logger.Error("stop failed", zap.Error(e.Err))
@@ -101,12 +99,12 @@ func (l *ZapLogger) LogEvent(event Event) {
 		} else {
 			l.Logger.Info("started")
 		}
-	case *CustomLogger:
+	case *LoggerInitialized:
 		if e.Err != nil {
-			l.Logger.Error("custom logger installation failed", zap.Error(e.Err))
+			l.Logger.Error("custom logger initialization failed", zap.Error(e.Err))
 		} else {
-			l.Logger.Info("installed custom fxevent.Logger",
-				zap.String("function", fxreflect.FuncName(e.Function)))
+			l.Logger.Info("initialized custom fxevent.Logger",
+				zap.String("function", fxreflect.FuncName(e.Constructor)))
 		}
 	}
 }


Test patch:
diff --git a/app_test.go b/app_test.go
index 5abc8f9..221d97c 100644
--- a/app_test.go
+++ b/app_test.go
@@ -80,7 +80,7 @@ func TestNewApp(t *testing.T) {
 			WithLogger(func() fxevent.Logger { return spy }))
 		defer app.RequireStart().RequireStop()
 		require.Equal(t,
-			[]string{"Provide", "Provide", "Provide", "Provide", "CustomLogger", "Started"},
+			[]string{"Provide", "Provide", "Provide", "Provide", "LoggerInitialized", "Started"},
 			spy.EventTypes())
 
 		assert.Contains(t, spy.Events()[0].(*fxevent.Provide).OutputTypeNames, "struct {}")
@@ -286,7 +286,7 @@ func TestWithLogger(t *testing.T) {
 		)
 
 		assert.Equal(t, []string{
-			"Supplied", "Provide", "Provide", "Provide", "CustomLogger",
+			"Supplied", "Provide", "Provide", "Provide", "LoggerInitialized",
 		}, spy.EventTypes())
 
 		spy.Reset()
@@ -329,7 +329,7 @@ func TestWithLogger(t *testing.T) {
 
 		// Example output:
 		// [Fx] SUPPLY  *zap.Logger
-		// [Fx] ERROR   Failed to construct custom logger: fx.WithLogger() from:
+		// [Fx] ERROR   Failed to initialize custom logger: fx.WithLogger() from:
 		// go.uber.org/fx_test.TestSetupLogger.func3
 		//        /Users/abg/dev/fx/app_test.go:334
 		// testing.tRunner
@@ -338,7 +338,7 @@ func TestWithLogger(t *testing.T) {
 
 		out := string(stderr)
 		assert.Contains(t, out, "[Fx] SUPPLY\t*zap.Logger\n")
-		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to construct custom logger: fx.WithLogger")
+		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to initialize custom logger: fx.WithLogger")
 		assert.Contains(t, out, "must provide constructor function, got  (type *bytes.Buffer)\n")
 	})
 
@@ -361,7 +361,7 @@ func TestWithLogger(t *testing.T) {
 			"must provide constructor function, got  (type *bytes.Buffer)",
 		)
 
-		assert.Equal(t, []string{"Supplied", "Provide", "CustomLogger"}, spy.EventTypes())
+		assert.Equal(t, []string{"Supplied", "Provide", "LoggerInitialized"}, spy.EventTypes())
 	})
 
 	t.Run("logger failed to build", func(t *testing.T) {
@@ -380,7 +380,7 @@ func TestWithLogger(t *testing.T) {
 		assert.Contains(t, err.Error(), "great sadness")
 
 		out := buff.String()
-		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to construct custom logger")
+		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to initialize custom logger")
 	})
 
 	t.Run("logger dependency failed to build", func(t *testing.T) {
@@ -404,7 +404,7 @@ func TestWithLogger(t *testing.T) {
 
 		out := buff.String()
 		assert.Contains(t, out, "[Fx] PROVIDE\t*zap.Logger")
-		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to construct custom logger")
+		assert.Contains(t, out, "[Fx] ERROR\t\tFailed to initialize custom logger")
 	})
 }
 
@@ -576,7 +576,7 @@ func TestOptions(t *testing.T) {
 			Provide(&bytes.Buffer{}), // error, not a constructor
 			WithLogger(func() fxevent.Logger { return spy }),
 		)
-		require.Equal(t, []string{"Provide", "CustomLogger"}, spy.EventTypes())
+		require.Equal(t, []string{"Provide", "LoggerInitialized"}, spy.EventTypes())
 		assert.Contains(t, spy.Events()[0].(*fxevent.Provide).Err.Error(), "must provide constructor function")
 	})
 }
@@ -810,9 +810,9 @@ func TestAppStart(t *testing.T) {
 		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
 		// Failed: can't invoke non-function {} (type struct {})
 		require.Equal(t,
-			[]string{"Provide", "Provide", "Provide", "CustomLogger", "Invoke", "Invoke"},
+			[]string{"Provide", "Provide", "Provide", "LoggerInitialized", "Invoking", "Invoked"},
 			spy.EventTypes())
-		failedEvent := spy.Events()[len(spy.EventTypes())-1].(*fxevent.Invoke)
+		failedEvent := spy.Events()[len(spy.EventTypes())-1].(*fxevent.Invoked)
 		assert.Contains(t, failedEvent.Err.Error(), "can't invoke non-function")
 		assert.Contains(t, failedEvent.Stacktrace, "go.uber.org/fx_test.TestAppStart")
 		assert.Contains(t, failedEvent.Stacktrace, "fx/app_test.go")
@@ -886,7 +886,7 @@ func TestAppStart(t *testing.T) {
 				func() type2 { return type2{} },
 			),
 			Invoke(func(type1) {
-				require.FailNow(t, "module Invoke must not be called")
+				require.FailNow(t, "module Invoked must not be called")
 			}),
 		)
 
@@ -1048,7 +1048,7 @@ func TestReplaceLogger(t *testing.T) {
 	spy := new(fxlog.Spy)
 	app := fxtest.New(t, WithLogger(func() fxevent.Logger { return spy }))
 	app.RequireStart().RequireStop()
-	assert.Equal(t, []string{"Provide", "Provide", "Provide", "CustomLogger", "Started"}, spy.EventTypes())
+	assert.Equal(t, []string{"Provide", "Provide", "Provide", "LoggerInitialized", "Started"}, spy.EventTypes())
 }
 
 func TestNopLogger(t *testing.T) {
@@ -1117,7 +1117,7 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
 		"Provide",
 		"Provide",
 		"Provide",
-		"CustomLogger",
+		"LoggerInitialized",
 		"LifecycleHookExecuting",
 		"LifecycleHookExecuted",
 		"Started",
@@ -1206,7 +1206,7 @@ func TestOptionString(t *testing.T) {
 			want: "fx.Provide(bytes.NewReader())",
 		},
 		{
-			desc: "Invoke",
+			desc: "Invoked",
 			give: Invoke(func(c io.Closer) error {
 				return c.Close()
 			}),
diff --git a/fxevent/console_test.go b/fxevent/console_test.go
index d7ac835..5d27d54 100644
--- a/fxevent/console_test.go
+++ b/fxevent/console_test.go
@@ -85,13 +85,13 @@ func TestConsoleLogger(t *testing.T) {
 			want: "[Fx] PROVIDE	*bytes.Buffer <= bytes.NewBuffer()\n",
 		},
 		{
-			name: "Invoke",
-			give: &Invoke{Function: bytes.NewBuffer, Err: nil},
+			name: "Invoked",
+			give: &Invoking{Function: bytes.NewBuffer},
 			want: "[Fx] INVOKE		bytes.NewBuffer()\n",
 		},
 		{
 			name: "InvokeError",
-			give: &Invoke{
+			give: &Invoked{
 				Function:   bytes.NewBuffer,
 				Err:        errors.New("some error"),
 				Stacktrace: "foo()\n\tbar/baz.go:42\n",
@@ -135,15 +135,15 @@ func TestConsoleLogger(t *testing.T) {
 		},
 		{
 			name: "CustomLoggerError",
-			give: &CustomLogger{Err: errors.New("great sadness")},
-			want: "[Fx] ERROR		Failed to construct custom logger: great sadness\n",
+			give: &LoggerInitialized{Err: errors.New("great sadness")},
+			want: "[Fx] ERROR		Failed to initialize custom logger: great sadness\n",
 		},
 		{
-			name: "CustomLogger",
-			give: &CustomLogger{
-				Function: func() Logger { panic("should not run") },
+			name: "LoggerInitialized",
+			give: &LoggerInitialized{
+				Constructor: func() Logger { panic("should not run") },
 			},
-			want: "[Fx] LOGGER	Setting up custom logger from go.uber.org/fx/fxevent.TestConsoleLogger.func1()\n",
+			want: "[Fx] LOGGER	Initialized custom logger from go.uber.org/fx/fxevent.TestConsoleLogger.func1()\n",
 		},
 	}
 
diff --git a/fxevent/event_test.go b/fxevent/event_test.go
index 2b6ade4..78079e4 100644
--- a/fxevent/event_test.go
+++ b/fxevent/event_test.go
@@ -33,11 +33,12 @@ func TestForCoverage(t *testing.T) {
 		&LifecycleHookExecuted{},
 		&Supplied{},
 		&Provide{},
-		&Invoke{},
+		&Invoking{},
+		&Invoked{},
 		&Stop{},
 		&Rollback{},
 		&Started{},
-		&CustomLogger{},
+		&LoggerInitialized{},
 	}
 
 	for _, e := range events {
diff --git a/fxevent/zap_test.go b/fxevent/zap_test.go
index 4bd81a8..4a264b0 100644
--- a/fxevent/zap_test.go
+++ b/fxevent/zap_test.go
@@ -118,8 +118,8 @@ func TestZapLogger(t *testing.T) {
 			},
 		},
 		{
-			name:        "Invoke",
-			give:        &Invoke{Function: bytes.NewBuffer, Err: nil},
+			name:        "Invoking",
+			give:        &Invoking{Function: bytes.NewBuffer},
 			wantMessage: "invoked",
 			wantFields: map[string]interface{}{
 				"function": "bytes.NewBuffer()",
@@ -127,7 +127,7 @@ func TestZapLogger(t *testing.T) {
 		},
 		{
 			name:        "InvokeError",
-			give:        &Invoke{Function: bytes.NewBuffer, Err: someError},
+			give:        &Invoked{Function: bytes.NewBuffer, Err: someError},
 			wantMessage: "invoke failed",
 			wantFields: map[string]interface{}{
 				"error":    "some error",
@@ -182,17 +182,17 @@ func TestZapLogger(t *testing.T) {
 			wantFields:  map[string]interface{}{},
 		},
 		{
-			name:        "CustomLogger Error",
-			give:        &CustomLogger{Err: someError},
-			wantMessage: "custom logger installation failed",
+			name:        "LoggerInitialized Error",
+			give:        &LoggerInitialized{Err: someError},
+			wantMessage: "custom logger initialization failed",
 			wantFields: map[string]interface{}{
 				"error": "some error",
 			},
 		},
 		{
-			name:        "CustomLogger",
-			give:        &CustomLogger{Function: bytes.NewBuffer, Err: nil},
-			wantMessage: "installed custom fxevent.Logger",
+			name:        "LoggerInitialized",
+			give:        &LoggerInitialized{Constructor: bytes.NewBuffer, Err: nil},
+			wantMessage: "initialized custom fxevent.Logger",
 			wantFields: map[string]interface{}{
 				"function": "bytes.NewBuffer()",
 			},