lib: add trace support for client reads and writes

- add `CURL_TRC_READ()` and `CURL_TRC_WRITE()`
- use in generic client writers and readers, as well
  as http headers, chunking and websockets

Closes #13223
This commit is contained in:
Stefan Eissing 2024-03-28 14:12:54 +01:00 коммит произвёл Daniel Stenberg
Родитель f46385d36d
Коммит 0b28ece657
Не найден ключ, соответствующий данной подписи
Идентификатор ключа GPG: 5CC908FDB71E12C2
9 изменённых файлов: 188 добавлений и 51 удалений

Просмотреть файл

@ -68,7 +68,7 @@ that.
## `tcp`
Tracing of TCP socket handling: connect, reads, writes.
Tracing of TCP socket handling: connect, sends, receives.
## `ssl`
@ -96,6 +96,14 @@ trace.
Tracing of DNS-over-HTTP operations to resolve hostnames.
## `read`
Traces reading of upload data from the application in order to send it to the server.
## `write`
Traces writing of download data, received from the server, to the application.
# EXAMPLE
~~~c

Просмотреть файл

@ -111,21 +111,30 @@ void Curl_failf(struct Curl_easy *data, const char *fmt, ...)
/* Curl_infof() is for info message along the way */
#define MAXINFO 2048
static void trc_infof(struct Curl_easy *data, struct curl_trc_feat *feat,
const char * const fmt, va_list ap) CURL_PRINTF(3, 0);
static void trc_infof(struct Curl_easy *data, struct curl_trc_feat *feat,
const char * const fmt, va_list ap)
{
int len = 0;
char buffer[MAXINFO + 2];
if(feat)
len = msnprintf(buffer, MAXINFO, "[%s] ", feat->name);
len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
buffer[len++] = '\n';
buffer[len] = '\0';
Curl_debug(data, CURLINFO_TEXT, buffer, len);
}
void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_is_verbose(data)) {
va_list ap;
int len = 0;
char buffer[MAXINFO + 2];
if(data->state.feat)
len = msnprintf(buffer, MAXINFO, "[%s] ", data->state.feat->name);
va_start(ap, fmt);
len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
trc_infof(data, data->state.feat, fmt, ap);
va_end(ap);
buffer[len++] = '\n';
buffer[len] = '\0';
Curl_debug(data, CURLINFO_TEXT, buffer, len);
}
}
@ -154,7 +163,40 @@ void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
}
}
struct curl_trc_feat Curl_trc_feat_read = {
"READ",
CURL_LOG_LVL_NONE,
};
struct curl_trc_feat Curl_trc_feat_write = {
"WRITE",
CURL_LOG_LVL_NONE,
};
void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_read)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_read, fmt, ap);
va_end(ap);
}
}
void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_write)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_write, fmt, ap);
va_end(ap);
}
}
static struct curl_trc_feat *trc_feats[] = {
&Curl_trc_feat_read,
&Curl_trc_feat_write,
#ifndef CURL_DISABLE_DOH
&Curl_doh_trc,
#endif

Просмотреть файл

@ -77,10 +77,18 @@ void Curl_failf(struct Curl_easy *data,
#define CURL_TRC_CF(data, cf, ...) \
do { if(Curl_trc_cf_is_verbose(cf, data)) \
Curl_trc_cf_infof(data, cf, __VA_ARGS__); } while(0)
#define CURL_TRC_WRITE(data, ...) \
do { if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_write)) \
Curl_trc_write(data, __VA_ARGS__); } while(0)
#define CURL_TRC_READ(data, ...) \
do { if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_read)) \
Curl_trc_read(data, __VA_ARGS__); } while(0)
#else
#define infof Curl_infof
#define CURL_TRC_CF Curl_trc_cf_infof
#define CURL_TRC_WRITE Curl_trc_write
#define CURL_TRC_READ Curl_trc_read
#endif
#ifndef CURL_DISABLE_VERBOSE_STRINGS
@ -90,6 +98,8 @@ struct curl_trc_feat {
const char *name;
int log_level;
};
extern struct curl_trc_feat Curl_trc_feat_read;
extern struct curl_trc_feat Curl_trc_feat_write;
#define Curl_trc_is_verbose(data) \
((data) && (data)->set.verbose && \
@ -97,10 +107,10 @@ struct curl_trc_feat {
((data)->state.feat->log_level >= CURL_LOG_LVL_INFO)))
#define Curl_trc_cf_is_verbose(cf, data) \
(Curl_trc_is_verbose(data) && \
(cf) && (cf)->cft->log_level >= CURL_LOG_LVL_INFO)
(cf) && (cf)->cft->log_level >= CURL_LOG_LVL_INFO)
#define Curl_trc_ft_is_verbose(data, ft) \
(Curl_trc_is_verbose(data) && \
(ft)->log_level >= CURL_LOG_LVL_INFO)
(Curl_trc_is_verbose(data) && \
(ft)->log_level >= CURL_LOG_LVL_INFO)
/**
* Output an informational message when transfer's verbose logging is enabled.
@ -114,6 +124,16 @@ void Curl_infof(struct Curl_easy *data,
*/
void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
const char *fmt, ...) CURL_PRINTF(3, 4);
void Curl_trc_ft_infof(struct Curl_easy *data, struct curl_trc_feat *ft,
const char *fmt, ...) CURL_PRINTF(3, 4);
void Curl_trc_write(struct Curl_easy *data,
const char *fmt, ...) CURL_PRINTF(2, 3);
void Curl_trc_read(struct Curl_easy *data,
const char *fmt, ...) CURL_PRINTF(2, 3);
#else /* defined(CURL_DISABLE_VERBOSE_STRINGS) */
/* All informational messages are not compiled in for size savings */
@ -134,6 +154,23 @@ static void Curl_trc_cf_infof(struct Curl_easy *data,
(void)data; (void)cf; (void)fmt;
}
static void Curl_trc_ft_infof(struct Curl_easy *data,
struct curl_trc_feat *ft,
const char *fmt, ...)
{
(void)data; (void)ft; (void)fmt;
}
static void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
static void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
#endif /* !defined(CURL_DISABLE_VERBOSE_STRINGS) */
#endif /* HEADER_CURL_TRC_H */

