GNOME.org
 

[gjs/make-exception-log-levels-consistent] jsapi-util: Make log levels of exceptions consistent

commit 06381b9ace868b0cc43d5c97a5fac6f4f7d8b52e
Author: Philip Chimento <philip chimento gmail com>
Date:   Sun Apr 5 22:29:58 2020 -0700

    jsapi-util: Make log levels of exceptions consistent
    
    When an exception originates from user code, and is not caught, that is
    a programmer error, therefore a critical log message. If an exception is
    logged elsewhere, or through logError(), then it should be a warning.
    
    For this purpose, introduce gjs_log_exception_uncaught() which should
    be called when logging any exception after calling into user code.
    
    Previously SyntaxErrors were logged as criticals and any other
    exceptions as warnings.

 gi/closure.cpp                             |  4 +-
 gi/function.cpp                            |  2 +-
 gi/gobject.cpp                             | 11 +++--
 gjs/context.cpp                            |  4 +-
 gjs/global.cpp                             |  2 +-
 gjs/jsapi-util.cpp                         | 73 ++++++++++++++++++++++--------
 gjs/jsapi-util.h                           |  7 +--
 installed-tests/js/testExceptions.js       | 16 +++++--
 installed-tests/js/testGIMarshalling.js    | 12 ++---
 installed-tests/scripts/testCommandLine.sh |  2 +-
 10 files changed, 90 insertions(+), 43 deletions(-)
---
diff --git a/gi/closure.cpp b/gi/closure.cpp
index 0528062a..15d7c64c 100644
--- a/gi/closure.cpp
+++ b/gi/closure.cpp
@@ -222,7 +222,7 @@ gjs_closure_invoke(GClosure                   *closure,
             if (return_exception)
                 JS_GetPendingException(context, retval);
             else
-                gjs_log_exception(context);
+                gjs_log_exception_uncaught(context);
         } else {
             retval.setUndefined();
             gjs_debug_closure("Closure invocation failed but no exception was set?"
@@ -231,7 +231,7 @@ gjs_closure_invoke(GClosure                   *closure,
         return false;
     }
 
-    if (gjs_log_exception(context)) {
+    if (gjs_log_exception_uncaught(context)) {
         gjs_debug_closure("Closure invocation succeeded but an exception was set"
                           " - closure %p", closure);
     }
diff --git a/gi/function.cpp b/gi/function.cpp
index 34e9a7ae..775d9ec1 100644
--- a/gi/function.cpp
+++ b/gi/function.cpp
@@ -495,7 +495,7 @@ out:
         } else if (!rval.isUndefined()) {
             JS_SetPendingException(context, rval);
         }
-        gjs_log_exception(context);
+        gjs_log_exception_uncaught(context);
     }
 
     if (trampoline->scope == GI_SCOPE_TYPE_ASYNC) {
diff --git a/gi/gobject.cpp b/gi/gobject.cpp
index bc51662d..454bff15 100644
--- a/gi/gobject.cpp
+++ b/gi/gobject.cpp
@@ -158,7 +158,7 @@ static void gjs_object_set_gproperty(GObject* object,
     JSAutoRealm ar(cx, js_obj);
 
     if (!jsobj_set_gproperty(cx, js_obj, value, pspec))
-        gjs_log_exception(cx);
+        gjs_log_exception_uncaught(cx);
 }
 
 static void gjs_object_get_gproperty(GObject* object,
@@ -172,8 +172,11 @@ static void gjs_object_get_gproperty(GObject* object,
     JSAutoRealm ar(cx, js_obj);
 
     GjsAutoChar underscore_name = gjs_hyphen_to_underscore(pspec->name);
-    if (!JS_GetProperty(cx, js_obj, underscore_name, &jsvalue) ||
-        !gjs_value_to_g_value(cx, jsvalue, value))
+    if (!JS_GetProperty(cx, js_obj, underscore_name, &jsvalue)) {
+        gjs_log_exception_uncaught(cx);
+        return;
+    }
+    if (!gjs_value_to_g_value(cx, jsvalue, value))
         gjs_log_exception(cx);
 }
 
@@ -220,7 +223,7 @@ static void gjs_object_custom_init(GTypeInstance* instance,
     gjs->object_init_list().popBack();
 
     if (!priv->init_custom_class_from_gobject(cx, object, G_OBJECT(instance)))
-        gjs_log_exception(cx);
+        gjs_log_exception_uncaught(cx);
 }
 
 static void gjs_interface_init(void* g_iface, void*) {
diff --git a/gjs/context.cpp b/gjs/context.cpp
index 32dfb81c..b5d1a0a4 100644
--- a/gjs/context.cpp
+++ b/gjs/context.cpp
@@ -783,7 +783,7 @@ bool GjsContextPrivate::run_jobs_fallible(void) {
                 }
 
                 /* There's nowhere for the exception to go at this point */
-                gjs_log_exception(m_cx);
+                gjs_log_exception_uncaught(m_cx);
             }
         }
     }
@@ -985,7 +985,7 @@ bool GjsContextPrivate::eval(const char* script, ssize_t script_len,
                         "Script %s threw an exception", filename);
         }
 
