DoH: add trace configuration

- refs #12397 where it is dicussed how to en-/disable verbose output
  of DoH operations
- introducing `struct curl_trc_feat` to track a curl feature for
  tracing
- adding `data->state.feat` optionally pointing to the feature a
  transfer belongs to
- adding trace functions and verbosity checks on features
- using trace feature in DoH code
- documenting `doh` as feature for `--trace-config`

Closes #12411

docs/libcurl/curl_global_trace.md

@@ -91,6 +91,10 @@ In order to find out all components involved in a transfer, run it with "all"
 configured. You can then see all names involved in your libcurl version in the
 trace.
 
+## `doh`
+
+Tracing of DNS-over-HTTP operations to resolve hostnames.
+
 # EXAMPLE
 
 ~~~c

lib/curl_trc.c

@@ -36,6 +36,7 @@
 
 #include "cf-socket.h"
 #include "connect.h"
+#include "doh.h"
 #include "http2.h"
 #include "http_proxy.h"
 #include "cf-h1-proxy.h"
@@ -113,12 +114,14 @@ void Curl_failf(struct Curl_easy *data, const char *fmt, ...)
 void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
 {
   DEBUGASSERT(!strchr(fmt, '\n'));
-  if(data && data->set.verbose) {
+  if(Curl_trc_is_verbose(data)) {
     va_list ap;
-    int len;
+    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, MAXINFO, fmt, ap);
+    len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
     va_end(ap);
     buffer[len++] = '\n';
     buffer[len] = '\0';
@@ -132,13 +135,16 @@ void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
   DEBUGASSERT(cf);
   if(Curl_trc_cf_is_verbose(cf, data)) {
     va_list ap;
-    int len;
+    int len = 0;
     char buffer[MAXINFO + 2];
+    if(data->state.feat)
+      len += msnprintf(buffer + len, MAXINFO - len, "[%s] ",
+                       data->state.feat->name);
     if(cf->sockindex)
-      len = msnprintf(buffer, MAXINFO, "[%s-%d] ",
+      len += msnprintf(buffer + len, MAXINFO - len, "[%s-%d] ",
                       cf->cft->name, cf->sockindex);
     else
-      len = msnprintf(buffer, MAXINFO, "[%s] ", cf->cft->name);
+      len += msnprintf(buffer + len, MAXINFO - len, "[%s] ", cf->cft->name);
     va_start(ap, fmt);
     len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
     va_end(ap);
@@ -148,6 +154,12 @@ void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
   }
 }
 
+static struct curl_trc_feat *trc_feats[] = {
+#ifndef CURL_DISABLE_DOH
+  &Curl_doh_trc,
+#endif
+  NULL,
+};
 
 static struct Curl_cftype *cf_types[] = {
   &Curl_cft_tcp,
@@ -219,6 +231,15 @@ CURLcode Curl_trc_opt(const char *config)
         break;
       }
     }
+    for(i = 0; trc_feats[i]; ++i) {
+      if(strcasecompare(token, "all")) {
+        trc_feats[i]->log_level = lvl;
+      }
+      else if(strcasecompare(token, trc_feats[i]->name)) {
+        trc_feats[i]->log_level = lvl;
+        break;
+      }
+    }
     token = strtok_r(NULL, ", ", &tok_buf);
   }
   free(tmp);

lib/curl_trc.h

