[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