From dbf219610ee6e0d7b1570503ef853e8fba36217d Mon Sep 17 00:00:00 2001
From: Simon McVittie <smcv@collabora.com>
Date: Fri, 26 Feb 2021 12:00:09 +0000
Subject: [PATCH] pressure-vessel: Put apt-style severity prefixes on messages

These indicate which lines are harmless and which lines are really bad,
without taking up too much space.

The mapping from GLib log level to message is not 100% obvious, because
G_LOG_LEVEL_ERROR is "worse than" an error. We diagnose "can't happen"
situations (assertion failures, etc.) as "Internal error". Ideally,
users should never see these: they indicate a bug.

For situations that will cause pressure-vessel to exit with an error,
introduce a new log level flag PV_LOG_LEVEL_FAILURE and map it to the
apt-style "E:" prefix. pv_log_failure() is a convenience macro to log
at level PV_LOG_LEVEL_FAILURE. Conceptually this is a fatal error, but
it's a fatal error prompted by something external to pressure-vessel,
for which we want pressure-vessel to clean up "nicely" and exit
gracefully, even though it's going to fail - so we can't use g_error()
for this.

In the parts of main() that involve parsing command-line arguments,
add usage_error() as syntactic sugar for pv_log_failure(). I might
eventually turn these into G_OPTION_ERROR_FAILED as we factor out
more of main() into helper functions, but for now they're handled
separately.

For less-severe log levels, use single-letter prefixes similar to apt's.

Signed-off-by: Simon McVittie <smcv@collabora.com>
---
 pressure-vessel/adverb.c   |  2 +-
 pressure-vessel/launch.c   |  2 +-
 pressure-vessel/launcher.c |  6 ++--
 pressure-vessel/utils.c    | 50 ++++++++++++++++++++++++++++---
 pressure-vessel/utils.h    |  5 ++++
 pressure-vessel/wrap.c     | 60 ++++++++++++++++++++------------------
 6 files changed, 87 insertions(+), 38 deletions(-)

diff --git a/pressure-vessel/adverb.c b/pressure-vessel/adverb.c
index 924b1dcde..1ec830553 100644
--- a/pressure-vessel/adverb.c
+++ b/pressure-vessel/adverb.c
@@ -965,7 +965,7 @@ out:
     _srt_rm_rf (locales_temp_dir);
 
   if (local_error != NULL)
-    g_warning ("%s", local_error->message);
+    pv_log_failure ("%s", local_error->message);
 
   global_original_environ = NULL;
   g_debug ("Exiting with status %d", ret);
