MINOR: peers: Add traces to peer_treat_updatemsg().
Add minimalistic traces for peers with only one event to diagnose potential
issues when decode peer update messages.
(cherry picked from commit d865935f3212f994d8868200d9a84315dbce1518)
[wt: also merge traces from f9e51beec and 1dfd4f10]
Signed-off-by: Willy Tarreau <w@1wt.eu>
diff --git a/src/peers.c b/src/peers.c
index afe770c..3466fa5 100644
--- a/src/peers.c
+++ b/src/peers.c
@@ -42,6 +42,7 @@
#include <haproxy/thread.h>
#include <haproxy/time.h>
#include <haproxy/tools.h>
+#include <haproxy/trace.h>
/*******************************/
@@ -288,6 +289,69 @@
struct dcache_tx_entry *i);
static inline void flush_dcache(struct peer *peer);
+/* trace source and events */
+static void peers_trace(enum trace_level level, uint64_t mask,
+ const struct trace_source *src,
+ const struct ist where, const struct ist func,
+ const void *a1, const void *a2, const void *a3, const void *a4);
+
+static const struct trace_event peers_trace_events[] = {
+#define PEERS_EV_UPDTMSG (1 << 0)
+ { .mask = PEERS_EV_UPDTMSG, .name = "updtmsg", .desc = "update message received" },
+};
+
+static const struct name_desc peers_trace_lockon_args[4] = {
+ /* arg1 */ { /* already used by the connection */ },
+ /* arg2 */ { .name="peers", .desc="Peers protocol" },
+ /* arg3 */ { },
+ /* arg4 */ { }
+};
+
+static const struct name_desc peers_trace_decoding[] = {
+#define PEERS_VERB_CLEAN 1
+ { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" },
+ { /* end */ }
+};
+
+
+struct trace_source trace_peers = {
+ .name = IST("peers"),
+ .desc = "Peers protocol",
+ .arg_def = TRC_ARG1_CONN, /* TRACE()'s first argument is always a connection */
+ .default_cb = peers_trace,
+ .known_events = peers_trace_events,
+ .lockon_args = peers_trace_lockon_args,
+ .decoding = peers_trace_decoding,
+ .report_events = ~0, /* report everything by default */
+};
+
+#define TRACE_SOURCE &trace_peers
+INITCALL1(STG_REGISTER, trace_register_source, TRACE_SOURCE);
+
+static void peers_trace(enum trace_level level, uint64_t mask,
+ const struct trace_source *src,
+ 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 (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 size_t *val = a4;
+
+ chunk_appendf(&trace_buf, " %llu", (unsigned long long)*val);
+ }
+ }
+}
+
static const char *statuscode_str(int statuscode)
{
switch (statuscode) {
@@ -1352,6 +1416,7 @@
unsigned int data_type;
void *data_ptr;
+ TRACE_ENTER(PEERS_EV_UPDTMSG, NULL, p);
/* Here we have data message */
if (!st)
goto ignore_msg;
@@ -1359,8 +1424,10 @@
expire = MS_TO_TICKS(st->table->expire);
if (updt) {
- if (msg_len < sizeof(update))
+ if (msg_len < sizeof(update)) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p);
goto malformed_exit;
+ }
memcpy(&update, *msg_cur, sizeof(update));
*msg_cur += sizeof(update);
@@ -1373,8 +1440,13 @@
if (exp) {
size_t expire_sz = sizeof expire;
- if (*msg_cur + expire_sz > msg_end)
+ if (*msg_cur + expire_sz > msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, msg_end, &expire_sz);
goto malformed_exit;
+ }
memcpy(&expire, *msg_cur, expire_sz);
*msg_cur += expire_sz;
@@ -1389,12 +1461,19 @@
unsigned int to_read, to_store;
to_read = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p);
goto malformed_free_newts;
+ }
to_store = MIN(to_read, st->table->key_size - 1);
- if (*msg_cur + to_store > msg_end)
+ if (*msg_cur + to_store > msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, msg_end, &to_store);
goto malformed_free_newts;
+ }
memcpy(newts->key.key, *msg_cur, to_store);
newts->key.key[to_store] = 0;
@@ -1403,8 +1482,13 @@
else if (st->table->type == SMP_T_SINT) {
unsigned int netinteger;
- if (*msg_cur + sizeof(netinteger) > msg_end)
+ if (*msg_cur + sizeof(netinteger) > msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, msg_end);
goto malformed_free_newts;
+ }
memcpy(&netinteger, *msg_cur, sizeof(netinteger));
netinteger = ntohl(netinteger);
@@ -1412,8 +1496,13 @@
*msg_cur += sizeof(netinteger);
}
else {
- if (*msg_cur + st->table->key_size > msg_end)
+ if (*msg_cur + st->table->key_size > msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, msg_end, &st->table->key_size);
goto malformed_free_newts;
+ }
memcpy(newts->key.key, *msg_cur, st->table->key_size);
*msg_cur += st->table->key_size;
@@ -1435,8 +1524,10 @@
continue;
decoded_int = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p);
goto malformed_unlock;
+ }
switch (stktable_data_types[data_type].std_type) {
case STD_T_SINT:
@@ -1467,12 +1558,16 @@
data.curr_tick = tick_add(now_ms, -decoded_int) & ~0x1;
data.curr_ctr = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p);
goto malformed_unlock;
+ }
data.prev_ctr = intdecode(msg_cur, msg_end);
- if (!*msg_cur)
+ if (!*msg_cur) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p);
goto malformed_unlock;
+ }
data_ptr = stktable_data_ptr(st->table, ts, data_type);
if (data_ptr)
@@ -1492,21 +1587,31 @@
break;
}
data_len = decoded_int;
- if (*msg_cur + data_len > msg_end)
+ if (*msg_cur + data_len > msg_end) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, msg_end, &data_len);
goto malformed_unlock;
+ }
/* Compute the end of the current data, <msg_end> being at the end of
* the entire message.
*/
end = *msg_cur + data_len;
id = intdecode(msg_cur, end);
- if (!*msg_cur || !id)
+ if (!*msg_cur || !id) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur, &id);
goto malformed_unlock;
+ }
dc = p->dcache;
if (*msg_cur == end) {
/* Dictionary entry key without value. */
if (id > dc->max_entries) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, NULL, &id);
goto malformed_unlock;
}
/* IDs sent over the network are numbered from 1. */
@@ -1516,8 +1621,13 @@
chunk = get_trash_chunk();
value_len = intdecode(msg_cur, end);
if (!*msg_cur || *msg_cur + value_len > end ||
- unlikely(value_len + 1 >= chunk->size))
+ unlikely(value_len + 1 >= chunk->size)) {
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, *msg_cur, &value_len);
+ TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG,
+ NULL, p, end, &chunk->size);
goto malformed_unlock;
+ }
chunk_memcpy(chunk, *msg_cur, value_len);
chunk->area[chunk->data] = '\0';
@@ -1540,11 +1650,13 @@
HA_RWLOCK_WRUNLOCK(STK_SESS_LOCK, &ts->lock);
stktable_touch_remote(st->table, ts, 1);
+ TRACE_LEAVE(PEERS_EV_UPDTMSG, NULL, p);
return 1;
ignore_msg:
/* skip consumed message */
co_skip(si_oc(si), totl);
+ TRACE_DEVEL("leaving in error", PEERS_EV_UPDTMSG);
return 0;
malformed_unlock:
@@ -1552,6 +1664,7 @@
HA_RWLOCK_WRUNLOCK(STK_SESS_LOCK, &ts->lock);
stktable_touch_remote(st->table, ts, 1);
appctx->st0 = PEER_SESS_ST_ERRPROTO;
+ TRACE_DEVEL("leaving in error", PEERS_EV_UPDTMSG);
return 0;
malformed_free_newts:
@@ -1559,6 +1672,7 @@
stksess_free(st->table, newts);
malformed_exit:
appctx->st0 = PEER_SESS_ST_ERRPROTO;
+ TRACE_DEVEL("leaving in error", PEERS_EV_UPDTMSG);
return 0;
}
@@ -1760,6 +1874,7 @@
goto incomplete;
/* malformed message */
+ TRACE_PROTO("malformed message: too large length encoding", PEERS_EV_UPDTMSG);
appctx->st0 = PEER_SESS_ST_ERRPROTO;
return -1;
}