diff --git a/.github/workflows/macos.yaml b/.github/workflows/macos.yaml index e5f96dc6382c..1bfebaadd1c1 100644 --- a/.github/workflows/macos.yaml +++ b/.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} diff --git a/channeld/channeld.c b/channeld/channeld.c index 3848f0d2e837..4ab087172808 100644 --- a/channeld/channeld.c +++ b/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; } diff --git a/closingd/simpleclosed.c b/closingd/simpleclosed.c index ab1e8dccc9cc..167669dc17ed 100644 --- a/closingd/simpleclosed.c +++ b/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; } diff --git a/common/ecdh_hsmd.c b/common/ecdh_hsmd.c index 68be59841eb2..9952ab8fd98e 100644 --- a/common/ecdh_hsmd.c +++ b/common/ecdh_hsmd.c @@ -1,31 +1,98 @@ #include "config.h" +#include #include -#include #include #include +#include #include +#include #include +#include +#include #include 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); -} +} \ No newline at end of file diff --git a/common/peer_io.c b/common/peer_io.c index 79812b77f589..8e308c1aa7b4 100644 --- a/common/peer_io.c +++ b/common/peer_io.c @@ -5,6 +5,8 @@ #include #include #include +#include +#include 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); diff --git a/common/status.c b/common/status.c index 7de0ebdfa6f7..de63149ba9e8 100644 --- a/common/status.c +++ b/common/status.c @@ -10,6 +10,8 @@ #include #include #include +#include +#include #include #include @@ -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); diff --git a/common/status.h b/common/status.h index fb2cad77ae01..de6510324291 100644 --- a/common/status.h +++ b/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 */ diff --git a/connectd/connectd.c b/connectd/connectd.c index cb95ef9b0cac..e861f649b5b4 100644 --- a/connectd/connectd.c +++ b/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(); } diff --git a/hsmd/hsmd.c b/hsmd/hsmd.c index 739a148bda66..d429da08a6e5 100644 --- a/hsmd/hsmd.c +++ b/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? */ diff --git a/lightningd/channel_control.c b/lightningd/channel_control.c index 202f0103990e..f9ac31f47b95 100644 --- a/lightningd/channel_control.c +++ b/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); diff --git a/lightningd/hsm_control.c b/lightningd/hsm_control.c index d7acaeafdc35..3e1b1a06df2e 100644 --- a/lightningd/hsm_control.c +++ b/lightningd/hsm_control.c @@ -13,7 +13,9 @@ #include #include #include +#include #include +#include #include #include @@ -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, diff --git a/openingd/openingd.c b/openingd/openingd.c index 52e50572e2e0..94923f8cafb6 100644 --- a/openingd/openingd.c +++ b/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);