libpriv/scripts: redirect scriptlet output to journal

Rather than just letting the scriptlets inherit the daemon's
stdout/stderr, redirect their outputs so that we can set a customized
identifier to make it easier to distinguish from the daemon output.

Also print out the `journalctl` command needed so that users can
investigate the output themselves.

Closes: coreos#998
Approved by: cgwalters

src/libpriv/rpmostree-bwrap.c

@@ -300,7 +300,7 @@ rpmostree_bwrap_set_child_setup (RpmOstreeBwrap *bwrap,
 
 gboolean
 rpmostree_bwrap_run (RpmOstreeBwrap *bwrap,
-                     GError **error)
+                     GError        **error)
 {
   int estatus;
   const char *current_lang = getenv ("LANG");
@@ -328,10 +328,11 @@ rpmostree_bwrap_run (RpmOstreeBwrap *bwrap,
     const char *errmsg = glnx_strjoina ("Executing bwrap(", bwrap->child_argv0, ")");
     GLNX_AUTO_PREFIX_ERROR (errmsg, error);
 
-    if (!g_spawn_sync (NULL, (char**)bwrap->argv->pdata, (char**) bwrap_env, G_SPAWN_SEARCH_PATH,
-                       bwrap_child_setup, bwrap,
-                       NULL, NULL, &estatus, error))
+    if (!g_spawn_sync (NULL, (char**)bwrap->argv->pdata, (char**) bwrap_env,
+                       G_SPAWN_SEARCH_PATH, bwrap_child_setup, bwrap, NULL, NULL,
+                       &estatus, error))
       return FALSE;
+
     if (!g_spawn_check_exit_status (estatus, error))
       return FALSE;
   }

src/libpriv/rpmostree-bwrap.h

@@ -50,6 +50,7 @@ void rpmostree_bwrap_set_child_setup (RpmOstreeBwrap *bwrap,
                                       GSpawnChildSetupFunc func,
                                       gpointer             data);
 
-gboolean rpmostree_bwrap_run (RpmOstreeBwrap *bwrap, GError **error);
+gboolean rpmostree_bwrap_run (RpmOstreeBwrap *bwrap,
+                              GError        **error);
 
 gboolean rpmostree_bwrap_selftest (GError **error);

src/libpriv/rpmostree-scripts.c

@@ -179,13 +179,29 @@ rpmostree_script_txn_validate (DnfPackage    *package,
   return TRUE;
 }
 
+struct ChildSetupData {
+  /* note fds are *not* owned */
+  gboolean all_fds_initialized;
+  int stdin_fd;
+  int stdout_fd;
+  int stderr_fd;
+};
+
 static void
-script_child_setup_stdin (gpointer data)
+script_child_setup (gpointer opaque)
 {
-  int fd = GPOINTER_TO_INT (data);
-
-  if (dup2 (fd, 0) < 0)
-    err (1, "dup2");
+  struct ChildSetupData *data = opaque;
+
+  /* make it really obvious for new users that we expect all fds to be initialized or -1 */
+  if (!data || !data->all_fds_initialized)
+    return;
+
+  if (data->stdin_fd >= 0 && dup2 (data->stdin_fd, STDIN_FILENO) < 0)
+    err (1, "dup2(stdin)");
+  if (data->stdout_fd >= 0 && dup2 (data->stdout_fd, STDOUT_FILENO) < 0)
+    err (1, "dup2(stdout)");
+  if (data->stderr_fd >= 0 && dup2 (data->stderr_fd, STDERR_FILENO) < 0)
+    err (1, "dup2(stderr)");
 }
 
 /* Lowest level script handler in this file; create a bwrap instance and run it
@@ -209,6 +225,8 @@ run_script_in_bwrap_container (int rootfs_fd,
   const char *postscript_path_host = postscript_path_container + 1;
   g_autoptr(RpmOstreeBwrap) bwrap = NULL;
   gboolean created_var_tmp = FALSE;
+  glnx_fd_close int stdout_fd = -1;
+  glnx_fd_close int stderr_fd = -1;
 
   /* TODO - Create a pipe and send this to bwrap so it's inside the
    * tmpfs.  Note the +1 on the path to skip the leading /.
@@ -259,8 +277,26 @@ run_script_in_bwrap_container (int rootfs_fd,
   if (!bwrap)
     goto out;
 
-  if (stdin_fd >= 0)
-    rpmostree_bwrap_set_child_setup (bwrap, script_child_setup_stdin, GINT_TO_POINTER (stdin_fd));
+
+  struct ChildSetupData data = { .stdin_fd = stdin_fd };
+
+  const char *id = glnx_strjoina ("rpm-ostree(", pkg_script, ")");
+  data.stdout_fd = stdout_fd = sd_journal_stream_fd (id, LOG_INFO, 0);
+  if (stdout_fd < 0)
+    {
+      glnx_throw_errno_prefix (error, "While creating stdout stream fd");
+      goto out;
+    }
+
+  data.stderr_fd = stderr_fd = sd_journal_stream_fd (id, LOG_ERR, 0);
+  if (stderr_fd < 0)
+    {
+      glnx_throw_errno_prefix (error, "While creating stderr stream fd");
+      goto out;
+    }
+
+  data.all_fds_initialized = TRUE;
+  rpmostree_bwrap_set_child_setup (bwrap, script_child_setup, &data);
 
   rpmostree_bwrap_append_child_argv (bwrap,
                                      interp,
@@ -269,7 +305,16 @@ run_script_in_bwrap_container (int rootfs_fd,
                                      NULL);
 
   if (!rpmostree_bwrap_run (bwrap, error))
-    goto out;
+    {
+      if (error)
+        {
+          g_assert (*error);
+          g_autofree char *errmsg = (*error)->message;
+          (*error)->message =
+            g_strdup_printf ("%s; run `journalctl -t '%s'` for more information", errmsg, id);
+        }
+      goto out;
+    }
 
   ret = TRUE;
  out:

tests/common/libvm.sh

@@ -339,3 +339,15 @@ vm_build_rpm() {
     build_rpm "$@"
     vm_send_test_repo 0 # XXX use rsync
 }
+
+vm_get_journal_cursor() {
+  vm_cmd journalctl -o json -n 1 | jq -r '.["__CURSOR"]'
+}
+
+vm_assert_journal_has_content() {
+  from_cursor=$1; shift
+  # add an extra helping of quotes for hungry ssh
+  vm_cmd journalctl --after-cursor "'$from_cursor'" > tmp-journal.txt
+  assert_file_has_content tmp-journal.txt "$@"
+  rm -f tmp-journal.txt
+}

tests/vmcheck/test-basic.sh

@@ -144,3 +144,12 @@ fi
 assert_file_has_content out.txt 'No change.'
 vm_assert_status_jq '.deployments[0]["pending-base-checksum"]|not'
 echo "ok changes to deployment variant don't affect deploy"
+
+vm_build_rpm bad-post post "echo a bad post >&2 && false"
+cursor=$(vm_get_journal_cursor)
+if vm_rpmostree install bad-post &> err.txt; then
+  assert_not_reached "installing pkg with failing post unexpectedly succeeded"
+fi
+assert_file_has_content err.txt "run.*journalctl.*for more information"
+vm_assert_journal_has_content $cursor 'rpm-ostree(bad-post.post).*a bad post'
+echo "ok script output prefixed in journal"