#include <proto/queue.h>
#include <proto/stick_table.h>
#include <proto/task.h>
+#include <proto/trace.h>
+
+extern struct trace_source trace_strm;
+
+/* Details about these events are defined in <src/stream.c> */
+#define STRM_EV_STRM_NEW (1ULL << 0)
+#define STRM_EV_STRM_FREE (1ULL << 1)
+#define STRM_EV_STRM_ERR (1ULL << 2)
+#define STRM_EV_STRM_ANA (1ULL << 3)
+#define STRM_EV_STRM_PROC (1ULL << 4)
+#define STRM_EV_SI_ST (1ULL << 5)
+#define STRM_EV_HTTP_ANA (1ULL << 6)
+#define STRM_EV_HTTP_ERR (1ULL << 7)
+#define STRM_EV_TCP_ANA (1ULL << 8)
+#define STRM_EV_TCP_ERR (1ULL << 9)
+#define STRM_EV_FLT_ANA (1ULL << 10)
+#define STRM_EV_FLT_ERR (1ULL << 11)
#define IS_HTX_STRM(strm) ((strm)->flags & SF_HTX)
#include <proto/ssl_sock.h>
#include <proto/task.h>
+#define TRACE_SOURCE &trace_strm
+
int be_lastsession(const struct proxy *be)
{
if (be->be_counters.last_sess)
uint32_t addr;
char *p;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
if (s->flags & SF_ASSIGNED)
goto no_cookie;
no_cookie:
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 1;
}
#include <proto/stream.h>
#include <proto/stream_interface.h>
+#define TRACE_SOURCE &trace_strm
+
/* Pool used to allocate filters */
DECLARE_STATIC_POOL(pool_head_filter, "filter", sizeof(struct filter));
{
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s, s->txn, msg);
RESUME_FILTER_LOOP(s, msg->chn) {
if (FLT_OPS(filter)->http_end) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->http_end(s, filter, msg);
if (ret <= 0)
BREAK_EXECUTION(s, msg->chn, end);
}
} RESUME_FILTER_END;
end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
return ret;
}
{
struct filter *filter;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s, s->txn, msg);
list_for_each_entry(filter, &strm_flt(s)->filters, list) {
- if (FLT_OPS(filter)->http_reset)
+ if (FLT_OPS(filter)->http_reset) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
FLT_OPS(filter)->http_reset(s, filter, msg);
+ }
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
}
/*
{
struct filter *filter;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s, s->txn, msg);
list_for_each_entry(filter, &strm_flt(s)->filters, list) {
- if (FLT_OPS(filter)->http_reply)
+ if (FLT_OPS(filter)->http_reply) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
FLT_OPS(filter)->http_reply(s, filter, status, msg);
+ }
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
}
/*
unsigned int out = co_data(msg->chn);
int ret = len - out;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s, s->txn, msg);
list_for_each_entry(filter, &strm_flt(s)->filters, list) {
/* Call "data" filters only */
if (!IS_DATA_FILTER(filter, msg->chn))
unsigned long long *flt_off = &FLT_OFF(filter, msg->chn);
unsigned int offset = *flt_off - *strm_off;
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->http_payload(s, filter, msg, out + offset, ret - offset);
if (ret < 0)
goto end;
}
*strm_off += ret;
end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
return ret;
}
{
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+
/* If this function is called, this means there is at least one filter,
* so we do not need to check the filter list's emptiness. */
FLT_FWD(filter, chn) = 0;
if (FLT_OPS(filter)->channel_start_analyze) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->channel_start_analyze(s, filter, chn);
if (ret <= 0)
BREAK_EXECUTION(s, chn, end);
} RESUME_FILTER_END;
end:
- return handle_analyzer_result(s, chn, an_bit, ret);
+ ret = handle_analyzer_result(s, chn, an_bit, ret);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+ return ret;
}
/*
{
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+
RESUME_FILTER_LOOP(s, chn) {
if (FLT_OPS(filter)->channel_pre_analyze && (filter->pre_analyzers & an_bit)) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->channel_pre_analyze(s, filter, chn, an_bit);
if (ret <= 0)
BREAK_EXECUTION(s, chn, check_result);
} RESUME_FILTER_END;
check_result:
- return handle_analyzer_result(s, chn, 0, ret);
+ ret = handle_analyzer_result(s, chn, 0, ret);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+ return ret;
}
/*
struct filter *filter;
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+
list_for_each_entry(filter, &strm_flt(s)->filters, list) {
if (FLT_OPS(filter)->channel_post_analyze && (filter->post_analyzers & an_bit)) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->channel_post_analyze(s, filter, chn, an_bit);
if (ret < 0)
break;
}
}
- return handle_analyzer_result(s, chn, 0, ret);
+ ret = handle_analyzer_result(s, chn, 0, ret);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+ return ret;
}
/*
int ret = 1;
msg = ((chn->flags & CF_ISRESP) ? &s->txn->rsp : &s->txn->req);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s, s->txn, msg);
+
RESUME_FILTER_LOOP(s, chn) {
if (FLT_OPS(filter)->http_headers) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->http_headers(s, filter, msg);
if (ret <= 0)
BREAK_EXECUTION(s, chn, check_result);
channel_htx_fwd_headers(chn, htxbuf(&chn->buf));
check_result:
- return handle_analyzer_result(s, chn, an_bit, ret);
+ ret = handle_analyzer_result(s, chn, an_bit, ret);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_FLT_ANA, s);
+ return ret;
}
/*
{
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+
/* Check if all filters attached on the stream have finished their
* processing on this channel. */
if (!(chn->flags & CF_FLT_ANALYZE))
unregister_data_filter(s, chn, filter);
if (FLT_OPS(filter)->channel_end_analyze) {
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->channel_end_analyze(s, filter, chn);
if (ret <= 0)
BREAK_EXECUTION(s, chn, end);
/* Remove backend filters from the list */
flt_stream_release(s, 1);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
+ }
+ else {
+ DBG_TRACE_DEVEL("waiting for sync", STRM_EV_STRM_ANA|STRM_EV_FLT_ANA, s);
}
-
return ret;
}
if (FLT_OPS(filter)->tcp_data) {
unsigned int i = ci_data(chn);
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_TCP_ANA|STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->tcp_data(s, filter, chn);
if (ret < 0)
break;
if (FLT_OPS(filter)->tcp_forward_data) {
/* Remove bytes that the current filter considered as
* forwarded */
+ DBG_TRACE_DEVEL(FLT_ID(filter), STRM_EV_TCP_ANA|STRM_EV_FLT_ANA, s);
ret = FLT_OPS(filter)->tcp_forward_data(s, filter, chn, ret - *fwd);
if (ret < 0)
goto end;
{
int ret = 1;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA|STRM_EV_FLT_ANA, s);
+
/* If there is no "data" filters, we do nothing */
if (!HAS_DATA_FILTERS(s, chn))
goto end;
}
/* Wait for data */
+ DBG_TRACE_DEVEL("waiting for more data", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA|STRM_EV_FLT_ANA, s);
return 0;
end:
/* Terminate the data filtering. If <ret> is negative, an error was
* encountered during the filtering. */
- return handle_analyzer_result(s, chn, an_bit, ret);
+ ret = handle_analyzer_result(s, chn, an_bit, ret);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA|STRM_EV_FLT_ANA, s);
+ return ret;
}
/*
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= finst;
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_FLT_ANA|STRM_EV_FLT_ERR, s);
return 0;
wait:
if (!(chn->flags & CF_ISRESP))
channel_dont_connect(chn);
+ DBG_TRACE_DEVEL("wairing for more data", STRM_EV_FLT_ANA, s);
return 0;
}
#include <proto/stats.h>
#include <proto/vars.h>
+#define TRACE_SOURCE &trace_strm
+
extern const char *stat_status_codes[];
struct pool_head *pool_head_requri = NULL;
struct htx *htx;
struct htx_sl *sl;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&req->buf);
}
/* we're not ready yet */
+ DBG_TRACE_DEVEL("waiting for the request",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
failed_keep_alive:
s->logs.level = 0;
s->res.flags &= ~CF_EXPECT_MORE; /* speed up sending a previous response */
http_reply_and_close(s, txn->status, NULL);
+ DBG_TRACE_DEVEL("leaving by closing K/A connection",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
return_int_err:
req->analysers &= AN_REQ_FLT_END;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
goto return_prx_yield;
}
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&req->buf);
req->analyse_exp = TICK_ETERNITY;
done_without_exp: /* done with this analyser, but dont reset the analyse_exp. */
req->analysers &= ~an_bit;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
tarpit:
req->analysers &= AN_REQ_FLT_END;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
return_prx_yield:
channel_dont_connect(req);
+ DBG_TRACE_DEVEL("waiting for more data",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
return 0;
}
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
/*
* Right now, we know that we have processed the entire headers
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_R;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
sl = http_get_stline(htx);
s->logs.tv_request = now;
/* OK let's go on with the BODY now */
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
return_bad_req: /* let's centralize all bad requests */
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_R;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
{
struct http_txn *txn = s->txn;
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, &txn->req);
/* This connection is being tarpitted. The CLIENT side has
* already set the connect expiration date to the right
* timeout. We just have to check that the client is still
*/
channel_dont_connect(req);
if ((req->flags & (CF_SHUTR|CF_READ_ERROR)) == 0 &&
- !tick_is_expired(req->analyse_exp, now_ms))
+ !tick_is_expired(req->analyse_exp, now_ms)) {
+ DBG_TRACE_DEVEL("waiting for tarpit timeout expiry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
+ }
+
/* We will set the queue timer to the time spent, just for
* logging purposes. We fake a 500 server error, so that the
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_T;
+
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
struct http_msg *msg = &s->txn->req;
struct htx *htx;
-
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&req->buf);
channel_dont_connect(req);
if (!tick_isset(req->analyse_exp))
req->analyse_exp = tick_add_ifset(now_ms, s->be->timeout.httpreq);
+ DBG_TRACE_DEVEL("waiting for more data",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
s->logs.tv_request = now; /* update the request timer to reflect full request */
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
return_int_err:
_HA_ATOMIC_ADD(&sess->fe->fe_counters.failed_req, 1);
if (sess->listener->counters)
_HA_ATOMIC_ADD(&sess->listener->counters->failed_req, 1);
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
short status = 0;
int ret;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&req->buf);
* was a write error, we may recover.
*/
if (!(req->flags & (CF_READ_ERROR | CF_READ_TIMEOUT)) &&
- (s->si[1].flags & SI_FL_L7_RETRY))
+ (s->si[1].flags & SI_FL_L7_RETRY)) {
+ DBG_TRACE_DEVEL("leaving on L7 retry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
+ }
msg->msg_state = HTTP_MSG_ERROR;
http_end_request(s);
http_end_response(s);
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 1;
}
}
goto return_bad_req;
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
}
* on some systems (eg: Linux). */
channel_auto_read(req);
}
+ DBG_TRACE_DEVEL("waiting for the end of the HTTP txn",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
missing_data_or_waiting:
if (msg->flags & HTTP_MSGF_TE_CHNK)
req->flags |= CF_EXPECT_MORE;
+ DBG_TRACE_DEVEL("waiting for more data to forward",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
return_cli_abort:
s->res.analysers &= AN_RES_FLT_END; /* we're in data phase, we want to abort both directions */
if (!(s->flags & SF_FINST_MASK))
s->flags |= ((txn->rsp.msg_state < HTTP_MSG_ERROR) ? SF_FINST_H : SF_FINST_D);
+ DBG_TRACE_DEVEL("leaving on error ",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
struct htx_sl *sl;
int n;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- rep,
- rep->rex, rep->wex,
- rep->flags,
- ci_data(rep),
- rep->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&rep->buf);
if (conn->err_code == CO_ER_SSL_EARLY_FAILED) {
if ((s->be->retry_type & PR_RE_EARLY_ERROR) &&
(si_b->flags & SI_FL_L7_RETRY) &&
- do_l7_retry(s, si_b) == 0)
+ do_l7_retry(s, si_b) == 0) {
+ DBG_TRACE_DEVEL("leaving on L7 retry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
+ }
txn->status = 425;
}
s->flags |= SF_ERR_SRVCL;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_H;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
else if (rep->flags & CF_READ_TIMEOUT) {
if ((si_b->flags & SI_FL_L7_RETRY) &&
(s->be->retry_type & PR_RE_TIMEOUT)) {
- if (co_data(rep) || do_l7_retry(s, si_b) == 0)
+ if (co_data(rep) || do_l7_retry(s, si_b) == 0) {
+ DBG_TRACE_DEVEL("leaving on L7 retry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
+ }
}
_HA_ATOMIC_ADD(&s->be->be_counters.failed_resp, 1);
if (objt_server(s->target)) {
s->flags |= SF_ERR_SRVTO;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_H;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
s->flags |= SF_FINST_H;
/* process_stream() will take care of the error */
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
else if (rep->flags & CF_SHUTR) {
if ((si_b->flags & SI_FL_L7_RETRY) &&
(s->be->retry_type & PR_RE_DISCONNECTED)) {
- if (co_data(rep) || do_l7_retry(s, si_b) == 0)
+ if (co_data(rep) || do_l7_retry(s, si_b) == 0) {
+ DBG_TRACE_DEVEL("leaving on L7 retry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
+ }
}
if (txn->flags & TX_NOT_FIRST)
s->flags |= SF_ERR_SRVCL;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_H;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
s->flags |= SF_FINST_H;
/* process_stream() will take care of the error */
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
channel_dont_close(rep);
rep->flags |= CF_READ_DONTWAIT; /* try to get back here ASAP */
+ DBG_TRACE_DEVEL("waiting for more data",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
rep->analysers &= ~an_bit;
rep->analyse_exp = TICK_ETERNITY;
channel_auto_close(rep);
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
return_int_err:
}
if ((s->be->retry_type & PR_RE_JUNK_REQUEST) &&
(si_b->flags & SI_FL_L7_RETRY) &&
- do_l7_retry(s, si_b) == 0)
+ do_l7_retry(s, si_b) == 0) {
+ DBG_TRACE_DEVEL("leaving on L7 retry",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
+ }
txn->status = 502;
/* fall through */
s->si[1].flags |= SI_FL_NOLINGER;
rep->analysers &= AN_RES_FLT_END;
rep->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
abort_keep_alive:
s->logs.level = 0;
s->res.flags &= ~CF_EXPECT_MORE; /* speed up sending a previous response */
http_reply_and_close(s, txn->status, NULL);
+ DBG_TRACE_DEVEL("leaving by closing K/A connection",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
if (unlikely(msg->msg_state < HTTP_MSG_BODY)) /* we need more data */
return 0;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- rep,
- rep->rex, rep->wex,
- rep->flags,
- ci_data(rep),
- rep->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&rep->buf);
/* we need to be called again. */
if (ret == HTTP_RULE_RES_YIELD) {
channel_dont_close(rep);
+ DBG_TRACE_DEVEL("waiting for more data",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
}
s->do_log(s);
s->logs.bytes_out = 0;
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
return_bad_resp:
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_H;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
struct htx *htx;
int ret;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- res,
- res->rex, res->wex,
- res->flags,
- ci_data(res),
- res->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn, msg);
htx = htxbuf(&res->buf);
msg->msg_state = HTTP_MSG_ERROR;
http_end_response(s);
http_end_request(s);
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 1;
}
}
goto return_bad_res;
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 1;
}
+ DBG_TRACE_DEVEL("waiting for the end of the HTTP txn",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
missing_data_or_waiting:
res->flags |= CF_EXPECT_MORE;
/* the stream handler will take care of timeouts and errors */
+ DBG_TRACE_DEVEL("waiting for more data to forward",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA, s, txn);
return 0;
return_srv_abort:
s->req.analysers &= AN_REQ_FLT_END; /* we're in data phase, we want to abort both directions */
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_D;
+ DBG_TRACE_DEVEL("leaving on error",
+ STRM_EV_STRM_ANA|STRM_EV_HTTP_ANA|STRM_EV_HTTP_ERR, s, txn);
return 0;
}
struct channel *chn = &s->req;
struct http_txn *txn = s->txn;
- DPRINTF(stderr,"[%u] %s: stream=%p states=%s,%s req->analysers=0x%08x res->analysers=0x%08x\n",
- now_ms, __FUNCTION__, s,
- h1_msg_state_str(txn->req.msg_state), h1_msg_state_str(txn->rsp.msg_state),
- s->req.analysers, s->res.analysers);
+ DBG_TRACE_ENTER(STRM_EV_HTTP_ANA, s, txn);
if (unlikely(txn->req.msg_state == HTTP_MSG_ERROR ||
txn->rsp.msg_state == HTTP_MSG_ERROR)) {
goto end;
}
- if (unlikely(txn->req.msg_state < HTTP_MSG_DONE))
+ if (unlikely(txn->req.msg_state < HTTP_MSG_DONE)) {
+ DBG_TRACE_DEVEL("waiting end of the request", STRM_EV_HTTP_ANA, s, txn);
return;
+ }
if (txn->req.msg_state == HTTP_MSG_DONE) {
/* No need to read anymore, the request was completely parsed.
/* The server has not finished to respond, so we
* don't want to move in order not to upset it.
*/
+ DBG_TRACE_DEVEL("waiting end of the response", STRM_EV_HTTP_ANA, s, txn);
return;
}
* poll for reads.
*/
channel_auto_read(chn);
- if (b_data(&chn->buf))
+ if (b_data(&chn->buf)) {
+ DBG_TRACE_DEVEL("waiting to flush the request", STRM_EV_HTTP_ANA, s, txn);
return;
+ }
txn->req.msg_state = HTTP_MSG_TUNNEL;
}
else {
txn->req.msg_state = HTTP_MSG_ERROR;
goto end;
}
+ DBG_TRACE_LEAVE(STRM_EV_HTTP_ANA, s, txn);
return;
}
chn->analysers |= AN_REQ_FLT_XFER_DATA;
channel_auto_close(chn);
channel_auto_read(chn);
+ DBG_TRACE_LEAVE(STRM_EV_HTTP_ANA, s, txn);
}
struct channel *chn = &s->res;
struct http_txn *txn = s->txn;
- DPRINTF(stderr,"[%u] %s: stream=%p states=%s,%s req->analysers=0x%08x res->analysers=0x%08x\n",
- now_ms, __FUNCTION__, s,
- h1_msg_state_str(txn->req.msg_state), h1_msg_state_str(txn->rsp.msg_state),
- s->req.analysers, s->res.analysers);
+ DBG_TRACE_ENTER(STRM_EV_HTTP_ANA, s, txn);
if (unlikely(txn->req.msg_state == HTTP_MSG_ERROR ||
txn->rsp.msg_state == HTTP_MSG_ERROR)) {
goto end;
}
- if (unlikely(txn->rsp.msg_state < HTTP_MSG_DONE))
+ if (unlikely(txn->rsp.msg_state < HTTP_MSG_DONE)) {
+ DBG_TRACE_DEVEL("waiting end of the response", STRM_EV_HTTP_ANA, s, txn);
return;
+ }
if (txn->rsp.msg_state == HTTP_MSG_DONE) {
/* In theory, we don't need to read anymore, but we must
* We have the choice of either breaking the connection
* or letting it pass through. Let's do the later.
*/
+ DBG_TRACE_DEVEL("waiting end of the request", STRM_EV_HTTP_ANA, s, txn);
return;
}
if (txn->flags & TX_CON_WANT_TUN) {
channel_auto_read(chn);
chn->flags |= CF_NEVER_WAIT;
- if (b_data(&chn->buf))
+ if (b_data(&chn->buf)) {
+ DBG_TRACE_DEVEL("waiting to flush the respone", STRM_EV_HTTP_ANA, s, txn);
return;
+ }
txn->rsp.msg_state = HTTP_MSG_TUNNEL;
}
else {
_HA_ATOMIC_ADD(&objt_server(s->target)->counters.cli_aborts, 1);
goto end;
}
+ DBG_TRACE_LEAVE(STRM_EV_HTTP_ANA, s, txn);
return;
}
chn->analysers |= AN_RES_FLT_XFER_DATA;
channel_auto_close(chn);
channel_auto_read(chn);
+ DBG_TRACE_LEAVE(STRM_EV_HTTP_ANA, s, txn);
}
void http_server_error(struct stream *s, struct stream_interface *si, int err,
static struct list service_keywords = LIST_HEAD_INIT(service_keywords);
+/* trace source and events */
+static void strm_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 :
+ * strm - stream
+ * si - stream interface
+ * http - http analyzis
+ * tcp - tcp analyzis
+ *
+ * STRM_EV_* macros are defined in <proto/stream.h>
+ */
+static const struct trace_event strm_trace_events[] = {
+ { .mask = STRM_EV_STRM_NEW, .name = "strm_new", .desc = "new stream" },
+ { .mask = STRM_EV_STRM_FREE, .name = "strm_free", .desc = "release stream" },
+ { .mask = STRM_EV_STRM_ERR, .name = "strm_err", .desc = "error during stream processing" },
+ { .mask = STRM_EV_STRM_ANA, .name = "strm_ana", .desc = "stream analyzers" },
+ { .mask = STRM_EV_STRM_PROC, .name = "strm_proc", .desc = "stream processing" },
+
+ { .mask = STRM_EV_SI_ST, .name = "si_state", .desc = "processing stream-interface states" },
+
+ { .mask = STRM_EV_HTTP_ANA, .name = "http_ana", .desc = "HTTP analyzers" },
+ { .mask = STRM_EV_HTTP_ERR, .name = "http_err", .desc = "error during HTTP analyzis" },
+
+ { .mask = STRM_EV_TCP_ANA, .name = "tcp_ana", .desc = "TCP analyzers" },
+ { .mask = STRM_EV_TCP_ERR, .name = "tcp_err", .desc = "error during TCP analyzis" },
+ {}
+};
+
+static const struct name_desc strm_trace_lockon_args[4] = {
+ /* arg1 */ { /* already used by the stream */ },
+ /* arg2 */ { },
+ /* arg3 */ { },
+ /* arg4 */ { }
+};
+
+static const struct name_desc strm_trace_decoding[] = {
+#define STRM_VERB_CLEAN 1
+ { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" },
+#define STRM_VERB_MINIMAL 2
+ { .name="minimal", .desc="report info on stream and stream-interfaces" },
+#define STRM_VERB_SIMPLE 3
+ { .name="simple", .desc="add info on request and response channels" },
+#define STRM_VERB_ADVANCED 4
+ { .name="advanced", .desc="add info on channel's buffer for data and developer levels only" },
+#define STRM_VERB_COMPLETE 5
+ { .name="complete", .desc="add info on channel's buffer" },
+ { /* end */ }
+};
+
+struct trace_source trace_strm = {
+ .name = IST("stream"),
+ .desc = "Applicative stream",
+ .arg_def = TRC_ARG1_STRM, // TRACE()'s first argument is always a stream
+ .default_cb = strm_trace,
+ .known_events = strm_trace_events,
+ .lockon_args = strm_trace_lockon_args,
+ .decoding = strm_trace_decoding,
+ .report_events = ~0, // report everything by default
+};
+
+#define TRACE_SOURCE &trace_strm
+INITCALL1(STG_REGISTER, trace_register_source, TRACE_SOURCE);
+
+/* the stream traces always expect that arg1, if non-null, is of a stream (from
+ * which we can derive everything), that arg2, if non-null, is an http
+ * transaction, that arg3, if non-null, is an http message.
+ */
+static void strm_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 stream *s = a1;
+ const struct http_txn *txn = a2;
+ const struct http_msg *msg = a3;
+ struct task *task;
+ const struct stream_interface *si_f, *si_b;
+ const struct channel *req, *res;
+ struct htx *htx;
+
+ if (!s || src->verbosity < STRM_VERB_CLEAN)
+ return;
+
+ task = s->task;
+ si_f = &s->si[0];
+ si_b = &s->si[1];
+ req = &s->req;
+ res = &s->res;
+ htx = (msg ? htxbuf(&msg->chn->buf) : NULL);
+
+ /* General info about the stream (htx/tcp, id...) */
+ chunk_appendf(&trace_buf, " : [%u,%s]",
+ s->uniq_id, ((s->flags & SF_HTX) ? "HTX" : "TCP"));
+ if (s->unique_id)
+ chunk_appendf(&trace_buf, " id=%s", s->unique_id);
+
+ /* Front and back stream-int state */
+ chunk_appendf(&trace_buf, " SI=(%s,%s)",
+ si_state_str(si_f->state), si_state_str(si_b->state));
+
+ /* If txn is defined, HTTP req/rep states */
+ if (txn)
+ chunk_appendf(&trace_buf, " HTTP=(%s,%s)",
+ h1_msg_state_str(txn->req.msg_state), h1_msg_state_str(txn->rsp.msg_state));
+ if (msg)
+ chunk_appendf(&trace_buf, " %s", ((msg->chn->flags & CF_ISRESP) ? "RESPONSE" : "REQUEST"));
+
+ if (src->verbosity == STRM_VERB_CLEAN)
+ return;
+
+ /* If msg defined, display status-line if possible (verbosity > MINIMAL) */
+ if (src->verbosity > STRM_VERB_MINIMAL && htx && htx_nbblks(htx)) {
+ const struct htx_blk *blk = htx_get_head_blk(htx);
+ const struct htx_sl *sl = htx_get_blk_ptr(htx, blk);
+ enum htx_blk_type type = htx_get_blk_type(blk);
+
+ if (type == HTX_BLK_REQ_SL || type == HTX_BLK_RES_SL)
+ chunk_appendf(&trace_buf, " - \"%.*s %.*s %.*s\"",
+ HTX_SL_P1_LEN(sl), HTX_SL_P1_PTR(sl),
+ HTX_SL_P2_LEN(sl), HTX_SL_P2_PTR(sl),
+ HTX_SL_P3_LEN(sl), HTX_SL_P3_PTR(sl));
+ }
+
+
+ /* If txn defined info about HTTP msgs, otherwise info about SI. */
+ if (txn) {
+ chunk_appendf(&trace_buf, " - t=%p s=(%p,0x%08x) txn.flags=0x%08x, http.flags=(0x%08x,0x%08x) status=%d",
+ task, s, s->flags, txn->flags, txn->req.flags, txn->rsp.flags, txn->status);
+ }
+ else {
+ chunk_appendf(&trace_buf, " - t=%p s=(%p,0x%08x) si_f=(%p,0x%08x,0x%x) si_b=(%p,0x%08x,0x%x) retries=%d",
+ task, s, s->flags, si_f, si_f->flags, si_f->err_type,
+ si_b, si_b->flags, si_b->err_type, si_b->conn_retries);
+ }
+
+ if (src->verbosity == STRM_VERB_MINIMAL)
+ return;
+
+
+ /* If txn defined, don't display all channel info */
+ if (src->verbosity == STRM_VERB_SIMPLE || txn) {
+ chunk_appendf(&trace_buf, " req=(%p .fl=0x%08x .exp(r,w,a)=(%u,%u,%u))",
+ req, req->flags, req->rex, req->wex, req->analyse_exp);
+ chunk_appendf(&trace_buf, " res=(%p .fl=0x%08x .exp(r,w,a)=(%u,%u,%u))",
+ res, res->flags, res->rex, res->wex, res->analyse_exp);
+ }
+ else {
+ chunk_appendf(&trace_buf, " req=(%p .fl=0x%08x .ana=0x%08x .exp(r,w,a)=(%u,%u,%u) .o=%lu .tot=%llu .to_fwd=%u)",
+ req, req->flags, req->analysers, req->rex, req->wex, req->analyse_exp,
+ req->output, req->total, req->to_forward);
+ chunk_appendf(&trace_buf, " res=(%p .fl=0x%08x .ana=0x%08x .exp(r,w,a)=(%u,%u,%u) .o=%lu .tot=%llu .to_fwd=%u)",
+ res, res->flags, res->analysers, res->rex, res->wex, res->analyse_exp,
+ res->output, res->total, res->to_forward);
+ }
+
+ if (src->verbosity == STRM_VERB_SIMPLE ||
+ (src->verbosity == STRM_VERB_ADVANCED && src->level < TRACE_LEVEL_DATA))
+ return;
+
+ /* channels' buffer info */
+ if (s->flags & SF_HTX) {
+ struct htx *rqhtx = htxbuf(&req->buf);
+ struct htx *rphtx = htxbuf(&res->buf);
+
+ chunk_appendf(&trace_buf, " htx=(%u/%u#%u, %u/%u#%u)",
+ rqhtx->data, rqhtx->size, htx_nbblks(rqhtx),
+ rphtx->data, rphtx->size, htx_nbblks(rphtx));
+ }
+ else {
+ chunk_appendf(&trace_buf, " buf=(%u@%p+%u/%u, %u@%p+%u/%u)",
+ (unsigned int)b_data(&req->buf), b_orig(&req->buf),
+ (unsigned int)b_head_ofs(&req->buf), (unsigned int)b_size(&req->buf),
+ (unsigned int)b_data(&req->buf), b_orig(&req->buf),
+ (unsigned int)b_head_ofs(&req->buf), (unsigned int)b_size(&req->buf));
+ }
+
+ /* If msg defined, display htx info if defined (level > USER) */
+ if (src->level > TRACE_LEVEL_USER && htx && htx_nbblks(htx)) {
+ int full = 0;
+
+ /* Full htx info (level > STATE && verbosity > SIMPLE) */
+ if (src->level > TRACE_LEVEL_STATE) {
+ if (src->verbosity == STRM_VERB_COMPLETE)
+ full = 1;
+ }
+
+ chunk_memcat(&trace_buf, "\n\t", 2);
+ htx_dump(&trace_buf, htx, full);
+ }
+}
+
/* Create a new stream for connection <conn>. Return < 0 on error. This is only
* valid right after the handshake, before the connection's data layer is
* initialized, because it relies on the session to be in conn->owner.
struct appctx *appctx = objt_appctx(origin);
const struct cs_info *csinfo;
+ DBG_TRACE_ENTER(STRM_EV_STRM_NEW);
if (unlikely((s = pool_alloc(pool_head_stream)) == NULL))
goto out_fail_alloc;
* stream is fully initialized before calling task_wakeup. So
* the caller must handle the task_wakeup
*/
+ DBG_TRACE_LEAVE(STRM_EV_STRM_NEW, s);
return s;
/* Error unrolling */
tasklet_free(s->si[0].wait_event.tasklet);
out_fail_alloc:
pool_free(pool_head_stream, s);
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_STRM_NEW|STRM_EV_STRM_ERR);
return NULL;
}
int must_free_sess;
int i;
+ DBG_TRACE_POINT(STRM_EV_STRM_FREE, s);
+
/* detach the stream from its own task before even releasing it so
* that walking over a task list never exhibits a dying stream.
*/
struct conn_stream *srv_cs = objt_cs(si->end);
struct connection *conn = srv_cs ? srv_cs->conn : objt_conn(si->end);
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+
/* the client might want to abort */
if ((rep->flags & CF_SHUTW) ||
((req->flags & CF_SHUTW_NOW) &&
if (s->srv_error)
s->srv_error(s, si);
/* Note: state = SI_ST_DIS now */
- return;
+ DBG_TRACE_STATE("client abort during connection attempt", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
}
/* retryable error ? */
- if (si->flags & (SI_FL_EXP|SI_FL_ERR)) {
+ else if (si->flags & (SI_FL_EXP|SI_FL_ERR)) {
if (!(s->flags & SF_SRV_REUSED) && conn) {
conn_stop_tracking(conn);
conn_full_close(conn);
}
si->state = SI_ST_CER;
- return;
+ DBG_TRACE_STATE("connection failed, retry", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
}
+
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
/* This function is called with (si->state == SI_ST_CER) meaning that a
struct conn_stream *cs = objt_cs(si->end);
struct connection *conn = cs_conn(cs);
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+
si->exp = TICK_ETERNITY;
si->flags &= ~SI_FL_EXP;
* client provoke retries.
*/
si->conn_retries = 0;
+ DBG_TRACE_DEVEL("Bad SSL cert, disable connection retries", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
}
}
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
- return;
+
+ DBG_TRACE_STATE("connection failed", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
stream_choose_redispatch(s);
si->exp = tick_add(now_ms, MS_TO_TICKS(delay));
}
si->flags &= ~SI_FL_ERR;
+ DBG_TRACE_STATE("retry a new connection", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
+
+ end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
/* This function is called with (si->state == SI_ST_RDY) meaning that a
struct conn_stream *srv_cs = objt_cs(si->end);
struct connection *conn = srv_cs ? srv_cs->conn : objt_conn(si->end);
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
/* We know the connection at least succeeded, though it could have
* since met an error for any other reason. At least it didn't time out
* eventhough the timeout might have been reported right after success.
si->err_type |= SI_ET_CONN_ABRT;
if (s->srv_error)
s->srv_error(s, si);
- return;
+ DBG_TRACE_STATE("client abort during connection attempt", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
/* retryable error ? */
if (!si->err_type)
si->err_type = SI_ET_CONN_ERR;
si->state = SI_ST_CER;
- return;
+ DBG_TRACE_STATE("connection failed, retry", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
}
/* data were sent and/or we had no error, sess_establish() will
* now take over.
*/
+ DBG_TRACE_STATE("connection established", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
si->err_type = SI_ET_NONE;
si->state = SI_ST_EST;
+
+ end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
/*
struct channel *req = &s->req;
struct channel *rep = &s->res;
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
/* First, centralize the timers information, and clear any irrelevant
* timeout.
*/
req->flags |= CF_WRITE_ERROR;
rep->flags |= CF_READ_ERROR;
si->err_type = SI_ET_DATA_ERR;
+ DBG_TRACE_STATE("read/write error", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
}
if (objt_server(s->target))
req->wex = TICK_ETERNITY;
/* If we managed to get the whole response, and we don't have anything
* left to send, or can't, switch to SI_ST_DIS now. */
- if (rep->flags & (CF_SHUTR | CF_SHUTW))
+ if (rep->flags & (CF_SHUTR | CF_SHUTW)) {
si->state = SI_ST_DIS;
+ DBG_TRACE_STATE("response channel shutdwn for read/write", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ }
+
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
/* Check if the connection request is in such a state that it can be aborted. */
struct stream_interface *si = &s->si[1];
struct channel *req = &s->req;
- DPRINTF(stderr,"[%u] %s: sess=%p rq=%p, rp=%p, exp(r,w)=%u,%u rqf=%08x rpf=%08x rqh=%lu rqt=%lu rph=%lu rpt=%lu cs=%d ss=%d\n",
- now_ms, __FUNCTION__,
- s,
- req, &s->res,
- req->rex, s->res.wex,
- req->flags, s->res.flags,
- ci_data(req), co_data(req), ci_data(&s->res), co_data(&s->res), s->si[0].state, s->si[1].state);
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
if (si->state == SI_ST_ASS) {
/* Server assigned to connection request, we have to try to connect now */
*/
if (check_req_may_abort(req, s)) {
si->err_type |= SI_ET_CONN_ABRT;
+ DBG_TRACE_STATE("connection aborted", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
goto abort_connection;
}
srv_inc_sess_ctr(srv);
if (srv)
srv_set_sess_last(srv);
- return;
+ DBG_TRACE_STATE("connection attempt", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+ goto end;
}
/* We have received a synchronous error. We might have to
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
- return;
+ DBG_TRACE_STATE("internal error during connection", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
/* We are facing a retryable error, but we don't want to run a
si->state = SI_ST_CER;
si->flags &= ~SI_FL_ERR;
sess_update_st_cer(s);
+
+ DBG_TRACE_STATE("connection error, retry", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
/* now si->state is one of SI_ST_CLO, SI_ST_TAR, SI_ST_ASS, SI_ST_REQ */
- return;
}
else if (si->state == SI_ST_QUE) {
/* connection request was queued, check for any update */
s->logs.t_queue = tv_ms_elapsed(&s->logs.tv_accept, &now);
si->state = SI_ST_ASS;
}
- return;
+ DBG_TRACE_STATE("dequeue connection request", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+ goto end;
}
/* Connection request still in queue... */
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
- return;
+ DBG_TRACE_STATE("connection request still queued", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+ goto end;
}
/* Connection remains in queue, check if we have to abort it */
pendconn_cond_unlink(s->pend_pos);
si->err_type |= SI_ET_QUEUE_ABRT;
+ DBG_TRACE_STATE("abort queued connection request", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
goto abort_connection;
}
/* Nothing changed */
- return;
}
else if (si->state == SI_ST_TAR) {
/* Connection request might be aborted */
if (check_req_may_abort(req, s)) {
si->err_type |= SI_ET_CONN_ABRT;
+ DBG_TRACE_STATE("connection aborted", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
goto abort_connection;
}
si->state = SI_ST_ASS;
else
si->state = SI_ST_REQ;
- return;
+
+ DBG_TRACE_STATE("retry connection now", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
+
+ end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
return;
abort_connection:
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
return;
}
{
struct stream_interface *si = &s->si[1];
- DPRINTF(stderr,"[%u] %s: sess=%p rq=%p, rp=%p, exp(r,w)=%u,%u rqf=%08x rpf=%08x rqh=%lu rqt=%lu rph=%lu rpt=%lu cs=%d ss=%d\n",
- now_ms, __FUNCTION__,
- s,
- &s->req, &s->res,
- s->req.rex, s->res.wex,
- s->req.flags, s->res.flags,
- ci_data(&s->req), co_data(&s->req), ci_data(&s->res), co_data(&s->res), s->si[0].state, s->si[1].state);
-
if (si->state != SI_ST_REQ)
return;
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+
if (unlikely(obj_type(s->target) == OBJ_TYPE_APPLET)) {
/* the applet directly goes to the EST state */
struct appctx *appctx = objt_appctx(si->end);
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
- return;
+ DBG_TRACE_STATE("failed to register applet", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
if (tv_iszero(&s->logs.tv_request))
si->state = SI_ST_EST;
si->err_type = SI_ET_NONE;
be_set_sess_last(s->be);
+
+ DBG_TRACE_STATE("applet registered", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
/* let sess_establish() finish the job */
- return;
+ goto end;
}
/* Try to assign a server */
/* We did not get a server. Either we queued the
* connection request, or we encountered an error.
*/
- if (si->state == SI_ST_QUE)
- return;
+ if (si->state == SI_ST_QUE) {
+ DBG_TRACE_STATE("connection request queued", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+ goto end;
+ }
/* we did not get any server, let's check the cause */
si_shutr(si);
si->state = SI_ST_CLO;
if (s->srv_error)
s->srv_error(s, si);
- return;
+ DBG_TRACE_STATE("connection request failed", STRM_EV_STRM_PROC|STRM_EV_SI_ST|STRM_EV_STRM_ERR, s);
+ goto end;
}
/* The server is assigned */
s->logs.t_queue = tv_ms_elapsed(&s->logs.tv_accept, &now);
si->state = SI_ST_ASS;
be_set_sess_last(s->be);
+ DBG_TRACE_STATE("connection request assigned to a server", STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
+
+ end:
+ DBG_TRACE_LEAVE(STRM_EV_STRM_PROC|STRM_EV_SI_ST, s);
}
/* This function parses the use-service action ruleset. It executes
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA, s);
/* now check whether we have some switching rules for this request */
if (!(s->flags & SF_BE_ASSIGNED)) {
}
}
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA, s);
return 1;
sw_failed:
s->txn->status = 500;
s->req.analysers &= AN_REQ_FLT_END;
s->req.analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_STRM_ANA|STRM_EV_STRM_ERR, s);
return 0;
}
struct session *sess = s->sess;
struct server_rule *rule;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bl=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- c_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA, s);
if (!(s->flags & SF_ASSIGNED)) {
list_for_each_entry(rule, &px->server_rules, list) {
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA, s);
return 1;
}
struct session *sess = s->sess;
struct sticking_rule *rule;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA, s);
list_for_each_entry(rule, &px->sticking_rules, list) {
int ret = 1 ;
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA, s);
return 1;
}
int i;
int nbreq = s->store_count;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- rep,
- rep->rex, rep->wex,
- rep->flags,
- ci_data(rep),
- rep->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA, s);
list_for_each_entry(rule, &px->storersp_rules, list) {
int ret = 1 ;
rep->analysers &= ~an_bit;
rep->analyse_exp = TICK_ETERNITY;
+
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA, s);
return 1;
}
struct stream_interface *si_f, *si_b;
unsigned int rate;
+ DBG_TRACE_ENTER(STRM_EV_STRM_PROC, s);
+
activity[tid].stream++;
req = &s->req;
stream_dump_and_crash(&s->obj_type, read_freq_ctr(&s->call_rate));
}
- //DPRINTF(stderr, "%s:%d: cs=%d ss=%d(%d) rqf=0x%08x rpf=0x%08x\n", __FUNCTION__, __LINE__,
- // si_f->state, si_b->state, si_b->err_type, req->flags, res->flags);
-
/* this data may be no longer valid, clear it */
if (s->txn)
memset(&s->txn->auth, 0, sizeof(s->txn->auth));
rp_prod_last = si_b->state;
/* Check for connection closure */
-
- DPRINTF(stderr,
- "[%u] %s:%d: task=%p s=%p, sfl=0x%08x, rq=%p, rp=%p, exp(r,w)=%u,%u rqf=%08x rpf=%08x rqh=%lu rqt=%lu rph=%lu rpt=%lu cs=%d ss=%d, cet=0x%x set=0x%x retr=%d\n",
- now_ms, __FUNCTION__, __LINE__,
- t,
- s, s->flags,
- req, res,
- req->rex, res->wex,
- req->flags, res->flags,
- ci_data(req), co_data(req), ci_data(res), co_data(res), si_f->state, si_b->state,
- si_f->err_type, si_b->err_type,
- si_b->conn_retries);
+ DBG_TRACE_POINT(STRM_EV_STRM_PROC, s);
/* nothing special to be done on client side */
if (unlikely(si_f->state == SI_ST_DIS))
if (si_b->exp)
t->expire = tick_first(t->expire, si_b->exp);
- DPRINTF(stderr,
- "[%u] queuing with exp=%u req->rex=%u req->wex=%u req->ana_exp=%u"
- " rep->rex=%u rep->wex=%u, si[0].exp=%u, si[1].exp=%u, cs=%d, ss=%d\n",
- now_ms, t->expire, req->rex, req->wex, req->analyse_exp,
- res->rex, res->wex, si_f->exp, si_b->exp, si_f->state, si_b->state);
-
s->pending_events &= ~(TASK_WOKEN_TIMER | TASK_WOKEN_RES);
stream_release_buffers(s);
+
+ DBG_TRACE_DEVEL("queuing", STRM_EV_STRM_PROC, s);
return t; /* nothing more to do */
}
+ DBG_TRACE_DEVEL("releasing", STRM_EV_STRM_PROC, s);
+
if (s->flags & SF_BE_ASSIGNED)
_HA_ATOMIC_SUB(&s->be->beconn, 1);
#include <proto/stream_interface.h>
#include <proto/tcp_rules.h>
+#define TRACE_SOURCE &trace_strm
+
/* List head of all known action keywords for "tcp-request connection" */
struct list tcp_req_conn_keywords = LIST_HEAD_INIT(tcp_req_conn_keywords);
struct list tcp_req_sess_keywords = LIST_HEAD_INIT(tcp_req_sess_keywords);
int partial;
int act_flags = 0;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- req,
- req->rex, req->wex,
- req->flags,
- ci_data(req),
- req->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
/* We don't know whether we have enough data, so must proceed
* this way :
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_R;
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA|STRM_EV_TCP_ERR, s);
return 0;
}
else if (rule->action >= ACT_ACTION_TRK_SC0 && rule->action <= ACT_ACTION_TRK_SCMAX) {
*/
req->analysers &= ~an_bit;
req->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 1;
missing_data:
/* just set the request timeout once at the beginning of the request */
if (!tick_isset(req->analyse_exp) && s->be->tcp_req.inspect_delay)
req->analyse_exp = tick_add(now_ms, s->be->tcp_req.inspect_delay);
+ DBG_TRACE_DEVEL("waiting for more data", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 0;
}
int partial;
int act_flags = 0;
- DPRINTF(stderr,"[%u] %s: stream=%p b=%p, exp(r,w)=%u,%u bf=%08x bh=%lu analysers=%02x\n",
- now_ms, __FUNCTION__,
- s,
- rep,
- rep->rex, rep->wex,
- rep->flags,
- ci_data(rep),
- rep->analysers);
+ DBG_TRACE_ENTER(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
/* We don't know whether we have enough data, so must proceed
* this way :
/* just set the analyser timeout once at the beginning of the response */
if (!tick_isset(rep->analyse_exp) && s->be->tcp_rep.inspect_delay)
rep->analyse_exp = tick_add(now_ms, s->be->tcp_rep.inspect_delay);
+ DBG_TRACE_DEVEL("waiting for more data", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 0;
}
s->flags |= SF_ERR_PRXCOND;
if (!(s->flags & SF_FINST_MASK))
s->flags |= SF_FINST_D;
+ DBG_TRACE_DEVEL("leaving on error", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA|STRM_EV_TCP_ERR, s);
return 0;
}
else if (rule->action == ACT_TCP_CLOSE) {
case ACT_RET_YIELD:
channel_dont_close(rep);
s->current_rule = rule;
+ DBG_TRACE_DEVEL("waiting for more data", STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 0;
}
break; /* ACT_RET_STOP/DONE */
*/
rep->analysers &= ~an_bit;
rep->analyse_exp = TICK_ETERNITY;
+ DBG_TRACE_LEAVE(STRM_EV_STRM_ANA|STRM_EV_TCP_ANA, s);
return 1;
}
projects / thirdparty / haproxy.git / commitdiff
