From 5c0f859c27264a844d6303ab0fff110cc83f4b9c Mon Sep 17 00:00:00 2001 From: Christopher Faulet Date: Fri, 4 Oct 2019 15:21:17 +0200 Subject: [PATCH] MINOR: mux-fcgi/trace: Register a new trace source with its events As for the mux h1 and h2, traces are now supported in the mux fcgi. All parts of the multiplexer is covered by these traces. Events are splitted by categories (fconn, fstrm, stream, rx, tx and rsp) for a total of ~40 different events with 5 verboisty levels. In traces, the first argument is always a connection. So it is easy to get the fconn (conn->ctx). The second argument is always a fstrm. The third one is an HTX message. Depending on the context it is the request or the response. In all cases it is owned by a channel. Finally, the fourth argument is an integer value. Its meaning depends on the calling context. --- src/mux_fcgi.c | 800 +++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 714 insertions(+), 86 deletions(-) diff --git a/src/mux_fcgi.c b/src/mux_fcgi.c index c459e76a9a..681669c51b 100644 --- a/src/mux_fcgi.c +++ b/src/mux_fcgi.c @@ -32,6 +32,7 @@ #include #include #include +#include /* FCGI Connection flags (32 bits) */ #define FCGI_CF_NONE 0x00000000 @@ -212,6 +213,142 @@ struct fcgi_strm_params { /* Maximum amount of data we're OK with re-aligning for buffer optimizations */ #define MAX_DATA_REALIGN 1024 +/* trace source and events */ +static void fcgi_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 : + * fconn - internal FCGI connection + * fstrm - internal FCGI stream + * strm - application layer + * rx - data receipt + * tx - data transmission + * rsp - response parsing + */ +static const struct trace_event fcgi_trace_events[] = { +#define FCGI_EV_FCONN_NEW (1ULL << 0) + { .mask = FCGI_EV_FCONN_NEW, .name = "fconn_new", .desc = "new FCGI connection" }, +#define FCGI_EV_FCONN_RECV (1ULL << 1) + { .mask = FCGI_EV_FCONN_RECV, .name = "fconn_recv", .desc = "Rx on FCGI connection" }, +#define FCGI_EV_FCONN_SEND (1ULL << 2) + { .mask = FCGI_EV_FCONN_SEND, .name = "fconn_send", .desc = "Tx on FCGI connection" }, +#define FCGI_EV_FCONN_BLK (1ULL << 3) + { .mask = FCGI_EV_FCONN_BLK, .name = "fconn_blk", .desc = "FCGI connection blocked" }, +#define FCGI_EV_FCONN_WAKE (1ULL << 4) + { .mask = FCGI_EV_FCONN_WAKE, .name = "fconn_wake", .desc = "FCGI connection woken up" }, +#define FCGI_EV_FCONN_END (1ULL << 5) + { .mask = FCGI_EV_FCONN_END, .name = "fconn_end", .desc = "FCGI connection terminated" }, +#define FCGI_EV_FCONN_ERR (1ULL << 6) + { .mask = FCGI_EV_FCONN_ERR, .name = "fconn_err", .desc = "error on FCGI connection" }, + +#define FCGI_EV_RX_FHDR (1ULL << 7) + { .mask = FCGI_EV_RX_FHDR, .name = "rx_fhdr", .desc = "FCGI record header received" }, +#define FCGI_EV_RX_RECORD (1ULL << 8) + { .mask = FCGI_EV_RX_RECORD, .name = "rx_record", .desc = "receipt of any FCGI record" }, +#define FCGI_EV_RX_EOI (1ULL << 9) + { .mask = FCGI_EV_RX_EOI, .name = "rx_eoi", .desc = "receipt of end of FCGI input" }, +#define FCGI_EV_RX_GETVAL (1ULL << 10) + { .mask = FCGI_EV_RX_GETVAL, .name = "rx_get_values", .desc = "receipt of FCGI GET_VALUES_RESULT record" }, +#define FCGI_EV_RX_STDOUT (1ULL << 11) + { .mask = FCGI_EV_RX_STDOUT, .name = "rx_stdout", .desc = "receipt of FCGI STDOUT record" }, +#define FCGI_EV_RX_STDERR (1ULL << 12) + { .mask = FCGI_EV_RX_STDERR, .name = "rx_stderr", .desc = "receipt of FCGI STDERR record" }, +#define FCGI_EV_RX_ENDREQ (1ULL << 13) + { .mask = FCGI_EV_RX_ENDREQ, .name = "rx_end_req", .desc = "receipt of FCGI END_REQUEST record" }, + +#define FCGI_EV_TX_RECORD (1ULL << 14) + { .mask = FCGI_EV_TX_RECORD, .name = "tx_record", .desc = "transmission of any FCGI record" }, +#define FCGI_EV_TX_EOI (1ULL << 15) + { .mask = FCGI_EV_TX_EOI, .name = "tx_eoi", .desc = "transmission of FCGI end of input" }, +#define FCGI_EV_TX_BEGREQ (1ULL << 16) + { .mask = FCGI_EV_TX_BEGREQ, .name = "tx_begin_request", .desc = "transmission of FCGI BEGIN_REQUEST record" }, +#define FCGI_EV_TX_GETVAL (1ULL << 17) + { .mask = FCGI_EV_TX_GETVAL, .name = "tx_get_values", .desc = "transmission of FCGI GET_VALUES record" }, +#define FCGI_EV_TX_PARAMS (1ULL << 18) + { .mask = FCGI_EV_TX_PARAMS, .name = "tx_params", .desc = "transmission of FCGI PARAMS record" }, +#define FCGI_EV_TX_STDIN (1ULL << 19) + { .mask = FCGI_EV_TX_STDIN, .name = "tx_stding", .desc = "transmission of FCGI STDIN record" }, +#define FCGI_EV_TX_ABORT (1ULL << 20) + { .mask = FCGI_EV_TX_ABORT, .name = "tx_abort", .desc = "transmission of FCGI ABORT record" }, + +#define FCGI_EV_RSP_DATA (1ULL << 21) + { .mask = FCGI_EV_RSP_DATA, .name = "rsp_data", .desc = "parse any data of H1 response" }, +#define FCGI_EV_RSP_EOM (1ULL << 22) + { .mask = FCGI_EV_RSP_EOM, .name = "rsp_eom", .desc = "reach the end of message of H1 response" }, +#define FCGI_EV_RSP_HDRS (1ULL << 23) + { .mask = FCGI_EV_RSP_HDRS, .name = "rsp_headers", .desc = "parse headers of H1 response" }, +#define FCGI_EV_RSP_BODY (1ULL << 24) + { .mask = FCGI_EV_RSP_BODY, .name = "rsp_body", .desc = "parse body part of H1 response" }, +#define FCGI_EV_RSP_TLRS (1ULL << 25) + { .mask = FCGI_EV_RSP_TLRS, .name = "rsp_trailerus", .desc = "parse trailers of H1 response" }, + +#define FCGI_EV_FSTRM_NEW (1ULL << 26) + { .mask = FCGI_EV_FSTRM_NEW, .name = "fstrm_new", .desc = "new FCGI stream" }, +#define FCGI_EV_FSTRM_BLK (1ULL << 27) + { .mask = FCGI_EV_FSTRM_BLK, .name = "fstrm_blk", .desc = "FCGI stream blocked" }, +#define FCGI_EV_FSTRM_END (1ULL << 28) + { .mask = FCGI_EV_FSTRM_END, .name = "fstrm_end", .desc = "FCGI stream terminated" }, +#define FCGI_EV_FSTRM_ERR (1ULL << 29) + { .mask = FCGI_EV_FSTRM_ERR, .name = "fstrm_err", .desc = "error on FCGI stream" }, + +#define FCGI_EV_STRM_NEW (1ULL << 30) + { .mask = FCGI_EV_STRM_NEW, .name = "strm_new", .desc = "app-layer stream creation" }, +#define FCGI_EV_STRM_RECV (1ULL << 31) + { .mask = FCGI_EV_STRM_RECV, .name = "strm_recv", .desc = "receiving data for stream" }, +#define FCGI_EV_STRM_SEND (1ULL << 32) + { .mask = FCGI_EV_STRM_SEND, .name = "strm_send", .desc = "sending data for stream" }, +#define FCGI_EV_STRM_FULL (1ULL << 33) + { .mask = FCGI_EV_STRM_FULL, .name = "strm_full", .desc = "stream buffer full" }, +#define FCGI_EV_STRM_WAKE (1ULL << 34) + { .mask = FCGI_EV_STRM_WAKE, .name = "strm_wake", .desc = "stream woken up" }, +#define FCGI_EV_STRM_SHUT (1ULL << 35) + { .mask = FCGI_EV_STRM_SHUT, .name = "strm_shut", .desc = "stream shutdown" }, +#define FCGI_EV_STRM_END (1ULL << 36) + { .mask = FCGI_EV_STRM_END, .name = "strm_end", .desc = "detaching app-layer stream" }, +#define FCGI_EV_STRM_ERR (1ULL << 37) + { .mask = FCGI_EV_STRM_ERR, .name = "strm_err", .desc = "stream error" }, + + { } +}; + +static const struct name_desc fcgi_trace_lockon_args[4] = { + /* arg1 */ { /* already used by the connection */ }, + /* arg2 */ { .name="fstrm", .desc="FCGI stream" }, + /* arg3 */ { }, + /* arg4 */ { } +}; + + +static const struct name_desc fcgi_trace_decoding[] = { +#define FCGI_VERB_CLEAN 1 + { .name="clean", .desc="only user-friendly stuff, generally suitable for level \"user\"" }, +#define FCGI_VERB_MINIMAL 2 + { .name="minimal", .desc="report only fconn/fstrm state and flags, no real decoding" }, +#define FCGI_VERB_SIMPLE 3 + { .name="simple", .desc="add request/response status line or htx info when available" }, +#define FCGI_VERB_ADVANCED 4 + { .name="advanced", .desc="add header fields or record decoding when available" }, +#define FCGI_VERB_COMPLETE 5 + { .name="complete", .desc="add full data dump when available" }, + { /* end */ } +}; + +static struct trace_source trace_fcgi = { + .name = IST("fcgi"), + .desc = "FastCGI multiplexer", + .arg_def = TRC_ARG1_CONN, // TRACE()'s first argument is always a connection + .default_cb = fcgi_trace, + .known_events = fcgi_trace_events, + .lockon_args = fcgi_trace_lockon_args, + .decoding = fcgi_trace_decoding, + .report_events = ~0, // report everything by default +}; + +#define TRACE_SOURCE &trace_fcgi +INITCALL1(STG_REGISTER, trace_register_source, TRACE_SOURCE); + /* FCGI connection and stream pools */ DECLARE_STATIC_POOL(pool_head_fcgi_conn, "fcgi_conn", sizeof(struct fcgi_conn)); DECLARE_STATIC_POOL(pool_head_fcgi_strm, "fcgi_strm", sizeof(struct fcgi_strm)); @@ -222,6 +359,8 @@ static struct task *fcgi_io_cb(struct task *t, void *ctx, unsigned short state); static inline struct fcgi_strm *fcgi_conn_st_by_id(struct fcgi_conn *fconn, int id); static struct task *fcgi_deferred_shut(struct task *t, void *ctx, unsigned short state); static struct fcgi_strm *fcgi_conn_stream_new(struct fcgi_conn *fconn, struct conn_stream *cs, struct session *sess); +static void fcgi_strm_notify_recv(struct fcgi_strm *fstrm); +static void fcgi_strm_notify_send(struct fcgi_strm *fstrm); static void fcgi_strm_alert(struct fcgi_strm *fstrm); static int fcgi_strm_send_abort(struct fcgi_conn *fconn, struct fcgi_strm *fstrm); @@ -243,6 +382,135 @@ static const struct fcgi_strm *fcgi_unknown_stream = &(const struct fcgi_strm){ .id = 0, }; +/* returns a fconn state as an abbreviated 3-letter string, or "???" if unknown */ +static inline const char *fconn_st_to_str(enum fcgi_conn_st st) +{ + switch (st) { + case FCGI_CS_INIT : return "INI"; + case FCGI_CS_SETTINGS : return "STG"; + case FCGI_CS_RECORD_H : return "RDH"; + case FCGI_CS_RECORD_D : return "RDD"; + case FCGI_CS_RECORD_P : return "RDP"; + case FCGI_CS_CLOSED : return "CLO"; + default : return "???"; + } +} + +/* returns a fstrm state as an abbreviated 3-letter string, or "???" if unknown */ +static inline const char *fstrm_st_to_str(enum fcgi_strm_st st) +{ + switch (st) { + case FCGI_SS_IDLE : return "IDL"; + case FCGI_SS_OPEN : return "OPN"; + case FCGI_SS_HREM : return "RCL"; + case FCGI_SS_HLOC : return "HCL"; + case FCGI_SS_ERROR : return "ERR"; + case FCGI_SS_CLOSED : return "CLO"; + default : return "???"; + } +} + + +/* the FCGI traces always expect that arg1, if non-null, is of type connection + * (from which we can derive fconn), that arg2, if non-null, is of type fstrm, + * and that arg3, if non-null, is a htx for rx/tx headers. + */ +static void fcgi_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 connection *conn = a1; + const struct fcgi_conn *fconn = conn ? conn->ctx : NULL; + const struct fcgi_strm *fstrm = a2; + const struct htx *htx = a3; + const size_t *val = a4; + + if (!fconn) + fconn = (fstrm ? fstrm->fconn : NULL); + + if (!fconn || src->verbosity < FCGI_VERB_CLEAN) + return; + + /* Display the response state if fstrm is defined */ + if (fstrm) + chunk_appendf(&trace_buf, " [rsp:%s]", h1m_state_str(fstrm->h1m.state)); + + if (src->verbosity == FCGI_VERB_CLEAN) + return; + + /* Display the value to the 4th argument (level > STATE) */ + if (src->level > TRACE_LEVEL_STATE && val) + chunk_appendf(&trace_buf, " - VAL=%lu", *val); + + /* Display status-line if possible (verbosity > MINIMAL) */ + if (src->verbosity > FCGI_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)); + } + + /* Display fconn info and, if defined, fstrm info */ + chunk_appendf(&trace_buf, " - fconn=%p(%s,0x%08x)", fconn, fconn_st_to_str(fconn->state), fconn->flags); + if (fstrm) + chunk_appendf(&trace_buf, " fstrm=%p(%d,%s,0x%08x)", fstrm, fstrm->id, fstrm_st_to_str(fstrm->state), fstrm->flags); + + if (!fstrm || fstrm->id <= 0) + chunk_appendf(&trace_buf, " dsi=%d", fconn->dsi); + if (fconn->dsi >= 0 && (mask & FCGI_EV_RX_FHDR)) + chunk_appendf(&trace_buf, " drt=%s", fcgi_rt_str(fconn->drt)); + + if (src->verbosity == FCGI_VERB_MINIMAL) + return; + + /* Display mbuf and dbuf info (level > USER & verbosity > SIMPLE) */ + if (src->level > TRACE_LEVEL_USER) { + if (src->verbosity == FCGI_VERB_COMPLETE || + (src->verbosity == FCGI_VERB_ADVANCED && (mask & (FCGI_EV_FCONN_RECV|FCGI_EV_RX_RECORD)))) + chunk_appendf(&trace_buf, " dbuf=%u@%p+%u/%u", + (unsigned int)b_data(&fconn->dbuf), b_orig(&fconn->dbuf), + (unsigned int)b_head_ofs(&fconn->dbuf), (unsigned int)b_size(&fconn->dbuf)); + if (src->verbosity == FCGI_VERB_COMPLETE || + (src->verbosity == FCGI_VERB_ADVANCED && (mask & (FCGI_EV_FCONN_SEND|FCGI_EV_TX_RECORD)))) { + struct buffer *hmbuf = br_head((struct buffer *)fconn->mbuf); + struct buffer *tmbuf = br_tail((struct buffer *)fconn->mbuf); + + chunk_appendf(&trace_buf, " .mbuf=[%u..%u|%u],h=[%u@%p+%u/%u],t=[%u@%p+%u/%u]", + br_head_idx(fconn->mbuf), br_tail_idx(fconn->mbuf), br_size(fconn->mbuf), + (unsigned int)b_data(hmbuf), b_orig(hmbuf), + (unsigned int)b_head_ofs(hmbuf), (unsigned int)b_size(hmbuf), + (unsigned int)b_data(tmbuf), b_orig(tmbuf), + (unsigned int)b_head_ofs(tmbuf), (unsigned int)b_size(tmbuf)); + } + + if (fstrm && (src->verbosity == FCGI_VERB_COMPLETE || + (src->verbosity == FCGI_VERB_ADVANCED && (mask & (FCGI_EV_STRM_RECV|FCGI_EV_RSP_DATA))))) + chunk_appendf(&trace_buf, " rxbuf=%u@%p+%u/%u", + (unsigned int)b_data(&fstrm->rxbuf), b_orig(&fstrm->rxbuf), + (unsigned int)b_head_ofs(&fstrm->rxbuf), (unsigned int)b_size(&fstrm->rxbuf)); + } + + /* Display htx info if defined (level > USER) */ + if (src->level > TRACE_LEVEL_USER && htx) { + int full = 0; + + /* Full htx info (level > STATE && verbosity > SIMPLE) */ + if (src->level > TRACE_LEVEL_STATE) { + if (src->verbosity == FCGI_VERB_COMPLETE) + full = 1; + else if (src->verbosity == FCGI_VERB_ADVANCED && (mask & (FCGI_EV_RSP_HDRS|FCGI_EV_TX_PARAMS))) + full = 1; + } + + chunk_memcat(&trace_buf, "\n\t", 2); + htx_dump(&trace_buf, htx, full); + } +} /*****************************************************/ /* functions below are for dynamic buffer management */ @@ -302,14 +570,15 @@ static int fcgi_buf_available(void *target) struct fcgi_strm *fstrm; if ((fconn->flags & FCGI_CF_DEM_DALLOC) && b_alloc_margin(&fconn->dbuf, 0)) { + TRACE_STATE("unblocking fconn, dbuf allocated", FCGI_EV_FCONN_RECV|FCGI_EV_FCONN_BLK|FCGI_EV_FCONN_WAKE, fconn->conn); fconn->flags &= ~FCGI_CF_DEM_DALLOC; fcgi_conn_restart_reading(fconn, 1); return 1; } if ((fconn->flags & FCGI_CF_MUX_MALLOC) && b_alloc_margin(br_tail(fconn->mbuf), 0)) { + TRACE_STATE("unblocking fconn, mbuf allocated", FCGI_EV_FCONN_SEND|FCGI_EV_FCONN_BLK|FCGI_EV_FCONN_WAKE, fconn->conn); fconn->flags &= ~FCGI_CF_MUX_MALLOC; - if (fconn->flags & FCGI_CF_DEM_MROOM) { fconn->flags &= ~FCGI_CF_DEM_MROOM; fcgi_conn_restart_reading(fconn, 1); @@ -320,8 +589,10 @@ static int fcgi_buf_available(void *target) if ((fconn->flags & FCGI_CF_DEM_SALLOC) && (fstrm = fcgi_conn_st_by_id(fconn, fconn->dsi)) && fstrm->cs && b_alloc_margin(&fstrm->rxbuf, 0)) { + TRACE_STATE("unblocking fstrm, rxbuf allocated", FCGI_EV_STRM_RECV|FCGI_EV_FSTRM_BLK|FCGI_EV_STRM_WAKE, fconn->conn, fstrm); fconn->flags &= ~FCGI_CF_DEM_SALLOC; fcgi_conn_restart_reading(fconn, 1); + fcgi_strm_notify_recv(fstrm); return 1; } @@ -429,6 +700,9 @@ static int fcgi_init(struct connection *conn, struct proxy *px, struct session * struct fcgi_strm *fstrm; struct fcgi_app *app = get_px_fcgi_app(px); struct task *t = NULL; + void *conn_ctx = conn->ctx; + + TRACE_ENTER(FCGI_EV_FSTRM_NEW); if (!app) goto fail_conn; @@ -491,22 +765,24 @@ static int fcgi_init(struct connection *conn, struct proxy *px, struct session * LIST_INIT(&fconn->sending_list); LIST_INIT(&fconn->buf_wait.list); + conn->ctx = fconn; + if (t) task_queue(t); /* FIXME: this is temporary, for outgoing connections we need to * immediately allocate a stream until the code is modified so that the * caller calls ->attach(). For now the outgoing cs is stored as - * conn->ctx by the caller. + * conn->ctx by the caller and saved in conn_ctx. */ - fstrm = fcgi_conn_stream_new(fconn, conn->ctx, sess); + fstrm = fcgi_conn_stream_new(fconn, conn_ctx, sess); if (!fstrm) goto fail; - conn->ctx = fconn; /* Repare to read something */ fcgi_conn_restart_reading(fconn, 1); + TRACE_LEAVE(FCGI_EV_FCONN_NEW, conn); return 0; fail: @@ -515,6 +791,8 @@ static int fcgi_init(struct connection *conn, struct proxy *px, struct session * tasklet_free(fconn->wait_event.tasklet); pool_free(pool_head_fcgi_conn, fconn); fail_conn: + conn->ctx = conn_ctx; // restore saved ctx + TRACE_DEVEL("leaving in error", FCGI_EV_FCONN_NEW|FCGI_EV_FCONN_END|FCGI_EV_FCONN_ERR); return -1; } @@ -555,11 +833,15 @@ static void fcgi_release(struct fcgi_conn *fconn) { struct connection *conn = NULL;; + TRACE_POINT(FCGI_EV_FCONN_END); + if (fconn) { /* The connection must be attached to this mux to be released */ if (fconn->conn && fconn->conn->ctx == fconn) conn = fconn->conn; + TRACE_DEVEL("freeing fconn", FCGI_EV_FCONN_END, conn); + if (LIST_ADDED(&fconn->buf_wait.list)) { HA_SPIN_LOCK(BUF_WQ_LOCK, &buffer_wq_lock); LIST_DEL(&fconn->buf_wait.list); @@ -584,6 +866,7 @@ static void fcgi_release(struct fcgi_conn *fconn) if (conn) { conn->mux = NULL; conn->ctx = NULL; + TRACE_DEVEL("freeing conn", FCGI_EV_FCONN_END, conn); conn_stop_tracking(conn); conn_full_close(conn); @@ -617,8 +900,11 @@ static inline int fcgi_conn_is_dead(struct fcgi_conn *fconn) static inline void fcgi_strm_error(struct fcgi_strm *fstrm) { if (fstrm->id && fstrm->state != FCGI_SS_ERROR) { - if (fstrm->state < FCGI_SS_ERROR) + TRACE_POINT(FCGI_EV_FSTRM_ERR, fstrm->fconn->conn, fstrm); + if (fstrm->state < FCGI_SS_ERROR) { fstrm->state = FCGI_SS_ERROR; + TRACE_STATE("switching to ERROR", FCGI_EV_FSTRM_ERR, fstrm->fconn->conn, fstrm); + } if (fstrm->cs) cs_set_error(fstrm->cs); } @@ -630,6 +916,7 @@ static void fcgi_strm_notify_recv(struct fcgi_strm *fstrm) struct wait_event *sw; if (fstrm->recv_wait) { + TRACE_POINT(FCGI_EV_STRM_WAKE, fstrm->fconn->conn, fstrm); sw = fstrm->recv_wait; sw->events &= ~SUB_RETRY_RECV; tasklet_wakeup(sw->tasklet); @@ -643,6 +930,7 @@ static void fcgi_strm_notify_send(struct fcgi_strm *fstrm) struct wait_event *sw; if (fstrm->send_wait && !LIST_ADDED(&fstrm->sending_list)) { + TRACE_POINT(FCGI_EV_STRM_WAKE, fstrm->fconn->conn, fstrm); sw = fstrm->send_wait; sw->events &= ~SUB_RETRY_SEND; LIST_ADDQ(&fstrm->fconn->sending_list, &fstrm->sending_list); @@ -661,12 +949,15 @@ static void fcgi_strm_notify_send(struct fcgi_strm *fstrm) */ static void fcgi_strm_alert(struct fcgi_strm *fstrm) { + TRACE_POINT(FCGI_EV_STRM_WAKE, fstrm->fconn->conn, fstrm); if (fstrm->recv_wait || fstrm->send_wait) { fcgi_strm_notify_recv(fstrm); fcgi_strm_notify_send(fstrm); } - else if (fstrm->cs && fstrm->cs->data_cb->wake != NULL) + else if (fstrm->cs && fstrm->cs->data_cb->wake != NULL) { + TRACE_POINT(FCGI_EV_STRM_WAKE, fstrm->fconn->conn, fstrm); fstrm->cs->data_cb->wake(fstrm->cs); + } } /* Writes the 16-bit record size at address */ @@ -694,6 +985,7 @@ static inline void fcgi_set_record_id(void *record, uint16_t id) static inline void fcgi_strm_close(struct fcgi_strm *fstrm) { if (fstrm->state != FCGI_SS_CLOSED) { + TRACE_ENTER(FCGI_EV_FSTRM_END, fstrm->fconn->conn, fstrm); fstrm->fconn->nb_streams--; if (!fstrm->id) fstrm->fconn->nb_reserved--; @@ -701,8 +993,10 @@ static inline void fcgi_strm_close(struct fcgi_strm *fstrm) if (!(fstrm->cs->flags & CS_FL_EOS) && !b_data(&fstrm->rxbuf)) fcgi_strm_notify_recv(fstrm); } + fstrm->state = FCGI_SS_CLOSED; + TRACE_STATE("switching to CLOSED", FCGI_EV_FSTRM_END, fstrm->fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_FSTRM_END, fstrm->fconn->conn, fstrm); } - fstrm->state = FCGI_SS_CLOSED; } /* Detaches a FCGI stream from its FCGI connection and releases it to the @@ -710,6 +1004,10 @@ static inline void fcgi_strm_close(struct fcgi_strm *fstrm) */ static void fcgi_strm_destroy(struct fcgi_strm *fstrm) { + struct connection *conn = fstrm->fconn->conn; + + TRACE_ENTER(FCGI_EV_FSTRM_END, conn, fstrm); + fcgi_strm_close(fstrm); eb32_delete(&fstrm->by_id); if (b_size(&fstrm->rxbuf)) { @@ -731,6 +1029,8 @@ static void fcgi_strm_destroy(struct fcgi_strm *fstrm) } tasklet_free(fstrm->wait_event.tasklet); pool_free(pool_head_fcgi_strm, fstrm); + + TRACE_LEAVE(FCGI_EV_FSTRM_END, conn); } /* Allocates a new stream for connection and adds it into fconn's @@ -743,6 +1043,8 @@ static struct fcgi_strm *fcgi_strm_new(struct fcgi_conn *fconn, int id) { struct fcgi_strm *fstrm; + TRACE_ENTER(FCGI_EV_FSTRM_NEW, fconn->conn); + fstrm = pool_alloc(pool_head_fcgi_strm); if (!fstrm) goto out; @@ -780,9 +1082,11 @@ static struct fcgi_strm *fcgi_strm_new(struct fcgi_conn *fconn, int id) fconn->nb_streams++; fconn->stream_cnt++; + TRACE_LEAVE(FCGI_EV_FSTRM_NEW, fconn->conn, fstrm); return fstrm; out: + TRACE_DEVEL("leaving in error", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR|FCGI_EV_FSTRM_END, fconn->conn); return NULL; } @@ -795,24 +1099,34 @@ static struct fcgi_strm *fcgi_conn_stream_new(struct fcgi_conn *fconn, struct co { struct fcgi_strm *fstrm = NULL; - if (fconn->nb_streams >= fconn->streams_limit) + TRACE_ENTER(FCGI_EV_FSTRM_NEW, fconn->conn); + if (fconn->nb_streams >= fconn->streams_limit) { + TRACE_DEVEL("leaving on streams_limit reached", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn); goto out; + } - if (fcgi_streams_left(fconn) < 1) + if (fcgi_streams_left(fconn) < 1) { + TRACE_DEVEL("leaving on !streams_left", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn); goto out; + } /* Defer choosing the ID until we send the first message to create the stream */ fstrm = fcgi_strm_new(fconn, 0); - if (!fstrm) + if (!fstrm) { + TRACE_DEVEL("leaving on fstrm creation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn); goto out; + } fstrm->cs = cs; fstrm->sess = sess; cs->ctx = fstrm; fconn->nb_cs++; - out: + TRACE_LEAVE(FCGI_EV_FSTRM_NEW, fconn->conn, fstrm); return fstrm; + + out: + return NULL; } /* Wakes a specific stream and assign its conn_stream some CS_FL_* flags among @@ -822,28 +1136,40 @@ static struct fcgi_strm *fcgi_conn_stream_new(struct fcgi_conn *fconn, struct co */ static void fcgi_strm_wake_one_stream(struct fcgi_strm *fstrm) { + struct fcgi_conn *fconn = fstrm->fconn; + + TRACE_ENTER(FCGI_EV_STRM_WAKE, fconn->conn, fstrm); + if (!fstrm->cs) { /* this stream was already orphaned */ fcgi_strm_destroy(fstrm); + TRACE_DEVEL("leaving with no fstrm", FCGI_EV_STRM_WAKE, fconn->conn); return; } - if (conn_xprt_read0_pending(fstrm->fconn->conn)) { - if (fstrm->state == FCGI_SS_OPEN) + if (conn_xprt_read0_pending(fconn->conn)) { + if (fstrm->state == FCGI_SS_OPEN) { fstrm->state = FCGI_SS_HREM; + TRACE_STATE("swtiching to HREM", FCGI_EV_STRM_WAKE|FCGI_EV_FSTRM_END, fconn->conn, fstrm); + } else if (fstrm->state == FCGI_SS_HLOC) fcgi_strm_close(fstrm); } - if ((fstrm->fconn->state == FCGI_CS_CLOSED || fstrm->fconn->conn->flags & CO_FL_ERROR)) { + if ((fconn->state == FCGI_CS_CLOSED || fconn->conn->flags & CO_FL_ERROR)) { fstrm->cs->flags |= CS_FL_ERR_PENDING; if (fstrm->cs->flags & CS_FL_EOS) fstrm->cs->flags |= CS_FL_ERROR; - if (fstrm->state < FCGI_SS_ERROR) + + if (fstrm->state < FCGI_SS_ERROR) { fstrm->state = FCGI_SS_ERROR; + TRACE_STATE("switching to ERROR", FCGI_EV_STRM_WAKE|FCGI_EV_FSTRM_END, fconn->conn, fstrm); + } } fcgi_strm_alert(fstrm); + + TRACE_LEAVE(FCGI_EV_STRM_WAKE, fconn->conn, fstrm); } /* Wakes unassigned streams (ID == 0) attached to the connection. */ @@ -870,6 +1196,8 @@ static void fcgi_wake_some_streams(struct fcgi_conn *fconn, int last) struct eb32_node *node; struct fcgi_strm *fstrm; + TRACE_ENTER(FCGI_EV_STRM_WAKE, fconn->conn); + /* Wake all streams with ID > last */ node = eb32_lookup_ge(&fconn->streams_by_id, last + 1); while (node) { @@ -878,6 +1206,8 @@ static void fcgi_wake_some_streams(struct fcgi_conn *fconn, int last) fcgi_strm_wake_one_stream(fstrm); } fcgi_wake_unassigned_streams(fconn); + + TRACE_LEAVE(FCGI_EV_STRM_WAKE, fconn->conn); } static int fcgi_set_default_param(struct fcgi_conn *fconn, struct fcgi_strm *fstrm, @@ -1170,14 +1500,18 @@ static int fcgi_conn_send_get_values(struct fcgi_conn *fconn) struct buffer *mbuf; struct fcgi_param max_reqs = { .n = ist("FCGI_MAX_REQS"), .v = ist("")}; struct fcgi_param mpxs_conns = { .n = ist("FCGI_MPXS_CONNS"), .v = ist("")}; - int ret; + int ret = 0; + + TRACE_ENTER(FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL, fconn->conn); mbuf = br_tail(fconn->mbuf); retry: if (!fcgi_get_buf(fconn, mbuf)) { fconn->flags |= FCGI_CF_MUX_MALLOC; fconn->flags |= FCGI_CF_DEM_MROOM; - return 0; + TRACE_STATE("waiting for fconn mbuf ring allocation", FCGI_EV_TX_RECORD|FCGI_EV_FCONN_BLK, fconn->conn); + ret = 0; + goto end; } while (1) { @@ -1203,11 +1537,13 @@ static int fcgi_conn_send_get_values(struct fcgi_conn *fconn) goto full; /* update the record's size now */ + TRACE_PROTO("FCGI GET_VALUES record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL, fconn->conn,,, (size_t[]){outbuf.data-8}); fcgi_set_record_size(outbuf.area, outbuf.data - 8); b_add(mbuf, outbuf.data); ret = 1; end: + TRACE_LEAVE(FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL, fconn->conn); return ret; full: /* Too large to be encoded. For GET_VALUES records, it is an error */ @@ -1218,12 +1554,14 @@ static int fcgi_conn_send_get_values(struct fcgi_conn *fconn) goto retry; fconn->flags |= FCGI_CF_MUX_MFULL; fconn->flags |= FCGI_CF_DEM_MROOM; + TRACE_STATE("mbuf ring full", FCGI_EV_TX_RECORD|FCGI_EV_FCONN_BLK, fconn->conn); ret = 0; goto end; fail: fconn->state = FCGI_CS_CLOSED; - ret = 0; - goto end; + TRACE_STATE("switching to CLOSED", FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL|FCGI_EV_FCONN_END, fconn->conn); + TRACE_DEVEL("leaving on error", FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn); + return 0; } /* Processes a GET_VALUES_RESULT record. Returns > 0 on success, 0 if it @@ -1237,6 +1575,8 @@ static int fcgi_conn_handle_values_result(struct fcgi_conn *fconn) struct buffer *dbuf; size_t offset; + TRACE_ENTER(FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); + dbuf = &fconn->dbuf; /* Record too large to be fully decoded */ @@ -1244,8 +1584,10 @@ static int fcgi_conn_handle_values_result(struct fcgi_conn *fconn) goto fail; /* process full record only */ - if (b_data(dbuf) < (fconn->drl + fconn->drp)) + if (b_data(dbuf) < (fconn->drl + fconn->drp)) { + TRACE_DEVEL("leaving on missing data", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); return 0; + } if (unlikely(b_contig_data(dbuf, b_head_ofs(dbuf)) < fconn->drl)) { /* Realign the dmux buffer if the record wraps. It is unexpected @@ -1269,13 +1611,18 @@ static int fcgi_conn_handle_values_result(struct fcgi_conn *fconn) offset += ret; if (isteqi(p.n, ist("FCGI_MPXS_CONNS"))) { - if (isteq(p.v, ist("1"))) + if (isteq(p.v, ist("1"))) { + TRACE_STATE("set mpxs param", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn,, (size_t[]){1}); fconn->flags |= FCGI_CF_MPXS_CONNS; - else + } + else { + TRACE_STATE("set mpxs param", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn,, (size_t[]){0}); fconn->flags &= ~FCGI_CF_MPXS_CONNS; + } } else if (isteqi(p.n, ist("FCGI_MAX_REQS"))) { fconn->streams_limit = strl2ui(p.v.ptr, p.v.len); + TRACE_STATE("set streams_limit", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn,, (size_t[]){fconn->streams_limit}); } /* * Ignore all other params @@ -1285,8 +1632,10 @@ static int fcgi_conn_handle_values_result(struct fcgi_conn *fconn) /* Reset the number of concurrent streams supported if the FCGI * application does not support connection multiplexing */ - if (!(fconn->flags & FCGI_CF_MPXS_CONNS)) + if (!(fconn->flags & FCGI_CF_MPXS_CONNS)) { fconn->streams_limit = 1; + TRACE_STATE("no mpxs for streams_limit to 1", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); + } /* We must be sure to have read exactly the announced record length, no * more no less @@ -1294,14 +1643,19 @@ static int fcgi_conn_handle_values_result(struct fcgi_conn *fconn) if (offset != fconn->drl) goto fail; + TRACE_PROTO("FCGI GET_VALUES_RESULT record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn,,, (size_t[]){fconn->drl}); b_del(&fconn->dbuf, fconn->drl + fconn->drp); fconn->drl = 0; fconn->drp = 0; fconn->state = FCGI_CS_RECORD_H; fcgi_wake_unassigned_streams(fconn); + TRACE_STATE("switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); + TRACE_LEAVE(FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); return 1; fail: fconn->state = FCGI_CS_CLOSED; + TRACE_STATE("switching to CLOSED", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); + TRACE_DEVEL("leaving on error", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn); return 0; } @@ -1314,6 +1668,8 @@ static int fcgi_conn_send_aborts(struct fcgi_conn *fconn) struct eb32_node *node; struct fcgi_strm *fstrm; + TRACE_ENTER(FCGI_EV_TX_RECORD, fconn->conn); + node = eb32_lookup_ge(&fconn->streams_by_id, 1); while (node) { fstrm = container_of(node, struct fcgi_strm, by_id); @@ -1324,6 +1680,8 @@ static int fcgi_conn_send_aborts(struct fcgi_conn *fconn) return 0; } fconn->flags |= FCGI_CF_ABRTS_SENT; + TRACE_STATE("aborts sent to all fstrms", FCGI_EV_TX_RECORD, fconn->conn); + TRACE_LEAVE(FCGI_EV_TX_RECORD, fconn->conn); return 1; } @@ -1338,12 +1696,16 @@ static int fcgi_strm_send_begin_request(struct fcgi_conn *fconn, struct fcgi_str struct fcgi_begin_request rec = { .role = FCGI_RESPONDER, .flags = 0}; int ret; + TRACE_ENTER(FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm); + mbuf = br_tail(fconn->mbuf); retry: if (!fcgi_get_buf(fconn, mbuf)) { fconn->flags |= FCGI_CF_MUX_MALLOC; - fconn->flags |= FCGI_CF_DEM_MROOM; - return 0; + fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("waiting for fconn mbuf ring allocation", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); + ret = 0; + goto end; } while (1) { @@ -1363,25 +1725,30 @@ static int fcgi_strm_send_begin_request(struct fcgi_conn *fconn, struct fcgi_str fcgi_set_record_id(outbuf.area, fstrm->id); outbuf.data = 8; - if (fconn->flags & FCGI_CF_KEEP_CONN) + if (fconn->flags & FCGI_CF_KEEP_CONN) { + TRACE_STATE("keep connection opened", FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm); rec.flags |= FCGI_KEEP_CONN; + } if (!fcgi_encode_begin_request(&outbuf, &rec)) goto full; /* commit the record */ + TRACE_PROTO("FCGI BEGIN_REQUEST record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm,, (size_t[]){0}); b_add(mbuf, outbuf.data); fstrm->flags |= FCGI_SF_BEGIN_SENT; fstrm->state = FCGI_SS_OPEN; - + TRACE_STATE("switching to OPEN", FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm); ret = 1; end: + TRACE_LEAVE(FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm); return ret; full: if ((mbuf = br_tail_add(fconn->mbuf)) != NULL) goto retry; fconn->flags |= FCGI_CF_MUX_MFULL; fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("mbuf ring full", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn); ret = 0; goto end; } @@ -1397,12 +1764,15 @@ static int fcgi_strm_send_empty_record(struct fcgi_conn *fconn, struct fcgi_strm struct buffer *mbuf; int ret; + TRACE_ENTER(FCGI_EV_TX_RECORD, fconn->conn, fstrm); mbuf = br_tail(fconn->mbuf); retry: if (!fcgi_get_buf(fconn, mbuf)) { fconn->flags |= FCGI_CF_MUX_MALLOC; - fconn->flags |= FCGI_CF_DEM_MROOM; - return 0; + fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("waiting for fconn mbuf ring allocation", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); + ret = 0; + goto end; } while (1) { @@ -1428,12 +1798,14 @@ static int fcgi_strm_send_empty_record(struct fcgi_conn *fconn, struct fcgi_strm ret = 1; end: + TRACE_LEAVE(FCGI_EV_TX_RECORD, fconn->conn, fstrm); return ret; full: if ((mbuf = br_tail_add(fconn->mbuf)) != NULL) goto retry; fconn->flags |= FCGI_CF_MUX_MFULL; fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("mbuf ring full", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); ret = 0; goto end; } @@ -1444,7 +1816,13 @@ static int fcgi_strm_send_empty_record(struct fcgi_conn *fconn, struct fcgi_strm */ static int fcgi_strm_send_empty_params(struct fcgi_conn *fconn, struct fcgi_strm *fstrm) { - return fcgi_strm_send_empty_record(fconn, fstrm, FCGI_PARAMS); + int ret; + + TRACE_POINT(FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm); + ret = fcgi_strm_send_empty_record(fconn, fstrm, FCGI_PARAMS); + if (ret) + TRACE_PROTO("FCGI PARAMS record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm,, (size_t[]){0}); + return ret; } /* Sends an empty STDIN record. It relies on fcgi_strm_send_empty_record(). It @@ -1454,9 +1832,14 @@ static int fcgi_strm_send_empty_stdin(struct fcgi_conn *fconn, struct fcgi_strm { int ret; + TRACE_POINT(FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN|FCGI_EV_TX_EOI, fconn->conn, fstrm); ret = fcgi_strm_send_empty_record(fconn, fstrm, FCGI_STDIN); - if (ret) + if (ret) { fstrm->flags |= FCGI_SF_ES_SENT; + TRACE_PROTO("FCGI STDIN record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm,, (size_t[]){0}); + TRACE_USER("FCGI request fully xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN|FCGI_EV_TX_EOI, fconn->conn, fstrm); + TRACE_STATE("stdin data fully sent", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN|FCGI_EV_TX_EOI, fconn->conn, fstrm); + } return ret; } @@ -1467,9 +1850,14 @@ static int fcgi_strm_send_abort(struct fcgi_conn *fconn, struct fcgi_strm *fstrm { int ret; + TRACE_POINT(FCGI_EV_TX_RECORD|FCGI_EV_TX_ABORT, fconn->conn, fstrm); ret = fcgi_strm_send_empty_record(fconn, fstrm, FCGI_ABORT_REQUEST); - if (ret) + if (ret) { fstrm->flags |= FCGI_SF_ABRT_SENT; + TRACE_PROTO("FCGI ABORT record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_ABORT, fconn->conn, fstrm,, (size_t[]){0}); + TRACE_USER("FCGI request aborted", FCGI_EV_TX_RECORD|FCGI_EV_TX_ABORT, fconn->conn, fstrm); + TRACE_STATE("abort sent", FCGI_EV_TX_RECORD|FCGI_EV_TX_ABORT, fconn->conn, fstrm); + } return ret; } @@ -1488,6 +1876,8 @@ static size_t fcgi_strm_send_params(struct fcgi_conn *fconn, struct fcgi_strm *f struct fcgi_strm_params params; size_t total = 0; + TRACE_ENTER(FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm, htx); + memset(¶ms, 0, sizeof(params)); params.p = get_trash_chunk(); @@ -1495,8 +1885,9 @@ static size_t fcgi_strm_send_params(struct fcgi_conn *fconn, struct fcgi_strm *f retry: if (!fcgi_get_buf(fconn, mbuf)) { fconn->flags |= FCGI_CF_MUX_MALLOC; - fconn->flags |= FCGI_CF_DEM_MROOM; - return 0; + fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("waiting for fconn mbuf ring allocation", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); + goto end; } while (1) { @@ -1625,6 +2016,7 @@ static size_t fcgi_strm_send_params(struct fcgi_conn *fconn, struct fcgi_strm *f if (outbuf.data == 8) goto full; } + TRACE_STATE("add server name header", FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm); } goto done; @@ -1658,22 +2050,26 @@ static size_t fcgi_strm_send_params(struct fcgi_conn *fconn, struct fcgi_strm *f goto error; /* update the record's size */ + TRACE_PROTO("FCGI PARAMS record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm,, (size_t[]){outbuf.data - 8}); fcgi_set_record_size(outbuf.area, outbuf.data - 8); b_add(mbuf, outbuf.data); end: + TRACE_LEAVE(FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm, htx, (size_t[]){total}); return total; full: if ((mbuf = br_tail_add(fconn->mbuf)) != NULL) goto retry; fconn->flags |= FCGI_CF_MUX_MFULL; fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("mbuf ring full", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); if (total) goto error; goto end; error: htx->flags |= HTX_FL_PROCESSING_ERROR; + TRACE_PROTO("processing error", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm); fcgi_strm_error(fstrm); goto end; } @@ -1691,6 +2087,7 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs uint32_t size; size_t total = 0; + TRACE_ENTER(FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx, (size_t[]){count}); if (!count) goto end; @@ -1698,8 +2095,9 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs retry: if (!fcgi_get_buf(fconn, mbuf)) { fconn->flags |= FCGI_CF_MUX_MALLOC; - fconn->flags |= FCGI_CF_DEM_MROOM; - return 0; + fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("waiting for fconn mbuf ring allocation", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); + goto end; } /* Perform some optimizations to reduce the number of buffer copies. @@ -1737,15 +2135,10 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs (b_data(mbuf) <= b_size(mbuf) / 4 || (size <= b_size(mbuf) / 4 && size + 8 <= b_contig_space(mbuf)))) goto copy; - - if ((mbuf = br_tail_add(fconn->mbuf)) != NULL) - goto retry; - - fconn->flags |= FCGI_CF_MUX_MFULL; - fstrm->flags |= FCGI_SF_BLK_MROOM; - goto end; + goto full; } + TRACE_PROTO("sending stding data (zero-copy)", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx, (size_t[]){size}); /* map a FCGI record to the HTX block so that we can put the * record header there. */ @@ -1761,6 +2154,9 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs buf->area = old_area; buf->data = buf->head = 0; total += size; + + htx = (struct htx *)buf->area; + htx_reset(htx); goto end; } @@ -1790,6 +2186,7 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs switch (type) { case HTX_BLK_DATA: + TRACE_PROTO("sending stding data", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx, (size_t[]){size}); v = htx_get_blk_value(htx, blk); if (v.len > count) v.len = count; @@ -1831,16 +2228,19 @@ static size_t fcgi_strm_send_stdin(struct fcgi_conn *fconn, struct fcgi_strm *fs done: /* update the record's size */ + TRACE_PROTO("FCGI STDIN record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm,, (size_t[]){outbuf.data - 8}); fcgi_set_record_size(outbuf.area, outbuf.data - 8); b_add(mbuf, outbuf.data); end: + TRACE_LEAVE(FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx, (size_t[]){total}); return total; full: if ((mbuf = br_tail_add(fconn->mbuf)) != NULL) goto retry; fconn->flags |= FCGI_CF_MUX_MFULL; fstrm->flags |= FCGI_SF_BLK_MROOM; + TRACE_STATE("mbuf ring full", FCGI_EV_TX_RECORD|FCGI_EV_FSTRM_BLK|FCGI_EV_FCONN_BLK, fconn->conn, fstrm); goto end; } @@ -1854,6 +2254,8 @@ static int fcgi_strm_handle_stdout(struct fcgi_conn *fconn, struct fcgi_strm *fs size_t ret; size_t max; + TRACE_ENTER(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); + dbuf = &fconn->dbuf; /* Only padding remains */ @@ -1867,7 +2269,8 @@ static int fcgi_strm_handle_stdout(struct fcgi_conn *fconn, struct fcgi_strm *fs if (!fcgi_get_buf(fconn, &fstrm->rxbuf)) { fconn->flags |= FCGI_CF_DEM_SALLOC; - return 0; + TRACE_STATE("waiting for fstrm rxbuf allocation", FCGI_EV_RX_RECORD|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); + goto fail; } /*max = MIN(b_room(&fstrm->rxbuf), fconn->drl);*/ @@ -1881,9 +2284,13 @@ static int fcgi_strm_handle_stdout(struct fcgi_conn *fconn, struct fcgi_strm *fs if (!ret) goto fail; fconn->drl -= ret; + TRACE_DATA("move some data to fstrm rxbuf", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm,, (size_t[]){ret}); + TRACE_PROTO("FCGI STDOUT record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm,, (size_t[]){ret}); - if (!buf_room_for_htx_data(&fstrm->rxbuf)) + if (!buf_room_for_htx_data(&fstrm->rxbuf)) { fconn->flags |= FCGI_CF_DEM_SFULL; + TRACE_STATE("fstrm rxbuf full", FCGI_EV_RX_RECORD|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); + } if (fconn->drl) goto fail; @@ -1898,8 +2305,11 @@ static int fcgi_strm_handle_stdout(struct fcgi_conn *fconn, struct fcgi_strm *fs goto fail; fconn->state = FCGI_CS_RECORD_H; + TRACE_STATE("switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); return 1; fail: + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); return 0; } @@ -1912,16 +2322,24 @@ static int fcgi_strm_handle_empty_stdout(struct fcgi_conn *fconn, struct fcgi_st { int ret; + TRACE_ENTER(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); + fconn->state = FCGI_CS_RECORD_P; + TRACE_STATE("switching to RECORD_P", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); fconn->drl += fconn->drp; fconn->drp = 0; ret = MIN(b_data(&fconn->dbuf), fconn->drl); b_del(&fconn->dbuf, ret); fconn->drl -= ret; - if (fconn->drl) + if (fconn->drl) { + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); return 0; + } fconn->state = FCGI_CS_RECORD_H; fstrm->state |= FCGI_SF_ES_RCVD; + TRACE_PROTO("FCGI STDOUT record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm,, (size_t[]){0}); + TRACE_STATE("stdout data fully send, switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR|FCGI_EV_RX_EOI, fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); return 1; } @@ -1934,6 +2352,7 @@ static int fcgi_strm_handle_stderr(struct fcgi_conn *fconn, struct fcgi_strm *fs struct buffer tag; size_t ret; + TRACE_ENTER(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDERR, fconn->conn, fstrm); dbuf = &fconn->dbuf; /* Only padding remains */ @@ -1950,6 +2369,7 @@ static int fcgi_strm_handle_stderr(struct fcgi_conn *fconn, struct fcgi_strm *fs if (!ret) goto fail; fconn->drl -= ret; + TRACE_PROTO("FCGI STDERR record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDERR, fconn->conn, fstrm, (size_t[]){ret}); trash.area[ret] = '\n'; trash.area[ret+1] = '\0'; @@ -1968,8 +2388,11 @@ static int fcgi_strm_handle_stderr(struct fcgi_conn *fconn, struct fcgi_strm *fs if (fconn->drl) goto fail; fconn->state = FCGI_CS_RECORD_H; + TRACE_STATE("switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_RX_RECORD|FCGI_EV_RX_STDERR, fconn->conn, fstrm); return 1; fail: + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDERR, fconn->conn, fstrm); return 0; } @@ -1985,6 +2408,7 @@ static int fcgi_strm_handle_end_request(struct fcgi_conn *fconn, struct fcgi_str struct buffer *dbuf; struct fcgi_end_request endreq; + TRACE_ENTER(FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ, fconn->conn, fstrm); dbuf = &fconn->dbuf; /* Record too large to be fully decoded */ @@ -1992,8 +2416,10 @@ static int fcgi_strm_handle_end_request(struct fcgi_conn *fconn, struct fcgi_str goto fail; /* process full record only */ - if (b_data(dbuf) < (fconn->drl + fconn->drp)) + if (b_data(dbuf) < (fconn->drl + fconn->drp)) { + TRACE_DEVEL("leaving on missing data", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ, fconn->conn); return 0; + } if (unlikely(b_contig_data(dbuf, b_head_ofs(dbuf)) < fconn->drl)) { /* Realign the dmux buffer if the record wraps. It is unexpected @@ -2009,6 +2435,8 @@ static int fcgi_strm_handle_end_request(struct fcgi_conn *fconn, struct fcgi_str goto fail; fstrm->flags |= FCGI_SF_ES_RCVD; + TRACE_STATE("end of script reported", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ|FCGI_EV_RX_EOI, fconn->conn, fstrm); + TRACE_PROTO("FCGI END_REQUEST record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ, fconn->conn, fstrm,, (size_t[]){fconn->drl}); fstrm->proto_status = endreq.errcode; fcgi_strm_close(fstrm); @@ -2016,10 +2444,13 @@ static int fcgi_strm_handle_end_request(struct fcgi_conn *fconn, struct fcgi_str fconn->drl = 0; fconn->drp = 0; fconn->state = FCGI_CS_RECORD_H; + TRACE_STATE("switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ, fconn->conn, fstrm); return 1; fail: fcgi_strm_error(fstrm); + TRACE_DEVEL("leaving on error", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ|FCGI_EV_FSTRM_ERR, fconn->conn, fstrm); return 0; } @@ -2030,14 +2461,19 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) struct fcgi_header hdr; int ret; + TRACE_ENTER(FCGI_EV_FCONN_WAKE, fconn->conn); + if (fconn->state == FCGI_CS_CLOSED) return; if (unlikely(fconn->state < FCGI_CS_RECORD_H)) { - if (fconn->state == FCGI_CS_INIT) - return; + if (fconn->state == FCGI_CS_INIT) { + TRACE_STATE("waiting FCGI GET_VALUES to be sent", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR|FCGI_EV_RX_GETVAL, fconn->conn); + return; + } if (fconn->state == FCGI_CS_SETTINGS) { /* ensure that what is pending is a valid GET_VALUES_RESULT record. */ + TRACE_STATE("receiving FCGI record header", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); ret = fcgi_decode_record_hdr(&fconn->dbuf, 0, &hdr); if (!ret) goto fail; @@ -2045,19 +2481,28 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) if (hdr.id || (hdr.type != FCGI_GET_VALUES_RESULT && hdr.type != FCGI_UNKNOWN_TYPE)) { fconn->state = FCGI_CS_CLOSED; + TRACE_PROTO("unexpected record type or flags", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR|FCGI_EV_RX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn); + TRACE_STATE("switching to CLOSED", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR|FCGI_EV_RX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn); goto fail; } goto new_record; } } - /* process as many incoming frames as possible below */ - while (b_data(&fconn->dbuf)) { + /* process as many incoming records as possible below */ + while (1) { + if (!b_data(&fconn->dbuf)) { + TRACE_DEVEL("no more Rx data", FCGI_EV_RX_RECORD, fconn->conn); + break; + } - if (fconn->state == FCGI_CS_CLOSED) + if (fconn->state == FCGI_CS_CLOSED) { + TRACE_STATE("end of connection reported", FCGI_EV_RX_RECORD|FCGI_EV_RX_EOI, fconn->conn); break; + } if (fconn->state == FCGI_CS_RECORD_H) { + TRACE_PROTO("receiving FCGI record header", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); ret = fcgi_decode_record_hdr(&fconn->dbuf, 0, &hdr); if (!ret) break; @@ -2069,6 +2514,7 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) fconn->drl = hdr.len; fconn->drp = hdr.padding; fconn->state = FCGI_CS_RECORD_D; + TRACE_STATE("FCGI record header rcvd, switching to RECORD_D", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); } /* Only FCGI_CS_RECORD_D or FCGI_CS_RECORD_P */ @@ -2081,6 +2527,7 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) (fstrm->flags & FCGI_SF_ES_RCVD) || (fstrm->cs->flags & (CS_FL_ERROR|CS_FL_ERR_PENDING|CS_FL_EOS)))) { /* we may have to signal the upper layers */ + TRACE_DEVEL("notifying stream before switching SID", FCGI_EV_RX_RECORD|FCGI_EV_STRM_WAKE, fconn->conn, fstrm); fstrm->cs->flags |= CS_FL_RCV_MORE; fcgi_strm_notify_recv(fstrm); } @@ -2097,6 +2544,7 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) switch (fconn->drt) { case FCGI_GET_VALUES_RESULT: + TRACE_PROTO("receiving FCGI GET_VALUES_RESULT record", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); ret = fcgi_conn_handle_values_result(fconn); break; @@ -2104,6 +2552,7 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) if (fstrm->flags & FCGI_SF_ES_RCVD) goto ignore_record; + TRACE_PROTO("receiving FCGI STDOUT record", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDOUT, fconn->conn, fstrm); if (fconn->drl) ret = fcgi_strm_handle_stdout(fconn, fstrm); else @@ -2111,14 +2560,16 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) break; case FCGI_STDERR: + TRACE_PROTO("receiving FCGI STDERR record", FCGI_EV_RX_RECORD|FCGI_EV_RX_STDERR, fconn->conn, fstrm); ret = fcgi_strm_handle_stderr(fconn, fstrm); break; case FCGI_END_REQUEST: + TRACE_PROTO("receiving FCGI END_REQUEST record", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ, fconn->conn, fstrm); ret = fcgi_strm_handle_end_request(fconn, fstrm); break; - /* implement all extra frame types here */ + /* implement all extra record types here */ default: ignore_record: /* drop records that we ignore. They may be @@ -2129,17 +2580,23 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) fconn->drl += fconn->drp; fconn->drp = 0; ret = MIN(b_data(&fconn->dbuf), fconn->drl); + TRACE_PROTO("receiving FCGI ignored record", FCGI_EV_RX_RECORD, fconn->conn, fstrm,, (size_t[]){ret}); + TRACE_STATE("switching to RECORD_P", FCGI_EV_RX_RECORD, fconn->conn, fstrm); b_del(&fconn->dbuf, ret); fconn->drl -= ret; ret = (fconn->drl == 0); } /* error or missing data condition met above ? */ - if (ret <= 0) + if (ret <= 0) { + TRACE_DEVEL("insufficient data to proceed", FCGI_EV_RX_RECORD, fconn->conn, fstrm); break; + } - if (fconn->state != FCGI_CS_RECORD_H && !(fconn->drl+fconn->drp)) + if (fconn->state != FCGI_CS_RECORD_H && !(fconn->drl+fconn->drp)) { fconn->state = FCGI_CS_RECORD_H; + TRACE_STATE("switching to RECORD_H", FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); + } } fail: @@ -2151,6 +2608,7 @@ static void fcgi_process_demux(struct fcgi_conn *fconn) (fstrm->flags & FCGI_SF_ES_RCVD) || (fstrm->cs->flags & (CS_FL_ERROR|CS_FL_ERR_PENDING|CS_FL_EOS)))) { /* we may have to signal the upper layers */ + TRACE_DEVEL("notifying stream before switching SID", FCGI_EV_RX_RECORD|FCGI_EV_STRM_WAKE, fconn->conn, fstrm); fstrm->cs->flags |= CS_FL_RCV_MORE; fcgi_strm_notify_recv(fstrm); } @@ -2165,20 +2623,25 @@ static int fcgi_process_mux(struct fcgi_conn *fconn) { struct fcgi_strm *fstrm, *fstrm_back; + TRACE_ENTER(FCGI_EV_FCONN_WAKE, fconn->conn); + if (unlikely(fconn->state < FCGI_CS_RECORD_H)) { if (unlikely(fconn->state == FCGI_CS_INIT)) { if (!(fconn->flags & FCGI_CF_GET_VALUES)) { fconn->state = FCGI_CS_RECORD_H; + TRACE_STATE("switching to RECORD_H", FCGI_EV_TX_RECORD|FCGI_EV_RX_RECORD|FCGI_EV_RX_FHDR, fconn->conn); fcgi_wake_unassigned_streams(fconn); goto mux; } + TRACE_PROTO("sending FCGI GET_VALUES record", FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL, fconn->conn); if (unlikely(!fcgi_conn_send_get_values(fconn))) goto fail; fconn->state = FCGI_CS_SETTINGS; + TRACE_STATE("switching to SETTINGS", FCGI_EV_TX_RECORD|FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn); } /* need to wait for the other side */ if (fconn->state < FCGI_CS_RECORD_H) - return 1; + goto done; } mux: @@ -2196,6 +2659,7 @@ static int fcgi_process_mux(struct fcgi_conn *fconn) LIST_DEL_INIT(&fstrm->send_list); continue; } + TRACE_POINT(FCGI_EV_STRM_WAKE, fconn->conn, fstrm); fstrm->flags &= ~FCGI_SF_BLK_ANY; fstrm->send_wait->events &= ~SUB_RETRY_SEND; LIST_ADDQ(&fconn->sending_list, &fstrm->sending_list); @@ -2206,10 +2670,15 @@ static int fcgi_process_mux(struct fcgi_conn *fconn) if (fconn->state == FCGI_CS_CLOSED) { if (fconn->stream_cnt - fconn->nb_reserved > 0) { fcgi_conn_send_aborts(fconn); - if (fconn->flags & FCGI_CF_MUX_BLOCK_ANY) + if (fconn->flags & FCGI_CF_MUX_BLOCK_ANY) { + TRACE_DEVEL("leaving in blocked situation", FCGI_EV_FCONN_WAKE|FCGI_EV_FCONN_BLK, fconn->conn); return 0; + } } } + + done: + TRACE_LEAVE(FCGI_EV_FCONN_WAKE, fconn->conn); return 1; } @@ -2224,14 +2693,21 @@ static int fcgi_recv(struct fcgi_conn *fconn) int max; size_t ret; - if (fconn->wait_event.events & SUB_RETRY_RECV) + TRACE_ENTER(FCGI_EV_FCONN_RECV, conn); + + if (fconn->wait_event.events & SUB_RETRY_RECV) { + TRACE_DEVEL("leaving on sub_recv", FCGI_EV_FCONN_RECV, conn); return (b_data(&fconn->dbuf)); + } - if (!fcgi_recv_allowed(fconn)) + if (!fcgi_recv_allowed(fconn)) { + TRACE_DEVEL("leaving on !recv_allowed", FCGI_EV_FCONN_RECV, conn); return 1; + } buf = fcgi_get_buf(fconn, &fconn->dbuf); if (!buf) { + TRACE_DEVEL("waiting for fconn dbuf allocation", FCGI_EV_FCONN_RECV|FCGI_EV_FCONN_BLK, conn); fconn->flags |= FCGI_CF_DEM_DALLOC; return 0; } @@ -2240,7 +2716,7 @@ static int fcgi_recv(struct fcgi_conn *fconn) if (!b_data(buf)) { /* try to pre-align the buffer like the * rxbufs will be to optimize memory copies. We'll make - * sure that the frame header lands at the end of the + * sure that the record header lands at the end of the * HTX block to alias it upon recv. We cannot use the * head because rcv_buf() will realign the buffer if * it's empty. Thus we cheat and pretend we already @@ -2254,17 +2730,25 @@ static int fcgi_recv(struct fcgi_conn *fconn) ret = max ? conn->xprt->rcv_buf(conn, conn->xprt_ctx, buf, max, 0) : 0; - if (max && !ret && fcgi_recv_allowed(fconn)) + if (max && !ret && fcgi_recv_allowed(fconn)) { + TRACE_DATA("failed to receive data, subscribing", FCGI_EV_FCONN_RECV, conn); conn->xprt->subscribe(conn, conn->xprt_ctx, SUB_RETRY_RECV, &fconn->wait_event); + } + else + TRACE_DATA("send data", FCGI_EV_FCONN_RECV, conn,,, (size_t[]){ret}); if (!b_data(buf)) { fcgi_release_buf(fconn, &fconn->dbuf); + TRACE_LEAVE(FCGI_EV_FCONN_RECV, conn); return (conn->flags & CO_FL_ERROR || conn_xprt_read0_pending(conn)); } - if (ret == max) + if (ret == max) { + TRACE_DEVEL("fconn dbuf full", FCGI_EV_FCONN_RECV|FCGI_EV_FCONN_BLK, conn); fconn->flags |= FCGI_CF_DEM_DFULL; + } + TRACE_LEAVE(FCGI_EV_FCONN_RECV, conn); return !!ret || (conn->flags & CO_FL_ERROR) || conn_xprt_read0_pending(conn); } @@ -2278,8 +2762,12 @@ static int fcgi_send(struct fcgi_conn *fconn) int done; int sent = 0; - if (conn->flags & CO_FL_ERROR) + TRACE_ENTER(FCGI_EV_FCONN_SEND, conn); + + if (conn->flags & CO_FL_ERROR) { + TRACE_DEVEL("leaving on connection error", FCGI_EV_FCONN_SEND, conn); return 1; + } if (conn->flags & (CO_FL_HANDSHAKE|CO_FL_WAIT_L4_CONN|CO_FL_WAIT_L6_CONN)) { @@ -2335,6 +2823,7 @@ static int fcgi_send(struct fcgi_conn *fconn) break; } sent = 1; + TRACE_DATA("send data", FCGI_EV_FCONN_SEND, conn,,, (size_t[]){ret}); b_del(buf, ret); if (b_data(buf)) { done = 1; @@ -2349,6 +2838,8 @@ static int fcgi_send(struct fcgi_conn *fconn) offer_buffers(NULL, tasks_run_queue); /* wrote at least one byte, the buffer is not full anymore */ + if (fconn->flags & (FCGI_CF_MUX_MFULL | FCGI_CF_DEM_MROOM)) + TRACE_STATE("fconn mbuf ring not fill anymore", FCGI_EV_FCONN_SEND|FCGI_EV_FCONN_BLK, conn); fconn->flags &= ~(FCGI_CF_MUX_MFULL | FCGI_CF_DEM_MROOM); } @@ -2359,7 +2850,7 @@ static int fcgi_send(struct fcgi_conn *fconn) /* We're not full anymore, so we can wake any task that are waiting * for us. */ - if (!(fconn->flags & (FCGI_CF_MUX_MFULL | FCGI_CF_DEM_MROOM))) { + if (!(fconn->flags & (FCGI_CF_MUX_MFULL | FCGI_CF_DEM_MROOM)) && fconn->state >= FCGI_CS_RECORD_H) { struct fcgi_strm *fstrm; list_for_each_entry(fstrm, &fconn->send_list, send_list) { @@ -2378,17 +2869,23 @@ static int fcgi_send(struct fcgi_conn *fconn) } fstrm->flags &= ~FCGI_SF_BLK_ANY; fstrm->send_wait->events &= ~SUB_RETRY_SEND; + TRACE_DEVEL("waking up pending stream", FCGI_EV_FCONN_SEND|FCGI_EV_STRM_WAKE, conn, fstrm); tasklet_wakeup(fstrm->send_wait->tasklet); LIST_ADDQ(&fconn->sending_list, &fstrm->sending_list); } } /* We're done, no more to send */ - if (!br_data(fconn->mbuf)) + if (!br_data(fconn->mbuf)) { + TRACE_DEVEL("leaving with everything sent", FCGI_EV_FCONN_SEND, conn); return sent; + } schedule: - if (!(conn->flags & CO_FL_ERROR) && !(fconn->wait_event.events & SUB_RETRY_SEND)) + if (!(conn->flags & CO_FL_ERROR) && !(fconn->wait_event.events & SUB_RETRY_SEND)) { + TRACE_STATE("more data to send, subscribing", FCGI_EV_FCONN_SEND, conn); conn->xprt->subscribe(conn, conn->xprt_ctx, SUB_RETRY_SEND, &fconn->wait_event); + } + TRACE_DEVEL("leaving with some data left to send", FCGI_EV_FCONN_SEND, conn); return sent; } @@ -2398,6 +2895,8 @@ static struct task *fcgi_io_cb(struct task *t, void *ctx, unsigned short status) struct fcgi_conn *fconn = ctx; int ret = 0; + TRACE_POINT(FCGI_EV_FCONN_WAKE, fconn->conn); + if (!(fconn->wait_event.events & SUB_RETRY_SEND)) ret = fcgi_send(fconn); if (!(fconn->wait_event.events & SUB_RETRY_RECV)) @@ -2415,6 +2914,8 @@ static int fcgi_process(struct fcgi_conn *fconn) { struct connection *conn = fconn->conn; + TRACE_POINT(FCGI_EV_FCONN_WAKE, conn); + if (b_data(&fconn->dbuf) && !(fconn->flags & FCGI_CF_DEM_BLOCK_ANY)) { fcgi_process_demux(fconn); @@ -2431,6 +2932,7 @@ static int fcgi_process(struct fcgi_conn *fconn) * to announce a graceful shutdown if not yet done. We don't * care if it fails, it will be tried again later. */ + TRACE_STATE("proxy stopped, sending ABORT to all streams", FCGI_EV_FCONN_WAKE|FCGI_EV_TX_RECORD, conn); if (!(fconn->flags & (FCGI_CF_ABRTS_SENT|FCGI_CF_ABRTS_FAILED))) { if (fconn->stream_cnt - fconn->nb_reserved > 0) fcgi_conn_send_aborts(fconn); @@ -2465,6 +2967,7 @@ static int fcgi_process(struct fcgi_conn *fconn) if (eb_is_empty(&fconn->streams_by_id)) { /* no more stream, kill the connection now */ fcgi_release(fconn); + TRACE_DEVEL("leaving after releasing the connection", FCGI_EV_FCONN_WAKE); return -1; } } @@ -2483,6 +2986,7 @@ static int fcgi_process(struct fcgi_conn *fconn) } fcgi_send(fconn); + TRACE_LEAVE(FCGI_EV_FCONN_WAKE, conn); return 0; } @@ -2492,6 +2996,7 @@ static int fcgi_wake(struct connection *conn) { struct fcgi_conn *fconn = conn->ctx; + TRACE_POINT(FCGI_EV_FCONN_WAKE, conn); return (fcgi_process(fconn)); } @@ -2499,20 +3004,25 @@ static int fcgi_wake(struct connection *conn) * nor sending for a certain amount of time, the connection is closed. If the * MUX buffer still has lying data or is not allocatable, the connection is * immediately killed. If it's allocatable and empty, we attempt to send a - * GOAWAY frame. + * ABORT records. */ static struct task *fcgi_timeout_task(struct task *t, void *context, unsigned short state) { struct fcgi_conn *fconn = context; int expired = tick_is_expired(t->expire, now_ms); - if (!expired && fconn) + TRACE_ENTER(FCGI_EV_FCONN_WAKE, (fconn ? fconn->conn : NULL)); + + if (!expired && fconn) { + TRACE_DEVEL("leaving (not expired)", FCGI_EV_FCONN_WAKE, fconn->conn); return t; + } task_destroy(t); if (!fconn) { /* resources were already deleted */ + TRACE_DEVEL("leaving (not more fconn)", FCGI_EV_FCONN_WAKE); return NULL; } @@ -2560,6 +3070,7 @@ static struct task *fcgi_timeout_task(struct task *t, void *context, unsigned sh if (eb_is_empty(&fconn->streams_by_id)) fcgi_release(fconn); + TRACE_LEAVE(FCGI_EV_FCONN_WAKE); return NULL; } @@ -2616,9 +3127,12 @@ static size_t fcgi_strm_parse_headers(struct fcgi_strm *fstrm, struct h1m *h1m, { int ret; + TRACE_ENTER(FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS, fstrm->fconn->conn, fstrm,, (size_t[]){max}); ret = h1_parse_msg_hdrs(h1m, NULL, htx, buf, *ofs, max); if (!ret) { + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS, fstrm->fconn->conn, fstrm); if (htx->flags & HTX_FL_PARSING_ERROR) { + TRACE_USER("rejected H1 response", FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS|FCGI_EV_FSTRM_ERR, fstrm->fconn->conn, fstrm); fcgi_strm_error(fstrm); fcgi_strm_capture_bad_message(fstrm->fconn, fstrm, h1m, buf); } @@ -2627,6 +3141,7 @@ static size_t fcgi_strm_parse_headers(struct fcgi_strm *fstrm, struct h1m *h1m, *ofs += ret; end: + TRACE_LEAVE(FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS, fstrm->fconn->conn, fstrm,, (size_t[]){ret}); return ret; } @@ -2636,9 +3151,12 @@ static size_t fcgi_strm_parse_data(struct fcgi_strm *fstrm, struct h1m *h1m, str { int ret; + TRACE_ENTER(FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY, fstrm->fconn->conn, fstrm,, (size_t[]){max}); ret = h1_parse_msg_data(h1m, htx, buf, *ofs, max, htxbuf); if (ret <= 0) { + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY, fstrm->fconn->conn, fstrm); if ((*htx)->flags & HTX_FL_PARSING_ERROR) { + TRACE_USER("rejected H1 response", FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY|FCGI_EV_FSTRM_ERR, fstrm->fconn->conn, fstrm); fcgi_strm_error(fstrm); fcgi_strm_capture_bad_message(fstrm->fconn, fstrm, h1m, buf); } @@ -2646,6 +3164,7 @@ static size_t fcgi_strm_parse_data(struct fcgi_strm *fstrm, struct h1m *h1m, str } *ofs += ret; end: + TRACE_LEAVE(FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY, fstrm->fconn->conn, fstrm,, (size_t[]){ret}); return ret; } @@ -2654,9 +3173,12 @@ static size_t fcgi_strm_parse_trailers(struct fcgi_strm *fstrm, struct h1m *h1m, { int ret; + TRACE_ENTER(FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS, fstrm->fconn->conn, fstrm,, (size_t[]){max}); ret = h1_parse_msg_tlrs(h1m, htx, buf, *ofs, max); if (ret <= 0) { + TRACE_DEVEL("leaving on missing data or error", FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS, fstrm->fconn->conn, fstrm); if (htx->flags & HTX_FL_PARSING_ERROR) { + TRACE_USER("rejected H1 response", FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS|FCGI_EV_FSTRM_ERR, fstrm->fconn->conn, fstrm); fcgi_strm_error(fstrm); fcgi_strm_capture_bad_message(fstrm->fconn, fstrm, h1m, buf); } @@ -2665,26 +3187,33 @@ static size_t fcgi_strm_parse_trailers(struct fcgi_strm *fstrm, struct h1m *h1m, *ofs += ret; fstrm->flags |= FCGI_SF_HAVE_I_TLR; end: + TRACE_LEAVE(FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS, fstrm->fconn->conn, fstrm,, (size_t[]){ret}); return ret; } static size_t fcgi_strm_add_eom(struct fcgi_strm *fstrm, struct h1m *h1m, struct htx *htx, size_t max) { + TRACE_ENTER(FCGI_EV_RSP_DATA, fstrm->fconn->conn, fstrm,, (size_t[]){max}); if (max < sizeof(struct htx_blk) + 1 || !htx_add_endof(htx, HTX_BLK_EOM)) return 0; h1m->state = H1_MSG_DONE; + TRACE_STATE("end of response", FCGI_EV_RSP_DATA|FCGI_EV_RSP_EOM, fstrm->fconn->conn, fstrm); + TRACE_LEAVE(FCGI_EV_RSP_DATA, fstrm->fconn->conn, fstrm); return (sizeof(struct htx_blk) + 1); } static size_t fcgi_strm_parse_response(struct fcgi_strm *fstrm, struct buffer *buf, size_t count) { + struct fcgi_conn *fconn = fstrm->fconn; struct htx *htx; struct h1m *h1m = &fstrm->h1m; size_t ret, data, total = 0; htx = htx_from_buf(buf); + TRACE_ENTER(FCGI_EV_RSP_DATA, fconn->conn, fstrm, htx, (size_t[]){count}); + data = htx->data; if (fstrm->state == FCGI_SS_ERROR) goto end; @@ -2693,9 +3222,13 @@ static size_t fcgi_strm_parse_response(struct fcgi_strm *fstrm, struct buffer *b size_t used = htx_used_space(htx); if (h1m->state <= H1_MSG_LAST_LF) { + TRACE_PROTO("parsing response headers", FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS, fconn->conn, fstrm); ret = fcgi_strm_parse_headers(fstrm, h1m, htx, &fstrm->rxbuf, &total, count); if (!ret) break; + + TRACE_USER("rcvd H1 response headers", FCGI_EV_RSP_DATA|FCGI_EV_RSP_HDRS, fconn->conn, fstrm, htx); + if ((h1m->flags & (H1_MF_VER_11|H1_MF_XFER_LEN)) == H1_MF_VER_11) { struct htx_blk *blk = htx_get_head_blk(htx); struct htx_sl *sl; @@ -2708,54 +3241,75 @@ static size_t fcgi_strm_parse_response(struct fcgi_strm *fstrm, struct buffer *b } } else if (h1m->state < H1_MSG_TRAILERS) { + TRACE_PROTO("parsing response payload", FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY, fconn->conn, fstrm); ret = fcgi_strm_parse_data(fstrm, h1m, &htx, &fstrm->rxbuf, &total, count, buf); if (!ret) break; + + TRACE_PROTO("rcvd response payload data", FCGI_EV_RSP_DATA|FCGI_EV_RSP_BODY, fconn->conn, fstrm, htx); + + if (h1m->state == H1_MSG_DONE) + TRACE_USER("H1 response fully rcvd", FCGI_EV_RSP_DATA|FCGI_EV_RSP_EOM, fconn->conn, fstrm, htx); } else if (h1m->state == H1_MSG_TRAILERS) { if (!(fstrm->flags & FCGI_SF_HAVE_I_TLR)) { + TRACE_PROTO("parsing response trailers", FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS, fconn->conn, fstrm); ret = fcgi_strm_parse_trailers(fstrm, h1m, htx, &fstrm->rxbuf, &total, count); if (!ret) break; + + TRACE_PROTO("rcvd H1 response trailers", FCGI_EV_RSP_DATA|FCGI_EV_RSP_TLRS, fconn->conn, fstrm, htx); } else if (!fcgi_strm_add_eom(fstrm, h1m, htx, count)) break; + + if (h1m->state == H1_MSG_DONE) + TRACE_USER("H1 response fully rcvd", FCGI_EV_RSP_DATA|FCGI_EV_RSP_EOM, fconn->conn, fstrm, htx); } else if (h1m->state == H1_MSG_DONE) { if (b_data(&fstrm->rxbuf) > total) { htx->flags |= HTX_FL_PARSING_ERROR; + TRACE_PROTO("too much data, parsing error", FCGI_EV_RSP_DATA, fconn->conn, fstrm); fcgi_strm_error(fstrm); } break; } else if (h1m->state == H1_MSG_TUNNEL) { + TRACE_PROTO("parsing response tunneled data", FCGI_EV_RSP_DATA, fconn->conn, fstrm); ret = fcgi_strm_parse_data(fstrm, h1m, &htx, &fstrm->rxbuf, &total, count, buf); if (fstrm->state != FCGI_SS_ERROR && (fstrm->flags & FCGI_SF_ES_RCVD) && b_data(&fstrm->rxbuf) == total) { + TRACE_DEVEL("end of tunneled data", FCGI_EV_RSP_DATA, fconn->conn, fstrm); if ((h1m->flags & (H1_MF_VER_11|H1_MF_XFER_LEN)) == H1_MF_VER_11) { if (!fcgi_strm_add_eom(fstrm, h1m, htx, count)) break; + TRACE_USER("H1 response fully rcvd", FCGI_EV_RSP_DATA|FCGI_EV_RSP_EOM, fconn->conn, fstrm, htx); } else { h1m->state = H1_MSG_DONE; + TRACE_USER("H1 response fully rcvd", FCGI_EV_RSP_DATA|FCGI_EV_RSP_EOM, fconn->conn, fstrm, htx); break; } } if (!ret) break; + + TRACE_PROTO("rcvd H1 response tunneled data", FCGI_EV_RSP_DATA, fconn->conn, fstrm, htx); } else { htx->flags |= HTX_FL_PROCESSING_ERROR; + TRACE_PROTO("processing error", FCGI_EV_RSP_DATA, fconn->conn, fstrm); fcgi_strm_error(fstrm); break; } count -= htx_used_space(htx) - used; - } while (fstrm->state != FCGI_SS_ERROR/* /\*fstrm->state == FCGI_SS_OPEN && *\/count */); + } while (fstrm->state != FCGI_SS_ERROR); if (fstrm->state == FCGI_SS_ERROR) { b_reset(&fstrm->rxbuf); htx_to_buf(htx, buf); + TRACE_DEVEL("leaving on error", FCGI_EV_RSP_DATA|FCGI_EV_STRM_ERR, fconn->conn, fstrm); return 0; } @@ -2764,6 +3318,7 @@ static size_t fcgi_strm_parse_response(struct fcgi_strm *fstrm, struct buffer *b end: htx_to_buf(htx, buf); ret = htx->data - data; + TRACE_LEAVE(FCGI_EV_RSP_DATA, fconn->conn, fstrm, htx, (size_t[]){ret}); return ret; } @@ -2777,14 +3332,19 @@ static struct conn_stream *fcgi_attach(struct connection *conn, struct session * struct fcgi_strm *fstrm; struct fcgi_conn *fconn = conn->ctx; + TRACE_ENTER(FCGI_EV_FSTRM_NEW, conn); cs = cs_new(conn); - if (!cs) + if (!cs) { + TRACE_DEVEL("leaving on CS allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR, conn); return NULL; + } fstrm = fcgi_conn_stream_new(fconn, cs, sess); if (!fstrm) { + TRACE_DEVEL("leaving on stream creation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR, conn); cs_free(cs); return NULL; } + TRACE_LEAVE(FCGI_EV_FSTRM_NEW, conn, fstrm); return cs; } @@ -2816,6 +3376,7 @@ static void fcgi_destroy(void *ctx) { struct fcgi_conn *fconn = ctx; + TRACE_POINT(FCGI_EV_FCONN_END, fconn->conn); if (eb_is_empty(&fconn->streams_by_id) || !fconn->conn || fconn->conn->ctx != fconn) fcgi_release(fconn); } @@ -2829,9 +3390,13 @@ static void fcgi_detach(struct conn_stream *cs) struct fcgi_conn *fconn; struct session *sess; + TRACE_ENTER(FCGI_EV_STRM_END, (fstrm ? fstrm->fconn->conn : NULL), fstrm); + cs->ctx = NULL; - if (!fstrm) + if (!fstrm) { + TRACE_LEAVE(FCGI_EV_STRM_END); return; + } /* The stream is about to die, so no need to attempt to run its task */ if (LIST_ADDED(&fstrm->sending_list) && @@ -2873,8 +3438,10 @@ static void fcgi_detach(struct conn_stream *cs) */ if (!(cs->conn->flags & CO_FL_ERROR) && (fconn->state != FCGI_CS_CLOSED) && - (fstrm->flags & (FCGI_SF_BLK_MBUSY|FCGI_SF_BLK_MROOM)) && (fstrm->send_wait || fstrm->recv_wait)) + (fstrm->flags & (FCGI_SF_BLK_MBUSY|FCGI_SF_BLK_MROOM)) && (fstrm->send_wait || fstrm->recv_wait)) { + TRACE_DEVEL("leaving on stream blocked", FCGI_EV_STRM_END|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); return; + } if ((fconn->flags & FCGI_CF_DEM_BLOCK_ANY && fstrm->id == fconn->dsi)) { /* unblock the connection if it was blocked on this stream. */ @@ -2891,18 +3458,29 @@ static void fcgi_detach(struct conn_stream *cs) if (!session_add_conn(sess, fconn->conn, fconn->conn->target)) { fconn->conn->owner = NULL; if (eb_is_empty(&fconn->streams_by_id)) { - if (!srv_add_to_idle_list(objt_server(fconn->conn->target), fconn->conn)) + if (!srv_add_to_idle_list(objt_server(fconn->conn->target), fconn->conn)) { /* The server doesn't want it, let's kill the connection right away */ fconn->conn->mux->destroy(fconn->conn); + TRACE_DEVEL("outgoing connection killed", FCGI_EV_STRM_END|FCGI_EV_FCONN_ERR); + } + TRACE_DEVEL("reusable idle connection", FCGI_EV_STRM_END, fconn->conn); return; } } } if (eb_is_empty(&fconn->streams_by_id)) { - if (session_check_idle_conn(fconn->conn->owner, fconn->conn) != 0) - /* At this point either the connection is destroyed, - or it's been added to the server idle list, just stop */ + int ret = session_check_idle_conn(fconn->conn->owner, fconn->conn); + if (ret == -1) { + /* The connection is destroyed, let's leave */ + TRACE_DEVEL("outgoing connection killed", FCGI_EV_STRM_END|FCGI_EV_FCONN_ERR); return; + } + else if (ret == 1) { + /* The connection was added to the server idle list, just stop */ + TRACE_DEVEL("reusable idle connection", FCGI_EV_STRM_END, fconn->conn); + return; + } + TRACE_DEVEL("connection in idle session list", FCGI_EV_STRM_END, fconn->conn); } /* Never ever allow to reuse a connection from a non-reuse backend */ if ((fconn->proxy->options & PR_O_REUSE_MASK) == PR_O_REUSE_NEVR) @@ -2916,22 +3494,25 @@ static void fcgi_detach(struct conn_stream *cs) else LIST_ADD(&srv->idle_conns[tid], &fconn->conn->list); } + TRACE_DEVEL("connection in idle server list", FCGI_EV_STRM_END, fconn->conn); } } /* We don't want to close right now unless we're removing the last - * stream, and either the connection is in error, or it reached the ID - * already specified in a GOAWAY frame received or sent (as seen by - * last_sid >= 0). + * stream and the connection is in error. */ if (fcgi_conn_is_dead(fconn)) { /* no more stream will come, kill it now */ + TRACE_DEVEL("leaving, killing dead connection", FCGI_EV_STRM_END, fconn->conn); fcgi_release(fconn); } else if (fconn->task) { fconn->task->expire = tick_add(now_ms, (fconn->state == FCGI_CS_CLOSED ? fconn->shut_timeout : fconn->timeout)); task_queue(fconn->task); + TRACE_DEVEL("leaving, refreshing connection's timeout", FCGI_EV_STRM_END, fconn->conn); } + else + TRACE_DEVEL("leaving", FCGI_EV_STRM_END, fconn->conn); } @@ -2941,6 +3522,8 @@ static void fcgi_do_shutr(struct fcgi_strm *fstrm) struct fcgi_conn *fconn = fstrm->fconn; struct wait_event *sw = &fstrm->wait_event; + TRACE_ENTER(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); + if (fstrm->state == FCGI_SS_CLOSED) goto done; @@ -2949,9 +3532,12 @@ static void fcgi_do_shutr(struct fcgi_strm *fstrm) * normally used to limit abuse. */ if ((fstrm->flags & FCGI_SF_KILL_CONN) && - !(fconn->flags & (FCGI_CF_ABRTS_SENT|FCGI_CF_ABRTS_FAILED))) + !(fconn->flags & (FCGI_CF_ABRTS_SENT|FCGI_CF_ABRTS_FAILED))) { + TRACE_STATE("stream wants to kill the connection", FCGI_EV_STRM_SHUT, fconn->conn, fstrm); fconn->state = FCGI_CS_CLOSED; + } else if (fstrm->flags & FCGI_SF_BEGIN_SENT) { + TRACE_STATE("no headers sent yet, trying a retryable abort", FCGI_EV_STRM_SHUT, fconn->conn, fstrm); if (!(fstrm->flags & (FCGI_SF_ES_SENT|FCGI_SF_ABRT_SENT)) && !fcgi_strm_send_abort(fconn, fstrm)) goto add_to_list; @@ -2963,6 +3549,7 @@ static void fcgi_do_shutr(struct fcgi_strm *fstrm) tasklet_wakeup(fconn->wait_event.tasklet); done: fstrm->flags &= ~FCGI_SF_WANT_SHUTR; + TRACE_LEAVE(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); return; add_to_list: @@ -2975,6 +3562,7 @@ static void fcgi_do_shutr(struct fcgi_strm *fstrm) } /* Let the handler know we want shutr */ fstrm->flags |= FCGI_SF_WANT_SHUTR; + TRACE_LEAVE(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); return; } @@ -2984,6 +3572,8 @@ static void fcgi_do_shutw(struct fcgi_strm *fstrm) struct fcgi_conn *fconn = fstrm->fconn; struct wait_event *sw = &fstrm->wait_event; + TRACE_ENTER(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); + if (fstrm->state != FCGI_SS_HLOC || fstrm->state == FCGI_SS_CLOSED) goto done; @@ -3002,8 +3592,10 @@ static void fcgi_do_shutw(struct fcgi_strm *fstrm) * normally used to limit abuse. */ if ((fstrm->flags & FCGI_SF_KILL_CONN) && - !(fconn->flags & (FCGI_CF_ABRTS_SENT|FCGI_CF_ABRTS_FAILED))) + !(fconn->flags & (FCGI_CF_ABRTS_SENT|FCGI_CF_ABRTS_FAILED))) { + TRACE_STATE("stream wants to kill the connection", FCGI_EV_STRM_SHUT, fconn->conn, fstrm); fconn->state = FCGI_CS_CLOSED; + } fcgi_strm_close(fstrm); } @@ -3012,6 +3604,7 @@ static void fcgi_do_shutw(struct fcgi_strm *fstrm) tasklet_wakeup(fconn->wait_event.tasklet); done: fstrm->flags &= ~FCGI_SF_WANT_SHUTW; + TRACE_LEAVE(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); return; add_to_list: @@ -3024,18 +3617,21 @@ static void fcgi_do_shutw(struct fcgi_strm *fstrm) } /* let the handler know we want to shutw */ fstrm->flags |= FCGI_SF_WANT_SHUTW; + TRACE_LEAVE(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); return; } /* This is the tasklet referenced in fstrm->wait_event.tasklet, it is used for * deferred shutdowns when the fcgi_detach() was done but the mux buffer was full - * and prevented the last frame from being emitted. + * and prevented the last record from being emitted. */ static struct task *fcgi_deferred_shut(struct task *t, void *ctx, unsigned short state) { struct fcgi_strm *fstrm = ctx; struct fcgi_conn *fconn = fstrm->fconn; + TRACE_ENTER(FCGI_EV_STRM_SHUT, fconn->conn, fstrm); + LIST_DEL_INIT(&fstrm->sending_list); if (fstrm->flags & FCGI_SF_WANT_SHUTW) fcgi_do_shutw(fstrm); @@ -3054,6 +3650,7 @@ static struct task *fcgi_deferred_shut(struct task *t, void *ctx, unsigned short } } + TRACE_LEAVE(FCGI_EV_STRM_SHUT); return NULL; } @@ -3062,6 +3659,7 @@ static void fcgi_shutr(struct conn_stream *cs, enum cs_shr_mode mode) { struct fcgi_strm *fstrm = cs->ctx; + TRACE_POINT(FCGI_EV_STRM_SHUT, fstrm->fconn->conn, fstrm); if (cs->flags & CS_FL_KILL_CONN) fstrm->flags |= FCGI_SF_KILL_CONN; @@ -3076,6 +3674,7 @@ static void fcgi_shutw(struct conn_stream *cs, enum cs_shw_mode mode) { struct fcgi_strm *fstrm = cs->ctx; + TRACE_POINT(FCGI_EV_STRM_SHUT, fstrm->fconn->conn, fstrm); if (cs->flags & CS_FL_KILL_CONN) fstrm->flags |= FCGI_SF_KILL_CONN; @@ -3096,6 +3695,7 @@ static int fcgi_subscribe(struct conn_stream *cs, int event_type, void *param) struct fcgi_conn *fconn = fstrm->fconn; if (event_type & SUB_RETRY_RECV) { + TRACE_DEVEL("unsubscribe(recv)", FCGI_EV_STRM_RECV, fconn->conn, fstrm); sw = param; BUG_ON(fstrm->recv_wait != NULL || (sw->events & SUB_RETRY_RECV)); sw->events |= SUB_RETRY_RECV; @@ -3103,6 +3703,7 @@ static int fcgi_subscribe(struct conn_stream *cs, int event_type, void *param) event_type &= ~SUB_RETRY_RECV; } if (event_type & SUB_RETRY_SEND) { + TRACE_DEVEL("unsubscribe(send)", FCGI_EV_STRM_SEND, fconn->conn, fstrm); sw = param; BUG_ON(fstrm->send_wait != NULL || (sw->events & SUB_RETRY_SEND)); sw->events |= SUB_RETRY_SEND; @@ -3125,14 +3726,17 @@ static int fcgi_unsubscribe(struct conn_stream *cs, int event_type, void *param) { struct wait_event *sw; struct fcgi_strm *fstrm = cs->ctx; + struct fcgi_conn *fconn = fstrm->fconn; if (event_type & SUB_RETRY_RECV) { + TRACE_DEVEL("subscribe(recv)", FCGI_EV_STRM_RECV, fconn->conn, fstrm); sw = param; BUG_ON(fstrm->recv_wait != sw); sw->events &= ~SUB_RETRY_RECV; fstrm->recv_wait = NULL; } if (event_type & SUB_RETRY_SEND) { + TRACE_DEVEL("subscribe(send)", FCGI_EV_STRM_SEND, fconn->conn, fstrm); sw = param; BUG_ON(fstrm->send_wait != sw); LIST_DEL(&fstrm->send_list); @@ -3155,8 +3759,12 @@ static size_t fcgi_rcv_buf(struct conn_stream *cs, struct buffer *buf, size_t co struct fcgi_conn *fconn = fstrm->fconn; size_t ret = 0; + TRACE_ENTER(FCGI_EV_STRM_RECV, fconn->conn, fstrm); + if (!(fconn->flags & FCGI_CF_DEM_SALLOC)) ret = fcgi_strm_parse_response(fstrm, buf, count); + else + TRACE_STATE("fstrm rxbuf not allocated", FCGI_EV_STRM_RECV|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); if (b_data(&fstrm->rxbuf)) cs->flags |= (CS_FL_RCV_MORE | CS_FL_WANT_ROOM); @@ -3180,6 +3788,7 @@ static size_t fcgi_rcv_buf(struct conn_stream *cs, struct buffer *buf, size_t co fcgi_conn_restart_reading(fconn, 1); } + TRACE_LEAVE(FCGI_EV_STRM_RECV, fconn->conn, fstrm); return ret; } @@ -3214,12 +3823,16 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co struct htx_blk *blk; uint32_t bsize; + TRACE_ENTER(FCGI_EV_STRM_SEND, fconn->conn, fstrm,, (size_t[]){count}); + /* If we were not just woken because we wanted to send but couldn't, * and there's somebody else that is waiting to send, do nothing, * we will subscribe later and be put at the end of the list */ - if (!LIST_ADDED(&fstrm->sending_list) && !LIST_ISEMPTY(&fconn->send_list)) + if (!LIST_ADDED(&fstrm->sending_list) && !LIST_ISEMPTY(&fconn->send_list)) { + TRACE_STATE("other streams already waiting, going to the queue and leaving", FCGI_EV_STRM_SEND|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); return 0; + } LIST_DEL_INIT(&fstrm->sending_list); /* We couldn't set it to NULL before, because we needed it in case @@ -3227,8 +3840,10 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co */ fstrm->send_wait = NULL; - if (fconn->state < FCGI_CS_RECORD_H) + if (fconn->state < FCGI_CS_RECORD_H) { + TRACE_STATE("connection not ready, leaving", FCGI_EV_STRM_SEND|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); return 0; + } htx = htxbuf(buf); if (fstrm->id == 0) { @@ -3237,6 +3852,7 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co if (id < 0) { fcgi_strm_close(fstrm); cs->flags |= CS_FL_ERROR; + TRACE_DEVEL("couldn't get a stream ID, leaving in error", FCGI_EV_STRM_SEND|FCGI_EV_FSTRM_ERR|FCGI_EV_STRM_ERR, fconn->conn, fstrm); return 0; } @@ -3259,6 +3875,7 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co } if (!(fstrm->flags & FCGI_SF_BEGIN_SENT)) { + TRACE_PROTO("sending FCGI BEGIN_REQUEST record", FCGI_EV_TX_RECORD|FCGI_EV_TX_BEGREQ, fconn->conn, fstrm); if (!fcgi_strm_send_begin_request(fconn, fstrm)) goto done; } @@ -3275,6 +3892,7 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co switch (htx_get_blk_type(blk)) { case HTX_BLK_REQ_SL: case HTX_BLK_HDR: + TRACE_USER("sending FCGI PARAMS record", FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm, htx); ret = fcgi_strm_send_params(fconn, fstrm, htx); if (!ret) { goto done; @@ -3284,12 +3902,14 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co break; case HTX_BLK_EOH: + TRACE_PROTO("sending FCGI PARAMS record", FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm, htx); ret = fcgi_strm_send_empty_params(fconn, fstrm); if (!ret) goto done; goto remove_blk; case HTX_BLK_DATA: + TRACE_PROTO("sending FCGI STDIN record", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx); ret = fcgi_strm_send_stdin(fconn, fstrm, htx, count, buf); if (ret > 0) { htx = htx_from_buf(buf); @@ -3301,6 +3921,7 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co break; case HTX_BLK_EOM: + TRACE_PROTO("sending FCGI STDIN record", FCGI_EV_TX_RECORD|FCGI_EV_TX_STDIN, fconn->conn, fstrm, htx); ret = fcgi_strm_send_empty_stdin(fconn, fstrm); if (!ret) goto done; @@ -3325,6 +3946,7 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co } if (fstrm->state == FCGI_SS_ERROR) { + TRACE_DEVEL("reporting error to the app-layer stream", FCGI_EV_STRM_SEND|FCGI_EV_FSTRM_ERR|FCGI_EV_STRM_ERR, fconn->conn, fstrm); cs_set_error(cs); if (!(fstrm->flags & FCGI_SF_BEGIN_SENT) || fcgi_strm_send_abort(fconn, fstrm)) fcgi_strm_close(fstrm); @@ -3334,16 +3956,22 @@ static size_t fcgi_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t co htx_to_buf(htx, buf); /* The mux is full, cancel the pending tasks */ - if ((fconn->flags & FCGI_CF_MUX_BLOCK_ANY) || (fstrm->flags & FCGI_SF_BLK_MBUSY)) + if ((fconn->flags & FCGI_CF_MUX_BLOCK_ANY) || (fstrm->flags & FCGI_SF_BLK_MBUSY)) { + TRACE_DEVEL("mux full, stopping senders", FCGI_EV_STRM_SEND|FCGI_EV_FCONN_BLK|FCGI_EV_FSTRM_BLK, fconn->conn, fstrm); fcgi_stop_senders(fconn); + } if (total > 0) { - if (!(fconn->wait_event.events & SUB_RETRY_SEND)) + if (!(fconn->wait_event.events & SUB_RETRY_SEND)) { + TRACE_DEVEL("data queued, waking up fconn sender", FCGI_EV_STRM_SEND|FCGI_EV_FCONN_SEND|FCGI_EV_FCONN_WAKE, fconn->conn, fstrm); tasklet_wakeup(fconn->wait_event.tasklet); + } /* Ok we managed to send something, leave the send_list */ LIST_DEL_INIT(&fstrm->send_list); } + + TRACE_LEAVE(FCGI_EV_STRM_SEND, fconn->conn, fstrm, htx, (size_t[]){total}); return total; } -- 2.39.5