v8: emit backtrace when trap happens.

[mathetake]

This PR tries to implement the feature for emitting backtrace information when trap happens with V8 runtime. This would improve extension developers' debuggability dramatically.

summary

I fixed the bug in wasm-c-api implemented in V8 and the patch has been merged to the V8's upstream: https://chromium-review.googlesource.com/c/v8/v8/+/2465353. Now it's possible to extract backtrace information from V8 when trap happens when we link against the latest V8 commit.

The example message is like this:

[2020-10-13 18:06:53.750][2197326][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:29] Function: proxy_on_tick failed:
V8 message: Uncaught RuntimeError: unreachable
wasm backtrace:
  0:  0x178f - runtime._panic
  1:  0xb046 - main.three
  2:  0xb034 - main.two
  3:  0xb02a - main.one
  4:  0x962a - (*main.rootContext).OnTick
  5:  0x95f0 - proxy_on_tick

from the the following Go SDK's code:

func (ctx *rootContext) OnTick() {
	one()
}

func one() {
	two()
}

func two() {
	three()
}

func three() {
	panic("oh")
}

The way I implemented is

• (1) use Trap::trace() API to get stacked function frames (which do not contain function names)
• (2) use name custom section (ref. wasm-spec) to get actual function names combined with frame informations acquired in (1).

message design

I am not sure how the backtrace message should look like, so I would like to have opinions as much as possible.

As of now, I just followed the style of wasmtime where <unknown> is the module name subsection in the name custom section:

>> wasmtime run aa.wasm
panic: C
Error: failed to run main module `aa.wasm`

Caused by:
    0: failed to invoke command default
    1: wasm trap: unreachable
       wasm backtrace:
         0:  0x238 - <unknown>!runtime._panic
         1:  0x33c - <unknown>!main.B
         2:  0x332 - <unknown>!main.A
         3:  0x2ba - <unknown>!main.run
         4:  0x29c - <unknown>!_start

Future works

• I guess compiler optimizations may make this useless sometimes. We should also consider using dwarf info (luckily C++/Rust/TinyGo seem to add dwarf infos in resulting binary by default)
• WAVM seems to have the trace API too, so after the discussion here, I will work on it as well.

⚠️IMPORTANT NOTE⚠️

This would not work until link the host against the latest upstream of V8

• patch https://chromium-review.googlesource.com/c/v8/v8/+/2465353
• mirror: v8/v8@8deb0fd

[PiotrSikora]

Thanks, this looks great!

Regarding your questions:

1. I'm confused as to why enabling this feature would expose Wasm's stack to the public?
2. Yes, we should support this in WAVM as well.
3. I'd like to defer merging this until it's available in Chromium's BETA channel (so ~6 weeks or so?).

[mathetake]

I'm confused as to why enabling this feature would expose Wasm's stack to the public?

Never mind, I just confused the meaning of "sandbox" in WASM. I edited the description

[mathetake]

Now the trace looks like this:

[2020-12-11 08:32:05.761][71282][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x17a9 - runtime._panic
  1:  0xb721 - command-line-arguments.f_10
  2:  0xb767 - command-line-arguments.f_9
  3:  0xb75d - command-line-arguments.f_8
  4:  0xb753 - command-line-arguments.f_7
  5:  0xb749 - command-line-arguments.f_6
  6:  0xb73f - command-line-arguments.f_5
  7:  0xb735 - command-line-arguments.f_4
  8:  0xb72b - command-line-arguments.f_3
  9:  0xb70f - command-line-arguments.f_2

[PiotrSikora]

Thanks! LGTM sans typo.

[PiotrSikora]

Could you re-kick the CI via an empty commit? It looks that CLA bot got stuck.

[mathetake]

done

[PiotrSikora]

Nit: if this fails then we should probably break from the loop, since we can't trust the pos anyway... But I just realized that we don't do this type of verification when parsing bytecode in other places, so feel free to drop this whole if block if you prefer.

[mathetake]

yeah, we trust given binaries anywhere while parsing so far 😄 maybe we should decide and stick to whether or not validate binary or not.

will add break for now.

[PiotrSikora]

Actually, we need to verify this value, i.e.:

if (size == static_cast<uint32_t>(-1) || pos + size > end) {
   function_names_index_ = {};
   return;
}

Also, use const auto to match rest of the code.

[mathetake]

wait, something's broken

[mathetake]

now looks good 😄

[2020-12-15 17:22:49.972][1539808][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick
[2020-12-15 17:22:49.988][1539905][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: It's 1608020569988011716: random value: 3792979139630623504
[2020-12-15 17:22:49.988][1539905][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: panic: aa
[2020-12-15 17:22:49.988][1539905][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick
[2020-12-15 17:22:49.988][1539906][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: It's 1608020569988198834: random value: 2471483108428180821
[2020-12-15 17:22:49.988][1539906][info][wasm] [source/extensions/common/wasm/context.cc:1153] wasm log helloworld: panic: aa
[2020-12-15 17:22:49.988][1539906][trace][wasm] [source/extensions/common/wasm/wasm_vm.cc:22] Function: proxy_on_tick failed: Uncaught RuntimeError: unreachable
Proxy-Wasm plugin in-VM backtrace:
  0:  0x179f - runtime._panic
  1:  0x9954 - (*command-line-arguments.helloWorld).OnTick
  2:  0x982b - proxy_on_tick