Using Hudson/Jenkins to diagnose that intermittent failure

I have been working on one of those intermittent bugs that just won't reproduce on my machine; but will reproduce intermittently on other machines while they are running automated testing. I filled the code with trace statements, now I suspect the problem is in code that I don't control and doesn't appear to have much in the way of diagnostics in the place I am working on.

So I did the obvious thing which is to run the tests on a loop on my machine overnight, 12 hours later and 8 test iterations later, no test failures and I am no further forward.

Since the tests are failing in the Hudson farm, it make sense to try to connect the debugger up to those jobs; but I don't want to hang around to attach the remove debugger to each. Thankfully there is a workaround that will allow me to set suitable breakpoints and manage the debugger connection for me.

First of all you need to configure you IDE to accept incoming debugger connections, here are some notes on configuring JDeveloper for a listening debugger, in Netbeans you need to use the Debug->Attach menu item and select "SocketListen" as the connector and configure as per JDeveloper. In Eclipse you need to configure the debug type as "Socket Listen".

The second step is modifying your build system so that there is a target you can call that will start the test cases in debug mode. This is an example of the parameters for one of our CI jobs that passes in the right information. Note of course the blacked out text the the name of then machine you are trying to connect back to. (The java tests are started with the parameter -agentlib:jdwp=transport=dt_socket,address=xxxx.oracle.com:5000,server=n) Make sure that you don't have any firewalls running on that machine that will block the in-coming connections.

You probably will want to run to run multiple jobs at the same time if you have the nodes available, so consider checking this concurrent build box. Always a good idea to bring cakes / cookies into the office if you are going to tie up all the preflight nodes for the day.

And then all that remains is to run a bunch of jobs and wait for your breakpoint to be hit, might take a little while; but it is going be quicker than running these jobs in series on your own machine. And if your farm is Heterogeneous so much the better for reproducing intermittent failures.

You can sit back and then wait for your code to fail..... may I suggest some sessions from JavaOne while you wait?

wadl2java 1.1.3 released

So after a little bit of a pause we now have a new release of the wadl2java client generation tool. This is a wide range of improvements in this release; but the main feature is the new support for generating JAX-RS 2.0 client code.

This generated code is nearly identical to the Jersey 1.x interface so most simple code should compile straight after a swap without too many problems. If the client is making use of ClientResponse these references will have to be replaced with Response; but otherwise the interface will be consistent. I would welcome suggestions as to how I could improve what is generated.

So here is a list of items of changes in the release:

• WADL-25, a patch to allow the passing in of argument to xjc, as provided by Brian Chapman thanks for that..
• There is a problem in when there was not response content type, this type of method now returns the relevant Response object.
• Classes that are @XmlType were being wrapped incorrectly with JAXBElement and the information was being taken from the return class.
• The Proxy objects are now immutable, modifying any property created a new instance.
• There is a now a programmatic interface to override the base URI at each level. (Suggested by Luigi Tagliamonte)
• Fix for Oracle Bug 13804542, generation would fail if inner and outer class names match
• JAX-RS 2.0 generation support available in all tool modes
• Fix for Oracle Bug 14534583, where a fault element was being incorrectly upgraded from a '2006 WADL. This was causing problems with the examples SOAPUI were providing.
• Fix for Oracle Bug 1462282, where the generated exception classes were not actually used in the generated code. All exceptions now extend WebAppilcationException to make migration from 1.x to 2.x easier.
• Improved method generation, removed "application" from media types, removed duplication when method takes and returns the same type (putApplicationXmlAsApplicationXml -> putXml), moved "As" to correct location when we have a type, removed excessive method combinations where we have symmetrical media types. (eg xml,json->xml,json)
• Initial work looking at how to support JSON-Schema type generation, non functional
• Adding functional testing for generated clients as was previously only examining the generated classes. Now they are run for both 1.x and 2.x type clients.

 Thanks again as usual help from Pavel Bucek in getting this software out the door.

So what credentials do you need?

One of the features that I am very proud of in the HTTP Analyzer in JDeveloper is the ability to test a SOAP service with the minimum of fuss. Rather than having to configure security headers and understand WS-Policy we make use of the WLS JAX-WS client to read and interpret the policies defined in the WSDL and then apply abstracted credentials.

