Skip to content

Commit

Permalink
Add module info to fxevent (#863)
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@sywhang
sywhang committed Mar 23, 2022
1 parent 24f6f50 commit 99425a8
Show file tree
Hide file tree
Showing 6 changed files with 75 additions and 15 deletions.
22 changes: 18 additions & 4 deletions fxevent/console.go
View file
Expand Up @@ -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)
Expand Down
10 changes: 6 additions & 4 deletions fxevent/console_test.go
View file
Expand Up @@ -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",
Expand All @@ -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",
Expand Down
18 changes: 17 additions & 1 deletion fxevent/event.go
View file
Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
Expand All @@ -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,
Expand All @@ -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

Expand Down
24 changes: 21 additions & 3 deletions fxevent/zap.go
View file
Expand Up @@ -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",
Expand Down Expand Up @@ -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)
}
7 changes: 6 additions & 1 deletion fxevent/zap_test.go
View file
Expand Up @@ -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",
},
},
{
Expand All @@ -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",
},
},
{
Expand All @@ -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",
},
},
{
Expand Down
9 changes: 7 additions & 2 deletions module.go
View file
Expand Up @@ -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:
Expand All @@ -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,
}
Expand All @@ -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
})
Expand All @@ -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,
})
Expand Down

0 comments on commit 99425a8

Please sign in to comment.