]> git.ipfire.org Git - thirdparty/haproxy.git/commitdiff
MINOIR: checks/trace: Register a new trace source with its events
authorChristopher Faulet <cfaulet@haproxy.com>
Sat, 10 Apr 2021 07:00:38 +0000 (09:00 +0200)
committerChristopher Faulet <cfaulet@haproxy.com>
Mon, 12 Apr 2021 10:09:36 +0000 (12:09 +0200)
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...

include/haproxy/check.h
include/haproxy/tcpcheck.h
src/check.c
src/tcpcheck.c

index 557af0cb51817a37ffad50dd3984839a8e4a16aa..2756a5fe264d54d6c17f5a0e59a784043d31cf74 100644 (file)
 #include <haproxy/check-t.h>
 #include <haproxy/proxy-t.h>
 #include <haproxy/server-t.h>
+#include <haproxy/trace-t.h>
+
+extern struct trace_source trace_check;
+
+/* Details about these events are defined in <src/check.c> */
+#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;
index 40005a2972937be5a23c5e19c372cca3d0f01184..4e92b8865f3c8cae40631c80db7c3b134b2c099a 100644 (file)
@@ -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);
index f4653ac3452cbf00778cea065df0dcc29cab0df1..4c625efa61cb13f2a64db4fc3b970a026723a385 100644 (file)
 #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 @@ 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 <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 @@ 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;
index a99ec0907be8de323a8b3069406ab34fae3500bb..5a51471db1c8a8b322cc4b1998acbe9d38ac555a 100644 (file)
 #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 @@ 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 <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;
 }