From 877d54e9b09e093c2102f519a84e2a52637ae035 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Fri, 24 Aug 2012 22:21:20 +0200 Subject: [PATCH] journal: generate structured journal messages for a number of events --- .gitignore | 1 + Makefile.am | 9 ++- TODO | 4 ++ src/core/job.c | 118 +++++++++++++++++++++++++++++++++++-- src/core/manager.c | 47 ++++++++++----- src/core/unit.c | 90 ++++++++++++++++++++++++++-- src/login/logind-dbus.c | 45 +++++++++++++- src/login/logind-seat.c | 14 ++++- src/login/logind-session.c | 20 +++++-- src/shared/log.c | 118 ++++++++++++++++++++++++++++++++++++- src/shared/log.h | 64 +++++++++++++------- src/sleep/sleep.c | 26 ++++++-- src/systemd/sd-id128.h | 1 + src/systemd/sd-messages.h | 33 +++++++++-- src/test/test-log.c | 46 +++++++++++++++ src/timedate/timedated.c | 14 ++++- 16 files changed, 582 insertions(+), 68 deletions(-) create mode 100644 src/test/test-log.c diff --git a/.gitignore b/.gitignore index 4c8bba887..ca95d7afb 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ +/test-log /test-journal-verify /test-journal-match /test-journal-stream diff --git a/Makefile.am b/Makefile.am index e5ace9b97..927d25f08 100644 --- a/Makefile.am +++ b/Makefile.am @@ -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 diff --git a/TODO b/TODO index a4643d7b8..b1d92dafa 100644 --- a/TODO +++ b/TODO @@ -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 diff --git a/src/core/job.c b/src/core/job.c index 8d51aa3fd..9614642f5 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -24,6 +24,8 @@ #include #include +#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 bcaf913b5..da766e6d5 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -41,7 +41,9 @@ #include #endif -#include +#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 0d5d15ef9..824683765 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -29,6 +29,8 @@ #include #include +#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); } diff --git a/src/login/logind-dbus.c b/src/login/logind-dbus.c index ae9671bb1..af62d8782 100644 --- a/src/login/logind-dbus.c +++ b/src/login/logind-dbus.c @@ -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 \ " \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; diff --git a/src/login/logind-seat.c b/src/login/logind-seat.c index 045712192..937315ebf 100644 --- a/src/login/logind-seat.c +++ b/src/login/logind-seat.c @@ -27,6 +27,8 @@ #include #include +#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); diff --git a/src/login/logind-session.c b/src/login/logind-session.c index 16d4955d5..77462a8d1 100644 --- a/src/login/logind-session.c +++ b/src/login/logind-session.c @@ -25,6 +25,8 @@ #include #include +#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); diff --git a/src/shared/log.c b/src/shared/log.c index 4fc430eed..67a3e1b84 100644 --- a/src/shared/log.c +++ b/src/shared/log.c @@ -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; + + if (vasprintf(&buf, format, ap) < 0) { + r = -ENOMEM; + goto finish; + } + + IOVEC_SET_STRING(iovec[n++], buf); + + iovec[n].iov_base = (char*) &nl; + iovec[n].iov_len = 1; + n++; + + format = va_arg(ap, char *); + } + va_end(ap); + + zero(mh); + mh.msg_iov = iovec; + mh.msg_iovlen = n; + + if (sendmsg(journal_fd, &mh, MSG_NOSIGNAL) < 0) + r = -errno; + else + r = 1; + + finish: + for (i = 1; i < n; i += 2) + free(iovec[i].iov_base); + + } else { + char buf[LINE_MAX]; + bool found = false; + + /* Fallback if journal logging is not available */ + + va_start(ap, format); + while (format) { + + vsnprintf(buf, sizeof(buf), format, ap); + char_array_0(buf); + + if (startswith(buf, "MESSAGE=")) { + found = true; + break; + } + + format = va_arg(ap, char *); + } + va_end(ap); + + if (found) + r = log_dispatch(level, file, line, func, buf + 8); + else + r = -EINVAL; + } + + errno = saved_errno; + return r; +} + int log_set_target_from_string(const char *e) { LogTarget t; diff --git a/src/shared/log.h b/src/shared/log.h index ab894df17..0c60b7671 100644 --- a/src/shared/log.h +++ b/src/shared/log.h @@ -70,30 +70,51 @@ void log_close_console(void); void log_parse_environment(void); int log_meta( - int level, - const char*file, - int line, - const char *func, - const char *format, ...) _printf_attr_(5,6); + int level, + const char*file, + int line, + const char *func, + const char *format, ...) _printf_attr_(5,6); int log_metav( - int level, - const char*file, - int line, - const char *func, - const char *format, - va_list ap); - -_noreturn_ void log_assert_failed(const char *text, const char *file, int line, const char *func); -_noreturn_ void log_assert_failed_unreachable(const char *text, const char *file, int line, const char *func); + int level, + const char*file, + int line, + const char *func, + const char *format, + va_list ap); + +int log_struct_internal( + int level, + const char *file, + int line, + const char *func, + const char *format, ...) _sentinel_; + +int log_oom_internal( + const char *file, + int line, + const char *func); /* This modifies the buffer passed! */ int log_dump_internal( - int level, - const char*file, - int line, - const char *func, - char *buffer); + int level, + const char*file, + int line, + const char *func, + char *buffer); + +_noreturn_ void log_assert_failed( + const char *text, + const char *file, + int line, + const char *func); + +_noreturn_ void log_assert_failed_unreachable( + const char *text, + const char *file, + int line, + const char *func); #define log_full(level, ...) log_meta(level, __FILE__, __LINE__, __func__, __VA_ARGS__) @@ -103,8 +124,9 @@ int log_dump_internal( #define log_warning(...) log_meta(LOG_WARNING, __FILE__, __LINE__, __func__, __VA_ARGS__) #define log_error(...) log_meta(LOG_ERR, __FILE__, __LINE__, __func__, __VA_ARGS__) -int __log_oom(const char *file, int line, const char *func); -#define log_oom() __log_oom(__FILE__, __LINE__, __func__) +#define log_struct(level, ...) log_struct_internal(level, __FILE__, __LINE__, __func__, __VA_ARGS__) + +#define log_oom() log_oom_internal(__FILE__, __LINE__, __func__) /* This modifies the buffer passed! */ #define log_dump(level, buffer) log_dump_internal(level, __FILE__, __LINE__, __func__, buffer) diff --git a/src/sleep/sleep.c b/src/sleep/sleep.c index c86f69c4a..71c7518a3 100644 --- a/src/sleep/sleep.c +++ b/src/sleep/sleep.c @@ -25,6 +25,8 @@ #include "log.h" #include "util.h" +#include "systemd/sd-id128.h" +#include "systemd/sd-messages.h" int main(int argc, char *argv[]) { const char *verb; @@ -66,9 +68,17 @@ int main(int argc, char *argv[]) { execute_directory(SYSTEM_SLEEP_PATH, NULL, arguments); if (streq(argv[1], "suspend")) - log_info("Suspending system..."); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START), + "MESSAGE=Suspending system...", + "SLEEP=suspend", + NULL); else - log_info("Hibernating system..."); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START), + "MESSAGE=Hibernating system...", + "SLEEP=hibernate", + NULL); fputs(verb, f); fputc('\n', f); @@ -77,9 +87,17 @@ int main(int argc, char *argv[]) { r = ferror(f) ? -errno : 0; if (streq(argv[1], "suspend")) - log_info("System resumed."); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP), + "MESSAGE=System resumed.", + "SLEEP=suspend", + NULL); else - log_info("System thawed."); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP), + "MESSAGE=System thawed.", + "SLEEP=hibernate", + NULL); arguments[1] = (char*) "post"; execute_directory(SYSTEM_SLEEP_PATH, NULL, arguments); diff --git a/src/systemd/sd-id128.h b/src/systemd/sd-id128.h index 27fa47942..126d83ce8 100644 --- a/src/systemd/sd-id128.h +++ b/src/systemd/sd-id128.h @@ -56,6 +56,7 @@ int sd_id128_get_boot(sd_id128_t *ret); * times. It is hence not a good idea to call this macro with an * expensive function as paramater or an expression with side * effects */ + #define SD_ID128_FORMAT_STR "%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x" #define SD_ID128_FORMAT_VAL(x) (x).bytes[0], (x).bytes[1], (x).bytes[2], (x).bytes[3], (x).bytes[4], (x).bytes[5], (x).bytes[6], (x).bytes[7], (x).bytes[8], (x).bytes[9], (x).bytes[10], (x).bytes[11], (x).bytes[12], (x).bytes[13], (x).bytes[14], (x).bytes[15] diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 9b485b9a8..01616c8f0 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -28,12 +28,35 @@ extern "C" { #endif -#define SD_MESSAGE_JOURNAL_START SD_ID128_MAKE(f7,73,79,a8,49,0b,40,8b,be,5f,69,40,50,5a,77,7b) -#define SD_MESSAGE_JOURNAL_STOP SD_ID128_MAKE(d9,3f,b3,c9,c2,4d,45,1a,97,ce,a6,15,ce,59,c0,0b) -#define SD_MESSAGE_JOURNAL_DROPPED SD_ID128_MAKE(a5,96,d6,fe,7b,fa,49,94,82,8e,72,30,9e,95,d6,1e) -#define SD_MESSAGE_JOURNAL_MISSED SD_ID128_MAKE(e9,bf,28,e6,e8,34,48,1b,b6,f4,8f,54,8a,d1,36,06) +#define SD_MESSAGE_JOURNAL_START SD_ID128_MAKE(f7,73,79,a8,49,0b,40,8b,be,5f,69,40,50,5a,77,7b) +#define SD_MESSAGE_JOURNAL_STOP SD_ID128_MAKE(d9,3f,b3,c9,c2,4d,45,1a,97,ce,a6,15,ce,59,c0,0b) +#define SD_MESSAGE_JOURNAL_DROPPED SD_ID128_MAKE(a5,96,d6,fe,7b,fa,49,94,82,8e,72,30,9e,95,d6,1e) +#define SD_MESSAGE_JOURNAL_MISSED SD_ID128_MAKE(e9,bf,28,e6,e8,34,48,1b,b6,f4,8f,54,8a,d1,36,06) -#define SD_MESSAGE_COREDUMP SD_ID128_MAKE(fc,2e,22,bc,6e,e6,47,b6,b9,07,29,ab,34,a2,50,b1) +#define SD_MESSAGE_COREDUMP SD_ID128_MAKE(fc,2e,22,bc,6e,e6,47,b6,b9,07,29,ab,34,a2,50,b1) + +#define SD_MESSAGE_SESSION_START SD_ID128_MAKE(8d,45,62,0c,1a,43,48,db,b1,74,10,da,57,c6,0c,66) +#define SD_MESSAGE_SESSION_STOP SD_ID128_MAKE(33,54,93,94,24,b4,45,6d,98,02,ca,83,33,ed,42,4a) +#define SD_MESSAGE_SEAT_START SD_ID128_MAKE(fc,be,fc,5d,a2,3d,42,80,93,f9,7c,82,a9,29,0f,7b) +#define SD_MESSAGE_SEAT_STOP SD_ID128_MAKE(e7,85,2b,fe,46,78,4e,d0,ac,cd,e0,4b,c8,64,c2,d5) + +#define SD_MESSAGE_TIME_CHANGE SD_ID128_MAKE(c7,a7,87,07,9b,35,4e,aa,a9,e7,7b,37,18,93,cd,27) +#define SD_MESSAGE_TIMEZONE_CHANGE SD_ID128_MAKE(45,f8,2f,4a,ef,7a,4b,bf,94,2c,e8,61,d1,f2,09,90) + +#define SD_MESSAGE_STARTUP_FINISHED SD_ID128_MAKE(b0,7a,24,9c,d0,24,41,4a,82,dd,00,cd,18,13,78,ff) + +#define SD_MESSAGE_SLEEP_START SD_ID128_MAKE(6b,bd,95,ee,97,79,41,e4,97,c4,8b,e2,7c,25,41,28) +#define SD_MESSAGE_SLEEP_STOP SD_ID128_MAKE(88,11,e6,df,2a,8e,40,f5,8a,94,ce,a2,6f,8e,bf,14) + +#define SD_MESSAGE_SHUTDOWN SD_ID128_MAKE(98,26,88,66,d1,d5,4a,49,9c,4e,98,92,1d,93,bc,40) + +#define SD_MESSAGE_UNIT_STARTING SD_ID128_MAKE(7d,49,58,e8,42,da,4a,75,8f,6c,1c,dc,7b,36,dc,c5) +#define SD_MESSAGE_UNIT_STARTED SD_ID128_MAKE(39,f5,34,79,d3,a0,45,ac,8e,11,78,62,48,23,1f,bf) +#define SD_MESSAGE_UNIT_STOPPING SD_ID128_MAKE(de,5b,42,6a,63,be,47,a7,b6,ac,3e,aa,c8,2e,2f,6f) +#define SD_MESSAGE_UNIT_STOPPED SD_ID128_MAKE(9d,1a,aa,27,d6,01,40,bd,96,36,54,38,aa,d2,02,86) +#define SD_MESSAGE_UNIT_FAILED SD_ID128_MAKE(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) +#define SD_MESSAGE_UNIT_RELOADING SD_ID128_MAKE(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) +#define SD_MESSAGE_UNIT_RELOADED SD_ID128_MAKE(be,02,cf,68,55,d2,42,8b,a4,0d,f7,e9,d0,22,f0,3d) #ifdef __cplusplus } diff --git a/src/test/test-log.c b/src/test/test-log.c new file mode 100644 index 000000000..cc924fa57 --- /dev/null +++ b/src/test/test-log.c @@ -0,0 +1,46 @@ +/*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/ + +/*** + This file is part of systemd. + + Copyright 2012 Lennart Poettering + + systemd is free software; you can redistribute it and/or modify it + under the terms of the GNU Lesser General Public License as published by + the Free Software Foundation; either version 2.1 of the License, or + (at your option) any later version. + + systemd is distributed in the hope that it will be useful, but + WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + Lesser General Public License for more details. + + You should have received a copy of the GNU Lesser General Public License + along with systemd; If not, see . +***/ + +#include +#include + +#include "log.h" + +int main(int argc, char* argv[]) { + + log_set_target(LOG_TARGET_CONSOLE); + log_open(); + + log_struct(LOG_INFO, + "MESSAGE=Waldo PID=%lu", (unsigned long) getpid(), + "SERVICE=piepapo", + NULL); + + log_set_target(LOG_TARGET_JOURNAL); + log_open(); + + log_struct(LOG_INFO, + "MESSAGE=Foobar PID=%lu", (unsigned long) getpid(), + "SERVICE=foobar", + NULL); + + return 0; +} diff --git a/src/timedate/timedated.c b/src/timedate/timedated.c index 09fd80833..34d287b2a 100644 --- a/src/timedate/timedated.c +++ b/src/timedate/timedated.c @@ -25,6 +25,8 @@ #include #include +#include "systemd/sd-id128.h" +#include "systemd/sd-messages.h" #include "util.h" #include "strv.h" #include "dbus-common.h" @@ -701,7 +703,11 @@ static DBusHandlerResult timedate_message_handler( hwclock_set_time(tm); } - log_info("Changed timezone to '%s'.", tz.zone); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIMEZONE_CHANGE), + "TIMEZONE=%s", tz.zone, + "MESSAGE=Changed timezone to '%s'.", tz.zone, + NULL); changed = bus_properties_changed_new( "/org/freedesktop/timedate1", @@ -842,7 +848,11 @@ static DBusHandlerResult timedate_message_handler( hwclock_set_time(tm); - log_info("Changed local time to %s", ctime(&ts.tv_sec)); + log_struct(LOG_INFO, + "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIME_CHANGE), + "REALTIME=%llu", (unsigned long long) timespec_load(&ts), + "MESSAGE=Changed local time to %s", ctime(&ts.tv_sec), + NULL); } } else if (dbus_message_is_method_call(message, "org.freedesktop.timedate1", "SetNTP")) { dbus_bool_t ntp; -- 2.30.2