Add fxevent.Decorated and emit it from fx.Decorate (#843)

This adds Decorated event to fx/fxevent package. Similar to Provided, this emits information on the following:

* The name of the decorator
* The dependencies of the decorator
* Types being decorated by the decorator

fx.Decorate now emits this event upon decoration.

This also needs to fix Dig to the latest master to include the dig.FillDecorateInfo API.

Ref: GO-1208

app_test.go

@@ -343,6 +343,44 @@ func TestNewApp(t *testing.T) {
 		assert.Contains(t, err.Error(), "/app_test.go")
 		assert.Contains(t, err.Error(), "Failed: must provide constructor function")
 	})
+
+	t.Run("Decorates", func(t *testing.T) {
+		t.Parallel()
+		spy := new(fxlog.Spy)
+
+		type A struct{ value int }
+		app := fxtest.New(t,
+			Provide(func() A { return A{value: 0} }),
+			Decorate(func(a A) A { return A{value: a.value + 1} }),
+			Invoke(func(a A) { assert.Equal(t, a.value, 1) }),
+			WithLogger(func() fxevent.Logger { return spy }))
+		defer app.RequireStart().RequireStop()
+
+		require.Equal(t,
+			[]string{"Provided", "Provided", "Provided", "Provided", "LoggerInitialized", "Decorated", "Invoking", "Invoked", "Started"},
+			spy.EventTypes())
+	})
+
+	t.Run("DecoratesFromManyModules", func(t *testing.T) {
+		t.Parallel()
+		spy := new(fxlog.Spy)
+
+		type A struct{ value int }
+		m := Module("decorator",
+			Decorate(func(a A) A { return A{value: a.value + 1} }),
+		)
+		app := fxtest.New(t,
+			m,
+			Provide(func() A { return A{value: 0} }),
+			Decorate(func(a A) A { return A{value: a.value + 1} }),
+			WithLogger(func() fxevent.Logger { return spy }),
+		)
+		defer app.RequireStart().RequireStop()
+
+		require.Equal(t,
+			[]string{"Provided", "Provided", "Provided", "Provided", "LoggerInitialized", "Decorated", "Decorated", "Started"},
+			spy.EventTypes())
+	})
 }
 
 func TestWithLoggerErrorUseDefault(t *testing.T) {

fxevent/console.go

@@ -72,6 +72,13 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 		if e.Err != nil {
 			l.logf("Error after options were applied: %v", e.Err)
 		}
+	case *Decorated:
+		for _, rtype := range e.OutputTypeNames {
+			l.logf("DECORATE\t%v <= %v", rtype, e.DecoratorName)
+		}
+		if e.Err != nil {
+			l.logf("Error after options were applied: %v", e.Err)
+		}
 	case *Invoking:
 		l.logf("INVOKE\t\t%s", e.FunctionName)
 	case *Invoked:

fxevent/console_test.go

@@ -115,6 +115,19 @@ func TestConsoleLogger(t *testing.T) {
 			},
 			want: "[Fx] PROVIDE	*bytes.Buffer <= bytes.NewBuffer()\n",
 		},
