Skip to content

Commit a086405

Browse files
GroxxJacobOaks
Groxx
and
JacobOaks
authored
Adding a before-call-begins fxevent, to help with troubleshooting (#1267)
# What Adds a "BeforeRun" fxevent.Event, mirroring "Run" but it is called _before_ the provided func is called by Dig, rather than after. This relies on uber-go/dig#431 (released as v1.19.0). # Motivation A recent startup-issue debugging session included logs like this: ``` {"level":"info","ts":1742516783.6106565,"caller":"fxevent/zap.go:51","message":"provided","constructor":"a", ... ... {"level":"info","ts":1742516783.6106653,"caller":"fxevent/zap.go:51","message":"provided","constructor":"q", ... ... {"level":"info","ts":1742516783.6106734,"caller":"fxevent/zap.go:51","message":"provided","constructor":"z", ... ... {"level":"info","ts":1742516784.7998207,"caller":"fxevent/zap.go:51","message":"run","name":"a", ... {"level":"info","ts":1742516784.7999196,"caller":"fxevent/zap.go:51","message":"run","name":"b", ... {"level":"info","ts":1742516784.9025834,"caller":"application.go:123", ... {"level":"info","ts":1742516789.5810778,"caller":"application.go:234", ... {"level":"info","ts":1742516790.740516,"caller":"application.go:345", ... # EOF ``` which accurately reflected the logs the app produced: during startup, it was getting OOM-killed after the final log, several seconds after the last Fx-"run" event. Unfortunately, Fx's `Run` event is logged _after_ a call completes, so the fxevent log immediately before the application-produced logs tells us _almost nothing_ about what is currently running. That seems... kinda not ideal. I've run into this quite a few times over the years, but I finally decided to do something about it. So I added a "before run" event, so this log will be much easier to diagnose: ``` {"level":"info","ts":1742516784.7899196,"caller":"fxevent/zap.go:51","message":"before run","name":"b", ... {"level":"info","ts":1742516784.7999196,"caller":"fxevent/zap.go:51","message":"run","name":"b", ... {"level":"info","ts":1742516784.8000196,"caller":"fxevent/zap.go:51","message":"before run","name":"c", ... {"level":"info","ts":1742516784.9025834,"caller":"application.go:123", ... # ^ clearly logged during "c" ``` After a quick attempt in Fx it became pretty clear that it would be difficult or almost impossible to do without changing Dig, so this PR relies on a change to Dig: uber-go/dig#431 <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit - **New Features** - Enhanced the logging system to provide proactive notifications before key lifecycle events, offering clearer insight into system operations. - **Tests** - Modified test cases to validate the improved event logging flow for greater accuracy in monitoring system behavior. - **Chores** - Updated a core dependency to support the new logging enhancements. <!-- end of auto-generated comment: release notes by coderabbit.ai --> --------- Co-authored-by: Jacob Oaks <joaks@uber.com>
1 parent 16999a7 commit a086405

15 files changed

Lines changed: 113 additions & 27 deletions

File tree

‎app_test.go‎

Lines changed: 21 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -365,7 +365,7 @@ func TestNewApp(t *testing.T) {
365365
defer app.RequireStart().RequireStop()
366366

367367
require.Equal(t,
368-
[]string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "Run", "Run", "Invoked", "Started"},
368+
[]string{"Provided", "Provided", "Provided", "Provided", "Decorated", "LoggerInitialized", "Invoking", "BeforeRun", "Run", "BeforeRun", "Run", "Invoked", "Started"},
369369
spy.EventTypes())
370370
})
371371

@@ -674,7 +674,7 @@ func TestWithLogger(t *testing.T) {
674674
)
675675

676676
assert.Equal(t, []string{
677-
"Provided", "Provided", "Provided", "Supplied", "Run", "LoggerInitialized",
677+
"Provided", "Provided", "Provided", "Supplied", "BeforeRun", "Run", "LoggerInitialized",
678678
}, spy.EventTypes())
679679

680680
spy.Reset()
@@ -704,7 +704,7 @@ func TestWithLogger(t *testing.T) {
704704
"must provide constructor function, got (type *bytes.Buffer)",
705705
)
706706

