core: turn ordering cycle log message into a recognizable one + catalog entry (#37893)

Fixes: #35642

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.

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"
@@ -383,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. */
@@ -396,23 +397,36 @@ 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 */
-                        log_struct(LOG_WARNING,
-                                   LOG_UNIT_MESSAGE(j->unit,
-                                                    "Found %s on %s/%s",
-                                                    unit_id == array ? "ordering cycle" : "dependency",
-                                                    *unit_id, *job_type),
+                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_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)));
 
                 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),
                                                     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())
@@ -432,6 +446,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,

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