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

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 <stdlib.h>  // for exit
 
 #include <memory>  // for unique_ptr
+#include <sstream>
 #include <string>
 #include <vector>
 
@@ -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<GjsAutoGClosure> 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 <stdint.h>
 #include <stdlib.h>  // for exit
 
+#include <sstream>
 #include <string>
 
 #include <girepository.h>
@@ -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(&param_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 <config.h>
 
-#include <stdio.h>  // for stderr
+#include <stdio.h>  // for stderr, open_memstream
+
+#include <sstream>
+#include <string>
 
 #include <glib-object.h>
 #include <glib.h>
@@ -12,6 +15,7 @@
 #include <js/TypeDecls.h>
 #include <js/friend/DumpFunctions.h>
 
+#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<JSContext *>(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<GList> contexts = gjs_context_get_all();
+    GList *iter;
+
+    for (iter = contexts; iter; iter = iter->next) {
+        GjsAutoUnref<GjsContext> 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 <stdio.h>'),
+    description: 'open_memstream() is available')
 if build_readline
     header_conf.set('HAVE_READLINE_READLINE_H',
         cxx.check_header('readline/readline.h', prefix: '#include <cstdio>',