quic: improve connect error message, debugging info, fix false connect report

- ECONNECTREFUSED has not its own fail message in quic filters
- Debug logging in connect eyballing improved
- Fix bug in ngtcp2/quiche that could lead to false success reporting.

Reported-by: Divy Le Ray

Fixes #10245
Closes #10248

5 files changed, 64 insertions, 38 deletions

diff --git a/lib/cf-socket.c b/lib/cf-socket.c
index df292d7b1..356b3657a 100644
--- a/lib/cf-socket.c
+++ b/lib/cf-socket.c
@@ -1555,10 +1555,14 @@ CURLcode Curl_cf_socket_peek(struct Curl_cfilter *cf,
   if(Curl_cf_is_socket(cf) && cf->ctx) {
     struct cf_socket_ctx *ctx = cf->ctx;
 
-    *psock = ctx->sock;
-    *paddr = &ctx->addr;
-    *premote_ip_str = ctx->r_ip;
-    *premote_port = ctx->r_port;
+    if(psock)
+      *psock = ctx->sock;
+    if(paddr)
+      *paddr = &ctx->addr;
+    if(premote_ip_str)
+      *premote_ip_str = ctx->r_ip;
+    if(premote_port)
+      *premote_port = ctx->r_port;
     return CURLE_OK;
   }
   return CURLE_FAILED_INIT;
diff --git a/lib/cf-socket.h b/lib/cf-socket.h
index 8e30d2862..9f1b01d4b 100644
--- a/lib/cf-socket.h
+++ b/lib/cf-socket.h
@@ -166,6 +166,10 @@ bool Curl_cf_is_socket(struct Curl_cfilter *cf);
 /**
  * Peek at the socket and remote ip/port the socket filter is using.
  * The filter owns all returned values.
+ * @param psock             pointer to hold socket descriptor or NULL
+ * @param paddr             pointer to hold addr reference or NULL
+ * @param premote_ip_str    pointer to hold remote addr as string or NULL
+ * @param premote_port      pointer to hold remote port number or NULL
  * Returns error if the filter is of invalid type.
  */
 CURLcode Curl_cf_socket_peek(struct Curl_cfilter *cf,
diff --git a/lib/connect.c b/lib/connect.c
index ce9a028bc..dfcf51401 100644
--- a/lib/connect.c
+++ b/lib/connect.c
@@ -352,6 +352,7 @@ void Curl_conncontrol(struct connectdata *conn,
  * provided method `cf_create` and running setup/connect on it.
  */
 struct eyeballer {
+  const char *name;
   const struct Curl_addrinfo *addr;  /* List of addresses to try, not owned */
   int ai_family;                     /* matching address family only */
   cf_ip_connect_create *cf_create;   /* for creating cf */
@@ -379,7 +380,7 @@ struct cf_he_ctx {
   cf_ip_connect_create *cf_create;
   const struct Curl_dns_entry *remotehost;
   cf_connect_state state;
-  struct eyeballer *baller[5];
+  struct eyeballer *baller[2];
   struct eyeballer *winner;
   struct curltime started;
 };
@@ -400,6 +401,8 @@ static CURLcode eyeballer_new(struct eyeballer **pballer,
   if(!baller)
     return CURLE_OUT_OF_MEMORY;
 
+  baller->name = ((ai_family == AF_INET)? "ipv4" : (
+                  (ai_family == AF_INET6)? "ipv6" : "ip"));
   baller->cf_create = cf_create;
   baller->addr = addr;
   baller->ai_family = ai_family;
@@ -458,8 +461,6 @@ static void baller_initiate(struct Curl_cfilter *cf,
   if(result)
     goto out;
 
-  CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer created %s"),
-                  baller->cf->cft->name));
   /* the new filter might have sub-filters */
   for(wcf = baller->cf; wcf; wcf = wcf->next) {
     wcf->conn = cf->conn;
@@ -472,7 +473,7 @@ static void baller_initiate(struct Curl_cfilter *cf,
 
 out:
   if(result) {
-    CF_DEBUGF(infof(data, "eyeballer failed"));
+    CF_DEBUGF(infof(data, "eyeballer[%s] failed", baller->name));
     baller_close(baller, data);
   }
   if(cf_prev)
@@ -546,8 +547,8 @@ static CURLcode baller_connect(struct Curl_cfilter *cf,
         baller->is_done = TRUE;
       }
       else if(Curl_timediff(*now, ctx->started) >= baller->timeoutms) {
-        infof(data, "After %" CURL_FORMAT_TIMEDIFF_T
-              "ms connect time, move on!", baller->timeoutms);
+        infof(data, "%s connect timeout after %" CURL_FORMAT_TIMEDIFF_T
+              "ms, move on!", baller->name, baller->timeoutms);
 #if defined(ETIMEDOUT)
         baller->error = ETIMEDOUT;
 #endif
@@ -592,13 +593,12 @@ evaluate:
       continue;
 
     if(!baller->has_started) {
-      CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] not started yet"), i));
       ++not_started;
       continue;
     }
     baller->result = baller_connect(cf, data, baller, &now, connected);
-    CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] connect -> %d, "
-              "connected=%d"), i, baller->result, *connected));
+    CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] connect -> %d, "
+              "connected=%d"), baller->name, baller->result, *connected));
 
     if(!baller->result) {
       if(*connected) {
@@ -619,11 +619,14 @@ evaluate:
       }
       allow = Curl_timeleft(data, &now, TRUE);
       baller->timeoutms = baller->addr->ai_next == NULL ? allow : allow / 2;
-      CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] starting"), i));
       baller_start_next(cf, data, baller);
