From 924775e8ce49817f96df19c2b06356c12ecfc754 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sat, 22 Jul 2017 15:52:20 -0400 Subject: [PATCH] core: when logging about dependency cycles, add UNIT= entries for all involved units Example log: Jul 22 15:55:21 fedora systemd[1]: a1.service: Found ordering cycle on a2.service/start Jul 22 15:55:21 fedora systemd[1]: a1.service: Found dependency on a3.service/start Jul 22 15:55:21 fedora systemd[1]: a1.service: Found dependency on a1.service/start Jul 22 15:55:21 fedora systemd[1]: a1.service: Job a2.service/start deleted to break ordering cycle starting with a1.service/start Jul 22 15:55:21 fedora systemd[1]: Starting a1.service... Jul 22 15:55:21 fedora systemd[1]: Started a1.service. Example log entry: Sat 2017-07-22 15:55:21.372389 EDT [s=0004bb6302d94ac3aa69987fb6157338;i=9ae;b=a96eb6153d4f4f3686c7b4 _BOOT_ID=a96eb6153d4f4f3686c7b4db8a432908 _MACHINE_ID=ad18f69b80264b52bb3b766240742383 _HOSTNAME=fedora PRIORITY=3 SYSLOG_FACILITY=3 SYSLOG_IDENTIFIER=systemd _UID=0 _GID=0 _PID=1 _TRANSPORT=journal _CAP_EFFECTIVE=3fffffffff _COMM=systemd _EXE=/usr/lib/systemd/systemd _SYSTEMD_CGROUP=/init.scope _SYSTEMD_UNIT=init.scope _SYSTEMD_SLICE=-.slice _SELINUX_CONTEXT=system_u:system_r:kernel_t:s0 CODE_FILE=../src/core/transaction.c CODE_FUNC=transaction_verify_order_one UNIT=a3.service UNIT=a1.service UNIT=a2.service CODE_LINE=430 MESSAGE=a1.service: Job a2.service/start deleted to break ordering cycle starting with a1.service _CMDLINE=/usr/lib/systemd/systemd --system --deserialize 28 _SOURCE_REALTIME_TIMESTAMP=1500753321372389 This should make it easier to see when any of the units are involved in an ordering cycle. Fixes #6336. v2: - also update the "Unable to break cycle" message. --- src/core/transaction.c | 83 ++++++++++++++++++++++++++++++++------------------ 1 file changed, 54 insertions(+), 29 deletions(-) diff --git a/src/core/transaction.c b/src/core/transaction.c index a2dfd8a..710a6a3 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -338,6 +338,26 @@ _pure_ static bool unit_matters_to_anchor(Unit *u, Job *j) { return false; } +static char* merge_unit_ids(const char* unit_log_field, char **pairs) { + char **unit_id, **job_type, *ans = NULL; + size_t alloc = 0, size = 0, next; + + STRV_FOREACH_PAIR(unit_id, job_type, pairs) { + next = strlen(unit_log_field) + strlen(*unit_id); + if (!GREEDY_REALLOC(ans, alloc, size + next + 1)) { + free(ans); + return NULL; + } + + sprintf(ans + size, "%s%s", unit_log_field, *unit_id); + if (*(unit_id+1)) + ans[size + next] = '\n'; + size += next + 1; + } + + return ans; +} + static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsigned generation, sd_bus_error *e) { Iterator i; Unit *u; @@ -352,7 +372,9 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi /* Have we seen this before? */ if (j->generation == generation) { - Job *k, *delete; + Job *k, *delete = NULL; + _cleanup_free_ char **array = NULL, *unit_ids = NULL; + char **unit_id, **job_type; /* If the marker is NULL we have been here already and * decided the job was loop-free from here. Hence @@ -360,46 +382,46 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi if (!j->marker) return 0; - /* So, the marker is not NULL and we already have been - * here. We have a cycle. Let's try to break it. We go - * backwards in our path and try to find a suitable - * job to remove. We use the marker to find our way - * back, since smart how we are we stored our way back - * in there. */ - log_unit_warning(j->unit, - "Found ordering cycle on %s/%s", - j->unit->id, job_type_to_string(j->type)); - - delete = NULL; + /* So, the marker is not NULL and we already have been here. We have + * a cycle. Let's try to break it. We go backwards in our path and + * try to find a suitable job to remove. We use the marker to find + * our way back, since smart how we are we stored our way back in + * there. */ + for (k = from; k; k = ((k->generation == generation && k->marker != k) ? k->marker : NULL)) { - /* logging for j not k here to provide consistent narrative */ - log_unit_warning(j->unit, - "Found dependency on %s/%s", - k->unit->id, job_type_to_string(k->type)); + /* For logging below */ + if (strv_push_pair(&array, k->unit->id, (char*) job_type_to_string(k->type)) < 0) + log_oom(); if (!delete && hashmap_get(tr->jobs, k->unit) && !unit_matters_to_anchor(k->unit, k)) - /* Ok, we can drop this one, so let's - * do so. */ + /* Ok, we can drop this one, so let's do so. */ delete = k; - /* Check if this in fact was the beginning of - * the cycle */ + /* Check if this in fact was the beginning of the cycle */ if (k == j) break; } + unit_ids = merge_unit_ids(j->manager->unit_log_field, array); /* ignore error */ + + STRV_FOREACH_PAIR(unit_id, job_type, array) + /* logging for j not k here to provide a consistent narrative */ + log_struct(LOG_WARNING, + "MESSAGE=%s: Found %s on %s/%s", + j->unit->id, + unit_id == array ? "ordering cycle" : "dependency", + *unit_id, *job_type, + unit_ids, NULL); if (delete) { const char *status; - /* logging for j not k here to provide consistent narrative */ - log_unit_warning(j->unit, - "Breaking ordering cycle by deleting job %s/%s", - delete->unit->id, job_type_to_string(delete->type)); - log_unit_error(delete->unit, - "Job %s/%s deleted to break ordering cycle starting with %s/%s", - delete->unit->id, job_type_to_string(delete->type), - j->unit->id, job_type_to_string(j->type)); + /* logging for j not k here to provide a consistent narrative */ + log_struct(LOG_ERR, + "MESSAGE=%s: Job %s/%s deleted to break ordering cycle starting with %s/%s", + j->unit->id, delete->unit->id, job_type_to_string(delete->type), + j->unit->id, job_type_to_string(j->type), + unit_ids, NULL); if (log_get_show_color()) status = ANSI_HIGHLIGHT_RED " SKIP " ANSI_NORMAL; @@ -412,7 +434,10 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi return -EAGAIN; } - log_error("Unable to break cycle"); + log_struct(LOG_ERR, + "MESSAGE=%s: Unable to break cycle starting with %s/%s", + j->unit->id, j->unit->id, job_type_to_string(j->type), + unit_ids, NULL); return sd_bus_error_setf(e, BUS_ERROR_TRANSACTION_ORDER_IS_CYCLIC, "Transaction order is cyclic. See system logs for details."); -- 2.7.4