Debug logs being truncated
guybedford opened this issue · 2 comments
guybedford commented
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 commented
It seems it would be worth investigating the verbosity passed to Viceroy by FastlyCLI in de011c3#diff-37970e7d817d4316a093bb967d74ff7e26d9c6c01d93f5a79d3d195ba9f6155bR63.
JakeChampion commented
@guybedford does the above PR (fastly/cli#878) to the Fastly CLI resolve the issue you were seeing?