Merge pull request #6623 from garlick/issue#6621

log helpful info when shutdown is stuck

Author: mergify[bot]

src/broker/overlay.c

@@ -372,6 +372,24 @@ int overlay_get_child_peer_count (struct overlay *ov)
     return count;
 }
 
+struct idset *overlay_get_child_peer_idset (struct overlay *ov)
+{
+    struct idset *ids;
+    struct child *child;
+
+    if (!(ids = idset_create (ov->size, 0)))
+        return NULL;
+    foreach_overlay_child (ov, child) {
+        if (subtree_is_online (child->status))
+            if (idset_set (ids, child->rank) < 0)
+                goto error;
+    }
+    return ids;
+error:
+    idset_destroy (ids);
+    return NULL;
+}
+
 void overlay_set_ipv6 (struct overlay *ov, int enable)
 {
     ov->enable_ipv6 = enable;
@@ -945,6 +963,17 @@ static void child_cb (flux_reactor_t *r,
         goto done;
     }
     if (!(child = child_lookup_online (ov, uuid))) {
+        bool is_hello = false;
+        json_int_t rank = FLUX_NODEID_ANY;
+
+        if (type == FLUX_MSGTYPE_REQUEST
+            && flux_msg_get_topic (msg, &topic) == 0
+            && streq (topic, "overlay.hello")) {
+            // extract the hello rank so we can include it in the trace
+            (void)flux_request_unpack (msg, NULL, "{s:I}", "rank", &rank);
+            is_hello = true;
+        }
+        trace_overlay_msg (ov->h, "rx", rank, ov->trace_requests, msg);
         /* This is a new peer trying to introduce itself by sending an
          * overlay.hello request.
          * N.B. the broker generates a new UUID on startup, and hello is only
@@ -953,15 +982,7 @@ static void child_cb (flux_reactor_t *r,
          * we don't bother checking if we've seen this UUID before, which can
          * be slow given current design.  See flux-framework/flux-core#5864.
          */
-        if (type == FLUX_MSGTYPE_REQUEST
-            && flux_msg_get_topic (msg, &topic) == 0
-            && streq (topic, "overlay.hello")
-            && !ov->shutdown_in_progress) {
-            trace_overlay_msg (ov->h,
-                               "rx",
-                               FLUX_NODEID_ANY,
-                               ov->trace_requests,
-                               msg);
+        if (is_hello && !ov->shutdown_in_progress) {
             hello_request_handler (ov, msg);
         }
         /* Or one of the following cases occurred that requires (or at least

src/broker/overlay.h

@@ -95,6 +95,7 @@ uint32_t overlay_get_rank (struct overlay *ov);
 void overlay_set_rank (struct overlay *ov, uint32_t rank); // test only
 uint32_t overlay_get_size (struct overlay *ov);
 int overlay_get_child_peer_count (struct overlay *ov);
+struct idset *overlay_get_child_peer_idset (struct overlay *ov);
 const char *overlay_get_bind_uri (struct overlay *ov);
 const char *overlay_get_parent_uri (struct overlay *ov);
 int overlay_set_parent_uri (struct overlay *ov, const char *uri);
@@ -148,6 +149,7 @@ int overlay_connect (struct overlay *ov);
  * The following accessors may be useful in the callback:
  * - overlay_parent_error() - test whether TBON parent connection has failed
  * - overlay_get_child_peer_count() - number of online children
+ * - overlay_get_child_peer_idset () - set of online children
  * - overlay_get_subtree_status (rank) - subtree status of child
  * - overlay_get_subtree_topo (rank) - topology of subtree rooted at child
  */

src/broker/state_machine.c

@@ -54,6 +54,11 @@ struct cleanup {
     flux_watcher_t *timer;
 };
 
+struct shutdown {
+    double timeout;
+    flux_watcher_t *timer;
+};
+
 struct monitor {
     struct flux_msglist *requests;
 
@@ -78,6 +83,7 @@ struct state_machine {
     struct monitor monitor;
     struct quorum quorum;
     struct cleanup cleanup;
+    struct shutdown shutdown;
 
     struct flux_msglist *wait_requests;
 
@@ -159,6 +165,7 @@ static struct state_next nexttab[] = {
 };
 
 static const double default_quorum_timeout = 60; // log slow joiners
+static const double default_shutdown_timeout = 60; // log slow shutdown
 static const double default_cleanup_timeout = -1;
 static const double goodbye_timeout = 60;
 
@@ -424,17 +431,49 @@ static void action_finalize (struct state_machine *s)
         state_machine_post (s, "rc3-none");
 }
 
+static void shutdown_timer_cb (flux_reactor_t *r,
+                               flux_watcher_t *w,
+                               int revents,
+                               void *arg)
+{
+    struct state_machine *s = arg;
+    struct idset *ranks = overlay_get_child_peer_idset (s->ctx->overlay);
+    char *rankstr = idset_encode (ranks, IDSET_FLAG_RANGE);
+    char *hoststr = flux_hostmap_lookup (s->ctx->h, rankstr, NULL);
+
+    flux_log (s->ctx->h,
+              LOG_ERR,
+              "shutdown delayed: waiting for %d peers: %s (rank %s)",
+              overlay_get_child_peer_count (s->ctx->overlay),
+              hoststr ? hoststr : "?",
+              rankstr ? rankstr : "?");
+
+    free (hoststr);
+    free (rankstr);
+    idset_destroy (ranks);
+
+    flux_timer_watcher_reset (w, s->shutdown.timeout, 0.);
+    flux_watcher_start (w);
+}
+
+
 static void action_shutdown (struct state_machine *s)
 {
-    if (overlay_get_child_peer_count (s->ctx->overlay) == 0)
+    if (overlay_get_child_peer_count (s->ctx->overlay) == 0) {
         state_machine_post (s, "children-none");
+        return;
+    }
 #if HAVE_LIBSYSTEMD
     if (s->ctx->sd_notify) {
         sd_notifyf (0,
                     "STATUS=Waiting for %d peers to shutdown",
                     overlay_get_child_peer_count (s->ctx->overlay));
     }
 #endif
+    if (s->shutdown.timeout >= 0) {
+        flux_timer_watcher_reset (s->shutdown.timer, s->shutdown.timeout, 0.);
+        flux_watcher_start (s->shutdown.timer);
+    }
 }
 
 static void goodbye_continuation (flux_future_t *f, void *arg)
@@ -1144,6 +1183,7 @@ static void overlay_monitor_cb (struct overlay *overlay,
                                 void *arg)
 {
     struct state_machine *s = arg;
+    int count;
 
     switch (s->state) {
         /* IN JOIN state, post parent-fail if something goes wrong with the
@@ -1166,8 +1206,21 @@ static void overlay_monitor_cb (struct overlay *overlay,
          * node) the exit event is posted immediately in action_shutdown().
          */
         case STATE_SHUTDOWN:
-            if (overlay_get_child_peer_count (overlay) == 0)
+            count = overlay_get_child_peer_count (overlay);
+            if (count == 0) {
                 state_machine_post (s, "children-complete");
+                flux_watcher_stop (s->shutdown.timer);
+            }
+#if HAVE_LIBSYSTEMD
+            else {
+                if (s->ctx->sd_notify) {
+                    sd_notifyf (0,
+                                "STATUS=Waiting for %d peer%s to shutdown",
+                                count,
+                                count > 1 ? "s" : "");
+                }
+            }
+#endif
             break;
         default:
             break;
@@ -1255,6 +1308,7 @@ void state_machine_destroy (struct state_machine *s)
         flux_watcher_destroy (s->quorum.timer);
         flux_future_destroy (s->quorum.f);
         flux_watcher_destroy (s->cleanup.timer);
+        flux_watcher_destroy (s->shutdown.timer);
         free (s);
         errno = saved_errno;
     }
@@ -1289,7 +1343,12 @@ struct state_machine *state_machine_create (struct broker *ctx)
                                                            0.,
                                                            0.,
                                                            cleanup_timer_cb,
-                                                           s)))
+                                                           s))
+        || !(s->shutdown.timer = flux_timer_watcher_create (r,
+                                                            0.,
+                                                            0.,
+                                                            shutdown_timer_cb,
+                                                            s)))
         goto error;
     flux_watcher_start (s->prep);
     flux_watcher_start (s->check);
