From 33f575527f6580db24eb8908d4371bf634c98796 Mon Sep 17 00:00:00 2001 From: Oleg Bespalov Date: Tue, 22 Mar 2022 18:38:58 +0100 Subject: [PATCH 1/5] Treat go panics as an interrupt error --- js/runner.go | 3 ++- js/runner_test.go | 10 +++++----- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/js/runner.go b/js/runner.go index f15d071ecc4..5f8592fcba6 100644 --- a/js/runner.go +++ b/js/runner.go @@ -799,7 +799,8 @@ func (u *VU) runFn( defer func() { if r := recover(); r != nil { gojaStack := u.Runtime.CaptureCallStack(20, nil) - err = fmt.Errorf("a panic occurred in VU code but was caught: %s", r) + + err = &common.InterruptError{Reason: fmt.Sprintf("a panic occurred in VU code: %s", r)} // TODO figure out how to use PanicLevel without panicing .. this might require changing // the logger we use see // https://github.com/sirupsen/logrus/issues/1028 diff --git a/js/runner_test.go b/js/runner_test.go index f828095bf3b..3b52bfb0f52 100644 --- a/js/runner_test.go +++ b/js/runner_test.go @@ -1941,7 +1941,7 @@ func TestVUPanic(t *testing.T) { vu.(*ActiveVU).Console.logger = logger.WithField("source", "console") err = vu.RunOnce() require.Error(t, err) - assert.Contains(t, err.Error(), "a panic occurred in VU code but was caught: here we panic") + assert.Contains(t, err.Error(), "a panic occurred in VU code: here we panic") entries := hook.Drain() require.Len(t, entries, 1) assert.Equal(t, logrus.ErrorLevel, entries[0].Level) @@ -2048,16 +2048,16 @@ func TestComplicatedFileImportsForGRPC(t *testing.T) { fs := afero.NewMemMapFs() protoFile, err := ioutil.ReadFile("../vendor/google.golang.org/grpc/test/grpc_testing/test.proto") require.NoError(t, err) - require.NoError(t, afero.WriteFile(fs, "/path/to/service.proto", protoFile, 0644)) + require.NoError(t, afero.WriteFile(fs, "/path/to/service.proto", protoFile, 0o644)) require.NoError(t, afero.WriteFile(fs, "/path/to/same-dir.proto", []byte( `syntax = "proto3";package whatever;import "service.proto";`, - ), 0644)) + ), 0o644)) require.NoError(t, afero.WriteFile(fs, "/path/subdir.proto", []byte( `syntax = "proto3";package whatever;import "to/service.proto";`, - ), 0644)) + ), 0o644)) require.NoError(t, afero.WriteFile(fs, "/path/to/abs.proto", []byte( `syntax = "proto3";package whatever;import "/path/to/service.proto";`, - ), 0644)) + ), 0o644)) grpcTestCase := func(expInitErr, expVUErr bool, cwd, loadCode string) multiFileTestCase { script := tb.Replacer.Replace(fmt.Sprintf(` From fa121456f8bfddaaf3153e11161ccb5cf98b430a Mon Sep 17 00:00:00 2001 From: Oleg Bespalov Date: Wed, 23 Mar 2022 19:25:21 +0100 Subject: [PATCH 2/5] feat: add integration tests, also cover init context panics --- .../workflows/xk6-tests/xk6-js-test/jstest.go | 2 +- cmd/run_test.go | 81 +++++++++++++++++++ js/bundle.go | 22 ++++- js/modules/k6/execution/execution_test.go | 2 +- 4 files changed, 103 insertions(+), 4 deletions(-) diff --git a/.github/workflows/xk6-tests/xk6-js-test/jstest.go b/.github/workflows/xk6-tests/xk6-js-test/jstest.go index 2fd327e0d2d..ba42b3b541e 100644 --- a/.github/workflows/xk6-tests/xk6-js-test/jstest.go +++ b/.github/workflows/xk6-tests/xk6-js-test/jstest.go @@ -48,7 +48,7 @@ func (j *JSTest) Exports() modules.Exports { func (j JSTest) Foo(arg float64) (bool, error) { state := j.vu.State() if state == nil { - return false, fmt.Errorf("the VU State is not avaialble in the init context") + return false, fmt.Errorf("the VU State is not available in the init context") } ctx := j.vu.Context() diff --git a/cmd/run_test.go b/cmd/run_test.go index 1648fcaf9f1..d5e86445c69 100644 --- a/cmd/run_test.go +++ b/cmd/run_test.go @@ -40,6 +40,7 @@ import ( "go.k6.io/k6/errext" "go.k6.io/k6/errext/exitcodes" "go.k6.io/k6/js/common" + "go.k6.io/k6/js/modules" "go.k6.io/k6/lib/fsext" "go.k6.io/k6/lib/testutils" ) @@ -212,3 +213,83 @@ func TestRunScriptErrorsAndAbort(t *testing.T) { }) } } + +// alarmist is a mock module that do a panic +type alarmist struct { + vu modules.VU +} + +var _ modules.Module = &alarmist{} + +func (a *alarmist) NewModuleInstance(vu modules.VU) modules.Instance { + return &alarmist{ + vu: vu, + } +} + +func (a *alarmist) Exports() modules.Exports { + return modules.Exports{ + Named: map[string]interface{}{ + "panic": a.panic, + }, + } +} + +func (a *alarmist) panic(s string) { + panic(s) +} + +func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { + t.Parallel() + + modules.Register("k6/x/alarmist", new(alarmist)) + + testCases := []struct { + caseName, testScript, expectedLogMessage string + }{ + { + caseName: "panic in the VU context", + testScript: ` + import { panic } from 'k6/x/alarmist'; + + export default function() { + panic('hey') + } + `, + expectedLogMessage: "a panic occurred in VU code: hey", + }, + { + caseName: "panic in the init context", + testScript: ` + import { panic } from 'k6/x/alarmist'; + + panic('hey') + export default function() { + console.log('lorem ipsum'); + } + `, + expectedLogMessage: "a panic occurred in the init context code: hey", + }, + } + + for _, tc := range testCases { + tc := tc + name := tc.caseName + + t.Run(name, func(t *testing.T) { + t.Parallel() + + testFilename := "script.js" + testState := newGlobalTestState(t) + require.NoError(t, afero.WriteFile(testState.fs, filepath.Join(testState.cwd, testFilename), []byte(tc.testScript), 0o644)) + testState.args = []string{"k6", "run", testFilename} + + testState.expectedExitCode = int(exitcodes.ScriptAborted) + newRootCommand(testState.globalState).execute() + + logs := testState.loggerHook.Drain() + + assert.True(t, testutils.LogContains(logs, logrus.ErrorLevel, tc.expectedLogMessage)) + }) + } +} diff --git a/js/bundle.go b/js/bundle.go index dba20a7d8e7..9996214407d 100644 --- a/js/bundle.go +++ b/js/bundle.go @@ -28,6 +28,7 @@ import ( "fmt" "net/url" "runtime" + "runtime/debug" "github.com/dop251/goja" "github.com/sirupsen/logrus" @@ -299,7 +300,24 @@ func (b *Bundle) Instantiate( // Instantiates the bundle into an existing runtime. Not public because it also messes with a bunch // of other things, will potentially thrash data and makes a mess in it if the operation fails. -func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init *InitContext, vuID uint64) error { +func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init *InitContext, vuID uint64) (err error) { + defer func() { + if r := recover(); r != nil { + gojaStack := rt.CaptureCallStack(20, nil) + + err = &common.InterruptError{Reason: fmt.Sprintf("a panic occurred in the init context code: %s", r)} + // TODO figure out how to use PanicLevel without panicing .. this might require changing + // the logger we use see + // https://github.com/sirupsen/logrus/issues/1028 + // https://github.com/sirupsen/logrus/issues/993 + b := new(bytes.Buffer) + for _, s := range gojaStack { + s.Write(b) + } + logger.Error("panic: ", r, "\n", string(debug.Stack()), "\nGoja stack:\n", b.String()) + } + }() + rt.SetFieldNameMapper(common.FieldNameMapper{}) rt.SetRandSource(common.NewRandSource()) @@ -333,7 +351,7 @@ func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init * init.moduleVUImpl.ctx = context.Background() unbindInit := b.setInitGlobals(rt, init) init.moduleVUImpl.eventLoop = eventloop.New(init.moduleVUImpl) - err := init.moduleVUImpl.eventLoop.Start(func() error { + err = init.moduleVUImpl.eventLoop.Start(func() error { _, err := rt.RunProgram(b.Program) return err }) diff --git a/js/modules/k6/execution/execution_test.go b/js/modules/k6/execution/execution_test.go index e07e657e98a..e4f8507f971 100644 --- a/js/modules/k6/execution/execution_test.go +++ b/js/modules/k6/execution/execution_test.go @@ -186,7 +186,7 @@ func TestVUTags(t *testing.T) { }) } -func TestAbortTest(t *testing.T) { //nolint: tparallel +func TestAbortTest(t *testing.T) { //nolint:tparallel t.Parallel() var ( From 0b5b4e5770bdca4d2c6539b14bfcabc7ca6db837 Mon Sep 17 00:00:00 2001 From: Oleg Bespalov Date: Thu, 24 Mar 2022 18:03:32 +0100 Subject: [PATCH 3/5] chore: temporary extract tests as file --- cmd/panic_integration_test.go | 98 +++++++++++++++++++++++++++++++++++ cmd/run_test.go | 81 ----------------------------- 2 files changed, 98 insertions(+), 81 deletions(-) create mode 100644 cmd/panic_integration_test.go diff --git a/cmd/panic_integration_test.go b/cmd/panic_integration_test.go new file mode 100644 index 00000000000..8a6a03c0700 --- /dev/null +++ b/cmd/panic_integration_test.go @@ -0,0 +1,98 @@ +package cmd + +// TODO: convert this into the integration tests, once https://github.com/grafana/k6/issues/2459 will be done + +import ( + "path/filepath" + "testing" + + "github.com/sirupsen/logrus" + "github.com/spf13/afero" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.k6.io/k6/errext/exitcodes" + "go.k6.io/k6/js/modules" + "go.k6.io/k6/lib/testutils" +) + +// alarmist is a mock module that do a panic +type alarmist struct { + vu modules.VU +} + +var _ modules.Module = &alarmist{} + +func (a *alarmist) NewModuleInstance(vu modules.VU) modules.Instance { + return &alarmist{ + vu: vu, + } +} + +func (a *alarmist) Exports() modules.Exports { + return modules.Exports{ + Named: map[string]interface{}{ + "panic": a.panic, + }, + } +} + +func (a *alarmist) panic(s string) { + panic(s) +} + +func init() { + modules.Register("k6/x/alarmist", new(alarmist)) +} + +func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { + t.Parallel() + + testCases := []struct { + caseName, testScript, expectedLogMessage string + }{ + { + caseName: "panic in the VU context", + testScript: ` + import { panic } from 'k6/x/alarmist'; + + export default function() { + panic('hey') + } + `, + expectedLogMessage: "a panic occurred in VU code: hey", + }, + { + caseName: "panic in the init context", + testScript: ` + import { panic } from 'k6/x/alarmist'; + + panic('hey') + export default function() { + console.log('lorem ipsum'); + } + `, + expectedLogMessage: "a panic occurred in the init context code: hey", + }, + } + + for _, tc := range testCases { + tc := tc + name := tc.caseName + + t.Run(name, func(t *testing.T) { + t.Parallel() + + testFilename := "script.js" + testState := newGlobalTestState(t) + require.NoError(t, afero.WriteFile(testState.fs, filepath.Join(testState.cwd, testFilename), []byte(tc.testScript), 0o644)) + testState.args = []string{"k6", "run", testFilename} + + testState.expectedExitCode = int(exitcodes.ScriptAborted) + newRootCommand(testState.globalState).execute() + + logs := testState.loggerHook.Drain() + + assert.True(t, testutils.LogContains(logs, logrus.ErrorLevel, tc.expectedLogMessage)) + }) + } +} diff --git a/cmd/run_test.go b/cmd/run_test.go index d5e86445c69..1648fcaf9f1 100644 --- a/cmd/run_test.go +++ b/cmd/run_test.go @@ -40,7 +40,6 @@ import ( "go.k6.io/k6/errext" "go.k6.io/k6/errext/exitcodes" "go.k6.io/k6/js/common" - "go.k6.io/k6/js/modules" "go.k6.io/k6/lib/fsext" "go.k6.io/k6/lib/testutils" ) @@ -213,83 +212,3 @@ func TestRunScriptErrorsAndAbort(t *testing.T) { }) } } - -// alarmist is a mock module that do a panic -type alarmist struct { - vu modules.VU -} - -var _ modules.Module = &alarmist{} - -func (a *alarmist) NewModuleInstance(vu modules.VU) modules.Instance { - return &alarmist{ - vu: vu, - } -} - -func (a *alarmist) Exports() modules.Exports { - return modules.Exports{ - Named: map[string]interface{}{ - "panic": a.panic, - }, - } -} - -func (a *alarmist) panic(s string) { - panic(s) -} - -func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { - t.Parallel() - - modules.Register("k6/x/alarmist", new(alarmist)) - - testCases := []struct { - caseName, testScript, expectedLogMessage string - }{ - { - caseName: "panic in the VU context", - testScript: ` - import { panic } from 'k6/x/alarmist'; - - export default function() { - panic('hey') - } - `, - expectedLogMessage: "a panic occurred in VU code: hey", - }, - { - caseName: "panic in the init context", - testScript: ` - import { panic } from 'k6/x/alarmist'; - - panic('hey') - export default function() { - console.log('lorem ipsum'); - } - `, - expectedLogMessage: "a panic occurred in the init context code: hey", - }, - } - - for _, tc := range testCases { - tc := tc - name := tc.caseName - - t.Run(name, func(t *testing.T) { - t.Parallel() - - testFilename := "script.js" - testState := newGlobalTestState(t) - require.NoError(t, afero.WriteFile(testState.fs, filepath.Join(testState.cwd, testFilename), []byte(tc.testScript), 0o644)) - testState.args = []string{"k6", "run", testFilename} - - testState.expectedExitCode = int(exitcodes.ScriptAborted) - newRootCommand(testState.globalState).execute() - - logs := testState.loggerHook.Drain() - - assert.True(t, testutils.LogContains(logs, logrus.ErrorLevel, tc.expectedLogMessage)) - }) - } -} From f1b7cfae05554c2001ddd9e817cc003646c0783a Mon Sep 17 00:00:00 2001 From: Oleg Bespalov Date: Fri, 25 Mar 2022 11:15:14 +0100 Subject: [PATCH 4/5] chore: check if code interrupts --- cmd/panic_integration_test.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/cmd/panic_integration_test.go b/cmd/panic_integration_test.go index 8a6a03c0700..d3aec0be886 100644 --- a/cmd/panic_integration_test.go +++ b/cmd/panic_integration_test.go @@ -56,7 +56,8 @@ func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { import { panic } from 'k6/x/alarmist'; export default function() { - panic('hey') + panic('hey'); + console.log('lorem ipsum'); } `, expectedLogMessage: "a panic occurred in VU code: hey", @@ -66,7 +67,7 @@ func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { testScript: ` import { panic } from 'k6/x/alarmist'; - panic('hey') + panic('hey'); export default function() { console.log('lorem ipsum'); } @@ -93,6 +94,7 @@ func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { logs := testState.loggerHook.Drain() assert.True(t, testutils.LogContains(logs, logrus.ErrorLevel, tc.expectedLogMessage)) + assert.False(t, testutils.LogContains(logs, logrus.InfoLevel, "lorem ipsum")) }) } } From 24d5940c09a9ee3fc54e6ad843913387d492fca7 Mon Sep 17 00:00:00 2001 From: Oleg Bespalov Date: Fri, 25 Mar 2022 14:04:13 +0100 Subject: [PATCH 5/5] chore: implement panic catcher as the helper --- cmd/panic_integration_test.go | 4 ++-- js/bundle.go | 27 ++++++--------------------- js/common/util.go | 24 ++++++++++++++++++++++++ js/runner.go | 27 +++++---------------------- js/runner_test.go | 2 +- 5 files changed, 38 insertions(+), 46 deletions(-) diff --git a/cmd/panic_integration_test.go b/cmd/panic_integration_test.go index d3aec0be886..19b17f4d0bf 100644 --- a/cmd/panic_integration_test.go +++ b/cmd/panic_integration_test.go @@ -60,7 +60,7 @@ func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { console.log('lorem ipsum'); } `, - expectedLogMessage: "a panic occurred in VU code: hey", + expectedLogMessage: "a panic occurred during JS execution: hey", }, { caseName: "panic in the init context", @@ -72,7 +72,7 @@ func TestRunScriptPanicsErrorsAndAbort(t *testing.T) { console.log('lorem ipsum'); } `, - expectedLogMessage: "a panic occurred in the init context code: hey", + expectedLogMessage: "a panic occurred during JS execution: hey", }, } diff --git a/js/bundle.go b/js/bundle.go index 9996214407d..dd5f0aaea8a 100644 --- a/js/bundle.go +++ b/js/bundle.go @@ -28,7 +28,6 @@ import ( "fmt" "net/url" "runtime" - "runtime/debug" "github.com/dop251/goja" "github.com/sirupsen/logrus" @@ -301,23 +300,6 @@ func (b *Bundle) Instantiate( // Instantiates the bundle into an existing runtime. Not public because it also messes with a bunch // of other things, will potentially thrash data and makes a mess in it if the operation fails. func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init *InitContext, vuID uint64) (err error) { - defer func() { - if r := recover(); r != nil { - gojaStack := rt.CaptureCallStack(20, nil) - - err = &common.InterruptError{Reason: fmt.Sprintf("a panic occurred in the init context code: %s", r)} - // TODO figure out how to use PanicLevel without panicing .. this might require changing - // the logger we use see - // https://github.com/sirupsen/logrus/issues/1028 - // https://github.com/sirupsen/logrus/issues/993 - b := new(bytes.Buffer) - for _, s := range gojaStack { - s.Write(b) - } - logger.Error("panic: ", r, "\n", string(debug.Stack()), "\nGoja stack:\n", b.String()) - } - }() - rt.SetFieldNameMapper(common.FieldNameMapper{}) rt.SetRandSource(common.NewRandSource()) @@ -351,10 +333,13 @@ func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init * init.moduleVUImpl.ctx = context.Background() unbindInit := b.setInitGlobals(rt, init) init.moduleVUImpl.eventLoop = eventloop.New(init.moduleVUImpl) - err = init.moduleVUImpl.eventLoop.Start(func() error { - _, err := rt.RunProgram(b.Program) - return err + err = common.RunWithPanicCatching(logger, rt, func() error { + return init.moduleVUImpl.eventLoop.Start(func() error { + _, errRun := rt.RunProgram(b.Program) + return errRun + }) }) + if err != nil { var exception *goja.Exception if errors.As(err, &exception) { diff --git a/js/common/util.go b/js/common/util.go index 9ec525ddde7..82bdd5e9e63 100644 --- a/js/common/util.go +++ b/js/common/util.go @@ -24,8 +24,10 @@ import ( "bytes" "fmt" "io" + "runtime/debug" "github.com/dop251/goja" + "github.com/sirupsen/logrus" ) // Throw a JS error; avoids re-wrapping GoErrors. @@ -79,3 +81,25 @@ func ToString(data interface{}) (string, error) { return "", fmt.Errorf("invalid type %T, expected string, []byte or ArrayBuffer", data) } } + +// RunWithPanicCatching catches panic and converts into an InterruptError error that should abort a script +func RunWithPanicCatching(logger logrus.FieldLogger, rt *goja.Runtime, fn func() error) (err error) { + defer func() { + if r := recover(); r != nil { + gojaStack := rt.CaptureCallStack(20, nil) + + err = &InterruptError{Reason: fmt.Sprintf("a panic occurred during JS execution: %s", r)} + // TODO figure out how to use PanicLevel without panicing .. this might require changing + // the logger we use see + // https://github.com/sirupsen/logrus/issues/1028 + // https://github.com/sirupsen/logrus/issues/993 + b := new(bytes.Buffer) + for _, s := range gojaStack { + s.Write(b) + } + logger.Error("panic: ", r, "\n", string(debug.Stack()), "\nGoja stack:\n", b.String()) + } + }() + + return fn() +} diff --git a/js/runner.go b/js/runner.go index 5f8592fcba6..70bc032b7da 100644 --- a/js/runner.go +++ b/js/runner.go @@ -21,7 +21,6 @@ package js import ( - "bytes" "context" "crypto/tls" "encoding/json" @@ -32,7 +31,6 @@ import ( "net/http" "net/http/cookiejar" "os" - "runtime/debug" "strconv" "strings" "sync" @@ -794,26 +792,11 @@ func (u *VU) runFn( if u.moduleVUImpl.eventLoop == nil { u.moduleVUImpl.eventLoop = eventloop.New(u.moduleVUImpl) } - err = u.moduleVUImpl.eventLoop.Start(func() (err error) { - // here the returned value purposefully shadows the external one as they can be different - defer func() { - if r := recover(); r != nil { - gojaStack := u.Runtime.CaptureCallStack(20, nil) - - err = &common.InterruptError{Reason: fmt.Sprintf("a panic occurred in VU code: %s", r)} - // TODO figure out how to use PanicLevel without panicing .. this might require changing - // the logger we use see - // https://github.com/sirupsen/logrus/issues/1028 - // https://github.com/sirupsen/logrus/issues/993 - b := new(bytes.Buffer) - for _, s := range gojaStack { - s.Write(b) - } - u.state.Logger.Log(logrus.ErrorLevel, "panic: ", r, "\n", string(debug.Stack()), "\nGoja stack:\n", b.String()) - } - }() - v, err = fn(goja.Undefined(), args...) // Actually run the JS script - return err + err = common.RunWithPanicCatching(u.state.Logger, u.Runtime, func() error { + return u.moduleVUImpl.eventLoop.Start(func() (err error) { + v, err = fn(goja.Undefined(), args...) // Actually run the JS script + return err + }) }) select { diff --git a/js/runner_test.go b/js/runner_test.go index 3b52bfb0f52..3edb27e0f01 100644 --- a/js/runner_test.go +++ b/js/runner_test.go @@ -1941,7 +1941,7 @@ func TestVUPanic(t *testing.T) { vu.(*ActiveVU).Console.logger = logger.WithField("source", "console") err = vu.RunOnce() require.Error(t, err) - assert.Contains(t, err.Error(), "a panic occurred in VU code: here we panic") + assert.Contains(t, err.Error(), "a panic occurred during JS execution: here we panic") entries := hook.Drain() require.Len(t, entries, 1) assert.Equal(t, logrus.ErrorLevel, entries[0].Level)