journal: generate structured journal messages for a number of events

3 files changed, 228 insertions, 27 deletions

diff --git a/src/core/job.c b/src/core/job.c
index 8d51aa3fdd..9614642f56 100644
--- a/src/core/job.c
+++ b/src/core/job.c
@@ -24,6 +24,8 @@
 #include <sys/timerfd.h>
 #include <sys/epoll.h>
 
+#include "systemd/sd-id128.h"
+#include "systemd/sd-messages.h"
 #include "set.h"
 #include "unit.h"
 #include "macro.h"
@@ -549,17 +551,74 @@ int job_run_and_invalidate(Job *j) {
         return r;
 }
 
-static void job_print_status_message(Unit *u, JobType t, JobResult result) {
+static const char *job_get_status_message_format(Unit *u, JobType t, JobResult result) {
         const UnitStatusMessageFormats *format_table;
-        const char *format;
+
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
 
         format_table = &UNIT_VTABLE(u)->status_message_formats;
         if (!format_table)
-                return;
+                return NULL;
+
+        if (t == JOB_START)
+                return format_table->finished_start_job[result];
+        else if (t == JOB_STOP || t == JOB_RESTART)
+                return format_table->finished_stop_job[result];
+
+        return NULL;
+}
 
+static const char *job_get_status_message_format_try_harder(Unit *u, JobType t, JobResult result) {
+        const char *format;
+
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
+
+        format = job_get_status_message_format(u, t, result);
+        if (format)
+                return format;
+
+        /* Return generic strings */
         if (t == JOB_START) {
+                if (result == JOB_DONE)
+                        return "Started %s.";
+                else if (result == JOB_FAILED)
+                        return "Failed to start %s.";
+                else if (result == JOB_DEPENDENCY)
+                        return "Dependency failed for %s.";
+                else if (result == JOB_TIMEOUT)
+                        return "Timed out starting %s.";
+        } else if (t == JOB_STOP || t == JOB_RESTART) {
+                if (result == JOB_DONE)
+                        return "Stopped %s.";
+                else if (result == JOB_FAILED)
+                        return "Stopped (with error) %s.";
+                else if (result == JOB_TIMEOUT)
+                        return "Timed out stoppping %s.";
+        } else if (t == JOB_RELOAD) {
+                if (result == JOB_DONE)
+                        return "Reloaded %s.";
+                else if (result == JOB_FAILED)
+                        return "Reload failed for %s.";
+                else if (result == JOB_TIMEOUT)
+                        return "Timed out reloading %s.";
+        }
+
+        return NULL;
+}
+
+static void job_print_status_message(Unit *u, JobType t, JobResult result) {
+        const char *format;
 
-                format = format_table->finished_start_job[result];
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
+
+        if (t == JOB_START) {
+                format = job_get_status_message_format(u, t, result);
                 if (!format)
                         return;
 
@@ -572,7 +631,7 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) {
 
                 case JOB_FAILED:
                         unit_status_printf(u, ANSI_HIGHLIGHT_RED_ON "FAILED" ANSI_HIGHLIGHT_OFF, format, unit_description(u));
-                        unit_status_printf(u, "", "See 'systemctl status %s' for details.", u->id);
+                        unit_status_printf(u, NULL, "See 'systemctl status %s' for details.", u->id);
                         break;
 
                 case JOB_DEPENDENCY:
@@ -589,7 +648,7 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) {
 
         } else if (t == JOB_STOP || t == JOB_RESTART) {
 
-                format = format_table->finished_stop_job[result];
+                format = job_get_status_message_format(u, t, result);
                 if (!format)
                         return;
 
@@ -618,6 +677,52 @@ static void job_print_status_message(Unit *u, JobType t, JobResult result) {
         }
 }
 
+#pragma GCC diagnostic push
+#pragma GCC diagnostic ignored "-Wformat-nonliteral"
+static void job_log_status_message(Unit *u, JobType t, JobResult result) {
+        const char *format;
+        char buf[LINE_MAX];
+
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
+
+        format = job_get_status_message_format_try_harder(u, t, result);
+        if (!format)
+                return;
+
+        snprintf(buf, sizeof(buf), format, unit_description(u));
+        char_array_0(buf);
+
+        if (t == JOB_START) {
+                sd_id128_t mid;
+
+                mid = result == JOB_DONE ? SD_MESSAGE_UNIT_STARTED : SD_MESSAGE_UNIT_FAILED;
+                log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR,
+                           "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid),
+                           "UNIT=%s", u->id,
+                           "RESULT=%s", job_result_to_string(result),
+                           "MESSAGE=%s", buf,
+                           NULL);
+
+        } else if (t == JOB_STOP)
+                log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR,
+                           "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_STOPPED),
+                           "UNIT=%s", u->id,
+                           "RESULT=%s", job_result_to_string(result),
+                           "MESSAGE=%s", buf,
+                           NULL);
+
+        else if (t == JOB_RELOAD)
+                log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR,
+                           "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_RELOADED),
+                           "UNIT=%s", u->id,
+                           "RESULT=%s", job_result_to_string(result),
+                           "MESSAGE=%s", buf,
+                           NULL);
+}
+#pragma GCC diagnostic pop
+
 int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) {
         Unit *u;
         Unit *other;
@@ -636,6 +741,7 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) {
         log_debug("Job %s/%s finished, result=%s", u->id, job_type_to_string(t), job_result_to_string(result));
 
         job_print_status_message(u, t, result);
+        job_log_status_message(u, t, result);
 
         job_add_to_dbus_queue(j);
 
diff --git a/src/core/manager.c b/src/core/manager.c
index bcaf913b5a..da766e6d58 100644
--- a/src/core/manager.c
+++ b/src/core/manager.c
@@ -41,7 +41,9 @@
 #include <libaudit.h>
 #endif
 
-#include <systemd/sd-daemon.h>
+#include "systemd/sd-daemon.h"
+#include "systemd/sd-id128.h"
+#include "systemd/sd-messages.h"
 
 #include "manager.h"
 #include "transaction.h"
@@ -2030,26 +2032,41 @@ void manager_check_finished(Manager *m) {
                         kernel_usec = m->initrd_timestamp.monotonic;
                         initrd_usec = m->startup_timestamp.monotonic - m->initrd_timestamp.monotonic;
 
-                        log_info("Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
-                                 format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                 format_timespan(initrd, sizeof(initrd), initrd_usec),
-                                 format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                 format_timespan(sum, sizeof(sum), total_usec));
+                        log_struct(LOG_INFO,
+                                   "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                                   "KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
+                                   "INITRD_USEC=%llu", (unsigned long long) initrd_usec,
+                                   "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                                   "MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
+                                   format_timespan(kernel, sizeof(kernel), kernel_usec),
+                                   format_timespan(initrd, sizeof(initrd), initrd_usec),
+                                   format_timespan(userspace, sizeof(userspace), userspace_usec),
+                                   format_timespan(sum, sizeof(sum), total_usec),
+                                   NULL);
                 } else {
                         kernel_usec = m->startup_timestamp.monotonic;
                         initrd_usec = 0;
 
-                        log_info("Startup finished in %s (kernel) + %s (userspace) = %s.",
-                                 format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                 format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                 format_timespan(sum, sizeof(sum), total_usec));
+                        log_struct(LOG_INFO,
+                                   "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                                   "KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
+                                   "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                                   "MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.",
+                                   format_timespan(kernel, sizeof(kernel), kernel_usec),
+                                   format_timespan(userspace, sizeof(userspace), userspace_usec),
+                                   format_timespan(sum, sizeof(sum), total_usec),
+                                   NULL);
                 }
         } else {
-                userspace_usec = initrd_usec = kernel_usec = 0;
-                total_usec = m->finish_timestamp.monotonic - m->startup_timestamp.monotonic;
-
-                log_debug("Startup finished in %s.",
-                          format_timespan(sum, sizeof(sum), total_usec));
+                initrd_usec = kernel_usec = 0;
+                total_usec = userspace_usec = m->finish_timestamp.monotonic - m->startup_timestamp.monotonic;
+
+                log_struct(LOG_INFO,
+                           "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                           "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                           "MESSAGE=Startup finished in %s.",
+                           format_timespan(sum, sizeof(sum), total_usec),
+                           NULL);
         }
 
         bus_broadcast_finished(m, kernel_usec, initrd_usec, userspace_usec, total_usec);
