common: guard ecdh() against HSM fd being non-blocking

.github/workflows/macos.yaml

@@ -56,16 +56,13 @@ jobs:
           uv run gmake
           uv run gmake check-gen-updated
           sudo gmake install
+          uv pip install pytest-flakefinder
 
       - name: Run pytest
         env:
           SLOW_MACHINE: 1
-          PYTEST_OPTS: "-vvv --timeout=1800 --durations=10"
+          PYTEST_OPTS: "--flake-finder --flake-runs=20 -vvv --timeout=60 --durations=10"
           PYTEST_TESTS: |
-            tests/test_misc.py::test_ipv4_and_ipv6
-            tests/test_misc.py::test_low_fd_limit
             tests/test_connection.py::test_websocket
-            tests/test_connection.py::test_wss_proxy
-            tests/test_plugin.py::test_inline_plugin_wait_for_log_no_selfmatch
         run: |
           VALGRIND=0 uv run pytest $PYTEST_TESTS -n $(sysctl -n hw.ncpu) ${PYTEST_OPTS}

channeld/channeld.c

@@ -210,12 +210,18 @@ const u8 *hsm_req(const tal_t *ctx, const u8 *req TAKES)
 	u8 *msg;
 
 	/* hsmd goes away at shutdown.  That's OK. */
-	if (!wire_sync_write(HSM_FD, req))
+	if (!wire_sync_write(HSM_FD, req)) {
+		status_broken("hsm_req: write to HSM failed (fd %i): %s",
+			      HSM_FD, strerror(errno));
 		exit(0);
+	}
 
 	msg = wire_sync_read(ctx, HSM_FD);
-	if (!msg)
+	if (!msg) {
+		status_broken("hsm_req: read from HSM failed (fd %i): %s",
+			      HSM_FD, strerror(errno));
 		exit(0);
+	}
 
 	return msg;
 }

closingd/simpleclosed.c

@@ -44,13 +44,13 @@ static const u8 *hsm_req(const tal_t *ctx, const u8 *req TAKES)
 	u8 *msg;
 	if (!wire_sync_write(HSM_FD, req))
 		status_failed(STATUS_FAIL_HSM_IO,
-			"Writing to HSM: %s",
-			strerror(errno));
+			"Writing to HSM (fd %i): %s",
+			HSM_FD, strerror(errno));
 	msg = wire_sync_read(ctx, HSM_FD);
 	if (!msg)
 		status_failed(STATUS_FAIL_HSM_IO,
-			"Reading from HSM: %s",
-			strerror(errno));
+			"Reading from HSM (fd %i): %s",
+			HSM_FD, strerror(errno));
 	return msg;
 }
 

common/ecdh_hsmd.c

@@ -1,31 +1,98 @@
 #include "config.h"
+#include <arpa/inet.h>
 #include <assert.h>
-#include <ccan/io/io.h>
 #include <common/ecdh.h>
 #include <common/ecdh_hsmd.h>
+#include <common/status.h>
 #include <common/utils.h>
+#include <errno.h>
 #include <hsmd/hsmd_wiregen.h>
+#include <netinet/in.h>
+#include <sys/socket.h>
 #include <wire/wire_sync.h>
 
 static int stashed_hsm_fd = -1;
 static void (*stashed_failed)(enum status_failreason, const char *fmt, ...);
 
