lib: add CURLINFO_CONN_ID and CURLINFO_XFER_ID

- add an `id` long to Curl_easy, -1 on init
- once added to a multi (or its own multi), it gets
  a non-negative number assigned by the connection cache
- `id` is unique among all transfers using the same
  cache until reaching LONG_MAX where it will wrap
  around. So, not unique eternally.
- CURLINFO_CONN_ID returns the connection id attached to
  data or, if none present, data->state.lastconnect_id
- variables and type declared in tool for write out

Closes #11185
This commit is contained in:
Stefan Eissing 2023-05-23 12:48:58 +02:00 committed by Daniel Stenberg
parent fdda99c6ee
commit e024d5665d
No known key found for this signature in database
GPG key ID: 5CC908FDB71E12C2
31 changed files with 252 additions and 94 deletions

View file

@ -179,7 +179,7 @@ ssize_t Curl_conn_recv(struct Curl_easy *data, int num, char *buf,
if(cf) {
return cf->cft->do_recv(cf, data, buf, len, code);
}
failf(data, CMSGI(data->conn, num, "recv: no filter connected"));
failf(data, "recv: no filter connected");
*code = CURLE_FAILED_INIT;
return -1;
}
@ -198,7 +198,7 @@ ssize_t Curl_conn_send(struct Curl_easy *data, int num,
if(cf) {
return cf->cft->do_send(cf, data, mem, len, code);
}
failf(data, CMSGI(data->conn, num, "send: no filter connected"));
failf(data, "send: no filter connected");
DEBUGASSERT(0);
*code = CURLE_FAILED_INIT;
return -1;

View file

@ -39,7 +39,8 @@ struct connectdata;
struct conncache {
struct Curl_hash hash;
size_t num_conn;
long next_connection_id;
curl_off_t next_connection_id;
curl_off_t next_easy_id;
struct curltime last_cleanup;
/* handle used for closing cached connections */
struct Curl_easy *closure_handle;

View file

@ -253,7 +253,7 @@ bool Curl_addr2string(struct sockaddr *sa, curl_socklen_t salen,
}
struct connfind {
long id_tofind;
curl_off_t id_tofind;
struct connectdata *found;
};

View file

@ -134,9 +134,7 @@ void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf,
va_list ap;
int len;
char buffer[MAXINFO + 2];
len = msnprintf(buffer, MAXINFO, "[CONN-%ld%s-%s] ",
cf->conn->connection_id, cf->sockindex? "/2" : "",
cf->cft->name);
len = msnprintf(buffer, MAXINFO, "[%s] ", cf->cft->name);
va_start(ap, fmt);
len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
va_end(ap);

View file

@ -118,23 +118,4 @@ void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf,
#define LOG_CF_IS_DEBUG(cf, data) Curl_log_cf_is_debug(cf, data)
/* Macros intended for DEBUGF logging, use like:
* DEBUGF(infof(data, CFMSG(cf, "this filter %s rocks"), "very much"));
* and it will output:
* [CONN-1-0][CF-SSL] this filter very much rocks
* on connection #1 with sockindex 0 for filter of type "SSL". */
#define DMSG(d,msg) \
"[CONN-%ld] "msg, (d)->conn->connection_id
#define DMSGI(d,i,msg) \
"[CONN-%ld-%d] "msg, (d)->conn->connection_id, (i)
#define CMSG(c,msg) \
"[CONN-%ld] "msg, (c)->connection_id
#define CMSGI(c,i,msg) \
"[CONN-%ld-%d] "msg, (c)->connection_id, (i)
#define CFMSG(cf,msg) \
"[CONN-%ld-%d][CF-%s] "msg, (cf)->conn->connection_id, \
(cf)->sockindex, (cf)->cft->name
#endif /* HEADER_CURL_LOG_H */

View file

@ -893,6 +893,8 @@ struct Curl_easy *curl_easy_duphandle(struct Curl_easy *data)
/* the connection cache is setup on demand */
outcurl->state.conn_cache = NULL;
outcurl->state.lastconnect_id = -1;
outcurl->state.recent_conn_id = -1;
outcurl->id = -1;
outcurl->progress.flags = data->progress.flags;
outcurl->progress.callback = data->progress.callback;

View file

@ -415,6 +415,13 @@ static CURLcode getinfo_offt(struct Curl_easy *data, CURLINFO info,
case CURLINFO_RETRY_AFTER:
*param_offt = data->info.retry_after;
break;
case CURLINFO_XFER_ID:
*param_offt = data->id;
break;
case CURLINFO_CONN_ID:
*param_offt = data->conn?
data->conn->connection_id : data->state.recent_conn_id;
break;
default:
return CURLE_UNKNOWN_OPTION;
}

View file

@ -1947,8 +1947,8 @@ static ssize_t h2_submit(struct stream_ctx **pstream,
h2_pri_spec(data, &pri_spec);
DEBUGF(LOG_CF(data, cf, "send request allowed %d (easy handle %p)",
nghttp2_session_check_request_allowed(ctx->h2), (void *)data));
DEBUGF(LOG_CF(data, cf, "send request allowed %d",
nghttp2_session_check_request_allowed(ctx->h2)));
switch(data->state.httpreq) {
case HTTPREQ_POST:
@ -1984,8 +1984,7 @@ static ssize_t h2_submit(struct stream_ctx **pstream,
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s",
stream_id, len, data->state.url));
infof(data, "Using Stream ID: %u (easy handle %p)",
stream_id, (void *)data);
infof(data, "Using Stream ID: %u", stream_id);
stream->id = stream_id;
stream->local_window_size = H2_STREAM_WINDOW_SIZE;
if(data->set.max_recv_speed) {
@ -2542,7 +2541,7 @@ CURLcode Curl_http2_switch(struct Curl_easy *data,
CURLcode result;
DEBUGASSERT(!Curl_conn_is_http2(data, conn, sockindex));
DEBUGF(infof(data, DMSGI(data, sockindex, "switching to HTTP/2")));
DEBUGF(infof(data, "switching to HTTP/2"));
result = http2_cfilter_add(&cf, data, conn, sockindex);
if(result)
@ -2601,7 +2600,7 @@ CURLcode Curl_http2_upgrade(struct Curl_easy *data,
CURLcode result;
DEBUGASSERT(!Curl_conn_is_http2(data, conn, sockindex));
DEBUGF(infof(data, DMSGI(data, sockindex, "upgrading to HTTP/2")));
DEBUGF(infof(data, "upgrading to HTTP/2"));
DEBUGASSERT(data->req.upgr101 == UPGR101_RECEIVED);
result = http2_cfilter_add(&cf, data, conn, sockindex);

View file

@ -1777,7 +1777,7 @@ static CURLcode imap_sendf(struct Curl_easy *data, const char *fmt, ...)
/* Calculate the tag based on the connection ID and command ID */
msnprintf(imapc->resptag, sizeof(imapc->resptag), "%c%03d",
'A' + curlx_sltosi(data->conn->connection_id % 26),
'A' + curlx_sltosi((long)(data->conn->connection_id % 26)),
++imapc->cmdid);
/* start with a blank buffer */

View file

@ -194,15 +194,10 @@ static void mstate(struct Curl_easy *data, CURLMstate state
#if defined(DEBUGBUILD) && !defined(CURL_DISABLE_VERBOSE_STRINGS)
if(data->mstate >= MSTATE_PENDING &&
data->mstate < MSTATE_COMPLETED) {
long connection_id = -5000;
if(data->conn)
connection_id = data->conn->connection_id;
infof(data,
"STATE: %s => %s handle %p; line %d (connection #%ld)",
"STATE: %s => %s handle %p; line %d",
multi_statename[oldstate], multi_statename[data->mstate],
(void *)data, lineno, connection_id);
(void *)data, lineno);
}
#endif
@ -464,6 +459,20 @@ struct Curl_multi *curl_multi_init(void)
CURL_DNS_HASH_SIZE);
}
#ifdef DEBUGBUILD
static void multi_warn_debug(struct Curl_multi *multi, struct Curl_easy *data)
{
if(!multi->warned) {
infof(data, "!!! WARNING !!!");
infof(data, "This is a debug build of libcurl, "
"do not use in production.");
multi->warned = true;
}
}
#else
#define multi_warn_debug(x,y) Curl_nop_stmt
#endif
/* returns TRUE if the easy handle is supposed to be present in the main link
list */
static bool in_main_list(struct Curl_easy *data)
@ -623,8 +632,14 @@ CURLMcode curl_multi_add_handle(struct Curl_multi *multi,
data->set.server_response_timeout;
data->state.conn_cache->closure_handle->set.no_signal =
data->set.no_signal;
data->id = data->state.conn_cache->next_easy_id++;
if(data->state.conn_cache->next_easy_id <= 0)
data->state.conn_cache->next_easy_id = 0;
CONNCACHE_UNLOCK(data);
multi_warn_debug(multi, data);
infof(data, "processing: %s", data->state.url);
return CURLM_OK;
}
@ -742,6 +757,7 @@ static CURLcode multi_done(struct Curl_easy *data,
but currently we have no such detail knowledge.
*/
data->state.recent_conn_id = conn->connection_id;
if((data->set.reuse_forbid
#if defined(USE_NTLM)
&& !(conn->http_ntlm_state == NTLMSTATE_TYPE2 ||
@ -753,7 +769,7 @@ static CURLcode multi_done(struct Curl_easy *data,
#endif
) || conn->bits.close
|| (premature && !Curl_conn_is_multiplex(conn, FIRSTSOCKET))) {
DEBUGF(infof(data, "multi_done, not re-using connection=%ld, forbid=%d"
DEBUGF(infof(data, "multi_done, not re-using connection=%zd, forbid=%d"
", close=%d, premature=%d, conn_multiplex=%d",
conn->connection_id,
data->set.reuse_forbid, conn->bits.close, premature,
@ -774,15 +790,16 @@ static CURLcode multi_done(struct Curl_easy *data,
conn->bits.conn_to_host ? conn->conn_to_host.dispname :
conn->host.dispname;
/* create string before returning the connection */
long connection_id = conn->connection_id;
curl_off_t connection_id = conn->connection_id;
msnprintf(buffer, sizeof(buffer),
"Connection #%ld to host %s left intact",
"Connection #%zd to host %s left intact",
connection_id, host);
/* the connection is no longer in use by this transfer */
CONNCACHE_UNLOCK(data);
if(Curl_conncache_return_conn(data, conn)) {
/* remember the most recently used connection */
data->state.lastconnect_id = connection_id;
data->state.recent_conn_id = connection_id;
infof(data, "%s", buffer);
}
else
@ -1895,14 +1912,7 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi,
multistate(data, MSTATE_COMPLETED);
}
#ifdef DEBUGBUILD
if(!multi->warned) {
infof(data, "!!! WARNING !!!");
infof(data, "This is a debug build of libcurl, "
"do not use in production.");
multi->warned = true;
}
#endif
multi_warn_debug(multi, data);
do {
/* A "stream" here is a logical stream if the protocol can handle that
@ -3690,7 +3700,7 @@ void Curl_expire_clear(struct Curl_easy *data)
}
#ifdef DEBUGBUILD
infof(data, "Expire cleared (transfer %p)", data);
infof(data, "Expire cleared");
#endif
nowp->tv_sec = 0;
nowp->tv_usec = 0;

View file

@ -419,8 +419,6 @@ CURLcode Curl_read(struct Curl_easy *data, /* transfer */
*n += nread;
result = CURLE_OK;
out:
/* DEBUGF(infof(data, "Curl_read(handle=%p) -> %d, nread=%ld",
data, result, nread)); */
return result;
}

View file

@ -1534,7 +1534,7 @@ static CURLcode telnet_do(struct Curl_easy *data, bool *done)
}
while(keepon) {
DEBUGF(infof(data, "telnet_do(handle=%p), poll %d fds", data, poll_cnt));
DEBUGF(infof(data, "telnet_do, poll %d fds", poll_cnt));
switch(Curl_poll(pfd, poll_cnt, interval_ms)) {
case -1: /* error, stop reading */
keepon = FALSE;
@ -1558,8 +1558,7 @@ static CURLcode telnet_do(struct Curl_easy *data, bool *done)
* in a clean way? Seems to be timing related, happens more
* on slow debug build */
if(data->state.os_errno == ECONNRESET) {
DEBUGF(infof(data, "telnet_do(handle=%p), unexpected ECONNRESET"
" on recv", data));
DEBUGF(infof(data, "telnet_do, unexpected ECONNRESET on recv"));
}
break;
}

View file

@ -474,7 +474,7 @@ static CURLcode readwrite_data(struct Curl_easy *data,
else {
/* read nothing but since we wanted nothing we consider this an OK
situation to proceed from */
DEBUGF(infof(data, DMSG(data, "readwrite_data: we're done")));
DEBUGF(infof(data, "readwrite_data: we're done"));
nread = 0;
}
@ -771,7 +771,7 @@ static CURLcode readwrite_data(struct Curl_easy *data,
out:
if(result)
DEBUGF(infof(data, DMSG(data, "readwrite_data() -> %d"), result));
DEBUGF(infof(data, "readwrite_data() -> %d", result));
return result;
}
@ -1236,7 +1236,7 @@ CURLcode Curl_readwrite(struct connectdata *conn,
*done = (0 == (k->keepon&(KEEP_RECVBITS|KEEP_SENDBITS))) ? TRUE : FALSE;
out:
if(result)
DEBUGF(infof(data, DMSG(data, "Curl_readwrite() -> %d"), result));
DEBUGF(infof(data, "Curl_readwrite() -> %d", result));
return result;
}

View file

@ -659,6 +659,9 @@ CURLcode Curl_open(struct Curl_easy **curl)
/* most recent connection is not yet defined */
data->state.lastconnect_id = -1;
data->state.recent_conn_id = -1;
/* and not assigned an id yet */
data->id = -1;
data->progress.flags |= PGRS_HIDE;
data->state.current_speed = -1; /* init to negative == impossible */
@ -680,7 +683,7 @@ CURLcode Curl_open(struct Curl_easy **curl)
static void conn_shutdown(struct Curl_easy *data)
{
DEBUGASSERT(data);
infof(data, "Closing connection %ld", data->conn->connection_id);
infof(data, "Closing connection");
/* possible left-overs from the async name resolvers */
Curl_resolver_cancel(data);
@ -763,7 +766,8 @@ void Curl_disconnect(struct Curl_easy *data,
/* the transfer must be detached from the connection */
DEBUGASSERT(!data->conn);
DEBUGF(infof(data, "Curl_disconnect(conn #%ld, dead=%d)",
DEBUGF(infof(data, "Curl_disconnect(conn #%"
CURL_FORMAT_CURL_OFF_T ", dead=%d)",
conn->connection_id, dead_connection));
/*
* If this connection isn't marked to force-close, leave it open if there
@ -952,7 +956,8 @@ static bool extract_if_dead(struct connectdata *conn,
}
if(dead) {
infof(data, "Connection %ld seems to be dead", conn->connection_id);
infof(data, "Connection %" CURL_FORMAT_CURL_OFF_T " seems to be dead",
conn->connection_id);
Curl_conncache_remove_conn(data, conn, FALSE);
return TRUE;
}
@ -1148,7 +1153,7 @@ ConnectionExists(struct Curl_easy *data,
completed yet and until then we don't re-use this connection */
if(!check->primary_ip[0]) {
infof(data,
"Connection #%ld is still name resolving, can't reuse",
"Connection #%zd is still name resolving, can't reuse",
check->connection_id);
continue;
}
@ -1158,8 +1163,8 @@ ConnectionExists(struct Curl_easy *data,
if(!Curl_conn_is_connected(check, FIRSTSOCKET)) {
foundPendingCandidate = TRUE;
/* Don't pick a connection that hasn't connected yet */
infof(data, "Connection #%ld isn't open enough, can't reuse",
check->connection_id);
infof(data, "Connection #%" CURL_FORMAT_CURL_OFF_T
"isn't open enough, can't reuse", check->connection_id);
continue;
}
@ -1335,8 +1340,8 @@ ConnectionExists(struct Curl_easy *data,
if(!Curl_ssl_config_matches(&needle->ssl_config,
&check->ssl_config)) {
DEBUGF(infof(data,
"Connection #%ld has different SSL parameters, "
"can't reuse",
"Connection #%" CURL_FORMAT_CURL_OFF_T
" has different SSL parameters, can't reuse",
check->connection_id));
continue;
}
@ -1477,14 +1482,14 @@ void Curl_verboseconnect(struct Curl_easy *data,
struct connectdata *conn)
{
if(data->set.verbose)
infof(data, "Connected to %s (%s) port %u (#%ld)",
infof(data, "Connected to %s (%s) port %u",
#ifndef CURL_DISABLE_PROXY
conn->bits.socksproxy ? conn->socks_proxy.host.dispname :
conn->bits.httpproxy ? conn->http_proxy.host.dispname :
#endif
conn->bits.conn_to_host ? conn->conn_to_host.dispname :
conn->host.dispname,
conn->primary_ip, conn->port, conn->connection_id);
conn->primary_ip, conn->port);
}
#endif
@ -3678,15 +3683,14 @@ static CURLcode create_conn(struct Curl_easy *data,
*in_connect = conn;
#ifndef CURL_DISABLE_PROXY
infof(data, "Re-using existing connection #%ld with %s %s",
conn->connection_id,
infof(data, "Re-using existing connection with %s %s",
conn->bits.proxy?"proxy":"host",
conn->socks_proxy.host.name ? conn->socks_proxy.host.dispname :
conn->http_proxy.host.name ? conn->http_proxy.host.dispname :
conn->host.dispname);
#else
infof(data, "Re-using existing connection #%ld with host %s",
conn->connection_id, conn->host.dispname);
infof(data, "Re-using existing connection with host %s",
conn->host.dispname);
#endif
}
else {

View file

@ -882,8 +882,8 @@ struct connectdata {
#define CONN_INUSE(c) ((c)->easyq.size)
/**** Fields set when inited and not modified again */
long connection_id; /* Contains a unique number to make it easier to
track the connections in the log output */
curl_off_t connection_id; /* Contains a unique number to make it easier to
track the connections in the log output */
/* 'dns_entry' is the particular host we use. This points to an entry in the
DNS cache and it will not get pruned while locked. It gets unlocked in
@ -1294,7 +1294,9 @@ struct UrlState {
/* buffers to store authentication data in, as parsed from input options */
struct curltime keeps_speed; /* for the progress meter really */
long lastconnect_id; /* The last connection, -1 if undefined */
curl_off_t lastconnect_id; /* The last connection, -1 if undefined */
curl_off_t recent_conn_id; /* The most recent connection used, might no
* longer exist */
struct dynbuf headerb; /* buffer to store headers in */
char *buffer; /* download buffer */
@ -1903,6 +1905,13 @@ struct Curl_easy {
/* First a simple identifier to easier detect if a user mix up this easy
handle with a multi handle. Set this to CURLEASY_MAGIC_NUMBER */
unsigned int magic;
/* once an easy handle is tied to a connection cache
a non-negative number to distinguish this transfer from
other using the same cache. For easier tracking
in log output.
This may wrap around after LONG_MAX to 0 again, so it
has no uniqueness guarantuee for very large processings. */
curl_off_t id;
/* first, two fields for the linked list of these */
struct Curl_easy *next;

View file

@ -173,7 +173,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
msh3_lock_initialize(&stream->recv_lock);
Curl_bufq_init2(&stream->recvbuf, H3_STREAM_CHUNK_SIZE,
H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT);
DEBUGF(LOG_CF(data, cf, "data setup (easy %p)", (void *)data));
DEBUGF(LOG_CF(data, cf, "data setup"));
return CURLE_OK;
}

View file

@ -224,7 +224,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
stream->recv_buf_nonflow = 0;
H3_STREAM_LCTX(data) = stream;
DEBUGF(LOG_CF(data, cf, "data setup (easy %p)", (void *)data));
DEBUGF(LOG_CF(data, cf, "data setup"));
return CURLE_OK;
}
@ -1670,8 +1670,7 @@ static ssize_t h3_stream_open(struct Curl_cfilter *cf,
goto out;
}
infof(data, "Using HTTP/3 Stream ID: %" PRId64 " (easy handle %p)",
stream->id, (void *)data);
infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream->id);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s",
stream->id, data->state.url));

View file

@ -277,7 +277,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
stream->id = -1;
Curl_bufq_initp(&stream->recvbuf, &ctx->stream_bufcp,
H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT);
DEBUGF(LOG_CF(data, cf, "data setup (easy %p)", (void *)data));
DEBUGF(LOG_CF(data, cf, "data setup"));
return CURLE_OK;
}
@ -995,8 +995,7 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf,
stream->closed = FALSE;
stream->reset = FALSE;
infof(data, "Using HTTP/3 Stream ID: %" PRId64 " (easy handle %p)",
stream3_id, (void *)data);
infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream3_id);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s",
stream3_id, data->state.url));

View file

@ -453,7 +453,7 @@ bool Curl_ssl_getsessionid(struct Curl_cfilter *cf,
}
}
DEBUGF(infof(data, DMSG(data, "%s Session ID in cache for %s %s://%s:%d"),
DEBUGF(infof(data, "%s Session ID in cache for %s %s://%s:%d",
no_match? "Didn't find": "Found",
Curl_ssl_cf_is_proxy(cf) ? "proxy" : "host",
cf->conn->handler->scheme, connssl->hostname, connssl->port));
@ -601,8 +601,8 @@ CURLcode Curl_ssl_addsessionid(struct Curl_cfilter *cf,
if(added)
*added = TRUE;
DEBUGF(infof(data, DMSG(data, "Added Session ID to cache for %s://%s:%d"
" [%s]"), store->scheme, store->name, store->remote_port,
DEBUGF(infof(data, "Added Session ID to cache for %s://%s:%d [%s]",
store->scheme, store->name, store->remote_port,
Curl_ssl_cf_is_proxy(cf) ? "PROXY" : "server"));
return CURLE_OK;
}

View file

@ -987,8 +987,7 @@ CURL_EXTERN CURLcode curl_ws_send(struct Curl_easy *data, const void *buffer,
return CURLE_SEND_ERROR;
}
if(!data->conn->proto.ws) {
failf(data, "Not a websocket transfer on connection #%ld",
data->conn->connection_id);
failf(data, "Not a websocket transfer");
return CURLE_SEND_ERROR;
}
ws = data->conn->proto.ws;