Repository: uber-go/fx
Pull request #863 (2022-03-22 07:03:35)

Add module info to fxevent
This adds the module info in the fxevent Provided/Decorated/Invoked
structs to make the logs more descriptive by including which module
each of these happened from.

This can be helpful especially for debugging decorates, since the
module from which decoration is applied changes the results.

Fix https://github.com/uber-go/fx/issues/855.
Refs GO-1285.

codecov[bot]: # [Codecov](https://codecov.io/gh/uber-go/fx/pull/863?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) Report
> Merging [#863](https://codecov.io/gh/uber-go/fx/pull/863?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (466d9df) into [master](https://codecov.io/gh/uber-go/fx/commit/5ebb2426e2aa578b7c3cafb879854e28115e5b0d?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) (5ebb242) will **increase** coverage by `0.02%`.
> The diff coverage is `100.00%`.

```diff
@@            Coverage Diff             @@
##           master     #863      +/-   ##
==========================================
+ Coverage   98.45%   98.47%   +0.02%     
==========================================
  Files          30       30              
  Lines        1100     1116      +16     
==========================================
+ Hits         1083     1099      +16     
  Misses         11       11              
  Partials        6        6              
```


| [Impacted Files](https://codecov.io/gh/uber-go/fx/pull/863?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go) | Coverage Δ | |
|---|---|---|
| [fxevent/event.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC9ldmVudC5nbw==) | `100.00% <ø> (ø)` | |
| [fxevent/console.go](https://codecov.io/gh/uber-go/fx/pull/863/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%> (ø)` | |
| [fxevent/zap.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZnhldmVudC96YXAuZ28=) | `100.00% <100.00%> (ø)` | |
| [module.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-bW9kdWxlLmdv) | `100.00% <100.00%> (ø)` | |
| [supply.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-c3VwcGx5Lmdv) | `100.00% <0.00%> (ø)` | |
| [replace.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-cmVwbGFjZS5nbw==) | `100.00% <0.00%> (ø)` | |
| [decorate.go](https://codecov.io/gh/uber-go/fx/pull/863/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go#diff-ZGVjb3JhdGUuZ28=) | `100.00% <0.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/uber-go/fx/pull/863?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/863?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=uber-go). Last update [5ebb242...466d9df](https://codecov.io/gh/uber-go/fx/pull/863?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 2fa9901..9f89853 100644
--- a/fxevent/console.go
+++ b/fxevent/console.go
@@ -62,25 +62,39 @@ func (l *ConsoleLogger) LogEvent(event Event) {
 	case *Supplied:
 		if e.Err != nil {
 			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 {
-			l.logf("SUPPLY\t%v", e.TypeName)
+			l.logf("SUPPLY\t%v", e.TypeName, e.ModuleName)
 		}
 	case *Provided:
 		for _, rtype := range e.OutputTypeNames {
-			l.logf("PROVIDE\t%v <= %v", rtype, e.ConstructorName)
+			if e.ModuleName != "" {
+				l.logf("PROVIDE\t%v <= %v from module %q", rtype, e.ConstructorName, e.ModuleName)
+			} else {
+				l.logf("PROVIDE\t%v <= %v", rtype, e.ConstructorName)
+			}
 		}
 		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.ModuleName != "" {
+				l.logf("DECORATE\t%v <= %v from module %q", rtype, e.DecoratorName, e.ModuleName)
+			} else {
+				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)
+		if e.ModuleName != "" {
+			l.logf("INVOKE\t\t%s from module %q", e.FunctionName, e.ModuleName)
+		} else {
+			l.logf("INVOKE\t\t%s", e.FunctionName)
+		}
 	case *Invoked:
 		if e.Err != nil {
 			l.logf("ERROR\t\tfx.Invoke(%v) called from:\n%+vFailed: %v", e.FunctionName, e.Trace, e.Err)
diff --git a/fxevent/event.go b/fxevent/event.go
index 10c0f2f..297c143 100644
--- a/fxevent/event.go
+++ b/fxevent/event.go
@@ -105,9 +105,12 @@ type OnStopExecuted struct {
 
 // Supplied is emitted after a value is added with fx.Supply.
 type Supplied struct {
-	// Name of the type of value that was added.
+	// TypeName is the name of the type of value that was added.
 	TypeName string
 
+	// ModuleName is the name of the module in which the value was added to.
+	ModuleName string
+
 	// Err is non-nil if we failed to supply the value.
 	Err error
 }
@@ -122,6 +125,10 @@ type Provided struct {
 	// this constructor.
 	OutputTypeNames []string
 
+	// ModuleName is the name of the module in which the constructor was
+	// provided to.
+	ModuleName string
+
 	// Err is non-nil if we failed to provide this constructor.
 	Err error
 }
@@ -132,6 +139,9 @@ type Decorated struct {
 	// provided to Fx.
 	DecoratorName string
 
+	// ModuleName is the name of the module in which the value was added to.
+	ModuleName string
+
 	// OutputTypeNames is a list of names of types that are decorated by
 	// this decorator.
 	OutputTypeNames []string
@@ -144,6 +154,9 @@ type Decorated struct {
 type Invoking struct {
 	// FunctionName is the name of the function that will be invoked.
 	FunctionName string
+
+	// ModuleName is the name of the module in which the value was added to.
+	ModuleName string
 }
 
 // Invoked is emitted after we invoke a function specified with fx.Invoke,
@@ -152,6 +165,9 @@ type Invoked struct {
 	// Functionname is the name of the function that was invoked.
 	FunctionName string
 
+	// ModuleName is the name of the module in which the value was added to.
+	ModuleName string
+
 	// Err is non-nil if the function failed to execute.
 	Err error
 
diff --git a/fxevent/zap.go b/fxevent/zap.go
index e6b75e5..349f236 100644
--- a/fxevent/zap.go
+++ b/fxevent/zap.go
@@ -75,39 +75,50 @@ func (l *ZapLogger) LogEvent(event Event) {
 			)
 		}
 	case *Supplied:
-		l.Logger.Info("supplied", zap.String("type", e.TypeName), zap.Error(e.Err))
+		l.Logger.Info("supplied",
+			zap.String("type", e.TypeName),
+			moduleField(e.ModuleName),
+			zap.Error(e.Err))
 	case *Provided:
 		for _, rtype := range e.OutputTypeNames {
 			l.Logger.Info("provided",
 				zap.String("constructor", e.ConstructorName),
+				moduleField(e.ModuleName),
 				zap.String("type", rtype),
 			)
 		}
 		if e.Err != nil {
 			l.Logger.Error("error encountered while applying options",
+				moduleField(e.ModuleName),
 				zap.Error(e.Err))
 		}
 	case *Decorated:
 		for _, rtype := range e.OutputTypeNames {
 			l.Logger.Info("decorated",
 				zap.String("decorator", e.DecoratorName),
+				moduleField(e.ModuleName),
 				zap.String("type", rtype),
 			)
 		}
 		if e.Err != nil {
 			l.Logger.Error("error encountered while applying options",
+				moduleField(e.ModuleName),
 				zap.Error(e.Err))
 		}
 	case *Invoking:
 		// Do not log stack as it will make logs hard to read.
 		l.Logger.Info("invoking",
-			zap.String("function", e.FunctionName))
+			zap.String("function", e.FunctionName),
+			moduleField(e.ModuleName),
+		)
 	case *Invoked:
 		if e.Err != nil {
 			l.Logger.Error("invoke failed",
 				zap.Error(e.Err),
 				zap.String("stack", e.Trace),
-				zap.String("function", e.FunctionName))
+				zap.String("function", e.FunctionName),
+				moduleField(e.ModuleName),
+			)
 		}
 	case *Stopping:
 		l.Logger.Info("received signal",
@@ -136,3 +147,10 @@ func (l *ZapLogger) LogEvent(event Event) {
 		}
 	}
 }
+
+func moduleField(name string) zap.Field {
+	if len(name) == 0 {
+		return zap.Skip()
+	}
+	return zap.String("module", name)
+}
diff --git a/module.go b/module.go
index 423155f..1412ec1 100644
--- a/module.go
+++ b/module.go
@@ -129,8 +129,9 @@ func (m *module) provide(p provide) {
 	switch {
 	case p.IsSupply:
 		ev = &fxevent.Supplied{
-			TypeName: p.SupplyType.String(),
-			Err:      m.app.err,
+			TypeName:   p.SupplyType.String(),
+			ModuleName: m.name,
+			Err:        m.app.err,
 		}
 
 	default:
@@ -141,6 +142,7 @@ func (m *module) provide(p provide) {
 
 		ev = &fxevent.Provided{
 			ConstructorName: fxreflect.FuncName(p.Target),
+			ModuleName:      m.name,
 			OutputTypeNames: outputNames,
 			Err:             m.app.err,
 		}
@@ -167,10 +169,12 @@ func (m *module) executeInvoke(i invoke) (err error) {
 	fnName := fxreflect.FuncName(i.Target)
 	m.app.log.LogEvent(&fxevent.Invoking{
 		FunctionName: fnName,
+		ModuleName:   m.name,
 	})
 	err = runInvoke(m.scope, i)
 	m.app.log.LogEvent(&fxevent.Invoked{
 		FunctionName: fnName,
+		ModuleName:   m.name,
 		Err:          err,
 		Trace:        fmt.Sprintf("%+v", i.Stack), // format stack trace as multi-line
 	})
@@ -188,6 +192,7 @@ func (m *module) decorate() (err error) {
 
 		m.app.log.LogEvent(&fxevent.Decorated{
 			DecoratorName:   fxreflect.FuncName(decorator.Target),
+			ModuleName:      m.name,
 			OutputTypeNames: outputNames,
 			Err:             err,
 		})


Test patch:
diff --git a/fxevent/console_test.go b/fxevent/console_test.go
index 0e7f465..9ef06d5 100644
--- a/fxevent/console_test.go
+++ b/fxevent/console_test.go
@@ -99,8 +99,8 @@ func TestConsoleLogger(t *testing.T) {
 		},
 		{
 			name: "Supplied",
-			give: &Supplied{TypeName: "*bytes.Buffer"},
-			want: "[Fx] SUPPLY	*bytes.Buffer\n",
+			give: &Supplied{TypeName: "*bytes.Buffer", ModuleName: "myModule"},
+			want: "[Fx] SUPPLY	*bytes.Buffer from module \"myModule\"\n",
 		},
 		{
 			name: "SuppliedError",
@@ -111,17 +111,19 @@ func TestConsoleLogger(t *testing.T) {
 			name: "Provided",
 			give: &Provided{
 				ConstructorName: "bytes.NewBuffer()",
+				ModuleName:      "myModule",
 				OutputTypeNames: []string{"*bytes.Buffer"},
 			},
-			want: "[Fx] PROVIDE	*bytes.Buffer <= bytes.NewBuffer()\n",
+			want: "[Fx] PROVIDE	*bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
 		},
 		{
 			name: "Decorated",
 			give: &Decorated{
 				DecoratorName:   "bytes.NewBuffer()",
+				ModuleName:      "myModule",
 				OutputTypeNames: []string{"*bytes.Buffer"},
 			},
-			want: "[Fx] DECORATE	*bytes.Buffer <= bytes.NewBuffer()\n",
+			want: "[Fx] DECORATE	*bytes.Buffer <= bytes.NewBuffer() from module \"myModule\"\n",
 		},
 		{
 			name: "DecorateError",
diff --git a/fxevent/zap_test.go b/fxevent/zap_test.go
index a6fc426..f4afdf0 100644
--- a/fxevent/zap_test.go
+++ b/fxevent/zap_test.go
@@ -147,12 +147,14 @@ func TestZapLogger(t *testing.T) {
 			name: "Provide",
 			give: &Provided{
 				ConstructorName: "bytes.NewBuffer()",
+				ModuleName:      "myModule",
 				OutputTypeNames: []string{"*bytes.Buffer"},
 			},
 			wantMessage: "provided",
 			wantFields: map[string]interface{}{
 				"constructor": "bytes.NewBuffer()",
 				"type":        "*bytes.Buffer",
+				"module":      "myModule",
 			},
 		},
 		{
@@ -167,12 +169,14 @@ func TestZapLogger(t *testing.T) {
 			name: "Decorate",
 			give: &Decorated{
 				DecoratorName:   "bytes.NewBuffer()",
+				ModuleName:      "myModule",
 				OutputTypeNames: []string{"*bytes.Buffer"},
 			},
 			wantMessage: "decorated",
 			wantFields: map[string]interface{}{
 				"decorator": "bytes.NewBuffer()",
 				"type":      "*bytes.Buffer",
+				"module":    "myModule",
 			},
 		},
 		{
@@ -185,10 +189,11 @@ func TestZapLogger(t *testing.T) {
 		},
 		{
 			name:        "Invoking/Success",
-			give:        &Invoking{FunctionName: "bytes.NewBuffer()"},
+			give:        &Invoking{ModuleName: "myModule", FunctionName: "bytes.NewBuffer()"},
 			wantMessage: "invoking",
 			wantFields: map[string]interface{}{
 				"function": "bytes.NewBuffer()",
+				"module":   "myModule",
 			},
 		},
 		{