Commit 877d54e9 authored by Lennart Poettering's avatar Lennart Poettering
Browse files

journal: generate structured journal messages for a number of events

parent 88fae6e0
/test-log
/test-journal-verify
/test-journal-match
/test-journal-stream
......
......@@ -1117,7 +1117,8 @@ noinst_PROGRAMS += \
test-strv \
test-install \
test-watchdog \
test-unit-name
test-unit-name \
test-log
TESTS += \
test-job-type \
......@@ -1173,6 +1174,12 @@ test_unit_name_SOURCES = \
test_unit_name_LDADD = \
libsystemd-core.la
test_log_SOURCES = \
src/test/test-log.c
test_log_LDADD = \
libsystemd-core.la
test_daemon_SOURCES = \
src/test/test-daemon.c
......
......@@ -49,6 +49,10 @@ Bugfixes:
Features:
* wall messages for shutdown should move to logind
* remove wants from journald.service
* allow writing multiple conditions in unit files on one line
* journal: json output needs to be able to deal with multiple assignments of the same field
......
......@@ -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);
......
......@@ -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);
......
......@@ -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);
}
......
......@@ -31,6 +31,8 @@
#include "path-util.h"
#include "polkit.h"
#include "special.h"
#include "systemd/sd-id128.h"
#include "systemd/sd-messages.h"
#define BUS_MANAGER_INTERFACE \
" <interface name=\"org.freedesktop.login1.Manager\">\n" \
......@@ -1138,6 +1140,42 @@ finish:
return 0;
}
static int bus_manager_log_shutdown(
Manager *m,
InhibitWhat w,
const char *unit_name) {
const char *p, *q;
assert(m);
assert(unit_name);
if (w != INHIBIT_SHUTDOWN)
return 0;
if (streq(unit_name, SPECIAL_POWEROFF_TARGET)) {
p = "MESSAGE=System is powering down.";
q = "SHUTDOWN=power-off";
} else if (streq(unit_name, SPECIAL_HALT_TARGET)) {
p = "MESSAGE=System is halting.";
q = "SHUTDOWN=halt";
} else if (streq(unit_name, SPECIAL_REBOOT_TARGET)) {
p = "MESSAGE=System is rebooting.";
q = "SHUTDOWN=reboot";
} else if (streq(unit_name, SPECIAL_KEXEC_TARGET)) {
p = "MESSAGE=System is rebooting with kexec.";
q = "SHUTDOWN=kexec";
} else {
p = "MESSAGE=System is shutting down.";
q = NULL;
}
return log_struct(LOG_NOTICE,
"MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SHUTDOWN),
p,
q, NULL);
}
int bus_manager_shutdown_or_sleep_now_or_later(
Manager *m,
const char *unit_name,
......@@ -1160,10 +1198,13 @@ int bus_manager_shutdown_or_sleep_now_or_later(
/* Shutdown is delayed, keep in mind what we
* want to do, and start a timeout */
r = delay_shutdown_or_sleep(m, w, unit_name);
else
else {
bus_manager_log_shutdown(m, w, unit_name);
/* Shutdown is not delayed, execute it
* immediately */
r = send_start_unit(m->bus, unit_name, error);
}
return r;
}
......@@ -2256,6 +2297,8 @@ int manager_dispatch_delayed(Manager *manager) {
if (delayed)
return 0;
bus_manager_log_shutdown(manager, manager->delayed_what, manager->delayed_unit);
/* Reset delay data */
unit_name = manager->delayed_unit;
manager->delayed_unit = NULL;
......
......@@ -27,6 +27,8 @@
#include <linux/vt.h>
#include <string.h>
#include "systemd/sd-id128.h"
#include "systemd/sd-messages.h"
#include "logind-seat.h"
#include "logind-acl.h"
#include "util.h"
......@@ -337,7 +339,11 @@ int seat_start(Seat *s) {
if (s->started)
return 0;
log_info("New seat %s.", s->id);
log_struct(LOG_INFO,
"MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SEAT_START),
"SEAT_ID=%s", s->id,
"MESSAGE=New seat %s.", s->id,
NULL);
/* Initialize VT magic stuff */
seat_preallocate_vts(s);
......@@ -361,7 +367,11 @@ int seat_stop(Seat *s) {
assert(s);
if (s->started)
log_info("Removed seat %s.", s->id);
log_struct(LOG_INFO,
"MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SEAT_STOP),
"SEAT_ID=%s", s->id,
"MESSAGE=Removed seat %s.", s->id,
NULL);
seat_stop_sessions(s);
......
......@@ -25,6 +25,8 @@
#include <sys/epoll.h>
#include <fcntl.h>
#include "systemd/sd-id128.h"
#include "systemd/sd-messages.h"
#include "strv.h"
#include "util.h"
#include "mkdir.h"
......@@ -542,8 +544,13 @@ int session_start(Session *s) {
if (r < 0)
return r;
log_full(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG,
"New session %s of user %s.", s->id, s->user->name);
log_struct(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG,
"MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_START),
"SESSION_ID=%s", s->id,
"USER_ID=%s", s->user->name,
"LEADER=%lu", (unsigned long) s->leader,
"MESSAGE=New session %s of user %s.", s->id, s->user->name,
NULL);
/* Create cgroup */
r = session_create_cgroup(s);
......@@ -679,8 +686,13 @@ int session_stop(Session *s) {
assert(s);
if (s->started)
log_full(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG,
"Removed session %s.", s->id);
log_struct(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG,
"MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_STOP),
"SESSION_ID=%s", s->id,
"USER_ID=%s", s->user->name,
"LEADER=%lu", (unsigned long) s->leader,
"MESSAGE=Removed session %s.", s->id,
NULL);
/* Kill cgroup */
k = session_terminate_cgroup(s);
......
......@@ -658,11 +658,127 @@ _noreturn_ void log_assert_failed_unreachable(const char *text, const char *file
log_assert(text, file, line, func, "Code should not be reached '%s' at %s:%u, function %s(). Aborting.");
}
int __log_oom(const char *file, int line, const char *func) {
int log_oom_internal(const char *file, int line, const char *func) {
log_meta(LOG_ERR, file, line, func, "Out of memory.");
return -ENOMEM;
}
int log_struct_internal(
int level,
const char *file,
int line,
const char *func,
const char *format, ...) {
int saved_errno;
va_list ap;
int r;
if (_likely_(LOG_PRI(level) > log_max_level))
return 0;
if (log_target == LOG_TARGET_NULL)
return 0;
if ((level & LOG_FACMASK) == 0)
level = log_facility | LOG_PRI(level);
saved_errno = errno;
if ((log_target == LOG_TARGET_AUTO ||
log_target == LOG_TARGET_JOURNAL_OR_KMSG ||
log_target == LOG_TARGET_JOURNAL) &&
journal_fd >= 0) {
char header[LINE_MAX];
struct iovec iovec[17];
unsigned n = 0, i;
struct msghdr mh;
const char nl = '\n';
/* If the journal is available do structured logging */
snprintf(header, sizeof(header),
"PRIORITY=%i\n"
"SYSLOG_FACILITY=%i\n"
"CODE_FILE=%s\n"
"CODE_LINE=%i\n"
"CODE_FUNCTION=%s\n"
"SYSLOG_IDENTIFIER=%s\n",
LOG_PRI(level),
LOG_FAC(level),
file,
line,
func,
program_invocation_short_name);
char_array_0(header);
zero(iovec);
IOVEC_SET_STRING(iovec[n++], header);
va_start(ap, format);
while (format && n + 1 < ELEMENTSOF(iovec)) {
char *buf;