From d5897faac46004965bdc2420728fed3bb1cbea50 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ivan=20Miri=C4=87?= Date: Thu, 22 Jun 2023 12:19:28 +0200 Subject: [PATCH] Initialize global event system in GlobalState, defer Exit emission earlier This ensures that the Exit event is sent even in the case of an early error, such as a script exception. Resolves https://github.com/grafana/k6/pull/3112#issuecomment-1600982890 --- cmd/run.go | 28 ++++---- cmd/state/state.go | 3 + cmd/test_load.go | 3 +- cmd/tests/cmd_run_test.go | 131 ++++++++++++++++++++++++++------------ cmd/tests/test_state.go | 2 + 5 files changed, 111 insertions(+), 56 deletions(-) diff --git a/cmd/run.go b/cmd/run.go index 4e328cb6e585..75c5ede4024a 100644 --- a/cmd/run.go +++ b/cmd/run.go @@ -73,20 +73,8 @@ func (c *cmdRun) run(cmd *cobra.Command, args []string) (err error) { // from sub-contexts while also attaching a reason for the abort. runCtx, runAbort := execution.NewTestRunContext(lingerCtx, logger) - test, err := loadAndConfigureTest(c.gs, cmd, args, getConfig) - if err != nil { - return err - } - if test.keyLogger != nil { - defer func() { - if klErr := test.keyLogger.Close(); klErr != nil { - logger.WithError(klErr).Warn("Error while closing the SSLKEYLOGFILE") - } - }() - } - emitEvent := func(evt *event.Event) func() { - waitDone := test.preInitState.Events.Emit(evt) + waitDone := c.gs.Events.Emit(evt) return func() { waitCtx, waitCancel := context.WithTimeout(globalCtx, waitEventDoneTimeout) defer waitCancel() @@ -101,9 +89,21 @@ func (c *cmdRun) run(cmd *cobra.Command, args []string) (err error) { Type: event.Exit, Data: &event.ExitData{Error: err}, })() - test.preInitState.Events.UnsubscribeAll() + c.gs.Events.UnsubscribeAll() }() + test, err := loadAndConfigureTest(c.gs, cmd, args, getConfig) + if err != nil { + return err + } + if test.keyLogger != nil { + defer func() { + if klErr := test.keyLogger.Close(); klErr != nil { + logger.WithError(klErr).Warn("Error while closing the SSLKEYLOGFILE") + } + }() + } + // Write the full consolidated *and derived* options back to the Runner. conf := test.derivedConfig testRunState, err := test.buildTestRunState(conf.Options) diff --git a/cmd/state/state.go b/cmd/state/state.go index f0595d7770e2..3facd99d0198 100644 --- a/cmd/state/state.go +++ b/cmd/state/state.go @@ -12,6 +12,7 @@ import ( "github.com/mattn/go-isatty" "github.com/sirupsen/logrus" + "go.k6.io/k6/event" "go.k6.io/k6/lib/fsext" "go.k6.io/k6/ui/console" ) @@ -39,6 +40,7 @@ type GlobalState struct { BinaryName string CmdArgs []string Env map[string]string + Events *event.System DefaultFlags, Flags GlobalFlags @@ -110,6 +112,7 @@ func NewGlobalState(ctx context.Context) *GlobalState { BinaryName: filepath.Base(binary), CmdArgs: os.Args, Env: env, + Events: event.NewEventSystem(100, logger), DefaultFlags: defaultFlags, Flags: getFlags(defaultFlags, env), OutMutex: outMutex, diff --git a/cmd/test_load.go b/cmd/test_load.go index ca412fe641b2..6dd1d6b66651 100644 --- a/cmd/test_load.go +++ b/cmd/test_load.go @@ -16,7 +16,6 @@ import ( "go.k6.io/k6/cmd/state" "go.k6.io/k6/errext" "go.k6.io/k6/errext/exitcodes" - "go.k6.io/k6/event" "go.k6.io/k6/js" "go.k6.io/k6/lib" "go.k6.io/k6/lib/fsext" @@ -71,7 +70,7 @@ func loadTest(gs *state.GlobalState, cmd *cobra.Command, args []string) (*loaded RuntimeOptions: runtimeOptions, Registry: registry, BuiltinMetrics: metrics.RegisterBuiltinMetrics(registry), - Events: event.NewEventSystem(100, gs.Logger), + Events: gs.Events, LookupEnv: func(key string) (string, bool) { val, ok := gs.Env[key] return val, ok diff --git a/cmd/tests/cmd_run_test.go b/cmd/tests/cmd_run_test.go index 108906202da6..2bc44725ca78 100644 --- a/cmd/tests/cmd_run_test.go +++ b/cmd/tests/cmd_run_test.go @@ -2062,55 +2062,106 @@ func TestEventSystemOK(t *testing.T) { assert.Equal(t, expLog, log) } -// Tests that the exit event is emitted with the test exit error. -func TestEventSystemAborted(t *testing.T) { +// Check emitted events in the case of a script error. +func TestEventSystemError(t *testing.T) { t.Parallel() - ts := NewGlobalTestState(t) + testCases := []struct { + name, script string + expLog []string + expExitCode exitcodes.ExitCode + }{ + { + name: "abort", + script: ` + import { test } from 'k6/execution'; - moduleName := fmt.Sprintf("k6/x/testevents-%d", atomic.AddUint64(&uniqueModuleNumber, 1)) - mod := events.New(event.GlobalEvents, nil) - modules.Register(moduleName, mod) + export let options = { + vus: 1, + iterations: 5, + } + + export default function () { + test.abort('oops!'); + } + `, expLog: []string{ + "got event Init with data ''", + "got event TestStart with data ''", + "got event IterStart with data '{Iteration:0 VUID:1 ScenarioName:default Error:}'", + "got event IterEnd with data '{Iteration:0 VUID:1 ScenarioName:default Error:test aborted: oops! at file:///-:11:16(6)}'", + "got event TestEnd with data ''", + "got event Exit with data '&{Error:test aborted: oops! at file:///-:11:16(6)}'", + "test aborted: oops! at file:///-:11:16(6)", + }, + expExitCode: exitcodes.ScriptAborted, + }, + { + name: "init", + script: "undefinedVar", + expLog: []string{ + "got event Exit with data '&{Error:could not initialize '-': could not load JS test " + + "'file:///-': ReferenceError: undefinedVar is not defined\n\tat file:///-:2:0(12)\n}'", + "ReferenceError: undefinedVar is not defined\n\tat file:///-:2:0(12)\n", + }, + expExitCode: exitcodes.ScriptException, + }, + { + name: "throw", + script: ` + export let options = { + vus: 1, + iterations: 2, + } + + export default function () { + throw new Error('oops!'); + } + `, expLog: []string{ + "got event Init with data ''", + "got event TestStart with data ''", + "got event IterStart with data '{Iteration:0 VUID:1 ScenarioName:default Error:}'", + "got event IterEnd with data '{Iteration:0 VUID:1 ScenarioName:default Error:Error: oops!\n\tat file:///-:9:11(3)\n}'", + "Error: oops!\n\tat file:///-:9:11(3)\n", + "got event IterStart with data '{Iteration:1 VUID:1 ScenarioName:default Error:}'", + "got event IterEnd with data '{Iteration:1 VUID:1 ScenarioName:default Error:Error: oops!\n\tat file:///-:9:11(3)\n}'", + "Error: oops!\n\tat file:///-:9:11(3)\n", + "got event TestEnd with data ''", + "got event Exit with data '&{Error:}'", + }, + expExitCode: 0, + }, + } - ts.CmdArgs = []string{"k6", "--quiet", "run", "-"} - ts.ExpectedExitCode = int(exitcodes.ScriptAborted) - ts.Stdin = bytes.NewBuffer([]byte(fmt.Sprintf(` - import events from '%s'; - import { test } from 'k6/execution'; - import { sleep } from 'k6'; + for _, tc := range testCases { + tc := tc + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + ts := NewGlobalTestState(t) - export let options = { - vus: 5, - duration: '5s', - } + moduleName := fmt.Sprintf("k6/x/testevents-%d", atomic.AddUint64(&uniqueModuleNumber, 1)) + mod := events.New(event.GlobalEvents, event.VUEvents) + modules.Register(moduleName, mod) - export default function () { - sleep(1); - test.abort('oops!'); - } - `, moduleName))) + ts.CmdArgs = []string{"k6", "--quiet", "run", "-"} + ts.ExpectedExitCode = int(tc.expExitCode) + ts.Stdin = bytes.NewBuffer([]byte(fmt.Sprintf("import events from '%s';\n%s", moduleName, tc.script))) - cmd.ExecuteWithGlobalState(ts.GlobalState) + cmd.ExecuteWithGlobalState(ts.GlobalState) - doneCh := make(chan struct{}) - go func() { - mod.WG.Wait() - close(doneCh) - }() + doneCh := make(chan struct{}) + go func() { + mod.WG.Wait() + close(doneCh) + }() - select { - case <-doneCh: - case <-time.After(time.Second): - t.Fatal("timed out") - } + select { + case <-doneCh: + case <-time.After(time.Second): + t.Fatal("timed out") + } - expLog := []string{ - `got event Init with data ''`, - `got event TestStart with data ''`, - `got event TestEnd with data ''`, - `got event Exit with data '&{Error:test aborted: oops! at file:///-:13:14(12)}'`, - `test aborted: oops! at file:///-:13:14(12)`, + log := ts.LoggerHook.Lines() + assert.Equal(t, tc.expLog, log) + }) } - log := ts.LoggerHook.Lines() - assert.Equal(t, expLog, log) } diff --git a/cmd/tests/test_state.go b/cmd/tests/test_state.go index 54e5be13a0e3..1459ed97b7ae 100644 --- a/cmd/tests/test_state.go +++ b/cmd/tests/test_state.go @@ -15,6 +15,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.k6.io/k6/cmd/state" + "go.k6.io/k6/event" "go.k6.io/k6/lib/fsext" "go.k6.io/k6/lib/testutils" "go.k6.io/k6/ui/console" @@ -90,6 +91,7 @@ func NewGlobalTestState(tb testing.TB) *GlobalTestState { BinaryName: "k6", CmdArgs: []string{}, Env: map[string]string{"K6_NO_USAGE_REPORT": "true"}, + Events: event.NewEventSystem(100, logger), DefaultFlags: defaultFlags, Flags: defaultFlags, OutMutex: outMutex,