Pivotal Knowledge Base

Follow

How to trace requests to an application at gorouter

Environment 

Product Version
Pivotal Cloud Foundry® (PCF) 1.6.x, 1.7.x
Component gorouter

Purpose

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 useful 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 which you can refer to this article

Procedure

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 VMs and look at logs

  1. Connect via Single SHell (SSH) into the Ops Manager VM
  2. With BOSH SSH, log on to gorouter VM(s) whose job name may look like this "router-partition-2cd4ed6b8375f747ca87/0"
  3. 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 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's 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. 

The caveat is that 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 a few (3 or 4) gorouters, this becomes a tedious manual process. 

Impact/Risks 

  • This information is based on the implementation details of how the gorouter generates log files, which may change at any time without formal notice.  

 

Comments

Powered by Zendesk