Inconsistent behavior of exec.test.abort within a group

[pomeh]

Brief summary

If I use exec.test.abort inside a group call, the k6 script exits immediately, that's OK.

But I got the exit code 0, while the documentation says it should be 108:

abort([String])
function
It aborts the test run with the exit code 108, and an optional string parameter can provide an error message. Aborting the test will not prevent the teardown() execution.

When I move the exec.test.abort call outside of the group, the exit code is 108 (what I expect).

k6 version

0.42.0

OS

Ubuntu 20.04

Docker version and image (if applicable)

docker.io/grafana/k6:0.42.0

Steps to reproduce the problem

Having 2 files:

abort-main.js

import exec from 'k6/execution';

export default function () {
    exec.test.abort("failed message from main");
    console.log("will not be visible");
}

abort-group.js

import exec from 'k6/execution';
import { group } from "k6";

export default function () {
    group("some group", () => {
        exec.test.abort("failed message from group");
        console.log("will not be visible");
    });

    console.log("will not be visible either");
}

And then, run k6 with both file, using docker.io/grafana/k6:0.42.0 Docker image, and finally get the exit code ($?), like this:

docker run --rm -v $(pwd)/:/usr/local/me docker.io/grafana/k6:0.42.0 run /usr/local/me/my-file.js ; echo "exit code is:" $?

Expected behaviour

I expect following results:

1. both test failed
2. the exit code is 108
3. the log messages will not be visible and will not be visible either are not present
4. the error messages failed message from main and failed message from group are visible

Actual behaviour

abort-main.js

$ docker run --rm -v $(pwd)/:/usr/local/me docker.io/grafana/k6:0.42.0 run /usr/local/me/abort-main.js ; echo "exit code is:" $?

          /\      |‾‾| /‾‾/   /‾‾/  
     /\  /  \     |  |/  /   /  /   
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: /usr/local/me/abort-main.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)


running (00m00.0s), 0/1 VUs, 0 complete and 1 interrupted iterations
default ✗ [ 100% ] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     iteration_duration...: avg=36.8µs min=36.8µs med=36.8µs max=36.8µs p(90)=36.8µs p(95)=36.8µs
     iterations...........: 1   10183.506792/s

exit code is: 108

results

