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

diff --git a/docs/libcurl/curl_global_trace.md b/docs/libcurl/curl_global_trace.md
index a34e1c50b2c36bee6ea1f5ae3a049c6a66459e42..1485af7f6737e5e901a88ab5222630b6552e1238 100644 (file)
--- 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 fa6ad229bcb79db75c674be341f3b8e6bec9bf6a..691aefc3777825d3beb248eb385a511fa50f2f19 100644 (file)
--- 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 92b0533c03bcb16723a24010261d97f1f575ef84..1440f496238844c7f1ee13d80fa3e588c20327a8 100644 (file)
--- 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 c1688378179386d9ce5d69ed603dae494ee794c8..07172b6151fd7acb2af49fe221930079ce650199 100644 (file)
--- 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 0c53dec6840a6287c389e9621fb8f0f276c3649d..ea8a7aa98db514878e0e9f5477dbd2ed05de2a0a 100644 (file)
--- 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 ac9d72470b97ae7106eb55a96a5a3aa1179862c6..48e7e462bad32a822da6a4fc817f43ab92411e7c 100644 (file)
--- 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 790195719eac7390cc8de624f78ddaf376971fee..7e099a2d158d7056ed24ae89ca30ed5973cca7d1 100644 (file)
--- 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 ed1d69fa9da184383057eec8ded0ab7ee70edada..ac4710ef5d3ca41f95de34120ec7503422c2233e 100644 (file)
--- 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 5bc5eccc48b317d7b931434ef37aef06ca254e38..907f64bac3f5c8050ed0e7a5f3ffdce14fc6957c 100644 (file)
--- 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;