feat: better errors with testing, dump_error() function (#132)

include/extension-api.h

@@ -117,8 +117,9 @@ class Engine {
 
   bool dump_value(JS::Value val, FILE *fp = stdout);
   bool print_stack(FILE *fp);
-  void dump_pending_exception(const char *description = "");
-  void dump_promise_rejection(HandleValue reason, HandleObject promise, FILE *fp);
+  void dump_error(HandleValue error, FILE *fp = stderr);
+  void dump_pending_exception(const char *description = "", FILE *fp = stderr);
+  void dump_promise_rejection(HandleValue reason, HandleObject promise, FILE *fp = stderr);
 };
 
 

runtime/engine.cpp

@@ -106,12 +106,12 @@ bool print_stack(JSContext *cx, FILE *fp) {
   return print_stack(cx, stackp, fp);
 }
 
-void dump_promise_rejection(JSContext *cx, HandleValue reason, HandleObject promise, FILE *fp) {
+void dump_error(JSContext *cx, HandleValue error, bool *has_stack, FILE *fp) {
   bool reported = false;
   RootedObject stack(cx);
 
-  if (reason.isObject()) {
-    RootedObject err(cx, &reason.toObject());
+  if (error.isObject()) {
+    RootedObject err(cx, &error.toObject());
     JSErrorReport *report = JS_ErrorFromException(cx, err);
     if (report) {
       fprintf(stderr, "%s\n", report->message().c_str());
@@ -124,20 +124,30 @@ void dump_promise_rejection(JSContext *cx, HandleValue reason, HandleObject prom
   // If the rejection reason isn't an `Error` object, we just dump the value
   // as-is.
   if (!reported) {
-    dump_value(cx, reason, stderr);
+    dump_value(cx, error, stderr);
   }
 
+  if (stack) {
+    *has_stack = true;
+    fprintf(stderr, "Stack:\n");
+    print_stack(cx, stack, stderr);
+  } else {
+    *has_stack = false;
+  }
+}
+
+void dump_promise_rejection(JSContext *cx, HandleValue reason, HandleObject promise, FILE *fp) {
+  bool has_stack;
+  dump_error(cx, reason, &has_stack, fp);
+
   // If the rejection reason isn't an `Error` object, we can't get an exception
   // stack from it. In that case, fall back to getting the stack from the
   // promise resolution site. These should be identical in many cases, such as
   // for exceptions thrown in async functions, but for some reason the
   // resolution site stack seems to sometimes be wrong, so we only fall back to
   // it as a last resort.
-  if (!stack) {
-    stack = JS::GetPromiseResolutionSite(promise);
-  }
-
-  if (stack) {
+  if (!has_stack) {
+    RootedObject stack(cx, JS::GetPromiseResolutionSite(promise));
     fprintf(stderr, "Stack:\n");
     print_stack(cx, stack, stderr);
   }
@@ -294,25 +304,29 @@ static bool report_unhandled_promise_rejections(JSContext *cx) {
   return true;
 }
 
-static void DumpPendingException(JSContext *cx, const char *description) {
+static void DumpPendingException(JSContext *cx, const char *description, FILE *fp) {
   JS::ExceptionStack exception(cx);
-  if (!JS::GetPendingExceptionStack(cx, &exception)) {
-    fprintf(stderr,
+  if (!JS::StealPendingExceptionStack(cx, &exception)) {
+    fprintf(fp,
             "Error: exception pending after %s, but got another error "
             "when trying to retrieve it. Aborting.\n",
             description);
   } else {
-    fprintf(stderr, "Exception while %s: ", description);
-    dump_value(cx, exception.exception(), stderr);
-    print_stack(cx, exception.stack(), stderr);
+      fprintf(fp, "Exception while %s\n", description);
+    JS::ErrorReportBuilder report(cx);
+    if (!report.init(cx, exception, JS::ErrorReportBuilder::WithSideEffects)) {
+      fprintf(fp, "unable to build error report");
+    } else {
+      JS::PrintError(fp, report, false);
+    }
   }
 }
 
 static void abort(JSContext *cx, const char *description) {
   // Note: we unconditionally print messages here, since they almost always
   // indicate serious bugs.
   if (JS_IsExceptionPending(cx)) {
-    DumpPendingException(cx, description);
+    DumpPendingException(cx, description, stderr);
   } else {
     fprintf(stderr,
             "Error while %s, but no exception is pending. "
@@ -374,6 +388,7 @@ bool api::Engine::initialize(const char *filename) {
   if (!eval_toplevel(filename, &result)) {
     if (JS_IsExceptionPending(cx())) {
       dump_pending_exception("pre-initializing");
+      fflush(stderr);
     }
     return false;
   }
@@ -493,8 +508,14 @@ void api::Engine::decr_event_loop_interest() {
 bool api::Engine::dump_value(JS::Value val, FILE *fp) { return ::dump_value(CONTEXT, val, fp); }
 bool api::Engine::print_stack(FILE *fp) { return ::print_stack(CONTEXT, fp); }
 
-void api::Engine::dump_pending_exception(const char *description) {
-  DumpPendingException(CONTEXT, description);
+void api::Engine::dump_pending_exception(const char *description, FILE *fp) {
+  DumpPendingException(CONTEXT, description, fp);
+}
+
+void api::Engine::dump_error(JS::HandleValue err, FILE *fp) {
+  bool has_stack;
+  ::dump_error(CONTEXT, err, &has_stack, fp);
+  fflush(fp);
 }
 
 void api::Engine::dump_promise_rejection(HandleValue reason, HandleObject promise, FILE *fp) {

tests/e2e/runtime-err/expect_serve_status.txt

@@ -0,0 +1 @@
+500

tests/e2e/runtime-err/expect_serve_stderr.txt

@@ -0,0 +1,5 @@
+stderr [0] :: Error while running request handler: 
+stderr [0] :: runtime error
+stderr [0] :: Stack:
+stderr [0] ::   @runtime-err.js:6:13
+stderr [0] ::   @runtime-err.js:7:7

tests/e2e/runtime-err/runtime-err.js

@@ -0,0 +1,9 @@
+import { strictEqual, deepStrictEqual, throws } from "../../assert.js";
+
+addEventListener("fetch", (evt) =>
+  evt.respondWith(
+    (async () => {
+      throw new Error('runtime error');
+    })()
+  )
+);

tests/e2e/syntax-err/expect_wizer_stderr.txt

@@ -1 +1,2 @@
-Exception while pre-initializing: (new SyntaxError("expected expression, got end of script", "syntax-err.js", 2))
+Exception while pre-initializing
+syntax-err.js:2:1 SyntaxError: expected expression, got end of script

tests/e2e/tla-err/expect_wizer_stderr.txt

@@ -1 +1,2 @@
-Exception while pre-initializing: (new Error("blah", "tla-err.js", 3))
+Exception while pre-initializing
+tla-err.js:3:10 Error: blah

tests/test.sh

@@ -47,14 +47,14 @@ if [ -z "$test_component" ]; then
    fi
 
    if [ -f "$test_wizer_stdout_expectation" ]; then
-      cmp "$stdout_log" "$test_wizer_stdout_expectation"
+      cmp -b "$stdout_log" "$test_wizer_stdout_expectation"
    fi
 
    if [ -f "$test_wizer_stderr_expectation" ]; then
       mv "$stderr_log" "$stderr_log.orig"
       cat "$stderr_log.orig" | head -n $(cat "$test_wizer_stderr_expectation" | wc -l) > "$stderr_log"
       rm "$stderr_log.orig"
-      cmp "$stderr_log" "$test_wizer_stderr_expectation"
+      cmp -b "$stderr_log" "$test_wizer_stderr_expectation"
    fi
 
    if [ ! -f "$test_component" ] || [ ! -s "$test_component" ]; then
@@ -113,20 +113,27 @@ if [ -f "$test_serve_headers_expectation" ]; then
    mv "$headers_log" "$headers_log.orig"
    cat "$headers_log.orig" | head -n $(cat "$test_serve_headers_expectation" | wc -l) | sed 's/\r//g' > "$headers_log"
    rm "$headers_log.orig"
-   cmp "$headers_log" "$test_serve_headers_expectation"
+   cmp -b "$headers_log" "$test_serve_headers_expectation"
 fi
 
 if [ -f "$test_serve_body_expectation" ]; then
-   cmp "$body_log" "$test_serve_body_expectation"
+   cmp -b "$body_log" "$test_serve_body_expectation"
 fi
 
 if [ -f "$test_serve_stdout_expectation" ]; then
-   cmp "$stdout_log" "$test_serve_stdout_expectation"
+   cmp -b "$stdout_log" "$test_serve_stdout_expectation"
 fi
 
 if [ -f "$test_serve_stderr_expectation" ]; then
-   tail -n +2 "$stderr_log" > "$stderr_log"
-   cmp "$stderr_log" "$test_serve_stderr_expectation"
+   mv "$stderr_log" "$stderr_log.orig"
+   if [[ $(cat "$stderr_log.orig" | tail -n +2 | head -n1) == "stderr [0] :: Warning: Using a DEBUG build. Expect things to be SLOW." ]]; then
+      cat $stderr_log.orig | tail -n +3 > "$stderr_log"
+      rm $stderr_log.orig
+   else
+      cat $stderr_log.orig | tail -n +2 > "$stderr_log"
+      rm $stderr_log.orig
+   fi
+   cmp -b "$stderr_log" "$test_serve_stderr_expectation"
 fi
 
 rm "$body_log"

tests/tests.cmake

@@ -26,19 +26,20 @@ function(test_integration TEST_NAME)
     )
 
     add_test(integration-${TEST_NAME} ${BASH_PROGRAM} ${CMAKE_SOURCE_DIR}/tests/test.sh ${RUNTIME_DIR} ${CMAKE_SOURCE_DIR}/tests/integration/${TEST_NAME} ${RUNTIME_DIR}/test-server.wasm ${TEST_NAME})
-    set_property(TEST integration-${TEST_NAME} PROPERTY ENVIRONMENT "WASMTIME=${WASMTIME};WIZER=${WIZER_DIR}/wizer;WASM_TOOLS=${WASM_TOOLS_DIR}/wasm-tools")
+    set_property(TEST integration-${TEST_NAME} PROPERTY ENVIRONMENT "WASMTIME=${WASMTIME};WIZER=${WIZER_DIR}/wizer;WASM_TOOLS=${WASM_TOOLS_DIR}/wasm-tools;")
     set_tests_properties(integration-${TEST_NAME} PROPERTIES TIMEOUT 120)
 endfunction()
 
-test_e2e(smoke)
 test_e2e(headers)
-test_e2e(tla)
+test_e2e(runtime-err)
+test_e2e(smoke)
 test_e2e(syntax-err)
 test_e2e(tla-err)
 test_e2e(tla-runtime-resolve)
+test_e2e(tla)
 
 test_integration(btoa)
-test_integration(performance)
 test_integration(crypto)
 test_integration(fetch)
+test_integration(performance)
 test_integration(timers)