Viceroy icon indicating copy to clipboard operation
Viceroy copied to clipboard

Published 20 hours ago • verified publisher icon fastly

Debug logs being truncated

Open guybedford opened this issue 1 year ago • 2 comments

With the new 0.4.0 release, Fastly CLI will auto-update Viceroy. In a debugging workflow for js-compute-runtime, I found I was getting the following debug logs before the update:

2023-03-17T18:34:21.822242Z  WARN no backend definitions found in /Users/gbedford/Projects/js-compute-runtime/integration-tests/js-compute/fixtures/byob/fastly.toml
2023-03-17T18:34:21.822403Z  INFO Listening on http://127.0.0.1:7676
2023-03-17T18:34:23.761738Z  INFO request{id=0}: handling request GET http://localhost:7676/?vscodeBrowserReqId=1679078063748
Log: ReadableByteStreamController {}
Log: got reader
Log: ReadableStreamDefaultReader {}
Log: reading
Assertion failure: isObject(), at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/obj-debug/dist/include/js/Value.h:957
2023-03-17T18:34:23.978461Z ERROR request{id=0}: WebAssembly trapped: error while executing at wasm backtrace:
    0: 0x73a2a5 - JS::Value::toObject() const
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/obj-debug/dist/include/js/Value.h:957:5              - js::StreamController::queue() const
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/StreamController.h:36:38
    1: 0x738cd0 - ReadableByteStreamControllerPullSteps(JSContext*, JS::Handle<js::ReadableByteStreamController*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/Stream.cpp:316:67              - js::ReadableStreamControllerPullSteps(JSContext*, JS::Handle<js::ReadableStreamController*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/Stream.cpp:451:10
    2: 0x8f0ce4 - js::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<js::ReadableStreamReader*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/ReadableStreamDefaultReader.cpp:312:10
    3: 0x8f523b - ReadableStreamDefaultReader_read(JSContext*, unsigned int, JS::Value*)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/ReadableStreamDefaultReader.cpp:213:7
    4: 0x4cef7f - CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:459:13
    5: 0x4ce639 - js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:547:12
    6: 0x4c723b - InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:614:10
    7: 0x4b0bbf - js::CallFromStack(JSContext*, JS::CallArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:619:10              - Interpret(JSContext*, js::RunState&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:3362:16
    8: 0x4a7b72 - js::RunScript(JSContext*, js::RunState&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:431:13
    9: 0x4ce7cc - js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:579:13
   10: 0x4c723b - InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:614:10
   11: 0x4cfc98 - js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:646:8
   12: 0x5ebebb - JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/CallAndConstruct.cpp:53:10
   13: 0x19463 - dispatch_fetch_event(JSContext*, JS::Handle<JSObject*>, double*)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:413:10              - __main_argc_argv
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:494:3
   14: 0xec7406 - <unknown>!__main_void
   15: 0x191e8 - __wizer_resume()
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:398:1

Caused by:
    wasm trap: wasm `unreachable` instruction executed
2023-03-17T18:34:23.978661Z  INFO request{id=0}: request completed using 9.0 MB of WebAssembly heap
2023-03-17T18:34:23.978665Z  INFO request{id=0}: request completed in 217ms
2023-03-17T18:34:23.979029Z ERROR There was an error handling the request error while executing at wasm backtrace:
    0: 0x73a2a5 - JS::Value::toObject() const
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/obj-debug/dist/include/js/Value.h:957:5              - js::StreamController::queue() const
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/StreamController.h:36:38
    1: 0x738cd0 - ReadableByteStreamControllerPullSteps(JSContext*, JS::Handle<js::ReadableByteStreamController*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/Stream.cpp:316:67              - js::ReadableStreamControllerPullSteps(JSContext*, JS::Handle<js::ReadableStreamController*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/Stream.cpp:451:10
    2: 0x8f0ce4 - js::ReadableStreamDefaultReaderRead(JSContext*, JS::Handle<js::ReadableStreamReader*>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/ReadableStreamDefaultReader.cpp:312:10
    3: 0x8f523b - ReadableStreamDefaultReader_read(JSContext*, unsigned int, JS::Value*)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/builtin/streams/ReadableStreamDefaultReader.cpp:213:7
    4: 0x4cef7f - CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:459:13
    5: 0x4ce639 - js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:547:12
    6: 0x4c723b - InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:614:10
    7: 0x4b0bbf - js::CallFromStack(JSContext*, JS::CallArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:619:10              - Interpret(JSContext*, js::RunState&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:3362:16
    8: 0x4a7b72 - js::RunScript(JSContext*, js::RunState&)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:431:13
    9: 0x4ce7cc - js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:579:13
   10: 0x4c723b - InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:614:10
   11: 0x4cfc98 - js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/Interpreter.cpp:646:8
   12: 0x5ebebb - JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/gecko-dev/js/src/vm/CallAndConstruct.cpp:53:10
   13: 0x19463 - dispatch_fetch_event(JSContext*, JS::Handle<JSObject*>, double*)
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:413:10              - __main_argc_argv
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:494:3
   14: 0xec7406 - <unknown>!__main_void
   15: 0x191e8 - __wizer_resume()
                    at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/js-compute-runtime/js-compute-runtime.cpp:398:1

After the update, with the same options this same debug logging is truncated to:

Log: ReadableByteStreamController {}
Log: got reader
Log: ReadableStreamDefaultReader {}
Log: reading
Assertion failure: isObject(), at /Users/gbedford/Projects/js-compute-runtime/c-dependencies/spidermonkey/obj-debug/dist/include/js/Value.h:957

I can understand not creating debug output like this for a release application, but it would be great to ensure fastly CLI can still get this level of detail. I tried passing the --verbose flag to fastly CLI and that didn't help, although I'm not sure if it in turn passes its verbose flag to Viceroy.

guybedford avatar Mar 17 '23 18:03 guybedford