Repository: uber-go/fx
Pull request #759 (2021-07-12 22:28:32)

Add events for lifecycle hook execution
This adds events for lifecycle hook execution. `LifecycleHookStart` and `LifecycleHookStop` was being used to fire events separately for `OnStart` and `OnStop` events previously. Since the recorded fields for both events aren't different, this change merges the two events into a single set of events, and adds another event so that an event is fired before and another is fired after a hook is executed.

Specifically, `LifecycleHookExecuting` is fired right before either an `OnStart` or `OnStop` hook is executed. After the hook has finished executing, `LifecycleHookExecuted` is fired with either an error or the runtime. Both `LifecycleHookExecuting` and `LifecycleHookExecuted` events contain the name of the hook being executed, the name of the caller that appended the lifecycle, and the method that's being executed (either `OnStart` or `OnStop`).

Refs: GO-707.

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

[![Impacted file tree graph](https://codecov.io/gh/uber-go/fx/pull/759/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/759?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     #759      +/-   ##
==========================================
+ Coverage   98.06%   98.21%   +0.14%     
==========================================
  Files          24       24              
  Lines         671      727      +56     
==========================================
+ Hits          658      714      +56     
  Misses         10       10              
  Partials        3        3              
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/759?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) | Coverage Δ | |
|---|---|---|
| [fxevent/console.go](https://codecov.io/gh/uber-go/fx/pull/759/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/759/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/759/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%> (ø)` | |
| [internal/lifecycle/lifecycle.go](https://codecov.io/gh/uber-go/fx/pull/759/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-aW50ZXJuYWwvbGlmZWN5Y2xlL2xpZmVjeWNsZS5nbw==) | `100.00% <100.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/uber-go/fx/pull/759?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/759?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go). Last update [734db16...5908ebd](https://codecov.io/gh/uber-go/fx/pull/759?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/fxevent/console.go b/fxevent/console.go
index a722882..0fee5c4 100644
--- a/fxevent/console.go
+++ b/fxevent/console.go
@@ -45,10 +45,14 @@ func (l *ConsoleLogger) logf(msg string, args ...interface{}) {
 // LogEvent logs the given event to the provided Zap logger.
 func (l *ConsoleLogger) LogEvent(event Event) {
 	switch e := event.(type) {
-	case *LifecycleHookStart:
-		l.logf("START\t\t%s", e.CallerName)
-	case *LifecycleHookStop:
-		l.logf("STOP\t\t%s", e.CallerName)
+	case *LifecycleHookExecuting:
+		l.logf("HOOK %s\t\t%s executing (caller: %s)", e.Method, e.FunctionName, e.CallerName)
+	case *LifecycleHookExecuted:
+		if e.Err != nil {
+			l.logf("HOOK %s\t\t%s called by %s failed in %s: %v", e.Method, e.FunctionName, e.CallerName, e.Runtime, e.Err)
+		} else {
+			l.logf("HOOK %s\t\t%s called by %s ran successfully in %s", e.Method, e.FunctionName, e.CallerName, e.Runtime)
+		}
 	case *ProvideError:
 		l.logf("Error after options were applied: %v", e.Err)
 	case *Supply:
diff --git a/fxevent/event.go b/fxevent/event.go
index f36d4a6..a58b473 100644
--- a/fxevent/event.go
+++ b/fxevent/event.go
@@ -22,6 +22,7 @@ package fxevent
 
 import (
 	"os"
+	"time"
 )
 
 // Event defines an event emitted by fx.
@@ -30,30 +31,39 @@ type Event interface {
 }
 
 // Passing events by type to make Event hashable in the future.
-func (*LifecycleHookStart) event() {}
-func (*LifecycleHookStop) event()  {}
-func (*ProvideError) event()       {}
-func (*Supply) event()             {}
-func (*Provide) event()            {}
-func (*Invoke) event()             {}
-func (*InvokeError) event()        {}
-func (*StartError) event()         {}
-func (*StopSignal) event()         {}
-func (*StopError) event()          {}
-func (*Rollback) event()           {}
-func (*RollbackError) event()      {}
-func (*Running) event()            {}
-func (*CustomLoggerError) event()  {}
-func (*CustomLogger) event()       {}
-
-// LifecycleHookStart is emitted whenever an OnStart hook is executed
-type LifecycleHookStart struct {
+func (*LifecycleHookExecuting) event() {}
+func (*LifecycleHookExecuted) event()  {}
+func (*ProvideError) event()           {}
+func (*Supply) event()                 {}
+func (*Provide) event()                {}
+func (*Invoke) event()                 {}
+func (*InvokeError) event()            {}
+func (*StartError) event()             {}
+func (*StopSignal) event()             {}
+func (*StopError) event()              {}
+func (*Rollback) event()               {}
+func (*RollbackError) event()          {}
+func (*Running) event()                {}
+func (*CustomLoggerError) event()      {}
+func (*CustomLogger) event()           {}
+
+// LifecycleHookExecuting is emitted before an OnStart hook is about to be executed.
+type LifecycleHookExecuting struct {
+	// FunctionName is the name of the hook being executed.
+	FunctionName string
+	// CallerName is the name of the caller that appended the hook.
 	CallerName string
+	// Method is the lifecycle hook method getting called.
+	Method string
 }
 
-// LifecycleHookStop is emitted whenever an OnStart hook is executed
-type LifecycleHookStop struct {
-	CallerName string
+// LifecycleHookExecuted is emitted after an OnStart hook has been executed.
+type LifecycleHookExecuted struct {
+	FunctionName string
+	CallerName   string
+	Method       string
+	Runtime      time.Duration
+	Err          error
 }
 
 // ProvideError is emitted whenever there is an error applying options.
diff --git a/fxevent/zap.go b/fxevent/zap.go
index a7dc04e..63cc15f 100644
--- a/fxevent/zap.go
+++ b/fxevent/zap.go
@@ -37,10 +37,28 @@ var _ Logger = (*ZapLogger)(nil)
 // LogEvent logs the given event to the provided Zap logger.
 func (l *ZapLogger) LogEvent(event Event) {
 	switch e := event.(type) {
-	case *LifecycleHookStart:
-		l.Logger.Info("starting", zap.String("caller", e.CallerName))
-	case *LifecycleHookStop:
-		l.Logger.Info("stopping", zap.String("caller", e.CallerName))
+	case *LifecycleHookExecuting:
+		l.Logger.Info("hook executing",
+			zap.String("method", e.Method),
+			zap.String("callee", e.FunctionName),
+			zap.String("caller", e.CallerName),
+		)
+	case *LifecycleHookExecuted:
+		if e.Err != nil {
+			l.Logger.Info("hook execute failed",
+				zap.String("method", e.Method),
+				zap.String("callee", e.FunctionName),
+				zap.String("caller", e.CallerName),
+				zap.Error(e.Err),
+			)
+		} else {
+			l.Logger.Info("hook executed",
+				zap.String("method", e.Method),
+				zap.String("callee", e.FunctionName),
+				zap.String("caller", e.CallerName),
+				zap.String("runtime", e.Runtime.String()),
+			)
+		}
 	case *ProvideError:
 		l.Logger.Error("error encountered while applying options",
 			zap.Error(e.Err))
diff --git a/internal/lifecycle/lifecycle.go b/internal/lifecycle/lifecycle.go
index 009a7ea..db3eb78 100644
--- a/internal/lifecycle/lifecycle.go
+++ b/internal/lifecycle/lifecycle.go
@@ -67,13 +67,23 @@ func (l *Lifecycle) Append(hook Hook) {
 	l.hooks = append(l.hooks, hook)
 }
 
+const (
+	_hookStart = "OnStart"
+	_hookStop  = "OnStop"
+)
+
 // Start runs all OnStart hooks, returning immediately if it encounters an
 // error.
 func (l *Lifecycle) Start(ctx context.Context) error {
 	l.startRecords = make(HookRecords, 0, len(l.hooks))
 	for _, hook := range l.hooks {
 		if hook.OnStart != nil {
-			l.logger.LogEvent(&fxevent.LifecycleHookStart{CallerName: hook.callerFrame.Function})
+			funcName := fxreflect.FuncName(hook.OnStart)
+			l.logger.LogEvent(&fxevent.LifecycleHookExecuting{
+				CallerName:   hook.callerFrame.Function,
+				FunctionName: funcName,
+				Method:       _hookStart,
+			})
 
 			l.mu.Lock()
 			l.runningHook = hook
@@ -81,15 +91,29 @@ func (l *Lifecycle) Start(ctx context.Context) error {
 
 			begin := time.Now()
 			if err := hook.OnStart(ctx); err != nil {
+				l.logger.LogEvent(&fxevent.LifecycleHookExecuted{
+					CallerName:   hook.callerFrame.Function,
+					FunctionName: funcName,
+					Method:       _hookStart,
+					Runtime:      time.Since(begin),
+					Err:          err,
+				})
 				return err
 			}
 			l.mu.Lock()
+			runtime := time.Since(begin)
 			l.startRecords = append(l.startRecords, HookRecord{
 				CallerFrame: hook.callerFrame,
 				Func:        hook.OnStart,
-				Runtime:     time.Since(begin),
+				Runtime:     runtime,
 			})
 			l.mu.Unlock()
+			l.logger.LogEvent(&fxevent.LifecycleHookExecuted{
+				CallerName:   hook.callerFrame.Function,
+				FunctionName: funcName,
+				Method:       _hookStart,
+				Runtime:      runtime,
+			})
 		}
 		l.numStarted++
 	}
@@ -111,24 +135,47 @@ func (l *Lifecycle) Stop(ctx context.Context) error {
 		if hook.OnStop == nil {
 			continue
 		}
+		funcName := fxreflect.FuncName(hook.OnStop)
 
-		l.logger.LogEvent(&fxevent.LifecycleHookStop{CallerName: hook.callerFrame.Function})
+		l.logger.LogEvent(&fxevent.LifecycleHookExecuting{
+			CallerName:   hook.callerFrame.Function,
+			FunctionName: funcName,
+			Method:       _hookStop,
+		})
 
 		l.mu.Lock()
 		l.runningHook = hook
 		l.mu.Unlock()
 
 		begin := time.Now()
-		if err := hook.OnStop(ctx); err != nil {
+		var err error
+		if err = hook.OnStop(ctx); err != nil {
 			// For best-effort cleanup, keep going after errors.
+			l.logger.LogEvent(&fxevent.LifecycleHookExecuted{
+				CallerName:   hook.callerFrame.Function,
+				FunctionName: funcName,
+				Method:       _hookStop,
+				Err:          err,
+			})
 			errs = append(errs, err)
 		}
 		l.mu.Lock()
+		runtime := time.Since(begin)
 		l.stopRecords = append(l.stopRecords, HookRecord{
 			CallerFrame: hook.callerFrame,
 			Func:        hook.OnStop,
-			Runtime:     time.Since(begin),
+			Runtime:     runtime,
 		})
+
+		if err == nil {
+			l.logger.LogEvent(&fxevent.LifecycleHookExecuted{
+				CallerName:   hook.callerFrame.Function,
+				FunctionName: funcName,
+				Method:       _hookStop,
+				Runtime:      runtime,
+			})
+		}
+
 		l.mu.Unlock()
 	}
 


Test patch:
diff --git a/app_test.go b/app_test.go
index 85c528c..b836d60 100644
--- a/app_test.go
+++ b/app_test.go
@@ -1094,9 +1094,11 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
 		"Provide",
 		"Provide",
 		"CustomLogger",
-		"LifecycleHookStart",
+		"LifecycleHookExecuting",
+		"LifecycleHookExecuted",
 		"Running",
-		"LifecycleHookStop",
+		"LifecycleHookExecuting",
+		"LifecycleHookExecuted",
 	}, spy.EventTypes())
 }
 
diff --git a/fxevent/console_test.go b/fxevent/console_test.go
index 9b5de0c..bc3ad30 100644
--- a/fxevent/console_test.go
+++ b/fxevent/console_test.go
@@ -23,9 +23,11 @@ package fxevent
 import (
 	"bytes"
 	"errors"
+	"fmt"
 	"os"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 )
@@ -39,14 +41,33 @@ func TestConsoleLogger(t *testing.T) {
 		want string
 	}{
 		{
-			name: "LifecycleHookStart",
-			give: &LifecycleHookStart{CallerName: "bytes.NewBuffer"},
-			want: "[Fx] START		bytes.NewBuffer\n",
+			name: "LifecycleHookExecuting",
+			give: &LifecycleHookExecuting{
+				Method:       "OnStop",
+				FunctionName: "hook.onStop1",
+				CallerName:   "bytes.NewBuffer",
+			},
+			want: "[Fx] HOOK OnStop		hook.onStop1 executing (caller: bytes.NewBuffer)\n",
 		},
 		{
-			name: "LifecycleHookStop",
-			give: &LifecycleHookStop{CallerName: "bytes.NewBuffer"},
-			want: "[Fx] STOP		bytes.NewBuffer\n",
+			name: "LifecycleHookExecutedError",
+			give: &LifecycleHookExecuted{
+				Method:       "OnStart",
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Err:          fmt.Errorf("some error"),
+			},
+			want: "[Fx] HOOK OnStart		hook.onStart1 called by bytes.NewBuffer failed in 0s: some error\n",
+		},
+		{
+			name: "LifecycleHookExecuted",
+			give: &LifecycleHookExecuted{
+				Method:       "OnStart",
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Runtime:      time.Millisecond * 3,
+			},
+			want: "[Fx] HOOK OnStart		hook.onStart1 called by bytes.NewBuffer ran successfully in 3ms\n",
 		},
 		{
 			name: "ProvideError",
diff --git a/fxevent/event_test.go b/fxevent/event_test.go
index 74d5582..798740a 100644
--- a/fxevent/event_test.go
+++ b/fxevent/event_test.go
@@ -29,8 +29,8 @@ import (
 // TestForCoverage adds coverage for own sake.
 func TestForCoverage(t *testing.T) {
 	events := []Event{
-		&LifecycleHookStart{},
-		&LifecycleHookStop{},
+		&LifecycleHookExecuting{},
+		&LifecycleHookExecuted{},
 		&ProvideError{},
 		&Supply{},
 		&Provide{},
diff --git a/fxevent/zap_test.go b/fxevent/zap_test.go
index a2d845a..2d99725 100644
--- a/fxevent/zap_test.go
+++ b/fxevent/zap_test.go
@@ -23,8 +23,10 @@ package fxevent
 import (
 	"bytes"
 	"errors"
+	"fmt"
 	"os"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -44,19 +46,49 @@ func TestZapLogger(t *testing.T) {
 		wantFields  map[string]interface{}
 	}{
 		{
-			name:        "LifecycleHookStart",
-			give:        &LifecycleHookStart{CallerName: "bytes.NewBuffer"},
-			wantMessage: "starting",
+			name: "LifecycleHookExecuting",
+			give: &LifecycleHookExecuting{
+				Method:       "OnStop",
+				FunctionName: "hook.onStop1",
+				CallerName:   "bytes.NewBuffer",
+			},
+			wantMessage: "hook executing",
 			wantFields: map[string]interface{}{
 				"caller": "bytes.NewBuffer",
+				"callee": "hook.onStop1",
+				"method": "OnStop",
 			},
 		},
 		{
-			name:        "LifecycleHookStop",
-			give:        &LifecycleHookStop{CallerName: "bytes.NewBuffer"},
-			wantMessage: "stopping",
+			name: "LifecycleHookExecutedError",
+			give: &LifecycleHookExecuted{
+				Method:       "OnStart",
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Err:          fmt.Errorf("some error"),
+			},
+			wantMessage: "hook execute failed",
 			wantFields: map[string]interface{}{
 				"caller": "bytes.NewBuffer",
+				"callee": "hook.onStart1",
+				"method": "OnStart",
+				"error":  "some error",
+			},
+		},
+		{
+			name: "LifecycleHookExecuted",
+			give: &LifecycleHookExecuted{
+				Method:       "OnStart",
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Runtime:      time.Millisecond * 3,
+			},
+			wantMessage: "hook executed",
+			wantFields: map[string]interface{}{
+				"caller":  "bytes.NewBuffer",
+				"callee":  "hook.onStart1",
+				"method":  "OnStart",
+				"runtime": "3ms",
 			},
 		},
 		{