707-
assert.Equal(t, []string{"Provided", "Provided", "Provided", "Supplied", "Provided", "Run", "LoggerInitialized"}, spy.EventTypes())
707+
assert.Equal(t, []string{"Provided", "Provided", "Provided", "Supplied", "Provided", "BeforeRun", "Run", "LoggerInitialized"}, spy.EventTypes())
708708
})
709709

710710
t.Run("logger failed to build", func(t *testing.T) {
@@ -989,8 +989,18 @@ func TestRunEventEmission(t *testing.T) {
989989
assert.NoError(t, app.Err())
990990
}
991991

992+
gotBeforeEvents := spy.Events().SelectByTypeName("BeforeRun")
992993
gotEvents := spy.Events().SelectByTypeName("Run")
993-
require.Len(t, gotEvents, len(tt.wantRunEvents))
994+
require.Len(t, gotBeforeEvents, len(tt.wantRunEvents), "wrong number of before-run events")
995+
require.Len(t, gotEvents, len(tt.wantRunEvents), "wrong number of run events")
996+
// BeforeRun events are just a reduced-field version of Run events
997+
for i, event := range gotBeforeEvents {
998+
rEvent, ok := event.(*fxevent.BeforeRun)
999+
require.True(t, ok)
1000+
1001+
assert.Equal(t, tt.wantRunEvents[i].Name, rEvent.Name)
1002+
assert.Equal(t, tt.wantRunEvents[i].Kind, rEvent.Kind)
1003+
}
9941004
for i, event := range gotEvents {
9951005
rEvent, ok := event.(*fxevent.Run)
9961006
require.True(t, ok)
@@ -1627,12 +1637,12 @@ func TestAppStart(t *testing.T) {
16271637
)
16281638

16291639
go func() {
1630-
app.Start(context.Background())
1640+
assert.NoError(t, app.Start(context.Background()))
16311641
close(startReturn)
16321642
}()
16331643

16341644
<-secondStart
1635-
app.Stop(context.Background())
1645+
assert.NoError(t, app.Stop(context.Background()))
16361646
assert.True(t, stop1Run)
16371647
})
16381648

@@ -1696,7 +1706,9 @@ func TestAppStart(t *testing.T) {
16961706
"Provided", "Provided", "Provided", "Provided",
16971707
"LoggerInitialized",
16981708
"Invoking",
1709+
"BeforeRun",
16991710
"Run",
1711+
"BeforeRun",
17001712
"Run",
17011713
"Invoked",
17021714
"OnStartExecuting", "OnStartExecuted",
@@ -1734,7 +1746,9 @@ func TestAppStart(t *testing.T) {
17341746
"Provided", "Provided", "Provided", "Provided",
17351747
"LoggerInitialized",
17361748
"Invoking",
1749+
"BeforeRun",
17371750
"Run",
1751+
"BeforeRun",
17381752
"Run",
17391753
"Invoked",
17401754
"OnStartExecuting", "OnStartExecuted",
@@ -2471,6 +2485,7 @@ func TestCustomLoggerWithLifecycle(t *testing.T) {
24712485
"Provided",
24722486
"Provided",
24732487
"Provided",
2488+
"BeforeRun",
24742489
"Run",
24752490
"LoggerInitialized",
24762491
"OnStartExecuting", "OnStartExecuted",

‎docs/go.mod‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ require (
1111
require (
1212
github.com/davecgh/go-spew v1.1.1 // indirect
1313
github.com/pmezard/go-difflib v1.0.0 // indirect
14-
go.uber.org/dig v1.18.0 // indirect
14+
go.uber.org/dig v1.19.0 // indirect
1515
go.uber.org/multierr v1.10.0 // indirect
1616
golang.org/x/sys v0.0.0-20220412211240-33da011f77ad // indirect
1717
gopkg.in/yaml.v3 v3.0.1 // indirect

‎docs/go.sum‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,8 +10,8 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/
1010
github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
1111
github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
1212
github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
13-
go.uber.org/dig v1.18.0 h1:imUL1UiY0Mg4bqbFfsRQO5G4CGRBec/ZujWTvSVp3pw=
14-
go.uber.org/dig v1.18.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
13+
go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
14+
go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
1515
go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
1616
go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
1717
go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=

‎fxevent/console.go‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,12 @@ func (l *ConsoleLogger) LogEvent(event Event) {
104104
if e.Err != nil {
105105
l.logf("Error after options were applied: %+v", e.Err)
106106
}
107+
case *BeforeRun:
108+
var moduleStr string
109+
if e.ModuleName != "" {
110+
moduleStr = fmt.Sprintf(" from module %q", e.ModuleName)
111+
}
112+
l.logf("BEFORE RUN\t%s: %s%s", e.Kind, e.Name, moduleStr)
107113
case *Run:
108114
var moduleStr string
109115
if e.ModuleName != "" {

‎fxevent/event.go‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ func (*Supplied) event() {}
3939
func (*Provided) event() {}
4040
func (*Replaced) event() {}
4141
func (*Decorated) event() {}
42+
func (*BeforeRun) event() {}
4243
func (*Run) event() {}
4344
func (*Invoking) event() {}
4445
func (*Invoked) event() {}
@@ -191,6 +192,20 @@ type Decorated struct {
191192
Err error
192193
}
193194

195+
// BeforeRun is emitted before a constructor, decorator, or supply/replace stub is run by Fx.
196+
// When complete, a Run will be emitted.
197+
type BeforeRun struct {
198+
// Name is the name of the function that will be run.
199+
Name string
200+
201+
// Kind indicates which Fx option was used to pass along the function.
202+
// It is either "provide", "decorate", "supply", or "replace".
203+
Kind string
204+
205+
// ModuleName is the name of the module in which the function belongs.
206+
ModuleName string
207+
}
208+
194209
// Run is emitted after a constructor, decorator, or supply/replace stub is run by Fx.
195210
type Run struct {
196211
// Name is the name of the function that was run.

‎fxevent/event_test.go‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ func TestForCoverage(t *testing.T) {
3939
&Provided{},
4040
&Replaced{},
4141
&Decorated{},
42+
&BeforeRun{},
4243
&Run{},
4344
&Invoking{},
4445
&Invoked{},

‎fxevent/slog.go‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,6 +192,12 @@ func (l *SlogLogger) LogEvent(event Event) {
192192
slogMaybeModuleField(e.ModuleName),
193193
slogErr(e.Err))
194194
}
195+
case *BeforeRun:
196+
l.logEvent("before run",
197+
slog.String("name", e.Name),
198+
slog.String("kind", e.Kind),
199+
slogMaybeModuleField(e.ModuleName),
200+
)
195201
case *Run:
196202
if e.Err != nil {
197203
l.logError("error returned",

‎fxevent/slog_test.go‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -340,6 +340,15 @@ func TestSlogLogger(t *testing.T) {
340340
"error": "some error",
341341
},
342342
},
343+
{
344+
name: "BeforeRun",
345+
give: &BeforeRun{Name: "bytes.NewBuffer()", Kind: "constructor"},
346+
wantMessage: "before run",
347+
wantFields: map[string]interface{}{
348+
"name": "bytes.NewBuffer()",
349+
"kind": "constructor",
350+
},
351+
},
343352
{
344353
name: "Run",
345354
give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor", Runtime: 3 * time.Millisecond},

‎fxevent/zap.go‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -167,6 +167,12 @@ func (l *ZapLogger) LogEvent(event Event) {
167167
moduleField(e.ModuleName),
168168
zap.Error(e.Err))
169169
}
170+
case *BeforeRun:
171+
l.logEvent("before run",
172+
zap.String("name", e.Name),
173+
zap.String("kind", e.Kind),
174+
moduleField(e.ModuleName),
175+
)
170176
case *Run:
171177
if e.Err != nil {
172178
l.logError("error returned",

‎go.mod‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ go 1.22
44

55
require (
66
github.com/stretchr/testify v1.8.1
7-
go.uber.org/dig v1.18.0
7+
go.uber.org/dig v1.19.0
88
go.uber.org/goleak v1.2.0
99
go.uber.org/multierr v1.10.0
1010
go.uber.org/zap v1.26.0

0 commit comments

Comments
 (0)