Repository: uber-go/fx (go)

Issue:
handle error formatting on `context.DeadlineExceeded` from hooks using fxevent
When the context exceeds a deadline during `OnStart`, the stack trace is added to the error passed up.
https://github.com/uber-go/fx/blob/fa108cc8a102c5a64d9a08d91d287024e9142507/app.go#L778-L788

If I understand correctly, the linked code is where this wrapping occurs, and the preferred solution is to let fxevent handle the display of the error.

We recently came across this when trying to suppress the stack trace in an error during startup https://github.com/celestiaorg/celestia-node/issues/1458. The stack trace is pretty scary for users, and doesn't appear on other startup errors that don't exceed a context deadline. 

Pull request:
Remove extraneous error logs in lifecycle deadline exceed errors
When running lifecycle hooks, it's possible they fail due to context deadline exceeded errors. Fx currently reports this error with a sorted list of all the hooks that have ran. This was added because it was difficult to debug which hook caused the context deadline error to occur.

Now that every hook that is run emits an associated fxevent ( OnStartExecuting, OnStartExecuted, OnStopExecuting, OnStartExecuted), this error wrapping is no longer necessary.

Example console output prior to this change:
```
[Fx] PROVIDE    int <= fx.Annotate(main.main.func1()
[Fx] PROVIDE    string <= fx.Annotate(main.main.func3()
[Fx] PROVIDE    fx.Lifecycle <= go.uber.org/fx.New.func1()
[Fx] PROVIDE    fx.Shutdowner <= go.uber.org/fx.(*App).shutdowner-fm()
[Fx] PROVIDE    fx.DotGraph <= go.uber.org/fx.(*App).dotGraph-fm()
[Fx] INVOKE             main.main.func5()
1
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() executing (caller: go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1)
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() called by go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 ran successfully in 15.917µs
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() executing (caller: go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1)
[Fx] ERROR              Failed to start: OnStart hook added by go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 failed: context deadline exceeded

go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 15.917µs from:
        go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/Users/sungyoon/go/pkg/mod/go.uber.org/fx@v1.18.1/annotated.go:445)

OnStart hook added by go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 failed: context deadline exceeded

go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 15.917µs from:
        go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/Users/sungyoon/go/pkg/mod/go.uber.org/fx@v1.18.1/annotated.go:445)
```

The same error after this change:
```
❯ go run main.go
[Fx] PROVIDE    int <= fx.Annotate(main.main.func1()
[Fx] PROVIDE    string <= fx.Annotate(main.main.func3()
[Fx] PROVIDE    fx.Lifecycle <= go.uber.org/fx.New.func1()
[Fx] PROVIDE    fx.Shutdowner <= go.uber.org/fx.(*App).shutdowner-fm()
[Fx] PROVIDE    fx.DotGraph <= go.uber.org/fx.(*App).dotGraph-fm()
[Fx] INVOKE             main.main.func5()
1
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1.1() executing (caller: go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1)
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1.1() called by go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1 ran successfully in 9.292µs
[Fx] HOOK OnStart               go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1.1() executing (caller: go.uber.org/fx.(*lifecycleHookAnnotation).buildHookInstaller.func1)
[Fx] ERROR              Failed to start: context deadline exceeded
context deadline exceeded
```

As shown above, the fxevent logs provide enough context for users to debug any issues from context deadline errors: hooks that were executed successfully, and hook that was attempted to execute before context was cancelled.

Fixes #999

Patch:
diff --git a/app.go b/app.go
index b0452b8..a5e2699 100644
--- a/app.go
+++ b/app.go
@@ -27,7 +27,6 @@ import (
 	"fmt"
 	"os"
 	"reflect"
-	"sort"
 	"strings"
 	"time"
 
@@ -796,33 +795,8 @@ func withTimeout(ctx context.Context, param *withTimeoutParams) error {
 			err = ctx.Err()
 		}
 	}
-	if err != context.DeadlineExceeded && err != errHookCallbackExited {
-		return err
-	}
-	// On timeout, report running hook's caller and recorded
-	// runtimes of hooks successfully run till end.
-	var r lifecycle.HookRecords
-	if param.hook == _onStartHook {
-		r = param.lifecycle.startHookRecords()
-	} else {
-		r = param.lifecycle.stopHookRecords()
-	}
-	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 {
-		sort.Sort(r)
-		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)
+
+	return err
 }
 
 // appLogger logs events to the given Fx app's "current" logger.
