ftp: add tracing support

- add `Curl_trc_feat_ftp` for tracing via trace config
- add macro CURL_TRC_FTP(data, fmt, ...)
- replace DEBUGF(infof()) statements in ftp.c by CURL_TRC_FTP()
- always trace FTP connection state

Closes #13580

docs/libcurl/curl_global_trace.md

@@ -74,6 +74,10 @@ Tracing of TCP socket handling: connect, sends, receives.
 
 Tracing of SSL/TLS operations, whichever SSL backend is used in your build.
 
+## `ftp`
+
+Tracing of FTP operations when this protocol is enabled in your build.
+
 ## `http/2`
 
 Details about HTTP/2 handling: frames, events, I/O, etc.

lib/curl_trc.c

@@ -194,9 +194,30 @@ void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...)
   }
 }
 
+#ifndef CURL_DISABLE_FTP
+struct curl_trc_feat Curl_trc_feat_ftp = {
+  "FTP",
+  CURL_LOG_LVL_NONE,
+};
+
+void Curl_trc_ftp(struct Curl_easy *data, const char *fmt, ...)
+{
+  DEBUGASSERT(!strchr(fmt, '\n'));
+  if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_ftp)) {
+    va_list ap;
+    va_start(ap, fmt);
+    trc_infof(data, &Curl_trc_feat_ftp, fmt, ap);
+    va_end(ap);
+  }
+}
+#endif /* !CURL_DISABLE_FTP */
+
 static struct curl_trc_feat *trc_feats[] = {
   &Curl_trc_feat_read,
   &Curl_trc_feat_write,
+#ifndef CURL_DISABLE_FTP
+  &Curl_trc_feat_ftp,
+#endif
 #ifndef CURL_DISABLE_DOH
   &Curl_doh_trc,
 #endif

lib/curl_trc.h

@@ -84,13 +84,25 @@ void Curl_failf(struct Curl_easy *data,
   do { if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_read)) \
          Curl_trc_read(data, __VA_ARGS__); } while(0)
 
-#else
+#ifndef CURL_DISABLE_FTP
+#define CURL_TRC_FTP(data, ...) \
+  do { if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_ftp)) \
+         Curl_trc_ftp(data, __VA_ARGS__); } while(0)
+#endif /* !CURL_DISABLE_FTP */
+
+#else /* CURL_HAVE_C99 */
+
 #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
+
+#ifndef CURL_DISABLE_FTP
+#define CURL_TRC_FTP   Curl_trc_ftp
 #endif
 
+#endif /* !CURL_HAVE_C99 */
+
 #ifndef CURL_DISABLE_VERBOSE_STRINGS
 /* informational messages enabled */
 
@@ -131,8 +143,11 @@ void Curl_trc_write(struct Curl_easy *data,
 void Curl_trc_read(struct Curl_easy *data,
                    const char *fmt, ...) CURL_PRINTF(2, 3);
 
-
+#ifndef CURL_DISABLE_FTP
-
+extern struct curl_trc_feat Curl_trc_feat_ftp;
+void Curl_trc_ftp(struct Curl_easy *data,
+                  const char *fmt, ...) CURL_PRINTF(2, 3);
+#endif
 
 
 #else /* defined(CURL_DISABLE_VERBOSE_STRINGS) */
@@ -173,6 +188,13 @@ static void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...)
   (void)data; (void)fmt;
 }
 
+#ifndef CURL_DISABLE_FTP
+static void Curl_trc_ftp(struct Curl_easy *data, const char *fmt, ...)
+{
+  (void)data; (void)fmt;
+}
+#endif
+
 #endif /* !defined(CURL_DISABLE_VERBOSE_STRINGS) */
 
 #endif /* HEADER_CURL_TRC_H */

lib/ftp.c

@@ -95,19 +95,87 @@
 
 #ifdef CURL_DISABLE_VERBOSE_STRINGS
 #define ftp_pasv_verbose(a,b,c,d)  Curl_nop_stmt