It turns out that this feature is very popular; but there is some confusion about just what information you might need to provide for a particular policy. So here is a simple summary of what is required for what type of policy.

Username Token

The simplest page just ask for a username and password. You are going to need this for policies that contains the phrase usernametoken, username, UNT or even HttpBasic and HttpDigest. The policy dictates where the values end up whether they be in an HTTP header or a WS-Security SOAP header.

X509 Certificates

The X509 panel is the most powerful and the most misunderstood. On this panel you can define a set of certificates and keys for both the client and the server.

The simplest version of this panel would be one that just contains the server key store. This is sufficient in most policy to be able to send a server an encrypted message and receive a message back. (In the most common case the server certificate is used to encrypt a symmetrical key, most likely AES,  that can be used to decrypt the message being received.)

You will also need this to verify messages that are signed by the server.

If you need to server to trust that you send the message with signing then you have to provide a identity in the form of a Public/Private key that can be used to encrypt the outgoing hashes used to sign the message. 

This client identity can also be used in leu of the username token described earlier. In the most common policy I have worked with the CN of the public certificate is used as the user identity. 

Http Keystores

Some policies will make use of a Https channel to send messages, and like the x509 certificate panel the settings come in both client and server side store.

In the simplest case this panel will just be configured with a "Trusted Certificates Keystore", so this will list with certificates or certificate signing authorities are going to be trusted by the analyser. In order to make this as easy as possible by default we append the "CA" certificates that come with Java so you can by default connect to most publish websites without any further configuration.

This will normally be enough unless the policy is defined as 2-Way HTTPS, most of the OWSM https policies I have worked with are 2-Way by default. The WLS ones tend to specify this explicitly. In the 2-Way case you again need to prove the identity of the client, and the only way of doing this is going to be with a Public/Private key that the server trusts.

STS Configuration

The final panel regards working with policies that require SAML tokens; JDeveloper is unable to issue SAML tokens itself so instead it need to get hold of a token from a STS store that is trusted by the server you are in contact with.

In this case you need to specify the URL of the endpoint of the STS service along with a security policy that will match that on the sever side. This is unfortunately a static list and has to be figured out manually. Perhaps this is something that can be improved on in a later release.

On important feature to note is that when connecting to the STS store the analyser will be using values from the other three panels that we have discussed. This might be important if you are having trouble setting up a connection.

Changing delay, and hence the order, in a DelayQueue

So I was looking at building a simple object cache that expires the objects after a given time. The obvious mechanism for this is the use the DelayedQueue class from the concurrency package in Java; but I wanted to know if it way possible to update the delay after an object has been added to the queue. Looking at the Delayed interface there didn't seem to be a good reason not to in the docs so I thought it was time to experiment.

So first of all you need to to create an instance of Delayed, this is a very simple implementation that with the switch of a flag you can basically invert the timeout order in the list. (And add a suitable offset so things happen in the right order)

static int COUNT=100;


   class DelayedSwap implements Delayed, Comparable<Delayed> {

       int index = 0;
       volatile boolean swap = false;
       long starttime;

       public DelayedSwap(int index, long starttime) {
           super();
           this.index = index;
           this.starttime = starttime;
       }

       private long getDelay() {
           return (swap ? starttime + (2*COUNT - index) * 100 :
               starttime + index * 100) - System.currentTimeMillis();
       }


       public String toString()
       {
           return index + " swapped " + swap + " delay " + getDelay();
       }

       @Override
       public long getDelay(TimeUnit unit) {
           return unit.convert(getDelay(), TimeUnit.MILLISECONDS);
       }

       @Override
       public int compareTo(Delayed delayed) {
           if (delayed == this)
               return 0;

           return (int)(getDelay(TimeUnit.MILLISECONDS) - delayed.getDelay(TimeUnit.MILLISECONDS));
       }
   }

So to test this I created a method that would create a bunch of the DelayedSwap objects and half way through processing the list switch the flag so altering the order of expiration.