diff --git a/pressure-vessel/launch.c b/pressure-vessel/launch.c
index 1913af2c0..66facac65 100644
--- a/pressure-vessel/launch.c
+++ b/pressure-vessel/launch.c
@@ -1107,7 +1107,7 @@ main (int argc,
 
 out:
   if (local_error != NULL)
-    g_warning ("%s", local_error->message);
+    pv_log_failure ("%s", local_error->message);
 
   if (signal_source > 0)
     g_source_remove (signal_source);
diff --git a/pressure-vessel/launcher.c b/pressure-vessel/launcher.c
index 1a859d54c..e95a7cedd 100644
--- a/pressure-vessel/launcher.c
+++ b/pressure-vessel/launcher.c
@@ -586,7 +586,7 @@ on_bus_acquired (PvPortalListener *listener,
 
   if (!export_launcher (connection, &error))
     {
-      g_warning ("Unable to export object: %s", error->message);
+      pv_log_failure ("Unable to export object: %s", error->message);
       *ret = EX_SOFTWARE;
       g_main_loop_quit (main_loop);
     }
@@ -703,7 +703,7 @@ connect_to_signals (void)
 
   if (sfd < 0)
     {
-      g_warning ("Unable to watch signals: %s", g_strerror (errno));
+      pv_log_failure ("Unable to watch signals: %s", g_strerror (errno));
       return 0;
     }
 
@@ -1042,7 +1042,7 @@ main (int argc,
 
 out:
   if (local_error != NULL)
-    g_warning ("%s", local_error->message);
+    pv_log_failure ("%s", local_error->message);
 
   if (exit_on_readable_id > 0)
     g_source_remove (exit_on_readable_id);
diff --git a/pressure-vessel/utils.c b/pressure-vessel/utils.c
index 57a2fb37b..47ccda7c3 100644
--- a/pressure-vessel/utils.c
+++ b/pressure-vessel/utils.c
@@ -927,6 +927,33 @@ pv_current_namespace_path_to_host_path (const gchar *current_env_path)
   return path_on_host;
 }
 
+static const char *
+get_level_prefix (GLogLevelFlags log_level)
+{
+  if (log_level & (G_LOG_FLAG_RECURSION
+                   | G_LOG_FLAG_FATAL
+                   | G_LOG_LEVEL_ERROR
+                   | G_LOG_LEVEL_CRITICAL))
+    return "Internal error";
+
+  if (log_level & PV_LOG_LEVEL_FAILURE)
+    return "E";
+
+  if (log_level & G_LOG_LEVEL_WARNING)
+    return "W";
+
+  if (log_level & G_LOG_LEVEL_MESSAGE)
+    return "N";   /* consistent with apt, which calls this a "notice" */
+
+  if (log_level & G_LOG_LEVEL_INFO)
+    return "I";
+
+  if (log_level & G_LOG_LEVEL_DEBUG)
+    return "D";
+
+  return "?!";
+}
+
 /**
  * log_handler_with_timestamp:
  * @log_domain: the log domain of the message
@@ -946,9 +973,14 @@ pv_log_to_stderr_with_timestamp (const gchar *log_domain,
    * was introduced in GLib 2.66 and we are targeting an older version */
   g_autofree gchar *timestamp = g_date_time_format (date_time, "%T");
 
-  g_printerr ("%s.%06i: %s[%d]: %s\n", timestamp,
+  g_printerr ("%s.%06i: %s[%d]: %s: %s\n", timestamp,
               g_date_time_get_microsecond (date_time),
-              my_prgname, my_pid, message);
+              my_prgname, my_pid, get_level_prefix (log_level), message);
+
+  if (log_level & (G_LOG_FLAG_RECURSION
+                   | G_LOG_FLAG_FATAL
+                   | G_LOG_LEVEL_ERROR))
+    G_BREAKPOINT ();
 }
 
 /**
@@ -964,7 +996,13 @@ pv_log_to_stderr (const gchar *log_domain,
                   const gchar *message,
                   gpointer user_data)
 {
-  g_printerr ("%s[%d]: %s\n", my_prgname, my_pid, message);
+  g_printerr ("%s[%d]: %s: %s\n",
+              my_prgname, my_pid, get_level_prefix (log_level), message);
+
+  if (log_level & (G_LOG_FLAG_RECURSION
+                   | G_LOG_FLAG_FATAL
+                   | G_LOG_LEVEL_ERROR))
+    G_BREAKPOINT ();
 }
 
 /**
@@ -974,7 +1012,11 @@ pv_log_to_stderr (const gchar *log_domain,
 void
 pv_set_up_logging (gboolean opt_verbose)
 {
-  GLogLevelFlags log_levels = G_LOG_LEVEL_WARNING | G_LOG_LEVEL_MESSAGE;
+  GLogLevelFlags log_levels = (G_LOG_LEVEL_ERROR
+                               | G_LOG_LEVEL_CRITICAL
+                               | PV_LOG_LEVEL_FAILURE
+                               | G_LOG_LEVEL_WARNING
+                               | G_LOG_LEVEL_MESSAGE);
   gboolean opt_timestamp = pv_boolean_environment ("PRESSURE_VESSEL_LOG_WITH_TIMESTAMP",
                                                    FALSE);
   gboolean opt_info = pv_boolean_environment ("PRESSURE_VESSEL_LOG_INFO", FALSE);
diff --git a/pressure-vessel/utils.h b/pressure-vessel/utils.h
index cf08ccf76..63cbf2093 100644
--- a/pressure-vessel/utils.h
+++ b/pressure-vessel/utils.h
@@ -39,6 +39,11 @@
 #define PR_SET_CHILD_SUBREAPER 36
 #endif
 
+#define PV_LOG_LEVEL_FAILURE (1 << G_LOG_LEVEL_USER_SHIFT)
+
+#define pv_log_failure(...) \
+  g_log (G_LOG_DOMAIN, PV_LOG_LEVEL_FAILURE, __VA_ARGS__)
+
 int pv_envp_cmp (const void *p1,
                  const void *p2);
 
diff --git a/pressure-vessel/wrap.c b/pressure-vessel/wrap.c
index 0f5bd8091..f59b495f2 100644
--- a/pressure-vessel/wrap.c
+++ b/pressure-vessel/wrap.c
@@ -156,7 +156,7 @@ check_bwrap (const char *tools_dir,
 
   if (bwrap_executable == NULL)
     {
-      g_warning ("Cannot find bwrap");
+      pv_log_failure ("Cannot find bwrap");
     }
   else if (only_prepare)
     {
@@ -186,18 +186,18 @@ check_bwrap (const char *tools_dir,
                          &wait_status,
                          error))
         {
-          g_warning ("Cannot run bwrap: %s", local_error->message);
+          pv_log_failure ("Cannot run bwrap: %s", local_error->message);
           g_clear_error (&local_error);
         }
       else if (wait_status != 0)
         {
-          g_warning ("Cannot run bwrap: wait status %d", wait_status);
+          pv_log_failure ("Cannot run bwrap: wait status %d", wait_status);
 
           if (child_stdout != NULL && child_stdout[0] != '\0')
-            g_warning ("Output:\n%s", child_stdout);
+            pv_log_failure ("Output:\n%s", child_stdout);
 
           if (child_stderr != NULL && child_stderr[0] != '\0')
-            g_warning ("Diagnostic output:\n%s", child_stderr);
+            pv_log_failure ("Diagnostic output:\n%s", child_stderr);
         }
       else
         {
@@ -241,14 +241,14 @@ check_launch_on_host (const char *launch_executable,
 
   if (wait_status != 0)
     {
-      g_warning ("Cannot run commands on host system: wait status %d",
+      pv_log_failure ("Cannot run commands on host system: wait status %d",
                  wait_status);
 
       if (child_stdout != NULL && child_stdout[0] != '\0')
-        g_warning ("Output:\n%s", child_stdout);
+        pv_log_failure ("Output:\n%s", child_stdout);
 
       if (child_stderr != NULL && child_stderr[0] != '\0')
-        g_warning ("Diagnostic output:\n%s", child_stderr);
+        pv_log_failure ("Diagnostic output:\n%s", child_stderr);
 
       return glnx_throw (error, "Unable to run a command on the host system");
     }
@@ -1248,6 +1248,8 @@ tristate_environment (const gchar *name)
   return TRISTATE_MAYBE;
 }
 
+#define usage_error(...) pv_log_failure (__VA_ARGS__)
+
 int
 main (int argc,
       char *argv[])
@@ -1296,8 +1298,8 @@ main (int argc,
 
   if (g_getenv ("STEAM_RUNTIME") != NULL)
     {
-      g_warning ("This program should not be run in the Steam Runtime. "
-                 "Use pressure-vessel-unruntime instead.");
+      usage_error ("This program should not be run in the Steam Runtime. "
+                   "Use pressure-vessel-unruntime instead.");
       ret = 2;
       goto out;
     }
@@ -1393,7 +1395,7 @@ main (int argc,
 
       if (opt_runtime_id[0] == '-' || opt_runtime_id[0] == '.')
         {
-          g_warning ("--runtime-id must not start with dash or dot");
+          usage_error ("--runtime-id must not start with dash or dot");
           goto out;
         }
 
@@ -1401,8 +1403,8 @@ main (int argc,
         {
           if (!g_ascii_isalnum (*p) && *p != '_' && *p != '-' && *p != '.')
             {
-              g_warning ("--runtime-id may only contain "
-                         "alphanumerics, underscore, dash or dot");
+              usage_error ("--runtime-id may only contain "
+                           "alphanumerics, underscore, dash or dot");
               goto out;
             }
         }
@@ -1413,7 +1415,7 @@ main (int argc,
 
   if (opt_runtime != NULL && opt_runtime_archive != NULL)
     {
-      g_warning ("--runtime and --runtime-archive cannot both be used");
+      usage_error ("--runtime and --runtime-archive cannot both be used");
       goto out;
     }
 
@@ -1447,8 +1449,8 @@ main (int argc,
   g_assert (opt_graphics_provider != NULL);
   if (opt_graphics_provider[0] != '\0' && opt_graphics_provider[0] != '/')
     {
-      g_warning ("--graphics-provider path must be absolute, not \"%s\"",
-                 opt_graphics_provider);
+      usage_error ("--graphics-provider path must be absolute, not \"%s\"",
+                   opt_graphics_provider);
       goto out;
     }
 
@@ -1486,7 +1488,7 @@ main (int argc,
 
   if (argc < 2 && !opt_test && !opt_only_prepare)
     {
-      g_warning ("An executable to run is required");
+      usage_error ("An executable to run is required");
       goto out;
     }
 
@@ -1500,7 +1502,7 @@ main (int argc,
 
   if (opt_terminal == PV_TERMINAL_NONE && opt_shell != PV_SHELL_NONE)
     {
-      g_warning ("--terminal=none is incompatible with --shell");
+      usage_error ("--terminal=none is incompatible with --shell");
       goto out;
     }
 
@@ -1563,8 +1565,8 @@ main (int argc,
     }
   else
     {
-      g_warning ("Either --home, --freedesktop-app-id, --steam-app-id "
-                 "or $SteamAppId is required");
+      usage_error ("Either --home, --freedesktop-app-id, --steam-app-id "
+                   "or $SteamAppId is required");
       goto out;
     }
 
@@ -1576,8 +1578,8 @@ main (int argc,
 
           if (equals == NULL)
             {
-              g_warning ("--env-if-host argument must be of the form "
-                         "NAME=VALUE, not \"%s\"", opt_env_if_host[i]);
+              usage_error ("--env-if-host argument must be of the form "
+                           "NAME=VALUE, not \"%s\"", opt_env_if_host[i]);
               goto out;
             }
         }
@@ -1585,7 +1587,7 @@ main (int argc,
 
   if (opt_only_prepare && opt_test)
     {
-      g_warning ("--only-prepare and --test are mutually exclusive");
+      usage_error ("--only-prepare and --test are mutually exclusive");
       goto out;
     }
 
@@ -1596,14 +1598,14 @@ main (int argc,
           if (strchr (opt_filesystems[i], ':') != NULL ||
               strchr (opt_filesystems[i], '\\') != NULL)
             {
-              g_warning ("':' and '\\' in --filesystem argument "
-                         "not handled yet");
+              usage_error ("':' and '\\' in --filesystem argument "
+                           "not handled yet");
               goto out;
             }
           else if (!g_path_is_absolute (opt_filesystems[i]))
             {
-              g_warning ("--filesystem argument must be an absolute "
-                         "path, not \"%s\"", opt_filesystems[i]);
+              usage_error ("--filesystem argument must be an absolute "
+                           "path, not \"%s\"", opt_filesystems[i]);
               goto out;
             }
         }
@@ -1611,7 +1613,7 @@ main (int argc,
 
   if (opt_copy_runtime && opt_variable_dir == NULL)
     {
-      g_warning ("--copy-runtime requires --variable-dir");
+      usage_error ("--copy-runtime requires --variable-dir");
       goto out;
     }
 
@@ -2592,7 +2594,7 @@ main (int argc,
 
 out:
   if (local_error != NULL)
-    g_warning ("%s", local_error->message);
+    pv_log_failure ("%s", local_error->message);
 
   for (i = 0; i < G_N_ELEMENTS (opt_preload_modules); i++)
     g_clear_pointer (&opt_preload_modules[i].values, g_ptr_array_unref);
-- 
GitLab