-      if(!baller->is_done) {
+      if(baller->is_done) {
+        CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] done"), baller->name));
+      }
+      else {
         /* next attempt was started */
-        CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] started"), i));
+        CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] trying next"),
+                        baller->name));
         ++ongoing;
       }
     }
@@ -655,10 +658,14 @@ evaluate:
        * its start delay_ms have expired */
       if((baller->primary && baller->primary->is_done) ||
           Curl_timediff(now, ctx->started) >= baller->delay_ms) {
-        CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] starting"), i));
         baller_start(cf, data, baller);
-        if(!baller->is_done) {
-          CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] has started"), i));
+        if(baller->is_done) {
+          CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] done"),
+                          baller->name));
+        }
+        else {
+          CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] starting"),
+                          baller->name));
           ++ongoing;
           ++added;
         }
@@ -679,8 +686,9 @@ evaluate:
   result = CURLE_COULDNT_CONNECT;
   for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) {
     struct eyeballer *baller = ctx->baller[i];
-    CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] assess started=%d, "
-              "result=%d"), i, baller->has_started, baller->result));
+    CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] assess started=%d, "
+              "result=%d"),
+              baller->name, baller->has_started, baller->result));
     if(baller && baller->has_started && baller->result) {
       result = baller->result;
       break;
@@ -887,6 +895,7 @@ static CURLcode cf_he_connect(struct Curl_cfilter *cf,
       if(!result && *done) {
         DEBUGASSERT(ctx->winner);
         DEBUGASSERT(ctx->winner->cf);
+        DEBUGASSERT(ctx->winner->cf->connected);
         /* we have a winner. Install and activate it.
          * close/free all others. */
         ctx->state = SCFST_DONE;
@@ -953,7 +962,7 @@ static void cf_he_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
 
   CF_DEBUGF(infof(data, CFMSG(cf, "destroy")));
   if(ctx) {
-    cf_he_close(cf, data);
+    cf_he_ctx_clear(cf, data);
   }
   /* release any resources held in state */
   Curl_safefree(ctx);
@@ -1189,11 +1198,8 @@ static void cf_setup_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
 {
   struct cf_setup_ctx *ctx = cf->ctx;
 
+  (void)data;
   CF_DEBUGF(infof(data, CFMSG(cf, "destroy")));
-  if(ctx) {
-    cf_setup_close(cf, data);
-  }
-  /* release any resources held in state */
   Curl_safefree(ctx);
 }
 
diff --git a/lib/vquic/curl_ngtcp2.c b/lib/vquic/curl_ngtcp2.c
index 09cae498e..5ee5ad86b 100644
--- a/lib/vquic/curl_ngtcp2.c
+++ b/lib/vquic/curl_ngtcp2.c
@@ -1169,6 +1169,10 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
   struct cf_ngtcp2_ctx *ctx = cf->ctx;
   struct HTTP *stream = data->req.p.http;
 
+  DEBUGASSERT(cf->connected);
+  DEBUGASSERT(ctx);
+  DEBUGASSERT(ctx->qconn);
+  DEBUGASSERT(ctx->h3conn);
   *err = CURLE_OK;
 
   if(!stream->memlen) {
@@ -1442,6 +1446,10 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
   ssize_t sent = 0;
   struct HTTP *stream = data->req.p.http;
 
+  DEBUGASSERT(cf->connected);
+  DEBUGASSERT(ctx);
+  DEBUGASSERT(ctx->qconn);
+  DEBUGASSERT(ctx->h3conn);
   *err = CURLE_OK;
 
   if(stream->closed) {
@@ -1576,8 +1584,16 @@ static CURLcode cf_process_ingress(struct Curl_cfilter *cf,
     if(recvd == -1) {
       if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK)
         break;
-
-      failf(data, "ngtcp2: recvfrom() unexpectedly returned %zd", recvd);
+      if(SOCKERRNO == ECONNREFUSED) {
+        const char *r_ip;
+        int r_port;
+        Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
+        failf(data, "ngtcp2: connection to %s port %u refused",
+              r_ip, r_port);
+        return CURLE_COULDNT_CONNECT;
+      }
+      failf(data, "ngtcp2: recvfrom() unexpectedly returned %zd (errno=%d)",
+                  recvd, SOCKERRNO);
       return CURLE_RECV_ERROR;
     }
 
@@ -2273,13 +2289,13 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
       return result;
   }
 
+  *done = FALSE;
   if(!ctx->qconn) {
     result = cf_connect_start(cf, data);
     if(result)
       goto out;
   }
 
-  *done = FALSE;
   result = cf_process_ingress(cf, data);
   if(result)
     goto out;
@@ -2301,12 +2317,10 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
 out:
 #ifndef CURL_DISABLE_VERBOSE_STRINGS
   if(result && result != CURLE_AGAIN) {
-    const struct Curl_sockaddr_ex *sockaddr;
     const char *r_ip;
     int r_port;
 
-    result = Curl_cf_socket_peek(cf->next, &ctx->sockfd,
-                                 &sockaddr, &r_ip, &r_port);
+    Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
     infof(data, "connect to %s port %u failed: %s",
           r_ip, r_port, curl_easy_strerror(result));
   }
@@ -2364,7 +2378,7 @@ CURLcode Curl_cf_ngtcp2_create(struct Curl_cfilter **pcf,
                                const struct Curl_addrinfo *ai)
 {
   struct cf_ngtcp2_ctx *ctx = NULL;
-  struct Curl_cfilter *cf = NULL, *udp_cf;
+  struct Curl_cfilter *cf = NULL, *udp_cf = NULL;
   CURLcode result;
 
   (void)data;
diff --git a/lib/vquic/curl_quiche.c b/lib/vquic/curl_quiche.c
index 48ea4399a..8863fe0a3 100644
--- a/lib/vquic/curl_quiche.c
+++ b/lib/vquic/curl_quiche.c
@@ -961,13 +961,13 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
       return result;
   }
 
+  *done = FALSE;
   if(!ctx->qconn) {
     result = cf_connect_start(cf, data);
     if(result)
       goto out;
   }
 
-  *done = FALSE;
   result = cf_process_ingress(cf, data);
   if(result)
     goto out;
@@ -990,12 +990,10 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
 out:
 #ifndef CURL_DISABLE_VERBOSE_STRINGS
   if(result && result != CURLE_AGAIN) {
-    const struct Curl_sockaddr_ex *sockaddr;
     const char *r_ip;
     int r_port;
 
-    result = Curl_cf_socket_peek(cf->next, &ctx->sockfd,
-                                 &sockaddr, &r_ip, &r_port);
+    Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
     infof(data, "connect to %s port %u failed: %s",
           r_ip, r_port, curl_easy_strerror(result));
   }
@@ -1094,7 +1092,7 @@ CURLcode Curl_cf_quiche_create(struct Curl_cfilter **pcf,
                                const struct Curl_addrinfo *ai)
 {
   struct cf_quiche_ctx *ctx = NULL;
-  struct Curl_cfilter *cf = NULL, *udp_cf;
+  struct Curl_cfilter *cf = NULL, *udp_cf = NULL;
   CURLcode result;
 
   (void)data;