Repository: uber-go/fx
Pull request #688 (2019-11-16 01:08:44)

Error reporting: Include Provide/Invoke stack traces
A number of errors we report during start up are fairly opaque because
they only reference the target function, not where the bad invocation
was made.

This is extra problematic if the target function was generated via
reflection. For example, @klnusbaum reported the following error which
was impossible to debug with just Fx.

    fx.Option should be passed to fx.New directly, not to fx.Provide:
    fx.Provide received fx.Provide(reflect.makeFuncStub())

To help debug issues like this, this PR changes Fx to capture a call
stack whenever `fx.Provide` or `fx.Invoke` are called. These stack
traces are later reported in the error messages for various errors
thrown during program startup.

With this change, the error above becomes similar to the following.

    fx.Option should be passed to fx.New directly, not to fx.Provide:
    fx.Provide received fx.Provide(reflect.makeFuncStub()) from:
    path/to/my/module.init
            /.../my/module.go:50
    path/to/your/app.main
            /.../your/app/main.go:42

Depends on #687
Ref T4487249

---

**Each commit should be reviewed separately.**

codecov[bot]: # [Codecov](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=h1) Report
> Merging [#688](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=desc) into [abg/option-stacks](https://codecov.io/gh/uber-go/fx/commit/ca345645b13c943cef337563dc6ebf565674baa3?src=pr&el=desc) will **increase** coverage by `0.14%`.
> The diff coverage is `100%`.

[![Impacted file tree graph](https://codecov.io/gh/uber-go/fx/pull/688/graphs/tree.svg?width=650&token=PYY9PSfaC6&height=150&src=pr)](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=tree)

```diff
@@                  Coverage Diff                  @@
##           abg/option-stacks     #688      +/-   ##
=====================================================
+ Coverage              97.92%   98.06%   +0.14%     
=====================================================
  Files                     13       14       +1     
  Lines                    481      516      +35     
=====================================================
+ Hits                     471      506      +35     
  Misses                     8        8              
  Partials                   2        2
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [annotated.go](https://codecov.io/gh/uber-go/fx/pull/688/diff?src=pr&el=tree#diff-YW5ub3RhdGVkLmdv) | `100% <100%> (ø)` | |
| [app.go](https://codecov.io/gh/uber-go/fx/pull/688/diff?src=pr&el=tree#diff-YXBwLmdv) | `97.33% <100%> (+0.34%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=footer). Last update [ca34564...fbb830b](https://codecov.io/gh/uber-go/fx/pull/688?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/annotated.go b/annotated.go
index 69e04cd..c0c4775 100644
--- a/annotated.go
+++ b/annotated.go
@@ -20,6 +20,13 @@
 
 package fx
 
+import (
+	"fmt"
+	"strings"
+
+	"go.uber.org/fx/internal/fxreflect"
+)
+
 // Annotated annotates a constructor provided to Fx with additional options.
 //
 // For example,
@@ -62,3 +69,17 @@ type Annotated struct {
 	// Target is the constructor being annotated with fx.Annotated.
 	Target interface{}
 }
+
+func (a Annotated) String() string {
+	var fields []string
+	if len(a.Name) > 0 {
+		fields = append(fields, fmt.Sprintf("Name: %q", a.Name))
+	}
+	if len(a.Group) > 0 {
+		fields = append(fields, fmt.Sprintf("Group: %q", a.Group))
+	}
+	if a.Target != nil {
+		fields = append(fields, fmt.Sprintf("Target: %v", fxreflect.FuncName(a.Target)))
+	}
+	return fmt.Sprintf("fx.Annotated{%v}", strings.Join(fields, ", "))
+}
diff --git a/app.go b/app.go
index 020104b..4d6dbb8 100644
--- a/app.go
+++ b/app.go
@@ -85,18 +85,29 @@ type Option interface {
 // loops, background timer loops, and background processing goroutines should
 // instead be managed using Lifecycle callbacks.
 func Provide(constructors ...interface{}) Option {
-	return provideOption(constructors)
+	return provideOption{
+		Targets: constructors,
+		Stack:   fxreflect.CallerStack(1, 0),
+	}
 }
 
-type provideOption []interface{}
+type provideOption struct {
+	Targets []interface{}
+	Stack   fxreflect.Stack
+}
 
-func (po provideOption) apply(app *App) {
-	app.provides = append(app.provides, po...)
+func (o provideOption) apply(app *App) {
+	for _, target := range o.Targets {
+		app.provides = append(app.provides, provide{
+			Target: target,
+			Stack:  o.Stack,
+		})
+	}
 }
 
-func (po provideOption) String() string {
-	items := make([]string, len(po))
-	for i, c := range po {
+func (o provideOption) String() string {
+	items := make([]string, len(o.Targets))
+	for i, c := range o.Targets {
 		items[i] = fxreflect.FuncName(c)
 	}
 	return fmt.Sprintf("fx.Provide(%s)", strings.Join(items, ", "))
@@ -121,18 +132,29 @@ func (po provideOption) String() string {
 // advanced features, including optional parameters and named instances, see
 // the documentation of the In and Out types.
 func Invoke(funcs ...interface{}) Option {
-	return invokeOption(funcs)
+	return invokeOption{
+		Targets: funcs,
+		Stack:   fxreflect.CallerStack(1, 0),
+	}
 }
 
-type invokeOption []interface{}
+type invokeOption struct {
+	Targets []interface{}
+	Stack   fxreflect.Stack
+}
 
-func (io invokeOption) apply(app *App) {
-	app.invokes = append(app.invokes, io...)
+func (o invokeOption) apply(app *App) {
+	for _, target := range o.Targets {
+		app.invokes = append(app.invokes, invoke{
+			Target: target,
+			Stack:  o.Stack,
+		})
+	}
 }
 
-func (io invokeOption) String() string {
-	items := make([]string, len(io))
-	for i, f := range io {
+func (o invokeOption) String() string {
+	items := make([]string, len(o.Targets))
+	for i, f := range o.Targets {
 		items[i] = fxreflect.FuncName(f)
 	}
 	return fmt.Sprintf("fx.Invoke(%s)", strings.Join(items, ", "))
@@ -311,8 +333,8 @@ type App struct {
 	err          error
 	container    *dig.Container
 	lifecycle    *lifecycleWrapper
-	provides     []interface{}
-	invokes      []interface{}
+	provides     []provide
+	invokes      []invoke
 	logger       *fxlog.Logger
 	startTimeout time.Duration
 	stopTimeout  time.Duration
@@ -322,6 +344,24 @@ type App struct {
 	dones   []chan os.Signal
 }
 
+// provide is a single constructor provided to Fx.
+type provide struct {
+	// Constructor provided to Fx. This may be an fx.Annotated.
+	Target interface{}
+
+	// Stack trace of where this provide was made.
+	Stack fxreflect.Stack
+}
+
+// invoke is a single invocation request to Fx.
+type invoke struct {
+	// Function to invoke.
+	Target interface{}
+
+	// Stack trace of where this invoke was made.
+	Stack fxreflect.Stack
+}
+
 // ErrorHandler handles Fx application startup errors.
 type ErrorHandler interface {
 	HandleError(error)
@@ -378,9 +418,14 @@ func New(opts ...Option) *App {
 	for _, p := range app.provides {
 		app.provide(p)
 	}
-	app.provide(func() Lifecycle { return app.lifecycle })
-	app.provide(app.shutdowner)
-	app.provide(app.dotGraph)
+
+	frames := fxreflect.CallerStack(0, 0) // include New in the stack for default Provides
+	app.provide(provide{
+		Target: func() Lifecycle { return app.lifecycle },
+		Stack:  frames,
+	})
+	app.provide(provide{Target: app.shutdowner, Stack: frames})
+	app.provide(provide{Target: app.dotGraph, Stack: frames})
 
 	if app.err != nil {
 		app.logger.Printf("Error after options were applied: %v", app.err)
@@ -528,32 +573,37 @@ func (app *App) dotGraph() (DotGraph, error) {
 	return DotGraph(b.String()), err
 }
 
-func (app *App) provide(constructor interface{}) {
+func (app *App) provide(p provide) {
+	constructor := p.Target
 	if app.err != nil {
 		return
 	}
 	app.logger.PrintProvide(constructor)
 
 	if _, ok := constructor.(Option); ok {
-		app.err = fmt.Errorf("fx.Option should be passed to fx.New directly, not to fx.Provide: fx.Provide received %v", constructor)
+		app.err = fmt.Errorf("fx.Option should be passed to fx.New directly, "+
+			"not to fx.Provide: fx.Provide received %v from:\n%+v",
+			constructor, p.Stack)
 		return
 	}
 
-	if a, ok := constructor.(Annotated); ok {
+	if ann, ok := constructor.(Annotated); ok {
 		var opts []dig.ProvideOption
 		switch {
-		case len(a.Group) > 0 && len(a.Name) > 0:
-			app.err = fmt.Errorf("fx.Annotate may not specify both name and group for %v", constructor)
+		case len(ann.Group) > 0 && len(ann.Name) > 0:
+			app.err = fmt.Errorf(
+				"fx.Annotated may specify only one of Name or Group: received %v from:\n%+v",
+				ann, p.Stack)
 			return
-		case len(a.Name) > 0:
-			opts = append(opts, dig.Name(a.Name))
-		case len(a.Group) > 0:
-			opts = append(opts, dig.Group(a.Group))
+		case len(ann.Name) > 0:
+			opts = append(opts, dig.Name(ann.Name))
+		case len(ann.Group) > 0:
+			opts = append(opts, dig.Group(ann.Group))
 
 		}
 
-		if err := app.container.Provide(a.Target, opts...); err != nil {
-			app.err = err
+		if err := app.container.Provide(ann.Target, opts...); err != nil {
+			app.err = fmt.Errorf("fx.Provide(%v) from:\n%+vFailed: %v", ann, p.Stack, err)
 		}
 		return
 	}
@@ -565,14 +615,18 @@ func (app *App) provide(constructor interface{}) {
 			t := ft.Out(i)
 
 			if t == reflect.TypeOf(Annotated{}) {
-				app.err = fmt.Errorf("fx.Annotated should be passed to fx.Provide directly, it should not be returned by the constructor: fx.Provide received %v", constructor)
+				app.err = fmt.Errorf(
+					"fx.Annotated should be passed to fx.Provide directly, "+
+						"it should not be returned by the constructor: "+
+						"fx.Provide received %v from:\n%+v",
+					fxreflect.FuncName(constructor), p.Stack)
 				return
 			}
 		}
 	}
 
 	if err := app.container.Provide(constructor); err != nil {
-		app.err = err
+		app.err = fmt.Errorf("fx.Provide(%v) from:\n%+vFailed: %v", fxreflect.FuncName(constructor), p.Stack, err)
 	}
 }
 
@@ -580,25 +634,28 @@ func (app *App) provide(constructor interface{}) {
 // encountered.
 func (app *App) executeInvokes() error {
 	// TODO: consider taking a context to limit the time spent running invocations.
-	var err error
 
-	for _, fn := range app.invokes {
+	for _, i := range app.invokes {
+		fn := i.Target
 		fname := fxreflect.FuncName(fn)
 		app.logger.Printf("INVOKE\t\t%s", fname)
 
+		var err error
 		if _, ok := fn.(Option); ok {
-			err = fmt.Errorf("fx.Option should be passed to fx.New directly, not to fx.Invoke: fx.Invoke received %v", fn)
+			err = fmt.Errorf("fx.Option should be passed to fx.New directly, "+
+				"not to fx.Invoke: fx.Invoke received %v from:\n%+v",
+				fn, i.Stack)
 		} else {
 			err = app.container.Invoke(fn)
 		}
 
 		if err != nil {
-			app.logger.Printf("Error during %q invoke: %v", fname, err)
-			break
+			app.logger.Printf("fx.Invoke(%v) called from:\n%+vFailed: %v", fname, i.Stack, err)
+			return err
 		}
 	}
 
-	return err
+	return nil
 }
 
 func (app *App) run(done <-chan os.Signal) {


Test patch:
diff --git a/annotated_test.go b/annotated_test.go
index 65e1751..8e9197e 100644
--- a/annotated_test.go
+++ b/annotated_test.go
@@ -24,6 +24,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 	"go.uber.org/fx"
 	"go.uber.org/fx/fxtest"
 )
@@ -83,7 +84,20 @@ func TestAnnotatedWrongUsage(t *testing.T) {
 			),
 			fx.Populate(&in),
 		)
-		assert.Contains(t, app.Err().Error(), "fx.Annotated should be passed to fx.Provide directly", "expected error when return types were annotated")
+
+		err := app.Err()
+		require.Error(t, err)
+
+		// Example:
+		// fx.Annotated should be passed to fx.Provide directly, it should not be returned by the constructor: fx.Provide received go.uber.org/fx_test.TestAnnotatedWrongUsage.func2.1() from:
+		// go.uber.org/fx_test.TestAnnotatedWrongUsage.func2
+		//         /.../fx/annotated_test.go:76
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
+		assert.Contains(t, err.Error(), "fx.Annotated should be passed to fx.Provide directly, it should not be returned by the constructor")
+		assert.Contains(t, err.Error(), "fx.Provide received go.uber.org/fx_test.TestAnnotatedWrongUsage")
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestAnnotatedWrongUsage")
+		assert.Contains(t, err.Error(), "/fx/annotated_test.go")
 	})
 
 	t.Run("Result Type", func(t *testing.T) {
@@ -100,3 +114,58 @@ func TestAnnotatedWrongUsage(t *testing.T) {
 		assert.Contains(t, app.Err().Error(), "embeds a dig.In", "expected error when result types were annotated")
 	})
 }
+
+func TestAnnotatedString(t *testing.T) {
+	tests := []struct {
+		desc string
+		give fx.Annotated
+		want string
+	}{
+		{
+			desc: "empty",
+			give: fx.Annotated{},
+			want: "fx.Annotated{}",
+		},
+		{
+			desc: "name",
+			give: fx.Annotated{Name: "foo"},
+			want: `fx.Annotated{Name: "foo"}`,
+		},
+		{
+			desc: "group",
+			give: fx.Annotated{Group: "foo"},
+			want: `fx.Annotated{Group: "foo"}`,
+		},
+		{
+			desc: "name and group",
+			give: fx.Annotated{Name: "foo", Group: "bar"},
+			want: `fx.Annotated{Name: "foo", Group: "bar"}`,
+		},
+		{
+			desc: "target",
+			give: fx.Annotated{Target: func() {}},
+			want: "fx.Annotated{Target: go.uber.org/fx_test.TestAnnotatedString.func1()}",
+		},
+		{
+			desc: "name and target",
+			give: fx.Annotated{Name: "foo", Target: func() {}},
+			want: `fx.Annotated{Name: "foo", Target: go.uber.org/fx_test.TestAnnotatedString.func2()}`,
+		},
+		{
+			desc: "group and target",
+			give: fx.Annotated{Group: "foo", Target: func() {}},
+			want: `fx.Annotated{Group: "foo", Target: go.uber.org/fx_test.TestAnnotatedString.func3()}`,
+		},
+		{
+			desc: "name, group and target",
+			give: fx.Annotated{Name: "foo", Group: "bar", Target: func() {}},
+			want: `fx.Annotated{Name: "foo", Group: "bar", Target: go.uber.org/fx_test.TestAnnotatedString.func4()}`,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.desc, func(t *testing.T) {
+			assert.Equal(t, tt.want, tt.give.String())
+		})
+	}
+}
diff --git a/app_test.go b/app_test.go
index 7f9edd0..665ce07 100644
--- a/app_test.go
+++ b/app_test.go
@@ -190,6 +190,55 @@ func TestNewApp(t *testing.T) {
 
 		err := app.Err()
 		require.Error(t, err)
+
+		// fx.Annotated may specify only one of Name or Group: received fx.Annotated{Name: "foo", Group: "bar", Target: go.uber.org/fx_test.TestAnnotatedWithGroupAndName.func1()} from:
+		// go.uber.org/fx_test.TestAnnotatedWithGroupAndName
+		//         /.../fx/annotated_test.go:164
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
+		assert.Contains(t, err.Error(), "fx.Annotated may specify only one of Name or Group:")
+		assert.Contains(t, err.Error(), `received fx.Annotated{Name: "foo", Group: "bar", Target: go.uber.org/fx_test.TestNewApp`)
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestNewApp")
+		assert.Contains(t, err.Error(), "fx/app_test.go")
+	})
+
+	t.Run("ErrorProvidingAnnotated", func(t *testing.T) {
+		app := NewForTest(t, Provide(Annotated{
+			Target: 42, // not a constructor
+			Name:   "foo",
+		}))
+
+		err := app.Err()
+		require.Error(t, err)
+
+		// Example:
+		// fx.Provide(fx.Annotated{...}) from:
+		//     go.uber.org/fx_test.TestNewApp.func8
+		//         /.../fx/app_test.go:206
+		//     testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
+		//     Failed: must provide constructor function, got 42 (type int)
+		assert.Contains(t, err.Error(), `fx.Provide(fx.Annotated{Name: "foo", Target: 42}) from:`)
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestNewApp")
+		assert.Contains(t, err.Error(), "fx/app_test.go")
+		assert.Contains(t, err.Error(), "Failed: must provide constructor function")
+	})
+
+	t.Run("ErrorProviding", func(t *testing.T) {
+		err := NewForTest(t, Provide(42)).Err()
+		require.Error(t, err)
+
+		// Example:
+		// fx.Provide(..) from:
+		//     go.uber.org/fx_test.TestNewApp.func8
+		//         /.../fx/app_test.go:206
+		//     testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
+		//     Failed: must provide constructor function, got 42 (type int)
+		assert.Contains(t, err.Error(), "fx.Provide(42) from:")
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestNewApp")
+		assert.Contains(t, err.Error(), "fx/app_test.go")
+		assert.Contains(t, err.Error(), "Failed: must provide constructor function")
 	})
 }
 
@@ -471,10 +520,25 @@ func TestAppStart(t *testing.T) {
 	})
 
 	t.Run("InvokeNonFunction", func(t *testing.T) {
-		app := NewForTest(t, Invoke(struct{}{}))
+		spy := printerSpy{&bytes.Buffer{}}
+
+		app := New(Logger(spy), Invoke(struct{}{}))
 		err := app.Err()
 		require.Error(t, err, "expected start failure")
 		assert.Contains(t, err.Error(), "can't invoke non-function")
+
+		// Example
+		// fx.Invoke({}) called from:
+		// go.uber.org/fx_test.TestAppStart.func4
+		//         /.../fx/app_test.go:525
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
+		// Failed: can't invoke non-function {} (type struct {})
+		output := spy.String()
+		assert.Contains(t, output, "fx.Invoke({}) called from:")
+		assert.Contains(t, output, "go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, output, "fx/app_test.go")
+		assert.Contains(t, output, "Failed: can't invoke non-function")
 	})
 
 	t.Run("ProvidingAProvideShouldFail", func(t *testing.T) {
@@ -494,8 +558,17 @@ func TestAppStart(t *testing.T) {
 
 		err := app.Err()
 		require.Error(t, err, "expected start failure")
+
+		// Example:
+		// fx.Option should be passed to fx.New directly, not to fx.Provide: fx.Provide received fx.Provide(go.uber.org/fx_test.TestAppStart.func5.2(), go.uber.org/fx_test.TestAppStart.func5.3()) from:
+		// go.uber.org/fx_test.TestAppStart.func5
+		//         /.../fx/app_test.go:550
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
 		assert.Contains(t, err.Error(), "fx.Option should be passed to fx.New directly, not to fx.Provide")
 		assert.Contains(t, err.Error(), "fx.Provide received fx.Provide(go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "fx/app_test.go")
 	})
 
 	t.Run("InvokingAnInvokeShouldFail", func(t *testing.T) {
@@ -513,8 +586,16 @@ func TestAppStart(t *testing.T) {
 		require.Error(t, err, "expected start failure")
 		assert.Equal(t, err, newErr, "start should return the same error fx.New encountered")
 
+		// Example
+		// fx.Option should be passed to fx.New directly, not to fx.Invoke: fx.Invoke received fx.Invoke(go.uber.org/fx_test.TestAppStart.func6.2()) from:
+		// go.uber.org/fx_test.TestAppStart.func6
+		//         /.../fx/app_test.go:579
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
 		assert.Contains(t, err.Error(), "fx.Option should be passed to fx.New directly, not to fx.Invoke")
 		assert.Contains(t, err.Error(), "fx.Invoke received fx.Invoke(go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "/fx/app_test.go")
 	})
 
 	t.Run("ProvidingOptionsShouldFail", func(t *testing.T) {
@@ -540,8 +621,17 @@ func TestAppStart(t *testing.T) {
 		)
 		err := app.Err()
 		require.Error(t, err, "expected start failure")
+
+		// Example:
+		// fx.Annotated should be passed to fx.Provide directly, it should not be returned by the constructor: fx.Provide received go.uber.org/fx_test.TestAnnotatedWrongUsage.func2.1() from:
+		// go.uber.org/fx_test.TestAnnotatedWrongUsage.func2
+		//         /.../fx/annotated_test.go:76
+		// testing.tRunner
+		//         /.../go/1.13.3/libexec/src/testing/testing.go:909
 		assert.Contains(t, err.Error(), "fx.Option should be passed to fx.New directly, not to fx.Provide")
 		assert.Contains(t, err.Error(), "fx.Provide received fx.Options(fx.Provide(go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "go.uber.org/fx_test.TestAppStart")
+		assert.Contains(t, err.Error(), "fx/app_test.go")
 	})
 }