picnoir/Systemd
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

core: when logging about dependency cycles, add UNIT= entries for all involved units

Browse source 
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.
This commit is contained in:
Zbigniew Jędrzejewski-Szmek 2017-07-22 15:52:20 -04:00
parent 3f6de63bf7
commit 924775e8ce
1 changed files with 53 additions and 28 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

81
src/core/transaction.c
View file

@ -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));
/* 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. */
delete = NULL;
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.");