MINOR: peers: Add traces for peer control messages.
Display traces when sending/receiving peer control messages (synchronisation, heartbeat).
Add remaining traces when parsing malformed messages (acks, stick-table definitions)
or ignoring them.
Also add traces when releasing session or when reaching the PEER_SESS_ST_ERRPROTO
peer protocol state.
diff --git a/src/peers.c b/src/peers.c
index 3a97d8a..624d268 100644
--- a/src/peers.c
+++ b/src/peers.c
@@ -298,6 +298,18 @@
static const struct trace_event peers_trace_events[] = {
#define PEERS_EV_UPDTMSG (1 << 0)
{ .mask = PEERS_EV_UPDTMSG, .name = "updtmsg", .desc = "update message received" },
+#define PEERS_EV_ACKMSG (1 << 1)
+ { .mask = PEERS_EV_ACKMSG, .name = "ackmsg", .desc = "ack message received" },
+#define PEERS_EV_SWTCMSG (1 << 2)
+ { .mask = PEERS_EV_SWTCMSG, .name = "swtcmsg", .desc = "switch message received" },
+#define PEERS_EV_DEFMSG (1 << 3)
+ { .mask = PEERS_EV_DEFMSG, .name = "defmsg", .desc = "definition message received" },
+#define PEERS_EV_CTRLMSG (1 << 4)
+ { .mask = PEERS_EV_CTRLMSG, .name = "ctrlmsg", .desc = "control message sent/received" },
+#define PEERS_EV_SESSREL (1 << 5)
+ { .mask = PEERS_EV_SESSREL, .name = "sessrl", .desc = "peer session releasing" },
+#define PEERS_EV_PROTOERR (1 << 6)
+ { .mask = PEERS_EV_PROTOERR, .name = "protoerr", .desc = "protocol error" },
};
static const struct name_desc peers_trace_lockon_args[4] = {
@@ -325,6 +337,25 @@
.report_events = ~0, /* report everything by default */
};
+/* Return peer control message types as strings (only for debugging purpose). */
+static inline char *ctrl_msg_type_str(unsigned int type)
+{
+ switch (type) {
+ case PEER_MSG_CTRL_RESYNCREQ:
+ return "RESYNCREQ";
+ case PEER_MSG_CTRL_RESYNCFINISHED:
+ return "RESYNCFINISHED";
+ case PEER_MSG_CTRL_RESYNCPARTIAL:
+ return "RESYNCPARTIAL";
+ case PEER_MSG_CTRL_RESYNCCONFIRM:
+ return "RESYNCCONFIRM";
+ case PEER_MSG_CTRL_HEARTBEAT:
+ return "HEARTBEAT";
+ default:
+ return "???";
+ }
+}
+
#define TRACE_SOURCE &trace_peers
INITCALL1(STG_REGISTER, trace_register_source, TRACE_SOURCE);
@@ -333,7 +364,7 @@
const struct ist where, const struct ist func,
const void *a1, const void *a2, const void *a3, const void *a4)
{
- if (mask & PEERS_EV_UPDTMSG) {
+ if (mask & (PEERS_EV_UPDTMSG|PEERS_EV_ACKMSG|PEERS_EV_SWTCMSG)) {
if (a2) {
const struct peer *peer = a2;
@@ -350,6 +381,73 @@
chunk_appendf(&trace_buf, " %llu", (unsigned long long)*val);
}
}
+
+ if (mask & PEERS_EV_DEFMSG) {
+ if (a2) {
+ const struct peer *peer = a2;
+
+ chunk_appendf(&trace_buf, " peer=%s", peer->id);
+ }
+ if (a3) {
+ const char *p = a3;
+
+ chunk_appendf(&trace_buf, " @%p", p);
+ }
+ if (a4) {
+ const int *val = a4;
+
+ chunk_appendf(&trace_buf, " %d", *val);
+ }
+ }
+
+ if (mask & PEERS_EV_CTRLMSG) {
+ if (a2) {
+ const unsigned char *ctrl_msg_type = a2;
+
+ chunk_appendf(&trace_buf, " %s", ctrl_msg_type_str(*ctrl_msg_type));
+
+ }
+ if (a3) {
+ const char *local_peer = a3;
+
+ chunk_appendf(&trace_buf, " %s", local_peer);
+ }
+
+ if (a4) {
+ const char *remote_peer = a4;
+
+ chunk_appendf(&trace_buf, " -> %s", remote_peer);
+ }
+ }
+
+ if (mask & (PEERS_EV_SESSREL|PEERS_EV_PROTOERR)) {
+ if (a2) {
+ const struct peer *peer = a2;
+ struct peers *peers = NULL;
+
+ if (peer) {
+ struct stream_interface *si;
+
+ si = peer->appctx->owner;
+ if (si) {
+ struct stream *s = si_strm(si);
+
+ peers = strm_fe(s)->parent;
+ }
+ }
+
+ if (peers)
+ chunk_appendf(&trace_buf, " %s", peers->local->id);
+ if (peer)
+ chunk_appendf(&trace_buf, " -> %s", peer->id);
+ }
+
+ if (a3) {
+ const int *prev_state = a3;
+
+ chunk_appendf(&trace_buf, " prev_state=%d\n", *prev_state);
+ }
+ }
}
static const char *statuscode_str(int statuscode)
@@ -863,6 +961,7 @@
{
struct peer *peer = appctx->ctx.peers.ptr;
+ TRACE_PROTO("releasing peer session", PEERS_EV_SESSREL, NULL, peer);
/* appctx->ctx.peers.ptr is not a peer session */
if (appctx->st0 < PEER_SESS_ST_SENDSUCCESS)
return;
@@ -1094,12 +1193,16 @@
* any other negative returned value must be considered as an error with an appctx st0
* returned value equal to PEER_SESS_ST_END.
*/
-static inline int peer_send_resync_reqmsg(struct appctx *appctx)
+static inline int peer_send_resync_reqmsg(struct appctx *appctx,
+ struct peer *peer, struct peers *peers)
{
struct peer_prep_params p = {
.control.head = { PEER_MSG_CLASS_CONTROL, PEER_MSG_CTRL_RESYNCREQ, },
};
+ TRACE_PROTO("send control message", PEERS_EV_CTRLMSG,
+ NULL, &p.control.head[1], peers->local->id, peer->id);
+
return peer_send_msg(appctx, peer_prepare_control_msg, &p);
}
@@ -1110,12 +1213,16 @@
* any other negative returned value must be considered as an error with an appctx st0
* returned value equal to PEER_SESS_ST_END.
*/
-static inline int peer_send_resync_confirmsg(struct appctx *appctx)
+static inline int peer_send_resync_confirmsg(struct appctx *appctx,
+ struct peer *peer, struct peers *peers)
{
struct peer_prep_params p = {
.control.head = { PEER_MSG_CLASS_CONTROL, PEER_MSG_CTRL_RESYNCCONFIRM, },
};
+ TRACE_PROTO("send control message", PEERS_EV_CTRLMSG,
+ NULL, &p.control.head[1], peers->local->id, peer->id);
+
return peer_send_msg(appctx, peer_prepare_control_msg, &p);
}
@@ -1126,7 +1233,8 @@
* any other negative returned value must be considered as an error with an appctx st0
* returned value equal to PEER_SESS_ST_END.
*/
-static inline int peer_send_resync_finishedmsg(struct appctx *appctx, struct peers *peers)
+static inline int peer_send_resync_finishedmsg(struct appctx *appctx,
+ struct peer *peer, struct peers *peers)
{
struct peer_prep_params p = {
.control.head = { PEER_MSG_CLASS_CONTROL, },
@@ -1135,6 +1243,9 @@
p.control.head[1] = (peers->flags & PEERS_RESYNC_STATEMASK) == PEERS_RESYNC_FINISHED ?
PEER_MSG_CTRL_RESYNCFINISHED : PEER_MSG_CTRL_RESYNCPARTIAL;
+ TRACE_PROTO("send control message", PEERS_EV_CTRLMSG,
+ NULL, &p.control.head[1], peers->local->id, peer->id);
+
return peer_send_msg(appctx, peer_prepare_control_msg, &p);
}
@@ -1145,12 +1256,16 @@
* any other negative returned value must be considered as an error with an appctx st0
* returned value equal to PEER_SESS_ST_END.
*/
-static inline int peer_send_heartbeatmsg(struct appctx *appctx)
+static inline int peer_send_heartbeatmsg(struct appctx *appctx,
+ struct peer *peer, struct peers *peers)
{
struct peer_prep_params p = {
.control.head = { PEER_MSG_CLASS_CONTROL, PEER_MSG_CTRL_HEARTBEAT, },
};
+ TRACE_PROTO("send control message", PEERS_EV_CTRLMSG,
+ NULL, &p.control.head[1], peers->local->id, peer->id);
+
return peer_send_msg(appctx, peer_prepare_control_msg, &p);
}
@@ -1698,6 +1813,9 @@
table_id = intdecode(msg_cur, msg_end);
if (!*msg_cur || (*msg_cur + sizeof(update) > msg_end)) {
/* malformed message */
+
+ TRACE_PROTO("malformed message", PEERS_EV_ACKMSG,
+ NULL, p, *msg_cur);
appctx->st0 = PEER_SESS_ST_ERRPROTO;
return 0;
}
@@ -1731,6 +1849,7 @@
table_id = intdecode(msg_cur, msg_end);
if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_SWTCMSG, NULL, p);
/* malformed message */
appctx->st0 = PEER_SESS_ST_ERRPROTO;
return 0;
@@ -1768,16 +1887,22 @@
uint64_t table_data;
table_id = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p);
goto malformed_exit;
+ }
table_id_len = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p, *msg_cur);
goto malformed_exit;
+ }
p->remote_table = NULL;
- if (!table_id_len || (*msg_cur + table_id_len) >= msg_end)
+ if (!table_id_len || (*msg_cur + table_id_len) >= msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p, *msg_cur, &table_id_len);
goto malformed_exit;
+ }
for (st = p->tables; st; st = st->next) {
/* Reset IDs */
@@ -1789,28 +1914,39 @@
p->remote_table = st;
}
- if (!p->remote_table)
+ if (!p->remote_table) {
+ TRACE_PROTO("ignored message", PEERS_EV_DEFMSG, NULL, p);
goto ignore_msg;
+ }
*msg_cur += table_id_len;
- if (*msg_cur >= msg_end)
+ if (*msg_cur >= msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p);
goto malformed_exit;
+ }
table_type = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p);
goto malformed_exit;
+ }
table_keylen = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p);
goto malformed_exit;
+ }
table_data = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p);
goto malformed_exit;
+ }
if (p->remote_table->table->type != peer_int_key_type[table_type]
|| p->remote_table->table->key_size != table_keylen) {
p->remote_table = NULL;
+ TRACE_PROTO("ignored message", PEERS_EV_DEFMSG, NULL, p);
goto ignore_msg;
}
@@ -1925,6 +2061,8 @@
struct shared_table *st;
/* Reset message: remote need resync */
+ TRACE_PROTO("received control message", PEERS_EV_CTRLMSG,
+ NULL, &msg_head[1], peers->local->id, peer->id);
/* prepare tables for a global push */
for (st = peer->tables; st; st = st->next) {
st->teaching_origin = st->last_pushed = st->table->update;
@@ -1938,6 +2076,8 @@
peer->flags |= PEER_F_TEACH_PROCESS;
}
else if (msg_head[1] == PEER_MSG_CTRL_RESYNCFINISHED) {
+ TRACE_PROTO("received control message", PEERS_EV_CTRLMSG,
+ NULL, &msg_head[1], peers->local->id, peer->id);
if (peer->flags & PEER_F_LEARN_ASSIGN) {
peer->flags &= ~PEER_F_LEARN_ASSIGN;
peers->flags &= ~(PEERS_F_RESYNC_ASSIGN|PEERS_F_RESYNC_PROCESS);
@@ -1946,6 +2086,8 @@
peer->confirm++;
}
else if (msg_head[1] == PEER_MSG_CTRL_RESYNCPARTIAL) {
+ TRACE_PROTO("received control message", PEERS_EV_CTRLMSG,
+ NULL, &msg_head[1], peers->local->id, peer->id);
if (peer->flags & PEER_F_LEARN_ASSIGN) {
peer->flags &= ~PEER_F_LEARN_ASSIGN;
peers->flags &= ~(PEERS_F_RESYNC_ASSIGN|PEERS_F_RESYNC_PROCESS);
@@ -1959,6 +2101,8 @@
else if (msg_head[1] == PEER_MSG_CTRL_RESYNCCONFIRM) {
struct shared_table *st;
+ TRACE_PROTO("received control message", PEERS_EV_CTRLMSG,
+ NULL, &msg_head[1], peers->local->id, peer->id);
/* If stopping state */
if (stopping) {
/* Close session, push resync no more needed */
@@ -1975,6 +2119,8 @@
peer->flags &= PEER_TEACH_RESET;
}
else if (msg_head[1] == PEER_MSG_CTRL_HEARTBEAT) {
+ TRACE_PROTO("received control message", PEERS_EV_CTRLMSG,
+ NULL, &msg_head[1], peers->local->id, peer->id);
peer->reconnect = tick_add(now_ms, MS_TO_TICKS(PEER_RECONNECT_TIMEOUT));
peer->rx_hbt++;
}
@@ -2021,19 +2167,19 @@
* -1 means an internal error occurred, 0 is for a peer protocol error leading
* to a peer state change (from the peer I/O handler point of view).
*/
-static inline int peer_send_msgs(struct appctx *appctx, struct peer *peer)
+static inline int peer_send_msgs(struct appctx *appctx,
+ struct peer *peer, struct peers *peers)
{
int repl;
struct stream_interface *si = appctx->owner;
struct stream *s = si_strm(si);
- struct peers *peers = strm_fe(s)->parent;
/* Need to request a resync */
if ((peer->flags & PEER_F_LEARN_ASSIGN) &&
(peers->flags & PEERS_F_RESYNC_ASSIGN) &&
!(peers->flags & PEERS_F_RESYNC_PROCESS)) {
- repl = peer_send_resync_reqmsg(appctx);
+ repl = peer_send_resync_reqmsg(appctx, peer, peers);
if (repl <= 0)
return repl;
@@ -2097,7 +2243,7 @@
}
if ((peer->flags & PEER_F_TEACH_PROCESS) && !(peer->flags & PEER_F_TEACH_FINISHED)) {
- repl = peer_send_resync_finishedmsg(appctx, peers);
+ repl = peer_send_resync_finishedmsg(appctx, peer, peers);
if (repl <= 0)
return repl;
@@ -2107,7 +2253,7 @@
/* Confirm finished or partial messages */
while (peer->confirm) {
- repl = peer_send_resync_confirmsg(appctx);
+ repl = peer_send_resync_confirmsg(appctx, peer, peers);
if (repl <= 0)
return repl;
@@ -2530,7 +2676,7 @@
send_msgs:
if (curpeer->flags & PEER_F_HEARTBEAT) {
curpeer->flags &= ~PEER_F_HEARTBEAT;
- repl = peer_send_heartbeatmsg(appctx);
+ repl = peer_send_heartbeatmsg(appctx, curpeer, curpeers);
if (repl <= 0) {
if (repl == -1)
goto out;
@@ -2539,7 +2685,7 @@
curpeer->tx_hbt++;
}
/* we get here when a peer_recv_msg() returns 0 in reql */
- repl = peer_send_msgs(appctx, curpeer);
+ repl = peer_send_msgs(appctx, curpeer, curpeers);
if (repl <= 0) {
if (repl == -1)
goto out;
@@ -2567,13 +2713,17 @@
goto switchstate;
}
case PEER_SESS_ST_ERRPROTO: {
+ TRACE_PROTO("protocol error", PEERS_EV_PROTOERR,
+ NULL, curpeer, &prev_state);
if (curpeer)
curpeer->proto_err++;
if (prev_state == PEER_SESS_ST_WAITMSG)
_HA_ATOMIC_SUB(&connected_peers, 1);
prev_state = appctx->st0;
- if (peer_send_error_protomsg(appctx) == -1)
+ if (peer_send_error_protomsg(appctx) == -1) {
+ TRACE_PROTO("could not send error message", PEERS_EV_PROTOERR);
goto out;
+ }
appctx->st0 = PEER_SESS_ST_END;
prev_state = appctx->st0;
}