How to see in the logs where the time is being spent using cf buildpack commands

Products

• VMware Tanzu Application Service for VMs

Issue/Introduction

How to follow a buildpack as it interacts with TAS platform by following the logs in real time?

Resolution

Noteable:

• When a user enters a cf buildpack command the flow (inside TAS) appears to be as follows: client -> haproxy/LB -> gorouter -> cloud_controller->blobstore->cloud_controller. In general, the majority of time spent on a “cf update-buildpack” command is between: client ~> cc or cc -> blobstore. The time taken at this stage would depend on factors such as the size of the buildpack and any network latency between the cli and the blobstore.
• Please note the logs associated during the cf cli interacting with cloud controller + node are found on the Cloud Controller VM in the following directory: (will need to be sudo) --> var/vcap/sys/log/cloud_controller_ng .

 

Steps below to see the logs in real time associated with buildpack commands/any cf command (you can redirect the outputs to a file if preferred):

1. In a terminal, ssh into opsman vm (may need to install cf cli) and run your CF_TRACE=true cf create-buildpack BUILDPACK command. Or can trigger buildpack update via pipeline.

2. Then grab/retrieve the cloud controller log bundle and find the request via parsing all of the cloud_controller_ng files.

3. Notice the output after running command (CF_TRACE=true cf create-buildpack BUILDPACK) will look similar to the below snippet: (you should see multiple of these calls associated with each command execution).

REQUEST: [2023-07-07T18:17:36Z]
GET / HTTP/1.1
Host: api.run-31.slot-##.#####-##-#####.#####.com
Accept: application/json
User-Agent: cf/6.53.0+8e2b70a4a.2020-10-01 (go1.13.8; amd64 linux)
 
RESPONSE: [2023-07-07T18:17:36Z]
HTTP/1.1 200 OK
Content-Length: 1552
Content-Type: application/json;charset=utf-8
Date: Fri, 07 Jul 2023 18:17:36 GMT
Server: nginx
X-B3-Spanid: 15bcacfe97f49209
X-B3-Traceid: 31fe2d117efd929315bcacfe97f49209
X-Content-Type-Options: nosniff
X-Vcap-Request-Id: 72a239ee-f2fa-4324-636a-1adf7d8a8e29::5cfe8ec9-75f8-4dd9-ac72-cb25dbf21207

 4. For each CF_TRACE=true "cf" command execution you should see multiple CAPI calls made by the cf cli client. Each call should have a unique Vcap Request Id. In the above example, take note of line #16 X-Vcap-Request-Id:72a239ee… At this point you can parse the /var/vcap/sys/log/cloud_controller_ng for the Vcap-Request Id:######.

• Similarly if you know which CC the request lands on then it is possible to use the Vcap request id to “grep” the clould_controller_ng file from cloud controller vm. (example screenshot of this method from my lab below)

 

 

-----------------------------------------------------------------------------------------------------------------------------------------------------
See the details in repro below to correlate the screenshot above:
----------------------------------------------------------------------------------------------------------------------------------------------------

#Command issued: ( ubuntu@opsmgr-31-####-###-#####-####-labs:~$ CF_TRACE=true cf create-buildpack java-test /tmp/java-buildpack-offline-v4.59.0.zip 3 )
 
#You will see output for each “CF_TRACE=true + cf command” detailing the numerous calls made in order to execute the command. You should see a REQUEST and RESPONSE for each call, this is where we locate and take note of the vcap_request_id:#### to follow along on the cloud controller vm in the /var/vcap/sys/log/cloud_controller_ng directory. (Will need sudo privilege)
 
# nginx-access. log - a record of all requests handled by that Node
# cloud_controller_ng. log - logs from the service which may detail information about a request (what was cc doing for the request)
 
#REQUEST1:
 
REQUEST: [2023-07-07T18:17:36Z]
GET / HTTP/1.1
Host: api.run-31.slot-35.#####-##-#####.######.com
Accept: application/json
User-Agent: cf/6.53.0+8e2b70a4a.2020-10-01 (go1.13.8; amd64 linux)
 
RESPONSE: [2023-07-07T18:17:36Z]
HTTP/1.1 200 OK
Content-Length: 1552
Content-Type: application/json;charset=utf-8
Date: Fri, 07 Jul 2023 18:17:36 GMT
Server: nginx
X-B3-Spanid: 15bcacfe97f49209 
X-B3-Traceid: 31fe2d117efd#####5bcacfe97f49209
X-Content-Type-Options: nosniff
X-Vcap-Request-Id: 72a239ee-####-4324-636a-1adf7d8a8e29::5cfe8ec9-####-4dd9-ac72-cb25dbf21207
 
#BELOW WE CAN SEE WHEN CLOUD CONTROLLER FIRST LEARNS ABOUT REQUEST AND WHEN THE NODE LEARNED OF THE REQUEST.
 
#ACCESS LOG ENTRY:
 
nginx-access.log:api.run-31.slot-35.######-###-###.######.com - [07/Jul/2023:18:17:36 +0000] "GET / HTTP/1.1" 200 1917 "-" "cf/6.53.0+8e2b70a4a.2020-10-01 (go1.13.8; amd64 linux)" 10.225.##.###, 10.225.##.###, 10.225.##.### vcap_request_id:72a239ee-####-4324-636a-1adf7d8a8e29::5cfe8ec9-75f8-4dd9-ac72-cb25dbf21207 response_time:0.012
 
 
#CLOUD CONTROLLER LOG ENTRY: (AS SHOWN BELOW, THE TOP ENTRY CC LEARNS ABOUT REQUEST AND BOTTOM ENTRY SHOWS CC COMPLETED REQUEST WITH STATUS CODE)
 
cloud_controller_ng.log:{"timestamp":"2023-07-07T18:17:36.298560458Z","message":"Started GET \"/\" for user: , ip: 10.225.##.### with vcap-request-id: 72a239ee-f2fa-4324-636a-1adf7d8a8e29::5cfe8ec9-75f8-4dd9-ac72-cb25dbf21207 at 2023-07-07 18:17:36 UTC","log_level":"info","source":"cc.api","data":{"request_guid":"72a239ee-f2fa-4324-636a-1adf7d8a8e29::5cfe8ec9-75f8-4dd9-ac72-cb25dbf21207"},"thread_id":93360,"fiber_id":93380,"process_id":6,"file":"/var/vcap/data/packages/cloud_controller_ng/2ef9e18a5996820253530635cebf3c2a803bc289/cloud_controller_ng/lib/cloud_controller/logs/request_logs.rb","lineno":14,"method":"start_request"}
 
cloud_controller_ng.log:{"timestamp":"2023-07-07T18:17:36.303965852Z","message":"Completed 200 vcap-request-id: 72a239ee-####-####-636a-1adf7d8a8e29::5cfe8ec9-####-4dd9-ac72-cb25dbf21207","log_level":"info","source":"cc.api","data":{"request_guid":"72a239ee-f2fa-4324-636a-1adf7d8a8e29::5cfe8ec9-75f8-4dd9-ac72-cb25dbf21207"},"thread_id":93360,"fiber_id":93380,"process_id":6,"file":"/var/vcap/data/packages/cloud_controller_ng/2ef9e18a5996820253530635cebf3c2a803bc289/cloud_controller_ng/lib/cloud_controller/logs/request_logs.rb","lineno":28,"method":"complete_request"}