diff --git a/core/local/eventloop_test.go b/core/local/eventloop_test.go new file mode 100644 index 00000000000..887ab22b525 --- /dev/null +++ b/core/local/eventloop_test.go @@ -0,0 +1,183 @@ +package local + +import ( + "context" + "io/ioutil" + "net/url" + "testing" + "time" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" + "go.k6.io/k6/js" + "go.k6.io/k6/lib" + "go.k6.io/k6/lib/metrics" + "go.k6.io/k6/lib/testutils" + "go.k6.io/k6/lib/types" + "go.k6.io/k6/loader" +) + +func eventLoopTest(t *testing.T, script []byte, testHandle func(context.Context, lib.Runner, error, *testutils.SimpleLogrusHook)) { + logger := logrus.New() + logger.SetOutput(ioutil.Discard) + logHook := &testutils.SimpleLogrusHook{HookedLevels: []logrus.Level{logrus.InfoLevel, logrus.WarnLevel, logrus.ErrorLevel}} + logger.AddHook(logHook) + + script = []byte(`import {setTimeout} from "k6/experimental"; + ` + string(script)) + registry := metrics.NewRegistry() + builtinMetrics := metrics.RegisterBuiltinMetrics(registry) + runner, err := js.New( + logger, + &loader.SourceData{ + URL: &url.URL{Path: "/script.js"}, + Data: script, + }, + nil, + lib.RuntimeOptions{}, + builtinMetrics, + registry, + ) + require.NoError(t, err) + + ctx, cancel, execScheduler, samples := newTestExecutionScheduler(t, runner, logger, + lib.Options{ + TeardownTimeout: types.NullDurationFrom(time.Second), + SetupTimeout: types.NullDurationFrom(time.Second), + }) + defer cancel() + + errCh := make(chan error, 1) + go func() { errCh <- execScheduler.Run(ctx, ctx, samples, builtinMetrics) }() + + select { + case err := <-errCh: + testHandle(ctx, runner, err, logHook) + case <-time.After(10 * time.Second): + t.Fatal("timed out") + } +} + +func TestEventLoop(t *testing.T) { + t.Parallel() + script := []byte(` + setTimeout(()=> {console.log("initcontext setTimeout")}, 200) + console.log("initcontext"); + export default function() { + setTimeout(()=> {console.log("default setTimeout")}, 200) + console.log("default"); + }; + export function setup() { + setTimeout(()=> {console.log("setup setTimeout")}, 200) + console.log("setup"); + }; + export function teardown() { + setTimeout(()=> {console.log("teardown setTimeout")}, 200) + console.log("teardown"); + }; + export function handleSummary() { + setTimeout(()=> {console.log("handleSummary setTimeout")}, 200) + console.log("handleSummary"); + }; +`) + eventLoopTest(t, script, func(ctx context.Context, runner lib.Runner, err error, logHook *testutils.SimpleLogrusHook) { + require.NoError(t, err) + _, err = runner.HandleSummary(ctx, &lib.Summary{RootGroup: &lib.Group{}}) + require.NoError(t, err) + entries := logHook.Drain() + msgs := make([]string, len(entries)) + for i, entry := range entries { + msgs[i] = entry.Message + } + require.Equal(t, []string{ + "initcontext", // first initialization + "initcontext setTimeout", + "initcontext", // for vu + "initcontext setTimeout", + "initcontext", // for setup + "initcontext setTimeout", + "setup", // setup + "setup setTimeout", + "default", // one iteration + "default setTimeout", + "initcontext", // for teardown + "initcontext setTimeout", + "teardown", // teardown + "teardown setTimeout", + "initcontext", // for handleSummary + "initcontext setTimeout", + "handleSummary", // handleSummary + "handleSummary setTimeout", + }, msgs) + }) +} + +func TestEventLoopCrossScenario(t *testing.T) { + t.Parallel() + script := []byte(` +import exec from "k6/execution" +export const options = { + scenarios: { + "first":{ + executor: "shared-iterations", + maxDuration: "1s", + iterations: 1, + vus: 1, + gracefulStop:"1s", + }, + "second": { + executor: "shared-iterations", + maxDuration: "1s", + iterations: 1, + vus: 1, + startTime: "3s", + } + } +} +export default function() { + let i = exec.scenario.name + setTimeout(()=> {console.log(i)}, 3000) +} +`) + + eventLoopTest(t, script, func(_ context.Context, _ lib.Runner, err error, logHook *testutils.SimpleLogrusHook) { + require.NoError(t, err) + entries := logHook.Drain() + msgs := make([]string, len(entries)) + for i, entry := range entries { + msgs[i] = entry.Message + } + require.Equal(t, []string{"second"}, msgs) + }) +} + +func TestEventLoopDoesntCrossIterations(t *testing.T) { + t.Parallel() + script := []byte(` +import { sleep } from "k6" +export const options = { + iterations: 2, + vus: 1, +} + +export default function() { + let i = __ITER; + setTimeout(()=> { console.log(i) }, 1000) + if (__ITER == 0) { + throw "just error" + } else { + sleep(1) + } +} +`) + + eventLoopTest(t, script, func(_ context.Context, _ lib.Runner, err error, logHook *testutils.SimpleLogrusHook) { + require.NoError(t, err) + entries := logHook.Drain() + msgs := make([]string, len(entries)) + for i, entry := range entries { + msgs[i] = entry.Message + } + require.Equal(t, []string{"just error\n\tat /script.js:13:4(15)\n\tat native\n", "1"}, msgs) + }) +} diff --git a/js/bundle.go b/js/bundle.go index c09848f7d8f..d80ec7a2b27 100644 --- a/js/bundle.go +++ b/js/bundle.go @@ -335,7 +335,12 @@ func (b *Bundle) instantiate(logger logrus.FieldLogger, rt *goja.Runtime, init * "require": init.Require, "open": init.Open, }) - if _, err := rt.RunProgram(b.Program); err != nil { + init.moduleVUImpl.eventLoop = newEventLoop(init.moduleVUImpl) + err := init.moduleVUImpl.eventLoop.start(func() error { + _, err := rt.RunProgram(b.Program) + return err + }) + if err != nil { var exception *goja.Exception if errors.As(err, &exception) { err = &scriptException{inner: exception} diff --git a/js/doc.go b/js/doc.go new file mode 100644 index 00000000000..21915fca4c4 --- /dev/null +++ b/js/doc.go @@ -0,0 +1,5 @@ +/* +Package js is the JavaScript implementation of the lib.Runner and relative concepts for +executing concurrent-safe JavaScript code. +*/ +package js diff --git a/js/eventloop.go b/js/eventloop.go new file mode 100644 index 00000000000..77bb712fbca --- /dev/null +++ b/js/eventloop.go @@ -0,0 +1,141 @@ +package js + +import ( + "fmt" + "sync" + + "github.com/dop251/goja" + "go.k6.io/k6/js/modules" +) + +// eventLoop implements an event with +// handling of unhandled rejected promises. +// +// A specific thing about this event loop is that it will wait to return +// not only until the queue is empty but until nothing is registered that it will run in the future. +// This is in contrast with more common behaviours where it only returns on +// a specific event/action or when the loop is empty. +// This is required as in k6 iterations (for which event loop will be primary used) +// are supposed to be independent and any work started in them needs to finish, +// but also they need to end when all the instructions are done. +// Additionally because of this on any error while the event loop will exit it's +// required to wait on the event loop to be empty before the execution can continue. +type eventLoop struct { + lock sync.Mutex + queue []func() error + wakeupCh chan struct{} // TODO: maybe use sync.Cond ? + registeredCallbacks int + vu modules.VU + + // pendingPromiseRejections are rejected promises with no handler, + // if there is something in this map at an end of an event loop then it will exit with an error. + // It's similar to what Deno and Node do. + pendingPromiseRejections map[*goja.Promise]struct{} +} + +// newEventLoop returns a new event loop with a few helpers attached to it: +// - reporting (and aborting on) unhandled promise rejections +func newEventLoop(vu modules.VU) *eventLoop { + e := &eventLoop{ + wakeupCh: make(chan struct{}, 1), + pendingPromiseRejections: make(map[*goja.Promise]struct{}), + vu: vu, + } + vu.Runtime().SetPromiseRejectionTracker(e.promiseRejectionTracker) + + return e +} + +func (e *eventLoop) wakeup() { + select { + case e.wakeupCh <- struct{}{}: + default: + } +} + +// registerCallback register that a callback will be invoked on the loop, preventing it from returning/finishing. +// The returned function, upon invocation, will queue its argument and wakeup the loop if needed. +// If the eventLoop has since stopped, it will not be executed. +// This function *must* be called from within running on the event loop, but its result can be called from anywhere. +func (e *eventLoop) registerCallback() func(func() error) { + e.lock.Lock() + e.registeredCallbacks++ + e.lock.Unlock() + + return func(f func() error) { + e.lock.Lock() + e.queue = append(e.queue, f) + e.registeredCallbacks-- + e.lock.Unlock() + e.wakeup() + } +} + +func (e *eventLoop) promiseRejectionTracker(p *goja.Promise, op goja.PromiseRejectionOperation) { + // No locking necessary here as the goja runtime will call this synchronously + // Read Notes on https://tc39.es/ecma262/#sec-host-promise-rejection-tracker + if op == goja.PromiseRejectionReject { + e.pendingPromiseRejections[p] = struct{}{} + } else { // goja.PromiseRejectionHandle so a promise that was previously rejected without handler now got one + delete(e.pendingPromiseRejections, p) + } +} + +func (e *eventLoop) popAll() (queue []func() error, awaiting bool) { + e.lock.Lock() + queue = e.queue + e.queue = make([]func() error, 0, len(queue)) + awaiting = e.registeredCallbacks != 0 + e.lock.Unlock() + return +} + +// start will run the event loop until it's empty and there are no uninvoked registered callbacks +// or a queued function returns an error. The provided firstCallback will be the first thing executed. +// After start returns the event loop can be reused as long as waitOnRegistered is called. +func (e *eventLoop) start(firstCallback func() error) error { + e.queue = []func() error{firstCallback} + for { + queue, awaiting := e.popAll() + + if len(queue) == 0 { + if !awaiting { + return nil + } + <-e.wakeupCh + continue + } + + for _, f := range queue { + if err := f(); err != nil { + return err + } + } + + // This will get a random unhandled rejection instead of the first one, for example. + // But that seems to be the case in other tools as well so it seems to not be that big of a problem. + for promise := range e.pendingPromiseRejections { + // TODO maybe throw the whole promise up and get make a better message outside of the event loop + value := promise.Result() + if o := value.ToObject(e.vu.Runtime()); o != nil { + stack := o.Get("stack") + if stack != nil { + value = stack + } + } + // this is the de facto wording in both firefox and deno at least + return fmt.Errorf("Uncaught (in promise) %s", value) //nolint:stylecheck + } + } +} + +// Wait on all registered callbacks so we know nothing is still doing work. +func (e *eventLoop) waitOnRegistered() { + for { + _, awaiting := e.popAll() + if !awaiting { + return + } + <-e.wakeupCh + } +} diff --git a/js/eventloop_test.go b/js/eventloop_test.go new file mode 100644 index 00000000000..7fed52b58e5 --- /dev/null +++ b/js/eventloop_test.go @@ -0,0 +1,118 @@ +package js + +import ( + "errors" + "fmt" + "testing" + "time" + + "github.com/dop251/goja" + "github.com/stretchr/testify/require" + "go.k6.io/k6/js/modulestest" +) + +func TestBasicEventLoop(t *testing.T) { + t.Parallel() + loop := newEventLoop(&modulestest.VU{RuntimeField: goja.New()}) + var ran int + f := func() error { //nolint:unparam + ran++ + return nil + } + require.NoError(t, loop.start(f)) + require.Equal(t, 1, ran) + require.NoError(t, loop.start(f)) + require.Equal(t, 2, ran) + require.Error(t, loop.start(func() error { + _ = f() + loop.registerCallback()(f) + return errors.New("something") + })) + require.Equal(t, 3, ran) +} + +func TestEventLoopRegistered(t *testing.T) { + t.Parallel() + loop := newEventLoop(&modulestest.VU{RuntimeField: goja.New()}) + var ran int + f := func() error { + ran++ + r := loop.registerCallback() + go func() { + time.Sleep(time.Second) + r(func() error { + ran++ + return nil + }) + }() + return nil + } + start := time.Now() + require.NoError(t, loop.start(f)) + took := time.Since(start) + require.Equal(t, 2, ran) + require.Less(t, time.Second, took) + require.Greater(t, time.Second+time.Millisecond*100, took) +} + +func TestEventLoopWaitOnRegistered(t *testing.T) { + t.Parallel() + var ran int + loop := newEventLoop(&modulestest.VU{RuntimeField: goja.New()}) + f := func() error { + ran++ + r := loop.registerCallback() + go func() { + time.Sleep(time.Second) + r(func() error { + ran++ + return nil + }) + }() + return fmt.Errorf("expected") + } + start := time.Now() + require.Error(t, loop.start(f)) + took := time.Since(start) + loop.waitOnRegistered() + took2 := time.Since(start) + require.Equal(t, 1, ran) + require.Greater(t, time.Millisecond*50, took) + require.Less(t, time.Second, took2) + require.Greater(t, time.Second+time.Millisecond*100, took2) +} + +func TestEventLoopReuse(t *testing.T) { + t.Parallel() + sleepTime := time.Millisecond * 500 + loop := newEventLoop(&modulestest.VU{RuntimeField: goja.New()}) + f := func() error { + for i := 0; i < 100; i++ { + bad := i == 17 + r := loop.registerCallback() + + go func() { + if !bad { + time.Sleep(sleepTime) + } + r(func() error { + if bad { + return errors.New("something") + } + panic("this should never execute") + }) + }() + } + return fmt.Errorf("expected") + } + for i := 0; i < 3; i++ { + start := time.Now() + require.Error(t, loop.start(f)) + took := time.Since(start) + loop.waitOnRegistered() + took2 := time.Since(start) + require.Greater(t, time.Millisecond*50, took) + require.Less(t, sleepTime, took2) + require.Greater(t, sleepTime+time.Millisecond*100, took2) + } +} diff --git a/js/initcontext.go b/js/initcontext.go index 13670e637a8..9b60b5975ed 100644 --- a/js/initcontext.go +++ b/js/initcontext.go @@ -43,6 +43,7 @@ import ( "go.k6.io/k6/js/modules/k6/data" "go.k6.io/k6/js/modules/k6/encoding" "go.k6.io/k6/js/modules/k6/execution" + "go.k6.io/k6/js/modules/k6/experimental" "go.k6.io/k6/js/modules/k6/grpc" "go.k6.io/k6/js/modules/k6/html" "go.k6.io/k6/js/modules/k6/http" @@ -151,10 +152,11 @@ func (i *InitContext) Require(arg string) goja.Value { } type moduleVUImpl struct { - ctxPtr *context.Context - initEnv *common.InitEnvironment - state *lib.State - runtime *goja.Runtime + ctxPtr *context.Context + initEnv *common.InitEnvironment + state *lib.State + runtime *goja.Runtime + eventLoop *eventLoop } func newModuleVUImpl() *moduleVUImpl { @@ -179,6 +181,29 @@ func (m *moduleVUImpl) Runtime() *goja.Runtime { return m.runtime } +func (m *moduleVUImpl) RegisterCallback() func(func() error) { + return m.eventLoop.registerCallback() +} + +/* This is here to illustrate how to use RegisterCallback to get a promise to work with the event loop +// TODO move this to a common function or remove before merging + +// MakeHandledPromise will create and promise and return it's resolve, reject methods as well wrapped in such a way that +// it will block the eventloop from exiting before they are called even if the promise isn't resolved by the time the +// current script ends executing +func (m *moduleVUImpl) MakeHandledPromise() (*goja.Promise, func(interface{}), func(interface{})) { + callback := m.eventLoop.registerCallback() + p, resolve, reject := m.runtime.NewPromise() + return p, func(i interface{}) { + // more stuff + callback(func() { resolve(i) }) + }, func(i interface{}) { + // more stuff + callback(func() { reject(i) }) + } +} +*/ + func toESModuleExports(exp modules.Exports) interface{} { if exp.Named == nil { return exp.Default @@ -359,17 +384,18 @@ func (i *InitContext) allowOnlyOpenedFiles() { func getInternalJSModules() map[string]interface{} { return map[string]interface{}{ - "k6": k6.New(), - "k6/crypto": crypto.New(), - "k6/crypto/x509": x509.New(), - "k6/data": data.New(), - "k6/encoding": encoding.New(), - "k6/execution": execution.New(), - "k6/net/grpc": grpc.New(), - "k6/html": html.New(), - "k6/http": http.New(), - "k6/metrics": metrics.New(), - "k6/ws": ws.New(), + "k6": k6.New(), + "k6/crypto": crypto.New(), + "k6/crypto/x509": x509.New(), + "k6/data": data.New(), + "k6/encoding": encoding.New(), + "k6/execution": execution.New(), + "k6/net/grpc": grpc.New(), + "k6/html": html.New(), + "k6/http": http.New(), + "k6/metrics": metrics.New(), + "k6/ws": ws.New(), + "k6/experimental": experimental.New(), } } diff --git a/js/modules/k6/experimental/experimental.go b/js/modules/k6/experimental/experimental.go new file mode 100644 index 00000000000..32dce96bce8 --- /dev/null +++ b/js/modules/k6/experimental/experimental.go @@ -0,0 +1,68 @@ +// Package experimental includes experimental module features +package experimental + +import ( + "errors" + "time" + + "github.com/dop251/goja" + "go.k6.io/k6/js/common" + "go.k6.io/k6/js/modules" +) + +type ( + // RootModule is the root experimental module + RootModule struct{} + // ModuleInstance represents an instance of the experimental module + ModuleInstance struct { + vu modules.VU + } +) + +var ( + _ modules.Module = &RootModule{} + _ modules.Instance = &ModuleInstance{} +) + +// NewModuleInstance implements modules.Module interface +func (*RootModule) NewModuleInstance(m modules.VU) modules.Instance { + return &ModuleInstance{vu: m} +} + +// New returns a new RootModule. +func New() *RootModule { + return &RootModule{} +} + +// Exports returns the exports of the experimental module +func (mi *ModuleInstance) Exports() modules.Exports { + return modules.Exports{ + Named: map[string]interface{}{ + "setTimeout": mi.setTimeout, + }, + } +} + +func (mi *ModuleInstance) setTimeout(f goja.Callable, t float64) { + if f == nil { + common.Throw(mi.vu.Runtime(), errors.New("setTimeout requires a function as first argument")) + } + // TODO maybe really return something to use with `clearTimeout + // TODO support arguments ... maybe + runOnLoop := mi.vu.RegisterCallback() + go func() { + timer := time.NewTimer(time.Duration(t * float64(time.Millisecond))) + select { + case <-timer.C: + runOnLoop(func() error { + _, err := f(goja.Undefined()) + return err + }) + case <-mi.vu.Context().Done(): + // TODO log something? + + timer.Stop() + runOnLoop(func() error { return nil }) + } + }() +} diff --git a/js/modules/modules.go b/js/modules/modules.go index 6e2041b94fc..eb8087f86fe 100644 --- a/js/modules/modules.go +++ b/js/modules/modules.go @@ -107,6 +107,24 @@ type VU interface { // Runtime returns the goja.Runtime for the current VU Runtime() *goja.Runtime + + // RegisterCallback lets a module declare that it wants to run a function on the event loop *at a later point in time*. + // It needs to be called from within the event loop, so not in a goroutine spawned by a module. + // Its result can be called with a function that will be executed *on the event loop* - + // possibly letting you call RegisterCallback again. + // Calling the result can be done at any time. The event loop will block until that happens, (if it doesn't + // have something else to run) so in the event of an iteration end or abort (for example due to an exception), + // It is the module responsibility to monitor the context and abort on it being done. + // This still means that the returned function here *needs* to be called to signal that the module + // has aborted the operation and will not do anything more, not doing so will block k6. + // + // Experimental + // + // Notice: This API is EXPERIMENTAL and may be changed or removed in a later release. + RegisterCallback() func(func() error) + + // sealing field will help probably with pointing users that they just need to embed this in their Instance + // implementations } // Exports is representation of ESM exports of a module diff --git a/js/modulestest/modulestest.go b/js/modulestest/modulestest.go index cf3574d5cfa..03519a7cb60 100644 --- a/js/modulestest/modulestest.go +++ b/js/modulestest/modulestest.go @@ -58,3 +58,9 @@ func (m *VU) State() *lib.State { func (m *VU) Runtime() *goja.Runtime { return m.RuntimeField } + +// RegisterCallback is not really implemented +func (m *VU) RegisterCallback() func(f func() error) { + // TODO Implement + return nil +} diff --git a/js/runner.go b/js/runner.go index 6f509aa9911..80aad46cd5f 100644 --- a/js/runner.go +++ b/js/runner.go @@ -403,7 +403,7 @@ func (r *Runner) HandleSummary(ctx context.Context, summary *lib.Summary) (map[s vu.Runtime.ToValue(r.Bundle.RuntimeOptions.SummaryExport.String), vu.Runtime.ToValue(summaryDataForJS), } - rawResult, _, _, err := vu.runFn(ctx, false, handleSummaryWrapper, wrapperArgs...) + rawResult, _, _, err := vu.runFn(ctx, false, handleSummaryWrapper, nil, wrapperArgs...) // TODO: refactor the whole JS runner to avoid copy-pasting these complicated bits... // deadline is reached so we have timeouted but this might've not been registered correctly @@ -535,7 +535,7 @@ func (r *Runner) runPart(ctx context.Context, out chan<- stats.SampleContainer, } vu.state.Group = group - v, _, _, err := vu.runFn(ctx, false, fn, vu.Runtime.ToValue(arg)) + v, _, _, err := vu.runFn(ctx, false, fn, nil, vu.Runtime.ToValue(arg)) // deadline is reached so we have timeouted but this might've not been registered correctly if deadline, ok := ctx.Deadline(); ok && time.Now().After(deadline) { @@ -729,8 +729,11 @@ func (u *ActiveVU) RunOnce() error { panic(fmt.Errorf("error setting __ITER in goja runtime: %w", err)) } + ctx, cancel := context.WithCancel(u.RunContext) + defer cancel() + *u.moduleVUImpl.ctxPtr = ctx // Call the exported function. - _, isFullIteration, totalTime, err := u.runFn(u.RunContext, true, fn, u.setupData) + _, isFullIteration, totalTime, err := u.runFn(ctx, true, fn, cancel, u.setupData) if err != nil { var x *goja.InterruptedError if errors.As(err, &x) { @@ -756,8 +759,10 @@ func (u *ActiveVU) RunOnce() error { return err } +// if isDefault is true, cancel also needs to be provided and it should cancel the provided context +// TODO remove the need for the above through refactoring of this function and its callees func (u *VU) runFn( - ctx context.Context, isDefault bool, fn goja.Callable, args ...goja.Value, + ctx context.Context, isDefault bool, fn goja.Callable, cancel func(), args ...goja.Value, ) (v goja.Value, isFullIteration bool, t time.Duration, err error) { if !u.Runner.Bundle.Options.NoCookiesReset.ValueOrZero() { u.state.CookieJar, err = cookiejar.New(nil) @@ -771,29 +776,31 @@ func (u *VU) runFn( u.state.Tags.Set("iter", strconv.FormatInt(u.state.Iteration, 10)) } - 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) - // 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()) - } - }() - startTime := time.Now() - v, err = fn(goja.Undefined(), args...) // Actually run the JS script - endTime := time.Now() - var exception *goja.Exception - if errors.As(err, &exception) { - err = &scriptException{inner: exception} - } + + if u.moduleVUImpl.eventLoop == nil { + u.moduleVUImpl.eventLoop = newEventLoop(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 = fmt.Errorf("a panic occurred in VU code but was caught: %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 + }) select { case <-ctx.Done(): @@ -802,6 +809,16 @@ func (u *VU) runFn( isFullIteration = true } + if cancel != nil { + cancel() + u.moduleVUImpl.eventLoop.waitOnRegistered() + } + endTime := time.Now() + var exception *goja.Exception + if errors.As(err, &exception) { + err = &scriptException{inner: exception} + } + if u.Runner.Bundle.Options.NoVUConnectionReuse.Bool { u.Transport.CloseIdleConnections() }