OpenTracing EJB instrumentation

A blog post by Juraci Paixão Kröhling

apm | ejb | jaeger | opentracing | tracing



OpenTracing features more and more framework integrations, allowing for transparent instrumentation of applications with minimal effort. This blog post will show how to use the EJB instrumentation to automatically trace EJB invocations.

Jaeger with EJB traces

For this demo, we’ll generate a project using the Wildfly Swarm project generator, which allows us to have a seed project with the appropriate OpenTracing support in place. The concrete OpenTracing solution we will use is provided by the Jaeger project, which is also provided as a Wildfly Swarm Fraction.

With that, we’ll create a simple JAX-RS endpoint with an EJB facet, invoking a set of EJB services in different ways to demonstrate all the features of this integration.

Our application has one endpoint called /order, responsible for receiving requests to place orders in our system. When we call this endpoint, we also call some other EJB services, like

  • AccountService to send a notification that an order has been placed

  • OrderService to effectively place the order

  • InventoryService to change our inventory

  • InventoryNotificationService, to notify other backend systems.

As we are only interested in the tracing parts, we’ll not implement the business code itself, only the scaffolding.

Our demo project is heavily based on the opentracing-ejb-example from the repository opentracing-contrib/java-ejb. We have also prepared an archive with the final outcome of this demo, which you can use as reference.

The seed project

To generate the seed project, open the Wildfly Swarm generator and create a project with the "Group ID" io.opentracing.contrib.ejb and "Artifact ID" demo-example. Add the dependencies EJB, CDI, JAX-RS, OpenTracing, and Jaeger.

Make sure to select all listed dependencies and confirm that they are shown in the "Selected dependencies" section, otherwise, you might not have all the required fractions for this demo.

Click on Generate Project and you’ll get a ZIP file with the seed project. Uncompress it and add the following dependency to the pom.xml, within the dependencies node and after the WildFly Swarm Fractions dependencies:

    <dependency>
      <groupId>io.opentracing.contrib</groupId>
      <artifactId>opentracing-ejb</artifactId>
      <version>0.0.2</version>
    </dependency>

It’s now a good time to perform a sanity build, to make sure everything is in place. The first build might take a few minutes:

$ mvn wildfly-swarm:run
...
...
2017-07-26 12:02:19,154 INFO  [org.wildfly.swarm] (main) WFSWARM99999: WildFly Swarm is Ready

If it looks good, stop the server with Ctrl+C and let’s start coding our application!

The application

Let’s start by defining a JAX-RS endpoint that also acts as a stateless EJB. This is a common trick to get JAX-RS endpoints to be managed as EJBs, so that they can be invoked via JMX or get monitoring features. Or, in our case, to get traced via EJB interceptors.

This endpoint is where we get our HTTP requests from and where our transaction starts, from the tracing perspective. Once we receive an HTTP request, we call the AccountService#sendNotification method and then the OrderService#processOrderPlacement.

Note that we annotate the class with @Interceptors(OpenTracingInterceptor.class), which means that all methods on this class are to be traced.

src/main/java/io/opentracing/contrib/ejb/demoexample/Endpoint.java:

package io.opentracing.contrib.ejb.demoexample;

import io.opentracing.contrib.ejb.OpenTracingInterceptor;

import javax.ejb.Stateless;
import javax.inject.Inject;
import javax.interceptor.Interceptors;
import javax.ws.rs.POST;
import javax.ws.rs.Path;
import java.util.logging.Logger;

/**
 * This is a regular JAX-RS endpoint with EJB capabilities. We use the EJB capability to specify an interceptor,
 * so that every method on this class is wrapped on its own span. If the OpenTracing JAX-RS integration is being used,
 * it would be a good idea to not have the interceptor at this level, to avoid having too much "noise".
 *
 * @author Juraci Paixão Kröhling
 */
@Path("/order")
@Stateless
@Interceptors(OpenTracingInterceptor.class)
public class Endpoint {
    private static final Logger log = Logger.getLogger(Endpoint.class.getName());

    @Inject
    AccountService accountService;

    @Inject
    OrderService orderService;

    @POST
    @Path("/")
    public String placeOrder() {
        log.info("Request received to place an order");
        accountService.sendNotification();
        orderService.processOrderPlacement();
        return "Order placed";
    }

}

Our AccountService is a simple stateless EJB, responsible for sending a notification about the new order to the owner of the account. Here, we could call another service, or send an email, SMS or any other form of message.

As this is a regular EJB, we are able to automatically join the span context from the JAX-RS endpoint, making this call a child span of the main transaction. This is all transparent to you as developer.

Note again that we annotate the bean with @Interceptors(OpenTracingInterceptor.class). As our interceptor is just like any other EJB interceptor, you could use a ejb-jar.xml to automatically use this inteceptor on all available beans. Whether or not to trace all beans is a per-deployment decision, so, no ejb-jar.xml is provided by the integration.

src/main/java/io/opentracing/contrib/ejb/demoexample/AccountService.java:

package io.opentracing.contrib.ejb.demoexample;

