New Feature in Payara Server & Payara Micro 5.182: MicroProfile OpenTracing
Originally published on 05 Jul 2018
Last updated on 13 Jul 2018
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.
Related Posts
Nugget Friday - Building Resilient Microservices with MicroProfile Fault Tolerance
Published on 08 Nov 2024
by Luqman Saeed
0 Comments
While we all want maximum uptime for our software systems, failures and downtimes are inevitable. However, these can be minimized and quickly resolved through comprehensive, robust and well-designed fault tolerance mechanisms. This Nugget ...
The Payara Monthly Catch - October 2024
Published on 30 Oct 2024
by Chiara Civardi
0 Comments