sysupdated: Improve logging about jobs

If someone runs `updatectl update`, sysupdate will be running multiple
update jobs at the same time, which can make reasoning about the output
in the journal quite difficult. Especially if things go wrong: the error
messages didn't mention which job failed. Nor was there any link between
job ID and the PID of the worker process logging to the journal. This
is all fixed here!

diff --git a/src/sysupdate/sysupdated.c b/src/sysupdate/sysupdated.c
index e8f4ffd1d5ebb660558aeaa836a74ddce3a4dbe5..6f15177c94eb10e20871b426bfc28acb58e9e2b2 100644 (file)
--- a/src/sysupdate/sysupdated.c
+++ b/src/sysupdate/sysupdated.c
@@ -210,7 +210,7 @@ static int job_parse_child_output(int _fd, sd_json_variant **ret) {
         assert(ret);
 
         if (fstat(fd, &st) < 0)
-                return log_error_errno(errno, "Failed to stat stdout fd: %m");
+                return log_debug_errno(errno, "Failed to stat stdout fd: %m");
 
         assert(S_ISREG(st.st_mode));
 
@@ -220,15 +220,15 @@ static int job_parse_child_output(int _fd, sd_json_variant **ret) {
         }
 
         if (lseek(fd, SEEK_SET, 0) == (off_t) -1)
-                return log_error_errno(errno, "Failed to seek to beginning of memfd: %m");
+                return log_debug_errno(errno, "Failed to seek to beginning of memfd: %m");
 
         f = take_fdopen(&fd, "r");
         if (!f)
-                return log_error_errno(errno, "Failed to reopen memfd: %m");
+                return log_debug_errno(errno, "Failed to reopen memfd: %m");
 
         r = sd_json_parse_file(f, "stdout", 0, &v, NULL, NULL);
         if (r < 0)
-                return log_error_errno(r, "Failed to parse JSON: %m");
+                return log_debug_errno(r, "Failed to parse JSON: %m");
 
         *ret = TAKE_PTR(v);
         return 0;
@@ -248,6 +248,8 @@ static void job_on_ready(Job *j) {
         if (!j->detach_cb)
                 return;
 
+        log_debug("Got READY=1 from job %" PRIu64", detaching.", j->id);
+
         assert(j->dbus_msg);
         msg = TAKE_PTR(j->dbus_msg);
 
@@ -255,7 +257,7 @@ static void job_on_ready(Job *j) {
 
         r = j->detach_cb(msg, j);
         if (r < 0)
-                log_warning_errno(r, "Failed to run callback on job ready event, ignoring: %m");
+                log_warning_errno(r, "Failed to detach job %" PRIu64 ", ignoring: %m", j->id);
 }
 
 static void job_on_errno(Job *j, const char *buf) {
@@ -266,7 +268,7 @@ static void job_on_errno(Job *j, const char *buf) {
 
         r = parse_errno(buf);
         if (r < 0) {
-                log_warning_errno(r, "Got invalid errno value, ignoring: %m");
+                log_warning_errno(r, "Got invalid errno value from job %" PRIu64 ", ignoring: %m", j->id);
                 return;
         }
 
@@ -336,7 +338,7 @@ static int job_on_exit(sd_event_source *s, const siginfo_t *si, void *userdata)
         else {
                 r = job_parse_child_output(TAKE_FD(j->stdout_fd), &json);
                 if (r < 0)
-                        sd_bus_error_set_errnof(&error, r, "Failed to parse JSON: %m");
+                        sd_bus_error_set_errnof(&error, r, "Failed to parse job worker output: %m");
         }
 
         /* Only send notification of exit if the job was actually detached */
@@ -351,17 +353,23 @@ static int job_on_exit(sd_event_source *s, const siginfo_t *si, void *userdata)
                                 j->object_path,
                                 j->status_errno != 0 ? -j->status_errno : si->si_status);
                 if (r < 0)
-                        log_warning_errno(r, "Cannot emit JobRemoved message, ignoring: %m");
+                        log_warning_errno(r,
+                                          "Cannot emit JobRemoved message for job %" PRIu64 ", ignoring: %m",
+                                          j->id);
         }
 
         if (j->dbus_msg && j->complete_cb) {
                 if (sd_bus_error_is_set(&error)) {
-                        log_warning("Bus error occurred, ignoring callback for job: %s", error.message);
+                        log_warning("Job %" PRIu64 " failed with bus error, ignoring callback: %s",
+                                    j->id, error.message);
                         sd_bus_reply_method_error(j->dbus_msg, &error);
                 } else {
                         r = j->complete_cb(j->dbus_msg, j, json, &error);
                         if (r < 0) {
-                                log_warning_errno(r, "Error during execution of job callback: %s", bus_error_message(&error, r));
+                                log_warning_errno(r,
+                                                  "Error during execution of job callback for job %" PRIu64 ": %s",
+                                                  j->id,
+                                                  bus_error_message(&error, r));
                                 sd_bus_reply_method_errno(j->dbus_msg, r, &error);
                         }
                 }
@@ -506,6 +514,9 @@ static int job_start(Job *j) {
                 _exit(EXIT_FAILURE);
         }
 
+        log_info("Started job %" PRIu64 " with worker PID " PID_FMT,
+                 j->id, pid.pid);
+
         r = event_add_child_pidref(j->manager->event, &j->child, &pid, WEXITED, job_on_exit, j);
         if (r < 0)
                 return log_error_errno(r, "Failed to add child process to event loop: %m");