New Feature in Payara Server & Payara Micro 5.182: MicroProfile OpenTracing

Published on 05 Jul 2018

Photo of Andrew Pielage by Andrew Pielage

Introduction

The 5.182 release of Payara Server & Payara Micro (Payara Platform) brings in MicroProfile (MP) 1.3. This introduces a couple of updates to some existing MP specifications, and three new ones: OpenTracing, OpenAPI, and Type-safe REST Client. In this blog I’ll be covering our implementation of OpenTracing.

 

Much like the MP OpenAPI spec, the MP OpenTracing spec actually heavily leans on a specification external to MP: This external spec is designed to give a consistent API to users of distributed tracing systems, such as Jaeger and Zipkin, and defines the structure of what these traces should look like. The MP spec builds on this by specifying that each implementation must provide a way of using an OpenTracing compliant tracer, as well as providing a new @Traced annotation for tracing methods.

 

The MicroProfile OpenTracing API

The MP OpenTracing spec provides two additions to the original OpenTracing API: an @Traced annotation and the ability to inject an OpenTracing Tracer instance into your applications.

 

The @Traced Annotation

The @Traced Annotation  allows you to specify that a method should be traced, providing a nice shortcut to manually instrumenting your code by injecting the Tracer instance, starting a trace (called a Span), and then ending the trace.

 

@Traced

public String thirsty() {

    return "Tea Guv'na?";

}

 

 

The annotation provides just two options: whether the method should be traced (the default value option of the annotation), and what the created Span should be called (operationName):

 

@Traced(operationName = “traceMe”)

 

By default, MP OpenTracing traces , even without being instrumented with this annotation, so the main use of this annotation is to either disable tracing of JAX-RS methods, or to trace additional non-JAX-RS methods.

 

@GET

@Path("endpoint3")

@Traced(value = false)

public String endpoint3() {

    return areYou.thirsty();

}

 
@Traced

public String thirsty() {

    return "Tea Guv'na?";

}

 

Injectable Tracer

MicroProfile OpenTracing also allows you to inject a Tracer instance into your application. This is just a pure, magical convenience – let the implementation deal with the shenanigans of finding and creating a Tracer!

 

import io.opentracing.Tracer;

…

@Inject

private Tracer tracer;

 

What You Can Do with the OpenTracing API

With an OpenTracing Tracer instance injected into your code, it probably makes sense to give a quick overview of what you can actually do with it.

The two main use cases are:

  • Starting and stopping traces manually:
tracer.buildSpan("manualTrace").startActive();

tracer.activeSpan().close();
  • Adding information to Spans created using the @Traced annotation:
@Traced(operationName = "greet")

public String endpoint2() {

    tracer.activeSpan().setTag("greeting", "whyHelloThere");

    return "Good Morrow!";

}

 

Those of you unfamiliar with distributed tracing are probably wondering what a Span is: in simple terms, a Span is a trace. In the OpenTracing world, a Trace is typically used to refer to a collection of one or more Spans, but in non-tech jargon it’s just a Trace with sub-traces.

 

Tags are simply used to attach information to the Span, in a key:value format. Logs are very much like tags, but also have a timestamp, so they are used for recording notable events.

 

Using MicroProfile OpenTracing with the Payara Platform

For our implementation in the Payara Platform, we elected to tie this into the existing Request Tracing Service. Tying into the existing Request Tracing Service eliminates the need to supply a third-party OpenTracing implementation as an extra dependency or library, as everything is built-in. While using  MP OpenTracing requires you to enable the Request Tracing Service (disabled by default), it also means you can quickly turn it off by disabling the service with an asadmin command (or with the Admin Console).

Integrating MP OpenTracing into the Request Tracing Service also allows you to use the other configuration options available to this service, such as the notification service and the sampling mechanisms, to create configurations such as only logging 10% of traces that take over 3 seconds to a HipChat room.

 

A Quick Example Using MP OpenTracing on a Payara Micro Instance

The following is a simple example, demonstrating how to enable Request Tracing on a Payara Micro instance, and how MP OpenTracing automatically traces JAX-RS requests.

 

So to start off, let’s create a web app with some JAX-RS endpoints:

pom.xml

