Error: Failed to initialize the compiled Wasm binary with Wizer

[cataggar]

Hi, I'm getting a wizer error when trying to use jco. This is a continuation of troubleshooting of bytecodealliance/StarlingMonkey#15 (comment). In jco/node_modules/@bytecodealliance/componentize-js/src/componentize.js, I turned on debugging.

const DEBUG_BINDINGS = true;
const DEBUG_CALLS = true;

I pushed the output debugging sources to https://github.com/cataggar/StarlingMonkey15/tree/main/b0c26fbad66e

~/ms/jco> node src/jco.js componentize /Users/cataggar/ms/StarlingMonkey15/cowsay/cowsay.js --wit /Users/cataggar/ms/StarlingMonkey15/cowsay/src/cowsay.wit -o /Users/cataggar/ms/StarlingMonkey15/cowsay.wasm

--- Wizer Env ---
{
  DEBUG: '1',
  SOURCE_NAME: 'cowsay.js',
  IMPORT_WRAPPER_CNT: '0',
  EXPORT_CNT: '1',
  WASMTIME_BACKTRACE_DETAILS: '1',
  EXPORT0_NAME: 'export_tsVersion',
  EXPORT0_ARGS: '',
  EXPORT0_RET: '*i32',
  EXPORT0_RETSIZE: '8',
  IMPORT_CNT: 0
}
(wizer) create the memory buffer JS object
(wizer) create the realloc JS function
(wizer) create the 0 import JS functions
(wizer) setting the binding global
(wizer) complete
Redirecting call to abort() to mozalloc_abort

Error: the `componentize.wizer` function trapped

Caused by:
    0: error while executing at wasm backtrace:
           0: 0x7a3ec5 - <unknown>!<wasm function 11740>
           1: 0x7a7fee - <unknown>!<wasm function 12478>
           2: 0x7a84e0 - <unknown>!<wasm function 12582>
           3: 0x72c8c0 - <unknown>!<wasm function 6861>
           4: 0x352387 - <unknown>!<wasm function 522>
           5: 0x6ad3b2 - <unknown>!<wasm function 4800>
           6: 0x74ed01 - <unknown>!<wasm function 7670>
           7: 0x36bb2f - <unknown>!<wasm function 562>
           8: 0x4dcd55 - <unknown>!<wasm function 1527>
           9: 0xa91cf - <unknown>!<wasm function 79>
          10: 0x3424d4 - <unknown>!<wasm function 498>
          11: 0x66ac73 - <unknown>!<wasm function 4035>
          12: 0x625349 - <unknown>!<wasm function 3385>
          13: 0x422874 - <unknown>!<wasm function 940>
          14: 0x4225c1 - <unknown>!<wasm function 940>
          15: 0x2d00ad - <unknown>!<wasm function 358>
          16: 0x1fc7ba - <unknown>!<wasm function 186>
          17: 0x50ceed - <unknown>!<wasm function 1721>
          18: 0x33853e - <unknown>!<wasm function 485>
    1: wasm trap: wasm `unreachable` instruction executed
