Repository: uber-go/fx
Pull request #870 (2022-04-01 19:26:58)

fxevent/ConsoleLogger: Use %+v for all errors
Many of the errors produced by dig format differently based on whether
you use "%v" or "%+v" with them, with "%+v" being a more readable
multi-line version.

The same is true for errors combined with multierr: "%v" produces a
;-separated list, and "%+v" produces a multi-line list of error
messages.

By using "%v" in all errors, Fx's console logger output is not super
readable. This change switches to "%+v" for all such errors so that
richer variants are printed if available.

Before this change, a bare Fx service with our internal framework would
fail with:

```
[Fx] ERROR              Failed to start: could not build arguments for function "go.uber.org/fx".(*App).constructCustomLogger.func2 ([..]/go.uber.org/fx/app.go:415): failed to build fxevent.Logger: could not build arguments for function "example.com/go/zapfx.git".glob..func2 ([..]/zapfx.git/zapfx.go:63): failed to build *zap.Logger: could not build arguments for function "example.com/go/zapfx.git".New ([..]/zapfx.git/zapfx.go:156): failed to build servicefx.Metadata: could not build arguments for function "example.com/go/servicefx.git".New ([..]/servicefx.git/servicefx.go:51): failed to build config.Provider: received non-nil error from function "example.com/go/configfx.git".New ([..]/configfx.git/configfx.go:53): no configuration files found, checked files [config/foo.yaml config/bar.yaml]
```

With this change, it fails with the following:

```
[Fx] ERROR              Failed to start: could not build arguments for function "go.uber.org/fx".(*App).constructCustomLogger.func2
        [..]/go.uber.org/fx/app.go:415:
failed to build fxevent.Logger:
could not build arguments for function "example.com/go/zapfx.git".glob..func2
        [..]/zapfx.git/zapfx.go:63:
failed to build *zap.Logger:
could not build arguments for function "example.com/go/zapfx.git".New
        [..]/zapfx.git/zapfx.go:156:
failed to build servicefx.Metadata:
could not build arguments for function "example.com/go/servicefx.git".New
        [..]/servicefx.git/servicefx.go:51:
failed to build config.Provider:
received non-nil error from function "example.com/go/configfx.git".New
        [..]/configfx.git/configfx.go:53:
no configuration files found, checked files [config/foo.yaml config/bar.yaml]
```


