Repository: uber-go/fx
Pull request #746 (2021-06-14 17:57:20)

Report running hook and executed hooks' runtimes as part of startup timeout error
When Fx.Start() timeouts during startup, it's difficult for the user to debug why it failed, because the only error message being printed is "context deadline exceeded". 

This enhances the error returned from timeout by adding a report of the currently executing hook's caller (the function that called `Append`) as well as a report of all the hooks that were successfully executed - specifically their runtimes, functions that ran as hooks, and their callers.

Refs GO-628.

codecov[bot]: # [Codecov](https://codecov.io/gh/uber-go/fx/pull/746?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) Report
> Merging [#746](https://codecov.io/gh/uber-go/fx/pull/746?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (36d2366) into [master](https://codecov.io/gh/uber-go/fx/commit/4a15da237beb9f0b528b1a81c3eb77f56e17957a?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (4a15da2) will **decrease** coverage by `1.73%`.
> The diff coverage is `85.71%`.

[![Impacted file tree graph](https://codecov.io/gh/uber-go/fx/pull/746/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/746?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     #746      +/-   ##
==========================================
- Coverage   97.71%   95.97%   -1.74%     
==========================================
  Files          19       19              
  Lines         525      597      +72     
==========================================
+ Hits          513      573      +60     
- Misses         10       20      +10     
- Partials        2        4       +2     
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/746?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) | Coverage Δ | |
|---|---|---|
| [internal/lifecycle/lifecycle.go](https://codecov.io/gh/uber-go/fx/pull/746/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-aW50ZXJuYWwvbGlmZWN5Y2xlL2xpZmVjeWNsZS5nbw==) | `90.24% <80.00%> (-9.76%)` | :arrow_down: |
| [fxtest/lifecycle.go](https://codecov.io/gh/uber-go/fx/pull/746/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-Znh0ZXN0L2xpZmVjeWNsZS5nbw==) | `92.98% <84.61%> (-7.02%)` | :arrow_down: |
| [app.go](https://codecov.io/gh/uber-go/fx/pull/746/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-YXBwLmdv) | `94.29% <89.47%> (-1.21%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/uber-go/fx/pull/746?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/746?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go). Last update [4a15da2...36d2366](https://codecov.io/gh/uber-go/fx/pull/746?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).

sywhang: Marking this as WIP till I add some more tests : )
sywhang: @abhinav @shirchen FYI I made the changes to the implementation to not use channels to report the times and get it directly from Lifecycle instead -- Since #747 is still underway, I'll hold off on making additional changes until that's done and rebase this with the changes from that. 

Patch:
diff --git a/app.go b/app.go
index 8275e3e..bb8d1a7 100644
--- a/app.go
+++ b/app.go
@@ -28,6 +28,7 @@ import (
 	"os"
 	"os/signal"
 	"reflect"
+	"sort"
 	"strings"
 	"sync"
 	"time"
@@ -661,6 +662,11 @@ func (app *App) Err() error {
 	return app.err
 }
 
+var (
+	_onStartHook = "OnStart"
+	_onStopHook  = "OnStop"
+)
+
 // Start kicks off all long-running goroutines, like network servers or
 // message queue consumers. It does this by interacting with the application's
 // Lifecycle.
@@ -679,7 +685,12 @@ func (app *App) Err() error {
 // Note that Start short-circuits immediately if the New constructor
 // encountered any errors in application initialization.
 func (app *App) Start(ctx context.Context) error {
-	return withTimeout(ctx, app.start)
+	return withTimeout(ctx, &withTimeoutParams{
+		hook:      _onStartHook,
+		callback:  app.start,
+		lifecycle: app.lifecycle,
+		log:       app.log,
+	})
 }
 
 // Stop gracefully stops the application. It executes any registered OnStop
@@ -690,7 +701,12 @@ func (app *App) Start(ctx context.Context) error {
 // called are executed. However, all those hooks are executed, even if some
 // fail.
 func (app *App) Stop(ctx context.Context) error {
-	return withTimeout(ctx, app.lifecycle.Stop)
+	return withTimeout(ctx, &withTimeoutParams{
+		hook:      _onStopHook,
+		callback:  app.lifecycle.Stop,
+		lifecycle: app.lifecycle,
+		log:       app.log,
+	})
 }
 
 // Done returns a channel of signals to block on after starting the
@@ -877,6 +893,7 @@ func (app *App) start(ctx context.Context) error {
 
 			return multierr.Append(err, stopErr)
 		}
+
 		return err
 	}
 	app.log.LogEvent(&fxevent.Running{})
@@ -884,13 +901,42 @@ func (app *App) start(ctx context.Context) error {
 	return nil
 }
 
-func withTimeout(ctx context.Context, f func(context.Context) error) error {
+type withTimeoutParams struct {
+	log       fxevent.Logger
+	hook      string
+	callback  func(context.Context) error
+	lifecycle *lifecycleWrapper
+}
+
+func withTimeout(ctx context.Context, param *withTimeoutParams) error {
 	c := make(chan error, 1)
-	go func() { c <- f(ctx) }()
+	go func() { c <- param.callback(ctx) }()
 
 	select {
 	case <-ctx.Done():
-		return ctx.Err()
+		err := ctx.Err()
+		if err != context.DeadlineExceeded {
+			return err
+		}
+		// On timeout, report running hook's caller and recorded
+		// runtimes of hooks successfully run till end.
+		r := param.lifecycle.hookRecords()
+		sort.Sort(r)
+		caller := param.lifecycle.runningHookCaller()
+		// TODO: Once this is integrated into fxevent, we can
+		// leave error unchanged and send this to fxevent.Logger, whose
+		// implementation can then determine how the error is presented.
+		if len(r) > 0 {
+			return fmt.Errorf("%v hook added by %v failed: %w\n%+v",
+				param.hook,
+				caller,
+				err,
+				r)
+		}
+		return fmt.Errorf("%v hook added by %v failed: %w",
+			param.hook,
+			caller,
+			err)
 	case err := <-c:
 		return err
 	}
diff --git a/internal/lifecycle/lifecycle.go b/internal/lifecycle/lifecycle.go
index ca4fdde..b416789 100644
--- a/internal/lifecycle/lifecycle.go
+++ b/internal/lifecycle/lifecycle.go
@@ -22,6 +22,11 @@ package lifecycle
 
 import (
 	"context"
+	"fmt"
+	"io"
+	"strings"
+	"sync"
+	"time"
 
 	"go.uber.org/fx/fxevent"
 	"go.uber.org/fx/internal/fxreflect"
@@ -33,14 +38,18 @@ import (
 type Hook struct {
 	OnStart func(context.Context) error
 	OnStop  func(context.Context) error
-	caller  string
+
+	callerFrame fxreflect.Frame
 }
 
 // Lifecycle coordinates application lifecycle hooks.
 type Lifecycle struct {
-	logger     fxevent.Logger
-	hooks      []Hook
-	numStarted int
+	logger      fxevent.Logger
+	hooks       []Hook
+	numStarted  int
+	records     HookRecords
+	runningHook Hook
+	mu          sync.Mutex
 }
 
 // New constructs a new Lifecycle.
@@ -50,19 +59,36 @@ func New(logger fxevent.Logger) *Lifecycle {
 
 // Append adds a Hook to the lifecycle.
 func (l *Lifecycle) Append(hook Hook) {
-	hook.caller = fxreflect.Caller()
+	// Save the caller's stack frame to report file/line number.
+	if f := fxreflect.CallerStack(2, 0); len(f) > 0 {
+		hook.callerFrame = f[0]
+	}
 	l.hooks = append(l.hooks, hook)
 }
 
 // Start runs all OnStart hooks, returning immediately if it encounters an
 // error.
 func (l *Lifecycle) Start(ctx context.Context) error {
+	l.records = make(HookRecords, 0, len(l.hooks))
 	for _, hook := range l.hooks {
 		if hook.OnStart != nil {
-			l.logger.LogEvent(&fxevent.LifecycleHookStart{CallerName: hook.caller})
+			l.logger.LogEvent(&fxevent.LifecycleHookStart{CallerName: hook.callerFrame.Function})
+
+			l.mu.Lock()
+			l.runningHook = hook
+			l.mu.Unlock()
+
+			begin := time.Now()
 			if err := hook.OnStart(ctx); err != nil {
 				return err
 			}
+			l.mu.Lock()
+			l.records = append(l.records, HookRecord{
+				CallerFrame: hook.callerFrame,
+				Func:        hook.OnStart,
+				Runtime:     time.Since(begin),
+			})
+			l.mu.Unlock()
 		}
 		l.numStarted++
 	}
@@ -74,18 +100,104 @@ func (l *Lifecycle) Start(ctx context.Context) error {
 // hooks run in reverse order.
 func (l *Lifecycle) Stop(ctx context.Context) error {
 	var errs []error
+	l.mu.Lock()
+	l.records = make(HookRecords, 0, l.numStarted)
+	l.mu.Unlock()
+
 	// Run backward from last successful OnStart.
 	for ; l.numStarted > 0; l.numStarted-- {
 		hook := l.hooks[l.numStarted-1]
 		if hook.OnStop == nil {
 			continue
 		}
-		l.logger.LogEvent(&fxevent.LifecycleHookStop{CallerName: hook.caller})
+
+		l.logger.LogEvent(&fxevent.LifecycleHookStop{CallerName: hook.callerFrame.Function})
+
+		l.mu.Lock()
+		l.runningHook = hook
+		l.mu.Unlock()
+
+		begin := time.Now()
 		if err := hook.OnStop(ctx); err != nil {
 			// For best-effort cleanup, keep going after errors.
 			errs = append(errs, err)
 		}
+		l.mu.Lock()
+		l.records = append(l.records, HookRecord{
+			CallerFrame: hook.callerFrame,
+			Func:        hook.OnStop,
+			Runtime:     time.Since(begin),
+		})
+		l.mu.Unlock()
 	}
 
 	return multierr.Combine(errs...)
 }
+
+// HookRecords returns the info of hooks that successfully ran till the end,
+// including their caller and runtime. Used to report timeout errors on Start/Stop.
+func (l *Lifecycle) HookRecords() HookRecords {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	r := make(HookRecords, len(l.records))
+	copy(r, l.records)
+	return r
+}
+
+// RunningHookCaller returns the name of the hook that was running when a Start/Stop
+// hook timed out.
+func (l *Lifecycle) RunningHookCaller() string {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	return l.runningHook.callerFrame.Function
+}
+
+// HookRecord keeps track of each Hook's execution time, the caller that appended the Hook, and function that ran as the Hook.
+type HookRecord struct {
+	CallerFrame fxreflect.Frame             // stack frame of the caller
+	Func        func(context.Context) error // function that ran as sanitized name
+	Runtime     time.Duration               // how long the hook ran
+}
+
+// HookRecords is a Stringer wrapper of HookRecord slice.
+type HookRecords []HookRecord
+
+func (rs HookRecords) Len() int {
+	return len(rs)
+}
+
+func (rs HookRecords) Less(i, j int) bool {
+	// Sort by runtime, greater ones at top.
+	return rs[i].Runtime > rs[j].Runtime
+}
+
+func (rs HookRecords) Swap(i, j int) {
+	rs[i], rs[j] = rs[j], rs[i]
+}
+
+// Used for logging startup errors.
+func (rs HookRecords) String() string {
+	var b strings.Builder
+	for _, r := range rs {
+		fmt.Fprintf(&b, "%s took %v from %s",
+			fxreflect.FuncName(r.Func), r.Runtime, r.CallerFrame)
+	}
+	return b.String()
+}
+
+// Format implements fmt.Formatter to handle "%+v".
+func (rs HookRecords) Format(w fmt.State, c rune) {
+	if !w.Flag('+') {
+		// Without %+v, fall back to String().
+		io.WriteString(w, rs.String())
+		return
+	}
+
+	for _, r := range rs {
+		fmt.Fprintf(w, "\n%s took %v from:\n\t%+v",
+			fxreflect.FuncName(r.Func),
+			r.Runtime,
+			r.CallerFrame)
+	}
+	fmt.Fprintf(w, "\n")
+}
diff --git a/lifecycle.go b/lifecycle.go
index f187e22..878b8a0 100644
--- a/lifecycle.go
+++ b/lifecycle.go
@@ -50,3 +50,11 @@ func (l *lifecycleWrapper) Append(h Hook) {
 		OnStop:  h.OnStop,
 	})
 }
+
+func (l *lifecycleWrapper) hookRecords() lifecycle.HookRecords {
+	return l.HookRecords()
+}
+
+func (l *lifecycleWrapper) runningHookCaller() string {
+	return l.RunningHookCaller()
+}


Test patch:
diff --git a/app_test.go b/app_test.go
index dba8d28..85c528c 100644
--- a/app_test.go
+++ b/app_test.go
@@ -29,6 +29,7 @@ import (
 	"io/ioutil"
 	"log"
 	"os"
+	"strings"
 	"testing"
 	"time"
 
@@ -640,11 +641,101 @@ func TestAppStart(t *testing.T) {
 		)
 
 		ctx, cancel := context.WithTimeout(context.Background(), time.Millisecond)
+
+		err := app.Start(ctx)
+		require.Error(t, err)
+		assert.Contains(t, err.Error(), "OnStart hook added by go.uber.org/fx_test.TestAppStart.func1.1 failed: context deadline exceeded")
+		cancel()
+	})
+
+	t.Run("TimeoutWithFinishedHooks", func(t *testing.T) {
+		type A struct{}
+		type B struct{ A *A }
+		type C struct{ B *B }
+		newA := func(lc Lifecycle) *A {
+			lc.Append(
+				Hook{
+					OnStart: func(context.Context) error {
+						return nil
+					},
+				},
+			)
+			return &A{}
+		}
+		newB := func(lc Lifecycle, a *A) *B {
+			lc.Append(
+				Hook{
+					OnStart: func(context.Context) error {
+						time.Sleep(10 * time.Millisecond)
+						return nil
+					},
+				},
+			)
+			return &B{a}
+		}
+		newC := func(lc Lifecycle, b *B) *C {
+			lc.Append(
+				Hook{
+					OnStart: func(ctx context.Context) error {
+						<-ctx.Done()
+						return ctx.Err()
+					},
+				},
+			)
+			return &C{b}
+		}
+		app := fxtest.New(
+			t,
+			Provide(newA, newB, newC),
+			Invoke(func(*C) {}),
+		)
+
+		ctx, cancel := context.WithTimeout(context.Background(), time.Second)
 		defer cancel()
 
 		err := app.Start(ctx)
 		require.Error(t, err)
-		assert.Contains(t, err.Error(), "context deadline exceeded")
+		assert.Contains(t, err.Error(), "OnStart hook added by go.uber.org/fx_test.TestAppStart.func2.3 failed: context deadline exceeded")
+
+		// Check that hooks successfully run contain file/line numbers
+		assert.Regexp(t, "app_test.go:\\d+", err.Error())
+
+		// Check that hooks successfully run are reported in order of runtime.
+		hook1Idx := strings.Index(err.Error(), "go.uber.org/fx_test.TestAppStart.func2.1.1()")
+		hook2Idx := strings.Index(err.Error(), "go.uber.org/fx_test.TestAppStart.func2.2.1()")
+		assert.Greater(t, hook1Idx, hook2Idx)
+	})
+
+	t.Run("CtxCancelledDuringStart", func(t *testing.T) {
+		type A struct{}
+		running := make(chan struct{})
+		newA := func(lc Lifecycle) *A {
+			lc.Append(
+				Hook{
+					OnStart: func(ctx context.Context) error {
+						close(running)
+						<-ctx.Done()
+						return ctx.Err()
+					},
+				},
+			)
+			return &A{}
+		}
+		app := fxtest.New(
+			t,
+			Provide(newA),
+			Invoke(func(*A) {}),
+		)
+
+		ctx, cancel := context.WithCancel(context.Background())
+		go func() {
+			<-running
+			cancel()
+		}()
+		err := app.Start(ctx)
+		require.Error(t, err)
+		assert.NotContains(t, err.Error(), "context deadline exceeded")
+		assert.NotContains(t, err.Error(), "timed out while executing hook OnStart")
 	})
 
 	t.Run("Rollback", func(t *testing.T) {
diff --git a/internal/lifecycle/lifecycle_test.go b/internal/lifecycle/lifecycle_test.go
index 3691be8..2a91b78 100644
--- a/internal/lifecycle/lifecycle_test.go
+++ b/internal/lifecycle/lifecycle_test.go
@@ -23,11 +23,17 @@ package lifecycle
 import (
 	"context"
 	"errors"
+	"fmt"
+	"sort"
+	"strings"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 	"go.uber.org/fx/fxevent"
 	"go.uber.org/fx/internal/fxlog"
+	"go.uber.org/fx/internal/fxreflect"
 	"go.uber.org/fx/internal/testutil"
 	"go.uber.org/goleak"
 	"go.uber.org/multierr"
@@ -220,6 +226,47 @@ func TestLifecycleStop(t *testing.T) {
 	})
 }
 
+func TestHookRecordsFormat(t *testing.T) {
+	t.Run("SortRecords", func(t *testing.T) {
+		t1, err := time.ParseDuration("10ms")
+		require.NoError(t, err)
+		t2, err := time.ParseDuration("20ms")
+		require.NoError(t, err)
+
+		f := fxreflect.Frame{
+			Function: "someFunc",
+			File:     "somefunc.go",
+			Line:     1,
+		}
+
+		r := HookRecords{
+			HookRecord{
+				CallerFrame: f,
+				Func: func(context.Context) error {
+					return nil
+				},
+				Runtime: t1,
+			},
+			HookRecord{
+				CallerFrame: f,
+				Func: func(context.Context) error {
+					return nil
+				},
+				Runtime: t2,
+			},
+		}
+
+		sort.Sort(r)
+		for _, format := range []string{"%v", "%+v", "%s"} {
+			s := fmt.Sprintf(format, r)
+			hook1Idx := strings.Index(s, "TestHookRecordsFormat.func1.1()")
+			hook2Idx := strings.Index(s, "TestHookRecordsFormat.func1.2()")
+			assert.Greater(t, hook1Idx, hook2Idx, "second hook must appear first in the formatted string")
+			assert.Contains(t, s, "somefunc.go:1", "file name and line should be reported")
+		}
+	})
+}
+
 func TestMain(m *testing.M) {
 	goleak.VerifyTestMain(m)
 }