(jco componentize) Error: Failed to initialize the compiled Wasm binary with Wizer:
Wizering failed to complete
Binary and sources available for debugging at /var/folders/xm/hr4sq0d567vfs0xdth9t38zc0000gn/T/b0c26fbad66e

    at componentize (file:///Users/cataggar/ms/jco/node_modules/@bytecodealliance/componentize-js/src/componentize.js:261:13)
    at async componentize (file:///Users/cataggar/ms/jco/src/cmd/componentize.js:11:25)
    at async file:///Users/cataggar/ms/jco/src/jco.js:200:9

[cataggar]

When trying to run locally, it is not responding when calling TypedFunction::call https://github.com/bytecodealliance/wizer/blob/v7.0.5/src/lib.rs#L894

~/ms/wizer> RUST_LOG=debug cargo run --release --features="env_logger structopt wasmprinter" -- --allow-wasi --init-func componentize.wizer --dir=/Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/sources --wasm-bulk-memory=true -o=/Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/out2.wasm /Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/in.wasm
   Compiling wizer v7.0.5 (/Users/cataggar/ms/wizer)
    Finished `release` profile [optimized] target(s) in 5.10s
     Running `target/release/wizer --allow-wasi --init-func componentize.wizer --dir=/Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/sources --wasm-bulk-memory=true -o=/Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/out2.wasm /Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/in.wasm`
[2024-09-16T16:26:26Z DEBUG wizer] Validating input Wasm
[2024-09-16T16:26:26Z DEBUG wizer::parse] Parsing the input Wasm
[2024-09-16T16:26:26Z DEBUG wizer::instrument] Instrumenting the input Wasm
[2024-09-16T16:26:26Z DEBUG wasmtime_cache::worker] Cache worker thread started.
[2024-09-16T16:26:26Z DEBUG wasmtime_cache::worker] New nice value of worker thread: 3
[2024-09-16T16:26:26Z DEBUG wizer] Preopening directory: /Users/cataggar/ms/StarlingMonkey15/b0c26fbad66e/sources
[2024-09-16T16:26:26Z DEBUG wasmtime::runtime::code_memory] ignoring section .wasmtime.engine
[2024-09-16T16:26:26Z DEBUG wasmtime::runtime::code_memory] ignoring section .symtab
[2024-09-16T16:26:26Z DEBUG wasmtime::runtime::code_memory] ignoring section .strtab
[2024-09-16T16:26:26Z DEBUG wasmtime::runtime::code_memory] ignoring section .shstrtab
[2024-09-16T16:26:26Z DEBUG wizer] Validating the exported initialization function
[2024-09-16T16:26:26Z DEBUG wizer] Calling the initialization function
[2024-09-16T16:26:26Z DEBUG wizer::dummy] Creating dummy imports
[2024-09-16T16:26:26Z DEBUG wizer::dummy] done Creating dummy imports
[2024-09-16T16:26:26Z DEBUG wizer] going to instantiate linker
[2024-09-16T16:26:26Z DEBUG wizer] going to get_export
[2024-09-16T16:26:26Z DEBUG wizer] going to get_typed_func
[2024-09-16T16:26:26Z DEBUG wizer] going to call init_func

I added a few debug statements like log::debug!("going to call init_func"); to see what was going on.

[guybedford]

I've transferred this issue into ComponentizeJS, as it's a componentize error.

Ideally we'd debug the Wasm stack here to determine the source of the panic in StarlingMonkey, but without debug tracing it's not possible to do that, so this will be very tricky to debug, down to adding a bunch of log statements to StarlingMonkey source itself to see where it's stopping.

The better debugging approach for now would be to run a bisection on the JS code running itself - try break the bundle down into the libraries you're trying to run and try running those libraries one by one, until you get the panic.

Note that syntax / runtime errors should display as normal JS errors with an error log.

I've added #137 to track getting better debug stacks, although this depends on work in Orca.

[cataggar]

I am able to get better debug stack traces by using the debug build.

• Updated package.json to use local jco: "@bytecodealliance/jco": "file:../jco"
• Updated jco package.json to use local ComponentizeJS: "@bytecodealliance/componentize-js": "file:../ComponentizeJS"
• set const DEBUG_BUILD = true in src/componentize.js
• built with npm run build:debug

~/ms/ComponentizeJS> npx jco componentize /Users/cataggar/ms/StarlingMonkey15/cowsay/cowsay.js --wit /Users/cataggar/ms/StarlingMonkey15/cowsay/src/cowsay.wit -o /Users/cataggar/ms/StarlingMonkey15/cowsay.wasm
Redirecting call to abort() to mozalloc_abort

Error: the `componentize.wizer` function trapped

Caused by:
   0: error while executing at wasm backtrace:
          0: 0x16409 - <unknown>!mozalloc_abort
          1: 0x16412 - <unknown>!abort
          2: 0xd9f3 - <unknown>!std::__2::__throw_bad_optional_access[abi:v160000]()
          3: 0x3364c - <unknown>!builtins::web::performance::Performance::timeOrigin_get(JSContext*, unsigned int, JS::Value*)
          4: 0x267638 - <unknown>!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
          5: 0x268076 - <unknown>!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
          6: 0x268787 - <unknown>!js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>)
          7: 0x395750 - <unknown>!js::NativeGetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>)
          8: 0x26b6e8 - <unknown>!js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>)
          9: 0x25ff99 - <unknown>!js::Interpret(JSContext*, js::RunState&)
         10: 0x25a84b - <unknown>!js::RunScript(JSContext*, js::RunState&)
         11: 0x268b27 - <unknown>!js::Execute(JSContext*, JS::Handle<JSScript*>, JS::Handle<JSObject*>, JS::MutableHandle<JS::Value>)
         12: 0x2b34f7 - <unknown>!js::ModuleObject::execute(JSContext*, JS::Handle<js::ModuleObject*>)
         13: 0x38a4f7 - <unknown>!InnerModuleEvaluation(JSContext*, JS::Handle<js::ModuleObject*>, JS::MutableHandle<JS::GCVector<js::ModuleObject*, 0ul, js::SystemAllocPolicy>>, unsigned long, unsigned long*)
         14: 0x38a3a6 - <unknown>!InnerModuleEvaluation(JSContext*, JS::Handle<js::ModuleObject*>, JS::MutableHandle<JS::GCVector<js::ModuleObject*, 0ul, js::SystemAllocPolicy>>, unsigned long, unsigned long*)
         15: 0x389fbf - <unknown>!JS::ModuleEvaluate(JSContext*, JS::Handle<JSObject*>, JS::MutableHandle<JS::Value>)
         16: 0x10eb5 - <unknown>!ScriptLoader::eval_top_level_script(char const*, JS::SourceText<mozilla::Utf8Unit>&, JS::MutableHandle<JS::Value>, JS::MutableHandle<JS::Value>)
         17: 0xd800 - <unknown>!api::Engine::eval_toplevel(JS::SourceText<mozilla::Utf8Unit>&, char const*, JS::MutableHandle<JS::Value>)
         18: 0xd56b - <unknown>!api::Engine::Engine(std::__2::unique_ptr<api::EngineConfig, std::__2::default_delete<api::EngineConfig>>)
         19: 0xbcd7 - <unknown>!wizen()
         20: 0xbe7a - <unknown>!__wizer_initialize()
         21: 0x234c4e - <unknown>!componentize_initialize
      note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information
   1: wasm trap: wasm `unreachable` instruction executed
