From: Frédéric Lécaille Date: Fri, 15 Jan 2021 15:21:28 +0000 (+0100) Subject: MINOR: peers: Add traces for peer control messages. X-Git-Tag: v2.4-dev6~56 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=da2b0844f;p=thirdparty%2Fhaproxy.git 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 3a97d8a90f..624d268eb5 100644 --- a/src/peers.c +++ b/src/peers.c @@ -298,6 +298,18 @@ static void peers_trace(enum trace_level level, uint64_t mask, 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 @@ struct trace_source trace_peers = { .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 @@ static void peers_trace(enum trace_level level, uint64_t mask, 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 @@ static void peers_trace(enum trace_level level, uint64_t mask, 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 @@ static void peer_session_release(struct appctx *appctx) { 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 @@ static int peer_prepare_control_msg(char *msg, size_t size, struct peer_prep_par * 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 @@ static inline int peer_send_resync_reqmsg(struct appctx *appctx) * 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 @@ static inline int peer_send_resync_confirmsg(struct appctx *appctx) * 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 @@ static inline int peer_send_resync_finishedmsg(struct appctx *appctx, struct pee 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 @@ static inline int peer_send_resync_finishedmsg(struct appctx *appctx, struct pee * 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 @@ static inline int peer_treat_ackmsg(struct appctx *appctx, struct peer *p, 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 @@ static inline int peer_treat_switchmsg(struct appctx *appctx, struct peer *p, 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 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, 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 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee 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 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee * -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 @@ static inline int peer_send_msgs(struct appctx *appctx, struct peer *peer) } 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 @@ static inline int peer_send_msgs(struct appctx *appctx, struct peer *peer) /* 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 @@ switchstate: 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 @@ send_msgs: 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 @@ send_msgs: 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; }