Distributing Tracing Lab - Java

Prerequisites

General Instructions

  1. Clone the git repository

    git clone https://github.com/ibm-cloud-architecture/learning-distributed-tracing-101.git
  2. Change to the lab directory

    cd lab-jaeger-java/solution

    The solution to the lab is located in the directory lab-jaeger-java/solution

    docker-compose is already configured to run Jaeger

    In case that stopping docker-compose doesn’t work with Ctrl-C you can stop using docker-compose stop

Test your environment

  1. Change directory to the lab:

    cd lab-jaeger-java
  2. Test the service without tracing enable

    docker-compose build
    docker-compose up
  3. Try the service

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!

Add client libraries

  1. Add the tracing client library for the java service-a, edit the file service-a/pom.xml and add the dependencies for opentracing-api, opentracing-spring-cloud-starter, and jaeger-client The pom.xml section should look like the following:

    <dependency>
        <groupId>io.opentracing</groupId>
        <artifactId>opentracing-api</artifactId>
        <version>0.31.0</version>
    </dependency>
    
    <dependency>
        <groupId>io.opentracing.contrib</groupId>
        <artifactId>opentracing-spring-cloud-starter</artifactId>
        <version>0.1.13</version>
    </dependency>
    
    <dependency>
        <groupId>io.jaegertracing</groupId>
        <artifactId>jaeger-client</artifactId>
        <version>0.31.0</version>
    </dependency>

Tracing every HTTP request

  1. Add A Bean to initialized the Tracer in the main Class in the file src/main/java/com/example/servicea/DemoApplication.java

    @Bean
    public io.opentracing.Tracer initTracer() {
      SamplerConfiguration samplerConfig = new SamplerConfiguration().withType("const").withParam(1);
      ReporterConfiguration reporterConfig = ReporterConfiguration.fromEnv().withLogSpans(true);
      return Configuration.fromEnv("service-a").withSampler(samplerConfig).withReporter(reporterConfig).getTracer();
    }
  2. Add the imports for jaegertracing in the file src/main/java/com/example/servicea/DemoApplication.java

    import io.jaegertracing.Configuration;
    import io.jaegertracing.Configuration.ReporterConfiguration;
    import io.jaegertracing.Configuration.SamplerConfiguration;
  3. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  4. Call the same API endpoint, but now is instrumented with tracing

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!
  5. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  6. Select the Service service-a from the drop-down options and click Find Traces

    java service a find trace
  7. Click on one of the traces, then expand the trace’s Tags and Logs. You should see information about the HTTP request such as http.method set to GET and http.status_code set to 200. The Logs section has two logs one with preHandle and the final log afterCompletion this gives you how much time the request took to be processed by your service business logic. In this example, it took 8ms.

    nodejs service a trace details
  8. Force an error in the service by calling the /error endpoint.

    curl http://localhost:8080/error -I
    HTTP/1.1 500
  9. Click Find Traces now it should show a trace with the error endpoint.

    java service a error
  10. Click on the trace with the /error, then expand the trace’s Tags and Logs. You should see information about the trace such as the http.status_code set to 500.

    java service a error details

Finding slow HTTP requests

