Pivotal Cloud Foundry® (PCF) versions 1.6.x and 1.7.x
This article discusses how to trace requests to an application at the Gorouter level. By following the procedure below, you can check when a request for a certain route was processed and at which Gorouter.
This should be used when you want to:
- Know which requests are coming into which Gorouter
- Troubleshoot performance problems by looking at logs with your application client side
Note that this article does not discuss how to trace requests at the Diego Cell level. For this, you can refer to this article.
Method 1: with cf logs
Run cf logs <your-application> to see which router instance handled requests. You will see log messages like this:
2016-07-29T22:08:53.48+0900 [RTR/0] OUT test-1.apps.example.com - [29/07/2016:13:08:43.479 +0000] "GET / HTTP/1.1" 200 0 361 "-" "curl/7.43.0" 10.64.35.253:38103 x_forwarded_for:"10.87.249.50, 10.64.35.253" x_forwarded_proto:"http" vcap_request_id:d6f6e3f2-9cc2-4a66-683e-9793172b2e80 response_time:10.004800615 app_id:fa0c940d-5eb9-4e47-ad5f-c91d729f6b85
Look for lines with [RTR/N] where RTR indicates that the line is from gorouter and N indicates its instance ID.
Here, you can see useful information such as the route "test-1.apps.example.com" and HTTP request/response information such as the method, path, version, and return code etc. Note that this message shows up after the gorouter receives the response from an application container, not when the request enters the gorouter.
This is useful if you are interested in tracing requests for a single application. But you cannot see logs for other applications or system components such as cloud controller.
Method 2: Log on to Gorouter Virtual Machines (VMs) and look at logs
- Connect via Single SHell (SSH) into the Ops Manager Virtual Machine (VM)
- With BOSH SSH, log on to gorouter VM(s) whose job name may look like this "router-partition-2cd4ed6b8375f747ca87/0"
- Look at the log file at /var/vcap/sys/log/gorouter/access.log
In the log file, you can see an entry that follows as soon as the Gorouter processes the request:
test-1.apps.example.com - [29/07/2016:06:04:50.779 +0000] "GET / HTTP/1.1" 200 0 348 "-" "curl/7.43.0" 10.64.35.253:40370 x_forwarded_for:"10.34.133.33, 10.64.35.253" x_forwarded_proto:"http" vcap_request_id:734d8980-f4a3-4f9b-707d-5c87d7f90ead response_time:0.004511341 app_id:fa0c940d-5eb9-4e47-ad5f-c91d729f6b85
Here's another example of the log for non-existent applications:
non-existent.apps.example.com - [29/07/2016:06:23:21.793 +0000] "GET / HTTP/1.1" 404 0 0 "-" "curl/7.43.0" 10.64.35.253:42735 x_forwarded_for:"10.34.133.33" x_forwarded_proto:"http" vcap_request_id:3944f7e4-d7e1-4685-4f73-5f431020c9ea response_time:- app_id:-
Notice that 404 was returned as there is no application with the route "non-existent.apps.example.com" in your system.
For live troubleshooting, you can use tail -f /var/vcap/sys/log/gorouter/access.log potentially with grep for the route of your interest so that you can check with your client side-by-side. Note that, as with Method 1, this message shows up after the Gorouter receives the response from an application container, not when the request enters the Gorouter.
This method is manual and not scalable if you have multiple Gorouters. Because traffic is load-balanced across them, you need to open a terminal to each of your Gorouters to watch for all the traffic (otherwise you could miss the request as it is sent to another Gorouter). If you have more than one (3 or 4) gorouters, this becomes a tedious manual process.
This information is based on the implementation details of how the Gorouter generates log files, which may change at any time without formal notice.