From: Christopher Faulet Date: Wed, 24 Sep 2025 15:49:05 +0000 (+0200) Subject: MINOR: peers: Improve traces for peers X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=76581c7bb70ec5cce9fb627c821e8a253031c698;p=thirdparty%2Fhaproxy.git MINOR: peers: Improve traces for peers Trace messages for peers were only protocol oriented and information provided were quite light. With this patch, the traces were improved. information about the peer, its applet and the section are dumped. Several verbosities are now available and messages are dumped at different levels depending on the context. It should easier to track issues in the peers. --- diff --git a/src/peers.c b/src/peers.c index 94abe58aa..45779f64a 100644 --- a/src/peers.c +++ b/src/peers.c @@ -274,34 +274,79 @@ 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); +static const char *statuscode_str(int statuscode); +static const char *peer_app_state_str(enum peer_app_state appstate); +static const char *peer_learn_state_str(enum peer_learn_state learnstate); +static const char *peer_applet_state_str(int state); + 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" }, +#define PEERS_EV_SESS_NEW (1ULL << 0) + { .mask = PEERS_EV_SESS_NEW, .name = "sess_new", .desc = "create new peer session" }, +#define PEERS_EV_SESS_END (1ULL << 1) + { .mask = PEERS_EV_SESS_END, .name = "sess_end", .desc = "peer session terminated" }, +#define PEERS_EV_SESS_ERR (1ULL << 2) + { .mask = PEERS_EV_SESS_ERR, .name = "sess_err", .desc = "error on peer session" }, +#define PEERS_EV_SESS_SHUT (1ULL << 3) + { .mask = PEERS_EV_SESS_SHUT, .name = "sess_shut", .desc = "peer session shutdown" }, +#define PEERS_EV_SESS_WAKE (1ULL << 4) + { .mask = PEERS_EV_SESS_WAKE, .name = "sess_wakeup", .desc = "peer session wakeup" }, +#define PEERS_EV_SESS_RESYNC (1ULL << 5) + { .mask = PEERS_EV_SESS_RESYNC, .name = "sess_resync", .desc = "peer session resync" }, +#define PEERS_EV_SESS_IO (1ULL << 6) + { .mask = PEERS_EV_SESS_IO, .name = "sess_io", .desc = "peer session I/O" }, + +#define PEERS_EV_RX_MSG (1ULL << 7) + { .mask = PEERS_EV_RX_MSG, .name = "rx_msg", .desc = "message received" }, +#define PEERS_EV_RX_BLK (1ULL << 8) + { .mask = PEERS_EV_RX_BLK, .name = "rx_blocked", .desc = "receive blocked" }, +#define PEERS_EV_RX_ERR (1ULL << 9) + { .mask = PEERS_EV_RX_ERR, .name = "rx_error", .desc = "receive error" }, + +#define PEERS_EV_TX_MSG (1ULL << 10) + { .mask = PEERS_EV_TX_MSG, .name = "tx_msg", .desc = "message sent" }, +#define PEERS_EV_TX_BLK (1ULL << 11) + { .mask = PEERS_EV_TX_BLK, .name = "tx_blocked", .desc = "send blocked" }, +#define PEERS_EV_TX_ERR (1ULL << 12) + { .mask = PEERS_EV_TX_ERR, .name = "tx_error", .desc = "send error" }, + + +#define PEERS_EV_PROTO_ERR (1ULL << 13) + { .mask = PEERS_EV_PROTO_ERR, .name = "proto_error", .desc = "protocol error" }, +#define PEERS_EV_PROTO_HELLO (1ULL << 14) + { .mask = PEERS_EV_PROTO_HELLO, .name = "proto_hello", .desc = "protocol hello mesage" }, +#define PEERS_EV_PROTO_SUCCESS (1ULL << 15) + { .mask = PEERS_EV_PROTO_SUCCESS, .name = "proto_success", .desc = "protocol success message" }, +#define PEERS_EV_PROTO_UPDATE (1ULL << 16) + { .mask = PEERS_EV_PROTO_UPDATE, .name = "proto_update", .desc = "protocol UPDATE message" }, +#define PEERS_EV_PROTO_ACK (1ULL << 17) + { .mask = PEERS_EV_PROTO_ACK, .name = "proto_ack", .desc = "protocol ACK message" }, +#define PEERS_EV_PROTO_SWITCH (1ULL << 18) + { .mask = PEERS_EV_PROTO_SWITCH, .name = "proto_switch", .desc = "protocol TABLE SWITCH message" }, +#define PEERS_EV_PROTO_DEF (1ULL << 19) + { .mask = PEERS_EV_PROTO_DEF, .name = "proto_def", .desc = "protocol TABLE DEFINITION message" }, +#define PEERS_EV_PROTO_CTRL (1ULL << 20) + { .mask = PEERS_EV_PROTO_CTRL, .name = "proto_crtl", .desc = "protocol control message" }, { } }; static const struct name_desc peers_trace_lockon_args[4] = { - /* arg1 */ { /* already used by the connection */ }, - /* arg2 */ { .name="peers", .desc="Peers protocol" }, - /* arg3 */ { }, + /* arg1 */ { /* already used by the appctx */ }, + /* arg2 */ { .name="peer", .desc="Peer" }, + /* arg3 */ { .name="peers", .desc="Peers" }, /* 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\"" }, +#define PEERS_VERB_MINIMAL 2 + { .name="minimal", .desc="report only peer state and flags, no real decoding" }, +#define PEERS_VERB_SIMPLE 3 + { .name="simple", .desc="add simple info about messages when available" }, +#define PEERS_VERB_ADVANCED 4 + { .name="advanced", .desc="add more info about messages when available" }, +#define PEERS_VERB_COMPLETE 5 + { .name="complete", .desc="add full data dump when available" }, { /* end */ } }; @@ -309,7 +354,7 @@ static const struct name_desc peers_trace_decoding[] = { struct trace_source trace_peers = { .name = IST("peers"), .desc = "Peers protocol", - .arg_def = TRC_ARG1_CONN, /* TRACE()'s first argument is always a connection */ + .arg_def = TRC_ARG1_APPCTX, .default_cb = peers_trace, .known_events = peers_trace_events, .lockon_args = peers_trace_lockon_args, @@ -344,81 +389,69 @@ 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|PEERS_EV_ACKMSG|PEERS_EV_SWTCMSG)) { - 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); - } - } - - 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; + const struct appctx *appctx = a1; + const struct peer *peer = a2; + const struct peers *peers = NULL; + const struct shared_table *st = a3; + + if (!peer && appctx) + peer = appctx->svcctx; + if (!peer || src->verbosity < PEERS_VERB_CLEAN) + return; + if (!peers) + peers = peer->peers; + if (!appctx) + appctx = peer->appctx; - chunk_appendf(&trace_buf, " %d", *val); - } - } + chunk_appendf(&trace_buf, " : [%c,%s] <%s/%s> ", + (appctx ? (appctx_is_back(appctx) ? 'B' : 'F') : '-'), + (appctx ? peer_applet_state_str(appctx->st0) : "-"), + peers->id, peer->id); - if (mask & PEERS_EV_CTRLMSG) { - if (a2) { - const unsigned char *ctrl_msg_type = a2; + if (peer->local) + chunk_appendf(&trace_buf, "RELOADING(%s) ", stopping ? "old" : "new"); - chunk_appendf(&trace_buf, " %s", ctrl_msg_type_str(*ctrl_msg_type)); + if (src->verbosity == PEERS_VERB_CLEAN) + return; - } - if (a3) { - const char *local_peer = a3; + chunk_appendf(&trace_buf, "peer=(.fl=0x%08x, .app=%s, .learn=%s, status=%s, ", + peer->flags, peer_app_state_str(peer->appstate), peer_learn_state_str(peer->learnstate), + statuscode_str(peer->statuscode)); - chunk_appendf(&trace_buf, " %s", local_peer); - } + chunk_appendf(&trace_buf, ".reco=%s, ", (peer->reconnect + ? (tick_is_expired(peer->reconnect, now_ms) + ? "" + : human_time(TICKS_TO_MS(peer->reconnect - now_ms), TICKS_TO_MS(1000))) + : "")); - if (a4) { - const char *remote_peer = a4; + chunk_appendf(&trace_buf, ".heart=%s, ", (peer->heartbeat + ? (tick_is_expired(peer->heartbeat, now_ms) + ? "" + : human_time(TICKS_TO_MS(peer->heartbeat - now_ms), TICKS_TO_MS(1000))) + : "")); - chunk_appendf(&trace_buf, " -> %s", remote_peer); - } - } + chunk_appendf(&trace_buf, ".last_hdshk=%s) ", (peer->last_hdshk + ? (tick_is_expired(peer->last_hdshk, now_ms) + ? "" + : human_time(TICKS_TO_MS(peer->last_hdshk - now_ms), TICKS_TO_MS(1000))) + : "")); - if (mask & (PEERS_EV_SESSREL|PEERS_EV_PROTOERR)) { - if (a2) { - const struct peer *peer = a2; - struct peers *peers = NULL; + if (st) + chunk_appendf(&trace_buf, "st=(.id=%s, .fl=0x%08x) ", st->table->id, st->flags); - if (peer->appctx) - peers = peer->peers; + if (src->verbosity == PEERS_VERB_MINIMAL) + return; - if (peers) - chunk_appendf(&trace_buf, " %s", peers->local->id); - chunk_appendf(&trace_buf, " -> %s", peer->id); - } + if (appctx) + chunk_appendf(&trace_buf, "appctx=(.fl=0x%08x, .st0=%d, .st1=%d) ", + appctx->flags, appctx->st0, appctx->st1); - if (a3) { - const int *prev_state = a3; + if (peers) + chunk_appendf(&trace_buf, "peers=(.fl=0x%08x, local=%s) ", + peers->flags, peers->local->id); - chunk_appendf(&trace_buf, " prev_state=%d\n", *prev_state); - } - } + if (src->verbosity == PEERS_VERB_SIMPLE) + return; } static const char *statuscode_str(int statuscode) @@ -477,6 +510,25 @@ static const char *peer_learn_state_str(enum peer_learn_state learnstate) } } +static const char *peer_applet_state_str(int state) +{ + switch (state) { + case PEER_SESS_ST_ACCEPT: return "ACCEPT"; + case PEER_SESS_ST_GETVERSION: return "GETVERSION"; + case PEER_SESS_ST_GETHOST: return "GETHOST"; + case PEER_SESS_ST_GETPEER: return "GETPEER"; + case PEER_SESS_ST_SENDSUCCESS: return "SENDSUCCESS"; + case PEER_SESS_ST_CONNECT: return "CONNECT"; + case PEER_SESS_ST_GETSTATUS: return "GETSTATUS"; + case PEER_SESS_ST_WAITMSG: return "WAITMSG"; + case PEER_SESS_ST_EXIT: return "EXIT"; + case PEER_SESS_ST_ERRPROTO: return "ERRPROTO"; + case PEER_SESS_ST_ERRSIZE: return "ERRSIZE"; + case PEER_SESS_ST_END: return "END"; + default: return "UNKNOWN"; + } +} + /* This function encode an uint64 to 'dynamic' length format. The encoded value is written at address *str, and the caller must assure that size after *str is large enough. @@ -1054,7 +1106,7 @@ void __peer_session_deinit(struct peer *peer) /* Mark the peer as stopping and wait for the sync task */ peer->flags |= PEER_F_WAIT_SYNCTASK_ACK; peer->appstate = PEER_APP_ST_STOPPING; - + TRACE_STATE("peer session stopping", PEERS_EV_SESS_END, peer->appctx, peer); task_wakeup(peers->sync_task, TASK_WOKEN_MSG); } @@ -1064,6 +1116,7 @@ static int peer_session_init(struct appctx *appctx) struct stream *s; struct sockaddr_storage *addr = NULL; + TRACE_ENTER(PEERS_EV_SESS_NEW, appctx, peer); if (!sockaddr_alloc(&addr, &peer->srv->addr, sizeof(peer->srv->addr))) goto out_error; set_host_port(addr, peer->srv->svc_port); @@ -1084,13 +1137,14 @@ static int peer_session_init(struct appctx *appctx) s->do_log = NULL; s->uniq_id = 0; - _HA_ATOMIC_INC(&active_peers); + TRACE_LEAVE(PEERS_EV_SESS_NEW, appctx, peer); return 0; out_free_addr: sockaddr_free(&addr); out_error: + TRACE_ERROR("peer session init failed", PEERS_EV_SESS_NEW|PEERS_EV_SESS_END|PEERS_EV_SESS_ERR, NULL, peer); return -1; } @@ -1101,7 +1155,6 @@ static void peer_session_release(struct appctx *appctx) { struct peer *peer = appctx->svcctx; - TRACE_PROTO("releasing peer session", PEERS_EV_SESSREL, NULL, peer); /* appctx->svcctx is not a peer session */ if (appctx->st0 < PEER_SESS_ST_SENDSUCCESS) return; @@ -1113,6 +1166,7 @@ static void peer_session_release(struct appctx *appctx) __peer_session_deinit(peer); peer->flags &= ~PEER_F_ALIVE; HA_SPIN_UNLOCK(PEER_LOCK, &peer->lock); + TRACE_STATE("peer session released", PEERS_EV_SESS_END, appctx, peer); } } @@ -1153,21 +1207,23 @@ static int peer_get_version(const char *str, */ static inline int peer_getline(struct appctx *appctx) { - int n; + int n = 0; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx); if (applet_get_inbuf(appctx) == NULL || !applet_input_data(appctx)) { applet_need_more_data(appctx); - return 0; + goto out; } n = applet_getline(appctx, trash.area, trash.size); if (!n) { applet_need_more_data(appctx); - return 0; + goto out; } if (n < 0 || trash.area[n - 1] != '\n') { appctx->st0 = PEER_SESS_ST_END; + TRACE_ERROR("failed to receive data (channel closed or full)", PEERS_EV_SESS_IO|PEERS_EV_RX_ERR, appctx); return -1; } @@ -1177,6 +1233,8 @@ static inline int peer_getline(struct appctx *appctx) trash.area[n - 1] = 0; applet_skip_input(appctx, n); + out: + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx); return n; } @@ -1193,20 +1251,25 @@ static inline int peer_send_msg(struct appctx *appctx, { int ret, msglen; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_TX_MSG, appctx); msglen = peer_prepare_msg(trash.area, trash.size, params); if (!msglen) { /* internal error: message does not fit in trash */ appctx->st0 = PEER_SESS_ST_END; + TRACE_ERROR("failed to send data (message too long)", PEERS_EV_SESS_IO|PEERS_EV_TX_ERR, appctx); return 0; } /* message to buffer */ ret = applet_putblk(appctx, trash.area, msglen); if (ret <= 0) { - if (ret != -1) + if (ret != -1) { + TRACE_ERROR("failed to send data (channel closed)", PEERS_EV_SESS_IO|PEERS_EV_TX_ERR, appctx); appctx->st0 = PEER_SESS_ST_END; + } } + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_TX_MSG, appctx); return ret; } @@ -1223,6 +1286,7 @@ static inline int peer_send_hellomsg(struct appctx *appctx, struct peer *peer) .hello.peer = peer, }; + TRACE_PROTO("send hello message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_HELLO, appctx, peer); return peer_send_msg(appctx, peer_prepare_hellomsg, &p); } @@ -1235,6 +1299,7 @@ static inline int peer_send_hellomsg(struct appctx *appctx, struct peer *peer) */ static inline int peer_send_status_successmsg(struct appctx *appctx) { + TRACE_PROTO("send status sucess message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_SUCCESS, appctx); return peer_send_msg(appctx, peer_prepare_status_successmsg, NULL); } @@ -1251,6 +1316,7 @@ static inline int peer_send_status_errormsg(struct appctx *appctx) .error_status.st1 = appctx->st1, }; + TRACE_PROTO("send status error message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_ERR, appctx); return peer_send_msg(appctx, peer_prepare_status_errormsg, &p); } @@ -1267,6 +1333,7 @@ static inline int peer_send_switchmsg(struct shared_table *st, struct appctx *ap .swtch.shared_table = st, }; + TRACE_PROTO("send table switch message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_SWITCH, appctx, NULL, st); return peer_send_msg(appctx, peer_prepare_switchmsg, &p); } @@ -1283,6 +1350,7 @@ static inline int peer_send_ackmsg(struct shared_table *st, struct appctx *appct .ack.shared_table = st, }; + TRACE_PROTO("send ack message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_ACK, appctx, NULL, st); return peer_send_msg(appctx, peer_prepare_ackmsg, &p); } @@ -1307,6 +1375,7 @@ static inline int peer_send_updatemsg(struct shared_table *st, struct appctx *ap }, }; + TRACE_PROTO("send update message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_UPDATE, appctx, NULL, st); return peer_send_msg(appctx, peer_prepare_updatemsg, &p); } @@ -1340,9 +1409,7 @@ static inline int peer_send_resync_reqmsg(struct appctx *appctx, .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); - + TRACE_PROTO("send resync request message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); return peer_send_msg(appctx, peer_prepare_control_msg, &p); } @@ -1360,9 +1427,7 @@ static inline int peer_send_resync_confirmsg(struct appctx *appctx, .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); - + TRACE_PROTO("send resync confirm message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); return peer_send_msg(appctx, peer_prepare_control_msg, &p); } @@ -1383,9 +1448,7 @@ static inline int peer_send_resync_finishedmsg(struct appctx *appctx, p.control.head[1] = (HA_ATOMIC_LOAD(&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); - + TRACE_PROTO("send full resync finish message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); return peer_send_msg(appctx, peer_prepare_control_msg, &p); } @@ -1403,9 +1466,7 @@ static inline int peer_send_heartbeatmsg(struct appctx *appctx, .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); - + TRACE_PROTO("send heartbeat message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); return peer_send_msg(appctx, peer_prepare_control_msg, &p); } @@ -1438,6 +1499,7 @@ static inline int peer_send_error_size_limitmsg(struct appctx *appctx) .error.head = { PEER_MSG_CLASS_ERROR, PEER_MSG_ERR_SIZELIMIT, }, }; + TRACE_PROTO("send error size limit message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_ERR, appctx); return peer_send_msg(appctx, peer_prepare_error_msg, &p); } @@ -1454,6 +1516,7 @@ static inline int peer_send_error_protomsg(struct appctx *appctx) .error.head = { PEER_MSG_CLASS_ERROR, PEER_MSG_ERR_PROTOCOL, }, }; + TRACE_PROTO("send protocol error message", PEERS_EV_SESS_IO|PEERS_EV_TX_MSG|PEERS_EV_PROTO_ERR, appctx); return peer_send_msg(appctx, peer_prepare_error_msg, &p); } @@ -1558,12 +1621,14 @@ int peer_send_teachmsgs(struct appctx *appctx, struct peer *p, int updates_sent = 0; int failed_once = 0; + TRACE_ENTER(PEERS_EV_SESS_IO, appctx, p, st); + ret = 1; use_timed = 0; if (st != p->last_local_table) { ret = peer_send_switchmsg(st, appctx); if (ret <= 0) - return ret; + goto out; p->last_local_table = st; } @@ -1653,6 +1718,7 @@ int peer_send_teachmsgs(struct appctx *appctx, struct peer *p, out: HA_RWLOCK_RDUNLOCK(STK_TABLE_UPDT_LOCK, &st->table->updt_lock); out_unlocked: + TRACE_LEAVE(PEERS_EV_SESS_IO, appctx, p, st); return ret; } @@ -1671,6 +1737,7 @@ int peer_send_teachmsgs(struct appctx *appctx, struct peer *p, static inline int peer_send_teach_process_msgs(struct appctx *appctx, struct peer *p, struct shared_table *st) { + TRACE_PROTO("send teach process messages", PEERS_EV_SESS_IO, appctx, p, st); return peer_send_teachmsgs(appctx, p, peer_teach_process_stksess_lookup, st); } @@ -1687,6 +1754,7 @@ static inline int peer_send_teach_process_msgs(struct appctx *appctx, struct pee static inline int peer_send_teach_stage1_msgs(struct appctx *appctx, struct peer *p, struct shared_table *st) { + TRACE_PROTO("send teach stage1 messages", PEERS_EV_SESS_IO, appctx, p, st); return peer_send_teachmsgs(appctx, p, peer_teach_stage1_stksess_lookup, st); } @@ -1703,6 +1771,7 @@ static inline int peer_send_teach_stage1_msgs(struct appctx *appctx, struct peer static inline int peer_send_teach_stage2_msgs(struct appctx *appctx, struct peer *p, struct shared_table *st) { + TRACE_PROTO("send teach stage2 messages", PEERS_EV_SESS_IO, appctx, p, st); return peer_send_teachmsgs(appctx, p, peer_teach_stage2_stksess_lookup, st); } @@ -1733,10 +1802,13 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex void *data_ptr; char *msg_save; - TRACE_ENTER(PEERS_EV_UPDTMSG, NULL, p); + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_UPDATE, appctx, p, st); + /* Here we have data message */ - if (!st) + if (!st) { + TRACE_PROTO("ignore update message: no remote table", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_UPDATE, appctx, p); goto ignore_msg; + } table = st->table; @@ -1744,7 +1816,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex if (updt) { if (msg_len < sizeof(update)) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: message too small", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_exit; } @@ -1760,10 +1832,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex size_t expire_sz = sizeof expire; 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); + TRACE_ERROR("malformed update message: wrong expiration size", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_exit; } @@ -1778,24 +1847,23 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex } newts = stksess_new(table, NULL); - if (!newts) + if (!newts) { + TRACE_PROTO("ignore update message: failed to get a new sticky session", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_UPDATE, appctx, p, st); goto ignore_msg; + } if (table->type == SMP_T_STR) { unsigned int to_read, to_store; to_read = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid string length", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_free_newts; } to_store = MIN(to_read, table->key_size - 1); 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); + TRACE_ERROR("malformed update message: invalid string (too big)", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_free_newts; } @@ -1808,10 +1876,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex unsigned int netinteger; 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); + TRACE_ERROR("malformed update message: invalid integer (too big)", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_free_newts; } @@ -1823,10 +1888,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex } else { if (*msg_cur + 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, &table->key_size); + TRACE_ERROR("malformed update message: invalid key (too big)", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_free_newts; } @@ -1881,7 +1943,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex for (idx = 0; idx < st->remote_data_nbelem[data_type]; idx++) { decoded_int = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid integer data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -1894,7 +1956,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex for (idx = 0; idx < st->remote_data_nbelem[data_type]; idx++) { decoded_int = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid unsigned integer data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -1907,7 +1969,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex for (idx = 0; idx < st->remote_data_nbelem[data_type]; idx++) { decoded_int = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid unsigned long data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -1928,20 +1990,21 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex decoded_int = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid freq_ctr data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); + /* TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); */ goto malformed_unlock; } data.curr_tick = tick_add(now_ms, -decoded_int) & ~0x1; data.curr_ctr = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid freq_ctr data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } data.prev_ctr = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid freq_ctr data", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -1959,7 +2022,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex } decoded_int = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid data value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -1994,13 +2057,13 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex data.curr_tick = tick_add(now_ms, -decoded_int) & ~0x1; data.curr_ctr = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid freq_ctr value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } data.prev_ctr = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, NULL, p); + TRACE_ERROR("malformed update message: invalid freq_ctr value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -2023,10 +2086,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex } data_len = decoded_int; 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); + TRACE_ERROR("malformed update message: invalid dict value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -2036,8 +2096,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex end = *msg_cur + data_len; id = intdecode(msg_cur, end); if (!*msg_cur || !id) { - TRACE_PROTO("malformed message", PEERS_EV_UPDTMSG, - NULL, p, *msg_cur, &id); + TRACE_ERROR("malformed update message: invalid dict value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -2045,8 +2104,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex 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); + TRACE_ERROR("malformed update message: invalid dict value", PEERS_EV_SESS_IO|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } /* IDs sent over the network are numbered from 1. */ @@ -2057,10 +2115,7 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex value_len = intdecode(msg_cur, end); if (!*msg_cur || *msg_cur + value_len > end || 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); + TRACE_ERROR("malformed update message: invalid dict value", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); goto malformed_unlock; } @@ -2129,24 +2184,24 @@ int peer_treat_updatemsg(struct appctx *appctx, struct peer *p, int updt, int ex goto update_wts; } + + ignore_msg: - TRACE_LEAVE(PEERS_EV_UPDTMSG, NULL, p); + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_UPDATE, appctx, p, st); return 1; malformed_unlock: /* malformed message */ 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; + goto malformed_exit; malformed_free_newts: /* malformed message */ stksess_free(st->table, newts); malformed_exit: appctx->st0 = PEER_SESS_ST_ERRPROTO; - TRACE_DEVEL("leaving in error", PEERS_EV_UPDTMSG); + TRACE_DEVEL("leaving in error", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p, st); return 0; } @@ -2165,19 +2220,21 @@ static inline int peer_treat_ackmsg(struct appctx *appctx, struct peer *p, uint32_t table_id ; uint32_t update; struct shared_table *st; + int ret = 1; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ACK, appctx, p); /* ignore ack during teaching process */ - if (p->flags & PEER_F_TEACH_PROCESS) - return 1; + if (p->flags & PEER_F_TEACH_PROCESS) { + TRACE_DEVEL("Ignore ack during teaching process", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ACK, appctx, p); + goto end; + } 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); + TRACE_ERROR("malformed ackk message: no table id", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); appctx->st0 = PEER_SESS_ST_ERRPROTO; - return 0; + ret = 0; + goto end; } memcpy(&update, *msg_cur, sizeof(update)); @@ -2190,7 +2247,9 @@ static inline int peer_treat_ackmsg(struct appctx *appctx, struct peer *p, } } - return 1; + end: + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ACK, appctx, p, st); + return ret; } /* @@ -2207,10 +2266,10 @@ static inline int peer_treat_switchmsg(struct appctx *appctx, struct peer *p, struct shared_table *st; int table_id; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_SWITCH, appctx, p); table_id = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_SWTCMSG, NULL, p); - /* malformed message */ + TRACE_ERROR("malformed table switch message: no table id", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); appctx->st0 = PEER_SESS_ST_ERRPROTO; return 0; } @@ -2223,6 +2282,7 @@ static inline int peer_treat_switchmsg(struct appctx *appctx, struct peer *p, } } + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_SWITCH, appctx, p, st); return 1; } @@ -2245,21 +2305,22 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, int table_id; uint64_t table_data; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); table_id = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p); + TRACE_ERROR("malformed table definition message: no table id", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } table_id_len = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p, *msg_cur); + TRACE_ERROR("malformed table definition message: no table name length", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } p->remote_table = NULL; 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); + TRACE_ERROR("malformed table definition message: no table name", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } @@ -2274,38 +2335,38 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, } if (!p->remote_table) { - TRACE_PROTO("ignored message", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: table not found", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } *msg_cur += table_id_len; if (*msg_cur >= msg_end) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p); + TRACE_ERROR("malformed table definition message: truncated message", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } table_type = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p); + TRACE_ERROR("malformed table definition message: no table type", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } table_keylen = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p); + TRACE_ERROR("malformed table definition message: no key length", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); goto malformed_exit; } table_data = intdecode(msg_cur, msg_end); if (!*msg_cur) { - TRACE_PROTO("malformed message", PEERS_EV_DEFMSG, NULL, p); + TRACE_ERROR("malformed table definition message: no data type", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, 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); + TRACE_PROTO("ignore table definition message: no key/type match", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } @@ -2328,14 +2389,14 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, type = intdecode(msg_cur, msg_end); if (!*msg_cur) { p->remote_table = NULL; - TRACE_PROTO("missing meta data for array", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: missing meta data for array", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } /* check if the data_type match the current from the bitfield */ if (type != data_type) { p->remote_table = NULL; - TRACE_PROTO("meta data mismatch type", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: meta data mismatch type", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } @@ -2343,7 +2404,7 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, p->remote_table->remote_data_nbelem[type] = intdecode(msg_cur, msg_end); if (!*msg_cur) { p->remote_table = NULL; - TRACE_PROTO("missing array size meta data for array", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: missing array size meta data for array", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } @@ -2352,7 +2413,7 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, intdecode(msg_cur, msg_end); if (!*msg_cur) { p->remote_table = NULL; - TRACE_PROTO("missing period for frqp", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: missing period for frqp", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } } @@ -2365,14 +2426,14 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, type = intdecode(msg_cur, msg_end); if (!*msg_cur) { p->remote_table = NULL; - TRACE_PROTO("missing meta data for frqp", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: missing data for frqp", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } /* check if the data_type match the current from the bitfield */ if (type != data_type) { p->remote_table = NULL; - TRACE_PROTO("meta data mismatch type", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: meta data mismatch", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } @@ -2380,7 +2441,7 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, intdecode(msg_cur, msg_end); if (!*msg_cur) { p->remote_table = NULL; - TRACE_PROTO("missing period for frqp", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: mismatch period for frqp", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } } @@ -2399,7 +2460,7 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, if (table_data & (1ULL << data_type)) { if (stktable_data_types[data_type].is_array) { p->remote_table = NULL; - TRACE_PROTO("missing array size meta data for array", PEERS_EV_DEFMSG, NULL, p); + TRACE_PROTO("ignore table definition message: missing array size meta data for array", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); goto ignore_msg; } } @@ -2410,11 +2471,13 @@ static inline int peer_treat_definemsg(struct appctx *appctx, struct peer *p, p->remote_table->remote_id = table_id; ignore_msg: + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_DEF, appctx, p); return 1; malformed_exit: /* malformed message */ appctx->st0 = PEER_SESS_ST_ERRPROTO; + TRACE_DEVEL("leaving in error", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, p); return 0; } @@ -2436,6 +2499,8 @@ static inline int peer_recv_msg(struct appctx *appctx, char *msg_head, size_t ms int reql; char *cur; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx); + reql = applet_getblk(appctx, msg_head, 2 * sizeof(char), *totl); if (reql <= 0) /* closed or EOL not found */ goto incomplete; @@ -2466,7 +2531,7 @@ static inline int peer_recv_msg(struct appctx *appctx, char *msg_head, size_t ms goto incomplete; /* malformed message */ - TRACE_PROTO("malformed message: too large length encoding", PEERS_EV_UPDTMSG); + TRACE_PROTO("malformed message: bad message length encoding", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); appctx->st0 = PEER_SESS_ST_ERRPROTO; return -1; } @@ -2477,6 +2542,7 @@ static inline int peer_recv_msg(struct appctx *appctx, char *msg_head, size_t ms if (*msg_len > trash.size) { /* Status code is not success, abort */ appctx->st0 = PEER_SESS_ST_ERRSIZE; + TRACE_PROTO("malformed message: too large length encoding", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } @@ -2486,15 +2552,18 @@ static inline int peer_recv_msg(struct appctx *appctx, char *msg_head, size_t ms *totl += reql; } + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx); return 1; incomplete: if (reql < 0 || se_fl_test(appctx->sedesc, SE_FL_SHW)) { /* there was an error or the message was truncated */ appctx->st0 = PEER_SESS_ST_END; + TRACE_ERROR("error or messafe truncated", PEERS_EV_SESS_IO|PEERS_EV_RX_ERR, appctx); return -1; } + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx); return 0; } @@ -2507,13 +2576,13 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee { struct peers *peers = peer->peers; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx, peer); + if (msg_head[0] == PEER_MSG_CLASS_CONTROL) { if (msg_head[1] == PEER_MSG_CTRL_RESYNCREQ) { 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); + TRACE_PROTO("Resync request message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); /* prepare tables for a global push */ for (st = peer->tables; st; st = st->next) { st->teaching_origin = st->last_pushed = st->update; @@ -2525,37 +2594,38 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee /* flag to start to teach lesson */ peer->flags |= (PEER_F_TEACH_PROCESS|PEER_F_DBG_RESYNC_REQUESTED); + TRACE_STATE("peer elected to teach leasson to remote peer", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); } 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); + TRACE_PROTO("Full resync finished message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); if (peer->learnstate == PEER_LR_ST_PROCESSING) { peer->learnstate = PEER_LR_ST_FINISHED; peer->flags |= PEER_F_WAIT_SYNCTASK_ACK; task_wakeup(peers->sync_task, TASK_WOKEN_MSG); + TRACE_STATE("Full resync finished", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); } 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); + TRACE_PROTO("Partial resync finished message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); if (peer->learnstate == PEER_LR_ST_PROCESSING) { peer->learnstate = PEER_LR_ST_FINISHED; peer->flags |= (PEER_F_LEARN_NOTUP2DATE|PEER_F_WAIT_SYNCTASK_ACK); task_wakeup(peers->sync_task, TASK_WOKEN_MSG); + TRACE_STATE("partial resync finished", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); } peer->confirm++; } 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); + TRACE_PROTO("Resync confirm message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); /* If stopping state */ if (stopping) { /* Close session, push resync no more needed */ peer->flags |= PEER_F_LOCAL_TEACH_COMPLETE; appctx->st0 = PEER_SESS_ST_END; + TRACE_STATE("process stopping, stop any resync", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); return 0; } for (st = peer->tables; st; st = st->next) { @@ -2565,20 +2635,22 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee /* reset teaching flags to 0 */ peer->flags &= ~PEER_TEACH_FLAGS; + TRACE_STATE("Stop teaching", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); } 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); + TRACE_PROTO("Heartbeat message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); peer->reconnect = tick_add(now_ms, MS_TO_TICKS(PEER_RECONNECT_TIMEOUT)); peer->rx_hbt++; } } else if (msg_head[0] == PEER_MSG_CLASS_STICKTABLE) { if (msg_head[1] == PEER_MSG_STKT_DEFINE) { + TRACE_PROTO("Table definition message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); if (!peer_treat_definemsg(appctx, peer, msg_cur, msg_end, totl)) return 0; } else if (msg_head[1] == PEER_MSG_STKT_SWITCH) { + TRACE_PROTO("Table switch message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_CTRL, appctx, peer); if (!peer_treat_switchmsg(appctx, peer, msg_cur, msg_end)) return 0; } @@ -2588,6 +2660,7 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee msg_head[1] == PEER_MSG_STKT_INCUPDATE_TIMED) { int update, expire; + TRACE_PROTO("Update message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_UPDATE, appctx, peer); update = msg_head[1] == PEER_MSG_STKT_UPDATE || msg_head[1] == PEER_MSG_STKT_UPDATE_TIMED; expire = msg_head[1] == PEER_MSG_STKT_UPDATE_TIMED || msg_head[1] == PEER_MSG_STKT_INCUPDATE_TIMED; if (!peer_treat_updatemsg(appctx, peer, update, expire, @@ -2596,15 +2669,18 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee } else if (msg_head[1] == PEER_MSG_STKT_ACK) { + TRACE_PROTO("Ack message received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ACK, appctx, peer); if (!peer_treat_ackmsg(appctx, peer, msg_cur, msg_end)) return 0; } } else if (msg_head[0] == PEER_MSG_CLASS_RESERVED) { appctx->st0 = PEER_SESS_ST_ERRPROTO; + TRACE_PROTO("malformed message: reserved", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx, peer); return 0; } + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_RX_MSG, appctx, peer); return 1; } @@ -2636,15 +2712,18 @@ static inline int peer_treat_awaited_msg(struct appctx *appctx, struct peer *pee int peer_send_msgs(struct appctx *appctx, struct peer *peer, struct peers *peers) { - int repl; + int repl = 1; + + TRACE_ENTER(PEERS_EV_SESS_IO, appctx, peer); /* Need to request a resync (only possible for a remote peer at this stage) */ if (peer->learnstate == PEER_LR_ST_ASSIGNED) { BUG_ON(peer->local); repl = peer_send_resync_reqmsg(appctx, peer, peers); if (repl <= 0) - return repl; + goto end; peer->learnstate = PEER_LR_ST_PROCESSING; + TRACE_STATE("Start processing resync", PEERS_EV_SESS_IO|PEERS_EV_SESS_RESYNC, appctx, peer); } /* Nothing to read, now we start to write */ @@ -2667,7 +2746,7 @@ int peer_send_msgs(struct appctx *appctx, if (st->last_get != st->last_acked) { repl = peer_send_ackmsg(st, appctx); if (repl <= 0) - return repl; + goto end; st->last_acked = st->last_get; } @@ -2677,7 +2756,8 @@ int peer_send_msgs(struct appctx *appctx, if (HA_RWLOCK_TRYRDLOCK(STK_TABLE_UPDT_LOCK, &st->table->updt_lock)) { applet_have_more_data(appctx); - return -1; + repl = -1; + goto end; } must_send = (peer->learnstate == PEER_LR_ST_NOTASSIGNED) && (st->last_pushed != st->table->localupdate); HA_RWLOCK_RDUNLOCK(STK_TABLE_UPDT_LOCK, &st->table->updt_lock); @@ -2686,7 +2766,7 @@ int peer_send_msgs(struct appctx *appctx, repl = peer_send_teach_process_msgs(appctx, peer, st); if (repl <= 0) { peer->stop_local_table = peer->last_local_table; - return repl; + goto end; } } } @@ -2695,7 +2775,7 @@ int peer_send_msgs(struct appctx *appctx, repl = peer_send_teach_stage1_msgs(appctx, peer, st); if (repl <= 0) { peer->stop_local_table = peer->last_local_table; - return repl; + goto end; } } @@ -2703,7 +2783,7 @@ int peer_send_msgs(struct appctx *appctx, repl = peer_send_teach_stage2_msgs(appctx, peer, st); if (repl <= 0) { peer->stop_local_table = peer->last_local_table; - return repl; + goto end; } } } @@ -2723,7 +2803,8 @@ int peer_send_msgs(struct appctx *appctx, updates++; if (updates >= peers_max_updates_at_once) { applet_have_more_data(appctx); - return -1; + repl = -1; + goto end; } st = st->next; @@ -2733,22 +2814,26 @@ int peer_send_msgs(struct appctx *appctx, if ((peer->flags & PEER_F_TEACH_PROCESS) && !(peer->flags & PEER_F_TEACH_FINISHED)) { repl = peer_send_resync_finishedmsg(appctx, peer, peers); if (repl <= 0) - return repl; + goto end; /* flag finished message sent */ peer->flags |= PEER_F_TEACH_FINISHED; + TRACE_STATE("full/partial resync finished", PEERS_EV_SESS_IO|PEERS_EV_SESS_RESYNC, appctx, peer); } /* Confirm finished or partial messages */ while (peer->confirm) { repl = peer_send_resync_confirmsg(appctx, peer, peers); if (repl <= 0) - return repl; - + goto end; + TRACE_STATE("Confirm resync is finished", PEERS_EV_SESS_IO|PEERS_EV_SESS_RESYNC, appctx, peer); peer->confirm--; } - return 1; + repl = 1; + end: + TRACE_LEAVE(PEERS_EV_SESS_IO, appctx, peer); + return repl; } /* @@ -2772,15 +2857,18 @@ static inline int peer_getline_version(struct appctx *appctx, if (strncmp(PEER_SESSION_PROTO_NAME " ", trash.area, proto_len + 1) != 0) { appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_ERRPROTO; + TRACE_ERROR("protocol error: invalid version line", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } if (peer_get_version(trash.area + proto_len + 1, maj_ver, min_ver) == -1 || *maj_ver != PEER_MAJOR_VER || *min_ver > PEER_MINOR_VER) { appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_ERRVERSION; + TRACE_ERROR("protocol error: invalid version", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } + TRACE_DATA("version line received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_HELLO, appctx); return 1; } @@ -2804,9 +2892,11 @@ static inline int peer_getline_host(struct appctx *appctx) if (strcmp(localpeer, trash.area) != 0) { appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_ERRHOST; + TRACE_ERROR("protocol error: wrong host", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } + TRACE_DATA("host line received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_HELLO, appctx); return 1; } @@ -2835,6 +2925,7 @@ static inline int peer_getline_last(struct appctx *appctx, struct peer **curpeer if (!p) { appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_ERRPROTO; + TRACE_ERROR("protocol error: invalid peer line", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } *p = 0; @@ -2849,10 +2940,12 @@ static inline int peer_getline_last(struct appctx *appctx, struct peer **curpeer if (!peer) { appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_ERRPEER; + TRACE_ERROR("protocol error: unknown peer", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_ERR, appctx); return -1; } *curpeer = peer; + TRACE_DATA("peer line received", PEERS_EV_SESS_IO|PEERS_EV_RX_MSG|PEERS_EV_PROTO_HELLO, appctx, peer); return 1; } @@ -2865,6 +2958,7 @@ static inline void init_connected_peer(struct peer *peer, struct peers *peers) { struct shared_table *st; + TRACE_ENTER(PEERS_EV_SESS_IO|PEERS_EV_SESS_NEW, NULL, peer); peer->heartbeat = tick_add(now_ms, MS_TO_TICKS(PEER_HEARTBEAT_TIMEOUT)); /* Init cursors */ @@ -2913,11 +3007,14 @@ static inline void init_connected_peer(struct peer *peer, struct peers *peers) * on the frontend side), flag it to start to teach lesson. */ peer->flags |= PEER_F_TEACH_PROCESS; + TRACE_STATE("peer elected to teach lesson to lacal peer", PEERS_EV_SESS_NEW, NULL, peer); } /* Mark the peer as starting and wait the sync task */ peer->flags |= PEER_F_WAIT_SYNCTASK_ACK; peer->appstate = PEER_APP_ST_STARTING; + TRACE_STATE("peer session starting", PEERS_EV_SESS_NEW, NULL, peer); + TRACE_LEAVE(PEERS_EV_SESS_IO|PEERS_EV_SESS_NEW, NULL, peer); } /* @@ -2932,6 +3029,8 @@ void peer_io_handler(struct appctx *appctx) int prev_state; int msg_done = 0; + TRACE_ENTER(PEERS_EV_SESS_IO, appctx); + if (unlikely(applet_fl_test(appctx, APPCTX_FL_EOS|APPCTX_FL_ERROR))) { applet_reset_input(appctx); goto out; @@ -2955,6 +3054,7 @@ switchstate: __fallthrough; case PEER_SESS_ST_GETVERSION: prev_state = appctx->st0; + TRACE_STATE("get version line", PEERS_EV_SESS_IO, appctx); reql = peer_getline_version(appctx, &maj_ver, &min_ver); if (reql <= 0) { if (!reql) @@ -2966,6 +3066,7 @@ switchstate: __fallthrough; case PEER_SESS_ST_GETHOST: prev_state = appctx->st0; + TRACE_STATE("get host line", PEERS_EV_SESS_IO, appctx); reql = peer_getline_host(appctx); if (reql <= 0) { if (!reql) @@ -2977,6 +3078,7 @@ switchstate: __fallthrough; case PEER_SESS_ST_GETPEER: { prev_state = appctx->st0; + TRACE_STATE("get peer line", PEERS_EV_SESS_IO, appctx); reql = peer_getline_last(appctx, &curpeer); if (reql <= 0) { if (!reql) @@ -2990,9 +3092,11 @@ switchstate: /* Local connection, reply a retry */ appctx->st0 = PEER_SESS_ST_EXIT; appctx->st1 = PEER_SESS_SC_TRYAGAIN; + TRACE_STATE("local connection, retry", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); goto switchstate; } + TRACE_STATE("release old session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); /* we're killing a connection, we must apply a random delay before * retrying otherwise the other end will do the same and we can loop * for a while. @@ -3024,11 +3128,13 @@ switchstate: curpeer = appctx->svcctx; HA_SPIN_LOCK(PEER_LOCK, &curpeer->lock); if (curpeer->appctx != appctx) { + TRACE_STATE("release old session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); appctx->st0 = PEER_SESS_ST_END; goto switchstate; } } + TRACE_STATE("send success", PEERS_EV_SESS_IO, appctx, curpeer); repl = peer_send_status_successmsg(appctx); if (repl <= 0) { if (repl == -1) @@ -3045,6 +3151,7 @@ switchstate: /* switch to waiting message state */ _HA_ATOMIC_INC(&connected_peers); appctx->st0 = PEER_SESS_ST_WAITMSG; + TRACE_STATE("connected, now wait for messages", PEERS_EV_SESS_IO, appctx, curpeer); goto switchstate; } case PEER_SESS_ST_CONNECT: { @@ -3053,11 +3160,13 @@ switchstate: curpeer = appctx->svcctx; HA_SPIN_LOCK(PEER_LOCK, &curpeer->lock); if (curpeer->appctx != appctx) { + TRACE_STATE("release old session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); appctx->st0 = PEER_SESS_ST_END; goto switchstate; } } + TRACE_STATE("send hello message", PEERS_EV_SESS_IO, appctx, curpeer); repl = peer_send_hellomsg(appctx, curpeer); if (repl <= 0) { if (repl == -1) @@ -3075,11 +3184,13 @@ switchstate: curpeer = appctx->svcctx; HA_SPIN_LOCK(PEER_LOCK, &curpeer->lock); if (curpeer->appctx != appctx) { + TRACE_STATE("release old session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); appctx->st0 = PEER_SESS_ST_END; goto switchstate; } } curpeer->statuscode = PEER_SESS_SC_CONNECTEDCODE; + TRACE_STATE("get status", PEERS_EV_SESS_IO, appctx, curpeer); reql = peer_getline(appctx); if (!reql) @@ -3108,6 +3219,7 @@ switchstate: } _HA_ATOMIC_INC(&connected_peers); appctx->st0 = PEER_SESS_ST_WAITMSG; + TRACE_STATE("connected, now wait for messages", PEERS_EV_SESS_IO, appctx, curpeer); } __fallthrough; case PEER_SESS_ST_WAITMSG: { @@ -3122,6 +3234,7 @@ switchstate: curpeer = appctx->svcctx; HA_SPIN_LOCK(PEER_LOCK, &curpeer->lock); if (curpeer->appctx != appctx) { + TRACE_STATE("release old session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); appctx->st0 = PEER_SESS_ST_END; goto switchstate; } @@ -3129,6 +3242,7 @@ switchstate: if (curpeer->flags & PEER_F_WAIT_SYNCTASK_ACK) { applet_wont_consume(appctx); + TRACE_STATE("peer is waiting for sync task", PEERS_EV_SESS_IO, appctx, curpeer); goto out; } @@ -3147,8 +3261,10 @@ switchstate: applet_will_consume(appctx); /* local peer is assigned of a lesson, start it */ - if (curpeer->learnstate == PEER_LR_ST_ASSIGNED && curpeer->local) + if (curpeer->learnstate == PEER_LR_ST_ASSIGNED && curpeer->local) { curpeer->learnstate = PEER_LR_ST_PROCESSING; + TRACE_STATE("peer starts to learn", PEERS_EV_SESS_IO, appctx, curpeer); + } reql = peer_recv_msg(appctx, (char *)msg_head, sizeof msg_head, &msg_len, &totl); if (reql <= 0) { @@ -3200,6 +3316,7 @@ send_msgs: if (prev_state == PEER_SESS_ST_WAITMSG) _HA_ATOMIC_DEC(&connected_peers); prev_state = appctx->st0; + TRACE_STATE("send status error message", PEERS_EV_SESS_IO|PEERS_EV_SESS_ERR, appctx, curpeer); if (peer_send_status_errormsg(appctx) == -1) goto out; appctx->st0 = PEER_SESS_ST_END; @@ -3208,23 +3325,21 @@ send_msgs: if (prev_state == PEER_SESS_ST_WAITMSG) _HA_ATOMIC_DEC(&connected_peers); prev_state = appctx->st0; + TRACE_STATE("send error size message", PEERS_EV_SESS_IO|PEERS_EV_SESS_ERR, appctx, curpeer); if (peer_send_error_size_limitmsg(appctx) == -1) goto out; appctx->st0 = PEER_SESS_ST_END; 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_DEC(&connected_peers); prev_state = appctx->st0; - if (peer_send_error_protomsg(appctx) == -1) { - TRACE_PROTO("could not send error message", PEERS_EV_PROTOERR); + TRACE_STATE("send proto error message", PEERS_EV_SESS_IO|PEERS_EV_SESS_ERR, appctx, curpeer); + if (peer_send_error_protomsg(appctx) == -1) goto out; - } appctx->st0 = PEER_SESS_ST_END; prev_state = appctx->st0; } @@ -3233,6 +3348,7 @@ send_msgs: if (prev_state == PEER_SESS_ST_WAITMSG) _HA_ATOMIC_DEC(&connected_peers); prev_state = appctx->st0; + TRACE_STATE("Terminate peer session", PEERS_EV_SESS_IO|PEERS_EV_SESS_END, appctx, curpeer); if (curpeer) { HA_SPIN_UNLOCK(PEER_LOCK, &curpeer->lock); curpeer = NULL; @@ -3248,6 +3364,8 @@ out: if (curpeer) HA_SPIN_UNLOCK(PEER_LOCK, &curpeer->lock); + + TRACE_LEAVE(PEERS_EV_SESS_IO, appctx, curpeer); return; } @@ -3282,6 +3400,7 @@ static void peer_session_forceshutdown(struct peer *peer) if (appctx->applet != &peer_applet) return; + TRACE_STATE("peer session shutdown", PEERS_EV_SESS_SHUT|PEERS_EV_SESS_END, appctx, peer); __peer_session_deinit(peer); appctx->st0 = PEER_SESS_ST_END; @@ -3316,6 +3435,8 @@ static struct appctx *peer_session_create(struct peers *peers, struct peer *peer unsigned int thr = 0; int idx; + TRACE_ENTER(PEERS_EV_SESS_NEW, NULL, peer); + peer->new_conn++; peer->reconnect = tick_add(now_ms, (stopping ? MS_TO_TICKS(PEER_LOCAL_RECONNECT_TIMEOUT) : MS_TO_TICKS(PEER_RECONNECT_TIMEOUT))); peer->heartbeat = TICK_ETERNITY; @@ -3325,8 +3446,10 @@ static struct appctx *peer_session_create(struct peers *peers, struct peer *peer for (idx = 0; idx < global.nbthread; idx++) thr = peers->applet_count[idx] < peers->applet_count[thr] ? idx : thr; appctx = appctx_new_on(&peer_applet, NULL, thr); - if (!appctx) + if (!appctx) { + TRACE_ERROR("peer APPCTX creation failed", PEERS_EV_SESS_NEW|PEERS_EV_SESS_END|PEERS_EV_SESS_ERR, NULL, peer); goto out_close; + } appctx->svcctx = (void *)peer; appctx->st0 = PEER_SESS_ST_CONNECT; @@ -3334,6 +3457,8 @@ static struct appctx *peer_session_create(struct peers *peers, struct peer *peer HA_ATOMIC_INC(&peers->applet_count[thr]); appctx_wakeup(appctx); + + TRACE_LEAVE(PEERS_EV_SESS_NEW, appctx, peer); return appctx; out_close: @@ -3371,6 +3496,7 @@ static void sync_peer_learn_state(struct peers *peers, struct peer *peer) /* Partial resync */ flags |= (peer->local ? PEERS_F_DBG_RESYNC_LOCALPARTIAL : PEERS_F_DBG_RESYNC_REMOTEPARTIAL); peers->resync_timeout = tick_add(now_ms, MS_TO_TICKS(PEER_RESYNC_TIMEOUT)); + TRACE_STATE("learning finished, peer session partially resync", PEERS_EV_SESS_RESYNC, NULL, peer); } else { /* Full resync */ @@ -3404,12 +3530,14 @@ static void sync_peer_learn_state(struct peers *peers, struct peer *peer) if (!commit_a_finish) { /* it remains some shard to request, we schedule a new request */ peers->resync_timeout = tick_add(now_ms, MS_TO_TICKS(PEER_RESYNC_TIMEOUT)); + TRACE_STATE("Resync in progress, some shard not resync yet", PEERS_EV_SESS_RESYNC, NULL, peer); } } if (commit_a_finish) { flags |= (PEERS_F_RESYNC_LOCAL_FINISHED|PEERS_F_RESYNC_REMOTE_FINISHED); flags |= (peer->local ? PEERS_F_DBG_RESYNC_LOCALFINISHED : PEERS_F_DBG_RESYNC_REMOTEFINISHED); + TRACE_STATE("learning finished, peer session fully resync", PEERS_EV_SESS_RESYNC, NULL, peer); } } peer->learnstate = PEER_LR_ST_NOTASSIGNED; @@ -3428,6 +3556,7 @@ static void sync_peer_app_state(struct peers *peers, struct peer *peer) if (peer->appstate == PEER_APP_ST_STOPPING) { clear_peer_learning_status(peer); peer->appstate = PEER_APP_ST_STOPPED; + TRACE_STATE("peer session now stopped", PEERS_EV_SESS_END, NULL, peer); } else if (peer->appstate == PEER_APP_ST_STARTING) { clear_peer_learning_status(peer); @@ -3443,6 +3572,7 @@ static void sync_peer_app_state(struct peers *peers, struct peer *peer) /* assign local peer for a lesson */ peer->learnstate = PEER_LR_ST_ASSIGNED; HA_ATOMIC_OR(&peers->flags, PEERS_F_RESYNC_ASSIGN|PEERS_F_DBG_RESYNC_LOCALASSIGN); + TRACE_STATE("peer session assigned for a local resync", PEERS_EV_SESS_RESYNC|PEERS_EV_SESS_WAKE, NULL, peer); } } else if (!peer->local) { @@ -3457,9 +3587,11 @@ static void sync_peer_app_state(struct peers *peers, struct peer *peer) /* assign remote peer for a lesson */ peer->learnstate = PEER_LR_ST_ASSIGNED; HA_ATOMIC_OR(&peers->flags, PEERS_F_RESYNC_ASSIGN|PEERS_F_DBG_RESYNC_REMOTEASSIGN); + TRACE_STATE("peer session assigned for a remote resync", PEERS_EV_SESS_RESYNC|PEERS_EV_SESS_WAKE, NULL, peer); } } peer->appstate = PEER_APP_ST_RUNNING; + TRACE_STATE("peer session running", PEERS_EV_SESS_NEW|PEERS_EV_SESS_WAKE, NULL, peer); appctx_wakeup(peer->appctx); } } @@ -3549,6 +3681,7 @@ static void __process_running_peer_sync(struct task *task, struct peers *peers, /* assign peer for the lesson */ peer->learnstate = PEER_LR_ST_ASSIGNED; HA_ATOMIC_OR(&peers->flags, PEERS_F_RESYNC_ASSIGN|PEERS_F_DBG_RESYNC_REMOTEASSIGN); + TRACE_STATE("peer session assigned for a remote resync", PEERS_EV_SESS_RESYNC|PEERS_EV_SESS_WAKE, NULL, peer); /* wake up peer handler to handle a request of resync */ appctx_wakeup(peer->appctx); @@ -3575,6 +3708,7 @@ static void __process_running_peer_sync(struct task *task, struct peers *peers, /* We are going to send updates, let's ensure we will * come back to send heartbeat messages or to reconnect. */ + TRACE_DEVEL("wakeup peer session to send update", PEERS_EV_SESS_WAKE, NULL, peer); task->expire = tick_first(peer->reconnect, peer->heartbeat); appctx_wakeup(peer->appctx); break; @@ -3590,11 +3724,13 @@ static void __process_running_peer_sync(struct task *task, struct peers *peers, * Flag it as not alive again for the next period. */ peer->flags &= ~PEER_F_ALIVE; + TRACE_STATE("unresponsive peer session detected", PEERS_EV_SESS_SHUT, NULL, peer); peer->reconnect = tick_add(now_ms, MS_TO_TICKS(PEER_RECONNECT_TIMEOUT)); } else { peer->reconnect = tick_add(now_ms, MS_TO_TICKS(50 + ha_random() % 2000)); peer->heartbeat = TICK_ETERNITY; + TRACE_STATE("dead peer session, force shutdown", PEERS_EV_SESS_SHUT, NULL, peer); peer_session_forceshutdown(peer); sync_peer_app_state(peers, peer); peer->no_hbt++; @@ -3603,6 +3739,7 @@ static void __process_running_peer_sync(struct task *task, struct peers *peers, else if (tick_is_expired(peer->heartbeat, now_ms)) { peer->heartbeat = tick_add(now_ms, MS_TO_TICKS(PEER_HEARTBEAT_TIMEOUT)); peer->flags |= PEER_F_HEARTBEAT; + TRACE_DEVEL("wakeup peer session to send heartbeat message", PEERS_EV_SESS_WAKE, NULL, peer); appctx_wakeup(peer->appctx); } task->expire = tick_first(peer->reconnect, peer->heartbeat);