(jco componentize) Error: Failed to initialize the compiled Wasm binary with Wizer:
Wizering failed to complete
   at componentize (file:///Users/cataggar/ms/ComponentizeJS/src/componentize.js:271:13)
   at async componentize (file:///Users/cataggar/ms/jco/src/cmd/componentize.js:11:25)
   at async file:///Users/cataggar/ms/jco/src/jco.js:200:9

[cataggar]

If I then add WASMTIME_BACKTRACE_DETAILS: '1', to the const env in src/component.js, it is more verbose:

~/ms/ComponentizeJS> npx jco componentize /Users/cataggar/ms/StarlingMonkey15/cowsay/cowsay.js --wit /Users/cataggar/ms/StarlingMonkey15/cowsay/src/cowsay.wit -o /Users/cataggar/ms/StarlingMonkey15/cowsay.wasm
Redirecting call to abort() to mozalloc_abort

Error: the `componentize.wizer` function trapped

Caused by:
    0: error while executing at wasm backtrace:
           0: 0x16409 - mozalloc_abort
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/obj-release/dist/include/mozilla/Assertions.h:58:3
           1: 0x16412 - abort
           2: 0xd9f3 - std::__2::__throw_bad_optional_access[abi:v160000]()
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/deps/cpm_cache/wasi-sdk/c3b77b0f4b7d10c88fc0dd93d5dae49796959c98/wasi-sdk/bin/../share/wasi-sysroot/include/c++/v1/optional:214:9
           3: 0x3364c - std::__2::optional<std::__2::chrono::time_point<std::__2::chrono::steady_clock, std::__2::chrono::duration<long long, std::__2::ratio<(long long)1, (long long)1000000000> > > >::value[abi:v160000]() &
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/deps/cpm_cache/wasi-sdk/c3b77b0f4b7d10c88fc0dd93d5dae49796959c98/wasi-sdk/bin/../share/wasi-sysroot/include/c++/v1/optional:1004:13              - builtins::web::performance::Performance::timeOrigin_get(JSContext*, unsigned int, JS::Value*)
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/builtins/web/performance.cpp:30:54
           4: 0x267638 - CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:488:7              - js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:581:12
           5: 0x268076 - js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:680:7
           6: 0x268787 - js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:802:10
           7: 0x395750 - <unknown>!js::NativeGetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>)
           8: 0x26b6e8 - js::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/ObjectOperations-inl.h:117:10              - js::ToObjectFromStackForPropertyAccess(JSContext*, JS::Handle<JS::Value>, int, JS::Handle<js::PropertyName*>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/ObjectOperations-inl.h:124:10              - js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:4730:11
           9: 0x25ff99 - <unknown>!js::Interpret(JSContext*, js::RunState&)
          10: 0x25a84b - MaybeEnterInterpreterTrampoline(JSContext*, js::RunState&)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:401:10              - js::RunScript(JSContext*, js::RunState&)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:459:13
          11: 0x268b27 - js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JS::Handle<JSObject*>, js::AbstractFramePtr, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:846:13              - js::Execute(JSContext*, JS::Handle<JSScript*>, JS::Handle<JSObject*>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Interpreter.cpp:878:10
          12: 0x2b34f7 - js::ModuleObject::execute(JSContext*, JS::Handle<js::ModuleObject*>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/builtin/ModuleObject.cpp:1420:10
          13: 0x38a4f7 - InnerModuleEvaluation(JSContext*, JS::Handle<js::ModuleObject*>, JS::MutableHandle<JS::GCVector<js::ModuleObject*, (unsigned long)0, js::SystemAllocPolicy> >, unsigned long, unsigned long*)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Modules.cpp:1752:9
          14: 0x38a3a6 - InnerModuleEvaluation(JSContext*, JS::Handle<js::ModuleObject*>, JS::MutableHandle<JS::GCVector<js::ModuleObject*, (unsigned long)0, js::SystemAllocPolicy> >, unsigned long, unsigned long*)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Modules.cpp:1669:9
          15: 0x389fbf - ModuleEvaluate(JSContext*, JS::Handle<js::ModuleObject*>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Modules.cpp:1523:13              - JS::ModuleEvaluate(JSContext*, JS::Handle<JSObject*>, JS::MutableHandle<JS::Value>)
                           at /home/runner/work/spidermonkey-wasi-embedding/spidermonkey-wasi-embedding/gecko-dev/js/src/vm/Modules.cpp:214:10
          16: 0x10eb5 - ScriptLoader::eval_top_level_script(char const*, JS::SourceText<mozilla::Utf8Unit>&, JS::MutableHandle<JS::Value>, JS::MutableHandle<JS::Value>)
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/runtime/script_loader.cpp:497:8
          17: 0xd800 - <unknown>!api::Engine::eval_toplevel(JS::SourceText<mozilla::Utf8Unit>&, char const*, JS::MutableHandle<JS::Value>)
          18: 0xd56b - api::Engine::eval_toplevel(char const*, JS::MutableHandle<JS::Value>)
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/runtime/engine.cpp:528:10              - api::Engine::Engine(std::__2::unique_ptr<api::EngineConfig, std::__2::default_delete<api::EngineConfig> >)
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/runtime/engine.cpp:410:10
          19: 0xbcd7 - wizen()
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/runtime/js.cpp:38:16
          20: 0xbe7a - __wizer_initialize()
                           at /Users/cataggar/ms/ComponentizeJS/StarlingMonkey/runtime/js.cpp:42:1
          21: 0x234c4e - std::__2::vector<componentize::embedding::CoreVal, std::__2::allocator<componentize::embedding::CoreVal> >::push_back[abi:v160000](componentize::embedding::CoreVal&&)
                           at /Users/cataggar/ms/ComponentizeJS/embedding/embedding.cpp:353:3              - componentize_initialize
                           at /Users/cataggar/ms/ComponentizeJS/embedding/embedding.cpp:395:18
    1: wasm trap: wasm `unreachable` instruction executed
(jco componentize) Error: Failed to initialize the compiled Wasm binary with Wizer:
Wizering failed to complete
    at componentize (file:///Users/cataggar/ms/ComponentizeJS/src/componentize.js:271:13)
    at async componentize (file:///Users/cataggar/ms/jco/src/cmd/componentize.js:11:25)
    at async file:///Users/cataggar/ms/jco/src/jco.js:200:9

[cataggar]

It runs successfully with this potential fix bytecodealliance/StarlingMonkey#158 .