From 201647e3f2ff04fbaebc1901431b7ff610f995fb Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 18 Jun 2025 11:47:06 +0200 Subject: [PATCH 1/6] core: output log cycle path in one log message, not many Fixes: #35642 --- src/core/transaction.c | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/src/core/transaction.c b/src/core/transaction.c index 699d60a865..617ab1adc1 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -396,13 +396,22 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi unit_ids = merge_unit_ids(unit_log_field(j->unit), array); /* ignore error */ - STRV_FOREACH_PAIR(unit_id, job_type, array) - /* logging for j not k here to provide a consistent narrative */ + size_t m = strv_length(array); + + _cleanup_free_ char *cycle_path_text = strdup("Found ordering cycle"); + if (m > 0) { + (void) strextendf(&cycle_path_text, " on %s/%s", array[0], array[1]); + if (m > 2) + (void) strextendf(&cycle_path_text, "; has dependency on %s/%s", array[2], array[3]); + } + + STRV_FOREACH_PAIR(unit_id, job_type, strv_skip(array, 4)) + (void) strextendf(&cycle_path_text, ", %s/%s", *unit_id, *job_type); + + /* logging for j not k here to provide a consistent narrative */ + if (cycle_path_text) log_struct(LOG_WARNING, - LOG_UNIT_MESSAGE(j->unit, - "Found %s on %s/%s", - unit_id == array ? "ordering cycle" : "dependency", - *unit_id, *job_type), + LOG_UNIT_MESSAGE(j->unit, "%s", cycle_path_text), LOG_ITEM("%s", strna(unit_ids))); if (delete) { From 5bbad6244ffc3849511c6ca652a27f1af550c599 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 18 Jun 2025 11:47:25 +0200 Subject: [PATCH 2/6] core: make log cycle messages recognizable via message IDs --- src/core/transaction.c | 4 ++++ src/systemd/sd-messages.h | 9 +++++++++ 2 files changed, 13 insertions(+) diff --git a/src/core/transaction.c b/src/core/transaction.c index 617ab1adc1..8962bf9461 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -1,6 +1,7 @@ /* SPDX-License-Identifier: LGPL-2.1-or-later */ #include "sd-bus.h" +#include "sd-messages.h" #include "alloc-util.h" #include "ansi-color.h" @@ -412,6 +413,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi if (cycle_path_text) log_struct(LOG_WARNING, LOG_UNIT_MESSAGE(j->unit, "%s", cycle_path_text), + LOG_MESSAGE_ID(SD_MESSAGE_UNIT_ORDERING_CYCLE_STR), LOG_ITEM("%s", strna(unit_ids))); if (delete) { @@ -422,6 +424,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi "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)), + LOG_MESSAGE_ID(SD_MESSAGE_DELETING_JOB_BECAUSE_ORDERING_CYCLE_STR), LOG_ITEM("%s", strna(unit_ids))); if (log_get_show_color()) @@ -441,6 +444,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi log_struct(LOG_ERR, LOG_UNIT_MESSAGE(j->unit, "Unable to break cycle starting with %s/%s", j->unit->id, job_type_to_string(j->type)), + LOG_MESSAGE_ID(SD_MESSAGE_CANT_BREAK_ORDERING_CYCLE_STR), LOG_ITEM("%s", strna(unit_ids))); return sd_bus_error_setf(e, BUS_ERROR_TRANSACTION_ORDER_IS_CYCLIC, diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 319154824a..02edf9facf 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -292,6 +292,15 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_SYSCTL_CHANGED SD_ID128_MAKE(9c,f5,6b,8b,af,95,46,cf,94,78,78,3a,8d,e4,21,13) #define SD_MESSAGE_SYSCTL_CHANGED_STR SD_ID128_MAKE_STR(9c,f5,6b,8b,af,95,46,cf,94,78,78,3a,8d,e4,21,13) +#define SD_MESSAGE_UNIT_ORDERING_CYCLE SD_ID128_MAKE(f2,7a,3f,94,40,6a,47,83,b9,46,a9,bc,84,9e,94,52) +#define SD_MESSAGE_UNIT_ORDERING_CYCLE_STR SD_ID128_MAKE_STR(f2,7a,3f,94,40,6a,47,83,b9,46,a9,bc,84,9e,94,52) + +#define SD_MESSAGE_DELETING_JOB_BECAUSE_ORDERING_CYCLE SD_ID128_MAKE(50,84,36,75,42,f7,47,2d,bc,6a,94,12,5d,5d,eb,ce) +#define SD_MESSAGE_DELETING_JOB_BECAUSE_ORDERING_CYCLE_STR SD_ID128_MAKE_STR(50,84,36,75,42,f7,47,2d,bc,6a,94,12,5d,5d,eb,ce) + +#define SD_MESSAGE_CANT_BREAK_ORDERING_CYCLE SD_ID128_MAKE(b3,11,2d,da,d1,90,45,53,8c,76,68,5b,a5,91,8a,80) +#define SD_MESSAGE_CANT_BREAK_ORDERING_CYCLE_STR SD_ID128_MAKE_STR(b3,11,2d,da,d1,90,45,53,8c,76,68,5b,a5,91,8a,80) + _SD_END_DECLARATIONS; #endif From fe458ad68e2813823c381c4010bad201f5e2c2be Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 18 Jun 2025 11:48:39 +0200 Subject: [PATCH 3/6] core: change ordering cycle log message log levels Let's downgrade the log message about our attempts to deal with an ordering cycle to warning, because this is a "positive" thing, we try to improve an earlier error. OTOH increase the log level when we first log about the cycle to error, since that highlights the actual problem. --- src/core/transaction.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/core/transaction.c b/src/core/transaction.c index 8962bf9461..88ff455a01 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -411,7 +411,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi /* logging for j not k here to provide a consistent narrative */ if (cycle_path_text) - log_struct(LOG_WARNING, + log_struct(LOG_ERR, LOG_UNIT_MESSAGE(j->unit, "%s", cycle_path_text), LOG_MESSAGE_ID(SD_MESSAGE_UNIT_ORDERING_CYCLE_STR), LOG_ITEM("%s", strna(unit_ids))); @@ -419,7 +419,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi if (delete) { const char *status; /* logging for j not k here to provide a consistent narrative */ - log_struct(LOG_ERR, + log_struct(LOG_WARNING, LOG_UNIT_MESSAGE(j->unit, "Job %s/%s deleted to break ordering cycle starting with %s/%s", delete->unit->id, job_type_to_string(delete->type), From 6650e21349273a5274ce00d689ed881d2976a6e7 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 18 Jun 2025 11:51:45 +0200 Subject: [PATCH 4/6] core: cast log_oom() got void --- src/core/transaction.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/transaction.c b/src/core/transaction.c index 88ff455a01..84de9000c3 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -384,7 +384,7 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi /* For logging below */ if (strv_push_pair(&array, k->unit->id, (char*) job_type_to_string(k->type)) < 0) - log_oom(); + (void) log_oom_warning(); if (!delete && hashmap_contains(tr->jobs, k->unit) && !job_matters_to_anchor(k)) /* Ok, we can drop this one, so let's do so. */ From becbd2ec4e00aafb656ebc4b2977c1f62adc2ee8 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Thu, 19 Jun 2025 10:15:35 +0200 Subject: [PATCH 5/6] core: when removing a job from a transaction, include in structured log message which --- src/core/transaction.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/core/transaction.c b/src/core/transaction.c index 84de9000c3..1fe3c950e2 100644 --- a/src/core/transaction.c +++ b/src/core/transaction.c @@ -425,6 +425,8 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi delete->unit->id, job_type_to_string(delete->type), j->unit->id, job_type_to_string(j->type)), LOG_MESSAGE_ID(SD_MESSAGE_DELETING_JOB_BECAUSE_ORDERING_CYCLE_STR), + LOG_ITEM("DELETED_UNIT=%s", delete->unit->id), + LOG_ITEM("DELETED_TYPE=%s", job_type_to_string(delete->type)), LOG_ITEM("%s", strna(unit_ids))); if (log_get_show_color()) From e4003f2d9cb93d09d99b87a3d2f68cb0889ecbe8 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Thu, 19 Jun 2025 10:15:49 +0200 Subject: [PATCH 6/6] catalog: add entries for the order cycle log messages Fixes: #35642 --- catalog/systemd.catalog.in | 52 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 52 insertions(+) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 5b22b3b7ff..f7ef980962 100644 --- a/catalog/systemd.catalog.in +++ b/catalog/systemd.catalog.in @@ -914,3 +914,55 @@ problems. If watchdog support is configured, but the watchdog hardware cannot be opened the system will not be protected by the watchdog logic. + +-- f27a3f94406a4783b946a9bc849e9452 +Subject: Unit ordering cycle found +Defined-By: systemd +Support: %SUPPORT_URL% +Documentation: man:systemd(1) + +A unit transaction was initiated that contains an ordering cycle, i.e. some +unit that was requested to be started (either directly, or indirectly due to a +requirement dependency such as Wants= or Requires=) is ordered before some +other unit (via After=/Before=), but that latter unit is also ordered before +the former by some dependency (either directly or indirectly). + +Ordering cycles consist of at least two units, but might involve many +more. They generally indicate a bug in the unit definitions, as a unit +conceptually cannot be run both before and after some other unit, it must be +strictly ordered either before or after. + +The ordering cycle is shown in the log message. An attempt will be made to +remove unit jobs from the transaction in order to make the transaction succeed +at least partially. Note that such cycle breaking is not going to correct the +issue, it is just an attempt to make the outcome less problematic. + +The correct fix is to analyze the cycle in question and then break the cycle at +the right place by removing the right After= or Before= lines from one or more +of the involved unit files. + +-- 5084367542f7472dbc6a94125d5debce +Subject: Unit job deleted due to an ordering cycle +Defined-By: systemd +Support: %SUPPORT_URL% +Documentation: man:systemd(1) + +In order to address an ordering cycle between units that have been added to a +transaction a job has been removed from the transaction. + +The removed job is '@DELETED_TYPE@' for unit @DELETED_UNIT@. + +The removal of the job is done in order to minimize the negative effect of an +ordering cycle — it is not going to fix the underlying problem, which is a bug +in the involved unit files. The deleted job might be fundamental for the other +units in the transaction to operate, which hence might fail. + +-- b3112ddad19045538c76685ba5918a80 +Subject: Unable to break ordering cycle between units +Defined-By: systemd +Support: %SUPPORT_URL% +Documentation: man:systemd(1) + +It has been attempted to break an ordering cycle between units for which jobs +have been enqueued as part of a transaction, but this was not successful. The +transaction will fail.