systemd: use structured logging for unit changes

Information which unit a log entry pertains to enables systemctl
status to display more log messages.

5 files changed, 48 insertions, 12 deletions

diff --git a/src/core/execute.c b/src/core/execute.c
index 5faeee8691..e502c2490f 100644
--- a/src/core/execute.c
+++ b/src/core/execute.c
@@ -62,6 +62,8 @@
 #include "loopback-setup.h"
 #include "path-util.h"
 #include "syscall-list.h"
+#include "sd-id128.h"
+#include "sd-messages.h"
 
 #define IDLE_TIMEOUT_USEC (5*USEC_PER_SEC)
 
@@ -1022,7 +1024,11 @@ int exec_spawn(ExecCommand *command,
 
         r = exec_context_load_environment(context, &files_env);
         if (r < 0) {
-                log_error("Failed to load environment files: %s", strerror(-r));
+                log_struct(LOG_ERR,
+                           "UNIT=%s", unit_id,
+                           "MESSAGE=Failed to load environment files: %s", strerror(-r),
+                           "ERRNO=%d", -r,
+                           NULL);
                 return r;
         }
 
@@ -1033,7 +1039,10 @@ int exec_spawn(ExecCommand *command,
         if (!line)
                 return log_oom();
 
-        log_debug("About to execute: %s", line);
+        log_struct(LOG_DEBUG,
+                   "UNIT=%s", unit_id,
+                   "MESSAGE=About to execute %s", line,
+                   NULL);
         free(line);
 
         r = cgroup_bonding_realize_list(cgroup_bondings);
@@ -1490,14 +1499,25 @@ int exec_spawn(ExecCommand *command,
         fail_child:
                 if (r != 0) {
                         log_open();
-                        log_warning("Failed at step %s spawning %s: %s",
-                                    exit_status_to_string(r, EXIT_STATUS_SYSTEMD),
-                                    command->path, strerror(-err));
+                        log_struct(LOG_ERR, MESSAGE_ID(SD_MESSAGE_SPAWN_FAILED),
+                                   "EXECUTABLE=%s", command->path,
+                                   "MESSAGE=Failed at step %s spawning %s: %s",
+                                          exit_status_to_string(r, EXIT_STATUS_SYSTEMD),
+                                          command->path, strerror(-err),
+                                   "ERRNO=%d", -err,
+                                   NULL);
+                        log_close();
                 }
 
                 _exit(r);
         }
 
+        log_struct(LOG_DEBUG,
+                   "UNIT=%s", unit_id,
+                   "MESSAGE=Forked %s as %lu",
+                          command->path, (unsigned long) pid,
+                   NULL);
+
         /* We add the new process to the cgroup both in the child (so
          * that we can be sure that no user code is ever executed
          * outside of the cgroup) and in the parent (so that we can be
@@ -1506,8 +1526,6 @@ int exec_spawn(ExecCommand *command,
         if (cgroup_bondings)
                 cgroup_bonding_install_list(cgroup_bondings, pid, cgroup_suffix);
 
-        log_debug("Forked %s as %lu", command->path, (unsigned long) pid);
-
         exec_status_start(&command->exec_status, pid);
 
         *ret = pid;
diff --git a/src/core/selinux-access.c b/src/core/selinux-access.c
index 852a328b7c..6dfe8b45f3 100644
--- a/src/core/selinux-access.c
+++ b/src/core/selinux-access.c
@@ -314,7 +314,7 @@ static int get_calling_context(
                 if (r >= 0)
                         return r;
 
-                log_error("bus_get_selinux_security_context failed %m");
+                log_error("bus_get_selinux_security_context failed: %m");
                 return r;
         }
 
diff --git a/src/core/service.c b/src/core/service.c
index 5742968d91..2febdb69d1 100644
--- a/src/core/service.c
+++ b/src/core/service.c
@@ -1614,7 +1614,12 @@ static void service_set_state(Service *s, ServiceState state) {
                 cgroup_bonding_trim_list(UNIT(s)->cgroup_bondings, true);
 
         if (old_state != state)
-                log_debug("%s changed %s -> %s", UNIT(s)->id, service_state_to_string(old_state), service_state_to_string(state));
+                log_struct(LOG_DEBUG,
+                           "UNIT=%s", UNIT(s)->id,
+                           "MESSAGE=%s changed %s -> %s", UNIT(s)->id,
+                                   service_state_to_string(old_state),
+                                   service_state_to_string(state),
+                           NULL);
 
         unit_notify(UNIT(s), table[old_state], table[state], s->reload_result == SERVICE_SUCCESS);
         s->reload_result = SERVICE_SUCCESS;
@@ -2948,8 +2953,16 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) {
                                 f = SERVICE_SUCCESS;
                 }
 
-                log_full(f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE,
-                         "%s: main process exited, code=%s, status=%i", u->id, sigchld_code_to_string(code), status);
+                log_struct(f == SERVICE_SUCCESS ? LOG_DEBUG : LOG_NOTICE,
+                           "MESSAGE=%s: main process exited, code=%s, status=%i/%s",
+                                  u->id, sigchld_code_to_string(code), status,
+                                  strna(code == CLD_EXITED
+                                        ? exit_status_to_string(status, EXIT_STATUS_FULL)
+                                        : signal_to_string(status)),
+                           "UNIT=%s", u->id,
+                           "EXIT_CODE=%s", sigchld_code_to_string(code),
+                           "EXIT_STATUS=%i", status,
+                           NULL);
 
                 if (f != SERVICE_SUCCESS)
                         s->result = f;
diff --git a/src/core/unit.c b/src/core/unit.c
index 6396bfc09f..99e1c27948 100644
--- a/src/core/unit.c
+++ b/src/core/unit.c
@@ -1438,7 +1438,10 @@ void unit_notify(Unit *u, UnitActiveState os, UnitActiveState ns, bool reload_su
                         check_unneeded_dependencies(u);
 
                 if (ns != os && ns == UNIT_FAILED) {
-                        log_notice("Unit %s entered failed state.", u->id);
+                        log_struct(LOG_NOTICE,
+                                   "MESSAGE=Unit %s entered failed state", u->id,
+                                   "UNIT=%s", u->id,
+                                   NULL);
                         unit_trigger_on_failure(u);
                 }
         }
diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h
index 698aa60eb7..5099a36e6a 100644
--- a/src/systemd/sd-messages.h
+++ b/src/systemd/sd-messages.h
@@ -58,6 +58,8 @@ extern "C" {
 #define SD_MESSAGE_UNIT_RELOADING   SD_ID128_MAKE(d3,4d,03,7f,ff,18,47,e6,ae,66,9a,37,0e,69,47,25)
 #define SD_MESSAGE_UNIT_RELOADED    SD_ID128_MAKE(7b,05,eb,c6,68,38,42,22,ba,a8,88,11,79,cf,da,54)
 
+#define SD_MESSAGE_SPAWN_FAILED     SD_ID128_MAKE(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7)
+
 #define SD_MESSAGE_FORWARD_SYSLOG_MISSED SD_ID128_MAKE(00,27,22,9c,a0,64,41,81,a7,6c,4e,92,45,8a,fa,2e)
 
 #ifdef __cplusplus