Exception message from JS not showing in log #1474

linfan68 · 2025-03-21T11:02:29Z

linfan68
Mar 21, 2025

Let's say we have an exception:

const testJsErrorFromJsCode = () => {
  DBG('=== testJsErrorFromJsCode ===')
  throw new Error('Test JS error from JS code')
}

And I'm getting this from console log:

/workspaces/dk-hwjs/src/targets/linux/prototypes/error-capture/main.ts:48: exception: throw!

And I found in fxDebugThrow function, the "throw" after "exception:" should be the "message".
However, from here:

moddable/xs/sources/xsRun.c

Line 1382 in 0135c0e

fxDebugThrow(the, C_NULL, 0, "throw");

I found the messages are hardcoded as "throw".

Is there a reason why we cannot extract the message from Exception object from here?

Answered by linfan68

Mar 24, 2025

OK, As I suspected, it was my "main.c"'s problem ...

This is the original structure of my main.c

int main(int argc, char *argv[]) {
  // ... Prepare work
  txMachine *the = &_root;
  // ... More code
  the = fxCloneMachine(&preparation->creation, the, "linemb", NULL);

  xsBeginHost(the);
  {
    xsTry
    {
      xsResult = xsAwaitImport("main", XS_IMPORT_NAMESPACE);
    }
    xsCatch
    {
      xsStringValue message = xsToString(xsException);
      fprintf(stderr, "### %s\n", message);
      error = 1;
    }

    // Start event loop
    GMainContext *main_context = g_main_context_default();
    GMainLoop *main_loop = g_main_loop_new(main_context, FALSE);
    g_main_loop_run(main_loop);…

View full answer

phoddie · 2025-03-21T15:06:20Z

phoddie
Mar 21, 2025
Maintainer

Is there a reason why we cannot extract the message from Exception object from here?

There are reasons. First, there is no guarantee that the throw is an instance of Error or even an object. These are all allowed:

throw 1;
throw undefined;
throw Promise.resolve();

Additionally, it is possible that naively attempting to get the message could execute script code, which could change the state of the program or throw another exception.

class AnError extends Error {
	set message(m) {
	}
	get message() {
		throw new Error("boom");
	}
}
throw new AnError("yikes");

So, XS is conservative here to avoid having the debugger introduce unexpected behaviors.

To do what you suggest should be possible by first checking that exception is an Error instance and then accessing the message through the internal slot. That would be done inside fxDebugThrow, rather than in the run loop, to apply to all throws.

0 replies

phoddie · 2025-03-21T19:51:05Z

phoddie
Mar 21, 2025
Maintainer

The information above is correct, but incomplete. When running with the debugger, XS logs what you want:

You must either be running a debug build without the debugger or an instrumented build. Those paths don't log the details.

Maybe you can explain a bit more about your environment?

FWIW – another approach is to log the exception yourself. If you are only interested in unhandled exceptions (which reset by default), you can enable the abort hook (MODDEF_XS_ABORTHOOK) which calls globalThis.abort(exception) so you can output whatever you like. See the aborthook example for details.

5 replies

linfan68 Mar 22, 2025
Author

@phoddie I'm running debug log bulid (the -dl flag), and I'm running moddable on an ARM Linux board based on this discussion:

#1344 (the LinEmb platform)

I've created a branch, synced with latest public for testing different error handling in the sample project:
https://github.com/linfan68/moddable/blob/linemb-error-handling/examples/devices/linemb/main.js

Here are the results:
I think issues are:

abort hook does not work
promise rejection does not trigger reset (or process exit in my case)

import Timer from 'timer'

trace('Hello, Linux Embedded!!!\n')

// !!! Abort hook does NOT work !!!
globalThis.abort = function (msg, exception) {
	trace(`abort hook called with "${msg}"\n`);
	trace(exception.stack, "\n");

	if (("unhandled exception" === msg) ||
		("unhandled rejection" === msg))
		return false;		// do not abort
}

//
// Error Handling Tests
// !!! ONLY ENABLE ONE CASE AT A TIME !!!
//

// ***************************************************************************
// Case 1: Uncaught exception from top level
// ***************************************************************************
throw new Error('Uncaught exception from top level!')

// =====OUTPUT======
// Hello, Linux Embedded!!!
// Error: unhandled exception
// =================
// (process exits)

// ***************************************************************************
// Case 2: Uncaught exception from setTimeout
// ***************************************************************************
Timer.set(() => {
	throw new Error('Uncaught exception from setTimeout!')
}, 1000)

// =====OUTPUT======
// Hello, Linux Embedded!!!
// Error: unhandled exception
// =================
// Process exited with code


// ***************************************************************************
// Case 3: Promise rejection
// ***************************************************************************
Promise.reject(new Error('Promise rejection!'))

// =====OUTPUT======
// Hello, Linux Embedded!!!
// =================
// Process keeps running

// ***************************************************************************
// Case 4: Uncaught exception from Promise
// ***************************************************************************
new Promise(() => {
	throw new Error('Uncaught exception from Promise!')
})

// =====OUTPUT======
// Hello, Linux Embedded!!!
// =================
// Process keeps running

// ***************************************************************************
// Case 5: Uncaught exception from setTimeout in Promise
// ***************************************************************************
new Promise(() => {
	Timer.set(() => {
		throw new Error('Uncaught exception from setTimeout in Promise!')
	}, 1000)
})

// =====OUTPUT======
// Hello, Linux Embedded!!!
// Error: unhandled exception
// =================
// Process exited

// ***************************************************************************
// Case 6: Promise rejection in setTimeout
// ***************************************************************************
new Promise((resolve, reject) => {
	Timer.set(() => {
		reject(new Error('Promise rejection in setTimeout!'))
	}, 1000)
})

// =====OUTPUT======
// Hello, Linux Embedded!!!
// =================
// Process keeps running

phoddie Mar 22, 2025
Maintainer

It wasn't clear that you are using the -dl flag. Thank you for that detail.

I ran a quick test with xsbug-log adapting your sample:

const DBG = m => trace(m + "\n");
const testJsErrorFromJsCode = () => {
  DBG('=== testJsErrorFromJsCode ===')
  throw new Error('Test JS error from JS code')
}
testJsErrorFromJsCode();

The output is pretty reasonable:

#xsbug-log listening on port 5002. ^C to exit.
#xsbug-log connected to "hellotest"
=== testJsErrorFromJsCode ===
# Break: Error: Test JS error from JS code!
  #0: testJsErrorFromJsCode /Users/hoddie/Projects/moddable/examples/hellotest/main.js:4
  #1: main /Users/hoddie/Projects/moddable/examples/hellotest/main.js:6
  #2: (host)
XS abort: unhandled exception

If I use xsbug instead and turn OFF "Break on exception" in xsbug preferences, then I get something more like what you see:

=== testJsErrorFromJsCode ===
/Users/hoddie/Projects/moddable/examples/hellotest/main.js (4) # Exception: throw!
XS abort: unhandled exception

That makes sense since the expanded error ("Error: Test JS error from JS code!") is part of the <break> element transmitted from the runtime to xsbug.

Are you configuring xsbug-log to disable "break on exception." If so, how?

linfan68 Mar 22, 2025
Author

@phoddie Sorry I didn't notice your reply and edited the post above...

Hmmm... now the challenge is my minimal LinEmb environment does not support debugger... but mostly I prefer using old fashion printf to debug my code. Also currently I'm facing the challenge that the program crashes on some random places within hours of long running session, so I'm digging into better ways to collect error information in the production environment.

Can you also take a look at the edited post? I tested different places to throw, and need some help to understand what happened, especially when promise rejection happens.

phoddie Mar 22, 2025
Maintainer

@linfan68 – There's too much here for me to unravel. Let's go step-by-step.

Please answer these questions from above:

Are you configuring xsbug-log to disable "break on exception"?
If so, how?

now the challenge is my minimal LinEmb environment

What is the mcconfig command line you use to build for this environment?

my minimal LinEmb environment does not support debugger

I assume you are referring to the xsbug application by "debugger". You are running xsbug-log with -dl which uses the same communication protocol and XS runtime debugging features.
.
Thank you.

linfan68 Mar 23, 2025
Author

@phoddie sorry for the confusion....

Please aware that I'm running in a new enviroment, and I wrote a new main.c to drive the whole thing.
So, I'm not sure if features needed to support debugging was added... but the executable built with "-d" cannot connect to xsbug
I was a little confused about the description here: https://github.com/Moddable-OpenSource/moddable/blob/public/documentation/tools/tools.md. I thought with "-dl", the log will directly go to console (and I realized it does not make sense, there is no "console" for ESP32...)

So, although I'm using "-dl" (in the wrong way I guess), I'm not running any debugger (xsbug or xsbug-log) with the executable. All I got is console log from an executable.

Some progress!

I fixed the abort hook issue by adding MODDEF_XS_ABORTHOOK support in my fxAbort implemetation.
Now this code:

import Timer from 'timer'

const foo = () => {
  throw new Error('This is an error in foo')
}
Timer.set(() => {
  foo()
} , 1000)

export function abortHook(msg: any, exception: any): boolean {
  trace(`!!! abortHook called with "${msg}" !!!\n`)
  trace(exception.stack, '\n\n\n')
  return true // abort
}
;(globalThis as any).abort = abortHook

generates this output:

instruments: 0,320000,896,2559968,0,131072,0,0,0,0,0,0
/workspaces/dk-hwjs/src/targets/linux/prototypes/error-capture/main.ts:4: exception: throw!
!!! abortHook called with "unhandled exception" !!!
Error: This is an error in foo
 at foo (/workspaces/dk-hwjs/src/targets/linux/prototypes/error-capture/main.ts:4)
 at (/workspaces/dk-hwjs/src/targets/linux/prototypes/error-capture/main.ts:7)

Yeah~~

import Timer from 'timer'
import Debug from 'debug'

const foo = async () => {
  throw new Error('Promise rejected from async function foo')
}
foo()

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

export function abortHook(msg: any, exception: any): boolean {
  trace(`\n\n!!! abortHook called with "${msg}" !!!\n`)
  trace(exception.stack, '\n\n\n')
  return true // abort
}
;(globalThis as any).abort = abortHook

// == OUTPUT ==
// instruments key: Chunk used,Chunk available,Slot used,Slot available,Stack used,Stack available,Garbage collections,Keys used,Modules loaded,Parser used,Floating Point,Promises settled
// instruments: 0,320000,896,2559968,0,131072,0,0,0,0,0,0
// /workspaces/dk-hwjs/src/targets/linux/prototypes/error-capture/main.ts:5: exception: throw!
// instruments: 176,320000,2240,2559968,2112,131072,2,1,1,0,0,0
// instruments: 176,320000,2240,2559968,1440,131072,2,1,1,0,0,0```

promise rejection:

new Promise((resolve, reject) => {
  Timer.set(() => {
    trace('Promise rejection\n')
    reject(new Error('Promise rejected'))
  }
  , 1000)
})
// === OUTPUT ===
// there is no error output in this case
//

Also as we disscussed before (#1186). But with GC triggered twice a second, still the abort hook does not trigger.

Again, this should be an issue with my new platform. Maybe some pointers in the code will be helpful for me to move forward.

linfan68 · 2025-03-24T16:15:45Z

linfan68
Mar 24, 2025
Author

OK, As I suspected, it was my "main.c"'s problem ...

This is the original structure of my main.c

int main(int argc, char *argv[]) {
  // ... Prepare work
  txMachine *the = &_root;
  // ... More code
  the = fxCloneMachine(&preparation->creation, the, "linemb", NULL);

  xsBeginHost(the);
  {
    xsTry
    {
      xsResult = xsAwaitImport("main", XS_IMPORT_NAMESPACE);
    }
    xsCatch
    {
      xsStringValue message = xsToString(xsException);
      fprintf(stderr, "### %s\n", message);
      error = 1;
    }

    // Start event loop
    GMainContext *main_context = g_main_context_default();
    GMainLoop *main_loop = g_main_loop_new(main_context, FALSE);
    g_main_loop_run(main_loop);
    // End event loop
  }
  xsEndHost(the);

  xsDeleteMachine(the);

  return error;
}

As we can see, I wrapped the main loop inside xsBeginHost() ... xsEndHost()
And I realized this beginHost...EndHost patterns are nested and only the LAST one handles "unhandled" exception and triggers abort().

Now I fixed it as following:

removed the try... catch. I should NOT handle the exception...
move the event loop outside the xsBeginHost() ... xsEndHost()

int main(int argc, char *argv[]) {
  // ... Prepare work
  txMachine *the = &_root;
  // ... More code
  the = fxCloneMachine(&preparation->creation, the, "linemb", NULL);

  xsBeginHost(the);
  {
    // xsTry
    // {
    xsResult = xsAwaitImport("main", XS_IMPORT_NAMESPACE);

    // }
    // xsCatch
    // {
    //   xsStringValue message = xsToString(xsException);
    //   fprintf(stderr, "### %s\n", message);
    //   error = 1;
    // }
  }
  xsEndHost(the);

  // Start event loop
  GMainContext *main_context = g_main_context_default();
  GMainLoop *main_loop = g_main_loop_new(main_context, FALSE);
  g_main_loop_run(main_loop);
  // End event loop

  xsDeleteMachine(the);

  return error;
}

After this, all cases (including the unhandled rejection) correctly trigger the abortHook.

I guess few people will facing this issue... I spent most of the time trying to understand how How xsBeginHost() ... xsEndHost() works, and realized how setjmp() and c_longjmp() can do exeption handling in C code... (thanks copilot chat with claude).

7 replies

phoddie Mar 27, 2025
Maintainer

I want to printout the JS stack in the interrupt handler, which is native code. Is this possible?

It is more-or-less possible. XS assumes a single virtual machine is always accessed from the same thread. An interrupt handler is effectively another thread accessing the VM. The state of the VM may not be consistent at that time. In particular, the the->frame which holds the current frame pointer is held in a variable (hopefully a register) during byte code execution, so it may not be entirely up to date.

Getting the name is involved. There are many cases. XS does that, but in some obscure cases simply getting the name could execute script, which would likely fail because the VM is already running. In practice, however, I think that is unlikely.

Here's a small native function that shows the approach. Note that it uses XS internals so it includes xsAll.h rather than xs.h.

#include "xsAll.h"

void xs_dumpFrames(txMachine *the)
{
	txSlot *aFrame = the->frame;
	while (aFrame) {
		char name[128] = "";
		fxBufferFrameName(the, name, sizeof(name), aFrame, "");

		txSlot* environment = mxFrameToEnvironment(aFrame);
		if (environment->ID != XS_NO_ID)
			printf("%s: %s:%d\n", name, fxGetKeyName(the, environment->ID), environment->value.environment.line);
		else
			printf("%s\n", name);

		aFrame = aFrame->next;
	}
}

Here's a small JavaScript test of that:

function dumpFrames() @ "xs_dumpFrames";

function foo() {
	dumpFrames();
}

function bar() {
	foo();
}

const test = () => {
	bar();
}

test();

And this is the output:

dumpFrames
foo: ../moddable/examples/helloworld/main.js:5
bar: ./moddable/examples/helloworld/main.js:9
test: ./moddable/examples/helloworld/main.js:13
main: ./moddable/examples/helloworld/main.js:16

Notice that it shows the function names for native functions (dumpFrames), regular functions (foo), and arrow functions (test). For scripts, it shows the source file path and line number.

🙋This small Linux host platform of yours sounds pretty great. It would be useful for others. Do you intend to publish that?

linfan68 Apr 1, 2025
Author

@phoddie Thanks for your help. I'll give it a try when I get a chance.
And I'm happy to publish the Linux host, I do have a fork that has a minimal implementation, but without these fixes we discussed here. I'll add some examples as well as improvments here and submit a PR.

phoddie Apr 1, 2025
Maintainer

And I'm happy to publish the Linux host, I do have a fork that has a minimal implementation, but without these fixes we discussed here. I'll add some examples as well as improvments here and submit a PR.

Awesome. Thank you!

linfan68 Apr 4, 2025
Author

@phoddie PR here: #1480

phoddie Apr 5, 2025
Maintainer

Yes, I saw that. Very exciting! I need a little time to review it. I'll share any comments on the PR. (We already mentioned the PR in the "Coming Attractions" section of today's Moddable SDK 5.6 release notes!)

Exception message from JS not showing in log #1474

Uh oh!

Uh oh!

linfan68 Mar 21, 2025

Replies: 3 comments · 12 replies

Uh oh!

phoddie Mar 21, 2025 Maintainer

Uh oh!

phoddie Mar 21, 2025 Maintainer

Uh oh!

Uh oh!

linfan68 Mar 22, 2025 Author

Uh oh!

phoddie Mar 22, 2025 Maintainer

Uh oh!

linfan68 Mar 22, 2025 Author

Uh oh!

phoddie Mar 22, 2025 Maintainer

Uh oh!

Uh oh!

linfan68 Mar 23, 2025 Author

Some progress!

Next

Uh oh!

linfan68 Mar 24, 2025 Author

Uh oh!

Uh oh!

phoddie Mar 27, 2025 Maintainer

Uh oh!

linfan68 Apr 1, 2025 Author

Uh oh!

phoddie Apr 1, 2025 Maintainer

Uh oh!

linfan68 Apr 4, 2025 Author

Uh oh!

phoddie Apr 5, 2025 Maintainer

linfan68
Mar 21, 2025

Replies: 3 comments 12 replies

phoddie
Mar 21, 2025
Maintainer

phoddie
Mar 21, 2025
Maintainer

linfan68 Mar 22, 2025
Author

phoddie Mar 22, 2025
Maintainer

linfan68 Mar 22, 2025
Author

phoddie Mar 22, 2025
Maintainer

linfan68 Mar 23, 2025
Author

linfan68
Mar 24, 2025
Author

phoddie Mar 27, 2025
Maintainer

linfan68 Apr 1, 2025
Author

phoddie Apr 1, 2025
Maintainer

linfan68 Apr 4, 2025
Author

phoddie Apr 5, 2025
Maintainer