tool: add curl command line option `--trace-ids`

- added and documented --trace-ids to prepend (after the timestamp)
  the transfer and connection identifiers to each verbose log line
- format is [n-m] with `n` being the transfer id and `m` being the
  connection id. In case there is not valid connection id, print 'x'.
- Log calls with a handle that has no transfer id yet, are written
  without any ids.

Closes #11185

docs/TheArtOfHttpScripting.md

@@ -64,6 +64,17 @@
 
     curl --trace-ascii d.txt --trace-time http://example.com/
 
+## See which Transfer
+
+ When doing parallel transfers, it is relevant to see which transfer is
+ doing what. When response headers are received (and logged) you need to
+ know which transfer these are for.
+ [`--trace-ids`](https://curl.se/docs/manpage.html#--trace-ids) option
+ is what you need. It will prepend the transfer and connection identifier
+ to each trace output line:
+
+    curl --trace-ascii d.txt --trace-ids http://example.com/
+
 ## See the Response
 
  By default curl sends the response to stdout. You need to redirect it

docs/cmdline-opts/Makefile.inc

@@ -265,6 +265,7 @@ DPAGES = \
   tlsv1.d \
   tr-encoding.d \
   trace-ascii.d \
+  trace-ids.d \
   trace-time.d \
   trace.d \
   unix-socket.d \

docs/cmdline-opts/trace-ids.d

@@ -0,0 +1,12 @@
+c: Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
+SPDX-License-Identifier: curl
+Long: trace-ids
+Help: Add transfer and connection identifiers to trace/verbose output
+Added: 8.2.0
+Category: verbose
+Example: --trace-ids --trace-ascii output $URL
+See-also: trace verbose
+Multi: boolean
+Scope: global
+---
+Prepends the transfer and connection identifiers to each trace or verbose line that curl displays.

docs/cmdline-opts/trace.d

@@ -7,7 +7,7 @@ Mutexed: verbose trace-ascii
 Category: verbose
 Example: --trace log.txt $URL
 Added: 7.9.7
-See-also: trace-ascii trace-time
+See-also: trace-ascii trace-ids trace-time
 Multi: single
 Scope: global
 ---

docs/options-in-versions

@@ -252,6 +252,7 @@
 --tr-encoding                        7.21.6
 --trace                              7.9.7
 --trace-ascii                        7.9.7
+--trace-ids                          8.2.0
 --trace-time                         7.14.0
 --unix-socket                        7.40.0
 --upload-file (-T)                   4.0

src/tool_cb_dbg.c

@@ -34,7 +34,7 @@
 
 #include "memdebug.h" /* keep this as LAST include */
 
-static void dump(const char *timebuf, const char *text,
+static void dump(const char *timebuf, const char *idsbuf, const char *text,
                  FILE *stream, const unsigned char *ptr, size_t size,
                  trace tracetype, curl_infotype infotype);
 
@@ -67,7 +67,8 @@ static const char *hms_for_sec(time_t tv_sec)
   return hms_buf;
 }
 
-static void log_line_start(FILE *log, const char *intro, curl_infotype type)
+static void log_line_start(FILE *log, const char *timebuf,
+                           const char *idsbuf, curl_infotype type)
 {
   /*
    * This is the trace look that is similar to what libcurl makes on its
@@ -76,12 +77,15 @@ static void log_line_start(FILE *log, const char *intro, curl_infotype type)
   static const char * const s_infotype[] = {
     "* ", "< ", "> ", "{ ", "} ", "{ ", "} "
   };
-  if(intro && *intro)
-    fprintf(log, "%s%s", intro, s_infotype[type]);
+  if((timebuf && *timebuf) || (idsbuf && *idsbuf))
+    fprintf(log, "%s%s%s", timebuf, idsbuf, s_infotype[type]);
   else
     fputs(s_infotype[type], log);
 }
 
+#define TRC_IDS_FORMAT_IDS_1  "[%" CURL_FORMAT_CURL_OFF_T "-x] "
+#define TRC_IDS_FORMAT_IDS_2  "[%" CURL_FORMAT_CURL_OFF_T "-%" \
+                                   CURL_FORMAT_CURL_OFF_T "] "
 /*
 ** callback for CURLOPT_DEBUGFUNCTION
 */
@@ -95,6 +99,13 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
   const char *text;
   struct timeval tv;
   char timebuf[20];
+  /* largest signed 64bit is: 9,223,372,036,854,775,807
+   * max length in decimal: 1 + (6*3) = 19
+   * formatted via TRC_IDS_FORMAT_IDS_2 this becomes 2 + 19 + 1 + 19 + 2 = 43
+   * negative xfer-id are not printed, negative conn-ids use TRC_IDS_FORMAT_1
+   */
+  char idsbuf[60];
+  curl_off_t xfer_id, conn_id;
 
   (void)handle; /* not used */
 
@@ -106,6 +117,20 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
   else
     timebuf[0] = 0;
 
+  if(handle && config->traceids &&
+     !curl_easy_getinfo(handle, CURLINFO_XFER_ID, &xfer_id) && xfer_id >= 0) {
+    if(!curl_easy_getinfo(handle, CURLINFO_CONN_ID, &conn_id) &&
+        conn_id >= 0) {
+      msnprintf(idsbuf, sizeof(idsbuf), TRC_IDS_FORMAT_IDS_2,
+                xfer_id, conn_id);
+    }
+    else {
+      msnprintf(idsbuf, sizeof(idsbuf), TRC_IDS_FORMAT_IDS_1, xfer_id);
+    }
+  }
+  else
+    idsbuf[0] = 0;
+
   if(!config->trace_stream) {
     /* open for append */
     if(!strcmp("-", config->trace_dump))
@@ -139,7 +164,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
         for(i = 0; i < size - 1; i++) {
           if(data[i] == '\n') { /* LF */
             if(!newl) {
-              log_line_start(output, timebuf, type);
+              log_line_start(output, timebuf, idsbuf, type);
             }
             (void)fwrite(data + st, i - st + 1, 1, output);
             st = i + 1;
@@ -147,7 +172,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
           }
         }
         if(!newl)
-          log_line_start(output, timebuf, type);
+          log_line_start(output, timebuf, idsbuf, type);
         (void)fwrite(data + st, i - st + 1, 1, output);
       }
       newl = (size && (data[size - 1] != '\n')) ? TRUE : FALSE;
@@ -156,7 +181,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
     case CURLINFO_TEXT:
     case CURLINFO_HEADER_IN:
       if(!newl)
-        log_line_start(output, timebuf, type);
+        log_line_start(output, timebuf, idsbuf, type);
       (void)fwrite(data, size, 1, output);
       newl = (size && (data[size - 1] != '\n')) ? TRUE : FALSE;
       traced_data = FALSE;
@@ -172,7 +197,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
            function */
         if(!config->isatty || ((output != stderr) && (output != stdout))) {
           if(!newl)
-            log_line_start(output, timebuf, type);
+            log_line_start(output, timebuf, idsbuf, type);
           fprintf(output, "[%zu bytes data]\n", size);
           newl = FALSE;
           traced_data = TRUE;
@@ -190,7 +215,7 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
 
   switch(type) {
   case CURLINFO_TEXT:
-    fprintf(output, "%s== Info: %.*s", timebuf, (int)size, data);
+    fprintf(output, "%s%s== Info: %.*s", timebuf, idsbuf, (int)size, data);
     /* FALLTHROUGH */
   default: /* in case a new one is introduced to shock us */
     return 0;
@@ -215,12 +240,12 @@ int tool_debug_cb(CURL *handle, curl_infotype type,
     break;
   }
 
-  dump(timebuf, text, output, (unsigned char *) data, size, config->tracetype,
-       type);
+  dump(timebuf, idsbuf, text, output, (unsigned char *) data, size,
+       config->tracetype, type);
   return 0;
 }
 
-static void dump(const char *timebuf, const char *text,
+static void dump(const char *timebuf, const char *idsbuf, const char *text,
                  FILE *stream, const unsigned char *ptr, size_t size,
                  trace tracetype, curl_infotype infotype)
 {
@@ -233,7 +258,8 @@ static void dump(const char *timebuf, const char *text,
     /* without the hex output, we can fit more on screen */
     width = 0x40;
 
-  fprintf(stream, "%s%s, %zu bytes (0x%zx)\n", timebuf, text, size, size);
+  fprintf(stream, "%s%s%s, %zu bytes (0x%zx)\n", timebuf, idsbuf,
+          text, size, size);
 
   for(i = 0; i < size; i += width) {
 

src/tool_cfgable.h

@@ -308,6 +308,7 @@ struct GlobalConfig {
   bool trace_fopened;
   trace tracetype;
   bool tracetime;                 /* include timestamp? */
+  bool traceids;                  /* include xfer-/conn-id? */
   int progressmode;               /* CURL_PROGRESS_BAR / CURL_PROGRESS_STATS */
   char *libcurl;                  /* Output libcurl code to this file name */
   bool fail_early;                /* exit on first transfer error */

src/tool_getparam.c

@@ -205,6 +205,7 @@ static const struct LongShort aliases[]= {
   {"$Z", "compressed-ssh",           ARG_BOOL},
   {"$~", "happy-eyeballs-timeout-ms", ARG_STRING},
   {"$!", "retry-all-errors",         ARG_BOOL},
+  {"$%", "trace-ids",                ARG_BOOL},
   {"0",   "http1.0",                 ARG_NONE},
   {"01",  "http1.1",                 ARG_NONE},
   {"02",  "http2",                   ARG_NONE},
@@ -1407,6 +1408,9 @@ ParameterError getparameter(const char *flag, /* f or -long-flag */
           return err;
         /* 0 is a valid value for this timeout */
         break;
+      case '%': /* --trace-ids */
+        global->traceids = toggle;
+        break;
       }
       break;
     case '#':

src/tool_listhelp.c

@@ -759,6 +759,9 @@ const struct helptxt helptext[] = {
   {"    --trace-ascii <file>",
    "Like --trace, but without hex output",
    CURLHELP_VERBOSE},
+  {"    --trace-ids",
+   "Add transfer/connection identifiers to trace/verbose output",
+   CURLHELP_VERBOSE},
   {"    --trace-time",
    "Add time stamps to trace/verbose output",
    CURLHELP_VERBOSE},