MINOR: mux-fcgi/trace: add traces at level ERROR for all kind of errors
A number of traces could be added or changed to report errors with
TRACE_ERROR. The goal is to be able to enable error tracing only to detect
anomalies.
diff --git a/src/mux_fcgi.c b/src/mux_fcgi.c
index defe955..d45951b 100644
--- a/src/mux_fcgi.c
+++ b/src/mux_fcgi.c
@@ -702,12 +702,16 @@
TRACE_ENTER(FCGI_EV_FSTRM_NEW);
- if (!app)
+ if (!app) {
+ TRACE_ERROR("No FCGI app found, don't create fconn", FCGI_EV_FCONN_NEW|FCGI_EV_FCONN_END|FCGI_EV_FCONN_ERR);
goto fail_conn;
+ }
fconn = pool_alloc(pool_head_fcgi_conn);
- if (!fconn)
+ if (!fconn) {
+ TRACE_ERROR("fconn allocation failure", FCGI_EV_FCONN_NEW|FCGI_EV_FCONN_END|FCGI_EV_FCONN_ERR);
goto fail_conn;
+ }
fconn->shut_timeout = fconn->timeout = px->timeout.server;
if (tick_isset(px->timeout.serverfin))
@@ -728,8 +732,10 @@
fconn->task = NULL;
if (tick_isset(fconn->timeout)) {
t = task_new(tid_bit);
- if (!t)
+ if (!t) {
+ TRACE_ERROR("fconn task allocation failure", FCGI_EV_FCONN_NEW|FCGI_EV_FCONN_END|FCGI_EV_FCONN_ERR);
goto fail;
+ }
fconn->task = t;
t->process = fcgi_timeout_task;
@@ -1049,11 +1055,14 @@
TRACE_ENTER(FCGI_EV_FSTRM_NEW, fconn->conn);
fstrm = pool_alloc(pool_head_fcgi_strm);
- if (!fstrm)
+ if (!fstrm) {
+ TRACE_ERROR("fstrm allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR|FCGI_EV_FSTRM_END, fconn->conn);
goto out;
+ }
fstrm->shut_tl = tasklet_new();
if (!fstrm->shut_tl) {
+ TRACE_ERROR("fstrm shut tasklet allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR|FCGI_EV_FSTRM_END, fconn->conn);
pool_free(pool_head_fcgi_strm, fstrm);
goto out;
}
@@ -1101,19 +1110,19 @@
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);
+ TRACE_ERROR("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) {
- TRACE_DEVEL("leaving on !streams_left", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn);
+ TRACE_ERROR("!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) {
- TRACE_DEVEL("leaving on fstrm creation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn);
+ TRACE_ERROR("fstream allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn);
goto out;
}
@@ -1126,6 +1135,7 @@
return fstrm;
out:
+ TRACE_DEVEL("leaving on error", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_END|FCGI_EV_FSTRM_ERR, fconn->conn);
return NULL;
}
@@ -1564,8 +1574,10 @@
return ret;
full:
/* Too large to be encoded. For GET_VALUES records, it is an error */
- if (!b_data(mbuf))
+ if (!b_data(mbuf)) {
+ TRACE_ERROR("GET_VALUES record too large", FCGI_EV_TX_RECORD|FCGI_EV_TX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn);
goto fail;
+ }
if ((mbuf = br_tail_add(fconn->mbuf)) != NULL)
goto retry;
@@ -1623,6 +1635,7 @@
ret = fcgi_aligned_decode_param(&inbuf, offset, &p);
if (!ret) {
/* name or value too large to be decoded at once */
+ TRACE_ERROR("error decoding GET_VALUES_RESULT param", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn);
goto fail;
}
offset += ret;
@@ -1657,8 +1670,10 @@
/* We must be sure to have read exactly the announced record length, no
* more no less
*/
- if (offset != fconn->drl)
+ if (offset != fconn->drl) {
+ TRACE_ERROR("invalid GET_VALUES_RESULT record length", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL|FCGI_EV_FCONN_ERR, fconn->conn);
goto fail;
+ }
TRACE_PROTO("FCGI GET_VALUES_RESULT record rcvd", FCGI_EV_RX_RECORD|FCGI_EV_RX_GETVAL, fconn->conn, 0, 0, (size_t[]){fconn->drl});
b_del(&fconn->dbuf, fconn->drl + fconn->drp);
@@ -2047,8 +2062,10 @@
}
done:
- if (!fcgi_set_default_param(fconn, fstrm, htx, sl, ¶ms))
+ if (!fcgi_set_default_param(fconn, fstrm, htx, sl, ¶ms)) {
+ TRACE_ERROR("error setting default params", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
goto error;
+ }
if (!fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_CGI_GATEWAY) ||
!fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_DOC_ROOT) ||
@@ -2065,8 +2082,10 @@
!fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_SCRIPT_FILE) ||
!fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_PATH_TRANS) ||
!fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_CONT_LEN) ||
- !fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_HTTPS))
+ !fcgi_encode_default_param(fconn, fstrm, ¶ms, &outbuf, FCGI_SP_HTTPS)) {
+ TRACE_ERROR("error encoding default params", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
goto error;
+ }
/* update the record's size */
TRACE_PROTO("FCGI PARAMS record xferred", FCGI_EV_TX_RECORD|FCGI_EV_TX_PARAMS, fconn->conn, fstrm, 0, (size_t[]){outbuf.data - FCGI_RECORD_HEADER_SZ});
@@ -2088,7 +2107,7 @@
error:
htx->flags |= HTX_FL_PROCESSING_ERROR;
- TRACE_PROTO("processing error", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
+ TRACE_ERROR("processing error sending PARAMS record", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
fcgi_strm_error(fstrm);
goto end;
}
@@ -2266,7 +2285,7 @@
if (!fcgi_strm_send_empty_stdin(fconn, fstrm)) {
/* bytes already reserved for this record. It should not fail */
htx->flags |= HTX_FL_PROCESSING_ERROR;
- TRACE_PROTO("processing error", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
+ TRACE_ERROR("processing error sending empty STDIN record", FCGI_EV_TX_RECORD|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
fcgi_strm_error(fstrm);
}
}
@@ -2453,8 +2472,10 @@
dbuf = &fconn->dbuf;
/* Record too large to be fully decoded */
- if (b_size(dbuf) < (fconn->drl + fconn->drp))
+ if (b_size(dbuf) < (fconn->drl + fconn->drp)) {
+ TRACE_ERROR("END_REQUEST record too large", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ|FCGI_EV_FSTRM_ERR, fconn->conn, fstrm);
goto fail;
+ }
/* process full record only */
if (b_data(dbuf) < (fconn->drl + fconn->drp)) {
@@ -2472,8 +2493,10 @@
inbuf = b_make(b_head(dbuf), b_data(dbuf), 0, fconn->drl);
- if (!fcgi_decode_end_request(&inbuf, 0, &endreq))
+ if (!fcgi_decode_end_request(&inbuf, 0, &endreq)) {
+ TRACE_ERROR("END_REQUEST record decoding failure", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ|FCGI_EV_FSTRM_ERR, fconn->conn, fstrm);
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);
@@ -2516,13 +2539,15 @@
/* 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)
+ if (!ret) {
+ TRACE_ERROR("header record decoding failure", FCGI_EV_RX_RECORD|FCGI_EV_RX_ENDREQ|FCGI_EV_FSTRM_ERR, fconn->conn, fstrm);
goto fail;
+ }
b_del(&fconn->dbuf, ret);
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_ERROR("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;
}
@@ -3279,7 +3304,7 @@
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);
+ TRACE_ERROR("parsing error, reject 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);
}
@@ -3303,7 +3328,7 @@
if (!ret) {
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);
+ TRACE_ERROR("parsing error, reject 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);
}
@@ -3325,7 +3350,7 @@
if (!ret) {
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);
+ TRACE_ERROR("parsing error, reject 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);
}
@@ -3409,7 +3434,7 @@
}
else {
htx->flags |= HTX_FL_PROCESSING_ERROR;
- TRACE_PROTO("processing error", FCGI_EV_RSP_DATA, fconn->conn, fstrm);
+ TRACE_ERROR("unexpected processing error", FCGI_EV_RSP_DATA|FCGI_EV_STRM_ERR, fconn->conn, fstrm);
fcgi_strm_error(fstrm);
break;
}
@@ -3446,17 +3471,20 @@
TRACE_ENTER(FCGI_EV_FSTRM_NEW, conn);
cs = cs_new(conn, conn->target);
if (!cs) {
- TRACE_DEVEL("leaving on CS allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR, conn);
- return NULL;
+ TRACE_ERROR("CS allocation failure", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR, conn);
+ goto err;
}
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;
+ goto err;
}
TRACE_LEAVE(FCGI_EV_FSTRM_NEW, conn, fstrm);
return cs;
+
+ err:
+ TRACE_DEVEL("leaving on error", FCGI_EV_FSTRM_NEW|FCGI_EV_FSTRM_ERR, conn);
+ return NULL;
}
/* Retrieves the first valid conn_stream from this connection, or returns NULL.