public static void main(String[] args) throws InterruptedException {

       long start = System.currentTimeMillis();
       final List delayed = new ArrayList();
       for (int i = 1; i < COUNT; i++) {
           delayed.add(new DelayedSwap(i, start));
       }

       final DelayQueue dq = new DelayQueue();
       dq.addAll(delayed);

       new Thread(new Runnable() {

           @Override
           public void run() {
               try {
                   TimeUnit.SECONDS.sleep(5);
               } catch (InterruptedException e) {
               }
               for (DelayedSwap d : delayed) {
                   d.swap = true;
               }
           }
       }).start();

       while (!dq.isEmpty()) {
           System.out.println(dq.take());
       }

   }

So what I was expecting was the elements 1-50 ish written out in the correct order but instead after the swap over the elements are coming out in an arbitrary order quite far away from the request delay time.

1 swapped false delay -19
2 swapped false delay -4
3 swapped false delay -4
4 swapped false delay -4
5 swapped false delay -4
6 swapped false delay -4
7 swapped false delay -4
8 swapped false delay -4
9 swapped false delay -4
10 swapped false delay -4
11 swapped false delay -4
12 swapped false delay -4
13 swapped false delay -4
14 swapped false delay -4
15 swapped false delay -4
16 swapped false delay -4
17 swapped false delay -4
18 swapped false delay -4
19 swapped false delay -4
20 swapped false delay -4
21 swapped false delay -4
22 swapped false delay -4
23 swapped false delay -4
24 swapped false delay -4
25 swapped false delay -4
26 swapped false delay -4
27 swapped false delay -4
28 swapped false delay -4
29 swapped false delay -4
30 swapped false delay -4
31 swapped false delay -4
32 swapped false delay -4
33 swapped false delay -4
34 swapped false delay -4
35 swapped false delay -4
36 swapped false delay -4
37 swapped false delay -4
38 swapped false delay -4
39 swapped false delay -5
40 swapped false delay -4
41 swapped false delay -4
42 swapped false delay -5
43 swapped false delay -4
44 swapped false delay -5
45 swapped false delay -5
46 swapped false delay -5
47 swapped false delay -5
48 swapped false delay -5
49 swapped false delay -5
50 swapped false delay -5
51 swapped true delay -6
94 swapped true delay -4306
96 swapped true delay -4506
87 swapped true delay -3606
91 swapped true delay -4006
97 swapped true delay -4606
95 swapped true delay -4406
98 swapped true delay -4706
92 swapped true delay -4106
82 swapped true delay -3106
80 swapped true delay -2906
90 swapped true delay -3906
93 swapped true delay -4206
74 swapped true delay -2306
99 swapped true delay -4806
70 swapped true delay -1906
69 swapped true delay -1806
66 swapped true delay -1506
83 swapped true delay -3206
62 swapped true delay -1107
61 swapped true delay -1007
58 swapped true delay -707
71 swapped true delay -2007
89 swapped true delay -3807
85 swapped true delay -3407
78 swapped true delay -2707
86 swapped true delay -3507
81 swapped true delay -3007
88 swapped true delay -3707
84 swapped true delay -3307
79 swapped true delay -2807
76 swapped true delay -2507
72 swapped true delay -2107
68 swapped true delay -1707
65 swapped true delay -1407
60 swapped true delay -907
57 swapped true delay -608
55 swapped true delay -408
75 swapped true delay -2408
77 swapped true delay -2608
73 swapped true delay -2208
63 swapped true delay -1208
67 swapped true delay -1608
64 swapped true delay -1308
59 swapped true delay -808
56 swapped true delay -508
54 swapped true delay -308
53 swapped true delay -208
52 swapped true delay -108
Process exited with exit code 0.

So the trick is when you know you are going to modify the delay is to remove and then re-add the element to the queue.

// Replacement swap loop
    for (DelayedSwap d : delayed) {
        if (dq.remove(d))
        {
            d.swap = true;
            dq.add(d);
        }
    }

This run produces a more sensible set of results:

