abortHook does not work inside async function

[linfan68]

Description
abortHook does not work when the exception is from async function

Steps to Reproduce

import Timer from "timer"

async function throwError() {
  trace("========throwError: An error will thrown now=========\n")
  throw new Error("exception from timer")
}

Timer.set(() => {
  throwError()
}, 1000)

globalThis.abort = function (msg, exception) {
  trace(`abort hook called with "${msg}"\n`)
  trace(exception.stack, "\n")
  return true
}

Expected behavior
(by removing the async keyword of throw Error() function)

instruments: 1,0,0,0,0,2,0,0,0,0,0,8587906,0,100,388,78848,2384,78832,1344,8192,0,1,1,0,0
instruments: 29,0,0,0,0,2,0,0,0,0,29,8587906,0,0,388,78848,2384,78832,848,8192,0,1,1,0,0
========throwError: An error will thrown now=========
abort hook called with "unhandled exception"
Error: exception from timer
 at throwError ()
 at ()
XS abort: unhandled exception

The board reboots after the error

Actual behavior

ases,Turns,System bytes free,CPU 0,CPU 1,Chunk used,Chunk available,Slot used,Slot available,Stack used,Stack available,Garbage collections,Keys used,Modules loaded,Parser used,Floating Point
instruments: 1,0,0,0,0,2,0,0,0,0,0,8587906,0,100,388,78848,2336,78832,1344,8192,0,1,1,0,0
instruments: 29,0,0,0,0,2,0,0,0,0,29,8587906,0,0,388,78848,2336,78832,848,8192,0,1,1,0,0
========throwError: An error will thrown now=========
instruments: 30,0,0,0,0,1,0,0,0,0,31,8587962,0,0,604,78848,2928,78832,960,8192,0,1,1,0,0
instruments: 31,0,0,0,0,1,0,0,0,0,31,8587962,0,0,604,78848,2928,78832,848,8192,0,1,1,0,0

The board does NOT reboot after the error

When an error is thrown inside an async function, the abortHook does not get called, and the code continues to execute. This can be dangerous as the code may run into some uncontrolled states.

Also, I tried if using -d build and test with debugger, the debugger does break when error throwing.

And a few more words about the abortHook:
I believe that being able to capture and diagnose problems in a production environment is crucial. In general, when a program crashes, we should:

1. Print logs, providing as much context as possible, at least the call stack.
2. Ideally, store the information in flash memory, so it can be read or uploaded upon next startup.
3. Restart the program, rather than continuing.

[phoddie]

Interesting behavior. The problem is more subtle than it first appears.

First, the abortHook is called if the exception is thrown at the root -- e.g. instead of calling throwError() from a timer, just call it directly. So, it is not all async functions.

From the timer, the abortHook is called too, once a garbage collection occurs. To see that, include the Debug module in your project's manifest ("$(MODDABLE)/modules/base/debug/manifest.json") and then add this at the top of your example:

import Debug from "debug"

Timer.set(() => {
  trace("timer tick & gc\n");
  Debug.gc();
}, 2000)

You'll see this output:

========throwError: An error will thrown now=========
timer tick & gc
XS abort: unhandled rejection
abort hook called with "unhandled rejection"
Error: exception from timer
 at throwError ($MODDABLE/examples/js/aborthook/main.js:44)
 at throwError ($MODDABLE/examples/js/aborthook/main.js:42)
 at ($MODDABLE/examples/js/aborthook/main.js:48)

In a real project (not a simple test case) GC generally happen frequently enough that the unhandled rejection will be reported reasonably soon after occurring. I'm not yet sure what it would take to report the unhanded rejection sooner. That will take some further investigation.

[linfan68]

GC works, I adding this code into the test:

import Debug from "debug"

Timer.repeat(() => {
  Debug.gc();
}, 500)

And got the stack trace back (soon enough)

@phoddie you may want to add a link to this discussion into the sample code?

[phoddie]

GC works...

Cool. At a minimum, it is a workaround.

...you may want to add a link to this discussion into the sample code?

Good suggestion, thank you. Before doing that, I'd like to investigate whether there is a way to avoid the need for the GC here.

[phoddie]

The reason that the unhanded rejection is not reported until after a garbage collection is because of a feature of Promises: it is possible to attach the rejection handler after the promise is rejected. As a result, the engine can only consider the rejection as unhandled when there are no more references to it.

Here's an example that shows a rejection handler being assigned after the promise is rejected. XS traces "oops" here as expected rather than reporting a rejected promise.

import Timer from "timer"

async function throwError() {
	throw "oops"
}

let promise = null;
Timer.set(() => {
	promise = throwError()
}, 1000)

Timer.set(() => {
	promise.catch(error => {
		trace(error, "\n")
	});
	promise = null;
}, 2000)