The way forward for JakartaEE packages

Many of you might have read Mike Milinkovich’s post about the negotiations between the Eclipse Foundation and Oracle over the use of the javax.* package names.

https://eclipse-foundation.blog/2019/05/03/jakarta-ee-java-trademarks/

To give a short summary: Oracle is donating all the Code and IP they have. And this is a HUGE step for them, involving hundreds of developers and even more lawyers (hey, Oracle is a huge company, they do not do anything without a lawyer involved). So I also don’t want to buy into the blame game but I’m rather thankful that they did this!

One thing we all hoped would happen did not materialise though: Oracle doesn’t want us to change anything on packages starting with javax.*. That’s a pity but it’s not worth fighting.

In the following post I’d like to share my view about how we can go forward with JakartaEE from a purely technical perspective.

What options are on the table?

Since we are not allowed to change a bit of the signatures in javax.* we need to do it somewhere else. There has been a vote already quite some time ago. And this vote was in favour of using jakarta.* for new JakartaEE specs. So it make sense to also use this package for new features in existing specs.

Preface: All those options have some drawback and I’m still not sure myself what would be the best solution.

Option A: Extend as we need changes

In the first scenario we would keep all javax.* packages alive. And if we need to enhance some interface then we’d just extend it into a new interface in the jakarta.* namespace and add the methods and functionality there when new features get added.

For example if we look at the following class:

public interface javax.servlet.ServletRequest

In case we need some additional method in there we’d just extend this interface:

public interface jakarta.servlet.ServletRequest
  extends javax.servlet.ServletRequest {
    int someNewMethod();

The benefit would be that we do not need to touch servers. We also would be perfectly backward compatible – so no user code would need to change.

But of course it also comes with a few huge bummers:

1. We cannot add any additional attributes to annotations. And there is no extending of annotations in Java…  All we could do is to copy the annotation over to jakarta.* and enhance it there. And all frameworks have to lookup both annotations. This is really annoying.

2. Whenever we have interface hierarchies, then we it becomes slightly ugly. Think about javax.json.JsonValue and it’s sub interfaces like JsonStructure, JsonArray, JsonNumber, etc .
In this case an interface in jakarta.* would need to extend both the parent in jakarta and the corresponding javax class:

public interface jakarta.json.JsonNumber 
  extends javax.json.JsonNumber, jakarta.json.JsonValue 

3.) It becomes virtually impossible for abstract class hierarchies. Except I missed something.
In the old days (before default methods got introduced in Java8) abstract classes have been used instead of interfaces to allow adding methods without forcing users to implement them. We see this prominently in JSF for example in ResourceHandler.java and ResourceHandlerWrapper.java