codecov[bot]: # [Codecov](https://codecov.io/gh/uber-go/fx/pull/870?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) Report
> Merging [#870](https://codecov.io/gh/uber-go/fx/pull/870?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (f54032b) into [master](https://codecov.io/gh/uber-go/fx/commit/30d87eee6413b99a00dfdcef36a3f416acae26e9?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (30d87ee) will **not change** coverage.
> The diff coverage is `100.00%`.

```diff
@@           Coverage Diff           @@
##           master     #870   +/-   ##
=======================================
  Coverage   98.49%   98.49%           
=======================================
  Files          30       30           
  Lines        1130     1130           
=======================================
  Hits         1113     1113           
  Misses         11       11           
  Partials        6        6           
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/870?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) | Coverage Δ | |
|---|---|---|
| [fxevent/console.go](https://codecov.io/gh/uber-go/fx/pull/870/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC9jb25zb2xlLmdv) | `100.00% <100.00%> (ø)` | |

------

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


Patch:
diff --git a/fxevent/console.go b/fxevent/console.go
index b42a419..b22ff1a 100644
--- a/fxevent/console.go
+++ b/fxevent/console.go
@@ -47,7 +47,7 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		l.logf("HOOK OnStart\t\t%s executing (caller: %s)", e.FunctionName, e.CallerName)
 	case *OnStartExecuted:
 		if e.Err != nil {
-			l.logf("HOOK OnStart\t\t%s called by %s failed in %s: %v", e.FunctionName, e.CallerName, e.Runtime, e.Err)
+			l.logf("HOOK OnStart\t\t%s called by %s failed in %s: %+v", e.FunctionName, e.CallerName, e.Runtime, e.Err)
 		} else {
 			l.logf("HOOK OnStart\t\t%s called by %s ran successfully in %s", e.FunctionName, e.CallerName, e.Runtime)
 		}
@@ -55,13 +55,13 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		l.logf("HOOK OnStop\t\t%s executing (caller: %s)", e.FunctionName, e.CallerName)
 	case *OnStopExecuted:
 		if e.Err != nil {
-			l.logf("HOOK OnStop\t\t%s called by %s failed in %s: %v", e.FunctionName, e.CallerName, e.Runtime, e.Err)
+			l.logf("HOOK OnStop\t\t%s called by %s failed in %s: %+v", e.FunctionName, e.CallerName, e.Runtime, e.Err)
 		} else {
 			l.logf("HOOK OnStop\t\t%s called by %s ran successfully in %s", e.FunctionName, e.CallerName, e.Runtime)
 		}
 	case *Supplied:
 		if e.Err != nil {
-			l.logf("ERROR\tFailed to supply %v: %v", e.TypeName, e.Err)
+			l.logf("ERROR\tFailed to supply %v: %+v", e.TypeName, e.Err)
 		} else if e.ModuleName != "" {
 			l.logf("SUPPLY\t%v from module %q", e.TypeName, e.ModuleName)
 		} else {
@@ -76,7 +76,7 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 			}
 		}
 		if e.Err != nil {
-			l.logf("Error after options were applied: %v", e.Err)
+			l.logf("Error after options were applied: %+v", e.Err)
 		}
 
 	case *Replaced:
@@ -99,7 +99,7 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 			}
 		}
 		if e.Err != nil {
-			l.logf("Error after options were applied: %v", e.Err)
+			l.logf("Error after options were applied: %+v", e.Err)
 		}
 	case *Invoking:
 		if e.ModuleName != "" {
@@ -109,23 +109,23 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		}
 	case *Invoked:
 		if e.Err != nil {
-			l.logf("ERROR\t\tfx.Invoke(%v) called from:\n%+vFailed: %v", e.FunctionName, e.Trace, e.Err)
+			l.logf("ERROR\t\tfx.Invoke(%v) called from:\n%+vFailed: %+v", e.FunctionName, e.Trace, e.Err)
 		}
 	case *Stopping:
 		l.logf("%v", strings.ToUpper(e.Signal.String()))
 	case *Stopped:
 		if e.Err != nil {
-			l.logf("ERROR\t\tFailed to stop cleanly: %v", e.Err)
+			l.logf("ERROR\t\tFailed to stop cleanly: %+v", e.Err)
 		}
 	case *RollingBack:
-		l.logf("ERROR\t\tStart failed, rolling back: %v", e.StartErr)
+		l.logf("ERROR\t\tStart failed, rolling back: %+v", e.StartErr)
 	case *RolledBack:
 		if e.Err != nil {
-			l.logf("ERROR\t\tCouldn't roll back cleanly: %v", e.Err)
+			l.logf("ERROR\t\tCouldn't roll back cleanly: %+v", e.Err)
 		}
 	case *Started:
 		if e.Err != nil {
-			l.logf("ERROR\t\tFailed to start: %v", e.Err)
+			l.logf("ERROR\t\tFailed to start: %+v", e.Err)
 		} else {
 			l.logf("RUNNING")
 		}


Test patch:
diff --git a/fxevent/console_test.go b/fxevent/console_test.go
index 3af0b45..0e95ce4 100644
--- a/fxevent/console_test.go
+++ b/fxevent/console_test.go
@@ -24,6 +24,7 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
+	"io"
 	"os"
 	"strings"
 	"testing"
@@ -32,6 +33,20 @@ import (
 	"github.com/stretchr/testify/assert"
 )
 
+// richError prints a different output when formatted with %+v vs %v.
+type richError struct{}
+
+func (e *richError) Error() string { return "plain error" }
+
+func (e *richError) Format(w fmt.State, c rune) {
+	if w.Flag('+') && c == 'v' {
+		// Format differently for %+v.
+		io.WriteString(w, "rich error")
+	} else {
+		io.WriteString(w, e.Error())
+	}
+}
+
 func TestConsoleLogger(t *testing.T) {
 	t.Parallel()
 
@@ -65,6 +80,15 @@ func TestConsoleLogger(t *testing.T) {
 			},
 			want: "[Fx] HOOK OnStop		hook.onStart1 called by bytes.NewBuffer failed in 0s: some error\n",
 		},
+		{
+			name: "OnStopExecutedError/rich error",
+			give: &OnStopExecuted{
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Err:          &richError{},
+			},
+			want: "[Fx] HOOK OnStop		hook.onStart1 called by bytes.NewBuffer failed in 0s: rich error\n",
+		},
 		{
 			name: "OnStopExecuted",
 			give: &OnStopExecuted{
@@ -83,6 +107,15 @@ func TestConsoleLogger(t *testing.T) {
 			},
 			want: "[Fx] HOOK OnStart		hook.onStart1 called by bytes.NewBuffer failed in 0s: some error\n",
 		},
+		{
+			name: "OnStartExecutedError/rich error",
+			give: &OnStartExecuted{
+				FunctionName: "hook.onStart1",
+				CallerName:   "bytes.NewBuffer",
+				Err:          &richError{},
+			},
+			want: "[Fx] HOOK OnStart		hook.onStart1 called by bytes.NewBuffer failed in 0s: rich error\n",
+		},
 		{
 			name: "OnStartExecuted",
 			give: &OnStartExecuted{
@@ -97,6 +130,11 @@ func TestConsoleLogger(t *testing.T) {
 			give: &Provided{Err: errors.New("some error")},
 			want: "[Fx] Error after options were applied: some error\n",
 		},
+		{
+			name: "ProvideError/rich error",
+			give: &Provided{Err: &richError{}},
+			want: "[Fx] Error after options were applied: rich error\n",
+		},
 		{
 			name: "Supplied",
 			give: &Supplied{TypeName: "*bytes.Buffer", ModuleName: "myModule"},
@@ -107,6 +145,11 @@ func TestConsoleLogger(t *testing.T) {
 			give: &Supplied{TypeName: "*bytes.Buffer", Err: errors.New("great sadness")},
 			want: "[Fx] ERROR	Failed to supply *bytes.Buffer: great sadness\n",
 		},
+		{
+			name: "SuppliedError/rich error",
+			give: &Supplied{TypeName: "*bytes.Buffer", Err: &richError{}},
+			want: "[Fx] ERROR	Failed to supply *bytes.Buffer: rich error\n",
+		},
 		{
 			name: "Provided",
 			give: &Provided{
@@ -143,6 +186,11 @@ func TestConsoleLogger(t *testing.T) {
 			give: &Decorated{Err: errors.New("some error")},
 			want: "[Fx] Error after options were applied: some error\n",
 		},
+		{
+			name: "DecorateError/rich error",
+			give: &Decorated{Err: &richError{}},
+			want: "[Fx] Error after options were applied: rich error\n",
+		},
 		{
 			name: "Invoking",
 			give: &Invoking{FunctionName: "bytes.NewBuffer()"},
@@ -162,11 +210,30 @@ func TestConsoleLogger(t *testing.T) {
 				"Failed: some error",
 			),
 		},
+		{
+			name: "Invoked/Error/rich",
+			give: &Invoked{
+				FunctionName: "bytes.NewBuffer()",
+				Err:          &richError{},
+				Trace:        "foo()\n\tbar/baz.go:42\n",
+			},
+			want: joinLines(
+				"[Fx] ERROR		fx.Invoke(bytes.NewBuffer()) called from:",
+				"foo()",
+				"	bar/baz.go:42",
+				"Failed: rich error",
+			),
+		},
 		{
 			name: "StartError",
 			give: &Started{Err: errors.New("some error")},
 			want: "[Fx] ERROR		Failed to start: some error\n",
 		},
+		{
+			name: "StartError/rich error",
+			give: &Started{Err: &richError{}},
+			want: "[Fx] ERROR		Failed to start: rich error\n",
+		},
 		{
 			name: "Stopping",
 			give: &Stopping{Signal: os.Interrupt},
@@ -177,16 +244,31 @@ func TestConsoleLogger(t *testing.T) {
 			give: &Stopped{Err: errors.New("some error")},
 			want: "[Fx] ERROR		Failed to stop cleanly: some error\n",
 		},
+		{
+			name: "Stopped/rich error",
+			give: &Stopped{Err: &richError{}},
+			want: "[Fx] ERROR		Failed to stop cleanly: rich error\n",
+		},
 		{
 			name: "RollingBack",
 			give: &RollingBack{StartErr: errors.New("some error")},
 			want: "[Fx] ERROR		Start failed, rolling back: some error\n",
 		},
+		{
+			name: "RollingBack/rich error",
+			give: &RollingBack{StartErr: &richError{}},
+			want: "[Fx] ERROR		Start failed, rolling back: rich error\n",
+		},
 		{
 			name: "RolledBack",
 			give: &RolledBack{Err: errors.New("some error")},
 			want: "[Fx] ERROR		Couldn't roll back cleanly: some error\n",
 		},
+		{
+			name: "RolledBack/rich error",
+			give: &RolledBack{Err: &richError{}},
+			want: "[Fx] ERROR		Couldn't roll back cleanly: rich error\n",
+		},
 		{
 			name: "Started",
 			give: &Started{},
@@ -197,6 +279,11 @@ func TestConsoleLogger(t *testing.T) {
 			give: &LoggerInitialized{Err: errors.New("great sadness")},
 			want: "[Fx] ERROR		Failed to initialize custom logger: great sadness\n",
 		},
+		{
+			name: "CustomLoggerError/rich error",
+			give: &LoggerInitialized{Err: &richError{}},
+			want: "[Fx] ERROR		Failed to initialize custom logger: rich error\n",
+		},
 		{
 			name: "LoggerInitialized",
 			give: &LoggerInitialized{ConstructorName: "go.uber.org/fx/fxevent.TestConsoleLogger.func1()"},