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 <mmichels@redhat.com>
Signed-off-by: Ben Pfaff <blp@ovn.org>

1 files 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 *