Fix: various: Correctly detect completion of systemd start/stop actions

When systemd receives a StartUnit() or StopUnit() method call, it
returns almost immediately, as soon as a start/stop job is enqueued. A
successful return code does NOT indicate that the start/stop has
finished.

Previously, we worked around this in action_complete() with a hack that
scheduled a follow-up monitor after a successful start/stop method call,
which polled the service after 2 seconds to see whether it was actually
running. However, this was not a robust solution. Timing issues could
result in Pacemaker having an incorrect view of the resource's status or
prematurely declaring the action as failed.

Now, we follow the best practice as documented in the systemd D-Bus API
doc (see StartUnit()):
https://www.freedesktop.org/software/systemd/man/latest/org.freedesktop.systemd1.html#Methods

After kicking off a systemd start/stop action, we make note of the job's
D-Bus object path. Then we register a D-Bus message filter that looks
for a JobRemoved signal whose bus path matches. This signal indicates
that the job has completed and includes its result. When we find the
matching signal, we set the action's result. We then remove the filter,
which causes the action to be finalized and freed. In the case of the
executor daemon, the action has a callback (action_complete()) that runs
during finalization and sets the executor's view of the action result.

Monitor actions still need much of the existing workaround code in
action_complete(), so we keep it for now. We bail out for start/stop
actions after setting the result as described above.

Ref T25

Co-authored-by: Reid Wahl <[email protected]>
Signed-off-by: Reid Wahl <[email protected]>

Author: clumens

daemons/execd/execd_commands.c