+#define FTP_CSTATE(c)   ""
+#define FTP_DSTATE(d)   ""
+#else /* CURL_DISABLE_VERBOSE_STRINGS */
+  /* for tracing purposes */
+static const char * const ftp_state_names[]={
+  "STOP",
+  "WAIT220",
+  "AUTH",
+  "USER",
+  "PASS",
+  "ACCT",
+  "PBSZ",
+  "PROT",
+  "CCC",
+  "PWD",
+  "SYST",
+  "NAMEFMT",
+  "QUOTE",
+  "RETR_PREQUOTE",
+  "STOR_PREQUOTE",
+  "POSTQUOTE",
+  "CWD",
+  "MKD",
+  "MDTM",
+  "TYPE",
+  "LIST_TYPE",
+  "RETR_TYPE",
+  "STOR_TYPE",
+  "SIZE",
+  "RETR_SIZE",
+  "STOR_SIZE",
+  "REST",
+  "RETR_REST",
+  "PORT",
+  "PRET",
+  "PASV",
+  "LIST",
+  "RETR",
+  "STOR",
+  "QUIT"
+};
+#define FTP_CSTATE(c)   ((c)? ftp_state_names[(c)->proto.ftpc.state] : "???")
+#define FTP_DSTATE(d)   (((d) && (d)->conn)? \
+                         ftp_state_names[(d)->conn->proto.ftpc.state] : "???")
+
+#endif /* !CURL_DISABLE_VERBOSE_STRINGS */
+
+/* This is the ONLY way to change FTP state! */
+static void _ftp_state(struct Curl_easy *data,
+                       ftpstate newstate
+#ifdef DEBUGBUILD
+                       , int lineno
 #endif
+  )
+{
+  struct connectdata *conn = data->conn;
+  struct ftp_conn *ftpc = &conn->proto.ftpc;
+
+#if defined(CURL_DISABLE_VERBOSE_STRINGS)
+  (void) lineno;
+#else /* CURL_DISABLE_VERBOSE_STRINGS */
+  if(ftpc->state != newstate)
+#ifdef DEBUGBUILD
+    CURL_TRC_FTP(data, "[%s] -> [%s] (line %d)", FTP_DSTATE(data),
+                 ftp_state_names[newstate], lineno);
+#else
+    CURL_TRC_FTP(data, "[%s] -> [%s]", FTP_DSTATE(data),
+                 ftp_state_names[newstate]);
+#endif
+#endif /* !CURL_DISABLE_VERBOSE_STRINGS */
+
+  ftpc->state = newstate;
+}
+
 
 /* Local API functions */
 #ifndef DEBUGBUILD
-static void _ftp_state(struct Curl_easy *data,
-                       ftpstate newstate);
 #define ftp_state(x,y) _ftp_state(x,y)
-#else
+#else /* !DEBUGBUILD */
-static void _ftp_state(struct Curl_easy *data,
-                       ftpstate newstate,
-                       int lineno);
 #define ftp_state(x,y) _ftp_state(x,y,__LINE__)
