From 5b1e0a3ccdcf394cf746ef4e75b7b69f1535a710 Mon Sep 17 00:00:00 2001 From: Sebastian Keller Date: Thu, 16 Mar 2023 22:13:09 +0100 Subject: stack: Print stack trace using glib logging functions When the gjs process is logging to the systemd journal directly via the glib logging functions, the stack trace would get logged indirectly via stderr. This however is not guaranteed to get added to the journal at the same time as the error messages logged via glib. This is especially noticeable when triggered from an endless loop or an idle callback. In some cases it even can result in the stack trace not getting logged at all. There is currently no public API in mozjs to dump a stack trace directly to a string from arbitrary threads, only to files, so this uses open_memstream() as a workaround. Related: https://gitlab.gnome.org/GNOME/gnome-shell/-/issues/1868 --- gi/function.cpp | 38 ++++++++++------ gi/function.h | 3 +- gi/object.cpp | 6 +-- gi/value.cpp | 26 ++++++----- gjs/context-private.h | 3 ++ gjs/stack.cpp | 52 +++++++++++++++++++++- installed-tests/js/testGObjectDestructionAccess.js | 4 +- installed-tests/js/testGtk3.js | 8 +--- meson.build | 3 ++ 9 files changed, 103 insertions(+), 40 deletions(-) diff --git a/gi/function.cpp b/gi/function.cpp index 1629876b..cf94b39e 100644 --- a/gi/function.cpp +++ b/gi/function.cpp @@ -8,6 +8,7 @@ #include // for exit #include // for unique_ptr +#include #include #include @@ -47,7 +48,6 @@ #include "gi/object.h" #include "gi/utils-inl.h" #include "gjs/context-private.h" -#include "gjs/context.h" #include "gjs/global.h" #include "gjs/jsapi-util.h" #include "gjs/macros.h" @@ -270,13 +270,21 @@ set_return_ffi_arg_from_giargument (GITypeInfo *ret_type, } void GjsCallbackTrampoline::warn_about_illegal_js_callback(const char* when, - const char* reason) { - g_critical("Attempting to run a JS callback %s. This is most likely caused " - "by %s. Because it would crash the application, it has been " - "blocked.", when, reason); - if (m_info) - g_critical("The offending callback was %s()%s.", m_info.name(), - m_is_vfunc ? ", a vfunc" : ""); + const char* reason, + bool dump_stack) { + std::ostringstream message; + + message << "Attempting to run a JS callback " << when << ". " + << "This is most likely caused by " << reason << ". " + << "Because it would crash the application, it has been blocked."; + if (m_info) { + message << "\nThe offending callback was " << m_info.name() << "()" + << (m_is_vfunc ? ", a vfunc." : "."); + } + if (dump_stack) { + message << "\n" << gjs_dumpstack_string(); + } + g_critical("%s", message.str().c_str()); } /* This is our main entry point for ffi_closure callbacks. @@ -293,8 +301,8 @@ void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { warn_about_illegal_js_callback( "during shutdown", "destroying a Clutter actor or GTK widget with ::destroy signal " - "connected, or using the destroy(), dispose(), or remove() vfuncs"); - gjs_dumpstack(); + "connected, or using the destroy(), dispose(), or remove() vfuncs", + true); return; } @@ -304,14 +312,15 @@ void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { warn_about_illegal_js_callback( "during garbage collection", "destroying a Clutter actor or GTK widget with ::destroy signal " - "connected, or using the destroy(), dispose(), or remove() vfuncs"); - gjs_dumpstack(); + "connected, or using the destroy(), dispose(), or remove() vfuncs", + true); return; } if (G_UNLIKELY(!gjs->is_owner_thread())) { warn_about_illegal_js_callback("on a different thread", - "an API not intended to be used in JS"); + "an API not intended to be used in JS", + false); return; } @@ -351,7 +360,8 @@ void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { if (g_object_get_qdata(gobj, ObjectBase::disposed_quark())) { warn_about_illegal_js_callback( "on disposed object", - "using the destroy(), dispose(), or remove() vfuncs"); + "using the destroy(), dispose(), or remove() vfuncs", + false); } gjs_log_exception(context); return; diff --git a/gi/function.h b/gi/function.h index c875ecbd..b9ee87be 100644 --- a/gi/function.h +++ b/gi/function.h @@ -79,7 +79,8 @@ struct GjsCallbackTrampoline : public Gjs::Closure { GObject* gobject, JS::MutableHandleValue rval, GIArgument** args, GITypeInfo* ret_type, int n_args, int c_args_offset, void* result); - void warn_about_illegal_js_callback(const char* when, const char* reason); + void warn_about_illegal_js_callback(const char* when, const char* reason, + bool dump_stack); static std::vector s_forever_closure_list; diff --git a/gi/object.cpp b/gi/object.cpp index 62e79c18..1ad12afe 100644 --- a/gi/object.cpp +++ b/gi/object.cpp @@ -58,7 +58,6 @@ #include "gi/wrapperutils.h" #include "gjs/atoms.h" #include "gjs/context-private.h" -#include "gjs/context.h" #include "gjs/deprecation.h" #include "gjs/jsapi-class.h" #include "gjs/jsapi-util.h" @@ -165,10 +164,9 @@ bool ObjectInstance::check_gobject_disposed_or_finalized( "Object %s.%s (%p), has been already %s — impossible to %s " "it. This might be caused by the object having been destroyed from C " "code using something such as destroy(), dispose(), or remove() " - "vfuncs.", + "vfuncs.\n%s", ns(), name(), m_ptr.get(), m_gobj_finalized ? "finalized" : "disposed", - for_what); - gjs_dumpstack(); + for_what, gjs_dumpstack_string().c_str()); return false; } diff --git a/gi/value.cpp b/gi/value.cpp index 17db002f..59237f1e 100644 --- a/gi/value.cpp +++ b/gi/value.cpp @@ -7,6 +7,7 @@ #include #include // for exit +#include #include #include @@ -46,7 +47,6 @@ #include "gjs/atoms.h" #include "gjs/byteArray.h" #include "gjs/context-private.h" -#include "gjs/context.h" #include "gjs/jsapi-util.h" #include "gjs/macros.h" #include "gjs/objectbox.h" @@ -142,22 +142,26 @@ void Gjs::Closure::marshal(GValue* return_value, unsigned n_param_values, GjsContextPrivate* gjs = GjsContextPrivate::from_cx(context); if (G_UNLIKELY(gjs->sweeping())) { GSignalInvocationHint *hint = (GSignalInvocationHint*) invocation_hint; - - g_critical("Attempting to call back into JSAPI during the sweeping phase of GC. " - "This is most likely caused by not destroying a Clutter actor or Gtk+ " - "widget with ::destroy signals connected, but can also be caused by " - "using the destroy(), dispose(), or remove() vfuncs. " - "Because it would crash the application, it has been " - "blocked and the JS callback not invoked."); + std::ostringstream message; + + message << "Attempting to call back into JSAPI during the sweeping " + "phase of GC. This is most likely caused by not destroying " + "a Clutter actor or Gtk+ widget with ::destroy signals " + "connected, but can also be caused by using the destroy(), " + "dispose(), or remove() vfuncs. Because it would crash the " + "application, it has been blocked and the JS callback not " + "invoked."; if (hint) { gpointer instance; g_signal_query(hint->signal_id, &signal_query); instance = g_value_peek_pointer(¶m_values[0]); - g_critical("The offending signal was %s on %s %p.", signal_query.signal_name, - g_type_name(G_TYPE_FROM_INSTANCE(instance)), instance); + message << "\nThe offending signal was " << signal_query.signal_name + << " on " << g_type_name(G_TYPE_FROM_INSTANCE(instance)) + << " " << instance << "."; } - gjs_dumpstack(); + message << "\n" << gjs_dumpstack_string(); + g_critical("%s", message.str().c_str()); return; } diff --git a/gjs/context-private.h b/gjs/context-private.h index 147feae4..cb621058 100644 --- a/gjs/context-private.h +++ b/gjs/context-private.h @@ -271,4 +271,7 @@ class GjsContextPrivate : public JS::JobQueue { void free_profiler(void); void dispose(void); }; + +std::string gjs_dumpstack_string(); + #endif // GJS_CONTEXT_PRIVATE_H_ diff --git a/gjs/stack.cpp b/gjs/stack.cpp index 3292eae4..9e22b4af 100644 --- a/gjs/stack.cpp +++ b/gjs/stack.cpp @@ -4,7 +4,10 @@ #include -#include // for stderr +#include // for stderr, open_memstream + +#include +#include #include #include @@ -12,6 +15,7 @@ #include #include +#include "gjs/context-private.h" #include "gjs/context.h" #include "gjs/jsapi-util.h" @@ -35,3 +39,49 @@ gjs_dumpstack(void) gjs_context_print_stack_stderr(context); } } + +#ifdef HAVE_OPEN_MEMSTREAM +static std::string +stack_trace_string(GjsContext *context) { + JSContext *cx = static_cast(gjs_context_get_native_context(context)); + std::ostringstream out; + FILE *stream; + GjsAutoChar buf; + size_t len; + + stream = open_memstream(buf.out(), &len); + if (!stream) { + out << "No stack trace for context " << context << ": " + "open_memstream() failed\n\n"; + return out.str(); + } + js::DumpBacktrace(cx, stream); + fclose(stream); + out << "== Stack trace for context " << context << " ==\n" + << buf.get() << "\n"; + return out.str(); +} +#endif + +std::string +gjs_dumpstack_string() { + std::string out; + std::ostringstream all_traces; + +#ifdef HAVE_OPEN_MEMSTREAM + GjsSmartPointer contexts = gjs_context_get_all(); + GList *iter; + + for (iter = contexts; iter; iter = iter->next) { + GjsAutoUnref context(GJS_CONTEXT(iter->data)); + all_traces << stack_trace_string(context); + } + out = all_traces.str(); + out.resize(MAX(out.size() - 2, 0)); +#else + out = "No stack trace: no open_memstream() support. " + "See https://bugzilla.mozilla.org/show_bug.cgi?id=1826290"; +#endif + + return out; +} diff --git a/installed-tests/js/testGObjectDestructionAccess.js b/installed-tests/js/testGObjectDestructionAccess.js index 889cebd7..8f079afd 100644 --- a/installed-tests/js/testGObjectDestructionAccess.js +++ b/installed-tests/js/testGObjectDestructionAccess.js @@ -381,9 +381,7 @@ describe('Disposed or finalized GObject', function () { file = null; GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*during garbage collection*'); - GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*dispose*'); + '*during garbage collection*offending callback was dispose()*'); System.gc(); GLib.test_assert_expected_messages_internal('Gjs', 'testGObjectDestructionAccess.js', 0, 'calls dispose vfunc on explicit disposal only'); diff --git a/installed-tests/js/testGtk3.js b/installed-tests/js/testGtk3.js index 9f4af90b..f409f255 100644 --- a/installed-tests/js/testGtk3.js +++ b/installed-tests/js/testGtk3.js @@ -177,9 +177,7 @@ describe('Gtk overrides', function () { it('avoid crashing when GTK vfuncs are called in garbage collection', function () { GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*during garbage collection*'); - GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*destroy*'); + '*during garbage collection*offending callback was destroy()*'); const BadLabel = GObject.registerClass(class BadLabel extends Gtk.Label { vfunc_destroy() {} @@ -206,9 +204,7 @@ describe('Gtk overrides', function () { expect(spy).toHaveBeenCalledTimes(1); GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*during garbage collection*'); - GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL, - '*destroy*'); + '*during garbage collection*offending callback was destroy()*'); label = null; System.gc(); GLib.test_assert_expected_messages_internal('Gjs', 'testGtk3.js', 0, diff --git a/meson.build b/meson.build index 74b3c006..add86602 100644 --- a/meson.build +++ b/meson.build @@ -330,6 +330,9 @@ header_conf.set('HAVE_DTRACE', get_option('dtrace'), description: 'Using dtrace probes') header_conf.set('HAVE_PRINTF_ALTERNATIVE_INT', have_printf_alternative_int, description: 'printf() accepts "%Id" for alternative integer output') +header_conf.set('HAVE_OPEN_MEMSTREAM', + cxx.has_function('open_memstream', prefix : '#include '), + description: 'open_memstream() is available') if build_readline header_conf.set('HAVE_READLINE_READLINE_H', cxx.check_header('readline/readline.h', prefix: '#include ', -- cgit v1.2.1 From c925d91e5d018f38b0f66d0ac592274d4b007efb Mon Sep 17 00:00:00 2001 From: Sebastian Keller Date: Thu, 16 Mar 2023 22:35:49 +0100 Subject: function: Always initialize callback return value When callback_closure() exits early, for example due to being called during GC, the return value would not be initialized. This value is often non-zero. If the callback is a source func of an idle or a timeout this would then get interpreted as G_SOURCE_CONTINUE and the same would repeat in the next iteration. If this happens fast enough, this results in the entire process being seemingly frozen while spamming the log with error messages. To fix this always initialize the return value to 0 or a comparable neutral value. Related: https://gitlab.gnome.org/GNOME/gnome-shell/-/issues/1868 --- gi/function.cpp | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/gi/function.cpp b/gi/function.cpp index cf94b39e..3fb87939 100644 --- a/gi/function.cpp +++ b/gi/function.cpp @@ -297,6 +297,14 @@ void GjsCallbackTrampoline::warn_about_illegal_js_callback(const char* when, void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { GITypeInfo ret_type; + // Fill in the result with some hopefully neutral value + g_callable_info_load_return_type(m_info, &ret_type); + if (g_type_info_get_tag(&ret_type) != GI_TYPE_TAG_VOID) { + GIArgument argument = {}; + gjs_gi_argument_init_default(&ret_type, &argument); + set_return_ffi_arg_from_giargument(&ret_type, result, &argument); + } + if (G_UNLIKELY(!is_valid())) { warn_about_illegal_js_callback( "during shutdown", @@ -375,8 +383,6 @@ void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { JS::RootedValue rval(context); - g_callable_info_load_return_type(m_info, &ret_type); - if (!callback_closure_inner(context, this_object, gobj, &rval, args, &ret_type, n_args, c_args_offset, result)) { if (!JS_IsExceptionPending(context)) { @@ -399,14 +405,6 @@ void GjsCallbackTrampoline::callback_closure(GIArgument** args, void* result) { descr.c_str(), m_info.ns(), m_info.name()); } - // Fill in the result with some hopefully neutral value - if (g_type_info_get_tag(&ret_type) != GI_TYPE_TAG_VOID) { - GIArgument argument = {}; - g_callable_info_load_return_type(m_info, &ret_type); - gjs_gi_argument_init_default(&ret_type, &argument); - set_return_ffi_arg_from_giargument(&ret_type, result, &argument); - } - // If the callback has a GError** argument, then make a GError from the // value that was thrown. Otherwise, log it as "uncaught" (critical // instead of warning) -- cgit v1.2.1