From 42cf0ef5431cf746a5f111341a8490704b69f026 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 31 Aug 2016 16:06:31 +0930 Subject: [PATCH] peer: do logging before crypto is on. We create a logging object when we connect, then carry it through. If it comes from the database, we just use the peerid as the log prefix. Signed-off-by: Rusty Russell --- daemon/cryptopkt.c | 37 ++++++++++++++------------ daemon/cryptopkt.h | 8 ++++-- daemon/db.c | 15 +++++++---- daemon/peer.c | 65 +++++++++++++++++++++++++++++++++------------- daemon/peer.h | 1 + 5 files changed, 85 insertions(+), 41 deletions(-) diff --git a/daemon/cryptopkt.c b/daemon/cryptopkt.c index e74931fa0..16fc9bdf3 100644 --- a/daemon/cryptopkt.c +++ b/daemon/cryptopkt.c @@ -48,6 +48,9 @@ struct key_negotiate { /* After DH key exchange, we create io_data to check auth. */ struct io_data *iod; + /* Logging structure we're using. */ + struct log *log; + /* Did we expect a particular ID? */ const struct pubkey *expected_id; @@ -55,6 +58,7 @@ struct key_negotiate { struct io_plan *(*cb)(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, void *arg); void *arg; @@ -422,15 +426,15 @@ static struct io_plan *recv_body_negotiate(struct io_conn *conn, struct pubkey id; /* We have full packet. */ - pkt = decrypt_body(neg, iod, neg->dstate->base_log, iod->in.cpkt, + pkt = decrypt_body(neg, iod, neg->log, iod->in.cpkt, le32_to_cpu(iod->hdr_in.length)); if (!pkt) return io_close(conn); - if (!check_proof(neg, neg->dstate->base_log, pkt, neg->expected_id, &id)) + if (!check_proof(neg, neg->log, pkt, neg->expected_id, &id)) return io_close(conn); - plan = neg->cb(conn, neg->dstate, neg->iod, &id, neg->arg); + plan = neg->cb(conn, neg->dstate, neg->iod, neg->log, &id, neg->arg); tal_free(neg); return plan; } @@ -441,7 +445,7 @@ static struct io_plan *recv_header_negotiate(struct io_conn *conn, size_t body_len; struct io_data *iod = neg->iod; - if (!decrypt_header(neg->dstate->base_log, iod, &body_len)) + if (!decrypt_header(neg->log, iod, &body_len)) return io_close(conn); return io_read(conn, iod->in.cpkt->data, body_len, recv_body_negotiate, @@ -492,14 +496,14 @@ static struct io_plan *keys_exchanged(struct io_conn *conn, sizeof(neg->their_sessionpubkey), &sessionkey)) { /* FIXME: Dump key in this case. */ - log_unusual(neg->dstate->base_log, "Bad sessionkey"); + log_unusual(neg->log, "Bad sessionkey"); return io_close(conn); } /* Derive shared secret. */ if (!secp256k1_ecdh(neg->dstate->secpctx, shared_secret, &sessionkey.pubkey, neg->seckey)) { - log_unusual(neg->dstate->base_log, "Bad ECDH"); + log_unusual(neg->log, "Bad ECDH"); return io_close(conn); } @@ -538,7 +542,7 @@ static struct io_plan *discard_extra(struct io_conn *conn, len -= sizeof(neg->their_sessionpubkey); discard = tal_arr(neg, char, len); - log_unusual(neg->dstate->base_log, + log_unusual(neg->log, "Ignoring %zu extra handshake bytes", len); return io_read(conn, discard, len, keys_exchanged, neg); @@ -553,21 +557,20 @@ static struct io_plan *session_key_receive(struct io_conn *conn, /* BOLT#1: The `length` field is the length after the field itself, and MUST be 33 or greater. */ if (le32_to_cpu(neg->keylen) < sizeof(neg->their_sessionpubkey)) { - log_unusual(neg->dstate->base_log, "short session key length %u", + log_unusual(neg->log, "short session key length %u", le32_to_cpu(neg->keylen)); return io_close(conn); } /* BOLT#1: `length` MUST NOT exceed 1MB (1048576 bytes). */ if (le32_to_cpu(neg->keylen) > 1048576) { - log_unusual(neg->dstate->base_log, + log_unusual(neg->log, "Oversize session key length %u", le32_to_cpu(neg->keylen)); return io_close(conn); } - log_debug(neg->dstate->base_log, - "Session key length %u", le32_to_cpu(neg->keylen)); + log_debug(neg->log, "Session key length %u", le32_to_cpu(neg->keylen)); /* Now read their key. */ return io_read(conn, neg->their_sessionpubkey, @@ -602,11 +605,13 @@ static struct io_plan *write_sessionkey(struct io_conn *conn, struct io_plan *peer_crypto_setup_(struct io_conn *conn, struct lightningd_state *dstate, const struct pubkey *id, + struct log *log, struct io_plan *(*cb)(struct io_conn *conn, - struct lightningd_state *dstate, - struct io_data *iod, - const struct pubkey *id, - void *arg), + struct lightningd_state *dstate, + struct io_data *iod, + struct log *log, + const struct pubkey *id, + void *arg), void *arg) { size_t outputlen; @@ -626,7 +631,7 @@ struct io_plan *peer_crypto_setup_(struct io_conn *conn, neg->arg = arg; neg->dstate = dstate; neg->expected_id = id; - /* FIXME: Create log buffer for neg, use that then pass to peer. */ + neg->log = log; gen_sessionkey(dstate->secpctx, neg->seckey, &sessionkey); diff --git a/daemon/cryptopkt.h b/daemon/cryptopkt.h index fbf16b1a4..ac75759b1 100644 --- a/daemon/cryptopkt.h +++ b/daemon/cryptopkt.h @@ -8,25 +8,29 @@ struct io_data; struct json_connecting; struct lightningd_state; +struct log; struct peer; struct io_plan *peer_crypto_setup_(struct io_conn *conn, struct lightningd_state *dstate, const struct pubkey *id, + struct log *log, struct io_plan *(*cb)(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, void *arg), void *arg); -#define peer_crypto_setup(conn, dstate, id, cb, arg) \ - peer_crypto_setup_((conn), (dstate), (id), \ +#define peer_crypto_setup(conn, dstate, id, log_, cb, arg) \ + peer_crypto_setup_((conn), (dstate), (id), (log_), \ typesafe_cb_preargs(struct io_plan *, void *, \ (cb), (arg), \ struct io_conn *, \ struct lightningd_state *, \ struct io_data *, \ + struct log *, \ const struct pubkey *), \ (arg)) diff --git a/daemon/db.c b/daemon/db.c index 717adb4d4..814320d77 100644 --- a/daemon/db.c +++ b/daemon/db.c @@ -903,6 +903,9 @@ static void db_load_peers(struct lightningd_state *dstate) while ((err = sqlite3_step(stmt)) != SQLITE_DONE) { enum state state; + struct log *l; + struct pubkey id; + const char *idstr; if (err != SQLITE_ROW) fatal("db_load_peers:step gave %s:%s", @@ -915,15 +918,17 @@ static void db_load_peers(struct lightningd_state *dstate) if (state == STATE_MAX) fatal("db_load_peers:unknown state %s", sqlite3_column_str(stmt, 1)); - peer = new_peer(dstate, state, sqlite3_column_int(stmt, 2) ? + pubkey_from_sql(dstate->secpctx, stmt, 0, &id); + idstr = pubkey_to_hexstr(dstate, dstate->secpctx, &id); + l = new_log(dstate, dstate->log_record, "%s:", idstr); + tal_free(idstr); + peer = new_peer(dstate, l, state, sqlite3_column_int(stmt, 2) ? CMD_OPEN_WITH_ANCHOR : CMD_OPEN_WITHOUT_ANCHOR); peer->htlc_id_counter = 0; - peer->id = tal(peer, struct pubkey); - pubkey_from_sql(dstate->secpctx, stmt, 0, peer->id); + peer->id = tal_dup(peer, struct pubkey, &id); peer->local.commit_fee_rate = sqlite3_column_int64(stmt, 3); - log_debug(dstate->base_log, "%s:%s:", + log_debug(peer->log, "%s:%s", __func__, state_name(peer->state)); - log_add_struct(dstate->base_log, "%s", struct pubkey, peer->id); } err = sqlite3_finalize(stmt); if (err != SQLITE_OK) diff --git a/daemon/peer.c b/daemon/peer.c index 8ddcac667..4f052645c 100644 --- a/daemon/peer.c +++ b/daemon/peer.c @@ -2351,6 +2351,7 @@ static bool peer_reconnected(struct peer *peer, } struct peer *new_peer(struct lightningd_state *dstate, + struct log *log, enum state state, enum state_input offer_anchor) { @@ -2386,7 +2387,6 @@ struct peer *new_peer(struct lightningd_state *dstate, peer->onchain.wscripts = NULL; peer->commit_timer = NULL; peer->nc = NULL; - peer->log = NULL; peer->their_prev_revocation_hash = NULL; peer->conn = NULL; peer->fake_close = false; @@ -2398,9 +2398,9 @@ struct peer *new_peer(struct lightningd_state *dstate, peer->local.mindepth = dstate->config.anchor_confirms; peer->local.commit = peer->remote.commit = NULL; peer->local.staging_cstate = peer->remote.staging_cstate = NULL; - peer->log = new_log(peer, peer->dstate->log_record, "%s:peer %p:", - log_prefix(peer->dstate->base_log), peer); - + peer->log = tal_steal(peer, log); + log_debug(peer->log, "New peer %p", peer); + htlc_map_init(&peer->htlcs); memset(peer->feechanges, 0, sizeof(peer->feechanges)); shachain_init(&peer->their_preimages); @@ -2445,7 +2445,7 @@ static bool peer_first_connected(struct peer *peer, const struct pubkey *id, bool we_connected) { - char *name; + char *name, *idstr; struct netaddr addr; peer->io_data = tal_steal(peer, iod); @@ -2470,9 +2470,10 @@ static bool peer_first_connected(struct peer *peer, return false; name = netaddr_name(peer, &addr); - log_info(peer->log, "Connected %s %s id %s", - we_connected ? "out to" : "in from", name, - pubkey_to_hexstr(name, peer->dstate->secpctx, peer->id)); + idstr = pubkey_to_hexstr(name, peer->dstate->secpctx, peer->id); + log_info(peer->log, "Connected %s %s id %s, changing prefix", + we_connected ? "out to" : "in from", name, idstr); + set_log_prefix(peer->log, tal_fmt(name, "%s:", idstr)); tal_free(name); log_debug(peer->log, "Using fee rate %"PRIu64, @@ -2628,29 +2629,34 @@ static struct io_plan *crypto_on_reconnect(struct io_conn *conn, static struct io_plan *crypto_on_reconnect_in(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, struct peer *peer) { + assert(log == peer->log); return crypto_on_reconnect(conn, dstate, iod, id, peer, false); } static struct io_plan *crypto_on_reconnect_out(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, struct peer *peer) { + assert(log == peer->log); return crypto_on_reconnect(conn, dstate, iod, id, peer, true); } static struct io_plan *crypto_on_out(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, struct json_connecting *connect) { /* Initiator currently funds channel */ - struct peer *peer = new_peer(dstate, STATE_INIT, CMD_OPEN_WITH_ANCHOR); + struct peer *peer = new_peer(dstate, log, STATE_INIT, CMD_OPEN_WITH_ANCHOR); if (!peer_first_connected(peer, conn, SOCK_STREAM, IPPROTO_TCP, iod, id, true)) { command_fail(connect->cmd, "Failed to make peer for %s:%s", @@ -2669,15 +2675,27 @@ static struct io_plan *peer_connected_out(struct io_conn *conn, struct lightningd_state *dstate, struct json_connecting *connect) { - log_debug(dstate->base_log, "Connected out to %s:%s", - connect->name, connect->port); + struct log *l; + const char *name; + struct netaddr addr; - return peer_crypto_setup(conn, dstate, NULL, crypto_on_out, connect); + l = new_log(conn, dstate->log_record, "OUT-%s:%s:", + connect->name, connect->port); + + if (!netaddr_from_fd(io_conn_fd(conn), SOCK_STREAM, IPPROTO_TCP, &addr)) { + log_unusual(l, "Failed to get netaddr: %s", strerror(errno)); + return io_close(conn); + } + name = netaddr_name(conn, &addr); + + log_debug(l, "Connected out to %s", name); + return peer_crypto_setup(conn, dstate, NULL, l, crypto_on_out, connect); } static struct io_plan *crypto_on_in(struct io_conn *conn, struct lightningd_state *dstate, struct io_data *iod, + struct log *log, const struct pubkey *id, void *unused) { @@ -2691,6 +2709,7 @@ static struct io_plan *crypto_on_in(struct io_conn *conn, if (peer) { /* Close any existing connection, without side effects. */ if (peer->conn) { + log_debug(log, "This is reconnect for peer %p", peer); log_debug(peer->log, "Reconnect: closing old conn %p for new conn %p", peer->conn, conn); io_set_finish(peer->conn, NULL, NULL); @@ -2698,11 +2717,12 @@ static struct io_plan *crypto_on_in(struct io_conn *conn, peer->conn = NULL; peer->connected = false; } - return crypto_on_reconnect_in(conn, dstate, iod, id, peer); + return crypto_on_reconnect_in(conn, dstate, iod, peer->log, id, + peer); } /* Initiator currently funds channel */ - peer = new_peer(dstate, STATE_INIT, CMD_OPEN_WITHOUT_ANCHOR); + peer = new_peer(dstate, log, STATE_INIT, CMD_OPEN_WITHOUT_ANCHOR); if (!peer_first_connected(peer, conn, SOCK_STREAM, IPPROTO_TCP, iod, id, false)) return io_close(conn); @@ -2713,10 +2733,18 @@ static struct io_plan *crypto_on_in(struct io_conn *conn, static struct io_plan *peer_connected_in(struct io_conn *conn, struct lightningd_state *dstate) { - /* FIXME: log incoming address. */ - log_debug(dstate->base_log, "Connected in"); + struct netaddr addr; + struct log *l; + const char *name; - return peer_crypto_setup(conn, dstate, NULL, crypto_on_in, NULL); + if (!netaddr_from_fd(io_conn_fd(conn), SOCK_STREAM, IPPROTO_TCP, &addr)) + return false; + name = netaddr_name(conn, &addr); + l = new_log(conn, dstate->log_record, "IN-%s:", name); + + log_debug(l, "Connected in"); + + return peer_crypto_setup(conn, dstate, NULL, l, crypto_on_in, NULL); } static int make_listen_fd(struct lightningd_state *dstate, @@ -4086,7 +4114,8 @@ static struct io_plan *peer_reconnect(struct io_conn *conn, struct peer *peer) assert(peer->id); return peer_crypto_setup(conn, peer->dstate, - peer->id, crypto_on_reconnect_out, peer); + peer->id, peer->log, + crypto_on_reconnect_out, peer); } /* We can't only retry when we want to send: they may want to send us diff --git a/daemon/peer.h b/daemon/peer.h index 954ed1b00..d292a21ac 100644 --- a/daemon/peer.h +++ b/daemon/peer.h @@ -239,6 +239,7 @@ void setup_listeners(struct lightningd_state *dstate, unsigned int portnum); struct peer *find_peer(struct lightningd_state *dstate, const struct pubkey *id); struct peer *new_peer(struct lightningd_state *dstate, + struct log *log, enum state state, enum state_input offer_anchor);