diff --git a/src/core/unit.c b/src/core/unit.c
index 0d5d15ef90..8246837658 100644
--- a/src/core/unit.c
+++ b/src/core/unit.c
@@ -29,6 +29,8 @@
 #include <unistd.h>
 #include <sys/stat.h>
 
+#include "systemd/sd-id128.h"
+#include "systemd/sd-messages.h"
 #include "set.h"
 #include "unit.h"
 #include "macro.h"
@@ -936,21 +938,93 @@ bool unit_condition_test(Unit *u) {
         return u->condition_result;
 }
 
-static void unit_status_print_starting_stopping(Unit *u, bool stopping) {
+static const char* unit_get_status_message_format(Unit *u, JobType t) {
         const UnitStatusMessageFormats *format_table;
-        const char *format;
+
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
+
+        if (t != JOB_START && t != JOB_STOP)
+                return NULL;
 
         format_table = &UNIT_VTABLE(u)->status_message_formats;
         if (!format_table)
-                return;
+                return NULL;
+
+        return format_table->starting_stopping[t == JOB_STOP];
+}
+
+static const char *unit_get_status_message_format_try_harder(Unit *u, JobType t) {
+        const char *format;
+
+        assert(u);
+        assert(t >= 0);
+        assert(t < _JOB_TYPE_MAX);
+
+        format = unit_get_status_message_format(u, t);
+        if (format)
+                return format;
+
+        /* Return generic strings */
+        if (t == JOB_START)
+                return "Starting %s.";
+        else if (t == JOB_STOP)
+                return "Stopping %s.";
+        else if (t == JOB_RELOAD)
+                return "Reloading %s.";
+
+        return NULL;
+}
+
+static void unit_status_print_starting_stopping(Unit *u, JobType t) {
+        const char *format;
+
+        assert(u);
 
-        format = format_table->starting_stopping[stopping];
+        /* We only print status messages for selected units on
+         * selected operations. */
+
+        format = unit_get_status_message_format(u, t);
         if (!format)
                 return;
 
         unit_status_printf(u, "", format, unit_description(u));
 }
 
+#pragma GCC diagnostic push
+#pragma GCC diagnostic ignored "-Wformat-nonliteral"
+static void unit_status_log_starting_stopping_reloading(Unit *u, JobType t) {
+        const char *format;
+        char buf[LINE_MAX];
+        sd_id128_t mid;
+
+        assert(u);
+
+        if (t != JOB_START && t != JOB_STOP && t != JOB_RELOAD)
+                return;
+
+        /* We log status messages for all units and all operations. */
+
+        format = unit_get_status_message_format_try_harder(u, t);
+        if (!format)
+                return;
+
+        snprintf(buf, sizeof(buf), format, unit_description(u));
+        char_array_0(buf);
+
+        mid = t == JOB_START ? SD_MESSAGE_UNIT_STARTING :
+              t == JOB_STOP  ? SD_MESSAGE_UNIT_STOPPING :
+                               SD_MESSAGE_UNIT_RELOADING;
+
+        log_struct(LOG_INFO,
+                   "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid),
+                   "UNIT=%s", u->id,
+                   "MESSAGE=%s", buf,
+                   NULL);
+}
+#pragma GCC diagnostic pop
+
 /* Errors:
  *         -EBADR:     This unit type does not support starting.
  *         -EALREADY:  Unit is already started.
@@ -990,7 +1064,8 @@ int unit_start(Unit *u) {
                 return unit_start(following);
         }
 
-        unit_status_print_starting_stopping(u, false);
+        unit_status_log_starting_stopping_reloading(u, JOB_START);
+        unit_status_print_starting_stopping(u, JOB_START);
 
         /* If it is stopped, but we cannot start it, then fail */
         if (!UNIT_VTABLE(u)->start)
@@ -1040,7 +1115,8 @@ int unit_stop(Unit *u) {
                 return unit_stop(following);
         }
 
-        unit_status_print_starting_stopping(u, true);
+        unit_status_log_starting_stopping_reloading(u, JOB_STOP);
+        unit_status_print_starting_stopping(u, JOB_STOP);
 
         if (!UNIT_VTABLE(u)->stop)
                 return -EBADR;
@@ -1079,6 +1155,8 @@ int unit_reload(Unit *u) {
                 return unit_reload(following);
         }
 
+        unit_status_log_starting_stopping_reloading(u, JOB_RELOAD);
+
         unit_add_to_dbus_queue(u);
         return UNIT_VTABLE(u)->reload(u);
 }