import io.opentracing.contrib.ejb.OpenTracingInterceptor;

import javax.ejb.Stateless;
import javax.interceptor.Interceptors;
import java.util.logging.Logger;

/**
 * This is a simple synchronous EJB, without any knowledge about span context or other OpenTracing semantics. All it
 * does is specify an interceptor and it's shown as the child of a parent span.
 *
 * @author Juraci Paixão Kröhling
 */
@Stateless
@Interceptors(OpenTracingInterceptor.class)
public class AccountService {
    private static final Logger log = Logger.getLogger(AccountService.class.getName());

    public void sendNotification() {
        log.info("Notifying the account owner about a new order");
    }
}

Our OrderService is responsible for actually placing the order: it’s where the business knowledge resides. We’ll later look into details at the InventoryService, but for now, we need to know that this service requires a SpanContext to be explicitly passed. We can get this context from the EJBContext, stored under a context data entry that can be retrieved with the constant io.opentracing.contrib.ejb.OpenTracingInterceptor.SPAN_CONTEXT.

src/main/java/io/opentracing/contrib/ejb/demoexample/OrderService.java:

package io.opentracing.contrib.ejb.demoexample;

import io.opentracing.SpanContext;
import io.opentracing.contrib.ejb.OpenTracingInterceptor;

import javax.annotation.Resource;
import javax.ejb.EJBContext;
import javax.ejb.Stateless;
import javax.inject.Inject;
import javax.interceptor.Interceptors;
import java.util.logging.Logger;

import static io.opentracing.contrib.ejb.OpenTracingInterceptor.SPAN_CONTEXT;

/**
 * This is a regular synchronous stateless EJB. It demonstrates how to get the span context for the span it's wrapped
 * on. This can be used to pass down the call chain, create child spans or add baggage items.
 *
 * @author Juraci Paixão Kröhling
 */
@Stateless
@Interceptors(OpenTracingInterceptor.class)
public class OrderService {
    private static final Logger log = Logger.getLogger(OrderService.class.getName());

    @Resource
    EJBContext ctx;

    @Inject
    InventoryService inventoryService;

    public void processOrderPlacement() {
        log.info("Placing order");
        Object ctxParentSpan = ctx.getContextData().get(SPAN_CONTEXT);
        if (ctxParentSpan instanceof SpanContext) {
            inventoryService.changeInventory((SpanContext) ctxParentSpan);
            return;
        }

        inventoryService.changeInventory(null);
    }
}

Our InventoryService is responsible for interfacing with backend systems dealing with inventory control. We don’t want to block the parent transaction while interacting with those systems, so, we make this an asynchronous EJB. When dealing with asynchronous objects, it’s a good idea to be explicit about the span context, as there are potential concurrency issues when sharing a context between a synchronous and an asynchronous bean.

The OpenTracing EJB integration is able to intercept the method call and detect if there is a span context among the parameters, which is the case of the changeInventory(SpanContext) method. In this situation, the following happens behind the scenes:

  1. The caller makes a method call, passing the SpanContext

  2. The interceptor is activated, creating a new child span using the SpanContext as the parent

  3. The interceptor replaces the original SpanContext with this new child span on the method call

  4. The intercepted method is finally invoked, wrapped by the new child span.

Note that the SpanContext passed by the OrderService is not the same as the one received by InventoryService. While this might cause some confusion, we believe this is the right semantic for this use case, as it allows for a complete tracing picture, without any explicit tracing code, apart from passing the context around.

src/main/java/io/opentracing/contrib/ejb/demoexample/InventoryService.java

package io.opentracing.contrib.ejb.demoexample;

import io.opentracing.SpanContext;
import io.opentracing.contrib.ejb.OpenTracingInterceptor;

import javax.ejb.Asynchronous;
import javax.ejb.Stateless;
import javax.inject.Inject;
import javax.interceptor.Interceptors;
import java.util.logging.Logger;

/**
 * This is an asynchronous stateless EJB with spans created automatically by the interceptor. Note that the span context
 * that this method sees is <b>not</b> the same as the span context sent by the caller: the interceptor wraps this
 * method call on its own span, and replaces the span context by the context of this new span. This is done so that this
 * span context can be passed along to the next service "as is".
 *
 * @author Juraci Paixão Kröhling
 */
@Asynchronous
@Stateless
@Interceptors({OpenTracingInterceptor.class})
public class InventoryService {
    private static final Logger log = Logger.getLogger(InventoryService.class.getName());

    @Inject
    InventoryNotificationService inventoryNotificationService;

    public void changeInventory(SpanContext context) {
        log.info("Changing the inventory");
        inventoryNotificationService.sendNotification(context);
    }
}

And finally, our last service, InventoryNotificationService: in this case, we notify another set of backend systems that a new order has been placed. Again, this is an asynchronous EJB and works like the one above, but additionally, we wanted to manually create a "business span", called sendNotification. This method could send several notifications, wrapping each one into a span of its own. As we manually started it, we manually finish it as well.

src/main/java/io/opentracing/contrib/ejb/demoexample/InventoryNotificationService.java