In the service-a we have the API endpoint /sayHello, we used this endpoint in the previous section but called it only once. This endpoint has some strange behavior that not all responses are fast, very often the response is slow 100ms.

  1. Stop docker-compose with Ctrl+C and start it again.

    docker-compose up
  2. Run the following code to call the API multiple times or open the URL endpoint http://localhost:8080/sayHello/Carlos on the web browser and click refresh multiple time.

    i=0;
    while [ $i -lt 15 ];
    do curl http://localhost:8080/sayHello/Carlos -I -s | head -n 1; i=$((i+1));
    done;
  3. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  4. Select the Service service-a from the drop-down options and click Find Traces

    java service a slow

    In the picture above, you can see a timeline graph with each trace represented with a circle, in this case, we have 15 traces in the result set when we clicked Find Traces. Some traces are taking approximately 100ms and others are taking approximately 2ms. You can see the pattern that only every 3rd request the response is slow. When troubleshooting we are interested first on the slowest requests, you can click on one of the traces on the graph, or you can sort in the table by Longest First.

  5. Select the trace that took the longest time 103ms, expand all the information for the single-span operation /sayHello including tags and logs.

    java service a slow details
  6. The handler has a sleep step in the method sayHello that delays the response every 3rd request. Open the file src/main/java/com/example/servicea/HelloController.java and locate the culprit code.

    // simulate a slow request every 3 requests
    try {
        if (counter++ % 3 == 0) {
            Thread.sleep(100);
        }
    } catch (InterruptedException e) {
        // TODO Auto-generated catch block
        e.printStackTrace();
    }
  7. Remove the try/catch block and save the file HelloController.java.

  8. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  9. Run again the following code to call the API multiple times or open the URL endpoint http://localhost:8080/sayHello/Carlos on the web browser and click refresh multiple time.

    i=0;
    while [ $i -lt 15 ];
    do curl http://localhost:8080/sayHello/Carlos -I -s | head -n 1; i=$((i+1));
    done;
  10. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  11. Select the Service service-a from the drop-down options and click Find Traces

    java service a fast

    You can see now that all HTTP requests are fast and the problem is fixed

    Cloud Native applications can be composed of microservices and each microservice handling multiple endpoints. Having the ability to have observability allows us to narrow down to a specific service, and within that service a specific endpoint having problems, starting with a single trace and span you can increase the observability of your applications.

Tracing an HTTP handler

In the previous example, we were able to identify the endpoint /sayHello as one of interest in our service. Let’s see how can we add tracing instrumentation to the function that is handling this endpoint.

  1. Add the following imports at the top of the file HelloController.java

    import io.opentracing.Scope;
    import io.opentracing.Span;
    import io.opentracing.Tracer;
  2. In the class HelloController add the following Autowire to have access to the global tracer

    @Autowired
        private Tracer tracer;
  3. Locate the method sayHello and wrap the code in a try with a scope, this will create a new child span.

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            String response = formatGreeting(name);
            return response;
        }
    }
  4. Get a reference to the new child span say-hello-handler using the method scope.span()

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            Span span = scope.span();
            String response = formatGreeting(name);
            return response;
        }
    }
  5. The OpenTracing API supports the method log you can log an event with a name and an object. Add a log to the span with a message that contains the value of the name.

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            Span span = scope.span();
            Map<String, String> fields = new LinkedHashMap<>();
            fields.put("event", name);
            fields.put("message", "this is a log message for name " + name);
            span.log(fields);
            // you can also log a string instead of a map, key=event value=<stringvalue>
            // span.log("this is a log message for name " + name);
            String response = formatGreeting(name);
            return response;
        }
    }
  6. The OpenTracing API supports the method setTag you can tag the span with a key and any value. Add a tag that contains the response, in normal use cases you would not log the entire response and instead key values that are useful for later searching for spans. Since we are using true in .startActive(true) there is no need to call explicit span.finish().

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            Span span = scope.span();
            Map<String, String> fields = new LinkedHashMap<>();
            fields.put("event", name);
            fields.put("message", "this is a log message for name " + name);
            span.log(fields);
            // you can also log a string instead of a map, key=event value=<stringvalue>
            // span.log("this is a log message for name " + name);
            String response = formatGreeting(name);
            span.setTag("response", response);
            return response;
        }
    }
  7. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  8. Call the API endpoint.

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!
  9. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  10. Select the Service service-a from the drop-down options and click Find Traces

    java service a 2 spans

    Notice in the result items table, for the trace item that the trace indicates that there are a total of two spans 2 Spans and that service-a contains two spans service-a (2)

  11. Click the trace, expand the spans say-hello, and then expand the Tags and Logs sections.

    java service a span details

    Notice in the Tags section the tag is located with key name and the string value Hello Carlos!. Notice in the Logs section the log event with the name name and the message this is a log message for name Carlos

Tracing a function

