From b7c7dffe358becd7f6302c934f83313a36a17230 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Fri, 10 May 2024 12:59:12 +0200 Subject: [PATCH] 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 | 4 + lib/curl_trc.c | 21 ++++ lib/curl_trc.h | 28 ++++- lib/ftp.c | 193 ++++++++++++++++-------------- 4 files changed, 153 insertions(+), 93 deletions(-) diff --git a/docs/libcurl/curl_global_trace.md b/docs/libcurl/curl_global_trace.md index 1485af7f67..4f011d32e4 100644 --- a/docs/libcurl/curl_global_trace.md +++ b/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. diff --git a/lib/curl_trc.c b/lib/curl_trc.c index 54bdd80000..f017e21a5a 100644 --- a/lib/curl_trc.c +++ b/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 diff --git a/lib/curl_trc.h b/lib/curl_trc.h index f64150feaf..3d38018342 100644 --- a/lib/curl_trc.h +++ b/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 */ diff --git a/lib/ftp.c b/lib/ftp.c index cdd93d84ea..049ea2c5c2 100644 --- a/lib/ftp.c +++ b/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 -static void _ftp_state(struct Curl_easy *data, - ftpstate newstate, - int lineno); +#else /* !DEBUGBUILD */ #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; } -- 2.47.3