From 6436d4afeef1e8d25ed0eb0e2f926e8b9ae1745e Mon Sep 17 00:00:00 2001 From: Mihail Stoykov Date: Thu, 28 Oct 2021 15:06:56 +0300 Subject: [PATCH] Add basic event loop with an API to be used by modules As well as cut down setTimeout implementation. A recent update to goja introduced support for ECMAscript Promise. The catch here is that Promise's then will only be called when goja exits executing js code and it has already been resolved. Also resolving and rejecting Promises needs to happen while no other js code is being executed as it will otherwise lead to a data race. This more or less necessitates adding an event loop. Additionally because a call to a k6 modules such as `k6/http` might make a promise to signal when an http request is made, but if (no changes were made) the iteration then finishes before the request completes, nothing would've stopped the start of a *new* iteration, which would probably just again ask k6/http to make a new request and return Promise. This might be a desirable behaviour for some cases but arguably will be very confusing so this commit also adds a way to Reserve(name should be changed) a place on the queue so that the event loop will not let the iteration finish until it gets unreserved. Additionally to that, some additional code was needed so there is an event loop for all special functions calls (setup, teardown, handleSummary, default) and the init context. This also adds handling of rejected promise which don't have a reject handler similar to what deno does. It also adds a per iteration context that gets canceled on the end of each iteration letting other code know that it needs to stop. This is particularly needed here as if an iteration gets aborted by a syntax error (or unhandled promise rejection), a new iteration will start right after that. But this means that any in-flight asynchronous operation (an http requests for example) will *not* get stopped. With a context that gets canceled every time module code can notice that and abort any operation. For this same reason the event loop need to be waited to be *empty* before the iteration ends. This did lead to some ... not very nice code, but a whole package needs a big refactor which will likely happen once common.Bind and co gets removed. And finally, a basic setTimeout implementation was added. There is no way to currently cancel the setTimeout aka no clearTimeout. This likely needs to be extended but this can definitely wait. Or we might decide to actually drop setTimeout. fixes #882 --- core/local/eventloop_test.go | 237 ++++++++++++++++++++++++++++++++++ js/bundle.go | 7 +- js/eventloop.go | 166 ++++++++++++++++++++++++ js/eventloop_test.go | 81 ++++++++++++ js/initcontext.go | 36 +++++- js/modules/modules.go | 15 +++ js/modulestest/modulestest.go | 6 + js/runner.go | 58 +++++---- 8 files changed, 578 insertions(+), 28 deletions(-) create mode 100644 core/local/eventloop_test.go create mode 100644 js/eventloop.go create mode 100644 js/eventloop_test.go diff --git a/core/local/eventloop_test.go b/core/local/eventloop_test.go new file mode 100644 index 00000000000..239dbfa7df7 --- /dev/null +++ b/core/local/eventloop_test.go @@ -0,0 +1,237 @@ +package local + +import ( + "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 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"); + }; +`) + + logger := logrus.New() + logger.SetOutput(ioutil.Discard) + logHook := testutils.SimpleLogrusHook{HookedLevels: []logrus.Level{logrus.InfoLevel}} + logger.AddHook(&logHook) + + 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: + 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) + case <-time.After(10 * time.Second): + t.Fatal("timed out") + } +} + +func TestEventLoopCrossScenario(t *testing.T) { + t.Parallel() + // TODO refactor the repeating parts here and the previous test + 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) +} +`) + + logger := logrus.New() + logger.SetOutput(ioutil.Discard) + logHook := testutils.SimpleLogrusHook{HookedLevels: []logrus.Level{logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel}} + logger.AddHook(&logHook) + + 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) + options := runner.GetOptions() + + ctx, cancel, execScheduler, samples := newTestExecutionScheduler(t, runner, logger, options) + defer cancel() + + errCh := make(chan error, 1) + go func() { errCh <- execScheduler.Run(ctx, ctx, samples, builtinMetrics) }() + + select { + case err := <-errCh: + 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) + case <-time.After(10 * time.Second): + t.Fatal("timed out") + } +} + +func TestEventLoopCrossIterations(t *testing.T) { + t.Parallel() + // TODO refactor the repeating parts here and the previous test + 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) + } +} +`) + + logger := logrus.New() + logger.SetOutput(ioutil.Discard) + logHook := testutils.SimpleLogrusHook{HookedLevels: []logrus.Level{logrus.InfoLevel, logrus.WarnLevel, logrus.ErrorLevel}} + logger.AddHook(&logHook) + + 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) + options := runner.GetOptions() + + ctx, cancel, execScheduler, samples := newTestExecutionScheduler(t, runner, logger, options) + defer cancel() + + errCh := make(chan error, 1) + go func() { errCh <- execScheduler.Run(ctx, ctx, samples, builtinMetrics) }() + + select { + case err := <-errCh: + 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:12:4(13)\n\tat native\n", "1"}, msgs) + case <-time.After(10 * time.Second): + t.Fatal("timed out") + } +} diff --git a/js/bundle.go b/js/bundle.go index dc6bac545fb..76a896243c3 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.initHelpers(ctx, rt) + 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/eventloop.go b/js/eventloop.go new file mode 100644 index 00000000000..bd42c436a8a --- /dev/null +++ b/js/eventloop.go @@ -0,0 +1,166 @@ +package js + +import ( + "context" + "fmt" + "sync" + "time" + + "github.com/dop251/goja" +) + +// an event loop +type eventLoop struct { + lock sync.Mutex + queue []func() error + wakeupCh chan struct{} // maybe use sync.Cond ? + reservedCount int + + // a map of promises which were rejected with no handler + // if there is something in this map at an end of a eventLoop + // the loop will exit with an error. This is a kin to what deno and node do + pendingPromiseRejections map[*goja.Promise]struct{} +} + +func newEventLoop() *eventLoop { + return &eventLoop{ + wakeupCh: make(chan struct{}, 1), + } +} + +func (e *eventLoop) wakeup() { + select { + case e.wakeupCh <- struct{}{}: + default: + } +} + +// reserve "reserves" a spot on the loop, preventing it from returning/finishing. The returning function will queue it's +// argument and wakeup the loop if needed. +// If the eventLoop has since stopped it will not be execeted +// This function *must* be called from within running on the event loop, but it's result can be called from anywhere +// TODO better name +func (e *eventLoop) reserve() func(func() error) { + e.lock.Lock() + e.reservedCount++ + e.lock.Unlock() + + return func(f func() error) { + e.lock.Lock() + e.queue = append(e.queue, f) + e.reservedCount-- + e.lock.Unlock() + e.wakeup() + } +} + +func (e *eventLoop) promiseRejectionTracker(p *goja.Promise, op goja.PromiseRejectionOperation) { + // No locking here as the goja runtime will call this synchrnously + // 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) + } +} + +// initHelpers initializes some helpers around the runtime and the event loop +// - adding setTimeout +// - reporting (and aborting on) unhandled promise rejection +func (e *eventLoop) initHelpers(ctx context.Context, rt *goja.Runtime) { + rt.SetPromiseRejectionTracker(e.promiseRejectionTracker) + e.addSetTimeout(ctx, rt) +} + +// start will run the event loop until it's empty and there are no reserved spots +// or a queued function returns an error. The provided function will be the first thing executed. +// After start returns the event loop should not be reused if an error was returend +func (e *eventLoop) start(f func() error) error { + // TODO this block can be moved to newEventLoop if we are never going to reuse an event loop + e.lock.Lock() + e.reservedCount = 0 + e.queue = []func() error{f} + e.pendingPromiseRejections = make(map[*goja.Promise]struct{}, len(e.pendingPromiseRejections)) + e.lock.Unlock() + for { + // acquire the queue + e.lock.Lock() + queue := e.queue + e.queue = make([]func() error, 0, len(queue)) + reserved := e.reservedCount != 0 + e.lock.Unlock() + + if len(queue) == 0 { + if !reserved { // we have empty queue and nothing that reserved a spot + return nil + } + <-e.wakeupCh // wait until the reserved is done + continue + } + + for _, f := range queue { + if err := f(); err != nil { + return err + } + } + + // yes it will be at random but that seems to be the case in other tools as well + 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() + // try to get the stack without actually needing the runtime + // this might break in the future :( + if o, ok := promise.Result().(*goja.Object); ok { + 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 + } + } +} + +// this exists so we can wait on all reserved so we know nothing is still doing work +func (e *eventLoop) waitOnReserved() { + for { + // acquire the queue + e.lock.Lock() + queue := e.queue + e.queue = make([]func() error, 0, len(queue)) + reserved := e.reservedCount != 0 + e.lock.Unlock() + + if len(queue) == 0 { + if !reserved { // we have empty queue and nothing that reserved a spot + return + } + <-e.wakeupCh // wait until the reserved is done + continue + } + + // don't actually do anything we just want to go through them + } +} + +func (e *eventLoop) addSetTimeout(ctx context.Context, rt *goja.Runtime) { + _ = rt.Set("setTimeout", func(f func() error, t float64) { + // TODO checks and fixes + // TODO maybe really return something to use with `clearTimeout + // TODO support arguments ... maybe + runOnLoop := e.reserve() + go func() { + timer := time.NewTimer(time.Duration(t * float64(time.Millisecond))) + select { + case <-timer.C: + runOnLoop(f) + case <-ctx.Done(): + // TODO log something? + + timer.Stop() + runOnLoop(func() error { return nil }) + } + }() + }) +} diff --git a/js/eventloop_test.go b/js/eventloop_test.go new file mode 100644 index 00000000000..0c7988e1a3a --- /dev/null +++ b/js/eventloop_test.go @@ -0,0 +1,81 @@ +package js + +import ( + "errors" + "fmt" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestBasicEventLoop(t *testing.T) { + t.Parallel() + loop := newEventLoop() + 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.reserve()(f) + return errors.New("something") + })) + require.Equal(t, 3, ran) +} + +func TestEventLoopReserve(t *testing.T) { + t.Parallel() + loop := newEventLoop() + var ran int + f := func() error { + ran++ + r := loop.reserve() + 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 TestEventLoopWaitOnReserved(t *testing.T) { + t.Parallel() + loop := newEventLoop() + var ran int + f := func() error { + ran++ + r := loop.reserve() + 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.waitOnReserved() + 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) +} diff --git a/js/initcontext.go b/js/initcontext.go index 3eab0d553e7..12741164bee 100644 --- a/js/initcontext.go +++ b/js/initcontext.go @@ -99,6 +99,7 @@ func NewInitContext( modules: getJSModules(), moduleVUImpl: &moduleVUImpl{ ctxPtr: ctxPtr, runtime: rt, + eventLoop: newEventLoop(), }, } } @@ -150,15 +151,17 @@ 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 { return &moduleVUImpl{ - ctxPtr: new(context.Context), + ctxPtr: new(context.Context), + eventLoop: newEventLoop(), } } @@ -178,6 +181,29 @@ func (m *moduleVUImpl) Runtime() *goja.Runtime { return m.runtime } +func (m *moduleVUImpl) Reserve() func(func() error) { + return m.eventLoop.reserve() +} + +/* This is here to illustrate how to use Reserve 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{})) { + reserved := m.eventLoop.reserve() + p, resolve, reject := m.runtime.NewPromise() + return p, func(i interface{}) { + // more stuff + reserved(func() { resolve(i) }) + }, func(i interface{}) { + // more stuff + reserved(func() { reject(i) }) + } +} +*/ + func toESModuleExports(exp modules.Exports) interface{} { if exp.Named == nil { return exp.Default diff --git a/js/modules/modules.go b/js/modules/modules.go index acff2edfa27..59ee1d497b2 100644 --- a/js/modules/modules.go +++ b/js/modules/modules.go @@ -114,6 +114,21 @@ type VU interface { // Runtime returns the goja.Runtime for the current VU Runtime() *goja.Runtime + + // Reserve lets a module say that it wants to run a function on the event loop *later*. + // It needs to be called from within the event loop - aka in js->go call *before* works is offloaded + // to a goroutine. + // Its result can be called with a function that will be executed *on the event loop* - + // possibly letting you call Reserve again. + // That (calling the result) can be done at any time. The event loop will block until that happens, + // 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. + Reserve() 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..481e9f877d6 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 } + +// Reserve is not really implemented +func (m *VU) Reserve() func(f func() error) { + // TODO Implement + return nil +} diff --git a/js/runner.go b/js/runner.go index 6f509aa9911..64ad0b3a212 100644 --- a/js/runner.go +++ b/js/runner.go @@ -150,7 +150,7 @@ func (r *Runner) NewVU(idLocal, idGlobal uint64, samplesOut chan<- stats.SampleC // nolint:funlen func (r *Runner) newVU(idLocal, idGlobal uint64, samplesOut chan<- stats.SampleContainer) (*VU, error) { // Instantiate a new bundle, make a VU out of it. - moduleVUImpl := &moduleVUImpl{ctxPtr: new(context.Context)} + moduleVUImpl := &moduleVUImpl{ctxPtr: new(context.Context), eventLoop: newEventLoop()} bi, err := r.Bundle.Instantiate(r.Logger, idLocal, moduleVUImpl) if err != nil { return nil, err @@ -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) { @@ -757,7 +760,7 @@ func (u *ActiveVU) RunOnce() error { } 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,24 +774,35 @@ 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 + + // TODO: we can optimize this to only make a new one if the previous one errored out + u.moduleVUImpl.eventLoop = newEventLoop() + u.moduleVUImpl.eventLoop.initHelpers(ctx, u.Runtime) + err = u.moduleVUImpl.eventLoop.start(func() (err error) { + // here the returned value purposefully shadows the external one as they can 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 + }) + if isDefault && err != nil { + cancel() + u.moduleVUImpl.eventLoop.waitOnReserved() + } endTime := time.Now() var exception *goja.Exception if errors.As(err, &exception) {