Remove extraneous error logs in lifecycle deadline exceed errors (#1005)

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
uber-go · Dec 27, 2022 · cb664ab · cb664ab
1 parent 0cae538
commit cb664ab
Show file tree

Hide file tree

Showing 5 changed files with 8 additions and 73 deletions.
diff --git 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/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) {

diff --git 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
@@ -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
@@ -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()
-}