+		{
+			name: "Decorated",
+			give: &Decorated{
+				DecoratorName:   "bytes.NewBuffer()",
+				OutputTypeNames: []string{"*bytes.Buffer"},
+			},
+			want: "[Fx] DECORATE	*bytes.Buffer <= bytes.NewBuffer()\n",
+		},
+		{
+			name: "DecorateError",
+			give: &Decorated{Err: errors.New("some error")},
+			want: "[Fx] Error after options were applied: some error\n",
+		},
 		{
 			name: "Invoking",
 			give: &Invoking{FunctionName: "bytes.NewBuffer()"},

fxevent/event.go

@@ -37,6 +37,7 @@ func (*OnStopExecuting) event()   {}
 func (*OnStopExecuted) event()    {}
 func (*Supplied) event()          {}
 func (*Provided) event()          {}
+func (*Decorated) event()         {}
 func (*Invoking) event()          {}
 func (*Invoked) event()           {}
 func (*Stopping) event()          {}
@@ -125,6 +126,20 @@ type Provided struct {
 	Err error
 }
 
+// Decorated is emitted when a decorator is provided to Fx.
+type Decorated struct {
+	// DecoratorName is the name of the decorator function that was
+	// provided to Fx.
+	DecoratorName string
+
+	// OutputTypeNames is a list of names of types that are decorated by
+	// this decorator.
+	OutputTypeNames []string
+
+	// Err is non-nil if we failed to provide this decorator.
+	Err error
+}
+
 // Invoking is emitted before we invoke a function specified with fx.Invoke.
 type Invoking struct {
 	// FunctionName is the name of the function that will be invoked.

fxevent/event_test.go

@@ -37,6 +37,7 @@ func TestForCoverage(t *testing.T) {
 		&OnStopExecuted{},
 		&Supplied{},
 		&Provided{},
+		&Decorated{},
 		&Invoking{},
 		&Invoked{},
 		&Stopping{},

fxevent/zap.go

@@ -87,6 +87,17 @@ func (l *ZapLogger) LogEvent(event Event) {
 			l.Logger.Error("error encountered while applying options",
 				zap.Error(e.Err))
 		}
+	case *Decorated:
+		for _, rtype := range e.OutputTypeNames {
+			l.Logger.Info("decorated",
+				zap.String("decorator", e.DecoratorName),
+				zap.String("type", rtype),
+			)
+		}
+		if e.Err != nil {
+			l.Logger.Error("error encountered while applying options",
+				zap.Error(e.Err))
+		}
 	case *Invoking:
 		// Do not log stack as it will make logs hard to read.
 		l.Logger.Info("invoking",

fxevent/zap_test.go

@@ -163,6 +163,26 @@ func TestZapLogger(t *testing.T) {
 				"error": "some error",
 			},
 		},
+		{
+			name: "Decorate",
+			give: &Decorated{
+				DecoratorName:   "bytes.NewBuffer()",
+				OutputTypeNames: []string{"*bytes.Buffer"},
+			},
+			wantMessage: "decorated",
+			wantFields: map[string]interface{}{
+				"decorator": "bytes.NewBuffer()",
+				"type":      "*bytes.Buffer",
+			},
+		},
+		{
+			name:        "Decorate with Error",
+			give:        &Decorated{Err: someError},
+			wantMessage: "error encountered while applying options",
+			wantFields: map[string]interface{}{
+				"error": "some error",
+			},
+		},
 		{
 			name:        "Invoking/Success",
 			give:        &Invoking{FunctionName: "bytes.NewBuffer()"},

go.mod

@@ -12,4 +12,4 @@ require (
 	golang.org/x/sys v0.0.0-20210903071746-97244b99971b
 )
 
-replace go.uber.org/dig => github.com/uber-go/dig v1.13.1-0.20220208182428-8193c7fedade
+replace go.uber.org/dig => github.com/uber-go/dig v1.13.1-0.20220217170604-a7e23e31e975

go.sum

@@ -22,8 +22,8 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
-github.com/uber-go/dig v1.13.1-0.20220208182428-8193c7fedade h1:q2FxCCuMWy3p904qjF7NyaFj4EP/G5T7eACVKLvMgrU=
-github.com/uber-go/dig v1.13.1-0.20220208182428-8193c7fedade/go.mod h1:jHAn/z1Ld1luVVyGKOAIFYz/uBFqKjjEEdIqVAqfQ2o=
+github.com/uber-go/dig v1.13.1-0.20220217170604-a7e23e31e975 h1:DThTt5qayrILkBHJQIu19u38oTPaWH/LU+RxMLz0/tA=
+github.com/uber-go/dig v1.13.1-0.20220217170604-a7e23e31e975/go.mod h1:jHAn/z1Ld1luVVyGKOAIFYz/uBFqKjjEEdIqVAqfQ2o=
 github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
 go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk=
 go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=

module.go

@@ -179,7 +179,19 @@ func (m *module) executeInvoke(i invoke) (err error) {
 
 func (m *module) decorate() (err error) {
 	for _, decorator := range m.decorators {
-		if err := runDecorator(m.scope, decorator); err != nil {
+		var info dig.DecorateInfo
+		err := runDecorator(m.scope, decorator, dig.FillDecorateInfo(&info))
+		outputNames := make([]string, len(info.Outputs))
+		for i, o := range info.Outputs {
+			outputNames[i] = o.String()
+		}
+
+		m.app.log.LogEvent(&fxevent.Decorated{
+			DecoratorName:   fxreflect.FuncName(decorator.Target),
+			OutputTypeNames: outputNames,
+			Err:             err,
+		})
+		if err != nil {
 			return err
 		}
 	}