javax.faces.application.ResourceHandlerWrapper extendsjavax.faces.application.ResourceHandler {

But how to map this to jakarta.*?

public abstract class 
  jakarta.faces.application.ResourceHandlerWrapper 
    extends javax.faces.application.ResourceHandlerWrapper 

and

public abstract class 
  jakarta.faces.application.ResourceHandler 
    extends javax.faces.application.ResourceHandler

But then jakarta.faces.application.ResourceHandlerWrapper is not an instance of jakarta.faces.application.ResourceHandler anymore 😦

Option B: Extend all interfaces and classes now

This is basically option A, but we do already extend all the interfaces in JakartaEE 8.
And of course they would for now all be empty.

The main benefit of this would be that users could migrate over all features from javax.* to jakarta.* without having to think about what is there and what not.

[See update 2019-05-07 for additional issues which popped up]

Option C: Replace all javax.* with jakarta.*

This is pretty much the most aggressive option. But it has some benefits as well. It would be a clean cut and while users would have to migrate, they only need to do it once. And the rules are really straight forward and clean. Just replace all javax.* imports with jakarta.*.

Of course this option also doesn’t come for free. in this cases it is not even the fault of JavaEE. There are still some JavaSE classes which reference classes which actually belong to JavaEE specifications. JSR-250 common-annotations (javax.annotation.*) is an example. Other nasty mix-ups are in the javax.security and java.sql area as shown in the following case:

public interface javax.sql.XAConnection extends PooledConnection { 
 javax.transaction.xa.XAResource getXAResource() throws SQLException;

Since javax.sql.XAConnection is not in JakartaEE but in SE we do not have any control over the return type. This will remain returning javax.tranxaction.xa.XAResource for some time…

What we might do is to do the reverse to Option A in such cases. By default we just migrate specs to jakarta.*. But in rare cases – as the one above – we extend the original javax types. That way we would at least allow to be upcast able.

How to migrate older applications?

Such a jakarta-only server could still serve old applications which use the javax.* APIs. In this case we would provide a javaagent which does a Class-transform and basically rewrites every JavaEE import to the corresponding JakartaEE import on the fly (in memory). Of course this is just a hack, but it might work out pretty fine.

We might also provide tools like a maven-plugin which dose the shade and transform during the build already.

Or containers also might op for doing this transformation when an app gets deployed to the server or on the first startup.

And what about the timeframe?

Initially it was concluded that JakartaEE 8 would be just a re-release of exact the same content as JavaEE 8.
With the only difference that it is now handled under the umbrella of the Eclipse Foundation, and not the JCP anymore.

Would this still hold true, then we would get a JakartaEE 8 with javax.* and JakartaEE 9 with jakarta.* packages. That might potentially be really confusing.

I personally would rather prefer to prepare the rename now and already ship JakartaEE 8 with the jakarta.* packages.

Final thoughts

All those ideas are just the beginning. We need to dig deeper, try ideas out and stick our heads together to come up with the best solution for everyone. There will most likely not be a perfect solution. But rest assured that we will not do stupid things!

Update 2019-05-07

I had a discussion with Emily Jiang on twitter during which I found one more potential problem for Option A and B: We must keep parameters for all interfaces which are expected to be implemented by users. Be it directly in form of e.g. javax.servlet.Servlet or javax.servlet.Filter or indirectly by having wrappers in user code.

Any input parameter would basically remain javax.* forever. Let’s look at an example. We migrate javax.servlet.Filter to jakarta.*:

public interface jakarta.servlet.Filter
  extends javax.servlet.Filter {..
     void doFilter(javax.servlet.ServletRequest request, 
                   javax.servlet.ServletResponse response,
                   javax.servlet.FilterChain chain) throws .. ;

I think it’s pretty obvious that we cannot change this signature, right? But on the other hand we might want to enhance the ServletRequest, so we’d need to introduce a jakarta.servlet.ServletRequest extends javax.servlet.ServletRequest. And since we cannot change the Filter method signature we’d have a big upcast party in all the code which touches it. Not a showstopper, but also certainly not nice.

Categorisation of APIs

I think we have a few different kind of APIs

  • Interfaces which must be implemented by the users.
  • Interfaces which are purely ‘used’, but never implemented in user code.
  • Interfaces which are mostly ‘used’, but sometimes wrapped in user code.

I’d say we should find a few of each and then play how they feel when assuming Option A, B and C before we decide which way to go.

Update 2019-05-10

I’ve already implemented quite a few spec APIs with the new package names (Option C style).

The APIs themselves are in the Apache Geronimo Spec Jakarta Branch Repository. This is work in progress and will be updated continuously.

I’ve also already migrated the core parts of the Apache OpenWebBeans CDI Container.

And finally we also already have an ok-ish branch for Apache Tomcat 10

It is certainly a lot of work to migrate to the new package space. But so far I did not hit any showstoppers!

To beans or not to beans.xml?

When to use a beans.xml file in your CDI application?

Today there was a discussion on Twitter whether beans.xml can simply be left away these days. This feature actually exists since the CDI-1.1 specification but results in a slightly different handling of your application.

META-INF/beans.xml present

In the old CDI-1.0 days one always had to add a META-INF/beans.xml file as a marker.

If a classpath entry has a META-INF/beans.xml file present then this is called an Explicit Bean Archive.

If we have an Explicit Bean Archive and no further bean-discovery-mode is defined, every class which is a candidate to be a bean will get picked up during class scanning and a ProcessAnnotatedType CDI Lifecycle event (PAT event) is being fired for it. There are not many classes which will not get handled that way. E.g. no PAT event will get fired for a non-static inner class. But you will even get a PAT for interfaces or abstract classes and enums for example!

And this feature (PAT for interfaces, etc) is often used via CDI Extensions to collect information or automatically register Custom Beans. E.g. the Apache DeltaSpike @MessageBundle mechanism is based on it.

Oh, there is another implication of this mode. Every class which gets scanned and is a potential bean candidate will automatically get registered as @Dependent scoped Bean. This is a part which I really don’t like because it fills up your BeanManager with mostly useless garbage. This is especially bad for jars where you have 100s of JavaSE classes but only a few CDI features on top of it. I will later show how to solve this problem.

JAR without any beans.xml

If not beans.xml is present (or the bean-discovery-mode is set to annotated) then only classes with a Bean Defining Annotation are picked up. In this case the ProcessAnnotatedType CDI Lifecycle event will also only get fired for those classes. And of course features like @MessageBundle will simply not work in those cases.

Trimmed Bean Archives

In CDI-2.0 we added a new feature. This is somewhat similar to the explicit bean archive as we know it from CDI-1.0 but adds a feature to not automatically pick up all classes as @Dependent scoped beans.

This mode is the trim mode and can be switched on with the following inside your beans.xml file:

<beans>
  <trim/>
</beans>

The effect is the following: Every class will get picked up by the class scanning and a ProcessAnnotatedType CDI lifecycle event is fired. After the event the AnnotatedType will get inspected. If the AnnotatedType has a Bean Defining Annotation it will get registered as Bean<T>. Otherwise it will simply get ignored in the further processing.

This gives us a neat way to still make all the fancy CDI Extension tricks and use PAT as a kind of business class scanning. While at the same time we do not overly pollute our BeanManager with information he will never need again.

Optional vs “if null”

Lately I see a lot of code like

Optional.ofNullable(i).orElse(x->doBla(x));

instead of a old known:

if (i != null) {
  doBla(i);
} 

It is debatable which style is easier to read. Especially when multiple layers are nested. It’s probably a matter of preference which style works better for you personally.

But what we can measure is the performance impact. Or since I do not have thus much time today let’s just quickly guess it.

Comparing the Source

The IF variant first:

NullFoo.java

public class NullFoo {
  public void test() {
    Integer i = 47;
    if (i != null ) {
      doSomething(i);
    }
  }

  private void doSomething(Integer i) {
    // actually we do nothing
  };
}

and now the functional version:

OptionalFoo.java


import java.util.Optional;

public class OptionalFoo {
  public void test() {
    Integer i = 47;
    Optional.ofNullable(i).ifPresent(x -> doSomething(x));
  }

  private void doSomething(Integer i) {
    // actually we do nothing
  };
}

The ByteCode

Judge about the performance yourself.
First the old style code as javap -c shows you:

~/tmp/delete/optionalfoo$>javap -c NullFoo.class
Compiled from "NullFoo.java"
public class NullFoo {
  public NullFoo();
    Code:
       0: aload_0
       1: invokespecial #1                  // Method java/lang/Object."":()V
       4: return

  public void test();
    Code:
       0: bipush        47
       2: invokestatic  #2                  // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
       5: astore_1
       6: aload_1
       7: ifnull        15
      10: aload_0
      11: aload_1
      12: invokespecial #3                  // Method doSomething:(Ljava/lang/Integer;)V
      15: return
}

The important part is line 7: ifnull. This is a dog cheap operation. Any modern cpu can execute 2 or 4 such CJMPZ (compare and jump if zero) operations per clock cycle and core (especially if the target fits into the jump prediction cache).

Now let’s look at the functional style Java bytecode:

~/tmp/delete/optionalfoo$>javap -c OptionalFoo.class
Compiled from "OptionalFoo.java"
public class OptionalFoo {
  public OptionalFoo();
    Code:
       0: aload_0
       1: invokespecial #1                  // Method java/lang/Object."":()V
       4: return

  public void test();
    Code:
       0: bipush        47
       2: invokestatic  #2                  // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
       5: astore_1
       6: aload_1
       7: invokestatic  #3                  // Method java/util/Optional.ofNullable:(Ljava/lang/Object;)Ljava/util/Optional;
      10: aload_0
      11: invokedynamic #4,  0              // InvokeDynamic #0:accept:(LOptionalFoo;)Ljava/util/function/Consumer;
      16: invokevirtual #5                  // Method java/util/Optional.ifPresent:(Ljava/util/function/Consumer;)V
      19: return
}

First we see a construtor invocation for Optional via invokestatic in line 2 followed by a push of the this pointer (aload_0).
Line 11 is a pretty expensive invokedynamic operation. It used to be way worse but even in the Java8 JVM invokedynamic is considerably more expensive than invokevirtual (simple method call).
And of course the call to the ifPresent method from our own code itself as well.

Note that there is a lot more going on in the following code parts (at least to a CJMPZ):

  • Code inside the Optional constructor
  • Code inside ifPresent

Fazit

Of course, if you do not invoke the code parts a million times per second then it probably will not matter. In which case you should use the style which is more readable (I personally still prefer the old null check).

But if you have to perform serious heavy lifting, then I suggest you benchmark your code with JMH. And you will most probably end up with the classic if statement. The code using a old-school nullcheck is about 200 times faster than the Optional variant.

Better test logs in parallel maven builds

Running Apache Maven in parallel

Apache Maven has a nice way to speed up builds by leveraging multiple CPU cores to build different modules in parallel.

$> mvn clean install -T8

will take 8 cores for your build.

More on parallel builds can be found here https://cwiki.apache.org/confluence/display/MAVEN/Parallel+builds+in+Maven+3

Failure analysis in Jenkins

But did you ever try to use parallel builds on a huge project when running in Jenkins (or locally with | tee some.log) and something did break?

You will end up with a big mess in your log file because all the output from multiple threads end up interweaved with each other. And you have no clue to detect which log line comes from which thread – and thus you also have no clue which log line comes from which module. Doesn’t exactly make finding failures easy.

How to separate the log lines?

What I did in many of my business project to get rid of this problem is the following little hack (I’m using testng, but it’s similar in JUnit):

@BeforeMethod(alwaysRun=true)
public final void markThreads() {
  Thread.currentThread.setName(
      Thread.currentThread.getId() + " - " + 
      this.getClass().getSimpleName());
}

You can provide this in a base class for all your unit tests for example.
You will now get the name of the test class for each log line since the thread name gets printed out be default in all log frameworks I know.

PS: with one could also switch surefire to generate a single file per test. But that slows down the build a bit and you end up with 2500 files. And it’s rather hard to catch side effects you got from previous tests leaving over state (SHOULD not be, but such bugs happen).

*update*

Romain Manni-Bucau just pinged me whether I used some special settings to make this work. Because by default maven doesn’t log the thread names.

And indeed he is correct. I totally forgot to point this out! In the maven logging config ${MAVEN_HOME}/conf/logging/simplelogger.properties I have enabled the following settings:

org.slf4j.simpleLogger.showThreadName=true

This will make Maven show you the thread names.

There is btw also another useful switch:

org.slf4j.simpleLogger.showDateTime=true

Which will additionally output the elapsed milli seconds for the whole build. This is really useful when hunting slow build parts.

toString(), equals() and hashCode() in JPA entities

Many users have generated toString, equals() and hashCode() methods in their JPA entities.
But most times they underestimate what impact that can have.

This blog post post is inspired by a chat I had with Gavin King and Vlad Mihalcea.

Preface: I like to emphase that I take a big focus on keeping the customer code portable across different JPA vendors. Some ‘Uber trick’ might work in one JPA vendor and totally mess up the others. Each JPA provider is broken in it’s own very special way. Trust me, I know what I am talking about from both a user and a vendor perspective… The stuff I show here is the least common denominator for JBoss Hibernate, EclipseLink and Apache OpenJPA. Please shout out if you think some of the shown code does not work on one of those JPA containers.

toString()

What’s wrong with most toString() methods in entities?
Well, most of the times developers just use the ‘generated toString’ shortcut to create this method. And that means that the generated toString() method usually just reads all the attributes of your entity and prints it.

What happens if you touch an attribute really depends in a high degree which ‘mode’ your JPA provider runs in. In Hibernate you often have the pure class. In that case not much will happen if you only read the attributes which are not Collections etc. By ‘using attributes’ I mean this.fieldname and not using getters like this.getFieldname(). Simply because Hibernate does not support lazy loading for any other fields in that mode. However, if you touch a @OneToMany or an @ElementCollection field then you will force lazy loading on the first time toString() gets invoked. It might also behave different if you use the getters instead of reading the attributes.

And if you use EclipseLink, Apache OpenJPA or even Hibernate in byte-code weaving mode or if you get a javassist proxy from Hibernate(e.g from em.getReference()) then you are in even deeper troubles. Because in that case touching the attributes might trigger lazy loading for any other field as well.

I tried to explain how the enhancement or ‘weaving’ works in JPA in a blog post many years ago https://struberg.wordpress.com/2012/01/08/jpa-enhancement-done-right/ Parts of it might nowadays work a tad different but the most basic approach should still be the same.

Note that OpenJPA will generate a toString() method for you if the entity class doesn’t have one. In that case we will print the name of the entity and the primary key. And since we know the state of the _loaded fields we will also not force generating a new PK if the entity didn’t already load one from the sequence.
According to Gavin and Vlad Hibernate doesn’t generate any toString(). I have no clue whether EclipseLink does.

For other JPA implementations than Apache OpenJPA I suggest you provide a toString which looks like the following

public String toString() {
    return this.getClass().getSimpleName() + "-" + getId();
}

And not a single attribute more.

equals() and hashCode()

This is where Vlad, Gavin and I really disagree.
My personal opinion is that you shall not write own equals() nor hashCode() methods for entities.

Vlad did write a blog post about equals() and hashCode() in the past https://vladmihalcea.com/2016/06/06/how-to-implement-equals-and-hashcode-using-the-entity-identifier/

As you can see it’s not exactly easy to write a proper equals() and hashCode() method for JPA entities. Even Vlad’s advanced version does have holes. E.g. if you use em.getReference() or em.merge().
In any case, there is a point where Gavin, Vlad and I agree upon: generating equals() and hashCode() with IDEs is totally bollocks for JPA entities. It’s always broken to compare *all* fields. You would simply not be able to update your database rows 😉

IF you like to write a equals() method then compare the ids with a fallback on instance equality. And have the hashCode() always return zero as shown in Vlad’s blog.

Another way is to generated a UUID in the constructor or the getId() method. But this is pretty performance intense and also not very nice to handle on the DB side (large Strings as PK consume a lot more storage in the indexes on disk and in memory)

Using ‘natural IDs’ for equals()

That sounds promising. And IF you have a really good natural ID then it’s also a good thing. But most times you don’t.

So what makes a good naturalId? It must adhere to the following criteria:

  • it must be unique
  • it must not change

Sadly most natural IDs you think of are not unique. The social security number (SSN) in most countries? Hah, not unique! Really, there are duplicates in most countries…
Also often used in examples: the ISBN of a book. Toooo bad that those are not unique neither… Sometimes the same ISBN references different books, and sometimes the same book has multiple ISBNs assigned.

What about immutability? Sometimes a customer does not have a SSN yet. Or you simply don’t know it YET. Or you only know it further down the application process. So the SSN is null and only later get’s filled. Or you detect a collision with another person and you have to assign one of them a new SSN (that really happens more often than you think!). There is also the case where the same physical person got multiple SSN (happens more frequent as well).

Many tables also simply don’t have a good natural ID. Romain Manni-Bucau came up with the example of a Blog entry. What natural ID does a blog entry have? The date? -> Not unique. The title? -> can get changed later…

Why do you need equals() and hashCode() at all?

This is a good question. And my answer is: “you don’t !”

The argument why people think it’s needed for JPA entities is because e.g. having a field like:

@OneToMany 
private Set others;

A HashSet internally of course uses equals() and hashCode() but why do you need to provide a custom one? In my opinion the one you implicitly derive from Object.class is perfectly fine. It gives you instance-equality. And since per the JPA specification the EntityManager guarantees that you only get exactly one single entity instance for a row in the database you don’t need more. Doubt it? Then read the JPA specification yourself:

"An EntityManager instance is associated with a persistence context. A persistence context is a set of entity instances in which for any persistent entity identity there is a unique entity instance."

https://docs.oracle.com/javaee/7/api/javax/persistence/EntityManager.html

An exception where instance equality does not work is if you mix managed with detached entity instances. But that is something you should avoid at any cost as my following examples show.

Why you shouldn’t store managed and detached entities in the same Collection

Why would you do that? Instead of storing entities in a Set you can always use a Map. In that case you again don’t need any equals() nor hashCode() for the whole entity. And even then you might get into troubles.

One example is to have a ‘cache’.
Say you have a university management software which has a Course table. Courses get updated only a few times per year and only by some administrative people. But almost every page in the application reads the information. So what could be more reasonable as to simply store the Course in a shared @ApplicationScoped cache as Map for say an hour? Why don’t I use the cache management provided with some JPA containers? Many reasons. First and foremost they are not portable. They are also really tricky to configure (I’m talking about real production, not a sample app!). And you like to have FULL control over the cache!

So, having a cache is really a great idea, but *please* do not store JPA entities in the cache. At least not as long as they are managed. All is fine as long as you only run it locally and click around on your app and only do unit tests. But under heavy load in production (our app had 5 Mio page hits/day average) you will hit the following problem:

The JPA specification does not allow an EntityManager to be used from multiple threads at the same time. As a managed entity is bound to an EntityManager, this limitation also affects the entities themselves.
So while you do the em.find() and later a coursesCache.put(courseId, course) the entity is still in ‘managed’ mode! And under heavy load it *will* happen that another user gets the still managed entity from the cache before it got detached (which happens at the tx commit or request end, depending on your setup). Boooommm it goes…

How can you avoid that? Simply use a view object. Normally the full database entities with all their gory attribute details and sub-tables are not needed on an overview course list anyway. So you better use a ‘new’ query:

CourseListVO couseViewItem 
  = em.createQuery("SELECT NEW org.myproject.Course(c.id, c.name, c.,...) " +
      " FROM Course AS c WHERE...");
cache.put(courseId, courseViewItem);

By using a ‘new Query’ you will get instances which are not managed by the container. And it’s also much faster and consumes less memory btw.

Oh I’m sure there are things which are still not cosidered yet…

PS: this is not an easy topic as you might be able to judge from looking at the involved people. Gavin is the inventor of Hibernate and JPA, Vlad is the current Hibernate maintainer. And I was involved in the DODS DB layer of Lutris Enhydra in the 90s and am a long time Apache OpenJPA committer (and even the current PMC chair).

Applying interceptors to producer methods

Interceptors are really cool if you have a common problem and like to apply it to without making every single colleague copy the same code over again and again to apply a solution over the whole code base.

In my case it was the urge to log out SOAP and REST invocations to other systems. I also like to add a logCorrelationId via HTTP header to each outgoing SOAP call. You can read more about the background over in my other logCorrelation blog post.

I’ll focus on integrating SOAP clients, but you can easily do the same for REST clients as well.

Integrating a SOAP client in an EE project

Usually I create a CDI producer for my SOAP ports. That way I can easily mock them out with a local dummy implementation by just using CDI’s @Specializes or @Alternative. If you combine this with with Apache DeltaSpike @Exclude and the DeltaSpike Configuration system then you can even even enable those Mock via ProjectStage or a configuration setting.

Consider you have a WSDL and you create a SOAP client with the interface CustomerService.

What we like to get from a ‘consumer’ perspective is the following usage:

public class SomeFancyClass {
  private @Inject CustomerService customerService;
  ...
}

Which means you need a CDI producer method, e.g. something like:

@ApplicationScoped
public class CusomerServiceSoapClientProducer {
  @ConfigProperty(name = "myproject.customerService.endpointUrl")
  private String customerServiceEndpointUrl;

  @Produces
  @RequestScoped
  @LogTiming
  public CustomerService createSoapPort() {
    // generated from the WSDL, e.g. via CXF
    CustomerServiceService svc = new CustomerServiceService();
    CustomerServiceServicePort port = svc.getCustomerServiceServicePort();

    // this sets the endpoint URL during producing.
    ((BindingProvider) port).getRequestContext().
           put(BindingProvider.ENDPOINT_ADDRESS_PROPERTY, customerServiceEndpointUrl);

    return port;
  }
}

Side note: the whole class could also be @RequestScoped to get the endpoint URL evaluated on every request. We could of course also use the DeltaSpike ConfigResolver programmatically to gain the same. But the whole point of setting the endpoint URL manually is that we don’t need to change the WSDL and have to recompile the project on every server change. We can also use different endpoints for various boxes (test vs production environments, or different customers) that way.

What is this @LogTiming stuff?

Now it becomes interesting! We now have a SOAP client which looks like a regular CDI bean from a ‘user’ point of view. But we like to get more information about that outgoing call. After all it’s an external system and we have no clue how it behaves in terms of performance. That means we like to protocol each and every SOAP call and log out it’s duration. Of course since we not only have 1 SOAP service client but multiple dozen ones we like to do this via an Interceptor!

@Inherited
@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface LogTiming {
}

Applying an Interceptor on a producer method?

Of course the code written above DOES work. But it behaves totally different as many of you will guess.
If you apply an interceptor annotation to a producer method, then it will not intercept the calls to the produced bean!
Instead it will just intercept the invocation of the producer method. A producer method gets invoked when the Contextual Instance gets created. For a @Produces @RequestScoped annotated producer method this will happen the first time a method on the produced CDI bean gets called in the very request (or thread for non-servlet request based threads). And exactly this call gets intercepted.

If we would just apply a stopwatch to this interceptor then we would get the info about how long it took to create the soap client. That’s not what we want! We like to get the times from each and every usage of that CustomerService invocation! So what does our LogTiming interceptor do?

Proxying the Proxy

The trick we apply is to to use our LogTiming Interceptor to wrap the produced SOAP port in yet another proxy. And this proxy logs out the request times, etc. As explained before we cannot use CDI interceptors, but we can use java.lang.reflect.Proxy!:

@LogTiming
@Interceptor
public class WebserviceLoggingInterceptor {

    @AroundInvoke
    private Object wrapProxy(InvocationContext ic) throws Exception {
        Object producedInstance = ic.proceed();
        Class[] interfaces = producedInstance.getClass().getInterfaces();
        Class<?> returnType = ic.getMethod().getReturnType();
        return Proxy.newProxyInstance(ClassUtils.getClassLoader(null), interfaces, new LoggingInvocationHandler(producedInstance, returnType));
    }
}

This code will register our reflect Proxy in the CDI context and each time someone calls a method on the injected CustomerService it will hit the LogInvocationHandler. This handler btw can also do other neat stuff. It can pass over the logCorrelationId (explanation see my other blog post linked above) as HTTP header to the outgoing SOAP call.

The final LoggingInvocationHandler looks like the following:

public class LoggingInvocationHandler implements InvocationHandler {
    private static final long SLOW_CALL_THRESHOLD = 100; // ms
 
    private final Logger logger;
    private final T delegate;

    public LoggingInvocationHandler(T delegate, Class loggerClass) {
        this.delegate = delegate;
        this.logger = LoggerFactory.getLogger(loggerClass);
    }

    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        if (EXCLUDED_METHODS.contains(method.getName())) {
            // don't log toString(), hashCode() etc...
            return method.invoke(delegate, args);
        }

        long start = System.currentTimeMillis();

        try {
            // setting log correlation header if any logCorrelationId is set on the thread.
            String logCorrelationId = LogCorrelationUtil.getCorrelationId();
            if (StringUtils.isNotEmpty(logCorrelationId) && delegate instanceof BindingProvider) {
                BindingProvider port = (BindingProvider) delegate;
                Map<String, List> headers = (Map<String, List>) port.getRequestContext().get(MessageContext.HTTP_REQUEST_HEADERS);
                if (headers == null) {
                    headers = new HashMap<>();
                }
                headers.put(LogCorrelationUtil.REQUEST_HEADER_CORRELATION_ID, Collections.singletonList(logCorrelationId));
                port.getRequestContext().put(MessageContext.HTTP_REQUEST_HEADERS, headers);
            }

            // continue with the real call
            return method.invoke(delegate, args);
        }
        finally {
            long duration = System.currentTimeMillis() - start;
            if (duration <= SLOW_CALL_THRESHOLD) {
                logger.info("soapRemoteCall took={} ms service={} method={}", duration, delegate.getClass().getName, method.getName());
            }
            else {
                // log a more detailed msg, e.g. with params
            }
        }
    }

Limitations

Of course this trick only works if the producer method returns an interface! That’s caused by the reflect Proxies are only available for pure interfaces.

I’m trying to remove this limitations by bringing intercepetors for produced instances to CDI-2.0 as well on working on a interceptors spec change to introduce ways to create subclassing proxies as easy as interface proxies. Stay tuned!

What is LogCorrelation?

While working on an article about CDI interceptors on producer methods I mention logCorrelation. I will not go into detail on this topic over at the other blog post as it would be simply too much over there. And this gives a great topic for a separate post anyway. And here we go…

So what is LogCorrelation?

Consider you have a more or less distributed application topology. You might have a server which does maintain customer data. There might be another box handling all the document archive, another one which holds the calculation kernel, etc etc.

Nowadays all people would say that are microservices. 8 years ago all people called it SOA. To be honest I GIVE A SHIT how some sales people name it as all this is around since much longer than I’m working in the industry (which is a whoopie 25 years already). It’s just modular applications talking with each other somehow. Sometimes via SOAP or REST, but maybe even via MessageQueue, shared database tables or file based with batches handling the passing over – to me it doesn’t matter much.

But for all those the problem is the same: Consider a user clicks on some button in his browser or fat client. This triggers an ‘application action’. And this single action might hit the first server, then this server pings another one, etc. Synchronous or asynchronous also doesn’t matter. This might go all over the place in your company and even externally.  At the end something happens and the user most times gets some response. And it is really, REALLY hard to tell what’s wrong and where it went wrong if something doesn’t work as expected or returns wrong results. Often you don’t even have a clue which servers were involved. And if your whole application starts to behave ‘laggy’ then you will have a hard time judging which system you need to tinker with.

Now how cool would it be if you could follow this single action over all the involved servers?

And this is exactly what logCorrelation does!

What is the trick?

The trick is really plain simple. Each ‘action’ gets an own unique logCorrelationId. That might be a UUID for example. The only requirement is that it’s ‘decently’ unique.

If a server gets a request then he checks if there was a logCorrelationId passed to him. If so, then he takes this id and stores it in a ThreadLocal. If there was no id passed, then this is a ‘new’ action and we generate a fresh logCorrelationId. Of course this logCorrelationId will also get set as e.g. HTTP header for all subsequent outgoing HTTP calls on this very thread.

Where do I show the logCorrealationId?

Our applications now all handle this logCorrelationId properly, but where can I look at it? What is the benefit of all this?

At my customers I mainly use Apache log4j as logging backend, (often with slf4j as API). The point is that only log4j (and logback, but with way worse performance) support a nice little feature called MDC which stands for Mapped Diagnostic Context.  It is basically a ThreadLocal<Map<String, String>> which will get logged out in each and every line you log out on this very thread.

This log4j feature can also be accessed via the slf4j API. E.g. in a javax.servlet.Filter

MDC.set("correlationId", logCorrelationId);
MDC.set("sessionId", httpSessionId);
MDC.set("userId", loggedInUser.getId());

For enabling it in the log output you need to configure a ConversionPattern:

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{ISO8601} [%t] %X{sessionId} %X{userId} %X{correlationId} %-5p %c{2} %m%n"/>
        </layout>
    </appender>

If you logging is configured properly in your company and you funnel all back into log aggregation systems like ELK (OpenSource with commercial support offering) or Splunk (Commercial with limited free offering) then you can now simply follow a single action over all the various systems.

What about non-user requests?

Non user requests can sometimes even be filled with more information. At a few customers we use Camunda BPMN Suite (OpenSource with commercial support). The core has a Thread which basically polls the DB and fetches new tasks to execute from it. Those will then get ‘executed’ in a parallel thread. For those threads we intercept the Executor and fill the logCorrelationId with the camunda jobId which basically is a uuid starting with ‘cam-‘. So once a process task blows up we can exactly figure what went wrong – even on a different server.

Of course this trick is not limited to the process engine…

PS: how does my stuff look like?

Probably it’s also worth sharing my LogCorrelationUtil:

/**
 * Helper for log correlation.
 *
 * @author Mark Struberg
 */
public class LogCorrelationUtil {

    public static final String REQUEST_HEADER_CORRELATION_ID = "X_LOG_CORRELATION_ID";
    public static final String MDC_CORRELATION_ID = "correlationId";

    private LogCorrelationUtil() {
    }

    /**
     * Creates a new log correlation Id ONLY IF there is no existing one!.
     * Takes about 4 uS, because I use a much faster UUID algo
     *
     * @param logEnvironment prefix for the logCorrelationId if a new one has to be created. Determines the environment the uuid got created in.
     * @param existingLogCorrelationId oder {@code null} if there is none yet
     */
    public static String enforceLogCorrelationId(LogEnvironment logEnvironment, String existingLogCorrelationId) {
        if (existingLogCorrelationId != null && existingLogCorrelationId.length() > 0) {
            return existingLogCorrelationId;
        }
        ThreadLocalRandom random = ThreadLocalRandom.current();
        String uuid = new UUID(random.nextLong(), random.nextLong()).toString();

        if (logEnvironment != null) {
            StringBuilder sb = new StringBuilder(60);
            sb.append(logEnvironment);
            sb.append(uuid);
            uuid = sb.toString();
        }
        return uuid;
    }

    /**
     * @return the logCorrelationId for this thread or {@code null}
     */
    public static final String getCorrelationId() {
        return MDC.get(MDC_CORRELATION_ID);
    }

    /**
     * Set the given logCorrelationId for the current Thread.
     */
    public static final void setCorrelationId(String logCorrelationId) {
        MDC.put(MDC_CORRELATION_ID, logCorrelationId);
    }

    /**
     * Clears the logCorrelationId from the current Thread.
     * This method MUST be called at the end of each request 
     * to prevent mem leaks!
     */
    public static final void clearCorrelationId() {
        MDC.remove(MDC_CORRELATION_ID);
    }
}