transfer numbers for logging, --trace-ids #11185

icing · 2023-05-23T10:57:52Z

Adding identifier to transfers and connections using the same connection cache (implicitly
the case when using the same multi handle). With type curl_off_t they are unique for all practical purposes.

Adding new CURLINFO_XFER_ID and CURLINFO_CONN_ID to the interface and documentation
to make them accessible for libcurl applications.

Adding --trace-ids to the curl command line to include the identifier in verbose log output. Example:

[4-x] * processing: https://curl.se/?4
...
[4-x] * STATE: INIT => CONNECT
...
[4-0] * STATE: PROTOCONNECT => DO
[4-0] * h2 [:method: GET]
...
[4-0] < HTTP/2 200
...
[4-x] * Expire cleared

This does not change any logging statements (yet). If we use these in the verbose output of curl itself, it would be suitable to change several statements that now contain connection id and a handle pointer.

bagder · 2023-05-23T11:30:37Z

lib/conncache.h

@@ -40,6 +40,7 @@ struct conncache {
  struct Curl_hash hash;
  size_t num_conn;
  long next_connection_id;
+  long next_easy_id;


I'm thinking we should maybe switch to curl_off_t here to be sure this is a 64 bit type, as long will be 32 bit on Windows - and the inconsistency might cause confusions down the line.

Or if we are fine with "just" 32 bits before wrapping, maybe we can go with unsigned int.

Whichever direction, I think we can apply the same thinking to the *connection_id fields, for the same reasons.

Both sound fine to me. With a 64 bit type, we reach uniqueness for all practical purposes, I guess (inside the same multi/conn cache).

The next question is then if we want to add this to all the info() statements or make this available to the logging functions. For the latter, it would sneak into the API and I am not sure that this is a good idea. But I do not know if someone is attached to the current log strings either.

With a signed 32 bit counter, there is still a theoretical chance that someone could add a handle every millisecond for 25 days and see it reach max. Going 64 bit takes away the entire discussion.

For the latter, it would sneak into the API and I am not sure that this is a good idea.

Maybe, since the DEBUGFUNCTION gets a CURL * as an argument, we can add a CURLINFO_* variable for this "easy_id" so that the app can opt to show this?

It doesn't solve the connection id, and it also then does not make the output of these id use a standard look as it will be left for the application.

But I do not know if someone is attached to the current log strings either.

I think many users are used to them at the very least, but we never promised that they would remain like this.

So, some more thinking between issue solving. A backwards compatible way to introduce this:

go curl_off_t for transfer and connection id (do we have printf format for that one btw?)

add CURLINFO_EASY_ID and CURLINFO_CONN_ID for the app to retrieve identifiers (-1 for unassigned, e.g. easy not part of multi yet or connection not assigned)

add --trace-id to curl that adds these to its verbose/trace output

Do we provide a standard implementation for apps to set as CURLOPT_DEBUGFUNCTION? Something along the lines of:

CURL_LOGFMT_DEFAULT (0) CURL_LOGFMT_IDS (1 << 0) /* add EASY and CONN ids */ CURL_LOGFMT_TIME (1 << 1) /* add timestamps */ CURL_LOGFMT_HEXDUMP (1 << 2) /* dump data in hex table */ /* set DEBUGFUNCTION/DEBUGDATA to log to FILE for this easy handle */ curl_easy_set_log(CURL*, FILE*, int fmt) /* set DEBUGFUNCTION/DEBUGDATA to log to FILE for all easy handles in multi that have no other setting already */ curl_multi_set_log(CURLM*, FILE*, int fmt)

bagder · 2023-06-09T21:42:21Z

lib/curl_log.h

@@ -124,15 +124,15 @@ void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf,
 * [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
+  "[CONN-%zd] "msg, (d)->conn->connection_id


I think you need to use "%" CURL_FORMAT_CURL_OFF_T everywhere for outputting curl_off_t variables correctly. The z flag is for size_t and it can be different than curl_off_t !

I removed these macros.

bagder · 2023-06-09T21:44:44Z

lib/multi.c

@@ -194,7 +194,7 @@ 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;
+     curl_off_t connection_id = -5000;


Shouldn't this be -1 now to match the documentation?

Removed, no longer logged explicitly.

bagder · 2023-06-09T21:45:32Z

lib/multi.c

@@ -3690,7 +3704,7 @@ void Curl_expire_clear(struct Curl_easy *data)
    }

 #ifdef DEBUGBUILD
-    infof(data, "Expire cleared (transfer %p)", data);
+    infof(data, "Expire cleared (easy handle %p)", data);


Maybe use the transfer id instead for consistency?

Removed the %p since --trace-ids takes care of that.

- 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.

- curl_easy_getinfo() can be used to retrieve these - 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

- it is not the identifier of the handle, but of the transfer done by it. - removing all changes to `infof()` statements

- added and documented --trace-ids to prepend (after the timestamp) the transfer and connection identifiers to each verbose log line - format is [n-m] with `n` being the transfer id and `m` being the connection id. In case there is not valid connection id, print 'x'. - Log calls with a handle that has no transfer id yet, are written without any ids.

…n the url in the log

- using CURL_FORMAT_OFF_T for connection ids - removed curl_log.h macros to log connection ids in infof() - changed CFLOG() implementation to only log the filter name since transfer and connection ids are now handled elsewhere - removed some connection id explicit logging where it is now redundant - removed some handle pointer logging

- added and documented --trace-ids to prepend (after the timestamp) the transfer and connection identifiers to each verbose log line - format is [n-m] with `n` being the transfer id and `m` being the connection id. In case there is not valid connection id, print 'x'. - Log calls with a handle that has no transfer id yet, are written without any ids. Closes #11185

- 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 curl#11185

- added and documented --trace-ids to prepend (after the timestamp) the transfer and connection identifiers to each verbose log line - format is [n-m] with `n` being the transfer id and `m` being the connection id. In case there is not valid connection id, print 'x'. - Log calls with a handle that has no transfer id yet, are written without any ids. Closes curl#11185

- 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 curl#11185

- added and documented --trace-ids to prepend (after the timestamp) the transfer and connection identifiers to each verbose log line - format is [n-m] with `n` being the transfer id and `m` being the connection id. In case there is not valid connection id, print 'x'. - Log calls with a handle that has no transfer id yet, are written without any ids. Closes curl#11185

bagder reviewed May 23, 2023

View reviewed changes

icing force-pushed the xfer-id branch from 201c70b to d63fc1d Compare June 7, 2023 12:43

github-actions bot added cmdline tool libcurl API labels Jun 7, 2023

icing force-pushed the xfer-id branch from 7dc2ae9 to 44fa521 Compare June 9, 2023 07:38

github-actions bot added the tests label Jun 9, 2023

bagder reviewed Jun 9, 2023

View reviewed changes

icing added 7 commits June 11, 2023 09:59

Converting new transfer id and connection id to curl_off_t

814f664

Adding CURLINFO_CONN_ID and CURLINFO_EASY_ID

b65d8d0

- curl_easy_getinfo() can be used to retrieve these - 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

wip od adding documentation and fixing test cases

85d1962

Renaming CURLINFO_EASY_ID to CURLINFO_XFER_ID

6e117d3

- it is not the identifier of the handle, but of the transfer done by it. - removing all changes to `infof()` statements

Convert remaining long connection_id vars to curl_off_t

331ab38

icing force-pushed the xfer-id branch from 9ff8cd3 to e6e98d9 Compare June 11, 2023 09:05

icing changed the title ~~Internal transfer numbers for logging~~ transfer numbers for logging, --trace-ids Jun 11, 2023

icing added 2 commits June 11, 2023 11:12

Add infof log statement right when transfer id is assigned and mentio…

e591e69

…n the url in the log

bagder approved these changes Jun 12, 2023

View reviewed changes

bagder closed this in e024d56 Jun 12, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

transfer numbers for logging, --trace-ids #11185

transfer numbers for logging, --trace-ids #11185

icing commented May 23, 2023 •

edited

bagder May 23, 2023

icing May 23, 2023

bagder May 23, 2023

icing May 25, 2023 •

edited

bagder Jun 9, 2023

icing Jun 12, 2023

bagder Jun 9, 2023

icing Jun 12, 2023

bagder Jun 9, 2023

icing Jun 12, 2023

transfer numbers for logging, --trace-ids #11185

transfer numbers for logging, --trace-ids #11185

Conversation

icing commented May 23, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

icing May 25, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

icing commented May 23, 2023 •

edited

icing May 25, 2023 •

edited