Refactor VU error handling

This was motivated by wanting to remove the goja dependency from the
lib/executor package, see #1769 (comment)

The idea is for runFn to always return a lib.Exception error that can
handle all JS errors and Go panics consistently. In practice I'm not
sure if this hack is worth it as it might mess up handling of some
errors...

js/runner.go

@@ -31,6 +31,7 @@ import (
 	"net/http/cookiejar"
 	"runtime/debug"
 	"strconv"
+	"strings"
 	"time"
 
 	"github.com/dop251/goja"
@@ -630,23 +631,41 @@ 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)
-			// 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())
+			err = lib.Exception{
+				Err:     fmt.Errorf("a panic occurred in VU code but was caught: %s", r),
+				StackGo: string(debug.Stack()),
+				StackJS: b.String(),
+			}
 		}
 	}()
 
 	startTime := time.Now()
 	v, err = fn(goja.Undefined(), args...) // Actually run the JS script
 	endTime := time.Now()
 
+	// Wrap goja.Exception in an internal type to avoid making goja a dependency
+	// in other packages.
+	if e, ok := err.(*goja.Exception); ok {
+		stack := e.String()
+		val := e.Value().Export()
+		eolIdx := strings.IndexByte(stack, '\n')
+		// HACK: Reuse the stack dump formatting, but remove the first redundant
+		// error line and reuse the first line in *some* cases, e.g.
+		// ReferenceErrors. :-/
+		firstLine, rest := stack[:eolIdx], stack[eolIdx+1:]
+		if _, ok := val.(map[string]interface{}); ok {
+			val = errors.New(firstLine)
+		}
+		err = lib.Exception{
+			Err:     val,
+			StackJS: rest,
+		}
+	}
+
 	select {
 	case <-ctx.Done():
 		isFullIteration = false

js/runner_test.go

@@ -38,7 +38,6 @@ import (
 	"testing"
 	"time"
 
-	"github.com/sirupsen/logrus"
 	logtest "github.com/sirupsen/logrus/hooks/test"
 	"github.com/spf13/afero"
 	"github.com/stretchr/testify/assert"
@@ -1733,14 +1732,10 @@ func TestSystemTags(t *testing.T) {
 
 func TestVUPanic(t *testing.T) {
 	r1, err := getSimpleRunner(t, "/script.js", `
-			var group = require("k6").group;
 			exports.default = function() {
-				group("panic here", function() {
-					if (__ITER == 0) {
-						panic("here we panic");
-					}
-					console.log("here we don't");
-				})
+				if (__ITER == 0) {
+					panic("here we panic");
+				}
 			}`,
 	)
 	require.NoError(t, err)
@@ -1759,37 +1754,18 @@ func TestVUPanic(t *testing.T) {
 				return
 			}
 
-			logger := logrus.New()
-			logger.SetLevel(logrus.InfoLevel)
-			logger.Out = ioutil.Discard
-			hook := testutils.SimpleLogrusHook{
-				HookedLevels: []logrus.Level{logrus.InfoLevel, logrus.ErrorLevel, logrus.FatalLevel, logrus.PanicLevel},
-			}
-			logger.AddHook(&hook)
-
 			ctx, cancel := context.WithCancel(context.Background())
 			defer cancel()
 			vu := initVU.Activate(&lib.VUActivationParams{RunContext: ctx})
 			vu.(*ActiveVU).Runtime.Set("panic", func(str string) { panic(str) })
-			vu.(*ActiveVU).state.Logger = logger
-
-			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")
-			entries := hook.Drain()
-			require.Len(t, entries, 1)
-			assert.Equal(t, logrus.ErrorLevel, entries[0].Level)
-			require.True(t, strings.HasPrefix(entries[0].Message, "panic: here we panic"))
-			require.True(t, strings.HasSuffix(entries[0].Message, "Goja stack:\nfile:///script.js:3:4(12)"))
+			errMsg := err.Error()
+			require.True(t, strings.HasPrefix(errMsg, "a panic occurred in VU code but was caught: here we panic"))
+			require.True(t, strings.HasSuffix(errMsg, "JavaScript stack:\nfile:///script.js:2:4(4)"))
 
 			err = vu.RunOnce()
 			assert.NoError(t, err)
-
-			entries = hook.Drain()
-			require.Len(t, entries, 1)
-			assert.Equal(t, logrus.InfoLevel, entries[0].Level)
-			require.Contains(t, entries[0].Message, "here we don't")
 		})
 	}
 }

lib/errors.go

@@ -27,6 +27,27 @@ import (
 	"github.com/loadimpact/k6/lib/consts"
 )
 
+// Exception represents an internal JS error or unexpected panic in VU code.
+type Exception struct {
+	Err              interface{}
+	StackGo, StackJS string
+}
+
+// Error implements the error interface.
+func (exc Exception) Error() string {
+	out := fmt.Sprintf("%s", exc.Err)
+	if exc.StackGo != "" {
+		out += fmt.Sprintf("\n%s", exc.StackGo)
+	}
+	if exc.StackJS != "" {
+		if exc.StackGo != "" {
+			out += "\nJavaScript stack:"
+		}
+		out += fmt.Sprintf("\n%s", exc.StackJS)
+	}
+	return out
+}
+
 // IterationInterruptedError is used when an iteration is interrupted due to
 // one of the following:
 // - normal JS exceptions, throw(), etc., with cause: error

lib/executor/helpers.go

@@ -26,7 +26,6 @@ import (
 	"math/big"
 	"time"
 
-	"github.com/dop251/goja"
 	"github.com/sirupsen/logrus"
 
 	"github.com/loadimpact/k6/lib"
@@ -113,14 +112,17 @@ func getIterationRunner(
 
 				// TODO: investigate context cancelled errors
 				switch e := err.(type) {
-				case *goja.Exception:
-					if er, ok := e.Value().Export().(lib.IterationInterruptedError); ok {
-						tags["cause"] = er.Cause()
+				case lib.Exception:
+					if e2, ok := e.Err.(lib.IterationInterruptedError); ok {
+						tags["cause"] = e2.Cause()
+						logger.Error(e.Error())
+					} else {
+						// 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
+						logger.WithField("source", "stacktrace").Error(e.Error())
 					}
-					logger.Error(err.Error())
-				case fmt.Stringer:
-					// TODO better detection for stack traces
-					logger.WithField("source", "stacktrace").Error(e.String())
 				default:
 					logger.Error(err.Error())
 				}