Просмотреть файл

@ -217,6 +217,9 @@ static CURLcode cw_out_ptr_flush(struct cw_out_ctx *ctx,
Curl_set_in_callback(data, TRUE);
nwritten = wcb((char *)buf, 1, wlen, wcb_data);
Curl_set_in_callback(data, FALSE);
CURL_TRC_WRITE(data, "cw_out, wrote %zu %s bytes -> %zu",
wlen, (otype == CW_OUT_BODY)? "body" : "header",
nwritten);
if(CURL_WRITEFUNC_PAUSE == nwritten) {
if(data->conn && data->conn->handler->flags & PROTOPT_NONETWORK) {
/* Protocols that work without network cannot be paused. This is
@ -227,6 +230,7 @@ static CURLcode cw_out_ptr_flush(struct cw_out_ctx *ctx,
}
/* mark the connection as RECV paused */
data->req.keepon |= KEEP_RECV_PAUSE;
CURL_TRC_WRITE(data, "cw_out, PAUSE requested by client");
break;
}
if(nwritten != wlen) {

Просмотреть файл

@ -361,6 +361,8 @@ static CURLcode hds_cw_collect_write(struct Curl_easy *data,
(type & CLIENTWRITE_TRAILER ? CURLH_TRAILER :
CURLH_HEADER)));
CURLcode result = Curl_headers_push(data, buf, htype);
CURL_TRC_WRITE(data, "header_collect pushed(type=%x, len=%zu) -> %d",
htype, blen, result);
if(result)
return result;
}

Просмотреть файл

@ -28,6 +28,7 @@
#include "urldata.h" /* it includes http_chunks.h */
#include "curl_printf.h"
#include "curl_trc.h"
#include "sendf.h" /* for the client write stuff */
#include "dynbuf.h"
#include "content_encoding.h"
@ -185,8 +186,11 @@ static CURLcode httpchunk_readwrite(struct Curl_easy *data,
if(0 == ch->datasize) {
ch->state = CHUNK_TRAILER; /* now check for trailers */
}
else
else {
ch->state = CHUNK_DATA;
CURL_TRC_WRITE(data, "http_chunked, chunk start of %"
CURL_FORMAT_CURL_OFF_T " bytes", ch->datasize);
}
}
buf++;
@ -221,6 +225,9 @@ static CURLcode httpchunk_readwrite(struct Curl_easy *data,
ch->datasize -= piece; /* decrease amount left to expect */
buf += piece; /* move read pointer forward */
blen -= piece; /* decrease space left in this round */
CURL_TRC_WRITE(data, "http_chunked, write %zu body bytes, %"
CURL_FORMAT_CURL_OFF_T " bytes in chunk remain",
piece, ch->datasize);
if(0 == ch->datasize)
/* end of data this round, we now expect a trailing CRLF */
@ -340,11 +347,14 @@ static CURLcode httpchunk_readwrite(struct Curl_easy *data,
even if there's no more chunks to read */
ch->datasize = blen;
ch->state = CHUNK_DONE;
CURL_TRC_WRITE(data, "http_chunk, response complete");
return CURLE_OK;
}
else {
ch->state = CHUNK_FAILED;
ch->last_code = CHUNKE_BAD_CHUNK;
CURL_TRC_WRITE(data, "http_chunk error, expected 0x0a, seeing 0x%ux",
(unsigned int)*buf);
return CURLE_RECV_ERROR;
}
case CHUNK_DONE:
@ -498,6 +508,7 @@ static CURLcode add_last_chunk(struct Curl_easy *data,
int rc;
if(!data->set.trailer_callback) {
CURL_TRC_READ(data, "http_chunk, added last, empty chunk");
return Curl_bufq_cwrite(&ctx->chunkbuf, STRCONST("0\r\n\r\n"), &n);
}
@ -535,6 +546,8 @@ static CURLcode add_last_chunk(struct Curl_easy *data,
out:
curl_slist_free_all(trailers);
CURL_TRC_READ(data, "http_chunk, added last chunk with trailers "
"from client -> %d", result);
return result;
}
@ -581,6 +594,8 @@ static CURLcode add_chunk(struct Curl_easy *data,
result = Curl_bufq_cwrite(&ctx->chunkbuf, buf, nread, &n);
if(!result)
result = Curl_bufq_cwrite(&ctx->chunkbuf, "\r\n", 2, &n);
CURL_TRC_READ(data, "http_chunk, made chunk of %zu bytes -> %d",
nread, result);
if(result)
return result;
}

Просмотреть файл

@ -88,7 +88,10 @@ CURLcode Curl_client_write(struct Curl_easy *data,
DEBUGASSERT(data->req.writer_stack);
}
return Curl_cwriter_write(data, data->req.writer_stack, type, buf, blen);
result = Curl_cwriter_write(data, data->req.writer_stack, type, buf, blen);
CURL_TRC_WRITE(data, "client_write(type=%x, len=%zu) -> %d",
type, blen, result);
return result;
}
static void cl_reset_writer(struct Curl_easy *data)
@ -115,7 +118,6 @@ static void cl_reset_reader(struct Curl_easy *data)
void Curl_client_cleanup(struct Curl_easy *data)
{
DEBUGF(infof(data, "Curl_client_cleanup()"));
cl_reset_reader(data);
cl_reset_writer(data);
@ -127,10 +129,10 @@ void Curl_client_reset(struct Curl_easy *data)
{
if(data->req.rewind_read) {
/* already requested */
DEBUGF(infof(data, "Curl_client_reset(), will rewind_read"));
CURL_TRC_READ(data, "client_reset, will rewind reader");
}
else {
DEBUGF(infof(data, "Curl_client_reset(), clear readers"));
CURL_TRC_READ(data, "client_reset, clear readers");
cl_reset_reader(data);
}
cl_reset_writer(data);
@ -145,7 +147,7 @@ CURLcode Curl_client_start(struct Curl_easy *data)
struct Curl_creader *r = data->req.reader_stack;
CURLcode result = CURLE_OK;
DEBUGF(infof(data, "client start, rewind readers"));
CURL_TRC_READ(data, "client start, rewind readers");
while(r) {
result = r->crt->rewind(data, r);
if(result) {
@ -249,7 +251,10 @@ static CURLcode cw_download_write(struct Curl_easy *data,
if(!(type & CLIENTWRITE_BODY)) {
if(is_connect && data->set.suppress_connect_headers)
return CURLE_OK;
return Curl_cwriter_write(data, writer->next, type, buf, nbytes);
result = Curl_cwriter_write(data, writer->next, type, buf, nbytes);
CURL_TRC_WRITE(data, "download_write header(type=%x, blen=%zu) -> %d",
type, nbytes, result);
return result;
}
/* Here, we deal with REAL BODY bytes. All filtering and transfer
@ -261,8 +266,8 @@ static CURLcode cw_download_write(struct Curl_easy *data,
if(data->req.no_body && nbytes > 0) {
/* BODY arrives although we want none, bail out */
streamclose(data->conn, "ignoring body");
DEBUGF(infof(data, "did not want a BODY, but seeing %zu bytes",
nbytes));
CURL_TRC_WRITE(data, "download_write body(type=%x, blen=%zu), "
"did not want a BODY", type, nbytes);
data->req.download_done = TRUE;
if(data->info.header_size)
/* if headers have been received, this is fine */
@ -298,6 +303,8 @@ static CURLcode cw_download_write(struct Curl_easy *data,
if(!data->req.ignorebody && (nwrite || (type & CLIENTWRITE_EOS))) {
result = Curl_cwriter_write(data, writer->next, type, buf, nwrite);
CURL_TRC_WRITE(data, "download_write body(type=%x, blen=%zu) -> %d",
type, nbytes, result);
if(result)
return result;
}
@ -333,7 +340,7 @@ static CURLcode cw_download_write(struct Curl_easy *data,
}
static const struct Curl_cwtype cw_download = {
"download",
"protocol",
NULL,
Curl_cwriter_def_init,
cw_download_write,
@ -698,9 +705,10 @@ static CURLcode cr_in_read(struct Curl_easy *data,
*peos = ctx->seen_eos;
break;
}
DEBUGF(infof(data, "cr_in_read(len=%zu, total=%"CURL_FORMAT_CURL_OFF_T
", read=%"CURL_FORMAT_CURL_OFF_T") -> %d, %zu, %d",
blen, ctx->total_len, ctx->read_len, CURLE_OK, *pnread, *peos));
CURL_TRC_READ(data, "cr_in_read(len=%zu, total=%"CURL_FORMAT_CURL_OFF_T
", read=%"CURL_FORMAT_CURL_OFF_T") -> %d, nread=%zu, eos=%d",
blen, ctx->total_len, ctx->read_len, CURLE_OK,
*pnread, *peos);
return CURLE_OK;
}
@ -798,7 +806,7 @@ static CURLcode cr_in_rewind(struct Curl_easy *data,
Curl_set_in_callback(data, true);
err = (data->set.seek_func)(data->set.seek_client, 0, SEEK_SET);
Curl_set_in_callback(data, false);
DEBUGF(infof(data, "cr_in, rewind via set.seek_func -> %d", err));
CURL_TRC_READ(data, "cr_in, rewind via set.seek_func -> %d", err);
if(err) {
failf(data, "seek callback returned error %d", (int)err);
return CURLE_SEND_FAIL_REWIND;
@ -811,7 +819,7 @@ static CURLcode cr_in_rewind(struct Curl_easy *data,
err = (data->set.ioctl_func)(data, CURLIOCMD_RESTARTREAD,
data->set.ioctl_client);
Curl_set_in_callback(data, false);
DEBUGF(infof(data, "cr_in, rewind via set.ioctl_func -> %d", (int)err));
CURL_TRC_READ(data, "cr_in, rewind via set.ioctl_func -> %d", (int)err);
if(err) {
failf(data, "ioctl callback returned error %d", (int)err);
return CURLE_SEND_FAIL_REWIND;
@ -823,8 +831,8 @@ static CURLcode cr_in_rewind(struct Curl_easy *data,
ourselves with fseek() */
if(data->state.fread_func == (curl_read_callback)fread) {
int err = fseek(data->state.in, 0, SEEK_SET);
DEBUGF(infof(data, "cr_in, rewind via fseek -> %d(%d)",
(int)err, (int)errno));
CURL_TRC_READ(data, "cr_in, rewind via fseek -> %d(%d)",
(int)err, (int)errno);
if(-1 != err)
/* successful rewind */
return CURLE_OK;
@ -945,7 +953,8 @@ static CURLcode cr_lc_read(struct Curl_easy *data,
ctx->eos = TRUE;
*pnread = nread;
*peos = ctx->eos;
return CURLE_OK;
result = CURLE_OK;
goto out;
}
/* at least one \n needs conversion to '\r\n', place into ctx->buf */
@ -977,6 +986,10 @@ static CURLcode cr_lc_read(struct Curl_easy *data,
ctx->eos = TRUE;
*peos = TRUE;
}
out:
CURL_TRC_READ(data, "cr_lc_read(len=%zu) -> %d, nread=%zu, eos=%d",
blen, result, *pnread, *peos);
return result;
}
@ -1054,12 +1067,16 @@ CURLcode Curl_creader_set_fread(struct Curl_easy *data, curl_off_t len)
result = Curl_creader_create(&r, data, &cr_in, CURL_CR_CLIENT);
if(result)
return result;
goto out;
ctx = r->ctx;
ctx->total_len = len;
cl_reset_reader(data);
return do_init_reader_stack(data, r);
result = do_init_reader_stack(data, r);
out:
CURL_TRC_READ(data, "add fread reader, len=%"CURL_FORMAT_CURL_OFF_T
" -> %d", len, result);
return result;
}
CURLcode Curl_creader_add(struct Curl_easy *data,
@ -1117,6 +1134,8 @@ CURLcode Curl_client_read(struct Curl_easy *data, char *buf, size_t blen,
result = Curl_creader_read(data, data->req.reader_stack, buf, blen,
nread, eos);
CURL_TRC_READ(data, "client_read(len=%zu) -> %d, nread=%zu, eos=%d",
blen, result, *nread, *eos);
return result;
}
@ -1124,8 +1143,10 @@ bool Curl_creader_needs_rewind(struct Curl_easy *data)
{
struct Curl_creader *reader = data->req.reader_stack;
while(reader) {
if(reader->crt->needs_rewind(data, reader))
if(reader->crt->needs_rewind(data, reader)) {
CURL_TRC_READ(data, "client reader needs rewind before next request");
return TRUE;
}
reader = reader->next;
}
return FALSE;
@ -1209,6 +1230,8 @@ static CURLcode cr_buf_read(struct Curl_easy *data,
ctx->index += nread;
*peos = (ctx->index == ctx->blen);
}
CURL_TRC_READ(data, "cr_buf_read(len=%zu) -> 0, nread=%zu, eos=%d",
blen, *pnread, *peos);
return CURLE_OK;
}
@ -1274,14 +1297,17 @@ CURLcode Curl_creader_set_buf(struct Curl_easy *data,
result = Curl_creader_create(&r, data, &cr_buf, CURL_CR_CLIENT);
if(result)
return result;
goto out;
ctx = r->ctx;
ctx->buf = buf;
ctx->blen = blen;
ctx->index = 0;
cl_reset_reader(data);
return do_init_reader_stack(data, r);
result = do_init_reader_stack(data, r);
out:
CURL_TRC_READ(data, "add buf reader, len=%zu -> %d", blen, result);
return result;
}
curl_off_t Curl_creader_total_length(struct Curl_easy *data)

Просмотреть файл

@ -1190,6 +1190,8 @@ CURLcode Curl_xfer_write_resp(struct Curl_easy *data,
data->req.eos_written = TRUE;
data->req.download_done = TRUE;
}
CURL_TRC_WRITE(data, "xfer_write_resp(len=%zu, eos=%d) -> %d",
blen, is_eos, result);
return result;
}

Просмотреть файл

@ -114,23 +114,23 @@ static void ws_dec_info(struct ws_decoder *dec, struct Curl_easy *data,
case 0:
break;
case 1:
infof(data, "WS-DEC: %s [%s%s]", msg,
ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL");
CURL_TRC_WRITE(data, "websocket, decoded %s [%s%s]", msg,
ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL");
break;
default:
if(dec->head_len < dec->head_total) {
infof(data, "WS-DEC: %s [%s%s](%d/%d)", msg,
ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL",
dec->head_len, dec->head_total);
CURL_TRC_WRITE(data, "websocket, decoded %s [%s%s](%d/%d)", msg,
ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL",
dec->head_len, dec->head_total);
}
else {
infof(data, "WS-DEC: %s [%s%s payload=%" CURL_FORMAT_CURL_OFF_T
"/%" CURL_FORMAT_CURL_OFF_T "]",
msg, ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL",
dec->payload_offset, dec->payload_len);
CURL_TRC_WRITE(data, "websocket, decoded %s [%s%s payload=%"
CURL_FORMAT_CURL_OFF_T "/%" CURL_FORMAT_CURL_OFF_T "]",
msg, ws_frame_name_of_op(dec->head[0]),
(dec->head[0] & WSBIT_FIN)? "" : " NON-FINAL",
dec->payload_offset, dec->payload_len);
}
break;
}
@ -277,9 +277,8 @@ static CURLcode ws_dec_pass_payload(struct ws_decoder *dec,
Curl_bufq_skip(inraw, (size_t)nwritten);
dec->payload_offset += (curl_off_t)nwritten;
remain = dec->payload_len - dec->payload_offset;
/* infof(data, "WS-DEC: passed %zd bytes payload, %"
CURL_FORMAT_CURL_OFF_T " remain",
nwritten, remain); */
CURL_TRC_WRITE(data, "websocket, passed %zd bytes payload, %"
CURL_FORMAT_CURL_OFF_T " remain", nwritten, remain);
}
return remain? CURLE_AGAIN : CURLE_OK;
@ -454,10 +453,12 @@ static CURLcode ws_cw_write(struct Curl_easy *data,
pass_ctx.cw_type = type;
result = ws_dec_pass(&ws->dec, data, &ctx->buf,
ws_cw_dec_next, &pass_ctx);
if(result == CURLE_AGAIN)
if(result == CURLE_AGAIN) {
/* insufficient amount of data, keep it for later.
* we pretend to have written all since we have a copy */
CURL_TRC_WRITE(data, "websocket, buffered incomplete frame head");
return CURLE_OK;
}
else if(result) {
infof(data, "WS: decode error %d", (int)result);
return result;