MINOIR: checks/trace: Register a new trace source with its events
Add the trace support for the checks. Only tcp-check based health-checks are
supported, including the agent-check.
In traces, the first argument is always a check object. So it is easy to get
all info related to the check. The tcp-check ruleset, the conn-stream and
the connection, the server state...
diff --git a/src/check.c b/src/check.c
index f4653ac..4c625ef 100644
--- a/src/check.c
+++ b/src/check.c
@@ -65,8 +65,82 @@
#include <haproxy/thread.h>
#include <haproxy/time.h>
#include <haproxy/tools.h>
+#include <haproxy/trace.h>
#include <haproxy/vars.h>
+/* 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 <haproxy/check.h>
+ */
+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 @@
/* 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
!(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 @@
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 @@
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 @@
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 @@
if (check->state & CHK_ST_PORT_MISS) {
/* NOTE: this is reported after <fall> 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 @@
set_server_check_status(check, tout, err_msg);
}
+ TRACE_LEAVE(CHK_EV_HCHK_END|CHK_EV_HCHK_ERR, check);
return;
}
@@ -785,6 +1021,7 @@
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 @@
* 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 @@
else
HA_SPIN_UNLOCK(EMAIL_ALERTS_LOCK, &q->lock);
+ TRACE_LEAVE(CHK_EV_HCHK_WAKE, check);
return ret;
}
@@ -858,25 +1097,32 @@
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 @@
* 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 @@
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 @@
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 @@
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 @@
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 a99ec09..5a51471 100644
--- a/src/tcpcheck.c
+++ b/src/tcpcheck.c
@@ -58,9 +58,12 @@
#include <haproxy/tcpcheck.h>
#include <haproxy/time.h>
#include <haproxy/tools.h>
+#include <haproxy/trace.h>
#include <haproxy/vars.h>
+#define TRACE_SOURCE &trace_check
+
/* Global tree to share all tcp-checks */
struct eb_root shared_tcpchecks = EB_ROOT;
@@ -345,7 +348,7 @@
/**************** 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 @@
/* Returns the first non COMMENT/ACTION_KW tcp-check rule from list <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 @@
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 @@
out:
free_trash_chunk(msg);
+ TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret});
return ret;
error:
@@ -608,6 +614,7 @@
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 @@
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 @@
out:
free_trash_chunk(msg);
+ TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret});
return ret;
error:
@@ -718,6 +728,7 @@
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 @@
out:
free_trash_chunk(msg);
+ TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret});
return ret;
error:
@@ -748,6 +760,7 @@
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 @@
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 @@
* 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 @@
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 @@
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 @@
/* 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 @@
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 @@
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 @@
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 @@
/* 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
};
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 @@
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 @@
}
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 @@
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 @@
int is_empty;
int read_poll = MAX_READ_POLL_LOOPS;
+ TRACE_ENTER(CHK_EV_RX_DATA, check);
+
- if (check->wait_list.events & SUB_RETRY_RECV)
+ 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 @@
* 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 @@
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 @@
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 @@
(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 @@
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 @@
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 @@
}
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 @@
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 @@
*/
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 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
*/
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 @@
out:
free_trash_chunk(tmp);
+ TRACE_LEAVE(CHK_EV_TCPCHK_EXP, check, 0, 0, (size_t[]){ret});
return ret;
}
@@ -1975,6 +2084,8 @@
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 @@
/* 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 @@
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 @@
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 @@
/* 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 @@
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 @@
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 @@
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 @@
(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 @@
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;
}