Repository: uber-go/fx (go)

Issue:
app.Run doesn't log when startup times out
Due to the usage of `withTimeout`, `app.Run` doesn't log an error when the start timeout expires.

The handling of the timeout is handled outside of the `app.start` function here:
https://github.com/uber-go/fx/blob/9b7de2d2224837121de68b61b5d4ed0d1fd7bf97/app.go#L951
The `err` value is then checked here:
https://github.com/uber-go/fx/blob/9b7de2d2224837121de68b61b5d4ed0d1fd7bf97/app.go#L886
And so the program will just exit with status code 1 and not give any indication that a timeout expired.

You could either create a Timeout event in fxevent, and log that there.
Otherwise you'd have to forego the `withTimeout` function and handle it inside of functions like `app.start` and `app.stop` so the `defer` statement in those can take care of logging.

Pull request description:
fxevent: Log Started/Stopped on timeout
As reported in #782, `App.Run` had a bug so that
if an application using it failed to start up because of a timeout
no event would be logged to indicate this.
The system would silently exit with a non-zero status code.

This PR resolves this by ensuring that even for timeouts,
we log `Started` or `Stopped` events with non-nil `Err` values.
This matches the behavior for other startup or shutdown failures.

To test this, I wanted to use `App.Run` directly so
I added an internal test-only option `WithExit`
that lets us override the behavior of `os.Exit`
without a global variable. (#792)

The issue resolution was pretty straightforward:

- Start: `defer LogEvent(..)` in Start instead of
  the wrapped `start` method which runs inside a separate gorotuine.
- Stop: Apply `defer LogEvent(..)` in Stop instead of `App.Run`.
  This actually exposed a bug too: we did not previously log `Stopped`
  if `App.Stop` was called. This resulted in some test changes.

There was a small non-determinism in `withTimeout`:
What if the context times out at the same time as the callback finishing?
`select` will pick one of the `case`s randomly.
I resolved this non-determinism by checking `ctx.Err()` in the success case again.

I also moved `App.start` next to `App.Start`, and `App.run` next to `App.Run`
to aid in readability. The move is in #791.

Resolves #782
Resolves GO-866


Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 7973713..d2b0b89 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -5,7 +5,10 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
 ## Unreleased
--  No changes yet.
+### Fixed
+- Fix `fxevent.Stopped` not being logged when `App.Stop` is called.
+- Fix `fxevent.Started` or `fxevent.Stopped` not being logged when start or
+  stop times out.
 
 ## [1.14.2] - 2021-08-16
 ### Changed
diff --git a/app.go b/app.go
index 2680e36..ad5a892 100644
--- a/app.go
+++ b/app.go
@@ -676,18 +676,17 @@ func (app *App) run(done <-chan os.Signal) (exitCode int) {
 	if err := app.Start(startCtx); err != nil {
 		return 1
 	}
+
 	sig := <-done
 	app.log.LogEvent(&fxevent.Stopping{Signal: sig})
 
 	stopCtx, cancel := context.WithTimeout(context.Background(), app.StopTimeout())
 	defer cancel()
 
-	err := app.Stop(stopCtx)
-	app.log.LogEvent(&fxevent.Stopped{Err: err})
-
-	if err != nil {
+	if err := app.Stop(stopCtx); err != nil {
 		return 1
 	}
+
 	return 0
 }
 
@@ -724,16 +723,7 @@ var (
 //
 // 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, &withTimeoutParams{
-		hook:      _onStartHook,
-		callback:  app.start,
-		lifecycle: app.lifecycle,
-		log:       app.log,
-	})
-}
-
-func (app *App) start(ctx context.Context) (err error) {
+func (app *App) Start(ctx context.Context) (err error) {
 	defer func() {
 		app.log.LogEvent(&fxevent.Started{Err: err})
 	}()
@@ -743,7 +733,15 @@ func (app *App) start(ctx context.Context) (err error) {
 		return app.err
 	}
 
-	// Attempt to start cleanly.
+	return withTimeout(ctx, &withTimeoutParams{
+		hook:      _onStartHook,
+		callback:  app.start,
+		lifecycle: app.lifecycle,
+		log:       app.log,
+	})
+}
+
+func (app *App) start(ctx context.Context) error {
 	if err := app.lifecycle.Start(ctx); err != nil {
 		// Start failed, rolling back.
 		app.log.LogEvent(&fxevent.RollingBack{StartErr: err})
@@ -757,7 +755,6 @@ func (app *App) start(ctx context.Context) (err error) {
 
 		return err
 	}
-
 	return nil
 }
 
@@ -768,7 +765,11 @@ func (app *App) start(ctx context.Context) (err error) {
 // If the application didn't start cleanly, only hooks whose OnStart phase was
 // called are executed. However, all those hooks are executed, even if some
 // fail.
-func (app *App) Stop(ctx context.Context) error {
+func (app *App) Stop(ctx context.Context) (err error) {
+	defer func() {
+		app.log.LogEvent(&fxevent.Stopped{Err: err})
+	}()
+
 	return withTimeout(ctx, &withTimeoutParams{
 		hook:      _onStopHook,
 		callback:  app.lifecycle.Stop,
@@ -957,6 +958,12 @@ func withTimeout(ctx context.Context, param *withTimeoutParams) error {
 	case <-ctx.Done():
 		err = ctx.Err()
 	case err = <-c:
+		// If the context finished at the same time as the callback
+		// prefer the context error.
+		// This eliminates non-determinism in select-case selection.
+		if ctx.Err() != nil {
+			err = ctx.Err()
+		}
 	}
 	if err != context.DeadlineExceeded {
 		return err


Test patch:
diff --git a/app_test.go b/app_test.go
index 393970c..00280f2 100644
--- a/app_test.go
+++ b/app_test.go
@@ -29,6 +29,7 @@ import (
 	"io/ioutil"
 	"log"
 	"os"
+	"reflect"
 	"strings"
 	"testing"
 	"time"
@@ -382,7 +383,7 @@ func TestWithLogger(t *testing.T) {
 
 		require.NoError(t, app.Err())
 
-		assert.Equal(t, []string{"Started"}, spy.EventTypes())
+		assert.Equal(t, []string{"Started", "Stopped"}, spy.EventTypes())
 	})
 
 	t.Run("error in Provide shows logs", func(t *testing.T) {
@@ -719,6 +720,126 @@ func TestTimeoutOptions(t *testing.T) {
 	assert.True(t, stopped, "app wasn't stopped")
 }
 
+func TestAppRunTimeout(t *testing.T) {
+	t.Parallel()
+
+	// This context is only valid as long as this test is running.
+	// It lets us have goroutines that block forever
+	// (as far as the test is concerned) without leaking them.
+	testCtx, cancel := context.WithCancel(context.Background())
+	t.Cleanup(cancel)
+
+	// Fails with an error immediately.
+	failure := func(context.Context) error {
+		return errors.New("great sadness")
+	}
+
+	// Blocks forever--or at least until this test finishes running.
+	blockForever := func(context.Context) error {
+		<-testCtx.Done()
+		return errors.New("user should not see this")
+	}
+
+	tests := []struct {
+		desc  string
+		hooks []Hook
+
+		// Type of the fxevent we want.
+		// Does not reflect the exact value.
+		wantEventType fxevent.Event
+	}{
+		{
+			// Timeout starting an application.
+			desc: "OnStart timeout",
+			hooks: []Hook{
+				{OnStart: blockForever},
+			},
+			wantEventType: &fxevent.Started{},
+		},
+		{
+			// Timeout during a rollback because start failed.
+			desc: "rollback timeout",
+			hooks: []Hook{
+				// The hooks are separate because
+				// OnStop will not be run if that hook failed.
+				{OnStop: blockForever},
+				{OnStart: failure},
+			},
+			wantEventType: &fxevent.Started{},
+		},
+		{
+			// Timeout during a stop.
+			desc: "OnStop timeout",
+			hooks: []Hook{
+				{OnStop: blockForever},
+			},
+			wantEventType: &fxevent.Stopped{},
+		},
+	}
+
+	for _, tt := range tests {
+		tt := tt
+		t.Run(tt.desc, func(t *testing.T) {
+			t.Parallel()
+
+			var (
+				exitCode int
+				exited   bool
+			)
+			exit := func(code int) {
+				exited = true
+				exitCode = code
+			}
+			defer func() {
+				assert.True(t, exited,
+					"os.Exit must be called")
+			}()
+
+			// If the OnStart hook for this is invoked,
+			// it means that the Start did not fail.
+			// In that case, shut down immediately
+			// rather than block forever.
+			shutdown := func(sd Shutdowner, lc Lifecycle) {
+				lc.Append(Hook{
+					OnStart: func(context.Context) error {
+						return sd.Shutdown()
+					},
+				})
+			}
+
+			app, spy := NewSpied(
+				StartTimeout(time.Millisecond),
+				StopTimeout(time.Millisecond),
+				WithExit(exit),
+				Invoke(func(lc Lifecycle) {
+					for _, h := range tt.hooks {
+						lc.Append(h)
+					}
+				}),
+				Invoke(shutdown),
+			)
+
+			app.Run()
+			assert.NotZero(t, exitCode,
+				"exit code mismatch")
+
+			eventType := reflect.TypeOf(tt.wantEventType).Elem().Name()
+			matchingEvents := spy.Events().SelectByTypeName(eventType)
+			require.Len(t, matchingEvents, 1,
+				"expected a %q event", eventType)
+
+			event := matchingEvents[0]
+			errv := reflect.ValueOf(event).Elem().FieldByName("Err")
+			require.True(t, errv.IsValid(),
+				"event %q does not have an Err attribute", eventType)
+
+			err, _ := errv.Interface().(error)
+			assert.ErrorIs(t, err, context.DeadlineExceeded,
+				"should fail because of a timeout")
+		})
+	}
+}
+
 func TestAppStart(t *testing.T) {
 	t.Parallel()
 
@@ -1215,7 +1336,14 @@ func TestReplaceLogger(t *testing.T) {
 	spy := new(fxlog.Spy)
 	app := fxtest.New(t, WithLogger(func() fxevent.Logger { return spy }))
 	app.RequireStart().RequireStop()
-	assert.Equal(t, []string{"Provided", "Provided", "Provided", "LoggerInitialized", "Started"}, spy.EventTypes())
+	assert.Equal(t, []string{
+		"Provided",
+		"Provided",
+		"Provided",
+		"LoggerInitialized",
+		"Started",
+		"Stopped",
+	}, spy.EventTypes())
 }
 
 func TestNopLogger(t *testing.T) {
@@ -1294,6 +1422,7 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
 		"OnStartExecuting", "OnStartExecuted",
 		"Started",
 		"OnStopExecuting", "OnStopExecuted",
+		"Stopped",
 	}, spy.EventTypes())
 }