package io.opentracing.contrib.ejb.demoexample;

import io.opentracing.Span;
import io.opentracing.SpanContext;
import io.opentracing.util.GlobalTracer;

import javax.ejb.Asynchronous;
import javax.ejb.Stateless;
import java.util.logging.Logger;

/**
 * This is the final call in the chain. This is an asynchronous stateless EJB, which obtains the span context
 * via a method parameter. This bean is not intercepted in any way by us, so, the span context received is exactly
 * the same as what was sent by the caller.
 *
 * @author Juraci Paixão Kröhling
 */
@Stateless
@Asynchronous
public class InventoryNotificationService {
    private static final Logger log = Logger.getLogger(InventoryNotificationService.class.getName());

    public void sendNotification(SpanContext context) {
        Span span = GlobalTracer.get().buildSpan("sendNotification").asChildOf(context).startManual();
        log.info("Sending an inventory change notification");
        span.finish();
    }

}

Now, let’s do a final sanity check and see if everything is in the right place: mvn wildfly-swarm:run . As before, the final message should be WildFly Swarm is Ready. Hit Ctrl+C and let’s setup our tracing backend.

The tracing backend

Instrumenting our code is one part of the story. The other part is to plug in an actual OpenTracing implementation that is capable of capturing the spans and submitting them to a backend service. For our demo, we’ll use Jaeger. If you don’t have a Jaeger server running yet, one can be started via Docker as follows:

docker run \
    --rm \
    -p5775:5775/udp \
    -p6831:6831/udp \
    -p6832:6832/udp \
    -p5778:5778 \
    -p16686:16686 \
    -p14268:14268 \
    --name jaeger \
    jaegertracing/all-in-one:latest

Tying everything together

Now that we have our code ready and a tracing backend, let’s start Wildfly Swarm passing a service name, which is the only property required by the Jaeger client. By default, Jaeger’s Java tracer will attempt to send traces via UDP to a Jaeger Agent located on the local machine. If you are using a different architecture, refer to the Jaeger’s documentation on how to use environment variables to configure the client, or refer to the Jaeger’s fraction for Wildfly Swarm.

For our demo, we’ll use a property that is recognized by the Jaeger’s Wildfly Swarm Fraction. The other two properties are telling Jaeger that every request should be sampled.

mvn wildfly-swarm:run -Dswarm.jaeger.service-name=order-processing -Dswarm.jaeger.sampler-type=const -Dswarm.jaeger.sampler-parameter=1

Watch the logs for an entry containing com.uber.jaeger.Configuration: if everything is correctly set, it should show the complete configuration of the Jaeger client, like this:

2017-07-26 12:03:09,139 INFO  [com.uber.jaeger.Configuration] (ServerService Thread Pool -- 6) Initialized tracer=Tracer(version=Java-0.20.0, serviceName=order-processing, reporter=RemoteReporter(queueProcessor=RemoteReporter.QueueProcessor(open=true), sender=UdpSender(udpTransport=ThriftUdpTransport(socket=java.net.DatagramSocket@7270de22, receiveBuf=null, receiveOffSet=-1, receiveLength=0)), maxQueueSize=100, closeEnqueueTimeout=1000), sampler=ConstSampler(decision=true, tags={sampler.type=const, sampler.param=true}), ipv4=-1062731153, tags={hostname=carambola, jaeger.version=Java-0.20.0, ip=192.168.2.111}, zipkinSharedRpcSpan=false)

Once the message WildFly Swarm is Ready is seen, we can start making requests to our endpoint:

$ curl -X POST localhost:8080/order
Order placed

And this can be seen on the server’s log:

2017-07-26 12:03:19,302 INFO  [io.opentracing.contrib.ejb.demoexample.Endpoint] (default task-2) Request received to place an order
2017-07-26 12:03:19,304 INFO  [io.opentracing.contrib.ejb.demoexample.AccountService] (default task-2) Notifying the account owner about a new order
2017-07-26 12:03:19,307 INFO  [io.opentracing.contrib.ejb.demoexample.OrderService] (default task-2) Placing order
2017-07-26 12:03:19,314 INFO  [io.opentracing.contrib.ejb.demoexample.InventoryService] (EJB default - 1) Changing the inventory
2017-07-26 12:03:19,322 INFO  [io.opentracing.contrib.ejb.demoexample.InventoryNotificationService] (EJB default - 2) Sending an inventory change notification

At this point, the complete trace with its 6 spans can be seen on Jaeger’s UI, located at http://localhost:16686/search , if you are using the Docker command we listed before.

Conclusion

EJBs are a very important part of Java EE and we expect the OpenTracing EJB framework integration to complement the other Java EE related integrations, like the Servlet and JAX-RS. In this blog post, we’ve shown how tracing EJBs can be accomplished by transparently tracing synchronous stateless EJBs, intercepting span contexts in asynchronous EJBs and by exposing the span context via EJB contexts, as well as manually starting spans to include specific business logic into the trace.




Published by Juraci Paixão Kröhling on 28 July 2017

redhatlogo-white

© 2016 | Hawkular is released under Apache License v2.0