Generate and send b3 tracing headers per CLI command

[Samze]

What's the user value of this feature request?
A single CLI command may result in multiple CAPI API requests. A unique id (vcap-request-id) is generated by go-router per api request that allows tracing issues through the system. Additionally, when enabled go-router will generate b3-trace-headers per request.

However, if you want to trace ALL requests for a particular CF CLI command you cannot, since there is no trace id that is per command and not per API call. This makes it hard to debug issues with the CLI, or to understand all the requests made for a single command (e.g. cf push).

The CLI should generate a unique ID per command and utilise the distributed b3 trace headers, see here.

This means if there is an issue, a developer can run CF_TRACE=true and see the generated b3 trace headers which can then be correlated to logs in the CF system by opeators.

Headers to set per command:

X-B3-Traceid - 128-bit in length and indicates the overall ID of the trace. Every span in a trace shares this ID. The X-B3-TraceId header is encoded as 32 lower-hex characters.

Headers to set per api call

X-B3-Spanid - 64-bit in length and indicates the position of the current operation in the trace tree. The X-B3-SpanId header is encoded as 16 lower-hex characters.

These then will be logged in different CF components, including CAPI, e.g. capi log

{
  "timestamp": "2024-11-18T21:00:58.094638225Z",
  "message": "Completed 200 vcap-request-id: 424e6816-392a-4c68-5531-cfccd8508bad::32c7ffa4-30f3-490e-8c89-96722c952549",
  "log_level": "info",
  "source": "cc.api",
  "data": {
    "request_guid": "424e6816-392a-4c68-5531-cfccd8508bad::32c7ffa4-30f3-490e-8c89-96722c952549",
    "user_guid": "8f6fb41c-b334-45e8-ba25-ba3b909bbb70",
    "b3_trace_id": "a67d95354cc07e8a87d5706c44ff5a6e",
    "b3_span_id": "4b24d3227b42b0cb666995afcef772e6",
    "status_code": 200
  },
  "thread_id": 72620,
  "fiber_id": 72640,
  "process_id": 7,
  "file": "/var/vcap/data/packages/cloud_controller_ng/19f5e6515e03b9d0de46e7ce1e34451881bc74e6/cloud_controller_ng/lib/cloud_controller/logs/request_logs.rb",
  "lineno": 32,
  "method": "complete_request"
}

It should also be possible to explicitly set the trace header.

We should introduce the following new environment variable.

export CF_B3_TRACE_ID=<my_trace_id>

In addition to this, if someone explicitly sets the header via -H using a cf curl that should take priority.

So the order of priority of this header is:

1. cf curl -H B3_TRACE_ID=xxx
2. CF_B3_TRACE_ID environment variable
3. Auto generated

Who is the functionality for?
Operators debugging CF issues.

Who else is affected by the change?
Currently b3 headers are generated by go-router, this would mean that CLI requests no longer contain unique b3 headers per request but rather per command.

[johha]

Would it be worth it to have a global parameter (e.g. --trace-id) which just prints the trace id/ vcap id without the full verbose output? I have seen cases where users seem to be overwhelmed and maybe even confused by the complete verbose output.

[Samze]

Would it be worth it to have a global parameter (e.g. --trace-id) which just prints the trace id/ vcap id without the full verbose output? I have seen cases where users seem to be overwhelmed and maybe even confused by the complete verbose output.

@johha Yeah thats a good idea and feedback we hear too. I wish CF_TRACE allowed for varying levels of verbosity.

For trace headers we have the following ids that could be output:

• B3_TRACE_ID = per command
• B3_SPAN_ID = per request
• VCAP_REQUEST_ID = per response

If we output trace ids for every api call we'd likely still have a lot of spam since we'd need to show the request URL + trace ids for every request. Did you have something in midn?

One option would be to just output the per command request id. Something like:

cf apps --trace-id
TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
Getting apps in org org-1 / space space-1 as admin...

name     requested state   processes             routes
dora     started           web:1/1, worker:0/0   dora.cocoanuts.app-runtime-interfaces.ci.cloudfoundry.org

2. Show only every API call trace ids and request url.

cf apps --trace-ids
REQUEST: [2024-12-05T10:03:31-07:00]
GET /v3/apps?order_by=name&per_page=5000&space_guids=71b2e041-2260-4f10-b8bd-cc02e29aa638 HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

GET /v3/processes?app_guids=f9964a6b-5403-4f6f-a123-f9c48d86a576%2Cb232d389-7dae-4eb4-9bf1-b392ba749106 HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

GET /v3/processes/b232d389-7dae-4eb4-9bf1-b392ba749106/stats HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

GET /v3/processes/f9964a6b-5403-4f6f-a123-f9c48d86a576/stats HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

GET /v3/processes/1b835eed-5a45-4627-b8f1-a56dfa6eb253/stats HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

GET /v3/routes?app_guids=f9964a6b-5403-4f6f-a123-f9c48d86a576%2Cb232d389-7dae-4eb4-9bf1-b392ba749106 
HTTP/1.1
B3_TRACE_ID: 76513d6af5c0456c51ec04e848b323a4
B3_SPAN_ID: c51ec04e848b323a4
VCAP_REQUEST_ID: 76513d6af5c0456:76513d6af5c0456

Getting apps in org org-1 / space space-1 as admin...

name     requested state   processes             routes
dora     started           web:1/1, worker:0/0   dora.cocoanuts.app-runtime-interfaces.ci.cloudfoundry.org

Or if we think theres value in both we could have trace-ids take a verbosity (e.g. trace_ids=1 outputs the first option, trace_ids=2 outputs the second).

Another thing we could do is to display the TRACE_ID if the command fails, e.g.

cf push app-does-not-exist
Pushing app app-does-not-exist to org o / space s as admin...
Packaging files to upload...
Uploading files...
 7.92 KiB / 7.92 KiB [===] 100.00% 1s

Waiting for API to complete processing files...

Staging app and tracing logs...
   Downloading web_servers_cnb_beta...

NoAppDetectedError - An app was not successfully detected by any available buildpack
FAILED - Trace ID: 8112be685aa24ec37e485b5ef394e3f9  # ◀️ Add trace to output

But I still think we'd want to a way to output the trace id explicitly on success.

Regardless, I think we can have that feature separate from this issue/PR which is to actually set the trace id header.

[a-b]

Since CF_TRACE already supports outputting to a file, we could enhance it by implementing log verbosity levels akin to Linux log levels.

Currently, the usage is as follows:

CF_TRACE=true                               Print API request diagnostics to stdout
CF_TRACE=path/to/trace.log         Append API request diagnostics to a log file

As proposed by @Samze, we could introduce an integer level ranging from 0 to 7, where 7 indicates the most detailed output. Lower levels, such as 6 or 5, would display the request path and headers without including the request body. One approach to achieve this would be introducing a new variable called CF_TRACE_LEVEL.