Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Debug logs being truncated #235

Open
guybedford opened this issue Mar 17, 2023 · 2 comments
Open

Debug logs being truncated #235

guybedford opened this issue Mar 17, 2023 · 2 comments

Comments

@guybedford
Copy link
Member

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
Copy link
Member Author

guybedford commented Mar 17, 2023 •
edited
Loading

It seems it would be worth investigating the verbosity passed to Viceroy by FastlyCLI in de011c3#diff-37970e7d817d4316a093bb967d74ff7e26d9c6c01d93f5a79d3d195ba9f6155bR63.

@itsrainy itsrainy mentioned this issue Mar 17, 2023
Merged
@JakeChampion
Copy link
Contributor

@guybedford does the above PR (fastly/cli#878) to the Fastly CLI resolve the issue you were seeing?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@guybedford @JakeChampion