From cb664ab48292cdeed25af7ad3d98afcc29719ca1 Mon Sep 17 00:00:00 2001 From: Sung Yoon Whang Date: Tue, 27 Dec 2022 14:52:09 -0800 Subject: [PATCH] Remove extraneous error logs in lifecycle deadline exceed errors (#1005) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- app.go | 30 ++---------------------------- app_test.go | 17 ++++------------- docs/modules.md | 2 ++ internal/lifecycle/lifecycle.go | 20 -------------------- lifecycle.go | 12 ------------ 5 files changed, 8 insertions(+), 73 deletions(-) diff --git a/app.go b/app.go index b0452b8f4..a5e269908 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/app_test.go b/app_test.go index b06a0cd60..df3bf8bcd 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) { diff --git a/docs/modules.md b/docs/modules.md index 71334dd15..41f28e045 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 ce037ac29..193918de7 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 72492a2a7..50198488e 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() -}