-#endif
+#endif /* DEBUGBUILD */
 
 static CURLcode ftp_sendquote(struct Curl_easy *data,
                               struct connectdata *conn,
@@ -223,6 +291,7 @@ const struct Curl_handler Curl_handler_ftps = {
 static void close_secondarysocket(struct Curl_easy *data,
                                   struct connectdata *conn)
 {
+  CURL_TRC_FTP(data, "[%s] closing DATA connection", FTP_DSTATE(data));
   Curl_conn_close(data, SECONDARYSOCKET);
   Curl_conn_cf_discard_all(data, conn, SECONDARYSOCKET);
 }
@@ -566,7 +635,7 @@ static CURLcode InitiateTransfer(struct Curl_easy *data)
   struct connectdata *conn = data->conn;
   bool connected;
 
-  DEBUGF(infof(data, "ftp InitiateTransfer()"));
+  CURL_TRC_FTP(data, "InitiateTransfer()");
   if(conn->bits.ftp_use_data_ssl && data->set.ftp_use_port &&
      !Curl_conn_is_ssl(conn, SECONDARYSOCKET)) {
     result = Curl_ssl_cfilter_add(data, conn, SECONDARYSOCKET);
@@ -649,7 +718,7 @@ static CURLcode AllowServerConnect(struct Curl_easy *data, bool *connected)
   }
 
 out:
-  DEBUGF(infof(data, "ftp AllowServerConnect() -> %d", result));
+  CURL_TRC_FTP(data, "AllowServerConnect() -> %d", result);
   return result;
 }
 
@@ -831,73 +900,6 @@ CURLcode Curl_GetFTPResponse(struct Curl_easy *data,
   return result;
 }
 
-#if defined(DEBUGBUILD) && !defined(CURL_DISABLE_VERBOSE_STRINGS)
-  /* for debug purposes */
-static const char * const ftp_state_names[]={
-  "STOP",
-  "WAIT220",
-  "AUTH",
-  "USER",
-  "PASS",
-  "ACCT",
-  "PBSZ",
-  "PROT",
-  "CCC",
-  "PWD",
-  "SYST",
-  "NAMEFMT",
-  "QUOTE",
-  "RETR_PREQUOTE",
-  "STOR_PREQUOTE",
-  "POSTQUOTE",
-  "CWD",
-  "MKD",
-  "MDTM",
-  "TYPE",
-  "LIST_TYPE",
-  "RETR_TYPE",
-  "STOR_TYPE",
-  "SIZE",
-  "RETR_SIZE",
-  "STOR_SIZE",
-  "REST",
-  "RETR_REST",
-  "PORT",
-  "PRET",
-  "PASV",
-  "LIST",
-  "RETR",
-  "STOR",
-  "QUIT"
-};
-#endif
-
-/* This is the ONLY way to change FTP state! */
-static void _ftp_state(struct Curl_easy *data,
-                       ftpstate newstate
-#ifdef DEBUGBUILD
-                       , int lineno
-#endif
-  )
-{
-  struct connectdata *conn = data->conn;
-  struct ftp_conn *ftpc = &conn->proto.ftpc;
-
-#if defined(DEBUGBUILD)
-
-#if defined(CURL_DISABLE_VERBOSE_STRINGS)
-  (void) lineno;
-#else
-  if(ftpc->state != newstate)
-    infof(data, "FTP %p (line %d) state change from %s to %s",
-          (void *)ftpc, lineno, ftp_state_names[ftpc->state],
-          ftp_state_names[newstate]);
-#endif
-#endif
-
-  ftpc->state = newstate;
-}
-
 static CURLcode ftp_state_user(struct Curl_easy *data,
                                struct connectdata *conn)
 {
@@ -941,7 +943,7 @@ static int ftp_domore_getsock(struct Curl_easy *data,
    * remote site, or we could wait for that site to connect to us. Or just
    * handle ordinary commands.
    */
-  DEBUGF(infof(data, "ftp_domore_getsock()"));
+  CURL_TRC_FTP(data, "[%s] ftp_domore_getsock()", FTP_DSTATE(data));
 
   if(FTP_STOP == ftpc->state) {
     /* if stopped and still in this state, then we're also waiting for a
@@ -1208,7 +1210,8 @@ static CURLcode ftp_state_use_port(struct Curl_easy *data,
           Curl_strerror(error, buffer, sizeof(buffer)));
     goto out;
   }
-  DEBUGF(infof(data, "ftp_state_use_port(), opened socket"));
+  CURL_TRC_FTP(data, "[%s] ftp_state_use_port(), opened socket",
+               FTP_DSTATE(data));
 
   /* step 3, bind to a suitable local address */
 
@@ -1269,7 +1272,8 @@ static CURLcode ftp_state_use_port(struct Curl_easy *data,
           Curl_strerror(SOCKERRNO, buffer, sizeof(buffer)));
     goto out;
   }
-  DEBUGF(infof(data, "ftp_state_use_port(), socket bound to port %d", port));
+  CURL_TRC_FTP(data, "[%s] ftp_state_use_port(), socket bound to port %d",
+               FTP_DSTATE(data), port);
 
   /* step 4, listen on the socket */
 
@@ -1278,7 +1282,8 @@ static CURLcode ftp_state_use_port(struct Curl_easy *data,
           Curl_strerror(SOCKERRNO, buffer, sizeof(buffer)));
     goto out;
   }
-  DEBUGF(infof(data, "ftp_state_use_port(), listening on %d", port));
+  CURL_TRC_FTP(data, "[%s] ftp_state_use_port(), listening on %d",
+               FTP_DSTATE(data), port);
 
   /* step 5, send the proper FTP command */
 
@@ -2353,7 +2358,7 @@ static CURLcode ftp_state_retr(struct Curl_easy *data,
   struct connectdata *conn = data->conn;
   struct ftp_conn *ftpc = &conn->proto.ftpc;
 
-  DEBUGF(infof(data, "ftp_state_retr()"));
+  CURL_TRC_FTP(data, "[%s] ftp_state_retr()", FTP_DSTATE(data));
   if(data->set.max_filesize && (filesize > data->set.max_filesize)) {
     failf(data, "Maximum file size exceeded");
     return CURLE_FILESIZE_EXCEEDED;
@@ -3068,7 +3073,7 @@ static CURLcode ftp_statemachine(struct Curl_easy *data,
         }
       }
       ftp_state(data, FTP_STOP); /* we are done with the CONNECT phase! */
-      DEBUGF(infof(data, "protocol connect phase DONE"));
+      CURL_TRC_FTP(data, "[%s] protocol connect phase DONE", FTP_DSTATE(data));
       break;
 
     case FTP_SYST:
@@ -3113,7 +3118,7 @@ static CURLcode ftp_statemachine(struct Curl_easy *data,
       }
 
       ftp_state(data, FTP_STOP); /* we are done with the CONNECT phase! */
-      DEBUGF(infof(data, "protocol connect phase DONE"));
+      CURL_TRC_FTP(data, "[%s] protocol connect phase DONE", FTP_DSTATE(data));
       break;
 
     case FTP_NAMEFMT:
@@ -3124,7 +3129,7 @@ static CURLcode ftp_statemachine(struct Curl_easy *data,
       }
 
       ftp_state(data, FTP_STOP); /* we are done with the CONNECT phase! */
-      DEBUGF(infof(data, "protocol connect phase DONE"));
+      CURL_TRC_FTP(data, "[%s] protocol connect phase DONE", FTP_DSTATE(data));
       break;
 
     case FTP_QUOTE:
@@ -3553,6 +3558,7 @@ static CURLcode ftp_done(struct Curl_easy *data, CURLcode status,
   /* Send any post-transfer QUOTE strings? */
   if(!status && !result && !premature && data->set.postquote)
     result = ftp_sendquote(data, conn, data->set.postquote);
+  CURL_TRC_FTP(data, "[%s] done, result=%d", FTP_DSTATE(data), result);
   Curl_safefree(ftp->pathalloc);
   return result;
 }
@@ -3821,7 +3827,8 @@ static CURLcode ftp_do_more(struct Curl_easy *data, int *completep)
   if(!ftpc->wait_data_conn) {
     /* no waiting for the data connection so this is now complete */
     *completep = 1;
-    DEBUGF(infof(data, "DO-MORE phase ends with %d", (int)result));
+    CURL_TRC_FTP(data, "[%s] DO-MORE phase ends with %d", FTP_DSTATE(data),
+                 (int)result);
   }
 
   return result;
@@ -3845,7 +3852,7 @@ CURLcode ftp_perform(struct Curl_easy *data,
   /* this is FTP and no proxy */
   CURLcode result = CURLE_OK;
 
-  DEBUGF(infof(data, "DO phase starts"));
+  CURL_TRC_FTP(data, "[%s] DO phase starts", FTP_DSTATE(data));
 
   if(data->req.no_body) {
     /* requested no body means no transfer... */
@@ -3865,10 +3872,15 @@ CURLcode ftp_perform(struct Curl_easy *data,
 
   *connected = Curl_conn_is_connected(data->conn, SECONDARYSOCKET);
 
-  infof(data, "ftp_perform ends with SECONDARY: %d", *connected);
+  if(*connected)
+    infof(data, "[FTP] [%s] perform, DATA connection established",
+          FTP_DSTATE(data));
+  else
+    CURL_TRC_FTP(data, "[%s] perform, awaiting DATA connect",
+                 FTP_DSTATE(data));
 
   if(*dophase_done)
-    DEBUGF(infof(data, "DO phase is complete1"));
+    CURL_TRC_FTP(data, "[%s] DO phase is complete1", FTP_DSTATE(data));
 
   return result;
 }
@@ -4435,11 +4447,11 @@ static CURLcode ftp_doing(struct Curl_easy *data,
   CURLcode result = ftp_multi_statemach(data, dophase_done);
 
   if(result)
-    DEBUGF(infof(data, "DO phase failed"));
+    CURL_TRC_FTP(data, "[%s] DO phase failed", FTP_DSTATE(data));
   else if(*dophase_done) {
     result = ftp_dophase_done(data, FALSE /* not connected */);
 
-    DEBUGF(infof(data, "DO phase is complete2"));
+    CURL_TRC_FTP(data, "[%s] DO phase is complete2", FTP_DSTATE(data));
   }
   return result;
 }
@@ -4563,6 +4575,7 @@ static CURLcode ftp_setup_connection(struct Curl_easy *data,
   ftpc->use_ssl = data->set.use_ssl;
   ftpc->ccc = data->set.ftp_ccc;
 
+  CURL_TRC_FTP(data, "[%s] setup connection -> %d", FTP_CSTATE(conn), result);
   return result;
 }