1 swapped false delay -4
2 swapped false delay -8
3 swapped false delay -14
4 swapped false delay -8
5 swapped false delay -4
6 swapped false delay -4
7 swapped false delay -4
8 swapped false delay -4
9 swapped false delay -4
10 swapped false delay -4
11 swapped false delay -4
12 swapped false delay -4
13 swapped false delay -4
14 swapped false delay -4
15 swapped false delay -4
16 swapped false delay -4
17 swapped false delay -4
18 swapped false delay -8
19 swapped false delay -4
20 swapped false delay -4
21 swapped false delay -4
22 swapped false delay -4
23 swapped false delay -4
24 swapped false delay -4
25 swapped false delay -4
26 swapped false delay -4
27 swapped false delay -4
28 swapped false delay -4
29 swapped false delay -4
30 swapped false delay -4
31 swapped false delay -4
32 swapped false delay -4
33 swapped false delay -4
34 swapped false delay -4
35 swapped false delay -4
36 swapped false delay -4
37 swapped false delay -4
38 swapped false delay -4
39 swapped false delay -5
40 swapped false delay -5
41 swapped false delay -5
42 swapped false delay -4
43 swapped false delay -4
44 swapped false delay -5
45 swapped false delay -5
46 swapped false delay -5
47 swapped false delay -5
48 swapped false delay -5
49 swapped false delay -5
50 swapped false delay -5
99 swapped true delay -5
98 swapped true delay -5
97 swapped true delay -11
96 swapped true delay -1
95 swapped true delay -5
94 swapped true delay -9
93 swapped true delay -5
92 swapped true delay -5
91 swapped true delay -5
90 swapped true delay -5
89 swapped true delay -5
88 swapped true delay -5
87 swapped true delay -5
86 swapped true delay -5
85 swapped true delay -5
84 swapped true delay -5
83 swapped true delay -5
82 swapped true delay -5
81 swapped true delay -5
80 swapped true delay -5
79 swapped true delay -5
78 swapped true delay -5
77 swapped true delay -5
76 swapped true delay -5
75 swapped true delay -5
74 swapped true delay -5
73 swapped true delay -5
72 swapped true delay -6
71 swapped true delay -5
70 swapped true delay -5
69 swapped true delay -5
68 swapped true delay -5
67 swapped true delay -5
66 swapped true delay -5
65 swapped true delay -5
64 swapped true delay -5
63 swapped true delay -6
62 swapped true delay -5
61 swapped true delay -6
60 swapped true delay -6
59 swapped true delay -6
58 swapped true delay -6
57 swapped true delay -6
56 swapped true delay -6
55 swapped true delay -6
54 swapped true delay -6
53 swapped true delay -6
52 swapped true delay -6
51 swapped true delay -6
Process exited with exit code 0.

I don't think this is a bug in the object itself, as you wouldn't expect a HashTable to orders it's self when the key changes, but I was a little bit surprise by the behaviour.

Catch a StackOverFlowError by its tail

One of the more annoying situations you might have to deal with when working with a Java program is a StackOverFlowError, if you have a nice producible test case then there are few options with regard to playing with the stack size, or setting a conditional breakpoint / trace of some kind.

But if you have a test case that might fail once in a 100 times, perhaps a race condition in AWTMulticaster as in my case, then you want to improve the diagnostics. The problem is that by default the VM won't any elements in a stack trace after the first 1024 entries. (At least for JDK 6) So if you run the following trivial example:

package other;

public class Overflow {


   public static final void call(double a, double b, double c, double d) {
       call(a,b,c,d);
   }


   public static void main(String[] args) {
       call(0,0,0,0);
   }

}

The output will stop before you get to the cause of the problem, making it very hard to resolve the issue.

> java other.Overflow 
Exception in thread "main" java.lang.StackOverflowError
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
        [ lots of lines removed ]
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
Process exited with exit code 1.

The good news is that this limit is one of the many official and unofficial things you can tweak when starting a VM.

> java -XX:MaxJavaStackTraceDepth=1000000 other.Overflow 
Exception in thread "main" java.lang.StackOverflowError
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
        [ lots of lines removed ]
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.call(Overflow.java:7)
 at other.Overflow.main(Overflow.java:12)
Process exited with exit code 1.

Notice that end of the stack now contains the root of the problem which will be incredibly useful when trying to diagnose the issue.

You probably don't want to leave this property set long term on a production servers because I am not entirely sure about the impact of it. Looking at the C++ code it appears that this is just a maximum value and won't affect most other stack traces as they are allocated in a linked list in segments of 32 entries.

try/with/resources refactoring that isn't

So I was looking at refactoring some code to use the new try/with/resources construct and found that perhaps it is not as simple as it first appears.