<?xml version="1.0" encoding="UTF-8"?>

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">

    <modelVersion>4.0.0</modelVersion>

 

    <groupId>fish.payara.blog</groupId>

    <artifactId>opentracing</artifactId>

    <version>1.0-SNAPSHOT</version>

    <packaging>war</packaging>

 

    <name>OpenTracing Blog</name>

 

    <properties>

        <maven.compiler.source>1.8</maven.compiler.source>

        <maven.compiler.target>1.8</maven.compiler.target>

        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>

    </properties>

   

    <dependencies>

        <dependency>

            <groupId>org.eclipse.microprofile.opentracing</groupId>

            <artifactId>microprofile-opentracing-api</artifactId>

            <version>1.0</version>

            <scope>provided</scope>

        </dependency>

       

         <dependency>

            <groupId>io.opentracing</groupId>

            <artifactId>opentracing-api</artifactId>

            <version>0.30.0</version>

            <scope>provided</scope>

        </dependency>

    </dependencies>

 

    <build>

        <plugins>

            <plugin>

                <groupId>org.apache.maven.plugins</groupId>

                <artifactId>maven-war-plugin</artifactId>

                <version>3.2.2</version>

                <configuration>

                    <failOnMissingWebXml>false</failOnMissingWebXml>

                </configuration>

            </plugin>

        </plugins>

    </build>

 

</project>

 

WebApp.java

package fish.payara.blog.opentracing;

 

import java.util.Set;

import javax.ws.rs.ApplicationPath;

import javax.ws.rs.core.Application;

 

/**

 *

 * @author Andrew Pielage <andrew.pielage@payara.fish>

 */

@ApplicationPath("/")

public class WebApp extends Application {

    @Override

    public Set<Class<?>> getClasses() {

        Set<Class<?>> resources = new java.util.HashSet<>();

        resources.add(JaxrsEndpoints.class);

        return resources;

    }

}

 

JaxrsEndpoints.java

package fish.payara.blog.opentracing;

 

import io.opentracing.Tracer;

import javax.enterprise.context.RequestScoped;

import javax.inject.Inject;

import javax.servlet.http.HttpServletRequest;

import javax.ws.rs.GET;

import javax.ws.rs.Path;

import javax.ws.rs.client.ClientBuilder;

import javax.ws.rs.client.WebTarget;

import org.eclipse.microprofile.opentracing.Traced;

 

/**

 *

 * @author Andrew Pielage <andrew.pielage@payara.fish>

 */

@Path("/")

@RequestScoped

public class JaxrsEndpoints {

   

    @Inject

    HttpServletRequest request;

   

    @Inject

    private Tracer tracer;

   

    @Inject

    private AreYou areYou;

   

    @GET

    public String endpoint1() {

        WebTarget target = ClientBuilder.newClient().target(request.getRequestURL() + "endpoint2");

        return target.request().get(String.class);

    }

   

    @GET

    @Path("endpoint2")

    @Traced(operationName = "greet")

    public String endpoint2() {

        tracer.activeSpan().setTag("greeting", "whyHelloThere");

        return "Good Morrow!";

    }

   

    @GET

    @Path("endpoint3")

    @Traced(value = false)

    public String endpoint3() {

        return areYou.thirsty();

    }

   

}

 

AreYou.java

package fish.payara.blog.opentracing;

 

import javax.enterprise.context.RequestScoped;

import org.eclipse.microprofile.opentracing.Traced;

 

/**

 *

 * @author Andrew Pielage <andrew.pielage@payara.fish>

 */

@RequestScoped

public class AreYou {

   

    @Traced

    public String thirsty() {

        return "Tea Guv'na?";

    }

}

 

The example is a little arbitrary, but I’m just trying to demonstrate the new feature – I’m not writing a well-constructed program!

 

As you can see though, I’ve got three JAX-RS endpoints: one which creates a JAX-RS client to call another endpoint, one which I’ve edited the name of using the @Traced annotation and added some extra information using an injected Tracer, and one which disables the automatic JAX-RS tracing whilst calling another non-JAX-RS method which has tracing enabled.

 

As mentioned briefly earlier, we’ll need to create a post boot command file to enable the Request Tracing Service in Payara Micro, and configure it to our liking:

 

set-requesttracing-configuration --thresholdValue=25 --enabled=true --target=server-config --thresholdUnit=MICROSECONDS --dynamic=true

requesttracing-log-notifier-configure --dynamic=true --enabled=true --target=server-config

 

