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 <rusty@rustcorp.com.au>

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);
 

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))
 

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)

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;
+
+	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, crypto_on_in, NULL);
+	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

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);