@@ -86,10 +86,21 @@ void Curl_failf(struct Curl_easy *data,
 #ifndef CURL_DISABLE_VERBOSE_STRINGS
 /* informational messages enabled */
 
-#define Curl_trc_is_verbose(data)    ((data) && (data)->set.verbose)
+struct curl_trc_feat {
+  const char *name;
+  int log_level;
+};
+
+#define Curl_trc_is_verbose(data) \
+            ((data) && (data)->set.verbose && \
+            (!(data)->state.feat || \
+             ((data)->state.feat->log_level >= CURL_LOG_LVL_INFO)))
 #define Curl_trc_cf_is_verbose(cf, data) \
-                            ((data) && (data)->set.verbose && \
-                            (cf) && (cf)->cft->log_level >= CURL_LOG_LVL_INFO)
+            (Curl_trc_is_verbose(data) && \
+            (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)
 
 /**
  * Output an informational message when transfer's verbose logging is enabled.
@@ -109,6 +120,7 @@ void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
 
 #define Curl_trc_is_verbose(d)        ((void)(d), FALSE)
 #define Curl_trc_cf_is_verbose(x,y)   ((void)(x), (void)(y), FALSE)
+#define Curl_trc_ft_is_verbose(x,y)   ((void)(x), (void)(y), FALSE)
 
 static void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
 {

lib/doh.c

@@ -69,7 +69,12 @@ static const char *doh_strerror(DOHcode code)
     return errors[code];
   return "bad error code";
 }
-#endif
+
+struct curl_trc_feat Curl_doh_trc = {
+  "DoH",
+  CURL_LOG_LVL_NONE,
+};
+#endif /* !CURL_DISABLE_VERBOSE_STRINGS */
 
 /* @unittest 1655
  */
@@ -189,9 +194,9 @@ static int doh_done(struct Curl_easy *doh, CURLcode result)
   struct dohdata *dohp = data->req.doh;
   /* so one of the DoH request done for the 'data' transfer is now complete! */
   dohp->pending--;
-  infof(data, "a DoH request is completed, %u to go", dohp->pending);
+  infof(doh, "a DoH request is completed, %u to go", dohp->pending);
   if(result)
-    infof(data, "DoH request %s", curl_easy_strerror(result));
+    infof(doh, "DoH request %s", curl_easy_strerror(result));
 
   if(!dohp->pending) {
     /* DoH completed */
@@ -242,6 +247,9 @@ static CURLcode dohprobe(struct Curl_easy *data,
        the gcc typecheck helpers */
     struct dynbuf *resp = &p->serverdoh;
     doh->state.internal = true;
+#ifndef CURL_DISABLE_VERBOSE_STRINGS
+    doh->state.feat = &Curl_doh_trc;
+#endif
     ERROR_CHECK_SETOPT(CURLOPT_URL, url);
     ERROR_CHECK_SETOPT(CURLOPT_DEFAULT_PROTOCOL, "https");
     ERROR_CHECK_SETOPT(CURLOPT_WRITEFUNCTION, doh_write_cb);
@@ -264,7 +272,7 @@ static CURLcode dohprobe(struct Curl_easy *data,
     ERROR_CHECK_SETOPT(CURLOPT_SHARE, data->share);
     if(data->set.err && data->set.err != stderr)
       ERROR_CHECK_SETOPT(CURLOPT_STDERR, data->set.err);
-    if(data->set.verbose)
+    if(Curl_trc_ft_is_verbose(data, &Curl_doh_trc))
       ERROR_CHECK_SETOPT(CURLOPT_VERBOSE, 1L);
     if(data->set.no_signal)
       ERROR_CHECK_SETOPT(CURLOPT_NOSIGNAL, 1L);
@@ -741,11 +749,11 @@ static void showdoh(struct Curl_easy *data,
                     const struct dohentry *d)
 {
   int i;
-  infof(data, "TTL: %u seconds", d->ttl);
+  infof(data, "[DoH] TTL: %u seconds", d->ttl);
   for(i = 0; i < d->numaddr; i++) {
     const struct dohaddr *a = &d->addr[i];
     if(a->type == DNS_TYPE_A) {
-      infof(data, "DoH A: %u.%u.%u.%u",
+      infof(data, "[DoH] A: %u.%u.%u.%u",
             a->ip.v4[0], a->ip.v4[1],
             a->ip.v4[2], a->ip.v4[3]);
     }
@@ -754,9 +762,9 @@ static void showdoh(struct Curl_easy *data,
       char buffer[128];
       char *ptr;
       size_t len;
-      msnprintf(buffer, 128, "DoH AAAA: ");
-      ptr = &buffer[10];
-      len = 118;
+      len = msnprintf(buffer, 128, "[DoH] AAAA: ");
+      ptr = &buffer[len];
+      len = sizeof(buffer) - len;
       for(j = 0; j < 16; j += 2) {
         size_t l;
         msnprintf(ptr, len, "%s%02x%02x", j?":":"", d->addr[i].ip.v6[j],
@@ -950,8 +958,11 @@ CURLcode Curl_doh_is_resolved(struct Curl_easy *data,
       struct Curl_dns_entry *dns;
       struct Curl_addrinfo *ai;
 
-      infof(data, "DoH Host name: %s", dohp->host);
-      showdoh(data, &de);
+
+      if(Curl_trc_ft_is_verbose(data, &Curl_doh_trc)) {
+        infof(data, "[DoH] Host name: %s", dohp->host);
+        showdoh(data, &de);
+      }
 
       result = doh2ai(&de, dohp->host, dohp->port, &ai);
       if(result) {

lib/doh.h

@@ -120,6 +120,8 @@ void de_init(struct dohentry *d);
 void de_cleanup(struct dohentry *d);
 #endif
 
+extern struct curl_trc_feat Curl_doh_trc;
+
 #else /* if DoH is disabled */
 #define Curl_doh(a,b,c,d) NULL
 #define Curl_doh_is_resolved(x,y) CURLE_COULDNT_RESOLVE_HOST

lib/urldata.h

@@ -53,6 +53,8 @@
 #define PORT_GOPHER 70
 #define PORT_MQTT 1883
 
+struct curl_trc_featt;
+
 #ifdef USE_WEBSOCKETS
 /* CURLPROTO_GOPHERS (29) is the highest publicly used protocol bit number,
  * the rest are internal information. If we use higher bits we only do this on
@@ -1446,6 +1448,10 @@ struct UrlState {
   CURLcode hresult; /* used to pass return codes back from hyper callbacks */
 #endif
 
+#ifndef CURL_DISABLE_VERBOSE_STRINGS
+  struct curl_trc_feat *feat; /* opt. trace feature transfer is part of */
+#endif
+
   /* Dynamically allocated strings, MUST be freed before this struct is
      killed. */
   struct dynamically_allocated_data {