From 0b28ece657b22733467ce5efc3df260f0d509ff5 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Thu, 28 Mar 2024 14:12:54 +0100 Subject: [PATCH] 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 --- docs/libcurl/curl_global_trace.md | 10 ++++- lib/curl_trc.c | 58 +++++++++++++++++++++---- lib/curl_trc.h | 43 +++++++++++++++++-- lib/cw-out.c | 4 ++ lib/headers.c | 2 + lib/http_chunks.c | 17 +++++++- lib/sendf.c | 70 +++++++++++++++++++++---------- lib/transfer.c | 2 + lib/ws.c | 33 ++++++++------- 9 files changed, 188 insertions(+), 51 deletions(-) diff --git a/docs/libcurl/curl_global_trace.md b/docs/libcurl/curl_global_trace.md index a34e1c50b2..1485af7f67 100644 --- a/docs/libcurl/curl_global_trace.md +++ b/docs/libcurl/curl_global_trace.md @@ -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 diff --git a/lib/curl_trc.c b/lib/curl_trc.c index fa6ad229bc..691aefc377 100644 --- a/lib/curl_trc.c +++ b/lib/curl_trc.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 diff --git a/lib/curl_trc.h b/lib/curl_trc.h index 92b0533c03..1440f49623 100644 --- a/lib/curl_trc.h +++ b/lib/curl_trc.h @@ -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 */ diff --git a/lib/cw-out.c b/lib/cw-out.c index c168837817..07172b6151 100644 --- a/lib/cw-out.c +++ b/lib/cw-out.c @@ -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) { diff --git a/lib/headers.c b/lib/headers.c index 0c53dec684..ea8a7aa98d 100644 --- a/lib/headers.c +++ b/lib/headers.c @@ -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; } diff --git a/lib/http_chunks.c b/lib/http_chunks.c index ac9d72470b..48e7e462ba 100644 --- a/lib/http_chunks.c +++ b/lib/http_chunks.c @@ -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; } diff --git a/lib/sendf.c b/lib/sendf.c index 790195719e..7e099a2d15 100644 --- a/lib/sendf.c +++ b/lib/sendf.c @@ -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) diff --git a/lib/transfer.c b/lib/transfer.c index ed1d69fa9d..ac4710ef5d 100644 --- a/lib/transfer.c +++ b/lib/transfer.c @@ -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; } diff --git a/lib/ws.c b/lib/ws.c index 5bc5eccc48..907f64bac3 100644 --- a/lib/ws.c +++ b/lib/ws.c @@ -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; -- 2.47.3