class Close implements AutoCloseable
   {
       @Override
       public void close() {
           System.out.println("Close");
       }
   }


   System.out.println("Normal version");


   Close close = new Close();
   try {
       throw new Error();
   }
   catch (Error e) {
       System.out.println("Catch");
   }
   finally {
       close.close();
   }

So the output for this is pretty easy to predict; but lets write it out just to be clear.

Normal version
Catch
Close

So this is pretty easy, lets throw some JDK 7 goodness on the code, this is an obvious refactoring right?

System.out.println("JDK 7 version");

   try (Close close2 = new Close()) {
       throw new Error();
   }
   catch (Error e) {
       System.out.println("Catch");
   }

So you can be pretty sure that given I am writing this up that the output is not going to be the same.

JDK 7 version
Close
Catch

So in this case the close is called before the catch, this might not be a problem but in some cases the catch block might need to make use of the resource before everything is shut down. If you want to perform a "refactoring" the code must behave the same before and after the changes. The following code is equivalent to the JDK 7 version without the try/with/resources

System.out.println("JDK 6 equivalent of JDK 7 version");

   Close close3 = new Close();
   try {
       try {
           throw new Error();
       }
       finally {
           close3.close();
       }
   }
   catch (Error e) {
       System.out.println("Catch");
   }

Just for completeness here is one possible refactoring of the original code which is functionally equivalent. Note quite as pretty I am afraid.

System.out.println("JDK 7 equivalent of original try/catch/finally");

   try (Close close4 = new Close()) {
       try {
         throw new Error();
       }
       catch (Error e) {
           System.out.println("Catch");
       }
   }

Now I ran this past my colleague Mark Warner and like me was surprised by the result. Mark pointed out that this nuance is noted in the java tutorial....

Note: A try-with-resources statement can have catch and finally blocks just like an ordinary try statement. In a try-with-resources statement, any catch or finally block is run after the resources declared have been closed.

...but it does feel like this rather important distinction is part of the small print that some people might at first glance assumed is related to the SQL example above it. (Yeah okay I didn't read the SQL example down to the end)

Again not something that will be a problem all the time; but it might be an important consideration in some quite important use cases.

try/with/resource context class loaders

For various reasons I seem to end up writing a lot of code that fiddles with the context class loader in order to get non-module code running in the OSGi environment that JDeveloper runs in. This leads to a whole bunch of code that looks like this:

 public void doSomething() {

       ClassLoader context = Thread.currentThread().getContextClassLoader();

       try {
           Thread.currentThread().setContextClassLoader(Example.class.getClassLoader());

           // Class class that required the context class loader
           Endpoint.publish(null, null);            
       }
       finally {
           Thread.currentThread().setContextClassLoader(context);

       }  
  }

Now it occurred to me that the try/with/resources feature in JDK 7 isn't just for the nasty things in life, well resources, you can use it for any operation that might previously used a try/finally for.

   public void doSomething() {

       try (CloseableContext c = contextClassLoader(Example.class)) {

           // Class class that required the context class loader
           Endpoint.publish(null, null);            
       }
   }

It would have been nice to just call the method an not to allocate any variables as in the following example but it isn't allowable in the spec.

   public void doSomething() {

       try (contextClassLoader(Example.class)) { // Compilation errors

           // Class class that required the context class loader
           Endpoint.publish(null, null);            
       }
   }

Still the implementation of this is rather trivial and does still tidy up the original code. The only wrinkle is the  need to have a public class/ interface subtype of AutoCloseable so that we can narrow the throws clause on the close() operation. If you don't do this then the original code has to deal with "throws Exception".

   public static CloseableContext contextClassLoader(Class loader) {
       return contextClassLoader(loader.getClassLoader());
   }

   public static CloseableContext contextClassLoader(ClassLoader loader) {
       final Thread currentThread = Thread.currentThread();
       final ClassLoader ocl = currentThread.getContextClassLoader();
       currentThread.setContextClassLoader(loader);
       return new CloseableContext(currentThread, ocl);
   }

   public static class CloseableContext implements AutoCloseable {
       private Thread _currentThread;
       private ClassLoader _ocl;

       private CloseableContext(Thread currentThread, ClassLoader ocl) {
           this._currentThread = currentThread;
           this._ocl = ocl;
       }

       @Override
       public void close() {
           this._currentThread.setContextClassLoader(this._ocl);
       }
   }