-        gjs_log_exception(m_cx);
+        gjs_log_exception_uncaught(m_cx);
         /* No exit code from script, but we don't want to exit(0) */
         *exit_status_p = 1;
         return false;
diff --git a/gjs/global.cpp b/gjs/global.cpp
index 6b1a7875..d4d12411 100644
--- a/gjs/global.cpp
+++ b/gjs/global.cpp
@@ -143,7 +143,7 @@ gjs_log_error(JSContext *cx,
         exc_state.restore();
     }
 
-    gjs_log_exception_full(cx, argv[0], jstr);
+    gjs_log_exception_full(cx, argv[0], jstr, G_LOG_LEVEL_WARNING);
 
     argv.rval().setUndefined();
     return true;
diff --git a/gjs/jsapi-util.cpp b/gjs/jsapi-util.cpp
index c270dd71..82fb2d80 100644
--- a/gjs/jsapi-util.cpp
+++ b/gjs/jsapi-util.cpp
@@ -395,11 +395,20 @@ gjs_value_debug_string(JSContext      *context,
     return _gjs_g_utf8_make_valid(bytes.get());
 }
 
-bool
-gjs_log_exception_full(JSContext       *context,
-                       JS::HandleValue  exc,
-                       JS::HandleString message)
-{
+/**
+ * gjs_log_exception_full:
+ * @cx: the #JSContext
+ * @exc: the exception value to be logged
+ * @message: a string to prepend to the log message
+ * @level: the severity level at which to log the exception
+ *
+ * Currently, uses %G_LOG_LEVEL_WARNING if the exception is being printed after
+ * being caught, and %G_LOG_LEVEL_CRITICAL if it was not caught by user code.
+ *
+ * Returns: %true if an exception was logged, %false if there was none pending.
+ */
+bool gjs_log_exception_full(JSContext* context, JS::HandleValue exc,
+                            JS::HandleString message, GLogLevelFlags level) {
     bool is_syntax;
     const GjsAtoms& atoms = GjsContextPrivate::atoms(context);
 
@@ -445,14 +454,13 @@ gjs_log_exception_full(JSContext       *context,
         lineNumber = js_lineNumber.toInt32();
 
         if (message) {
-            g_critical("JS ERROR: %s: %s @ %s:%u", utf8_message.get(),
-                       utf8_exception.get(),
-                       utf8_filename ? utf8_filename.get() : "unknown",
-                       lineNumber);
+            g_log(G_LOG_DOMAIN, level, "JS ERROR: %s: %s @ %s:%u",
+                  utf8_message.get(), utf8_exception.get(),
+                  utf8_filename ? utf8_filename.get() : "unknown", lineNumber);
         } else {
-            g_critical("JS ERROR: %s @ %s:%u", utf8_exception.get(),
-                       utf8_filename ? utf8_filename.get() : "unknown",
-                       lineNumber);
+            g_log(G_LOG_DOMAIN, level, "JS ERROR: %s @ %s:%u",
+                  utf8_exception.get(),
+                  utf8_filename ? utf8_filename.get() : "unknown", lineNumber);
         }
 
     } else {
@@ -468,17 +476,19 @@ gjs_log_exception_full(JSContext       *context,
 
         if (message) {
             if (utf8_stack)
-                g_warning("JS ERROR: %s: %s\n%s", utf8_message.get(),
-                          utf8_exception.get(), utf8_stack.get());
+                g_log(G_LOG_DOMAIN, level, "JS ERROR: %s: %s\n%s",
+                      utf8_message.get(), utf8_exception.get(),
+                      utf8_stack.get());
             else
-                g_warning("JS ERROR: %s: %s", utf8_message.get(),
-                          utf8_exception.get());
+                g_log(G_LOG_DOMAIN, level, "JS ERROR: %s: %s",
+                      utf8_message.get(), utf8_exception.get());
         } else {
             if (utf8_stack)
-                g_warning("JS ERROR: %s\n%s", utf8_exception.get(),
-                          utf8_stack.get());
+                g_log(G_LOG_DOMAIN, level, "JS ERROR: %s\n%s",
+                      utf8_exception.get(), utf8_stack.get());
             else
-                g_warning("JS ERROR: %s", utf8_exception.get());
+                g_log(G_LOG_DOMAIN, level, "JS ERROR: %s",
+                      utf8_exception.get());
         }
     }
 
@@ -494,7 +504,30 @@ gjs_log_exception(JSContext  *context)
 
     JS_ClearPendingException(context);
 
-    gjs_log_exception_full(context, exc, nullptr);
+    gjs_log_exception_full(context, exc, nullptr, G_LOG_LEVEL_WARNING);
+    return true;
+}
+
+/**
+ * gjs_log_exception_uncaught:
+ * @cx: the #JSContext
+ *
+ * Logs the exception pending on @cx, if any, indicating an uncaught exception
+ * in the running JS program.
+ * (Currently, due to main loop boundaries, uncaught exceptions may not bubble
+ * all the way back up to the top level, so this doesn't necessarily mean the
+ * program exits with an error.)
+ *
+ * Returns: %true if an exception was logged, %false if there was none pending.
+ */
+bool gjs_log_exception_uncaught(JSContext* cx) {
+    JS::RootedValue exc(cx);
+    if (!JS_GetPendingException(cx, &exc))
+        return false;
+
+    JS_ClearPendingException(cx);
+
+    gjs_log_exception_full(cx, exc, nullptr, G_LOG_LEVEL_CRITICAL);
     return true;
 }
 
diff --git a/gjs/jsapi-util.h b/gjs/jsapi-util.h
index 3d399ce3..47866a8f 100644
--- a/gjs/jsapi-util.h
+++ b/gjs/jsapi-util.h
@@ -242,9 +242,10 @@ bool gjs_throw_gerror_message(JSContext* cx, GError* error);
 
 bool        gjs_log_exception                (JSContext       *context);
 
-bool gjs_log_exception_full(JSContext       *context,
-                            JS::HandleValue  exc,
-                            JS::HandleString message);
+bool gjs_log_exception_uncaught(JSContext* cx);
+
+bool gjs_log_exception_full(JSContext* cx, JS::HandleValue exc,
+                            JS::HandleString message, GLogLevelFlags level);
 
 GJS_USE
 char *gjs_value_debug_string(JSContext      *context,
diff --git a/installed-tests/js/testExceptions.js b/installed-tests/js/testExceptions.js
index 8e7b1e1d..abcfeb47 100644
--- a/installed-tests/js/testExceptions.js
+++ b/installed-tests/js/testExceptions.js
@@ -35,7 +35,7 @@ describe('Exceptions', function () {
     // FIXME: In the next cases the errors aren't thrown but logged
 
     it('are logged from constructor', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: set*');
 
         new Foo({prop: 'bar'});
@@ -51,7 +51,7 @@ describe('Exceptions', function () {
         bar.bind_property('prop',
             foo, 'prop',
             GObject.BindingFlags.DEFAULT);
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: set*');
 
         // wake up the binding so that g_object_set() is called on foo
@@ -68,7 +68,7 @@ describe('Exceptions', function () {
         foo.bind_property('prop',
             bar, 'prop',
             GObject.BindingFlags.DEFAULT);
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: get*');
 
         // wake up the binding so that g_object_get() is called on foo
@@ -152,6 +152,16 @@ describe('logError', function () {
             logError(e, 'prefix');
         }
     });
+
+    it('logs a SyntaxError', function () {
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+            'JS ERROR: SyntaxError:*');
+        try {
+            Reflect.parse('!@#$%^&');
+        } catch (e) {
+            logError(e);
+        }
+    });
 });
 
 describe('Exception from function with too few arguments', function () {
diff --git a/installed-tests/js/testGIMarshalling.js b/installed-tests/js/testGIMarshalling.js
index 7247078c..1f772db3 100644
--- a/installed-tests/js/testGIMarshalling.js
+++ b/installed-tests/js/testGIMarshalling.js
@@ -1369,7 +1369,7 @@ describe('Wrong virtual functions', function () {
     }).pend('https://gitlab.gnome.org/GNOME/gjs/issues/311');
 
     it('marshals multiple out parameters', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Function *vfunc_vfunc_multiple_out_parameters*Array*');
 
         expect(tester.vfunc_multiple_out_parameters()).toEqual([0, 0]);
@@ -1379,7 +1379,7 @@ describe('Wrong virtual functions', function () {
     });
 
     it('marshals a return value and one out parameter', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Function *vfunc_return_value_and_one_out_parameter*Array*');
 
         expect(tester.vfunc_return_value_and_one_out_parameter()).toEqual([0, 0]);
@@ -1389,7 +1389,7 @@ describe('Wrong virtual functions', function () {
     });
 
     it('marshals a return value and multiple out parameters', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Function *vfunc_return_value_and_multiple_out_parameters*Array*');
 
         expect(tester.vfunc_return_value_and_multiple_out_parameters()).toEqual([0, 0, 0]);
@@ -1399,7 +1399,7 @@ describe('Wrong virtual functions', function () {
     });
 
     it('marshals an array out parameter', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Expected type gfloat for Argument*undefined*');
 
         expect(tester.vfunc_array_out_parameter()).toEqual(null);
@@ -1409,7 +1409,7 @@ describe('Wrong virtual functions', function () {
     });
 
     it('marshals an enum return value', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Expected type enum for Return*undefined*');
 
         expect(tester.vfunc_return_enum()).toEqual(0);
@@ -1419,7 +1419,7 @@ describe('Wrong virtual functions', function () {
     });
 
     it('marshals an enum out parameter', function () {
-        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_WARNING,
+        GLib.test_expect_message('Gjs', GLib.LogLevelFlags.LEVEL_CRITICAL,
             'JS ERROR: Error: Expected type enum for Argument*undefined*');
 
         expect(tester.vfunc_out_enum()).toEqual(0);
diff --git a/installed-tests/scripts/testCommandLine.sh b/installed-tests/scripts/testCommandLine.sh
index 6f07dd50..7cd71fc4 100755
--- a/installed-tests/scripts/testCommandLine.sh
+++ b/installed-tests/scripts/testCommandLine.sh
@@ -222,7 +222,7 @@ test -z "$($gjs awaitcatch.js)"
 report "catching an await expression should not cause unhandled rejection"
 # https://gitlab.gnome.org/GNOME/gjs/issues/18
 G_DEBUG=$(echo "$G_DEBUG" | sed -e 's/fatal-warnings,\{0,1\}//')
-$gjs -c "(async () => await true)(); void foobar;" 2>&1 | grep -q 'Script .* threw an exception'
+$gjs -c "(async () => await true)(); void foobar;" 2>&1 | grep -q 'ReferenceError: foobar is not defined'
 report "main program exceptions are not swallowed by queued promise jobs"
 G_DEBUG="$OLD_G_DEBUG"
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]