The HTTP handler usually calls other functions to perform the business logic, when calling another function within the same service you can create a child span.

  1. The sayHello handler calls the function formatGreeting to process the input name. In the method formatGreeting create a new span using tracer.buildSpan and name the span format-greeting.

    private String formatGreeting(String name) {
        try (Scope scope = tracer.buildSpan("format-greeting").startActive(true)) {
            Span span = scope.span();
            span.log("formatting message locally for name " + name);
            String response = "Hello " + name + "!";
            return response;
        }
    }
  2. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  3. Call the API endpoint.

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!
  4. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  5. Select the Service service-a from the drop-down options and click Find Traces

    java service a 3 spans

    Notice that the trace now contains three spans.

  6. Click the trace, expand the spans say-hello and format-greeting, and then expand the Logs sections.

    java service a span formatter

    Notice the cascading effect between the three spans, the span format-greeting contains the message formatting message locally for name Carlos that we instrumented.

Distributing Tracing

You can have a single trace that goes across multiple services, this allows you to distribute tracing and better observability on the interactions between services.

In the previous example, we instrumented a single service service-a, and created a span when calling a local function to format the greeting message.

For the following example, we are going to use a remote service service-b to format the message, and returning the formatted greeting message to the HTTP client.

  1. In the file HelloController.java locate the handler function sayHello and replace the function call formatGreeting(name) with formatGreetingRemote(name).

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            Span span = scope.span();
            Map<String, String> fields = new LinkedHashMap<>();
            fields.put("event", name);
            fields.put("message", "this is a log message for name " + name);
            span.log(fields);
            String response = formatGreetingRemote(name);
            span.setTag("response", response);
            return response;
        }
    }
  2. In the method formatGreetingRemote the HTTP request is automatically instrumented, and the tracing headers inserted when calling the remote service service-b endpoint /formatGreeting.

    private String formatGreetingRemote(String name) {
        String serviceName = System.getenv("SERVICE_FORMATTER");
        if (serviceName == null) {
            serviceName = "localhost";
        }
        String urlPath = "http://" + serviceName + ":8081/formatGreeting";
        URI uri = UriComponentsBuilder //
                .fromHttpUrl(urlPath) //
                .queryParam("name", name).build(Collections.emptyMap());
        ResponseEntity<String> response = restTemplate.getForEntity(uri, String.class);
        return response.getBody();
    }
  3. The service service-b is already instrumented to trace every HTTP request using the same procedure Trace every HTTP request that we did for service service-a.

  4. Import at the top of the file src/main/java/com/example/serviceb/FormatController.java the opentracing libraries.

    import io.opentracing.Scope;
    import io.opentracing.Span;
    import io.opentracing.Tracer;
  5. In the class FormatController add the following Autowire to have access to the global tracer

    @Autowired
        private Tracer tracer;
  6. Located the HTTP handler function formatGreeting in the file FormatController.java

    public String formatGreeting(@RequestParam String name) {
        String response = "Hello, from service-b " + name + "!";
        return response;
    }
  7. Create a new child span using the parent span located in the req object as context. This will allow the trace to have an additional child span. Use the function tracer.startSpan and name the span format-greeting.

    public String formatGreeting(@RequestParam String name) {
        try (Scope scope = tracer.buildSpan("format-greeting").startActive(true)) {
            Span span = scope.span();
            String response = "Hello, from service-b " + name + "!";
            return response;
        }
    }
  8. Add a log event to the new span using the method span.log.

    public String formatGreeting(@RequestParam String name) {
        try (Scope scope = tracer.buildSpan("format-greeting").startActive(true)) {
            Span span = scope.span();
            span.log("formatting message remotely for name " + name);
            String response = "Hello, from service-b " + name + "!";
            return response;
        }
    }
  9. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  10. Call the API endpoint.

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!
  11. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  12. Select the Service service-a from the drop-down options and click Find Traces

    java services b trace

    Notice that the trace contains a total of four spans 5 Spans two for service-a(3) and two for service-b(2)

  13. Click the trace to drill down to get more details.

    java services b spans

    Notice in the top section, the summary which includes the Trace Start, Duration: 16ms, Services: 2, Depth: 5 and Total Spans: 5.

    Notice the bottom section on how the total duration of 16ms is broken down per span, and at which time each span started and ended. You can see that the time spent in service-b was 5ms, meaning that for this single HTTP request service-a spent 11ms and service-b spent 5ms.

  14. Expand the Logs sections for both spans say-hello from service-a and format-greeting from service-b.

    java services b logs

    Notice on the right side, each span has a summary each with the associated Service, Duration, and Start Time. The Start Time of a span marks the end time from the previous span.

    Notice the time for the first log message this is a log message for name Carlos in service-a is of 1ms, this means this log event happened 1ms after the trace started.

    Notice the time for the second log message formatting message remotely for name Carlos in service-b is of 4.98ms, this means this log event happened 4.98ms after the trace started in service-a.

    It is very useful to see the log events we instrumented in our endpoint handlers across services in this manner because it provides full observability of the lifecycle of the HTTP request across multiple services.

