diff --git a/include/haproxy/check.h b/include/haproxy/check.h index 557af0cb5..2756a5fe2 100644 --- a/include/haproxy/check.h +++ b/include/haproxy/check.h @@ -25,6 +25,39 @@ #include #include #include +#include + +extern struct trace_source trace_check; + +/* Details about these events are defined in */ +#define CHK_EV_TASK_WAKE (1ULL << 0) +#define CHK_EV_HCHK_START (1ULL << 1) +#define CHK_EV_HCHK_WAKE (1ULL << 2) +#define CHK_EV_HCHK_RUN (1ULL << 3) +#define CHK_EV_HCHK_END (1ULL << 4) +#define CHK_EV_HCHK_SUCC (1ULL << 5) +#define CHK_EV_HCHK_ERR (1ULL << 6) +#define CHK_EV_HCHK (CHK_EV_HCHK_START|CHK_EV_HCHK_WAKE|CHK_EV_HCHK_RUN|\ + CHK_EV_HCHK_END|CHK_EV_HCHK_SUCC|CHK_EV_HCHK_ERR) + +#define CHK_EV_TCPCHK_EVAL (1ULL << 7) +#define CHK_EV_TCPCHK_ERR (1ULL << 8) +#define CHK_EV_TCPCHK_CONN (1ULL << 9) +#define CHK_EV_TCPCHK_SND (1ULL << 10) +#define CHK_EV_TCPCHK_EXP (1ULL << 11) +#define CHK_EV_TCPCHK_ACT (1ULL << 12) +#define CHK_EV_TCPCHK (CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_ERR|CHK_EV_TCPCHK_CONN|\ + CHK_EV_TCPCHK_SND|CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ACT) + +#define CHK_EV_RX_DATA (1ULL << 13) +#define CHK_EV_RX_BLK (1ULL << 14) +#define CHK_EV_RX_ERR (1ULL << 15) +#define CHK_EV_RX (CHK_EV_RX_DATA|CHK_EV_RX_BLK|CHK_EV_RX_ERR) + +#define CHK_EV_TX_DATA (1ULL << 16) +#define CHK_EV_TX_BLK (1ULL << 17) +#define CHK_EV_TX_ERR (1ULL << 18) +#define CHK_EV_TX (CHK_EV_TX_DATA|CHK_EV_TX_BLK|CHK_EV_TX_ERR) extern struct data_cb check_conn_cb; extern struct proxy checks_fe; diff --git a/include/haproxy/tcpcheck.h b/include/haproxy/tcpcheck.h index 40005a297..4e92b8865 100644 --- a/include/haproxy/tcpcheck.h +++ b/include/haproxy/tcpcheck.h @@ -35,8 +35,8 @@ extern struct action_kw_list tcp_check_keywords; extern struct pool_head *pool_head_tcpcheck_rule; -int tcpcheck_get_step_id(struct check *check, struct tcpcheck_rule *rule); -struct tcpcheck_rule *get_first_tcpcheck_rule(struct tcpcheck_rules *rules); +int tcpcheck_get_step_id(const struct check *check, const struct tcpcheck_rule *rule); +struct tcpcheck_rule *get_first_tcpcheck_rule(const struct tcpcheck_rules *rules); struct tcpcheck_ruleset *create_tcpcheck_ruleset(const char *name); struct tcpcheck_ruleset *find_tcpcheck_ruleset(const char *name); diff --git a/src/check.c b/src/check.c index f4653ac34..4c625efa6 100644 --- a/src/check.c +++ b/src/check.c @@ -65,8 +65,82 @@ #include #include #include +#include #include +/* trace source and events */ +static void check_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); + +/* The event representation is split like this : + * check - check + * + * CHECK_EV_* macros are defined in + */ +static const struct trace_event check_trace_events[] = { + { .mask = CHK_EV_TASK_WAKE, .name = "task_wake", .desc = "Check task woken up" }, + { .mask = CHK_EV_HCHK_START, .name = "hchck_start", .desc = "Health-check started" }, + { .mask = CHK_EV_HCHK_WAKE, .name = "hchck_wake", .desc = "Health-check woken up" }, + { .mask = CHK_EV_HCHK_RUN, .name = "hchck_run", .desc = "Health-check running" }, + { .mask = CHK_EV_HCHK_END, .name = "hchck_end", .desc = "Health-check terminated" }, + { .mask = CHK_EV_HCHK_SUCC, .name = "hchck_succ", .desc = "Health-check success" }, + { .mask = CHK_EV_HCHK_ERR, .name = "hchck_err", .desc = "Health-check failure" }, + + { .mask = CHK_EV_TCPCHK_EVAL, .name = "tcp_check_eval", .desc = "tcp-check rules evaluation" }, + { .mask = CHK_EV_TCPCHK_ERR, .name = "tcp_check_err", .desc = "tcp-check evaluation error" }, + { .mask = CHK_EV_TCPCHK_CONN, .name = "tcp_check_conn", .desc = "tcp-check connection rule" }, + { .mask = CHK_EV_TCPCHK_SND, .name = "tcp_check_send", .desc = "tcp-check send rule" }, + { .mask = CHK_EV_TCPCHK_EXP, .name = "tcp_check_expect", .desc = "tcp-check expect rule" }, + { .mask = CHK_EV_TCPCHK_ACT, .name = "tcp_check_action", .desc = "tcp-check action rule" }, + + { .mask = CHK_EV_RX_DATA, .name = "rx_data", .desc = "receipt of data" }, + { .mask = CHK_EV_RX_BLK, .name = "rx_blk", .desc = "receipt blocked" }, + { .mask = CHK_EV_RX_ERR, .name = "rx_err", .desc = "receipt error" }, + + { .mask = CHK_EV_TX_DATA, .name = "tx_data", .desc = "transmission of data" }, + { .mask = CHK_EV_TX_BLK, .name = "tx_blk", .desc = "transmission blocked" }, + { .mask = CHK_EV_TX_ERR, .name = "tx_err", .desc = "transmission error" }, + + {} +}; + +static const struct name_desc check_trace_lockon_args[4] = { + /* arg1 */ { /* already used by the check */ }, + /* arg2 */ { }, + /* arg3 */ { }, + /* arg4 */ { } +}; + +static const struct name_desc check_trace_decoding[] = { +#define CHK_VERB_CLEAN 1 + { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" }, +#define CHK_VERB_MINIMAL 2 + { .name="minimal", .desc="report info on stream and stream-interfaces" }, +#define CHK_VERB_SIMPLE 3 + { .name="simple", .desc="add info on request and response channels" }, +#define CHK_VERB_ADVANCED 4 + { .name="advanced", .desc="add info on channel's buffer for data and developer levels only" }, +#define CHK_VERB_COMPLETE 5 + { .name="complete", .desc="add info on channel's buffer" }, + { /* end */ } +}; + +struct trace_source trace_check = { + .name = IST("check"), + .desc = "Health-check", + .arg_def = TRC_ARG1_CHK, // TRACE()'s first argument is always a stream + .default_cb = check_trace, + .known_events = check_trace_events, + .lockon_args = check_trace_lockon_args, + .decoding = check_trace_decoding, + .report_events = ~0, // report everything by default +}; + +#define TRACE_SOURCE &trace_check +INITCALL1(STG_REGISTER, trace_register_source, TRACE_SOURCE); + static int wake_srv_chk(struct conn_stream *cs); struct data_cb check_conn_cb = { @@ -78,6 +152,154 @@ struct data_cb check_conn_cb = { /* Dummy frontend used to create all checks sessions. */ struct proxy checks_fe; + +static inline void check_trace_buf(const struct buffer *buf, size_t ofs, size_t len) +{ + size_t block1, block2; + int line, ptr, newptr; + + block1 = b_contig_data(buf, ofs); + block2 = 0; + if (block1 > len) + block1 = len; + block2 = len - block1; + + ofs = b_peek_ofs(buf, ofs); + + line = 0; + ptr = ofs; + while (ptr < ofs + block1) { + newptr = dump_text_line(&trace_buf, b_orig(buf), b_size(buf), ofs + block1, &line, ptr); + if (newptr == ptr) + break; + ptr = newptr; + } + + line = ptr = 0; + while (ptr < block2) { + newptr = dump_text_line(&trace_buf, b_orig(buf), b_size(buf), block2, &line, ptr); + if (newptr == ptr) + break; + ptr = newptr; + } +} + +/* trace source and events */ +static void check_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) +{ + const struct check *check = a1; + const struct server *srv = (check ? check->server : NULL); + const size_t *val = a4; + const char *res; + + if (!check || src->verbosity < CHK_VERB_CLEAN) + return; + + chunk_appendf(&trace_buf, " : [%c] SRV=%s", + ((check->type == PR_O2_EXT_CHK) ? 'E' : (check->state & CHK_ST_AGENT ? 'A' : 'H')), + srv->id); + + chunk_appendf(&trace_buf, " status=%d/%d %s", + (check->health >= check->rise) ? check->health - check->rise + 1 : check->health, + (check->health >= check->rise) ? check->fall : check->rise, + (check->health >= check->rise) ? (srv->uweight ? "UP" : "DRAIN") : "DOWN"); + + switch (check->result) { + case CHK_RES_NEUTRAL: res = "-"; break; + case CHK_RES_FAILED: res = "FAIL"; break; + case CHK_RES_PASSED: res = "PASS"; break; + case CHK_RES_CONDPASS: res = "COND"; break; + default: res = "UNK"; break; + } + + if (src->verbosity == CHK_VERB_CLEAN) + return; + + chunk_appendf(&trace_buf, " - last=%s(%d)/%s(%d)", + get_check_status_info(check->status), check->status, + res, check->result); + + /* Display the value to the 4th argument (level > STATE) */ + if (src->level > TRACE_LEVEL_STATE && val) + chunk_appendf(&trace_buf, " - VAL=%lu", (long)*val); + + chunk_appendf(&trace_buf, " check=%p(0x%08x)", check, check->state); + + if (src->verbosity == CHK_VERB_MINIMAL) + return; + + + if (check->cs) { + chunk_appendf(&trace_buf, " - conn=%p(0x%08x)", check->cs->conn, check->cs->conn->flags); + chunk_appendf(&trace_buf, " cs=%p(0x%08x)", check->cs, check->cs->flags); + } + + if (mask & CHK_EV_TCPCHK) { + const char *type; + + switch (check->tcpcheck_rules->flags & TCPCHK_RULES_PROTO_CHK) { + case TCPCHK_RULES_PGSQL_CHK: type = "PGSQL"; break; + case TCPCHK_RULES_REDIS_CHK: type = "REDIS"; break; + case TCPCHK_RULES_SMTP_CHK: type = "SMTP"; break; + case TCPCHK_RULES_HTTP_CHK: type = "HTTP"; break; + case TCPCHK_RULES_MYSQL_CHK: type = "MYSQL"; break; + case TCPCHK_RULES_LDAP_CHK: type = "LDAP"; break; + case TCPCHK_RULES_SSL3_CHK: type = "SSL3"; break; + case TCPCHK_RULES_AGENT_CHK: type = "AGENT"; break; + case TCPCHK_RULES_SPOP_CHK: type = "SPOP"; break; + case TCPCHK_RULES_TCP_CHK: type = "TCP"; break; + default: type = "???"; break; + } + if (check->current_step) + chunk_appendf(&trace_buf, " - tcp-check=(%s,%d)", type, tcpcheck_get_step_id(check, NULL)); + else + chunk_appendf(&trace_buf, " - tcp-check=(%s,-)", type); + } + + /* Display bi and bo buffer info (level > USER & verbosity > SIMPLE) */ + if (src->level > TRACE_LEVEL_USER) { + const struct buffer *buf = NULL; + + chunk_appendf(&trace_buf, " bi=%u@%p+%u/%u", + (unsigned int)b_data(&check->bi), b_orig(&check->bi), + (unsigned int)b_head_ofs(&check->bi), (unsigned int)b_size(&check->bi)); + chunk_appendf(&trace_buf, " bo=%u@%p+%u/%u", + (unsigned int)b_data(&check->bo), b_orig(&check->bo), + (unsigned int)b_head_ofs(&check->bo), (unsigned int)b_size(&check->bo)); + + if (src->verbosity >= CHK_VERB_ADVANCED && (mask & (CHK_EV_RX))) + buf = (b_is_null(&check->bi) ? NULL : &check->bi); + else if (src->verbosity >= CHK_VERB_ADVANCED && (mask & (CHK_EV_TX))) + buf = (b_is_null(&check->bo) ? NULL : &check->bo); + + if (buf) { + if ((check->tcpcheck_rules->flags & TCPCHK_RULES_PROTO_CHK) == TCPCHK_RULES_HTTP_CHK) { + int full = (src->verbosity == CHK_VERB_COMPLETE); + + chunk_memcat(&trace_buf, "\n\t", 2); + htx_dump(&trace_buf, htxbuf(buf), full); + } + else { + int max = ((src->verbosity == CHK_VERB_COMPLETE) ? 1024 : 256); + + chunk_memcat(&trace_buf, "\n", 1); + if (b_data(buf) > max) { + check_trace_buf(buf, 0, max); + chunk_memcat(&trace_buf, " ...\n", 6); + } + else + check_trace_buf(buf, 0, b_data(buf)); + } + + } + } + +} + + /**************************************************************************/ /************************ Handle check results ****************************/ /**************************************************************************/ @@ -222,6 +444,8 @@ void set_server_check_status(struct check *check, short status, const char *desc short prev_status = check->status; int report = 0; + TRACE_POINT(CHK_EV_HCHK_RUN, check); + if (status == HCHK_STATUS_START) { check->result = CHK_RES_UNKNOWN; /* no result yet */ check->desc[0] = '\0'; @@ -261,6 +485,7 @@ void set_server_check_status(struct check *check, short status, const char *desc return; report = 0; + switch (check->result) { case CHK_RES_FAILED: /* Failure to connect to the agent as a secondary check should not @@ -338,6 +563,7 @@ void check_notify_failure(struct check *check) if (check->health > 0) return; + TRACE_STATE("health-check failed, set server DOWN", CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); /* We only report a reason for the check if we did not do so previously */ srv_set_stopped(s, NULL, (!s->track && !(s->proxy->options2 & PR_O2_LOGHCHKS)) ? check : NULL); } @@ -372,6 +598,7 @@ void check_notify_success(struct check *check) if ((check->state & CHK_ST_AGENT) && s->next_state == SRV_ST_STOPPING) return; + TRACE_STATE("health-check succeeded, set server RUNNING", CHK_EV_HCHK_END|CHK_EV_HCHK_SUCC, check); srv_set_running(s, NULL, (!s->track && !(s->proxy->options2 & PR_O2_LOGHCHKS)) ? check : NULL); } @@ -400,6 +627,7 @@ void check_notify_stopping(struct check *check) if ((s->agent.state & CHK_ST_ENABLED) && (s->agent.health < s->agent.rise)) return; + TRACE_STATE("health-check condionnaly succeeded, set server STOPPING", CHK_EV_HCHK_END|CHK_EV_HCHK_SUCC, check); srv_set_stopping(s, NULL, (!s->track && !(s->proxy->options2 & PR_O2_LOGHCHKS)) ? check : NULL); } @@ -554,8 +782,9 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) struct buffer *chk; int step; - if (check->result != CHK_RES_UNKNOWN) + if (check->result != CHK_RES_UNKNOWN) { return; + } errno = unclean_errno(errno_bck); if (conn && errno) @@ -565,6 +794,8 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) !(cs->flags & CS_FL_ERROR) && !expired) return; + TRACE_ENTER(CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check, 0, 0, (size_t[]){expired}); + /* we'll try to build a meaningful error message depending on the * context of the error possibly present in conn->err_code, and the * socket error possibly collected above. This is useful to know the @@ -575,8 +806,10 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) if (check->type == PR_O2_TCPCHK_CHK && (check->tcpcheck_rules->flags & TCPCHK_RULES_PROTO_CHK) == TCPCHK_RULES_TCP_CHK) { step = tcpcheck_get_step_id(check, NULL); - if (!step) + if (!step) { + TRACE_DEVEL("initial connection failure", CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); chunk_printf(chk, " at initial connection step of tcp-check"); + } else { chunk_printf(chk, " at step %d of tcp-check", step); /* we were looking for a string */ @@ -585,6 +818,7 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) chunk_appendf(chk, " (connect port %d)" ,check->current_step->connect.port); else chunk_appendf(chk, " (connect)"); + TRACE_DEVEL("connection failure", CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); } else if (check->current_step && check->current_step->action == TCPCHK_ACT_EXPECT) { struct tcpcheck_expect *expect = &check->current_step->expect; @@ -633,9 +867,11 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) chunk_appendf(chk, " (undefined expect!)"); break; } + TRACE_DEVEL("expect rule failed", CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); } else if (check->current_step && check->current_step->action == TCPCHK_ACT_SEND) { chunk_appendf(chk, " (send)"); + TRACE_DEVEL("send rule failed", CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); } if (check->current_step && check->current_step->comment) @@ -665,7 +901,6 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) if (check->state & CHK_ST_PORT_MISS) { /* NOTE: this is reported after tries */ - chunk_printf(chk, "No port available for the TCP connection"); set_server_check_status(check, HCHK_STATUS_SOCKERR, err_msg); } @@ -709,6 +944,7 @@ void chk_report_conn_err(struct check *check, int errno_bck, int expired) set_server_check_status(check, tout, err_msg); } + TRACE_LEAVE(CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); return; } @@ -785,6 +1021,7 @@ static int wake_srv_chk(struct conn_stream *cs) struct email_alertq *q = container_of(check, typeof(*q), check); int ret = 0; + TRACE_ENTER(CHK_EV_HCHK_WAKE, check); if (check->server) HA_SPIN_LOCK(SERVER_LOCK, &check->server->lock); else @@ -803,6 +1040,7 @@ static int wake_srv_chk(struct conn_stream *cs) * main processing task so let's simply wake it up. If we get here, * we expect errno to still be valid. */ + TRACE_ERROR("report connection error", CHK_EV_HCHK_WAKE|CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); chk_report_conn_err(check, errno, 0); task_wakeup(check->task, TASK_WOKEN_IO); } @@ -830,6 +1068,7 @@ static int wake_srv_chk(struct conn_stream *cs) else HA_SPIN_UNLOCK(EMAIL_ALERTS_LOCK, &q->lock); + TRACE_LEAVE(CHK_EV_HCHK_WAKE, check); return ret; } @@ -858,25 +1097,32 @@ struct task *process_chk_conn(struct task *t, void *context, unsigned int state) int rv; int expired = tick_is_expired(t->expire, now_ms); + TRACE_ENTER(CHK_EV_TASK_WAKE, check); + if (check->server) HA_SPIN_LOCK(SERVER_LOCK, &check->server->lock); if (!(check->state & CHK_ST_INPROGRESS)) { /* no check currently running */ - if (!expired) /* woke up too early */ + if (!expired) /* woke up too early */ { + TRACE_STATE("health-check wake up too early", CHK_EV_TASK_WAKE, check); goto out_unlock; + } /* we don't send any health-checks when the proxy is * stopped, the server should not be checked or the check * is disabled. */ if (((check->state & (CHK_ST_ENABLED | CHK_ST_PAUSED)) != CHK_ST_ENABLED) || - proxy->disabled) + proxy->disabled) { + TRACE_STATE("health-check paused or disabled", CHK_EV_TASK_WAKE, check); goto reschedule; + } /* we'll initiate a new check */ set_server_check_status(check, HCHK_STATUS_START, NULL); check->state |= CHK_ST_INPROGRESS; + TRACE_STATE("init new health-check", CHK_EV_TASK_WAKE|CHK_EV_HCHK_START, check); task_set_affinity(t, tid_bit); @@ -894,10 +1140,12 @@ struct task *process_chk_conn(struct task *t, void *context, unsigned int state) * error would have already been detected */ if ((conn->flags & CO_FL_ERROR) || cs->flags & CS_FL_ERROR || expired) { + TRACE_ERROR("report connection error", CHK_EV_TASK_WAKE|CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); chk_report_conn_err(check, 0, expired); } else { if (check->state & CHK_ST_CLOSE_CONN) { + TRACE_DEVEL("closing current connection", CHK_EV_TASK_WAKE|CHK_EV_HCHK_RUN, check); cs_destroy(cs); cs = NULL; conn = NULL; @@ -905,12 +1153,15 @@ struct task *process_chk_conn(struct task *t, void *context, unsigned int state) check->state &= ~CHK_ST_CLOSE_CONN; tcpcheck_main(check); } - if (check->result == CHK_RES_UNKNOWN) + if (check->result == CHK_RES_UNKNOWN) { + TRACE_DEVEL("health-check not expired", CHK_EV_TASK_WAKE|CHK_EV_HCHK_RUN, check); goto out_unlock; /* timeout not reached, wait again */ + } } } /* check complete or aborted */ + TRACE_STATE("health-check complete or aborted", CHK_EV_TASK_WAKE|CHK_EV_HCHK_END, check); check->current_step = NULL; @@ -945,14 +1196,17 @@ struct task *process_chk_conn(struct task *t, void *context, unsigned int state) if (check->server) { if (check->result == CHK_RES_FAILED) { /* a failure or timeout detected */ + TRACE_DEVEL("report failure", CHK_EV_TASK_WAKE|CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check); check_notify_failure(check); } else if (check->result == CHK_RES_CONDPASS) { /* check is OK but asks for stopping mode */ + TRACE_DEVEL("report conditionnal success", CHK_EV_TASK_WAKE|CHK_EV_HCHK_END|CHK_EV_HCHK_SUCC, check); check_notify_stopping(check); } else if (check->result == CHK_RES_PASSED) { /* a success was detected */ + TRACE_DEVEL("report success", CHK_EV_TASK_WAKE|CHK_EV_HCHK_END|CHK_EV_HCHK_SUCC, check); check_notify_success(check); } } @@ -977,6 +1231,8 @@ struct task *process_chk_conn(struct task *t, void *context, unsigned int state) out_unlock: if (check->server) HA_SPIN_UNLOCK(SERVER_LOCK, &check->server->lock); + + TRACE_LEAVE(CHK_EV_TASK_WAKE, check); return t; } @@ -995,11 +1251,13 @@ int check_buf_available(void *target) struct check *check = target; if ((check->state & CHK_ST_IN_ALLOC) && b_alloc(&check->bi)) { + TRACE_STATE("unblocking check, input buffer allocated", CHK_EV_TCPCHK_EXP|CHK_EV_RX_BLK, check); check->state &= ~CHK_ST_IN_ALLOC; tasklet_wakeup(check->wait_list.tasklet); return 1; } if ((check->state & CHK_ST_OUT_ALLOC) && b_alloc(&check->bo)) { + TRACE_STATE("unblocking check, output buffer allocated", CHK_EV_TCPCHK_SND|CHK_EV_TX_BLK, check); check->state &= ~CHK_ST_OUT_ALLOC; tasklet_wakeup(check->wait_list.tasklet); return 1; diff --git a/src/tcpcheck.c b/src/tcpcheck.c index a99ec0907..5a51471db 100644 --- a/src/tcpcheck.c +++ b/src/tcpcheck.c @@ -58,9 +58,12 @@ #include #include #include +#include #include +#define TRACE_SOURCE &trace_check + /* Global tree to share all tcp-checks */ struct eb_root shared_tcpchecks = EB_ROOT; @@ -345,7 +348,7 @@ void free_tcpcheck_ruleset(struct tcpcheck_ruleset *rs) /**************** Everything about tcp-checks execution *******************/ /**************************************************************************/ /* Returns the id of a step in a tcp-check ruleset */ -int tcpcheck_get_step_id(struct check *check, struct tcpcheck_rule *rule) +int tcpcheck_get_step_id(const struct check *check, const struct tcpcheck_rule *rule) { if (!rule) rule = check->current_step; @@ -366,7 +369,7 @@ int tcpcheck_get_step_id(struct check *check, struct tcpcheck_rule *rule) /* Returns the first non COMMENT/ACTION_KW tcp-check rule from list or * NULL if none was found. */ -struct tcpcheck_rule *get_first_tcpcheck_rule(struct tcpcheck_rules *rules) +struct tcpcheck_rule *get_first_tcpcheck_rule(const struct tcpcheck_rules *rules) { struct tcpcheck_rule *r; @@ -550,6 +553,8 @@ static enum tcpcheck_eval_ret tcpcheck_mysql_expect_packet(struct check *check, unsigned int err = 0, plen = 0; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); + /* 3 Bytes for the packet length and 1 byte for the sequence id */ if (b_data(&check->bi) < offset+4) { if (!last_read) @@ -596,6 +601,7 @@ static enum tcpcheck_eval_ret tcpcheck_mysql_expect_packet(struct check *check, out: free_trash_chunk(msg); + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; error: @@ -608,6 +614,7 @@ static enum tcpcheck_eval_ret tcpcheck_mysql_expect_packet(struct check *check, goto out; wait_more_data: + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); ret = TCPCHK_EVAL_WAIT; goto out; } @@ -651,6 +658,8 @@ enum tcpcheck_eval_ret tcpcheck_ldap_expect_bindrsp(struct check *check, struct struct ist desc = IST_NULL; unsigned short msglen = 0; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); + /* Check if the server speaks LDAP (ASN.1/BER) * http://en.wikipedia.org/wiki/Basic_Encoding_Rules * http://tools.ietf.org/html/rfc4511 @@ -695,6 +704,7 @@ enum tcpcheck_eval_ret tcpcheck_ldap_expect_bindrsp(struct check *check, struct out: free_trash_chunk(msg); + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; error: @@ -718,6 +728,7 @@ enum tcpcheck_eval_ret tcpcheck_spop_expect_agenthello(struct check *check, stru struct ist desc = IST_NULL; unsigned int framesz; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); memcpy(&framesz, b_head(&check->bi), 4); framesz = ntohl(framesz); @@ -737,6 +748,7 @@ enum tcpcheck_eval_ret tcpcheck_spop_expect_agenthello(struct check *check, stru out: free_trash_chunk(msg); + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; error: @@ -748,6 +760,7 @@ enum tcpcheck_eval_ret tcpcheck_spop_expect_agenthello(struct check *check, stru goto out; wait_more_data: + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); ret = TCPCHK_EVAL_WAIT; goto out; } @@ -768,6 +781,8 @@ enum tcpcheck_eval_ret tcpcheck_agent_expect_reply(struct check *check, struct t const char *wrn = NULL; /* first warning to report */ char *cmd, *p; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); + /* We're getting an agent check response. The agent could * have been disabled in the mean time with a long check * still pending. It is important that we ignore the whole @@ -892,18 +907,25 @@ enum tcpcheck_eval_ret tcpcheck_agent_expect_reply(struct check *check, struct t * present after going back up. */ if (as) { - if (strcasecmp(as, "drain") == 0) + if (strcasecmp(as, "drain") == 0) { + TRACE_DEVEL("set server into DRAIN mode", CHK_EV_TCPCHK_EXP, check); srv_adm_set_drain(check->server); - else if (strcasecmp(as, "maint") == 0) + } + else if (strcasecmp(as, "maint") == 0) { + TRACE_DEVEL("set server into MAINT mode", CHK_EV_TCPCHK_EXP, check); srv_adm_set_maint(check->server); - else + } + else { + TRACE_DEVEL("set server into READY mode", CHK_EV_TCPCHK_EXP, check); srv_adm_set_ready(check->server); + } } /* now change weights */ if (ps) { const char *msg; + TRACE_DEVEL("change server weigth", CHK_EV_TCPCHK_EXP, check); msg = server_parse_weight_change_request(check->server, ps); if (!wrn || !*wrn) wrn = msg; @@ -914,6 +936,7 @@ enum tcpcheck_eval_ret tcpcheck_agent_expect_reply(struct check *check, struct t cs += strlen("maxconn:"); + TRACE_DEVEL("change server maxconn", CHK_EV_TCPCHK_EXP, check); msg = server_parse_maxconn_change_request(check->server, cs); if (!wrn || !*wrn) wrn = msg; @@ -940,12 +963,14 @@ enum tcpcheck_eval_ret tcpcheck_agent_expect_reply(struct check *check, struct t chunk_printf(t, "via agent : %s%s%s%s", hs, *msg ? " (" : "", msg, *msg ? ")" : ""); + TRACE_DEVEL("update server health status", CHK_EV_TCPCHK_EXP, check); set_server_check_status(check, status, t->area); } else if (err && *err) { /* No status change but we'd like to report something odd. * Just report the current state and copy the message. */ + TRACE_DEVEL("agent reports an error", CHK_EV_TCPCHK_EXP, check); chunk_printf(&trash, "agent reports an error : %s", err); set_server_check_status(check, status/*check->status*/, trash.area); } @@ -953,16 +978,21 @@ enum tcpcheck_eval_ret tcpcheck_agent_expect_reply(struct check *check, struct t /* No status change but we'd like to report something odd. * Just report the current state and copy the message. */ + TRACE_DEVEL("agent reports a warning", CHK_EV_TCPCHK_EXP, check); chunk_printf(&trash, "agent warns : %s", wrn); set_server_check_status(check, status/*check->status*/, trash.area); } - else + else { + TRACE_DEVEL("update server health status", CHK_EV_TCPCHK_EXP, check); set_server_check_status(check, status, NULL); + } out: + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; wait_more_data: + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); ret = TCPCHK_EVAL_WAIT; goto out; } @@ -985,6 +1015,8 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec struct tcpcheck_rule *next; int status, port; + TRACE_ENTER(CHK_EV_TCPCHK_CONN, check); + next = get_next_tcpcheck_rule(check->tcpcheck_rules, rule); /* current connection already created, check if it is established or not */ @@ -995,6 +1027,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec if (!(check->wait_list.events & SUB_RETRY_SEND)) conn->mux->subscribe(cs, SUB_RETRY_SEND, &check->wait_list); ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("not connected yet", CHK_EV_TCPCHK_CONN, check); } else ret = tcpcheck_eval_recv(check, rule); @@ -1017,6 +1050,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec chunk_appendf(&trash, " comment: '%s'", rule->comment); set_server_check_status(check, HCHK_STATUS_SOCKERR, trash.area); ret = TCPCHK_EVAL_STOP; + TRACE_ERROR("conn-stream allocation error", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check); goto out; } @@ -1031,6 +1065,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec /* no client address */ if (!sockaddr_alloc(&conn->dst, NULL, 0)) { + TRACE_ERROR("sockaddr allocation error", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check); status = SF_ERR_RESOURCE; goto fail_check; } @@ -1067,12 +1102,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec port = s->svc_port; } set_host_port(conn->dst, port); + TRACE_DEVEL("set port", CHK_EV_TCPCHK_CONN, check, 0, 0, (size_t[]){port}); xprt = ((connect->options & TCPCHK_OPT_SSL) ? xprt_get(XPRT_SSL) : ((connect->options & TCPCHK_OPT_DEFAULT_CONNECT) ? check->xprt : xprt_get(XPRT_RAW))); if (conn_prepare(conn, proto, xprt) < 0) { + TRACE_ERROR("xprt allocation error", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check); status = SF_ERR_RESOURCE; goto fail_check; } @@ -1082,19 +1119,23 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec if ((connect->options & TCPCHK_OPT_SOCKS4) && s && (s->flags & SRV_F_SOCKS4_PROXY)) { conn->send_proxy_ofs = 1; conn->flags |= CO_FL_SOCKS4; + TRACE_DEVEL("configure SOCKS4 proxy", CHK_EV_TCPCHK_CONN); } else if ((connect->options & TCPCHK_OPT_DEFAULT_CONNECT) && s && s->check.via_socks4 && (s->flags & SRV_F_SOCKS4_PROXY)) { conn->send_proxy_ofs = 1; conn->flags |= CO_FL_SOCKS4; + TRACE_DEVEL("configure SOCKS4 proxy", CHK_EV_TCPCHK_CONN); } if (connect->options & TCPCHK_OPT_SEND_PROXY) { conn->send_proxy_ofs = 1; conn->flags |= CO_FL_SEND_PROXY; + TRACE_DEVEL("configure PROXY protocol", CHK_EV_TCPCHK_CONN, check); } else if ((connect->options & TCPCHK_OPT_DEFAULT_CONNECT) && s && s->check.send_proxy && !(check->state & CHK_ST_AGENT)) { conn->send_proxy_ofs = 1; conn->flags |= CO_FL_SEND_PROXY; + TRACE_DEVEL("configure PROXY protocol", CHK_EV_TCPCHK_CONN, check); } status = SF_ERR_INTERNAL; @@ -1149,6 +1190,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec connect->mux_proto || (!connect->alpn && !check->alpn_str)) { const struct mux_ops *mux_ops; + TRACE_DEVEL("try to install mux now", CHK_EV_TCPCHK_CONN, check); if (connect->mux_proto) mux_ops = connect->mux_proto->mux; else if ((connect->options & TCPCHK_OPT_DEFAULT_CONNECT) && check->mux_proto) @@ -1161,6 +1203,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec mux_ops = conn_get_best_mux(conn, IST_NULL, PROTO_SIDE_BE, mode); } if (mux_ops && conn_install_mux(conn, mux_ops, cs, proxy, check->sess) < 0) { + TRACE_ERROR("failed to install mux", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check); status = SF_ERR_INTERNAL; goto fail_check; } @@ -1196,6 +1239,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec case SF_ERR_PRXCOND: case SF_ERR_RESOURCE: case SF_ERR_INTERNAL: + TRACE_ERROR("report connection error", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check, 0, 0, (size_t[]){status}); chk_report_conn_err(check, errno, 0); ret = TCPCHK_EVAL_STOP; goto out; @@ -1210,16 +1254,20 @@ enum tcpcheck_eval_ret tcpcheck_eval_connect(struct check *check, struct tcpchec conn->mux->subscribe(cs, SUB_RETRY_RECV, &check->wait_list); } ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("not connected yet", CHK_EV_TCPCHK_CONN, check); goto out; } out: - if (conn && check->result == CHK_RES_FAILED) + if (conn && check->result == CHK_RES_FAILED) { conn->flags |= CO_FL_ERROR; + TRACE_ERROR("connect failed, report conncetion error", CHK_EV_TCPCHK_CONN|CHK_EV_TCPCHK_ERR, check); + } if (ret == TCPCHK_EVAL_CONTINUE && check->proxy->timeout.check) check->task->expire = tick_add_ifset(now_ms, check->proxy->timeout.check); + TRACE_LEAVE(CHK_EV_TCPCHK_CONN, check, 0, 0, (size_t[]){ret}); return ret; } @@ -1237,20 +1285,26 @@ enum tcpcheck_eval_ret tcpcheck_eval_send(struct check *check, struct tcpcheck_r struct htx *htx = NULL; int connection_hdr = 0; + TRACE_ENTER(CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA, check); + if (check->state & CHK_ST_OUT_ALLOC) { ret = TCPCHK_EVAL_WAIT; + TRACE_STATE("waiting for output buffer allocation", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA|CHK_EV_TX_BLK, check); goto out; } if (!check_get_buf(check, &check->bo)) { check->state |= CHK_ST_OUT_ALLOC; ret = TCPCHK_EVAL_WAIT; + TRACE_STATE("waiting for output buffer allocation", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA|CHK_EV_TX_BLK, check); goto out; } /* Data already pending in the output buffer, send them now */ - if (b_data(&check->bo)) + if (b_data(&check->bo)) { + TRACE_DEVEL("Data still pending, try to send it now", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA, check); goto do_send; + } /* Always release input buffer when a new send is evaluated */ check_release_buf(check, &check->bi); @@ -1382,16 +1436,19 @@ enum tcpcheck_eval_ret tcpcheck_eval_send(struct check *check, struct tcpcheck_r }; do_send: + TRACE_DATA("send data", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA, check); if (conn->mux->snd_buf(cs, &check->bo, (IS_HTX_CONN(conn) ? (htxbuf(&check->bo))->data: b_data(&check->bo)), 0) <= 0) { if ((conn->flags & CO_FL_ERROR) || (cs->flags & CS_FL_ERROR)) { ret = TCPCHK_EVAL_STOP; + TRACE_DEVEL("connection error during send", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA|CHK_EV_TX_ERR, check); goto out; } } if ((IS_HTX_CONN(conn) && !htx_is_empty(htxbuf(&check->bo))) || b_data(&check->bo)) { cs->conn->mux->subscribe(cs, SUB_RETRY_SEND, &check->wait_list); ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("data not fully sent, wait", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA, check); goto out; } @@ -1399,6 +1456,8 @@ enum tcpcheck_eval_ret tcpcheck_eval_send(struct check *check, struct tcpcheck_r free_trash_chunk(tmp); if (!b_data(&check->bo) || ret == TCPCHK_EVAL_STOP) check_release_buf(check, &check->bo); + + TRACE_LEAVE(CHK_EV_TCPCHK_SND, check, 0, 0, (size_t[]){ret}); return ret; error_htx: @@ -1408,6 +1467,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_send(struct check *check, struct tcpcheck_r } chunk_printf(&trash, "tcp-check send : failed to build HTTP request at step %d", tcpcheck_get_step_id(check, rule)); + TRACE_ERROR("failed to build HTTP request", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA|CHK_EV_TCPCHK_ERR, check); set_server_check_status(check, HCHK_STATUS_L7RSP, trash.area); ret = TCPCHK_EVAL_STOP; goto out; @@ -1415,6 +1475,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_send(struct check *check, struct tcpcheck_r error_lf: chunk_printf(&trash, "tcp-check send : failed to build log-format string at step %d", tcpcheck_get_step_id(check, rule)); + TRACE_ERROR("failed to build log-format string", CHK_EV_TCPCHK_SND|CHK_EV_TX_DATA|CHK_EV_TCPCHK_ERR, check); set_server_check_status(check, HCHK_STATUS_L7RSP, trash.area); ret = TCPCHK_EVAL_STOP; goto out; @@ -1435,17 +1496,24 @@ enum tcpcheck_eval_ret tcpcheck_eval_recv(struct check *check, struct tcpcheck_r int is_empty; int read_poll = MAX_READ_POLL_LOOPS; - if (check->wait_list.events & SUB_RETRY_RECV) + TRACE_ENTER(CHK_EV_RX_DATA, check); + + if (check->wait_list.events & SUB_RETRY_RECV) { + TRACE_DEVEL("waiting for response", CHK_EV_RX_DATA, check); goto wait_more_data; + } if (cs->flags & CS_FL_EOS) goto end_recv; - if (check->state & CHK_ST_IN_ALLOC) + if (check->state & CHK_ST_IN_ALLOC) { + TRACE_STATE("waiting for input buffer allocation", CHK_EV_RX_DATA|CHK_EV_RX_BLK, check); goto wait_more_data; + } if (!check_get_buf(check, &check->bi)) { check->state |= CHK_ST_IN_ALLOC; + TRACE_STATE("waiting for input buffer allocation", CHK_EV_RX_DATA|CHK_EV_RX_BLK, check); goto wait_more_data; } @@ -1474,11 +1542,13 @@ enum tcpcheck_eval_ret tcpcheck_eval_recv(struct check *check, struct tcpcheck_r * or not. It is very common that an RST sent by the server is * reported as an error just after the last data chunk. */ + TRACE_ERROR("connection error during recv", CHK_EV_RX_DATA|CHK_EV_RX_ERR, check); goto stop; } if (!cur_read) { if (!(cs->flags & (CS_FL_WANT_ROOM|CS_FL_ERROR|CS_FL_EOS))) { conn->mux->subscribe(cs, SUB_RETRY_RECV, &check->wait_list); + TRACE_DEVEL("waiting for response", CHK_EV_RX_DATA, check); goto wait_more_data; } if (is_empty) { @@ -1489,15 +1559,19 @@ enum tcpcheck_eval_ret tcpcheck_eval_recv(struct check *check, struct tcpcheck_r if (rule->comment) chunk_appendf(&trash, " comment: '%s'", rule->comment); + TRACE_ERROR("empty response", CHK_EV_RX_DATA|CHK_EV_RX_ERR, check); status = ((rule->expect.err_status != HCHK_STATUS_UNKNOWN) ? rule->expect.err_status : HCHK_STATUS_L7RSP); set_server_check_status(check, status, trash.area); goto stop; } } + TRACE_DATA("data received", CHK_EV_RX_DATA, check, 0, 0, (size_t[]){cur_read}); out: if (!b_data(&check->bi) || ret == TCPCHK_EVAL_STOP) check_release_buf(check, &check->bi); + + TRACE_LEAVE(CHK_EV_RX_DATA, check, 0, 0, (size_t[]){ret}); return ret; stop: @@ -1526,18 +1600,23 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp struct ist desc = IST_NULL; int i, match, inverse; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); + last_read |= (!htx_free_data_space(htx) || (htx->flags & HTX_FL_EOM)); if (htx->flags & HTX_FL_PARSING_ERROR) { + TRACE_ERROR("invalid response", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); status = HCHK_STATUS_L7RSP; goto error; } if (htx_is_empty(htx)) { if (last_read) { + TRACE_ERROR("empty response received", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); status = HCHK_STATUS_L7RSP; goto error; } + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto wait_more_data; } @@ -1549,6 +1628,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp (check->server->next_state != SRV_ST_STOPPED) && (check->code == 404)) { /* 404 may be accepted as "stopping" only if the server was up */ + TRACE_STATE("404 response & disable-404", CHK_EV_TCPCHK_EXP, check); goto out; } @@ -1592,12 +1672,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp if (!nbuf) { status = HCHK_STATUS_L7RSP; desc = ist("Failed to allocate buffer to eval log-format string"); + TRACE_ERROR("buffer allocation failure", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } nbuf->data = sess_build_logline(check->sess, NULL, b_orig(nbuf), b_size(nbuf), &expect->hdr.name_fmt); if (!b_data(nbuf)) { status = HCHK_STATUS_L7RSP; desc = ist("log-format string evaluated to an empty string"); + TRACE_ERROR("invalid log-format string (hdr name)", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } npat = ist2(b_orig(nbuf), b_data(nbuf)); @@ -1610,12 +1692,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp if (!vbuf) { status = HCHK_STATUS_L7RSP; desc = ist("Failed to allocate buffer to eval log-format string"); + TRACE_ERROR("buffer allocation failure", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } vbuf->data = sess_build_logline(check->sess, NULL, b_orig(vbuf), b_size(vbuf), &expect->hdr.value_fmt); if (!b_data(vbuf)) { status = HCHK_STATUS_L7RSP; desc = ist("log-format string evaluated to an empty string"); + TRACE_ERROR("invalid log-format string (hdr value)", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } vpat = ist2(b_orig(vbuf), b_data(vbuf)); @@ -1727,11 +1811,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp } if (!b_data(&trash)) { - if (!last_read) + if (!last_read) { + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto wait_more_data; + } status = ((status != HCHK_STATUS_UNKNOWN) ? status : HCHK_STATUS_L7RSP); if (LIST_ISEMPTY(&expect->onerror_fmt)) desc = ist("HTTP content check could not find a response body"); + TRACE_ERROR("no response boduy found while expected", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } @@ -1740,12 +1827,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp if (!tmp) { status = HCHK_STATUS_L7RSP; desc = ist("Failed to allocate buffer to eval log-format string"); + TRACE_ERROR("buffer allocation failure", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } tmp->data = sess_build_logline(check->sess, NULL, b_orig(tmp), b_size(tmp), &expect->fmt); if (!b_data(tmp)) { status = HCHK_STATUS_L7RSP; desc = ist("log-format string evaluated to an empty string"); + TRACE_ERROR("invalid log-format string", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } } @@ -1770,6 +1859,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp */ if (!match && !last_read && (expect->min_recv == -1)) { ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto out; } @@ -1788,17 +1878,23 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect_http(struct check *check, struct tcp goto error; } - if (!(match ^ inverse)) + if (!(match ^ inverse)) { + TRACE_STATE("expect rule failed", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; + } + + TRACE_STATE("expect rule succeeded", CHK_EV_TCPCHK_EXP, check); out: free_trash_chunk(tmp); free_trash_chunk(nbuf); free_trash_chunk(vbuf); free_trash_chunk(msg); + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; error: + TRACE_STATE("expect rule failed", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); ret = TCPCHK_EVAL_STOP; msg = alloc_trash_chunk(); if (msg) @@ -1824,6 +1920,8 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck enum healthcheck_status status; int match, inverse; + TRACE_ENTER(CHK_EV_TCPCHK_EXP, check); + last_read |= b_full(&check->bi); /* The current expect might need more data than the previous one, check again @@ -1833,10 +1931,12 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck if ((expect->type == TCPCHK_EXPECT_STRING || expect->type == TCPCHK_EXPECT_BINARY) && (b_data(&check->bi) < istlen(expect->data))) { ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto out; } if (expect->min_recv > 0 && (b_data(&check->bi) < expect->min_recv)) { ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto out; } } @@ -1868,12 +1968,14 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck if (!tmp) { status = HCHK_STATUS_L7RSP; desc = ist("Failed to allocate buffer to eval format string"); + TRACE_ERROR("buffer allocation failure", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } tmp->data = sess_build_logline(check->sess, NULL, b_orig(tmp), b_size(tmp), &expect->fmt); if (!b_data(tmp)) { status = HCHK_STATUS_L7RSP; desc = ist("log-format string evaluated to an empty string"); + TRACE_ERROR("invalid log-format string", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } if (expect->type == TCPCHK_EXPECT_BINARY_LF) { @@ -1881,6 +1983,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck if (parse_binary(b_orig(tmp), &tmp->area, &len, NULL) == 0) { status = HCHK_STATUS_L7RSP; desc = ist("Failed to parse hexastring resulting of eval of a log-format string"); + TRACE_ERROR("invalid binary log-format string", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); goto error; } tmp->data = len; @@ -1888,6 +1991,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck if (b_data(&check->bi) < tmp->data) { if (!last_read) { ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto out; } break; @@ -1911,15 +2015,19 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck */ if (!match && !last_read && (expect->min_recv == -1)) { ret = TCPCHK_EVAL_WAIT; + TRACE_DEVEL("waiting for more data", CHK_EV_TCPCHK_EXP, check); goto out; } /* Result as expected, next rule. */ - if (match ^ inverse) + if (match ^ inverse) { + TRACE_STATE("expect rule succeeded", CHK_EV_TCPCHK_EXP, check); goto out; + } error: /* From this point on, we matched something we did not want, this is an error state. */ + TRACE_STATE("expect rule failed", CHK_EV_TCPCHK_EXP|CHK_EV_TCPCHK_ERR, check); ret = TCPCHK_EVAL_STOP; msg = alloc_trash_chunk(); if (msg) @@ -1929,6 +2037,7 @@ enum tcpcheck_eval_ret tcpcheck_eval_expect(struct check *check, struct tcpcheck out: free_trash_chunk(tmp); + TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret}); return ret; } @@ -1975,6 +2084,8 @@ int tcpcheck_main(struct check *check) if (check->result != CHK_RES_UNKNOWN) goto out; + TRACE_ENTER(CHK_EV_TCPCHK_EVAL, check); + /* Note: the conn-stream and the connection may only be undefined before * the first rule evaluation (it is always a connect rule) or when the * conn-stream allocation failed on a connect rule, during cs allocation. @@ -1986,8 +2097,10 @@ int tcpcheck_main(struct check *check) /* 2- check if a rule must be resume. It happens if check->current_step * is defined. */ - else if (check->current_step) + else if (check->current_step) { rule = check->current_step; + TRACE_PROTO("resume rule evaluation", CHK_EV_TCPCHK_EVAL, check, 0, 0, (size_t[]){ tcpcheck_get_step_id(check, rule)}); + } /* 3- It is the first evaluation. We must create a session and preset * tcp-check variables */ @@ -1998,6 +2111,7 @@ int tcpcheck_main(struct check *check) check->sess = session_new(&checks_fe, NULL, &check->obj_type); if (!check->sess) { chunk_printf(&trash, "TCPCHK error allocating check session"); + TRACE_ERROR("session allocation failure", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_ERR, check); set_server_check_status(check, HCHK_STATUS_SOCKERR, trash.area); goto out_end_tcpcheck; } @@ -2013,6 +2127,7 @@ int tcpcheck_main(struct check *check) smp.data = var->data; vars_set_by_name_ifexist(istptr(var->name), istlen(var->name), &smp); } + TRACE_PROTO("start rules evaluation", CHK_EV_TCPCHK_EVAL, check); } /* Now evaluate the tcp-check rules */ @@ -2031,10 +2146,12 @@ int tcpcheck_main(struct check *check) /* We are still waiting the connection gets closed */ if (cs && (check->state & CHK_ST_CLOSE_CONN)) { + TRACE_DEVEL("wait previous connection closure", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_CONN, check); eval_ret = TCPCHK_EVAL_WAIT; break; } + TRACE_PROTO("eval connect rule", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_CONN, check); eval_ret = tcpcheck_eval_connect(check, rule); /* Refresh conn-stream and connection */ @@ -2045,11 +2162,13 @@ int tcpcheck_main(struct check *check) break; case TCPCHK_ACT_SEND: check->current_step = rule; + TRACE_PROTO("eval send rule", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_SND, check); eval_ret = tcpcheck_eval_send(check, rule); must_read = 1; break; case TCPCHK_ACT_EXPECT: check->current_step = rule; + TRACE_PROTO("eval expect rule", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_EXP, check); if (must_read) { eval_ret = tcpcheck_eval_recv(check, rule); if (eval_ret == TCPCHK_EVAL_STOP) @@ -2072,6 +2191,7 @@ int tcpcheck_main(struct check *check) break; case TCPCHK_ACT_ACTION_KW: /* Don't update the current step */ + TRACE_PROTO("eval action kw rule", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_ACT, check); eval_ret = tcpcheck_eval_action_kw(check, rule); break; default: @@ -2096,6 +2216,8 @@ int tcpcheck_main(struct check *check) if (check->current_step) { rule = check->current_step; + TRACE_DEVEL("eval tcp-check result", CHK_EV_TCPCHK_EVAL, check); + if (rule->action == TCPCHK_ACT_EXPECT) { struct buffer *msg; enum healthcheck_status status; @@ -2105,6 +2227,7 @@ int tcpcheck_main(struct check *check) (check->server->next_state != SRV_ST_STOPPED) && (check->code == 404)) { set_server_check_status(check, HCHK_STATUS_L7OKCD, NULL); + TRACE_PROTO("tcp-check conditionally passed (disable-404)", CHK_EV_TCPCHK_EVAL, check); goto out_end_tcpcheck; } @@ -2127,18 +2250,23 @@ int tcpcheck_main(struct check *check) else set_server_check_status(check, HCHK_STATUS_L7OKD, "(tcp-check)"); } - else + else { set_server_check_status(check, HCHK_STATUS_L7OKD, "(tcp-check)"); + } + TRACE_PROTO("tcp-check passed", CHK_EV_TCPCHK_EVAL, check); out_end_tcpcheck: - if ((conn && conn->flags & CO_FL_ERROR) || (cs && cs->flags & CS_FL_ERROR)) + if ((conn && conn->flags & CO_FL_ERROR) || (cs && cs->flags & CS_FL_ERROR)) { + TRACE_ERROR("report connection error", CHK_EV_TCPCHK_EVAL|CHK_EV_TCPCHK_ERR, check); chk_report_conn_err(check, errno, 0); + } /* the tcpcheck is finished, release in/out buffer now */ check_release_buf(check, &check->bi); check_release_buf(check, &check->bo); out: + TRACE_LEAVE(CHK_EV_HCHK_RUN, check); return retcode; }