diff --git a/connectd/connectd.c b/connectd/connectd.c index c6e06a585..d7a2d2340 100644 --- a/connectd/connectd.c +++ b/connectd/connectd.c @@ -76,7 +76,8 @@ static void try_connect_one_addr(struct connecting *connect); * timer to call a higher function again, so has to be pre-declared. */ static void try_connect_peer(struct daemon *daemon, const struct node_id *id, - struct wireaddr_internal *addrs TAKES); + struct wireaddr_internal *addrs TAKES, + const char *reason); /* We track peers which are important, and try to reconnect (with backoff) */ static void schedule_reconnect_if_important(struct daemon *daemon, @@ -290,6 +291,8 @@ struct io_plan *peer_connected(struct io_conn *conn, int subd_fd; bool option_gossip_queries; struct connecting *connect; + const char *connect_reason; + u64 connect_time_nsec; u64 prev_connectd_counter; /* We remove any previous connection immediately, on the assumption it's dead */ @@ -358,7 +361,16 @@ struct io_plan *peer_connected(struct io_conn *conn, * in progress right now) */ if (connect->conn) io_set_finish(connect->conn, NULL, NULL); + if (incoming) + connect_reason = "incoming connection while trying to connect"; + else + connect_reason = tal_steal(tmpctx, connect->reason); + connect_time_nsec = time_to_nsec(timemono_since(connect->start)); tal_free(connect); + } else { + assert(incoming); + connect_reason = "incoming connection"; + connect_time_nsec = 0; } /* This contains the per-peer state info; gossipd fills in pps->gs */ @@ -394,7 +406,9 @@ struct io_plan *peer_connected(struct io_conn *conn, msg = towire_connectd_peer_connected(NULL, id, peer->counter, addr, remote_addr, - incoming, their_features); + incoming, their_features, + connect_reason, + connect_time_nsec); } /*~ daemon_conn is a message queue for inter-daemon communication: we @@ -761,9 +775,11 @@ struct io_plan *connection_out(struct io_conn *conn, struct connecting *connect) */ static void connect_failed(struct daemon *daemon, const struct node_id *id, + const char *connect_reason, + struct timemono start, enum jsonrpc_errcode errcode, const char *errfmt, ...) - PRINTF_FMT(4,5); + PRINTF_FMT(6, 7); static void reconnect(struct important_id *imp) { @@ -775,7 +791,8 @@ static void reconnect(struct important_id *imp) append_gossmap_addresses(&addrs, imp->daemon, &imp->id); imp->reconnect_timer = NULL; - try_connect_peer(imp->daemon, &imp->id, take(addrs)); + try_connect_peer(imp->daemon, &imp->id, take(addrs), + "reconnect by timer"); } static void schedule_reconnect_if_important(struct daemon *daemon, @@ -825,6 +842,7 @@ void release_one_waiting_connection(struct daemon *daemon, const char *why) if (c->waiting) { status_peer_debug(&c->id, "Unblocking for %s", why); c->waiting = false; + c->start = time_mono(); try_connect_one_addr(c); break; } @@ -833,6 +851,8 @@ void release_one_waiting_connection(struct daemon *daemon, const char *why) static void connect_failed(struct daemon *daemon, const struct node_id *id, + const char *connect_reason, + struct timemono start, enum jsonrpc_errcode errcode, const char *errfmt, ...) { @@ -848,7 +868,10 @@ static void connect_failed(struct daemon *daemon, /* lightningd may have a connect command waiting to know what * happened. */ - msg = towire_connectd_connect_failed(NULL, id, errcode, errmsg); + msg = towire_connectd_connect_failed(NULL, id, + connect_reason, + time_to_nsec(timemono_since(start)), + errcode, errmsg); daemon_conn_send(daemon->master, take(msg)); /* If we're supposed to schedule a reconnect, do so */ @@ -999,9 +1022,11 @@ static void try_connect_one_addr(struct connecting *connect) struct daemon *daemon = connect->daemon; struct node_id id = connect->id; const char *errors = tal_steal(tmpctx, connect->errors); + const char *reason = tal_steal(tmpctx, connect->reason); + struct timemono start = connect->start; tal_free(connect); - connect_failed(daemon, &id, + connect_failed(daemon, &id, reason, start, CONNECT_ALL_ADDRESSES_FAILED, "All addresses failed: %s", errors); @@ -1784,7 +1809,8 @@ static bool addr_in(const struct wireaddr_internal *needle, /*~ Try to connect to a single peer, given some addresses (in order) */ static void try_connect_peer(struct daemon *daemon, const struct node_id *id, - struct wireaddr_internal *addrs TAKES) + struct wireaddr_internal *addrs TAKES, + const char *reason TAKES) { bool use_proxy = daemon->always_use_proxy; struct connecting *connect; @@ -1793,6 +1819,8 @@ static void try_connect_peer(struct daemon *daemon, /* In case we return without using it, make sure it's freed. */ if (taken(addrs)) tal_steal(tmpctx, addrs); + if (taken(reason)) + tal_steal(tmpctx, reason); /* Already existing? Must have crossed over, it'll know soon. */ peer = peer_htable_get(daemon->peers, id); @@ -1831,7 +1859,7 @@ static void try_connect_peer(struct daemon *daemon, /* Still no address? Fail immediately. Important ones get * retried; an address may get gossiped. */ if (tal_count(addrs) == 0) { - connect_failed(daemon, id, + connect_failed(daemon, id, reason, time_mono(), CONNECT_NO_KNOWN_ADDRESS, "Unable to connect, no address known for peer"); return; @@ -1840,6 +1868,7 @@ static void try_connect_peer(struct daemon *daemon, /* Start connecting to it: since this is the only place we allocate * a 'struct connecting' we don't write a separate new_connecting(). */ connect = tal(daemon, struct connecting); + connect->reason = tal_strdup(connect, reason); connect->daemon = daemon; connect->id = *id; connect->addrs = tal_dup_talarr(connect, struct wireaddr_internal, addrs); @@ -1859,8 +1888,10 @@ static void try_connect_peer(struct daemon *daemon, > daemon->max_connect_in_flight); if (connect->waiting) status_peer_debug(id, "Too many connections, waiting..."); - else + else { + connect->start = time_mono(); try_connect_one_addr(connect); + } } static void destroy_important_id(struct important_id *imp) @@ -1875,10 +1906,11 @@ static void connect_to_peer(struct daemon *daemon, const u8 *msg) struct wireaddr_internal *addrs; bool transient; struct important_id *imp; + char *reason; if (!fromwire_connectd_connect_to_peer(tmpctx, msg, &id, &addrs, - &transient)) + &transient, &reason)) master_badmsg(WIRE_CONNECTD_CONNECT_TO_PEER, msg); /* fromwire doesn't allocate empty arrays! */ @@ -1917,7 +1949,7 @@ static void connect_to_peer(struct daemon *daemon, const u8 *msg) /* Do gossmap lookup to find any addresses from there, and append. */ append_gossmap_addresses(&addrs, daemon, &id); - try_connect_peer(daemon, &id, addrs); + try_connect_peer(daemon, &id, addrs, take(reason)); } /* lightningd tells us a peer should be disconnected. */ diff --git a/connectd/connectd.h b/connectd/connectd.h index 09778e2d5..7da8a71c4 100644 --- a/connectd/connectd.h +++ b/connectd/connectd.h @@ -203,6 +203,12 @@ struct connecting { /* How far did we get? */ const char *connstate; + /* Why are we connecting? */ + const char *reason; + + /* When did we start? */ + struct timemono start; + /* Accumulated errors */ char *errors; }; diff --git a/connectd/connectd_wire.csv b/connectd/connectd_wire.csv index 78df85efc..c70b901e2 100644 --- a/connectd/connectd_wire.csv +++ b/connectd/connectd_wire.csv @@ -64,10 +64,13 @@ msgdata,connectd_connect_to_peer,id,node_id, msgdata,connectd_connect_to_peer,len,u32, msgdata,connectd_connect_to_peer,addrs,wireaddr_internal,len msgdata,connectd_connect_to_peer,transient,bool, +msgdata,connectd_connect_to_peer,reason,wirestring, # Connectd->master: connect failed. msgtype,connectd_connect_failed,2020 msgdata,connectd_connect_failed,id,node_id, +msgdata,connectd_connect_failed,connect_reason,wirestring, +msgdata,connectd_connect_failed,connect_nsec,u64, msgdata,connectd_connect_failed,failcode,enum jsonrpc_errcode, msgdata,connectd_connect_failed,failreason,wirestring, @@ -80,6 +83,8 @@ msgdata,connectd_peer_connected,remote_addr,?wireaddr, msgdata,connectd_peer_connected,incoming,bool, msgdata,connectd_peer_connected,flen,u16, msgdata,connectd_peer_connected,features,u8,flen +msgdata,connectd_peer_connected,connect_reason,wirestring, +msgdata,connectd_peer_connected,connect_nsec,u64, # connectd -> master: peer disconnected. msgtype,connectd_peer_disconnected,2006 diff --git a/lightningd/connect_control.c b/lightningd/connect_control.c index d42681155..74aef56c5 100644 --- a/lightningd/connect_control.c +++ b/lightningd/connect_control.c @@ -235,7 +235,9 @@ static struct command_result *json_connect(struct command *cmd, peer_channels_cleanup(peer); subd_send_msg(cmd->ld->connectd, - take(towire_connectd_connect_to_peer(NULL, &id_addr.id, addr, true))); + take(towire_connectd_connect_to_peer(NULL, &id_addr.id, + addr, true, + tal_fmt(tmpctx, "connect command %s", cmd->id)))); /* Leave this here for peer_connected, connect_failed or peer_disconnected. */ new_connect(cmd->ld, &id_addr.id, cmd); @@ -252,6 +254,8 @@ AUTODATA(json_command, &connect_command); static void connect_failed(struct lightningd *ld, const struct node_id *id, const struct wireaddr_internal *addrhint, + const char *connect_reason, + u64 connect_nsec, enum jsonrpc_errcode errcode, const char *errmsg) { @@ -268,7 +272,9 @@ void connect_failed_disconnect(struct lightningd *ld, const struct node_id *id, const struct wireaddr_internal *addrhint) { - connect_failed(ld, id, addrhint, CONNECT_DISCONNECTED_DURING, + connect_failed(ld, id, addrhint, + "", 0, + CONNECT_DISCONNECTED_DURING, "disconnected during connection"); } @@ -277,12 +283,17 @@ static void handle_connect_failed(struct lightningd *ld, const u8 *msg) struct node_id id; enum jsonrpc_errcode errcode; char *errmsg; + char *connect_reason; + u64 nsec; - if (!fromwire_connectd_connect_failed(tmpctx, msg, &id, &errcode, &errmsg)) + if (!fromwire_connectd_connect_failed(tmpctx, msg, &id, + &connect_reason, + &nsec, + &errcode, &errmsg)) fatal("Connect gave bad CONNECTD_CONNECT_FAILED message %s", tal_hex(msg, msg)); - connect_failed(ld, &id, NULL, errcode, errmsg); + connect_failed(ld, &id, NULL, connect_reason, nsec, errcode, errmsg); } const char *connect_any_cmd_id(const tal_t *ctx, @@ -422,6 +433,7 @@ void connectd_start_shutdown(struct subd *connectd) void connectd_connect_to_peer(struct lightningd *ld, const struct peer *peer, + const char *reason, bool is_important) { /* Give connectd an address if we know it. */ @@ -435,7 +447,8 @@ void connectd_connect_to_peer(struct lightningd *ld, subd_send_msg(peer->ld->connectd, take(towire_connectd_connect_to_peer(NULL, &peer->id, waddr, - !is_important))); + !is_important, + reason))); } void tell_connectd_peer_importance(struct peer *peer, @@ -453,7 +466,9 @@ void tell_connectd_peer_importance(struct peer *peer, } else if (!was_important && is_important) { /* Tell connectd it's now important (unless we're told not to reconnect) */ if (peer->ld->reconnect) - connectd_connect_to_peer(peer->ld, peer, true); + connectd_connect_to_peer(peer->ld, peer, + "peer established channel", + true); } } diff --git a/lightningd/connect_control.h b/lightningd/connect_control.h index 47f14391d..57b33790d 100644 --- a/lightningd/connect_control.h +++ b/lightningd/connect_control.h @@ -18,6 +18,7 @@ void connectd_start_shutdown(struct subd *connectd); /* Tell connectd to connect to peer: give it what we know. */ void connectd_connect_to_peer(struct lightningd *ld, const struct peer *peer, + const char *reason, bool is_important); /* Kill subds, tell connectd to disconnect once they're drained. */ diff --git a/lightningd/gossip_control.c b/lightningd/gossip_control.c index 6b484a77e..0043de968 100644 --- a/lightningd/gossip_control.c +++ b/lightningd/gossip_control.c @@ -177,7 +177,8 @@ static void handle_connect_to_peer(struct subd *gossip, const u8 *msg) connectmsg = towire_connectd_connect_to_peer(NULL, &id, NULL, //addrhint, - true); //transient + true, //transient + "gossipd"); subd_send_msg(gossip->ld->connectd, take(connectmsg)); } diff --git a/lightningd/peer_control.c b/lightningd/peer_control.c index 59c06c4d9..ae2f017d1 100644 --- a/lightningd/peer_control.c +++ b/lightningd/peer_control.c @@ -1708,17 +1708,21 @@ void handle_peer_connected(struct lightningd *ld, const u8 *msg) struct peer_connected_hook_payload *hook_payload; u64 connectd_counter; const char *cmd_id; + char *connect_reason; + u64 connect_nsec; struct wireaddr *last_known_addr; hook_payload = tal(NULL, struct peer_connected_hook_payload); hook_payload->ld = ld; hook_payload->error = NULL; if (!fromwire_connectd_peer_connected(hook_payload, msg, - &id, &connectd_counter, - &hook_payload->addr, - &hook_payload->remote_addr, - &hook_payload->incoming, - &their_features)) { + &id, &connectd_counter, + &hook_payload->addr, + &hook_payload->remote_addr, + &hook_payload->incoming, + &their_features, + &connect_reason, + &connect_nsec)) { u64 prev_connectd_counter; if (!fromwire_connectd_peer_reconnected(hook_payload, msg, &id, &prev_connectd_counter, @@ -1734,6 +1738,8 @@ void handle_peer_connected(struct lightningd *ld, const u8 *msg) * fail any connect attempts: this is a race. */ log_peer_debug(ld->log, &id, "peer reconnected"); peer_disconnected(ld, &id, prev_connectd_counter, false); + connect_reason = tal_strdup(hook_payload, ""); + connect_nsec = 0; } /* If we connected, and it's a normal address */ @@ -1809,6 +1815,8 @@ void handle_peer_connected(struct lightningd *ld, const u8 *msg) } } + /* Free connection reason string to keep memleak detection happy. */ + tal_free(connect_reason); plugin_hook_call_peer_connected(ld, cmd_id, hook_payload); } @@ -2689,7 +2697,9 @@ static void setup_peer(struct peer *peer) /* Make sure connectd knows to try reconnecting (unless * --dev-no-reconnect). */ if (connect && ld->reconnect) - connectd_connect_to_peer(ld, peer, important); + connectd_connect_to_peer(ld, peer, + "started with channel", + important); } void setup_peers(struct lightningd *ld) diff --git a/lightningd/test/run-invoice-select-inchan.c b/lightningd/test/run-invoice-select-inchan.c index 96dc1d617..3ed72c704 100644 --- a/lightningd/test/run-invoice-select-inchan.c +++ b/lightningd/test/run-invoice-select-inchan.c @@ -218,6 +218,7 @@ void connect_succeeded(struct lightningd *ld UNNEEDED, const struct peer *peer U /* Generated stub for connectd_connect_to_peer */ void connectd_connect_to_peer(struct lightningd *ld UNNEEDED, const struct peer *peer UNNEEDED, + const char *reason UNNEEDED, bool is_important UNNEEDED) { fprintf(stderr, "connectd_connect_to_peer called!\n"); abort(); } /* Generated stub for create_anchor_details */ @@ -269,7 +270,7 @@ void force_peer_disconnect(struct lightningd *ld UNNEEDED, bool fromwire_channeld_dev_memleak_reply(const void *p UNNEEDED, bool *leak UNNEEDED) { fprintf(stderr, "fromwire_channeld_dev_memleak_reply called!\n"); abort(); } /* Generated stub for fromwire_connectd_peer_connected */ -bool fromwire_connectd_peer_connected(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED, struct wireaddr_internal *addr UNNEEDED, struct wireaddr **remote_addr UNNEEDED, bool *incoming UNNEEDED, u8 **features UNNEEDED) +bool fromwire_connectd_peer_connected(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED, struct wireaddr_internal *addr UNNEEDED, struct wireaddr **remote_addr UNNEEDED, bool *incoming UNNEEDED, u8 **features UNNEEDED, wirestring **connect_reason UNNEEDED, u64 *connect_nsec UNNEEDED) { fprintf(stderr, "fromwire_connectd_peer_connected called!\n"); abort(); } /* Generated stub for fromwire_connectd_peer_disconnected */ bool fromwire_connectd_peer_disconnected(const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED) diff --git a/wallet/test/run-wallet.c b/wallet/test/run-wallet.c index 5ce78e712..54f0a3858 100644 --- a/wallet/test/run-wallet.c +++ b/wallet/test/run-wallet.c @@ -213,6 +213,7 @@ void connect_succeeded(struct lightningd *ld UNNEEDED, const struct peer *peer U /* Generated stub for connectd_connect_to_peer */ void connectd_connect_to_peer(struct lightningd *ld UNNEEDED, const struct peer *peer UNNEEDED, + const char *reason UNNEEDED, bool is_important UNNEEDED) { fprintf(stderr, "connectd_connect_to_peer called!\n"); abort(); } /* Generated stub for create_anchor_details */ @@ -298,7 +299,7 @@ bool fromwire_channeld_offer_htlc_reply(const tal_t *ctx UNNEEDED, const void *p bool fromwire_channeld_sending_commitsig(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, u64 *commitnum UNNEEDED, struct penalty_base **pbase UNNEEDED, struct fee_states **fee_states UNNEEDED, struct height_states **blockheight_states UNNEEDED, struct changed_htlc **changed UNNEEDED) { fprintf(stderr, "fromwire_channeld_sending_commitsig called!\n"); abort(); } /* Generated stub for fromwire_connectd_peer_connected */ -bool fromwire_connectd_peer_connected(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED, struct wireaddr_internal *addr UNNEEDED, struct wireaddr **remote_addr UNNEEDED, bool *incoming UNNEEDED, u8 **features UNNEEDED) +bool fromwire_connectd_peer_connected(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED, struct wireaddr_internal *addr UNNEEDED, struct wireaddr **remote_addr UNNEEDED, bool *incoming UNNEEDED, u8 **features UNNEEDED, wirestring **connect_reason UNNEEDED, u64 *connect_nsec UNNEEDED) { fprintf(stderr, "fromwire_connectd_peer_connected called!\n"); abort(); } /* Generated stub for fromwire_connectd_peer_disconnected */ bool fromwire_connectd_peer_disconnected(const void *p UNNEEDED, struct node_id *id UNNEEDED, u64 *counter UNNEEDED)