From 02acb41a485c3df0231c71d9a44569af10be34ad Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Tue, 13 Nov 2018 08:33:02 -0800 Subject: [PATCH] raft: Improve logging for sent RPCs. For debugging, it is useful to know the source code line that sent a given RPC message. Acked-by: Mark Michelson Signed-off-by: Ben Pfaff --- ovsdb/raft.c | 55 ++++++++++++++++++++++++++++++++-------------------- 1 file changed, 34 insertions(+), 21 deletions(-) diff --git a/ovsdb/raft.c b/ovsdb/raft.c index 02ba763e5..6c5c6068f 100644 --- a/ovsdb/raft.c +++ b/ovsdb/raft.c @@ -303,9 +303,15 @@ static bool raft_rpc_is_heartbeat(const union raft_rpc *); static bool raft_is_rpc_synced(const struct raft *, const union raft_rpc *); static void raft_handle_rpc(struct raft *, const union raft_rpc *); -static bool raft_send(struct raft *, const union raft_rpc *); -static bool raft_send__(struct raft *, const union raft_rpc *, - struct raft_conn *); +static bool raft_send_at(struct raft *, const union raft_rpc *, + int line_number); +#define raft_send(raft, rpc) raft_send_at(raft, rpc, __LINE__) + +static bool raft_send_to_conn_at(struct raft *, const union raft_rpc *, + struct raft_conn *, int line_number); +#define raft_send_to_conn(raft, rpc, conn) \ + raft_send_to_conn_at(raft, rpc, conn, __LINE__) + static void raft_send_append_request(struct raft *, struct raft_server *, unsigned int n, const char *comment); @@ -1055,7 +1061,7 @@ raft_transfer_leadership(struct raft *raft, const char *reason) .term = raft->term, } }; - raft_send__(raft, &rpc, conn); + raft_send_to_conn(raft, &rpc, conn); raft_record_note(raft, "transfer leadership", "transferring leadership to %s because %s", @@ -1295,14 +1301,18 @@ raft_get_nickname(const struct raft *raft, const struct uuid *sid, } static void -log_rpc(const union raft_rpc *rpc, - const char *direction, const struct raft_conn *conn) +log_rpc(const union raft_rpc *rpc, const char *direction, + const struct raft_conn *conn, int line_number) { static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(600, 600); if (!raft_rpc_is_heartbeat(rpc) && !VLOG_DROP_DBG(&rl)) { struct ds s = DS_EMPTY_INITIALIZER; + if (line_number) { + ds_put_format(&s, "raft.c:%d ", line_number); + } + ds_put_format(&s, "%s%s ", direction, conn->nickname); raft_rpc_format(rpc, &s); - VLOG_DBG("%s%s %s", direction, conn->nickname, ds_cstr(&s)); + VLOG_DBG("%s", ds_cstr(&s)); ds_destroy(&s); } } @@ -1320,7 +1330,7 @@ raft_send_add_server_request(struct raft *raft, struct raft_conn *conn) .address = raft->local_address, }, }; - raft_send__(raft, &rq, conn); + raft_send_to_conn(raft, &rq, conn); } static void @@ -1345,7 +1355,7 @@ raft_conn_run(struct raft *raft, struct raft_conn *conn) .sid = raft->sid, }, }; - raft_send__(raft, &rq, conn); + raft_send_to_conn(raft, &rq, conn); } else { union raft_rpc rq = (union raft_rpc) { .hello_request = { @@ -1356,7 +1366,7 @@ raft_conn_run(struct raft *raft, struct raft_conn *conn) .address = raft->local_address, }, }; - raft_send__(raft, &rq, conn); + raft_send_to_conn(raft, &rq, conn); } } @@ -1366,7 +1376,7 @@ raft_conn_run(struct raft *raft, struct raft_conn *conn) break; } - log_rpc(&rpc, "<--", conn); + log_rpc(&rpc, "<--", conn, 0); raft_handle_rpc(raft, &rpc); raft_rpc_uninit(&rpc); } @@ -1434,13 +1444,14 @@ raft_waiter_complete_rpc(struct raft *raft, const union raft_rpc *rpc) struct raft_conn *dst = raft_find_conn_by_sid(raft, &rpc->common.sid); if (dst) { - raft_send__(raft, rpc, dst); + raft_send_to_conn(raft, rpc, dst); } } static void raft_waiter_complete(struct raft *raft, struct raft_waiter *w) { + VLOG_INFO("%s:%d", __FILE__, __LINE__); switch (w->type) { case RAFT_W_ENTRY: if (raft->role == RAFT_LEADER) { @@ -4001,10 +4012,10 @@ raft_rpc_is_heartbeat(const union raft_rpc *rpc) static bool -raft_send__(struct raft *raft, const union raft_rpc *rpc, - struct raft_conn *conn) +raft_send_to_conn_at(struct raft *raft, const union raft_rpc *rpc, + struct raft_conn *conn, int line_number) { - log_rpc(rpc, "-->", conn); + log_rpc(rpc, "-->", conn, line_number); return !jsonrpc_session_send( conn->js, raft_rpc_to_jsonrpc(&raft->cid, &raft->sid, rpc)); } @@ -4022,12 +4033,13 @@ raft_is_rpc_synced(const struct raft *raft, const union raft_rpc *rpc) } static bool -raft_send(struct raft *raft, const union raft_rpc *rpc) +raft_send_at(struct raft *raft, const union raft_rpc *rpc, int line_number) { const struct uuid *dst = &rpc->common.sid; if (uuid_equals(dst, &raft->sid)) { static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 1); - VLOG_WARN_RL(&rl, "attempting to send RPC to self"); + VLOG_WARN_RL(&rl, "attempted to send RPC to self from raft.c:%d", + line_number); return false; } @@ -4035,9 +4047,10 @@ raft_send(struct raft *raft, const union raft_rpc *rpc) if (!conn) { static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 1); char buf[SID_LEN + 1]; - VLOG_DBG_RL(&rl, "%s: no connection to %s, cannot send RPC", - raft->local_nickname, - raft_get_nickname(raft, dst, buf, sizeof buf)); + VLOG_DBG_RL(&rl, "%s: no connection to %s, cannot send RPC " + "from raft.c:%d", raft->local_nickname, + raft_get_nickname(raft, dst, buf, sizeof buf), + line_number); return false; } @@ -4046,7 +4059,7 @@ raft_send(struct raft *raft, const union raft_rpc *rpc) return true; } - return raft_send__(raft, rpc, conn); + return raft_send_to_conn_at(raft, rpc, conn, line_number); } static struct raft * -- 2.39.2