diff --git a/docs/modules.md b/docs/modules.md
index 71334dd..41f28e0 100644
--- a/docs/modules.md
+++ b/docs/modules.md
@@ -53,6 +53,7 @@ To write an Fx module:
      ),
      fx.Invoke(startServer),
      fx.Decorate(wrapLogger),
+
    )
    ```
 
@@ -71,6 +72,7 @@ To write an Fx module:
      ),
      fx.Invoke(startServer),
      fx.Decorate(wrapLogger),
+
    )
    ```
 
diff --git a/internal/lifecycle/lifecycle.go b/internal/lifecycle/lifecycle.go
index ce037ac..193918d 100644
--- a/internal/lifecycle/lifecycle.go
+++ b/internal/lifecycle/lifecycle.go
@@ -339,26 +339,6 @@ func (l *Lifecycle) runStopHook(ctx context.Context, hook Hook) (runtime time.Du
 	return l.clock.Since(begin), err
 }
 
-// StartHookRecords returns the info of OnStart hooks that successfully ran till the end,
-// including their caller and runtime. Used to report timeout errors on Start.
-func (l *Lifecycle) StartHookRecords() HookRecords {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	r := make(HookRecords, len(l.startRecords))
-	copy(r, l.startRecords)
-	return r
-}
-
-// StopHookRecords returns the info of OnStop hooks that successfully ran till the end,
-// including their caller and runtime. Used to report timeout errors on Stop.
-func (l *Lifecycle) StopHookRecords() HookRecords {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	r := make(HookRecords, len(l.stopRecords))
-	copy(r, l.stopRecords)
-	return r
-}
-
 // RunningHookCaller returns the name of the hook that was running when a Start/Stop
 // hook timed out.
 func (l *Lifecycle) RunningHookCaller() string {
diff --git a/lifecycle.go b/lifecycle.go
index 72492a2..5019848 100644
--- a/lifecycle.go
+++ b/lifecycle.go
@@ -145,15 +145,3 @@ func (l *lifecycleWrapper) Append(h Hook) {
 		OnStopName:  h.onStopName,
 	})
 }
-
-func (l *lifecycleWrapper) startHookRecords() lifecycle.HookRecords {
-	return l.StartHookRecords()
-}
-
-func (l *lifecycleWrapper) stopHookRecords() lifecycle.HookRecords {
-	return l.StopHookRecords()
-}
-
-func (l *lifecycleWrapper) runningHookCaller() string {
-	return l.RunningHookCaller()
-}


Test patch:
diff --git a/app_test.go b/app_test.go
index b06a0cd..df3bf8b 100644
--- a/app_test.go
+++ b/app_test.go
@@ -30,7 +30,6 @@ import (
 	"os"
 	"reflect"
 	"runtime"
-	"strings"
 	"testing"
 	"time"
 
@@ -1114,7 +1113,7 @@ func TestAppStart(t *testing.T) {
 		// remainder of the tests. As a workaround, we provide fxlog.Spy to prevent the lifecycle
 		// goroutine from writing to testing.T.
 		spy := new(fxlog.Spy)
-		app := New(
+		app := NewForTest(t,
 			WithLogger(func() fxevent.Logger { return spy }),
 			WithClock(mockClock),
 			Provide(blocker),
@@ -1125,7 +1124,7 @@ func TestAppStart(t *testing.T) {
 
 		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")
+		assert.Contains(t, "context deadline exceeded", err.Error())
 		cancel()
 	})
 
@@ -1188,15 +1187,7 @@ func TestAppStart(t *testing.T) {
 
 		err := app.Start(ctx)
 		require.Error(t, err)
-		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)
+		assert.Contains(t, "context deadline exceeded", err.Error())
 	})
 
 	t.Run("CtxCancelledDuringStart", func(t *testing.T) {
@@ -1446,7 +1437,7 @@ func TestAppStart(t *testing.T) {
 			Invoke(addHook),
 		)
 		err := app.Start(context.Background()).Error()
-		assert.Contains(t, err, "OnStart hook added by go.uber.org/fx_test.TestAppStart.func10.1 failed: goroutine exited without returning")
+		assert.Contains(t, "goroutine exited without returning", err)
 	})
 
 	t.Run("StartTwiceWithHooksErrors", func(t *testing.T) {