[systemd-devel] [PATCH v2] journal: new logging macros to include _SYSTEMD_UNIT
Zbigniew Jędrzejewski-Szmek
zbyszek at in.waw.pl
Sat Dec 22 01:47:37 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.
The set of logging functions is expanded to take a pair
of arguments (g. "_SYSTEMD_UNIT=" and the RHS), which add an extra
line to the structured log entry. This can be used to add macros
which add a different identifier later on.
---
src/core/job.c | 46 ++++++++++++++++++---------
src/core/service.c | 3 +-
src/core/unit.h | 6 ++++
src/shared/log.c | 85 ++++++++++++++++++++++++++++++++++++++++++++------
src/shared/log.h | 24 ++++++++++++--
src/shared/logs-show.c | 2 +-
6 files changed, 138 insertions(+), 28 deletions(-)
So, here's a second version which is slightly more generic.
I think that the front-end (log_*_unit macros) is fine, and it can be merged,
since the other changes are fairly localized and can be fixed afterwards if
necessary. It'll become clear what is needed when different types of identifiers
are used (job or device). If nobody object, I'll merge it like this and then
work on tagging more log lines with unit identifiers.
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/core/unit.h b/src/core/unit.h
index b40f034..42b08bb 100644
--- a/src/core/unit.h
+++ b/src/core/unit.h
@@ -552,3 +552,9 @@ UnitActiveState unit_active_state_from_string(const char *s);
const char *unit_dependency_to_string(UnitDependency i);
UnitDependency unit_dependency_from_string(const char *s);
+
+#define log_debug_unit(unit, ...) log_meta_object(LOG_DEBUG, __FILE__, __LINE__, __func__, "_SYSTEMD_UNIT=", unit, __VA_ARGS__)
+#define log_info_unit(unit, ...) log_meta_object(LOG_INFO, __FILE__, __LINE__, __func__, "_SYSTEMD_UNIT=", unit, __VA_ARGS__)
+#define log_notice_unit(unit, ...) log_meta_object(LOG_NOTICE, __FILE__, __LINE__, __func__, "_SYSTEMD_UNIT=", unit, __VA_ARGS__)
+#define log_warning_unit(unit, ...) log_meta_object(LOG_WARNING, __FILE__, __LINE__, __func__, "_SYSTEMD_UNIT=", unit, __VA_ARGS__)
+#define log_error_unit(unit, ...) log_meta_object(LOG_ERR, __FILE__, __LINE__, __func__, "_SYSTEMD_UNIT=", unit, __VA_ARGS__)
diff --git a/src/shared/log.c b/src/shared/log.c
index 6357868..8d3458e 100644
--- a/src/shared/log.c
+++ b/src/shared/log.c
@@ -308,6 +308,8 @@ static int write_to_console(
const char*file,
int line,
const char *func,
+ const char *object_name,
+ const char *object,
const char *buffer) {
char location[64];
@@ -346,6 +348,8 @@ static int write_to_syslog(
const char*file,
int line,
const char *func,
+ const char *object_name,
+ const char *object,
const char *buffer) {
char header_priority[16], header_time[64], header_pid[16];
@@ -361,7 +365,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 +412,8 @@ static int write_to_kmsg(
const char*file,
int line,
const char *func,
+ const char *object_name,
+ const char *object,
const char *buffer) {
char header_priority[16], header_pid[16];
@@ -439,6 +446,8 @@ static int write_to_journal(
const char*file,
int line,
const char *func,
+ const char *object_name,
+ const char *object,
const char *buffer) {
char header[LINE_MAX];
@@ -454,6 +463,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 +471,9 @@ static int write_to_journal(
file,
line,
func,
+ object ? object_name : "",
+ object ? LINE_MAX : 0, object, /* %.0s means no output */
+ object ? "\n" : "",
program_invocation_short_name);
char_array_0(header);
@@ -485,6 +498,8 @@ static int log_dispatch(
const char*file,
int line,
const char *func,
+ const char *object_name,
+ const char *object,
char *buffer) {
int r = 0;
@@ -512,7 +527,8 @@ 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,
+ object_name, object, buffer);
if (k < 0) {
if (k != -EAGAIN)
log_close_journal();
@@ -524,7 +540,8 @@ 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,
+ object_name, object, buffer);
if (k < 0) {
if (k != -EAGAIN)
log_close_syslog();
@@ -540,7 +557,8 @@ 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,
+ object_name, object, buffer);
if (k < 0) {
log_close_kmsg();
log_open_console();
@@ -549,7 +567,8 @@ static int log_dispatch(
}
if (k <= 0) {
- k = write_to_console(level, file, line, func, buffer);
+ k = write_to_console(level, file, line, func,
+ object_name, object, buffer);
if (k < 0)
return k;
}
@@ -575,7 +594,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, NULL, buffer);
errno = saved_errno;
return r;
@@ -599,7 +618,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, NULL, buffer);
errno = saved_errno;
return r;
@@ -622,6 +641,53 @@ int log_meta(
return r;
}
+int log_metav_object(
+ int level,
+ const char*file,
+ int line,
+ const char *func,
+ const char *object_name,
+ const char *object,
+ 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,
+ object_name, object, buffer);
+ errno = saved_errno;
+
+ return r;
+}
+
+int log_meta_object(
+ int level,
+ const char*file,
+ int line,
+ const char *func,
+ const char *object_name,
+ const char *object,
+ const char *format, ...) {
+
+ int r;
+ va_list ap;
+
+ va_start(ap, format);
+ r = log_metav_object(level, file, line, func,
+ object_name, object, 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 +698,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, NULL, buffer);
abort();
}
#pragma GCC diagnostic pop
@@ -774,7 +840,8 @@ 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, NULL, buf + 8);
else
r = -EINVAL;
}
diff --git a/src/shared/log.h b/src/shared/log.h
index 5c946fa..2d08a77 100644
--- a/src/shared/log.h
+++ b/src/shared/log.h
@@ -85,6 +85,25 @@ int log_metav(
const char *format,
va_list ap);
+int log_meta_object(
+ int level,
+ const char*file,
+ int line,
+ const char *func,
+ const char *object_name,
+ const char *object,
+ const char *format, ...) _printf_attr_(7,8);
+
+int log_metav_object(
+ int level,
+ const char*file,
+ int line,
+ const char *func,
+ const char *object_name,
+ const char *object,
+ const char *format,
+ va_list ap);
+
int log_struct_internal(
int level,
const char *file,
@@ -117,6 +136,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__)
@@ -136,5 +158,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.8.1.rc0.194.gaf2e3a9
More information about the systemd-devel
mailing list