From 7ae15401dd8105c844e912ea462c596f1de76e78 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Thu, 5 May 2016 14:23:34 +0930 Subject: [PATCH] daemon: log all state changes the same way. Signed-off-by: Rusty Russell --- daemon/peer.c | 37 +++++++++++++++------- daemon/peer.h | 2 ++ state.c | 87 ++++++++++++++++++++++++--------------------------- 3 files changed, 69 insertions(+), 57 deletions(-) diff --git a/daemon/peer.c b/daemon/peer.c index 6b6fc8ecb..dab577f54 100644 --- a/daemon/peer.c +++ b/daemon/peer.c @@ -119,6 +119,13 @@ static void set_current_command(struct peer *peer, peer->curr_cmd.jsoncmd = jsoncmd; } +void set_peer_state(struct peer *peer, enum state newstate, const char *caller) +{ + log_debug(peer->log, "%s: %s => %s", caller, + state_name(peer->state), state_name(newstate)); + peer->state = newstate; +} + static void peer_breakdown(struct peer *peer) { /* If we have a closing tx, use it. */ @@ -141,10 +148,9 @@ static void state_single(struct peer *peer, enum command_status status; const struct bitcoin_tx *broadcast; size_t old_outpkts = tal_count(peer->outpkt); - + status = state(peer, input, idata, &broadcast); - log_debug(peer->log, "%s => %s", - input_name(input), state_name(peer->state)); + log_debug(peer->log, "Peer condition: %s", cstatus_name(peer->cond)); switch (status) { case CMD_NONE: break; @@ -400,8 +406,10 @@ static void peer_disconnect(struct io_conn *conn, struct peer *peer) if (peer->cond == PEER_CLOSED) return; - if (peer->state != STATE_ERR_BREAKDOWN) + if (peer->state != STATE_ERR_BREAKDOWN) { + set_peer_state(peer, STATE_ERR_BREAKDOWN, "peer_disconnect"); peer_breakdown(peer); + } } static struct peer *new_peer(struct lightningd_state *dstate, @@ -1279,7 +1287,7 @@ static void check_for_resolution(struct peer *peer, * output which is not *irrevocably resolved* until all outputs are * *irrevocably resolved*. */ - peer->state = STATE_CLOSED; + set_peer_state(peer, STATE_CLOSED, "check_for_resolution"); io_break(peer); } @@ -1323,18 +1331,25 @@ static void anchor_spent(struct peer *peer, peer->closing_onchain.ci = find_commit(peer->them.commit, &txid); if (peer->closing_onchain.ci) { if (peer->closing_onchain.ci->revocation_preimage) { - peer->state = STATE_CLOSE_ONCHAIN_CHEATED; + set_peer_state(peer, STATE_CLOSE_ONCHAIN_CHEATED, + "anchor_spent"); resolve_cheating(peer); } else { - peer->state = STATE_CLOSE_ONCHAIN_THEIR_UNILATERAL; + set_peer_state(peer, + STATE_CLOSE_ONCHAIN_THEIR_UNILATERAL, + "anchor_spent"); resolve_their_unilateral(peer); } } else if (txidmatch(peer->us.commit->tx, &txid)) { - peer->state = STATE_CLOSE_ONCHAIN_OUR_UNILATERAL; + set_peer_state(peer, + STATE_CLOSE_ONCHAIN_OUR_UNILATERAL, + "anchor_spent"); peer->closing_onchain.ci = peer->us.commit; resolve_our_unilateral(peer); } else if (is_mutual_close(peer, tx)) { - peer->state = STATE_CLOSE_ONCHAIN_MUTUAL; + set_peer_state(peer, + STATE_CLOSE_ONCHAIN_MUTUAL, + "anchor_spent"); resolve_mutual_close(peer); } else /* FIXME: Log harder! */ @@ -1799,7 +1814,7 @@ static void json_getpeers(struct command *cmd, /* FIXME: Report anchor. */ - if (!p->us.commit) { + if (!p->us.commit || !p->us.commit->cstate) { json_object_end(response); continue; } @@ -2299,7 +2314,7 @@ static void json_disconnect(struct command *cmd, * one side to freak out. We just ensure we ignore it. */ log_debug(peer->log, "Pretending connection is closed"); peer->fake_close = true; - peer->state = STATE_ERR_BREAKDOWN; + set_peer_state(peer, STATE_ERR_BREAKDOWN, "json_disconnect"); peer_breakdown(peer); command_success(cmd, null_response(cmd)); diff --git a/daemon/peer.h b/daemon/peer.h index 99bc86a57..201c92fcf 100644 --- a/daemon/peer.h +++ b/daemon/peer.h @@ -228,6 +228,8 @@ void setup_listeners(struct lightningd_state *dstate, unsigned int portnum); /* Populates very first peer->{us,them}.commit->{tx,cstate} */ bool setup_first_commit(struct peer *peer); +void set_peer_state(struct peer *peer, enum state newstate, const char *why); + /* Call this after commit changes, or revocation accepted/sent. */ void peer_check_if_cleared(struct peer *peer); diff --git a/state.c b/state.c index c0d710788..855d9e023 100644 --- a/state.c +++ b/state.c @@ -1,28 +1,19 @@ #include +#include #ifndef TEST_STATE_COVERAGE #include #endif +#include #include -/* STATE_CLOSE* can be treated as a bitset offset from STATE_CLOSED */ -#define BITS_TO_STATE(bits) (STATE_CLOSED + (bits)) -#define STATE_TO_BITS(state) ((state) - STATE_CLOSED) - -/* For the rare cases where state may not change */ -static enum command_status next_state_nocheck(struct peer *peer, - enum command_status cstatus, - const enum state state) -{ - peer->state = state; - return cstatus; -} - static enum command_status next_state(struct peer *peer, + const enum state_input input, enum command_status cstatus, const enum state state) { assert(peer->state != state); - return next_state_nocheck(peer, cstatus, state); + set_peer_state(peer, state, input_name(input)); + return cstatus; } /* @@ -34,8 +25,12 @@ static enum command_status next_state(struct peer *peer, * INPUT_NO_MORE_HTLCS when we get the last one. * - HTLC add/remove in STATE_NORMAL. */ -static enum command_status unchanged_state(enum command_status cstatus) +static enum command_status unchanged_state(const struct peer *peer, + const enum state_input input, + enum command_status cstatus) { + log_debug(peer->log, "%s: %s unchanged", + input_name(input), state_name(peer->state)); return cstatus; } @@ -97,13 +92,13 @@ enum command_status state(struct peer *peer, queue_pkt_open(peer, OPEN_CHANNEL__ANCHOR_OFFER__WILL_CREATE_ANCHOR); change_peer_cond(peer, PEER_CMD_OK, PEER_BUSY); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_OPEN_WITHANCHOR); } else if (input_is(input, CMD_OPEN_WITHOUT_ANCHOR)) { change_peer_cond(peer, PEER_CMD_OK, PEER_BUSY); queue_pkt_open(peer, OPEN_CHANNEL__ANCHOR_OFFER__WONT_CREATE_ANCHOR); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_OPEN_NOANCHOR); } break; @@ -114,7 +109,7 @@ enum command_status state(struct peer *peer, complete_cmd(peer, &cstatus, CMD_FAIL); goto err_breakdown; } - return next_state(peer, cstatus, STATE_OPEN_WAIT_FOR_ANCHOR); + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_ANCHOR); } else if (input_is(input, CMD_CLOSE)) { complete_cmd(peer, &cstatus, CMD_FAIL); goto breakdown; @@ -131,7 +126,7 @@ enum command_status state(struct peer *peer, goto err_breakdown; } bitcoin_create_anchor(peer, BITCOIN_ANCHOR_CREATED); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_ANCHOR_CREATE); } else if (input_is(input, CMD_CLOSE)) { complete_cmd(peer, &cstatus, CMD_FAIL); @@ -144,7 +139,7 @@ enum command_status state(struct peer *peer, case STATE_OPEN_WAIT_FOR_ANCHOR_CREATE: if (input_is(input, BITCOIN_ANCHOR_CREATED)) { queue_pkt_anchor(peer); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_COMMIT_SIG); } else if (input_is(input, CMD_CLOSE)) { bitcoin_release_anchor(peer, BITCOIN_ANCHOR_CREATED); @@ -168,7 +163,7 @@ enum command_status state(struct peer *peer, BITCOIN_ANCHOR_DEPTHOK, BITCOIN_ANCHOR_TIMEOUT); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAITING_THEIRANCHOR); } else if (input_is(input, CMD_CLOSE)) { complete_cmd(peer, &cstatus, CMD_FAIL); @@ -190,7 +185,7 @@ enum command_status state(struct peer *peer, peer_watch_anchor(peer, BITCOIN_ANCHOR_DEPTHOK, INPUT_NONE); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAITING_OURANCHOR); } else if (input_is(input, CMD_CLOSE)) { bitcoin_release_anchor(peer, INPUT_NONE); @@ -213,7 +208,7 @@ enum command_status state(struct peer *peer, INPUT_NONE); goto err_breakdown; } - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAITING_OURANCHOR_THEYCOMPLETED); } /* Fall thru */ @@ -222,9 +217,9 @@ enum command_status state(struct peer *peer, queue_pkt_open_complete(peer); if (peer->state == STATE_OPEN_WAITING_OURANCHOR_THEYCOMPLETED) { complete_cmd(peer, &cstatus, CMD_SUCCESS); - return next_state(peer, cstatus, STATE_NORMAL); + return next_state(peer, input, cstatus, STATE_NORMAL); } - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_COMPLETE_OURANCHOR); } else if (input_is(input, CMD_CLOSE)) { /* We no longer care about anchor depth. */ @@ -260,7 +255,7 @@ enum command_status state(struct peer *peer, BITCOIN_ANCHOR_TIMEOUT); goto err_breakdown; } - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAITING_THEIRANCHOR_THEYCOMPLETED); } /* Fall thru */ @@ -268,14 +263,14 @@ enum command_status state(struct peer *peer, if (input_is(input, BITCOIN_ANCHOR_TIMEOUT)) { /* Anchor didn't reach blockchain in reasonable time. */ queue_pkt_err(peer, pkt_err(peer, "Anchor timed out")); - return next_state(peer, cstatus, STATE_ERR_ANCHOR_TIMEOUT); + return next_state(peer, input, cstatus, STATE_ERR_ANCHOR_TIMEOUT); } else if (input_is(input, BITCOIN_ANCHOR_DEPTHOK)) { queue_pkt_open_complete(peer); if (peer->state == STATE_OPEN_WAITING_THEIRANCHOR_THEYCOMPLETED) { complete_cmd(peer, &cstatus, CMD_SUCCESS); - return next_state(peer, cstatus, STATE_NORMAL); + return next_state(peer, input, cstatus, STATE_NORMAL); } - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_OPEN_WAIT_FOR_COMPLETE_THEIRANCHOR); } else if (input_is(input, CMD_CLOSE)) { /* We no longer care about anchor depth. */ @@ -306,10 +301,10 @@ enum command_status state(struct peer *peer, /* Ready for business! Anchorer goes first. */ if (peer->state == STATE_OPEN_WAIT_FOR_COMPLETE_OURANCHOR) { complete_cmd(peer, &cstatus, CMD_SUCCESS); - return next_state(peer, cstatus, STATE_NORMAL); + return next_state(peer, input, cstatus, STATE_NORMAL); } else { complete_cmd(peer, &cstatus, CMD_SUCCESS); - return next_state(peer, cstatus, STATE_NORMAL); + return next_state(peer, input, cstatus, STATE_NORMAL); } } else if (input_is(input, CMD_CLOSE)) { complete_cmd(peer, &cstatus, CMD_FAIL); @@ -336,7 +331,7 @@ enum command_status state(struct peer *peer, if (input_is(input, CMD_SEND_COMMIT)) { queue_pkt_commit(peer); change_peer_cond(peer, PEER_CMD_OK, PEER_BUSY); - return next_state(peer, cstatus, STATE_NORMAL_COMMITTING); + return next_state(peer, input, cstatus, STATE_NORMAL_COMMITTING); } else if (input_is(input, CMD_SEND_HTLC_ADD)) { /* We are to send an HTLC add. */ queue_pkt_htlc_add(peer, idata->htlc_prog); @@ -361,7 +356,7 @@ enum command_status state(struct peer *peer, goto err_breakdown; } complete_cmd(peer, &cstatus, CMD_SUCCESS); - return next_state(peer, cstatus, STATE_NORMAL); + return next_state(peer, input, cstatus, STATE_NORMAL); } if (input_is(input, CMD_CLOSE)) { @@ -370,23 +365,23 @@ enum command_status state(struct peer *peer, err = accept_pkt_htlc_add(peer, idata->pkt); if (err) goto err_breakdown; - return unchanged_state(cstatus); + return unchanged_state(peer, input, cstatus); } else if (input_is(input, PKT_UPDATE_FULFILL_HTLC)) { err = accept_pkt_htlc_fulfill(peer, idata->pkt); if (err) goto err_breakdown; - return unchanged_state(cstatus); + return unchanged_state(peer, input, cstatus); } else if (input_is(input, PKT_UPDATE_FAIL_HTLC)) { err = accept_pkt_htlc_fail(peer, idata->pkt); if (err) goto err_breakdown; - return unchanged_state(cstatus); + return unchanged_state(peer, input, cstatus); } else if (input_is(input, PKT_UPDATE_COMMIT)) { err = accept_pkt_commit(peer, idata->pkt); if (err) goto err_breakdown; queue_pkt_revocation(peer); - return unchanged_state(cstatus); + return unchanged_state(peer, input, cstatus); } else if (input_is(input, PKT_CLOSE_CLEARING)) { goto accept_clearing; } else if (input_is_pkt(input)) { @@ -404,7 +399,7 @@ enum command_status state(struct peer *peer, * either commit tx */ peer_watch_htlcs_cleared(peer, INPUT_HTLCS_CLEARED); - return next_state(peer, cstatus, STATE_BOTH_CLEARING); + return next_state(peer, input, cstatus, STATE_BOTH_CLEARING); /* FIXME: We must continue to allow fulfill & fail! */ } else if (input_is(input, CMD_SEND_HTLC_FAIL) || input_is(input, CMD_SEND_HTLC_FULFILL)) { @@ -449,13 +444,13 @@ enum command_status state(struct peer *peer, bitcoin_close(peer)); change_peer_cond(peer, PEER_CLOSING, PEER_CLOSED); - return next_state(peer, cstatus, + return next_state(peer, input, cstatus, STATE_CLOSE_WAIT_CLOSE); } /* Offer the new fee. */ queue_pkt_close_signature(peer); - return unchanged_state(cstatus); + return unchanged_state(peer, input, cstatus); } else if (input_is(input, INPUT_CLOSE_COMPLETE_TIMEOUT)) { err = pkt_err(peer, "Close timed out"); goto err_breakdown; @@ -475,11 +470,11 @@ enum command_status state(struct peer *peer, case STATE_CLOSE_ONCHAIN_THEIR_UNILATERAL: case STATE_CLOSE_ONCHAIN_OUR_UNILATERAL: case STATE_CLOSE_ONCHAIN_MUTUAL: - return next_state(peer, cstatus, STATE_ERR_INTERNAL); + return next_state(peer, input, cstatus, STATE_ERR_INTERNAL); } /* State machine should handle all possible states. */ - return next_state(peer, cstatus, STATE_ERR_INTERNAL); + return next_state(peer, input, cstatus, STATE_ERR_INTERNAL); unexpected_pkt: peer_unexpected_pkt(peer, idata->pkt); @@ -493,7 +488,7 @@ unexpected_pkt: err_breakdown: queue_pkt_err(peer, err); breakdown: - return next_state(peer, cstatus, STATE_ERR_BREAKDOWN); + return next_state(peer, input, cstatus, STATE_ERR_BREAKDOWN); start_clearing: /* @@ -504,13 +499,13 @@ start_clearing: /* No more commands, we're already closing. */ set_peer_cond(peer, PEER_CLOSING); - return next_state(peer, cstatus, STATE_US_CLEARING); + return next_state(peer, input, cstatus, STATE_US_CLEARING); start_closing_cleared: /* As soon as we send packet, they could close. */ peer_calculate_close_fee(peer); queue_pkt_close_signature(peer); - return next_state(peer, cstatus, STATE_WAIT_FOR_CLOSE_SIG); + return next_state(peer, input, cstatus, STATE_WAIT_FOR_CLOSE_SIG); accept_clearing: err = accept_pkt_close_clearing(peer, idata->pkt); @@ -526,5 +521,5 @@ accept_clearing: /* Tell them we're clearing too. */ queue_pkt_close_clearing(peer); - return next_state(peer, cstatus, STATE_BOTH_CLEARING); + return next_state(peer, input, cstatus, STATE_BOTH_CLEARING); }