Baggage propagation

Imagine a scenario where you want to redirect all Safari users to a specific version of a service using theUser-Agent HTTP header. This is useful in canary deployments when a new version is rolled out for a specific subset of users. However, the header is present only at the first service. If the routing rule is for a service lower in a call graph then the header has to be propagated through all intermediate services. This is a great use-case for distributed context propagation which is a feature of many tracing systems.

Baggage items are key:value string pairs that apply to the given Span, its SpanContext, and all Spans which directly or transitively reference the local Span. That is, baggage items propagate in-band along with the trace itself.

Baggage items enable powerful functionality given a full-stack OpenTracing integration (for example, arbitrary application data from a mobile app can make it, transparently, all the way into the depths of a storage system), and with it some powerful costs: use this feature with care.

Use this feature thoughtfully and with care. Every key and value is copied into every local and remote child of the associated Span, and that can add up to a lot of network and CPU overhead.

  1. Locate the HTTP handler sayHello in the file HelloController.java. Use the method span.setBaggageItem('my-baggage', name) before the method call formatGreetingRemote(name) to set the baggage with key my-baggage to the value of the name parameter.

    public String sayHello(@PathVariable String name) {
        try (Scope scope = tracer.buildSpan("say-hello-handler").startActive(true)) {
            Span span = scope.span();
            Map<String, String> fields = new LinkedHashMap<>();
            fields.put("event", name);
            fields.put("message", "this is a log message for name " + name);
            span.log(fields);
            span.setBaggageItem("my-baggage", name);
            String response = formatGreetingRemote(name);
            span.setTag("response", response);
            return response;
        }
    }
  2. Locate the HTTP handler formatGreeting in the file FormatController.java. Use the method span.getBaggageItem('my-baggage') to get the value of the name parameter at service-a. For convenience log the value using span.log to see the value in the Jaeger UI.

    public String formatGreeting(@RequestParam String name) {
        try (Scope scope = tracer.buildSpan("format-greeting").startActive(true)) {
            Span span = scope.span();
            span.log("formatting message remotely for name " + name);
            String response = "Hello, from service-b " + name + "!";
            String myBaggage = span.getBaggageItem("my-baggage");
            span.log("this is baggage " + myBaggage);
            return response;
        }
    }
  3. Build and run the service. If docker-compose is already running in the terminal enter Ctrl+C to exit and stop the containers.

    docker-compose build
    docker-compose up
  4. Call the same API endpoint, but now is instrumented with tracing

    curl http://localhost:8080/sayHello/Carlos
    Hello Carlos!
  5. Open the Jaeger UI using the web browser

    open http://localhost:16686/jaeger
  6. Select the Service service-a from the drop-down options and click Find Traces. Expand the section Logs for the spans say-hello and format-greeting

    java service b baggage

    Notice that the baggage is set in the service-a with the value Carlos this baggage is propagated to all spans local or remote. In the server-b span you can see the baggage value Carlos is propagated.

Searching Traces

If you have a specific trace id you can search for it by putting the trace id on the top left search box.

You can also use a tag to search for example searching traces that have a specific HTTP status code, or one of the custom tags we added to a span.

  1. To search for traces using HTTP method GET and status code 200, enter http.status_code=200 http.method=GET on the Tags field in the search form, and then click Find Traces.

    jaeger ui search

Dependency graph

The Jaeger UI has a view for service dependencies, it shows a visual Directed acyclic graph (DAG).

Click the tab Dependencies, then click the DAG tab.

jaeger ui dependencies dag 1

Notice that the graph shows the direction with an arrow flowing from service-a to service-b. It also shows the number of traces between the services.

This is is a simple example and there is not much value for a small set of services, but when a large number of services each with multiple endpoints then the graph becomes more interesting like the following example:

jaeger ui dependencies dag 2