1. ✅ test failed (it's OK because we get default ✗ message)
2. ✅ the exit code is 108
3. ✅ the log messages will not be visible and will not be visible either are not present
4. ❌ the error message failed message from main is visible (text is missing in the output)

abort-group.js

$ docker run --rm -v $(pwd)/:/usr/local/me docker.io/grafana/k6:0.42.0 run /usr/local/me/abort-group.js ; echo "exit code is:" $?

          /\      |‾‾| /‾‾/   /‾‾/  
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: /usr/local/me/abort-group.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

time="2023-01-12T16:50:42Z" level=error msg="GoError: test aborted: failed message from group at file:///usr/local/me/abort-group.js:6:24(7)\n\tat go.k6.io/k6/js/modules/k6.(*K6).Group-fm (native)\n\tat file:///usr/local/me/abort-group.js:5:4(5)\n\tat native\n" executor=per-vu-iterations scenario=default source=stacktrace

running (00m00.0s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [ 100% ] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU

     █ some group

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     group_duration.......: avg=18.37µs min=18.37µs med=18.37µs max=18.37µs p(90)=18.37µs p(95)=18.37µs
     iteration_duration...: avg=72.52µs min=72.52µs med=72.52µs max=72.52µs p(90)=72.52µs p(95)=72.52µs
     iterations...........: 1   5404.032489/s

exit code is: 0

results

1. ❌ test failed (it's KO because we get default ✓ message)
2. ❌ the exit code is 0
3. ✅ the log messages will not be visible and will not be visible either are not present
4. ✅ the error message failed message from group is visible

[na--]

Thanks for reporting this, I just tried it and can confirm it's a bug 😞

[na--]

Something quite weird is going on 😕 The problem disappears when I try to run the test with 2 iterations, i.e. k6 exits with 108 even if the test is aborted in the middle of a group() call...

We'll need to do some digging to figure out exactly what is causing this, but my bet is that our group() function, which nests together multiple layers of Go and JS code, is not playing well with how we Interrupt() the goja Runtime 🤔

k6/js/modules/k6/execution/execution.go

Lines 168 to 176 in 60b8b15

	"abort": func() interface{} {
	return func(msg goja.Value) {
	reason := errext.AbortTest
	if msg != nil && !goja.IsUndefined(msg) {
	reason = fmt.Sprintf("%s: %s", reason, msg.String())
	}
	rt.Interrupt(&errext.InterruptError{Reason: reason})
	}
	},

k6/js/modules/k6/k6.go

Lines 87 to 138 in 60b8b15

	// Group wraps a function call and executes it within the provided group name.
	func (mi *K6) Group(name string, fn goja.Callable) (goja.Value, error) {
	state := mi.vu.State()
	if state == nil {
	return nil, ErrGroupInInitContext
	}
	if fn == nil {
	return nil, errors.New("group() requires a callback as a second argument")
	}
	g, err := state.Group.Group(name)
	if err != nil {
	return goja.Undefined(), err
	}
	old := state.Group
	state.Group = g
	shouldUpdateTag := state.Options.SystemTags.Has(metrics.TagGroup)
	if shouldUpdateTag {
	state.Tags.Modify(func(tagsAndMeta *metrics.TagsAndMeta) {
	tagsAndMeta.SetSystemTagOrMeta(metrics.TagGroup, g.Path)
	})
	}
	defer func() {
	state.Group = old
	if shouldUpdateTag {
	state.Tags.Modify(func(tagsAndMeta *metrics.TagsAndMeta) {
	tagsAndMeta.SetSystemTagOrMeta(metrics.TagGroup, old.Path)
	})
	}
	}()
	startTime := time.Now()
	ret, err := fn(goja.Undefined())
	t := time.Now()
	ctx := mi.vu.Context()
	ctm := state.Tags.GetCurrentValues()
	metrics.PushIfNotDone(ctx, state.Samples, metrics.Sample{
	TimeSeries: metrics.TimeSeries{
	Metric: state.BuiltinMetrics.GroupDuration,
	Tags: ctm.Tags,
	},
	Time: t,
	Value: metrics.D(t.Sub(startTime)),
	Metadata: ctm.Metadata,
	})
	return ret, err
	}

Something seems to mask the error 😕

[na--]

Ok, so, if I add spew.Dump(err) here:

k6/js/runner.go

Line 740 in 60b8b15

if err != nil {

I get this when I call exec.test.abort() outside of a group():

(*goja.InterruptedError)(0xc00109e880)(test aborted: failed message from group at file:///...

however, if I call it inside of a group() callback, I get this:

(*js.scriptException)(0xc0005288c0)(GoError: test aborted: failed message from group at file:///...
	at go.k6.io/k6/js/modules/k6.(*K6).Group-fm (native)
	at file:///...
)

So something is indeed transforming this very specific interrupt error into a generic exception 🤔 I think this might happen because group() returns it as its error result, so goja just converts it in an exception 🤔 And a normal exception in a k6 script iteration doesn't normally abort the whole test. But when there are 2 iterations, we actually get the original goja.InterruptedError from the Runtime and we are back on track.

Looking at how the whole handling of interrupt errors is done, there are quite a few special cases and things that have a bit of a code smell to them... 😞 I am not sure this code cannot be streamlined and simplified 🤔 With some more integration tests, of course, and an eye towards also improving #2804 🤞

Some examples of the special handling I noticed:

• Why is there special handling in cmd/run.go 😕
  

  k6/cmd/run.go

  Line 183 in 60b8b15

  err = common.UnwrapGojaInterruptedError(err)

  
  

  k6/cmd/run.go

  Line 209 in 60b8b15

  err = errext.WithExitCodeIfNone(common.UnwrapGojaInterruptedError(err), exitcodes.GenericEngine)

• This seems quite wonky:
  

  k6/js/runner.go

  Lines 739 to 748 in 60b8b15

  	_, isFullIteration, totalTime, err := u.runFn(ctx, true, fn, cancel, u.setupData)
  	if err != nil {
  	var x *goja.InterruptedError
  	if errors.As(err, &x) {
  	if v, ok := x.Value().(*errext.InterruptError); ok {
  	v.Reason = x.Error()
  	err = v
  	}
  	}
  	}

• Why do we need to very manually unwrap this so often? 😕 The type has Go's Unwrap() convention:
  

  k6/js/common/interrupt_error.go

  Lines 9 to 18 in 60b8b15

  	// UnwrapGojaInterruptedError returns the internal error handled by goja.
  	func UnwrapGojaInterruptedError(err error) error {
  	var gojaErr *goja.InterruptedError
  	if errors.As(err, &gojaErr) {
  	if e, ok := gojaErr.Value().(error); ok {
  	return e
  	}
  	}
  	return err
  	}

[na--]

I think this part in goja is the thing that transforms our nice InterruptError into a generic exception:

k6/vendor/github.com/dop251/goja/runtime.go

Lines 1993 to 1999 in 60b8b15

	if last := out[len(out)-1]; last.Type().Name() == "error" {
	if !last.IsNil() {
	err := last.Interface()
	if _, ok := err.(*Exception); ok {
	panic(err)
	}
	panic(r.NewGoError(last.Interface().(error)))

We should be able to extract the internal error by following this advice, though that would require even more special handling like the one I complained about in the previous post 😞 Not sure there is a better alternative though. @mstoykov, any ideas?

[mstoykov]

I have opened an upstream PR to fix it.

The problem disappears when I try to run the test with 2 iterations, i.e. k6 exits with 108

That was because the first iteration just gets an exception from the group returning the error and it being handled as exception. And the second one actually trying to run and hitting the interrupt error.