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

.github/workflows/macos.yaml

@@ -52,20 +52,19 @@ jobs:
           export CPATH=/opt/homebrew/include
           export LIBRARY_PATH=/opt/homebrew/lib
 
-          uv run ./configure --disable-valgrind --disable-compat
+          uv run ./configure --disable-valgrind --disable-compat --disable-rust
           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=30 -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: |
+          # delete_me: serial (-n 1) to test whether the flake is load/concurrency
+          # dependent; 20 sequential attempts, new diagnostics capture errno/fd.
           VALGRIND=0 uv run pytest $PYTEST_TESTS -n $(sysctl -n hw.ncpu) ${PYTEST_OPTS}

channeld/channeld.c

@@ -210,12 +210,19 @@ 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));
+		diag_hsm_socket(HSM_FD);
 		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);
-}
+}

common/peer_io.c

@@ -5,6 +5,8 @@
 #include <common/per_peer_state.h>
 #include <common/status.h>
 #include <wire/wire_sync.h>
+#include <errno.h>
+#include <string.h>
 
 void peer_write(struct per_peer_state *pps, const void *msg TAKES)
 {
@@ -18,8 +20,14 @@ void peer_write(struct per_peer_state *pps, const void *msg TAKES)
 u8 *peer_read(const tal_t *ctx, struct per_peer_state *pps)
 {
 	u8 *msg = wire_sync_read(ctx, pps->peer_fd);
-	if (!msg)
+	if (!msg) {
+		/* macOS flake diagnosis: capture why the peer connection died
+		 * (errno 0 = EOF, i.e. the other end was closed). */
+		int err = errno;
+		status_debug("peer_read failed on peer_fd %i: %s (errno %i)",
+			     pps->peer_fd, strerror(err), err);
 		peer_failed_connection_lost();
+	}
 
 	status_peer_io(LOG_IO_IN, NULL, msg);
 

common/status.c

@@ -10,6 +10,8 @@
 #include <common/utils.h>
 #include <common/version.h>
 #include <errno.h>
+#include <inttypes.h>
+#include <sys/stat.h>
 #include <wire/peer_wire.h>
 #include <wire/wire_sync.h>
 
@@ -183,6 +185,18 @@ void status_send_fd(int fd)
 	fdpass_send(status_fd, fd);
 }
 
+void diag_hsm_socket(int fd)
+{
+	struct stat st;
+
+	if (fstat(fd, &st) == 0)
+		status_debug("hsm diag: fd %i st_dev=%ju st_ino=%ju",
+			     fd, (uintmax_t)st.st_dev, (uintmax_t)st.st_ino);
+	else
+		status_debug("hsm diag: fd %i fstat failed: %s",
+			     fd, strerror(errno));
+}
+
 void status_send_fatal(const u8 *msg TAKES)
 {
 	int reason = fromwire_peektype(msg);

common/status.h

@@ -96,4 +96,9 @@ void status_send_fd(int fd);
 /* Print BROKEN status: callback for dump_memleak. */
 void memleak_status_broken(void *unused, const char *fmt, ...);
 
+/* macOS flake diagnosis: log the socket identity (st_dev:st_ino) of an HSM
+ * fd.  Both ends of a socketpair share st_ino, so we can tell whether the
+ * subdaemon's HSM_FD and hsmd's client are really the same socket. */
+void diag_hsm_socket(int fd);
+
 #endif /* LIGHTNING_COMMON_STATUS_H */

connectd/connectd.c

@@ -105,6 +105,9 @@ static struct connecting *find_connecting(struct daemon *daemon,
 /*~ When we free a peer, we remove it from the daemon's hashtable. */
 static void destroy_peer(struct peer *peer)
 {
+	/* macOS flake diagnosis: log every peer we drop, so we can correlate
+	 * a subdaemon's peer-EOF with connectd tearing down that peer. */
+	status_peer_debug(&peer->id, "connectd dropping peer");
 	if (!peer_htable_del(peer->daemon->peers, peer))
 		abort();
 }

hsmd/hsmd.c

@@ -176,6 +176,14 @@ 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", conn fd %i, for %s",
+		     c->dbid, io_conn_fd(c->conn),
+		     node_id_valid(&c->id) ? fmt_node_id(tmpctx, &c->id) : "(none)");
+	diag_hsm_socket(io_conn_fd(c->conn));
+
 	if (!uintmap_del(&clients, c->dbid))
 		status_failed(STATUS_FAIL_INTERNAL_ERROR,
 			      "Failed to remove client dbid %"PRIu64, c->dbid);
@@ -235,8 +243,11 @@ static struct client *new_client(const tal_t *ctx,
 		struct client *old_client = uintmap_get(&clients, dbid);
 
 		/* Close conn and free any old client of this dbid. */
-		if (old_client)
+		if (old_client) {
+			status_debug("new_client dbid %"PRIu64": closing old client conn fd %i",
+				     dbid, io_conn_fd(old_client->conn));
 			io_close(old_client->conn);
+		}
 
 		if (!uintmap_add(&clients, dbid, c))
 			status_failed(STATUS_FAIL_INTERNAL_ERROR,
@@ -618,7 +629,10 @@ static struct io_plan *pass_client_hsmfd(struct io_conn *conn,
 			      strerror(errno));
 
 	status_debug("new_client: %"PRIu64, dbid);
+	status_debug("hsmfd pair for dbid %"PRIu64": hsmd fds[0]=%i fds[1]=%i",
+		     dbid, fds[0], fds[1]);
 	new_client(c, c->chainparams, &id, dbid, capabilities, fds[0]);
+	diag_hsm_socket(fds[0]);
 
 	/*~ We stash this in a global, because we need to get both the fd and
 	 * the client pointer to the callback.  The other way would be to
@@ -731,7 +745,8 @@ static struct io_plan *handle_client(struct io_conn *conn, struct client *c)
 	enum hsmd_wire t = fromwire_peektype(c->msg_in);
 
 	if (!is_lightningd(c))
-		status_peer_debug(&c->id, "Got %s", hsmd_wire_name(t));
+		status_peer_debug(&c->id, "Got %s on fd %i",
+				  hsmd_wire_name(t), io_conn_fd(conn));
 
 	/* Before we do anything else, is this client allowed to do
 	 * what he asks for? */

lightningd/channel_control.c

@@ -1781,6 +1781,11 @@ bool peer_start_channeld(struct channel *channel,
 				      "Failed to get hsm fd");
 		return false;
 	}
+	/* macOS flake diagnosis: log the fd numbers handed to channeld at the
+	 * openingd->channeld handoff, so we can spot an fd collision with
+	 * the old (openingd) HSM fd being torn down. */
+	log_debug(channel->log, "spawning channeld: hsmfd %i, peer_fd %i",
+		  hsmfd, peer_fd->fd);
 
 	/* At this point, we can forward via alias scid, at least. */
 	tell_connectd_scid(ld, *channel->alias[LOCAL], &channel->peer->id);

lightningd/hsm_control.c

@@ -13,7 +13,9 @@
 #include <lightningd/hsm_control.h>
 #include <lightningd/jsonrpc.h>
 #include <lightningd/lightningd.h>
+#include <lightningd/log.h>
 #include <lightningd/subd.h>
+#include <inttypes.h>
 #include <wally_bip32.h>
 #include <wire/wire_sync.h>
 
@@ -29,7 +31,15 @@ static int hsm_get_fd(struct lightningd *ld,
 	if (!fromwire_hsmd_client_hsmfd_reply(msg))
 		fatal("Bad reply from HSM: %s", tal_hex(tmpctx, msg));
 
-	return fdpass_recv(ld->hsm_fd);
+	/* macOS flake diagnosis: the fd lightningd actually received for this
+	 * client, so we can reconcile it against hsmd's fds[1] and the
+	 * subdaemon's HSM_FD (suspect fd cross-wiring on macOS). */
+	{
+		int recvfd = fdpass_recv(ld->hsm_fd);
+		log_debug(ld->log, "hsm_get_fd: dbid %"PRIu64" received fd %i",
+			  dbid, recvfd);
+		return recvfd;
+	}
 }
 
 int hsm_get_client_fd(struct lightningd *ld,

openingd/openingd.c

@@ -1488,10 +1488,13 @@ int main(int argc, char *argv[])
 	msg = wire_sync_read(tmpctx, HSM_FD);
 	if (!fromwire_hsmd_get_per_commitment_point_reply(tmpctx, msg,
 							 &state->first_per_commitment_point[LOCAL],
-							 &none))
+							 &none)) {
+		diag_hsm_socket(HSM_FD);
 		status_failed(STATUS_FAIL_HSM_IO,
 			      "Bad get_per_commitment_point_reply %s",
 			      tal_hex(tmpctx, msg));
+	}
+
 	/*~ The HSM gives us the N-2'th per-commitment secret when we get the
 	 * N'th per-commitment point.  But since N=0, it won't give us one. */
 	assert(none == NULL);