@@ -872,14 +872,16 @@ action_complete(svc_action_t * action)
     if (pcmk__result_ok(&(cmd->result))
         && pcmk__strcase_any_of(cmd->action, PCMK_ACTION_START,
                                 PCMK_ACTION_STOP, NULL)) {
-        /* systemd returns from start and stop actions after the action
-         * begins, not after it completes. We have to jump through a few
-         * hoops so that we don't report 'complete' to the rest of pacemaker
-         * until it's actually done.
+        /* Getting results for when a start or stop action completes is now
+         * handled by watching for JobRemoved() signals from systemd and
+         * reacting to them. So, we can bypass the rest of the code in this
+         * function for those actions, and simply finalize cmd.
+         *
+         * @TODO When monitors are handled in the same way, this function
+         * can either be drastically simplified or done away with entirely.
          */
-        goagain = true;
-        cmd->real_action = cmd->action;
-        cmd->action = pcmk__str_copy(PCMK_ACTION_MONITOR);
+        services__copy_result(action, &(cmd->result));
+        goto finalize;
 
     } else if (cmd->result.execution_status == PCMK_EXEC_PENDING &&
                pcmk__str_any_of(cmd->action, PCMK_ACTION_MONITOR, PCMK_ACTION_STATUS, NULL) &&

lib/services/services_private.h

@@ -51,7 +51,7 @@ struct svc_action_private_s {
 #endif
 
 #if SUPPORT_SYSTEMD
-    char *job_path;
+    char *job_path;         // D-Bus object path for enqueued start/stop job
 #endif  // SUPPORT_SYSTEMD
 };
 

lib/services/systemd.c

@@ -14,7 +14,9 @@
 #include <crm/services_internal.h>
 #include <crm/common/mainloop.h>
 
+#include <inttypes.h>               // PRIu32
 #include <stdbool.h>
+#include <stdint.h>                 // uint32_t
 #include <stdio.h>                  // fopen(), NULL, etc.
 #include <sys/stat.h>
 #include <gio/gio.h>
@@ -785,6 +787,8 @@ systemd_unit_metadata(const char *name, int timeout)
 static void
 process_unit_method_reply(DBusMessage *reply, svc_action_t *op)
 {
+    bool start_stop = pcmk__strcase_any_of(op->action, PCMK_ACTION_START,
+                                           PCMK_ACTION_STOP, NULL);
     DBusError error;
 
     dbus_error_init(&error);
@@ -798,11 +802,25 @@ process_unit_method_reply(DBusMessage *reply, svc_action_t *op)
 
     } else if (!pcmk_dbus_type_check(reply, NULL, DBUS_TYPE_OBJECT_PATH,
                                      __func__, __LINE__)) {
+        const char *reason = "systemd D-Bus method had unexpected reply";
+
         crm_info("DBus request for %s of %s succeeded but "
                  "return type was unexpected",
                  op->action, pcmk__s(op->rsc, "unknown resource"));
-        services__set_result(op, PCMK_OCF_OK, PCMK_EXEC_DONE,
-                             "systemd DBus method had unexpected reply");
+
+        if (!op->synchronous && start_stop) {
+            /* The start or stop job is enqueued but is not complete. We need a
+             * job path to detect completion in job_removed_filter().
+             */
+            services__set_result(op, PCMK_OCF_UNKNOWN_ERROR, PCMK_EXEC_ERROR,
+                                 reason);
+
+        } else {
+            /* Something weird happened, but the action is finished and there
+             * was no D-Bus error. So call it a success.
+             */
+            services__set_result(op, PCMK_OCF_OK, PCMK_EXEC_DONE, reason);
+        }
 
     } else {
         const char *path = NULL;
@@ -813,9 +831,114 @@ process_unit_method_reply(DBusMessage *reply, svc_action_t *op)
 
         crm_debug("DBus request for %s of %s using %s succeeded",
                   op->action, pcmk__s(op->rsc, "unknown resource"), path);
-        pcmk__str_update(&(op->opaque->job_path), path);
-        services__set_result(op, PCMK_OCF_OK, PCMK_EXEC_DONE, NULL);
+
+        if (!op->synchronous && start_stop) {
+            // Should be set to unknown/pending already
+            services__set_result(op, PCMK_OCF_UNKNOWN, PCMK_EXEC_PENDING, NULL);
+            pcmk__str_update(&(op->opaque->job_path), path);
+
+        } else {
+            services__set_result(op, PCMK_OCF_OK, PCMK_EXEC_DONE, NULL);
+        }
+    }
+}
+
+/*!
+ * \internal
+ * \brief Process a systemd \c JobRemoved signal for a given service action
+ *
+ * This filter is expected to be added with \c finalize_async_action_dbus() as
+ * the \c free_data_function. Then if \p message is a \c JobRemoved signal for
+ * the action specified by \p user_data, the action's result is set, the filter
+ * is removed, and the action is finalized.
+ *
+ * \param[in,out] connection  D-Bus connection
+ * \param[in]     message     D-Bus message
+ * \param[in,out] user_data   Service action (\c svc_action_t)
+ *
+ * \retval \c DBUS_HANDLER_RESULT_HANDLED if \p message is a \c JobRemoved
+ *         signal for \p user_data
+ * \retval \c DBUS_HANDLER_RESULT_NOT_YET_HANDLED otherwise (on error, if
+ *         \p message is not a \c JobRemoved signal, or if the signal is for
+ *         some other action's job)
+ */
+static DBusHandlerResult
+job_removed_filter(DBusConnection *connection, DBusMessage *message,
+                   void *user_data)
+{
+    svc_action_t *action = user_data;
+    const char *action_name = NULL;
+    uint32_t job_id = 0;
+    const char *bus_path = NULL;
+    const char *unit_name = NULL;
+    const char *result = NULL;
+    DBusError error;
+
+    CRM_CHECK((connection != NULL) && (message != NULL),
+              return DBUS_HANDLER_RESULT_NOT_YET_HANDLED);
+
+    // action should always be set when the filter is added
+    if ((action == NULL)
+        || !dbus_message_is_signal(message, BUS_NAME_MANAGER, "JobRemoved")) {
+        return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
+    }
+
+    dbus_error_init(&error);
+    if (!dbus_message_get_args(message, &error,
+                               DBUS_TYPE_UINT32, &job_id,
+                               DBUS_TYPE_OBJECT_PATH, &bus_path,
+                               DBUS_TYPE_STRING, &unit_name,
+                               DBUS_TYPE_STRING, &result,
+                               DBUS_TYPE_INVALID)) {
+        crm_err("Could not interpret systemd DBus signal: %s " QB_XS " (%s)",
+                error.message, error.name);
+        dbus_error_free(&error);
+        return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
+    }
+
+    if (!pcmk__str_eq(bus_path, action->opaque->job_path, pcmk__str_none)) {
+        // This filter is not for this job
+        return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
     }
+
+    action_name = pcmk__s(action->action, "(unknown)");
+
+    crm_trace("Setting %s result for %s (JobRemoved id=%" PRIu32 ", result=%s",
+              action_name, unit_name, job_id, result);
+
+    if (pcmk__str_eq(result, "done", pcmk__str_none)) {
+        services__set_result(action, PCMK_OCF_OK, PCMK_EXEC_DONE, NULL);
+
+    } else if (pcmk__str_eq(result, "timeout", pcmk__str_none)) {
+        services__format_result(action, PCMK_OCF_UNKNOWN_ERROR, PCMK_EXEC_TIMEOUT,
+                                "systemd %s job for %s timed out",
+                                action_name, unit_name);
+
+    } else {
+        services__format_result(action, PCMK_OCF_UNKNOWN_ERROR, PCMK_EXEC_ERROR,
+                                "systemd %s job for %s failed with result '%s'",
+                                action_name, unit_name, result);
+    }
+
+    /* This instance of the filter was specifically for the given action.
+     *
+     * The action gets finalized by services__finalize_async_op() via the
+     * filter's free_data_function.
+     */
+    dbus_connection_remove_filter(systemd_proxy, job_removed_filter, action);
+    return DBUS_HANDLER_RESULT_HANDLED;
+}
+
+/*!
+ * \internal
+ * \brief \c DBusFreeFunction wrapper for \c services__finalize_async_op()
+ *
+ * \param[in,out] action  Asynchronous service action to finalize
+ */
+static void
+finalize_async_action_dbus(void *action)
+{
+    services__finalize_async_op((svc_action_t *) action);
 }
 
 /*!
@@ -842,12 +965,34 @@ unit_method_complete(DBusPendingCall *pending, void *user_data)
     CRM_LOG_ASSERT(pending == op->opaque->pending);
     services_set_op_pending(op, NULL);
 
-    // Determine result and finalize action
     process_unit_method_reply(reply, op);
-    services__finalize_async_op(op);
+
     if (reply != NULL) {
         dbus_message_unref(reply);
     }
+
+    if ((op->status == PCMK_EXEC_PENDING)
+        && pcmk__strcase_any_of(op->action, PCMK_ACTION_START, PCMK_ACTION_STOP,
+                                NULL)) {
+        /* Start and stop method calls return when the job is enqueued, not when
+         * it's complete. Start and stop actions must be finalized after the job
+         * is complete, because the action callback function may use it. We add
+         * a message filter to process the JobRemoved signal, which indicates
+         * completion.
+         *
+         * The filter takes ownership of op, which will be finalized when the
+         * filter is later removed.
+         */
+        if (dbus_connection_add_filter(systemd_proxy, job_removed_filter, op,
+                                       finalize_async_action_dbus)) {
+            return;
+        }
+        crm_err("Could not add D-Bus filter for systemd JobRemoved signals");
+        services__set_result(op, PCMK_OCF_UNKNOWN_ERROR, PCMK_EXEC_ERROR,
+                             "Failed to add D-Bus filter for systemd "
+                             "JobRemoved signal");
+    }
+    services__finalize_async_op(op);
 }
 
 /* When the cluster manages a systemd resource, we create a unit file override
@@ -1193,7 +1338,14 @@ systemd_timeout_callback(gpointer p)
     services__format_result(op, PCMK_OCF_UNKNOWN_ERROR, PCMK_EXEC_TIMEOUT,
                             "%s action for systemd unit %s "
                             "did not complete in time", op->action, op->agent);
-    services__finalize_async_op(op);
+
+    if (op->opaque->job_path != NULL) {
+        // A filter owns this op
+        dbus_connection_remove_filter(systemd_proxy, job_removed_filter, op);
+
+    } else {
+        services__finalize_async_op(op);
+    }
     return FALSE;
 }
 
@@ -1247,6 +1399,7 @@ services__execute_systemd(svc_action_t *op)
                          "Bug in service library");
 
     if (invoke_unit_by_name(op->agent, op, NULL) == pcmk_rc_ok) {
+        // @TODO Why plus 5000? No explanation in fccd046.
         op->opaque->timerid = pcmk__create_timer(op->timeout + 5000,
                                                  systemd_timeout_callback, op);
         services_add_inflight_op(op);