+/* Temporary diagnosis (macOS flake): a subdaemon reads EOF on its HSM fd
+ * while hsmd's client is still alive and never received the request, which
+ * looks like the fd being aliased rather than a streaming error.  Print the
+ * socket identity so we can tell whether it is still hsmd's socketpair
+ * (AF_UNIX) or was recycled as, say, a peer TCP connection (AF_INET:port). */
+static void ecdh_diag_fd(int fd)
+{
+	struct sockaddr_storage ss;
+	socklen_t len = sizeof(ss);
+
+	if (getsockname(fd, (struct sockaddr *)&ss, &len) == 0) {
+		if (ss.ss_family == AF_UNIX)
+			status_debug("ecdh: fd %i local addr is AF_UNIX", fd);
+		else if (ss.ss_family == AF_INET) {
+			struct sockaddr_in *sin = (struct sockaddr_in *)&ss;
+			status_debug("ecdh: fd %i local addr is AF_INET:%u",
+				     fd, ntohs(sin->sin_port));
+		} else
+			status_debug("ecdh: fd %i local addr family %u",
+				     fd, ss.ss_family);
+	} else
+		status_debug("ecdh: fd %i getsockname failed: %s",
+			     fd, strerror(errno));
+
+	len = sizeof(ss);
+	if (getpeername(fd, (struct sockaddr *)&ss, &len) == 0) {
+		if (ss.ss_family == AF_UNIX)
+			status_debug("ecdh: fd %i peer addr is AF_UNIX", fd);
+		else if (ss.ss_family == AF_INET) {
+			struct sockaddr_in *sin = (struct sockaddr_in *)&ss;
+			status_debug("ecdh: fd %i peer addr is AF_INET:%u",
+				     fd, ntohs(sin->sin_port));
+		} else
+			status_debug("ecdh: fd %i peer addr family %u",
+				     fd, ss.ss_family);
+	} else if (errno == ENOTCONN)
+		status_debug("ecdh: fd %i peer addr: not connected", fd);
+	else
+		status_debug("ecdh: fd %i getpeername failed: %s",
+			     fd, strerror(errno));
+}
+
 void ecdh(const struct pubkey *point, struct secret *ss)
 {
 	const u8 *msg = towire_hsmd_ecdh_req(NULL, point);
+	u8 *resp;
 
 	assert(stashed_hsm_fd >= 0);
 	assert(stashed_failed != NULL);
 
-	if (!wire_sync_write(stashed_hsm_fd, take(msg)))
-		stashed_failed(STATUS_FAIL_HSM_IO, "Write ECDH to hsmd failed");
+	/* Report errno and fd so a failure is diagnosable from the daemon log
+	 * (macOS CI flake: intermittent "No hsmd ECDH response", errno 0 =
+	 * EOF). */
+	if (!wire_sync_write(stashed_hsm_fd, take(msg))) {
+		ecdh_diag_fd(stashed_hsm_fd);
+		stashed_failed(STATUS_FAIL_HSM_IO,
+			       "Write ECDH to hsmd failed (fd %i): %s",
+			       stashed_hsm_fd, strerror(errno));
+	}
 
-	msg = wire_sync_read(tmpctx, stashed_hsm_fd);
-	if (!msg)
-		stashed_failed(STATUS_FAIL_HSM_IO, "No hsmd ECDH response");
+	resp = wire_sync_read(tmpctx, stashed_hsm_fd);
+	if (!resp) {
+		ecdh_diag_fd(stashed_hsm_fd);
+		stashed_failed(STATUS_FAIL_HSM_IO,
+			       "No hsmd ECDH response (fd %i): %s",
+			       stashed_hsm_fd, strerror(errno));
+	}
 
-	if (!fromwire_hsmd_ecdh_resp(msg, ss))
-		stashed_failed(STATUS_FAIL_HSM_IO, "Invalid hsmd ECDH response");
+	/* Temporary diagnosis of the macOS flake: if hsmd's reply won't parse,
+	 * dump exactly what we read so we can tell garbage apart from a real
+	 * response (a parse failure that also corrupts the tal header shows up
+	 * as a SIGABRT here rather than this log line). */
+	if (!fromwire_hsmd_ecdh_resp(resp, ss)) {
+		status_debug("ecdh: bad HSM reply (%zu bytes): %s",
+			     tal_bytelen(resp),
+			     tal_hexstr(tmpctx, resp, tal_bytelen(resp)));
+		stashed_failed(STATUS_FAIL_HSM_IO,
+			       "Invalid hsmd ECDH response");
+	}
 }
 
 void ecdh_hsmd_setup(int hsm_fd,
@@ -34,6 +101,4 @@ void ecdh_hsmd_setup(int hsm_fd,
 {
 	stashed_hsm_fd = hsm_fd;
 	stashed_failed = failed;
-	/* Like read_fds in subd.c: don't trust sender's O_NONBLOCK state (issue #9060). */
-	io_fd_block(hsm_fd, true);
-}
+}

hsmd/hsmd.c

@@ -176,6 +176,11 @@ static struct io_plan *client_read_next(struct io_conn *conn, struct client *c)
  * closed by the other end. */
 static void destroy_client(struct client *c)
 {
+	/* Temporary diagnosis of the macOS flake: log when a subdaemon's HSM
+	 * client connection goes away, so we can tell whether hsmd drops it
+	 * (subdaemon then sees EOF on its HSM fd). */
+	status_debug("Destroying client %"PRIu64, c->dbid);
+
 	if (!uintmap_del(&clients, c->dbid))
 		status_failed(STATUS_FAIL_INTERNAL_ERROR,
 			      "Failed to remove client dbid %"PRIu64, c->dbid);