[systemd-devel] [RFC/PATCH] journal: new logging macros to include _SYSTEMD_UNIT

Zbigniew Jędrzejewski-Szmek zbyszek at in.waw.pl
Wed Dec 5 01:55:48 PST 2012


Adding _SYSTEMD_UNIT= to log lines allows them to be shown
in 'systemctl status' output, etc.

A new set of macros and functions is added. This allows for less
verbose notation than using log_struct() explicitly. Just a few
example log lines are modified to show the usage.

---
 src/core/job.c         |   46 +++++++++++++++++++++----------
 src/core/service.c     |    3 +-
 src/shared/log.c       |   71 ++++++++++++++++++++++++++++++++++++++++++------
 src/shared/log.h       |   28 +++++++++++++++++--
 src/shared/logs-show.c |    2 +-
 5 files changed, 122 insertions(+), 28 deletions(-)

Hi,
quite a few different patches have been merged (or sent to the mailing
list), to add unit information to log lines. This patch implements a generic
approach, with a new set of macros. If think that something like this is
unavoidable, but would like to hear ideas how to reach the same goal
less intrusively.

Zbyszek

diff --git a/src/core/job.c b/src/core/job.c
index f08b8cb..b496986 100644
--- a/src/core/job.c
+++ b/src/core/job.c
@@ -187,8 +187,9 @@ Job* job_install(Job *j) {
                         if (j->type == JOB_NOP || uj->state == JOB_WAITING ||
                             (job_type_allows_late_merge(j->type) && job_type_is_superset(uj->type, j->type))) {
                                 job_merge_into_installed(uj, j);
-                                log_debug("Merged into installed job %s/%s as %u",
-                                          uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id);
+                                log_debug_unit(uj->unit->id,
+                                               "Merged into installed job %s/%s as %u",
+                                               uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id);
                                 return uj;
                         } else {
                                 /* already running and not safe to merge into */
@@ -196,8 +197,9 @@ Job* job_install(Job *j) {
                                 /* XXX It should be safer to queue j to run after uj finishes, but it is
                                  * not currently possible to have more than one installed job per unit. */
                                 job_merge_into_installed(uj, j);
-                                log_debug("Merged into running job, re-running: %s/%s as %u",
-                                          uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id);
+                                log_debug_unit(uj->unit->id,
+                                               "Merged into running job, re-running: %s/%s as %u",
+                                               uj->unit->id, job_type_to_string(uj->type), (unsigned) uj->id);
                                 uj->state = JOB_WAITING;
                                 return uj;
                         }
@@ -208,7 +210,9 @@ Job* job_install(Job *j) {
         *pj = j;
         j->installed = true;
         j->manager->n_installed_jobs ++;
-        log_debug("Installed new job %s/%s as %u", j->unit->id, job_type_to_string(j->type), (unsigned) j->id);
+        log_debug_unit(j->unit->id,
+                       "Installed new job %s/%s as %u",
+                       j->unit->id, job_type_to_string(j->type), (unsigned) j->id);
         return j;
 }
 
@@ -225,12 +229,16 @@ int job_install_deserialized(Job *j) {
         pj = (j->type == JOB_NOP) ? &j->unit->nop_job : &j->unit->job;
 
         if (*pj) {
-                log_debug("Unit %s already has a job installed. Not installing deserialized job.", j->unit->id);
+                log_debug_unit(j->unit->id,
+                               "Unit %s already has a job installed. Not installing deserialized job.",
+                               j->unit->id);
                 return -EEXIST;
         }
         *pj = j;
         j->installed = true;
-        log_debug("Reinstalled deserialized job %s/%s as %u", j->unit->id, job_type_to_string(j->type), (unsigned) j->id);
+        log_debug_unit(j->unit->id,
+                       "Reinstalled deserialized job %s/%s as %u",
+                       j->unit->id, job_type_to_string(j->type), (unsigned) j->id);
         return 0;
 }
 
@@ -457,9 +465,10 @@ bool job_is_runnable(Job *j) {
 }
 
 static void job_change_type(Job *j, JobType newtype) {
-        log_debug("Converting job %s/%s -> %s/%s",
-                  j->unit->id, job_type_to_string(j->type),
-                  j->unit->id, job_type_to_string(newtype));
+        log_debug_unit(j->unit->id,
+                       "Converting job %s/%s -> %s/%s",
+                       j->unit->id, job_type_to_string(j->type),
+                       j->unit->id, job_type_to_string(newtype));
 
         j->type = newtype;
 }
@@ -744,7 +753,8 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) {
 
         j->result = result;
 
-        log_debug("Job %s/%s finished, result=%s", u->id, job_type_to_string(t), job_result_to_string(result));
+        log_debug_unit(u->id, "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);
@@ -804,14 +814,19 @@ int job_finish_and_invalidate(Job *j, JobResult result, bool recursive) {
         }
 
         /* Trigger OnFailure dependencies that are not generated by
-         * the unit itself. We don't tread JOB_CANCELED as failure in
+         * the unit itself. We don't treat JOB_CANCELED as failure in
          * this context. And JOB_FAILURE is already handled by the
          * unit itself. */
         if (result == JOB_TIMEOUT || result == JOB_DEPENDENCY) {
-                log_notice("Job %s/%s failed with result '%s'.",
+                log_struct(LOG_NOTICE,
+                           UNIT_ID(u->id),
+                           "JOB_TYPE=%s", job_type_to_string(t),
+                           "JOB_RESULT=%s", job_result_to_string(t),
+                           "Job %s/%s failed with result '%s'.",
                            u->id,
                            job_type_to_string(t),
-                           job_result_to_string(result));
+                           job_result_to_string(result),
+                           NULL);
 
                 unit_trigger_on_failure(u);
         }
@@ -918,7 +933,8 @@ void job_timer_event(Job *j, uint64_t n_elapsed, Watch *w) {
         assert(j);
         assert(w == &j->timer_watch);
 
-        log_warning("Job %s/%s timed out.", j->unit->id, job_type_to_string(j->type));
+        log_warning_unit(j->unit->id, "Job %s/%s timed out.",
+                         j->unit->id, job_type_to_string(j->type));
         job_finish_and_invalidate(j, JOB_TIMEOUT, true);
 }
 
diff --git a/src/core/service.c b/src/core/service.c
index 3d2be96..f4e4057 100644
--- a/src/core/service.c
+++ b/src/core/service.c
@@ -169,7 +169,8 @@ static void service_unwatch_pid_file(Service *s) {
         if (!s->pid_file_pathspec)
                 return;
 
-        log_debug("Stopping watch for %s's PID file %s", UNIT(s)->id, s->pid_file_pathspec->path);
+        log_debug_unit(UNIT(s)->id, "Stopping watch for %s's PID file %s",
+                       UNIT(s)->id, s->pid_file_pathspec->path);
         path_spec_unwatch(s->pid_file_pathspec, UNIT(s));
         path_spec_done(s->pid_file_pathspec);
         free(s->pid_file_pathspec);
diff --git a/src/shared/log.c b/src/shared/log.c
index 6357868..90fa71e 100644
--- a/src/shared/log.c
+++ b/src/shared/log.c
@@ -308,6 +308,7 @@ static int write_to_console(
                 const char*file,
                 int line,
                 const char *func,
+                const char *unit,
                 const char *buffer) {
 
         char location[64];
@@ -346,6 +347,7 @@ static int write_to_syslog(
         const char*file,
         int line,
         const char *func,
+        const char *unit,
         const char *buffer) {
 
         char header_priority[16], header_time[64], header_pid[16];
@@ -361,7 +363,8 @@ static int write_to_syslog(
         char_array_0(header_priority);
 
         t = (time_t) (now(CLOCK_REALTIME) / USEC_PER_SEC);
-        if (!(tm = localtime(&t)))
+        tm = localtime(&t);
+        if (!tm)
                 return -EINVAL;
 
         if (strftime(header_time, sizeof(header_time), "%h %e %T ", tm) <= 0)
@@ -407,6 +410,7 @@ static int write_to_kmsg(
         const char*file,
         int line,
         const char *func,
+        const char *unit,
         const char *buffer) {
 
         char header_priority[16], header_pid[16];
@@ -439,6 +443,7 @@ static int write_to_journal(
         const char*file,
         int line,
         const char *func,
+        const char *unit,
         const char *buffer) {
 
         char header[LINE_MAX];
@@ -454,6 +459,7 @@ static int write_to_journal(
                  "CODE_FILE=%s\n"
                  "CODE_LINE=%i\n"
                  "CODE_FUNCTION=%s\n"
+                 "%s%.*s%s"
                  "SYSLOG_IDENTIFIER=%s\n"
                  "MESSAGE=",
                  LOG_PRI(level),
@@ -461,6 +467,9 @@ static int write_to_journal(
                  file,
                  line,
                  func,
+                 unit ? "_SYSTEMD_UNIT=" : "",
+                 unit ? LINE_MAX : 0, unit, /* %.0s means no output */
+                 unit ? "\n" : "",
                  program_invocation_short_name);
 
         char_array_0(header);
@@ -485,6 +494,7 @@ static int log_dispatch(
         const char*file,
         int line,
         const char *func,
+        const char *unit,
         char *buffer) {
 
         int r = 0;
@@ -512,7 +522,7 @@ static int log_dispatch(
                     log_target == LOG_TARGET_JOURNAL_OR_KMSG ||
                     log_target == LOG_TARGET_JOURNAL) {
 
-                        k = write_to_journal(level, file, line, func, buffer);
+                        k = write_to_journal(level, file, line, func, unit, buffer);
                         if (k < 0) {
                                 if (k != -EAGAIN)
                                         log_close_journal();
@@ -524,7 +534,7 @@ static int log_dispatch(
                 if (log_target == LOG_TARGET_SYSLOG_OR_KMSG ||
                     log_target == LOG_TARGET_SYSLOG) {
 
-                        k = write_to_syslog(level, file, line, func, buffer);
+                        k = write_to_syslog(level, file, line, func, unit, buffer);
                         if (k < 0) {
                                 if (k != -EAGAIN)
                                         log_close_syslog();
@@ -540,7 +550,7 @@ static int log_dispatch(
                      log_target == LOG_TARGET_JOURNAL_OR_KMSG ||
                      log_target == LOG_TARGET_KMSG)) {
 
-                        k = write_to_kmsg(level, file, line, func, buffer);
+                        k = write_to_kmsg(level, file, line, func, unit, buffer);
                         if (k < 0) {
                                 log_close_kmsg();
                                 log_open_console();
@@ -549,7 +559,7 @@ static int log_dispatch(
                 }
 
                 if (k <= 0) {
-                        k = write_to_console(level, file, line, func, buffer);
+                        k = write_to_console(level, file, line, func, unit, buffer);
                         if (k < 0)
                                 return k;
                 }
@@ -575,7 +585,7 @@ int log_dump_internal(
                 return 0;
 
         saved_errno = errno;
-        r = log_dispatch(level, file, line, func, buffer);
+        r = log_dispatch(level, file, line, func, NULL, buffer);
         errno = saved_errno;
 
         return r;
@@ -599,7 +609,7 @@ int log_metav(
         vsnprintf(buffer, sizeof(buffer), format, ap);
         char_array_0(buffer);
 
-        r = log_dispatch(level, file, line, func, buffer);
+        r = log_dispatch(level, file, line, func, NULL, buffer);
         errno = saved_errno;
 
         return r;
@@ -622,6 +632,49 @@ int log_meta(
         return r;
 }
 
+int log_metav_unit(
+        int level,
+        const char*file,
+        int line,
+        const char *func,
+        const char *unit,
+        const char *format,
+        va_list ap) {
+
+        char buffer[LINE_MAX];
+        int saved_errno, r;
+
+        if (_likely_(LOG_PRI(level) > log_max_level))
+                return 0;
+
+        saved_errno = errno;
+        vsnprintf(buffer, sizeof(buffer), format, ap);
+        char_array_0(buffer);
+
+        r = log_dispatch(level, file, line, func, unit, buffer);
+        errno = saved_errno;
+
+        return r;
+}
+
+int log_meta_unit(
+        int level,
+        const char*file,
+        int line,
+        const char *func,
+        const char *unit,
+        const char *format, ...) {
+
+        int r;
+        va_list ap;
+
+        va_start(ap, format);
+        r = log_metav_unit(level, file, line, func, unit, format, ap);
+        va_end(ap);
+
+        return r;
+}
+
 #pragma GCC diagnostic push
 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
 _noreturn_ static void log_assert(const char *text, const char *file, int line, const char *func, const char *format) {
@@ -632,7 +685,7 @@ _noreturn_ static void log_assert(const char *text, const char *file, int line,
         char_array_0(buffer);
         log_abort_msg = buffer;
 
-        log_dispatch(LOG_CRIT, file, line, func, buffer);
+        log_dispatch(LOG_CRIT, file, line, func, NULL, buffer);
         abort();
 }
 #pragma GCC diagnostic pop
@@ -774,7 +827,7 @@ int log_struct_internal(
                 va_end(ap);
 
                 if (found)
-                        r = log_dispatch(level, file, line, func, buf + 8);
+                        r = log_dispatch(level, file, line, func, NULL, buf + 8);
                 else
                         r = -EINVAL;
         }
diff --git a/src/shared/log.h b/src/shared/log.h
index 1bd9dbf..d6ab4b2 100644
--- a/src/shared/log.h
+++ b/src/shared/log.h
@@ -84,6 +84,23 @@ int log_metav(
                 const char *format,
                 va_list ap);
 
+int log_meta_unit(
+                int level,
+                const char*file,
+                int line,
+                const char *func,
+                const char *unit,
+                const char *format, ...) _printf_attr_(6,7);
+
+int log_metav_unit(
+                int level,
+                const char*file,
+                int line,
+                const char *func,
+                const char *unit,
+                const char *format,
+                va_list ap);
+
 int log_struct_internal(
                 int level,
                 const char *file,
@@ -116,6 +133,9 @@ _noreturn_ void log_assert_failed_unreachable(
                 int line,
                 const char *func);
 
+#define MESSAGE_ID(x) "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(x)
+#define UNIT_ID(x) "_SYSTEMD_UNIT=%s", x
+
 #define log_full(level, ...) log_meta(level,   __FILE__, __LINE__, __func__, __VA_ARGS__)
 
 #define log_debug(...)   log_meta(LOG_DEBUG,   __FILE__, __LINE__, __func__, __VA_ARGS__)
@@ -124,6 +144,12 @@ _noreturn_ void log_assert_failed_unreachable(
 #define log_warning(...) log_meta(LOG_WARNING, __FILE__, __LINE__, __func__, __VA_ARGS__)
 #define log_error(...)   log_meta(LOG_ERR,     __FILE__, __LINE__, __func__, __VA_ARGS__)
 
+#define log_debug_unit(unit, ...)   log_meta_unit(LOG_DEBUG,   __FILE__, __LINE__, __func__, unit, __VA_ARGS__)
+#define log_info_unit(unit, ...)    log_meta_unit(LOG_INFO,    __FILE__, __LINE__, __func__, unit, __VA_ARGS__)
+#define log_notice_unit(unit, ...)  log_meta_unit(LOG_NOTICE,  __FILE__, __LINE__, __func__, unit, __VA_ARGS__)
+#define log_warning_unit(unit, ...) log_meta_unit(LOG_WARNING, __FILE__, __LINE__, __func__, unit, __VA_ARGS__)
+#define log_error_unit(unit, ...)   log_meta_unit(LOG_ERR,     __FILE__, __LINE__, __func__, unit, __VA_ARGS__)
+
 #define log_struct(level, ...) log_struct_internal(level, __FILE__, __LINE__, __func__, __VA_ARGS__)
 
 #define log_oom() log_oom_internal(__FILE__, __LINE__, __func__)
@@ -135,5 +161,3 @@ bool log_on_console(void);
 
 const char *log_target_to_string(LogTarget target);
 LogTarget log_target_from_string(const char *s);
-
-#define MESSAGE_ID(x) "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(x)
diff --git a/src/shared/logs-show.c b/src/shared/logs-show.c
index ca5ad43..ddc82ca 100644
--- a/src/shared/logs-show.c
+++ b/src/shared/logs-show.c
@@ -807,7 +807,7 @@ int show_journal_by_unit(
         if (how_many <= 0)
                 return 0;
 
-        if (asprintf(&m1, "_SYSTEMD_UNIT=%s", unit) < 0 ||
+        if (asprintf(&m1, UNIT_ID(unit)) < 0 ||
             asprintf(&m2, "COREDUMP_UNIT=%s", unit) < 0 ||
             asprintf(&m3, "UNIT=%s", unit) < 0) {
                 r = -ENOMEM;
-- 
1.7.10.4



More information about the systemd-devel mailing list