@@ -1320,6 +1379,13 @@ struct state_machine *state_machine_create (struct broker *ctx)
         log_err ("error configuring cleanup timeout attribute");
         goto error;
     }
+    if (timeout_configure (s,
+                           "broker.shutdown-timeout",
+                           &s->shutdown.timeout,
+                           default_shutdown_timeout) < 0) {
+        log_err ("error configuring shutdown timeout attribute");
+        goto error;
+    }
     norestart_configure (s);
     overlay_set_monitor_cb (ctx->overlay, overlay_monitor_cb, s);
     if (s->ctx->rank == 0) {

t/t0025-broker-state-machine.t

@@ -334,4 +334,26 @@ test_expect_success 'cleanup gets SIGHUP after broker.cleanup-timeout expires' '
 		./killbroker 15 60
 '
 
+test_expect_success 'create hanging rc3 for rank > 0' '
+	cat <<-EOT >rc3_hang &&
+	#!/bin/sh
+	rank=\$(flux getattr rank)
+	test \$rank -eq 0 && exit 0
+	sleep 5
+	EOT
+	chmod +x rc3_hang
+'
+
+test_expect_success 'run instance with short shutdown timeout' '
+	flux start -s3 \
+		-Slog-filename=shutdown.log \
+		-Sbroker.rc1_path= \
+		-Sbroker.rc3_path="$(pwd)/rc3_hang" \
+		-Sbroker.shutdown-timeout=1s \
+		true
+'
+test_expect_success 'appropriate message was logged' '
+	grep "shutdown delayed" shutdown.log
+'
+
 test_done