Now whenever we start Payara Micro with the --postbootcommandfile option, all of the asadmin commands above will be run shortly after it boots, enabling the Request Tracing Service and configuring it to print out any trace that takes longer than 25 microseconds to the log file (which will be pretty much everything).

 

So, with all of this, we can start a Payara Micro instance and deploy the application:

java -jar payara-micro.jar –autobindhttp --postbootcommandfile ./postboot.txt --deploy opentracing-demo-1.0-SNAPSHOT.war

 

Now, if we hit the three endpoints with a browser, we should see something akin to the following in the logs (I’ve prettified them to actually make them legible):

 

Example Log

[#|2018-06-21T17:31:17.892+0100|INFO|Payara 5.182|fish.payara.nucleus.notification.log.LogNotifierService|_ThreadID=32;_ThreadName=http-thread-pool::http-listener-1(2);_TimeMillis=1529598677892;_LevelValue=800;|

  Request execution time: 32(ms) exceeded the acceptable threshold - {"traceSpans":[

{"operationName":"processContainerRequest","spanContext":{"spanId":"a7f9c2a3-2417-45a4-802a-1e32a87d74b9","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.816+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.848+01:00[Europe/London]","traceDuration":"32000000","spanTags":[{"Server": "server"},{"Domain": "domain1"}],"references":[{"spanContext":{"spanId":"67516ebe-440a-40f9-81a8-55c6b8958775","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]},

{"operationName":"processWebserviceRequest","spanContext":{"spanId":"fd901da3-466f-497f-a531-c239a7d781b7","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.818+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.846+01:00[Europe/London]","traceDuration":"28000000","spanTags":[{"payara-tracing-relationshiptype": "[ChildOf]"},{"ResponseStatus": "200"},{"payara-tracing-parentid": "[67516ebe-440a-40f9-81a8-55c6b8958775]"},{"host": "[opensuse-leap:8080]"},{"connection": "[keep-alive]"},{"Method": "GET"},{"cache-control": "[no-cache]"},{"URL": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint2"},{"payara-tracing-traceid": "[19e2e8c6-f1e2-4a78-928e-979c9adb09e2]"},{"pragma": "[no-cache]"},{"user-agent": "[Jersey/2.27.payara-p5 (HttpUrlConnection 1.8.0_172)]"},{"accept": "[text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2]"}],"references":[{"spanContext":{"spanId":"a7f9c2a3-2417-45a4-802a-1e32a87d74b9","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]},

{"operationName":"greet","spanContext":{"spanId":"48af56f2-5a73-4108-a2ec-9d1f67c4a5a5","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.833+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.843+01:00[Europe/London]","traceDuration":"8000000","spanTags":[{"http.status_code": "200"},{"span.kind": "server"},{"greeting": "whyHelloThere"},{"http.url": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint2"},{"http.method": "GET"}],"references":[{"spanContext":{"spanId":"fd901da3-466f-497f-a531-c239a7d781b7","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]}

]}|#]

 

[#|2018-06-21T17:31:17.933+0100|INFO|Payara 5.182|fish.payara.nucleus.notification.log.LogNotifierService|_ThreadID=31;_ThreadName=http-thread-pool::http-listener-1(1);_TimeMillis=1529598677933;_LevelValue=800;|

  Request execution time: 289(ms) exceeded the acceptable threshold - {"traceSpans":[

{"operationName":"processContainerRequest","spanContext":{"spanId":"67516ebe-440a-40f9-81a8-55c6b8958775","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.636+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.925+01:00[Europe/London]","traceDuration":"289000000","spanTags":[{"Server": "server"},{"Domain": "domain1"}]},

{"operationName":"processWebserviceRequest","spanContext":{"spanId":"72064961-c163-48a5-8dcf-b57cd69f6510","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.648+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.924+01:00[Europe/London]","traceDuration":"276000000","spanTags":[{"referer": "[http://localhost:4848/common/applications/webApplicationLinks.jsf?appID=opentracing-5.182-SNAPSHOT&contextRoot=/opentracing-5.182-SNAPSHOT]"},{"accept-language": "[en-GB,en;q=0.8,de;q=0.5,zh-CN;q=0.3]"},{"ResponseStatus": "200"},{"host": "[opensuse-leap:8080]"},{"upgrade-insecure-requests": "[1]"},{"connection": "[keep-alive]"},{"Method": "GET"},{"URL": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/"},{"accept-encoding": "[gzip, deflate]"},{"user-agent": "[Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0]"},{"accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]"}],"references":[{"spanContext":{"spanId":"67516ebe-440a-40f9-81a8-55c6b8958775","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]},

{"operationName":"GET:fish.payara.blog.opentracing.JaxrsEndpoints.endpoint1","spanContext":{"spanId":"ce0ae592-340a-44ec-bf08-95837370dc55","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.687+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.923+01:00[Europe/London]","traceDuration":"236000000","spanTags":[{"http.status_code": "200"},{"span.kind": "server"},{"http.url": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/"},{"http.method": "GET"}],"references":[{"spanContext":{"spanId":"72064961-c163-48a5-8dcf-b57cd69f6510","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]},

{"operationName":"GET","spanContext":{"spanId":"be7b63e1-0169-471a-b0f8-2966313d692c","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"startTime":"2018-06-21T17:31:17.808+01:00[Europe/London]","endTime":"2018-06-21T17:31:17.904+01:00[Europe/London]","traceDuration":"96000000","spanTags":[{"http.status_code": "200"},{"span.kind": "client"},{"http.url": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint2"},{"http.method": "GET"}],"references":[{"spanContext":{"spanId":"ce0ae592-340a-44ec-bf08-95837370dc55","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"},{"spanContext":{"spanId":"ce0ae592-340a-44ec-bf08-95837370dc55","traceId":"19e2e8c6-f1e2-4a78-928e-979c9adb09e2"},"relationshipType":"ChildOf"}]}

]}|#]

 

[#|2018-06-21T17:31:18.225+0100|INFO|Payara 5.182|fish.payara.nucleus.notification.log.LogNotifierService|_ThreadID=33;_ThreadName=http-thread-pool::http-listener-1(3);_TimeMillis=1529598678225;_LevelValue=800;|

  Request execution time: 12(ms) exceeded the acceptable threshold - {"traceSpans":[

{"operationName":"processContainerRequest","spanContext":{"spanId":"e47d7f79-20b5-401c-9de6-787d8d9579e4","traceId":"85cf7b44-8b82-4bb2-bf2b-84bef243c0db"},"startTime":"2018-06-21T17:31:18.213+01:00[Europe/London]","endTime":"2018-06-21T17:31:18.225+01:00[Europe/London]","traceDuration":"12000000","spanTags":[{"Server": "server"},{"Domain": "domain1"}]},

{"operationName":"processServletRequest","spanContext":{"spanId":"b448b27b-cb45-424a-bf27-51d37bdf9ddb","traceId":"85cf7b44-8b82-4bb2-bf2b-84bef243c0db"},"startTime":"2018-06-21T17:31:18.223+01:00[Europe/London]","endTime":"2018-06-21T17:31:18.223+01:00[Europe/London]","traceDuration":"0","spanTags":[{"accept-language": "[en-GB,en;q=0.8,de;q=0.5,zh-CN;q=0.3]"},{"ResponseStatus": "404"},{"QueryString": "null"},{"host": "[opensuse-leap:8080]"},{"connection": "[keep-alive]"},{"Class": "org.apache.catalina.servlets.DefaultServlet"},{"Method": "GET"},{"URL": "http://opensuse-leap:8080/favicon.ico"},{"accept-encoding": "[gzip, deflate]"},{"user-agent": "[Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0]"},{"accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]"}],"references":[{"spanContext":{"spanId":"e47d7f79-20b5-401c-9de6-787d8d9579e4","traceId":"85cf7b44-8b82-4bb2-bf2b-84bef243c0db"},"relationshipType":"ChildOf"}]}

]}|#]

 

[#|2018-06-21T17:31:22.262+0100|INFO|Payara 5.182|fish.payara.nucleus.notification.log.LogNotifierService|_ThreadID=34;_ThreadName=http-thread-pool::http-listener-1(4);_TimeMillis=1529598682262;_LevelValue=800;|

  Request execution time: 12(ms) exceeded the acceptable threshold - {"traceSpans":[

{"operationName":"processContainerRequest","spanContext":{"spanId":"f2ac63b0-a0d8-4067-ae1c-fef0e6be3400","traceId":"c82b9c10-2efc-484b-a73e-40ba060dd0d3"},"startTime":"2018-06-21T17:31:22.249+01:00[Europe/London]","endTime":"2018-06-21T17:31:22.261+01:00[Europe/London]","traceDuration":"12000000","spanTags":[{"Server": "server"},{"Domain": "domain1"}]},

{"operationName":"processWebserviceRequest","spanContext":{"spanId":"960a4487-66cf-43bc-b2dd-b8f57638851f","traceId":"c82b9c10-2efc-484b-a73e-40ba060dd0d3"},"startTime":"2018-06-21T17:31:22.252+01:00[Europe/London]","endTime":"2018-06-21T17:31:22.261+01:00[Europe/London]","traceDuration":"9000000","spanTags":[{"accept-language": "[en-GB,en;q=0.8,de;q=0.5,zh-CN;q=0.3]"},{"ResponseStatus": "200"},{"host": "[opensuse-leap:8080]"},{"upgrade-insecure-requests": "[1]"},{"connection": "[keep-alive]"},{"Method": "GET"},{"URL": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint2"},{"accept-encoding": "[gzip, deflate]"},{"user-agent": "[Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0]"},{"accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]"}]},

{"operationName":"greet","spanContext":{"spanId":"1a1d47d2-6416-45df-8798-ea7063d5b17a","traceId":"c82b9c10-2efc-484b-a73e-40ba060dd0d3"},"startTime":"2018-06-21T17:31:22.257+01:00[Europe/London]","endTime":"2018-06-21T17:31:22.261+01:00[Europe/London]","traceDuration":"4000000","spanTags":[{"http.status_code": "200"},{"span.kind": "server"},{"greeting": "whyHelloThere"},{"http.url": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint2"},{"http.method": "GET"}]}

]}|#]

 

[#|2018-06-21T17:31:25.247+0100|INFO|Payara 5.182|fish.payara.nucleus.notification.log.LogNotifierService|_ThreadID=35;_ThreadName=http-thread-pool::http-listener-1(5);_TimeMillis=1529598685247;_LevelValue=800;|

  Request execution time: 10(ms) exceeded the acceptable threshold - {"traceSpans":[

{"operationName":"processContainerRequest","spanContext":{"spanId":"22cdfb9b-be25-454f-8207-33b1391df892","traceId":"ac703b71-c3dd-4241-a3f5-a0da9806b171"},"startTime":"2018-06-21T17:31:25.236+01:00[Europe/London]","endTime":"2018-06-21T17:31:25.246+01:00[Europe/London]","traceDuration":"10000000","spanTags":[{"Server": "server"},{"Domain": "domain1"}]},

{"operationName":"processWebserviceRequest","spanContext":{"spanId":"c7c3ba4e-55c8-4b7d-85d1-088b795e07b2","traceId":"ac703b71-c3dd-4241-a3f5-a0da9806b171"},"startTime":"2018-06-21T17:31:25.238+01:00[Europe/London]","endTime":"2018-06-21T17:31:25.246+01:00[Europe/London]","traceDuration":"8000000","spanTags":[{"accept-language": "[en-GB,en;q=0.8,de;q=0.5,zh-CN;q=0.3]"},{"ResponseStatus": "200"},{"host": "[opensuse-leap:8080]"},{"upgrade-insecure-requests": "[1]"},{"connection": "[keep-alive]"},{"Method": "GET"},{"URL": "http://opensuse-leap:8080/opentracing-5.182-SNAPSHOT/endpoint3"},{"accept-encoding": "[gzip, deflate]"},{"user-agent": "[Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0]"},{"accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]"}]},

{"operationName":"fish.payara.blog.opentracing.AreYou.thirsty","spanContext":{"spanId":"9244b209-aaab-4447-bd4a-0ede26295d2b","traceId":"ac703b71-c3dd-4241-a3f5-a0da9806b171"},"startTime":"2018-06-21T17:31:25.244+01:00[Europe/London]","endTime":"2018-06-21T17:31:25.244+01:00[Europe/London]","traceDuration":"0","references":[{"spanContext":{"spanId":"c7c3ba4e-55c8-4b7d-85d1-088b795e07b2","traceId":"ac703b71-c3dd-4241-a3f5-a0da9806b171"},"relationshipType":"ChildOf"}]}

]}|#]

 

Further Reading

Hopefully this has given you enough of an overview to get started, but if you want to keep playing, I’d recommend looking at the MicroProfile OpenTracing repo to see how things are changing in MP OpenTracing 1.1 and beyond. And as always, feel free to raise enhancement requests or issues on our GitHub Issues page or forum.

 

 Payara Server & Payara Micro Download Here 

 

 

Comments