How good intentions can grind SSL to a halt

We were running a load test of our application installed at the customer. The set up was quite complicated: several nodes running the application at the customer site and a single test server outside of the customer network struggling to send a lot of messages to the customer. The servers running there were in turn sending separate ack messages to our test server.

It also involved a firewall at the customer site, HTTPS with client authentication, custom key- and trust stores, XML digital signatures, Oracle database and Oracle AQ queues and more. And JBoss as the application server.

The setup was working all right but the customer has very strict performance requirements which we had to meet. Hence the tests.

After solving couple of obvious and not so obvious problems we reached quite a good throughput. Not what we wanted but reasonable. The problem was that when we tried to increase the load the hell broke loose.

The log files contained a large number of "send failed" messages with HTTP status code 403 and some HTML page clearly coming from the customer's firewall. The HTML was a generic "you are not allowed in" error message. The customer also reported seeing a log of "read timeout" messages in the firewall's logs.

The firewall was not really a dummy thing in our setup. It also handled SSL at the customer side. Our test server sent HTTPS messages to the firewall which did authentication magic and then passed the request to one of the nodes using HTTP. On the way back the application sent the ack messages as HTTP requests to the firewall which then initiated HTTPS to our test server.

403 errors happened both on our test server and on the servers at the customer, but the pattern was different. Under a moderate load the errors were happening at the customer side, not many, comparing to the number of messages. And first errors came quite quickly. There were no errors on the test server.

Increasing the load did not change the situation until we reached some threshold. The situation at the customer side did not change, but we immediately started to see 403 messages on our test server. Much, much more than at the customer side.

How such a problem can be analyzed? There are probably several ways but I describe what I did.

1. Switch on SSL logging on our test server: -Djavax.net.debug=ssl and rerun the tests.
   
   
2. Analyze the logs. The logs were already quite large and SSL debug setting added a lot more info. And the test server was both sending and receiving HTTPS messages. So analyzing the logs took some time. But eventually I started to see a pattern.
   

   <timestamp> INFO  [STDOUT] (<thread name>) *** ClientHello, Unknown-3.3
   <timestamp> INFO  [STDOUT] (<thread name>) *** 
   ...
   <timestamp + [10-20-30sec]> INFO  [STDOUT] (<thread name>) INFO %% Created:  [Session-101, TLS_DHE_RSA_WITH_AES_128_CBC_SHA]
   <timestamp + [20-30sec]> INFO  [STDOUT] (<thread name>) *** ServerHello, TLSv1
   ...
   <timestamp + [20-30sec]> INFO  [STDOUT] (<thread name>) *** ServerHelloDone
   <timestamp + [20-30sec]> INFO  [STDOUT] (<thread name>) WRITE: TLSv1 Alert, length = 2
   <timestamp + [20-30sec]> INFO  [STDOUT] (<thread name>) Exception sending alert: java.net.SocketException: Broken pipe
   

   So the server thread receives a ClientHello SSL message and then does something for dozens of seconds before trying to send ServerHello message. And then is it too late: the sending side has closed the connection.
   
   
3. When the same thread was again involved, the log was different:
   

   <timestamp> INFO  [STDOUT] (<thread name>) *** ClientHello, Unknown-3.3
   <timestamp> INFO  [STDOUT] (<thread name>) *** 
   <timestamp> INFO  [STDOUT] (<thread name>) %% Resuming [Session-78, TLS_DHE_RSA_WITH_AES_128_CBC_SHA]
   <timestamp> INFO  [STDOUT] (<thread name>) *** ServerHello, TLSv1
   …
   <timestamp + [200-300ms]> INFO  [STDOUT] (<thread name>) *** 
   <timestamp + [200-300ms]> INFO  [STDOUT] (<thread name>)  *** READ: TLSv1 Application Data, length = 208
   ...
   

   The delay was happening only if a new SSL session was created. It did not happen for all the created sessions though. In some cases there was some delay between ClientHello and ServerHello but not that large: well under 10 seconds.
   
   
4. Googling did not help. The most messages describe "reverse DNS lookup" problem which I believed had nothing to do with our problem. Just in case I tried to verify this with a simple test application which did not experienced any delays doing reverse DNS lookup, both for known and unknown addresses.
   
   
5. Everything I have seen so far could match 403s in the log at the customer side. The problem happened only if a new SSL session was created which did not happen that often. This explained why there were not that many 403s. And the reason for the errors starting to appear almost immediately was also clear: more SSL sessions had to be created to cope with more connection attempts from the customer to our test server.
   
   
6. The question remained: what was causing the delays. Since I am lazy I did not want waste my time on running some network traffic analysers. Good move in hindsight.
   
   Simple HTTPS tests in my development environment were OK. Reproducing the complete setup locally was out of the question. And debugging on the server ... well, I tried it, but it was extremely slow most of the time. SSH tunnel, VM server, whatever.
   
   Instead I have started the tests again and fired jstack -l <jboss_pid> in the loop redirecting the output to individual files.
   
   As soon I noticed 'broken pipe' messages in the log I stopped the test, found the thread name which logged 'broken pipe' and looked at the output of jstack to see what the thread was doing between outputting ClientHello and ServerHello. Not much, apparently:
   

   "<thread-name>" daemon prio=10 tid=0x00002aab10d17000 nid=0x354b waiting for monitor entry [0x0000000053617000]
      java.lang.Thread.State: BLOCKED (on object monitor)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - waiting to lock <0x00002aaacfc89bf0> (a java.security.SecureRandom)
    at java.math.BigInteger.randomBits(BigInteger.java:479)
   ...
    at org.bouncycastle.crypto.generators.DHParametersHelper.generateSafePrimes(Unknown Source)
    at org.bouncycastle.crypto.generators.DHParametersGenerator.generateParameters(Unknown Source)
    at org.bouncycastle.jce.provider.JDKKeyPairGenerator$DH.generateKeyPair(Unknown Source)
    at com.sun.net.ssl.internal.ssl.DHCrypt.<init>(DHCrypt.java:76)
   ...
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.clientHello(ServerHandshaker.java:425)

   This "waiting to lock <0x00002aaacfc89bf0>" was in almost every jstack output, and then multiple times. There was of course one thread holding the lock, and the thread was also processing ClientHello and generating DH (Diffie-Hellman) key pair.
   
   
7. OK, I found the bottleneck but what's next? One thing that bothered me was that bouncycastle in the stack trace, but first I concentrated on the BigInteger generation. Unfortunately, because I lost some time on that, on reading about /dev/random, /dev/urandom, and various post about the default java's SecureRandom being not that fast. But trying to switch to something else involved quite some work.
   
   
8. I decided to look at bouncycastle. As it happened the application had bouncycastle packaged because it used some of the classes but we never needed it to be a security provider. But the fact that is was there in the stack trace clearly proved that it was installed as a security provider. Fortunately the tests we were doing did not use the functionality that relied on bouncycastle so I just deleted the jars and executed the tests again.
   
   I actually ran the tests several times, with and without bouncycastle. Every run with bouncycastle had some 'broken pipe' messages in the log. Every run without it had none. And there were no delays between ClientHello and ServerHello messages.
   
   
9. Well, is bouncycastle that slow? I was not sure but I doubted. So more googling, looking at the sources of bouncycastle and the cryptoproviders that come with JDK provided the explanation.
   
   When the SSL server code needs to generate a "Diffie-Hellman" key pair for a new session, it knows only the required key strength. It asks java for a key pair generator and uses it to generate a key pair of the required strength. To generate the key pair some DH parameters (this includes large random prime numbers) are needed. A newly created bouncycastle key pair generator generates parameters first time it is used. The SSL code never reuses key pair generators.
   
   Result: bouncycastle has to generate large random prime numbers for each new key pair. The default JDK DH code generates DH parameters only once and then caches them so every newly created key pair generator just reuses what is there!
   
   Interestingly the latest version of bouncycastle (1.47) has added some caching but is it per thread and if I am not mistaken DH parameters have to be cached explicitly.
   
   
10. I verified that my findings were correct with a small test application that generated a DH key pair using a default crypto provider and bouncycastle. 4 threads doing it in parallel with the default provider took less than 100 ms and with bouncycastle more than a minute.
    
    
11. OK, the delays are explained. But why bouncycastle ended up being registered as a security provider? For my test application I had to explicitly add it with Security.addProvider(). And even then it was not used if I just asked for a DH keypair generator, it was only used when I explicitly asked for a DH keypair generator from bouncycastle.
    
    And it is not mentioned anywhere in JDK/JRE or JBoss startup or deploy files. It means that there is somewhere some piece of code that not only loads bouncycastle provider but also registers it before at least some of the JDK's default providers.
    
    Another round of tests, this time with -Djava.security.debug=provider. This produces enough information to understand when a provider is loaded. The log output clearly shows that bouncycastle is not there during startup of JBoss or after the startup completed. But almost immediately after I started to send test data some output about bouncycastle was added to the log.
    
    Unfortunately java.security.debug does not help with the most important question: what component/jar/whatever is loading a provider.
    
    
12. Last step: I modified BouncyCastleProvider so that it now prints a stack trace to the log. Another test run and we have the winner:
    

    java.lang.Exception: XXYYZZ
           at org.bouncycastle.jce.provider.BouncyCastleProvider.<init>(BouncyCastleProvider.java:78)
           at sun.reflect.xxx
    ...
           at java.lang.Class.newInstance(Class.java:308)
           at org.apache.ws.security.WSSConfig.loadProvider(WSSConfig.java:569)
    ...
           at org.apache.ws.security.WSSConfig.<init>(WSSConfig.java:304)
    ...
           at org.apache.ws.security.message.WSSecTimestamp.<init>

    This class comes from wss4j. And what a beauty it is! You can find the full source code on the internet, for example here.
    
    The important parts are:
    

    /**
         * a static boolean flag that determines whether default JCE providers
         * should be added at the time of construction.
         *
         * These providers, and the order in which they are added, can interfere
         * with some JVMs (such as IBMs).
         */
        private static boolean addJceProviders = true;
    
        /**
         * Set the value of the internal addJceProviders flag.  This flag
         * turns on (or off) automatic registration of known JCE providers
         * that provide necessary cryptographic algorithms for use with WSS4J.
         * By default, this flag is true, for backwards compatibility.  You may
         * wish (or need) to initialize the JCE manually, e.g., in some JVMs.
         */
        public static void setAddJceProviders(boolean value) {
            addJceProviders = value;
        }
        private synchronized void staticInit() {
    ...
            if (addJceProviders) {
                addJceProvider("BC", "org.bouncycastle.jce.provider.BouncyCastleProvider");
            }
    ...
        }
    ...
        private boolean loadProvider(String id, String className) {
    ...
            // Install the provider after the SUN provider (see WSS-99)
            // Otherwise fall back to the old behaviour of inserting
            // the provider in position 2. For AIX, install it after
            // the IBMJCE provider.
            //
            int ret = 0;
            for (int i = 0; i < provs.length; i++) {
                if ("SUN".equals(provs[i].getName())
                    || "IBMJCE".equals(provs[i].getName())) {
                    ret =
                        java.security.Security.insertProviderAt(
                             (java.security.Provider) c.newInstance(), i + 2);
                    break;
                }
            }
            if (ret == 0) {
                ret =
                    java.security.Security.insertProviderAt(
                         (java.security.Provider) c.newInstance(), 2);
            }
    ...
        }

    
    Wow! Not only these ... alternatively thinking ... individuals mess the environment they have no business to touch, they do it by default so if I do not want it I have to opt-out. They also knew that whatever they were doing can cause problems. They were at least once bitten by this code (WSS-99). But the code is still there. Some people just never learn. Unfortunately they lay rakes and let other people step on them.
    
    And the reason? It is there, in WSS-99: so that they can get to the strong encryption algorithms on some JDKs. Road to hell is paved with good intentions.
    
    Newsflash, guys: whatever you are doing is wrong. You have no business altering the runtime environment like that. Your jar is just a small piece of big pile of code running on a server. And the problem you just so creatively "solved" could have been solved in a much less obtrusive way, and only for those environments where the problem really existed.
    
    But no, "we know better" kicks in again.
    
    

Now the cause of the performance problem is identified but how can it be fixed? Unfortunately our application needs wss4j. But even if we did not need it, it comes with JBoss. It is there silently sitting and waiting its moment.

The best way is of course to patch wss4j. I do not have a problem with patching but unfortunately it is not a solution in our case. In many cases we can't control the environment. Quite often our application is installed into a "standard" jboss environment of a client. Normally our application is the only application in this environment but we still allowed doing only some configuration changes like JAVA_OPTS and such.

Another possibility is to make sure bouncycastle is loaded explicitly for example via jre/lib/security/java.security. But again, it is not always allowed. In addition it just does not feel right: that jdk is not used only by our application and bouncycastle is definitely not present by default in classpath.

One can repackage bouncycastle to remove class org.bouncycastle.jce.provider.BouncyCastleProvider. Or try and mess with classloading preventing this class to be loaded. But these solutions look even less attractive.

SecurityManager can help as well because adding a provider is hooked into it, but using a SecurityManager brings its own share of nuances. For starters it requires understanding SecurityManager. Good luck with it :-)

WSSConfig class has a possibility to disable this stupid functionality so going this way can also solve the problem. The only challenge here is to do it soon enough before WSSConfig manages to screw up things. The best way is building a separate jar with some JBoss deployment descriptor so that the code is triggered during JBoss startup.

To continue testing I have added some code to our application that does two things. First it disables WSSConfig's automatic provider loading. And then it checks if bouncycastle is already loaded and which DH keypair generator is used by default. If I get bouncycastle's keypair generator I just move bouncycastle to the end of the list. Yes I know I am changing the environment I have no right to touch :-) but we need to continue testing. Later I probably just move this code into a separate JBoss specific jar.

And for the authors of this wonderful library, wss4j ... Guys, there is still room for improvement. Maybe my hard drive is not partitioned optimally? Or how about patching KDE2 under FreeBSD? There are so many unsolved problems around. Do not let common sense stop you.

Do Repeat Yourself, powered by OSB

I am up to my ears in OSB now. Unfortunately I can't at the moment follow my own advice. So I am going to enjoy this fine product as much as can.

Let's start with the DRY principle and how OSB supports it. DRY is important, no doubt. Working with a complex product I expect that I can easily implement something in one place and then just reuse it in several places.

Being an enterprise product OSB is no exception here. But looking at the "do not repeat yourself" possibilities provided by OSB I wonder what has happened to people who had added these possibilities to the product.

My guess so far is that the functionality available now was released by mistake. After a release it was too late to remove or disable it. People who have added this functionality were probably fired on the spot. And since then adding anything that actually increases reuse within OSB projects was a big no-no. I am almost certain that somebody working on the next version of the product is contemplating the possibility to disable copy-paste.

In OSB there are like two or three places where you as a developer (designer? mouse-driven integration architect?) can reuse some other component or piece of code. And even these possibilities are crippled. Like the notorious OSB XQuery support (emphasis mine).

The Oracle XQuery engine fully supports all of the language features that are described in the World Wide Web (W3C) specification for XQuery with one exception: modules. For more information about ...

But OK, let's talk about a specific example, like validating an XML message against an XML schema definition. Unlike other, no so enterpricey, products, OSB is "XML- or nothing- inside" technology. All messages are converted to XML when they received, they stay XML as they pass through OSB and only when a message leaves OSB it might be converted to something else. Quite a logical requirement that it is sometimes necessary to validate these XML messages against some XML schema.

For example, I am building an OSB proxy service that is accessible as a SOAP webservice, and I want to "XML schema" validate incoming messages. OSB provides such a possibility with a nice "Validate" message processing stage action. (Too many words? Do not worry, it is just some diagram element in the design palette that I can insert somewhere in the message flow of the service I am building.) I place it on the message flow and go about configuring it (more mousing around): specify what part of the message I want to validate and the schema element or type to validate against.

This was easy. Except... What is this story about selecting a schema's type or element? I guess somebody had to think hard to come up with such a way to validate XML against a schema. I have to select not only a schema but also an element or a type within that schema! (And do not get me started on the fact that the schema has to be present somewhere within the project. I can't specify URI, URL, reference to classpath or whatever.)

Remember DRY? Now imagine a webservice with 10 or 20 operations defined in its WSDL. As a matter of fact WSDL adds some complexity of its own here, like multipart messages. But let's keep things simple: these WSDLs all use messages with a single part. And now imagine you need to deal with 5 to 10 such webservices.

This can't be true I thought! Let's google.... Hmmm... Uguh... Aha, this way... I see.... And here?... So, that's it?... No, here is another one... Guys, can I have a different Google?

The search was not really useful except for one post. But it confirmed my suspicion. Here is the list of possibilities to deal with XML schema validation in OSB, both googled and the ones I came up with:

1. Pretty obvious: ditch OSB in favor of something usable. Unfortunately won't work in most situations.


2. Delegate: find some junior developer and ask him to do it. But it is cruel. This poor soul does not deserve such a torture.


3. Much better delegation: find the person or persons responsible for choosing this product in the first place and let them do it. Ah dreams....
   
   If you lucky this might bring discussion back to point 1 above. If you are not... Either way you don't have to work with OSB anymore.
   
   Unfortunately this is not a realistic scenario either.


4. Fight against the requirement of XML schema validation. Explain. Demonstrate. Say Oracle is aware of the problem so when you migrate once more (like to version 50g) this functionality will be there for you to use.


5. Follow a Scrum master. Redefine the definition of XML validation. Be creative. If you are lucky the requirements do not say explicitly "validate XML messages against XML schema". Maybe it's just "validate". Most likely you will have to perform some business validation anyway. Sheer by mistake OSB allows some degree of freedom here. Instead of having to write N XQuery files, drag-and-drop one "case" box and then another N expression boxes you can get away with at most (N + 1) XQuery files and 1 expression box. What a relief.


6. Be creative. Ever heard about void*? java.lang.Object? xsd:any is your friend! Take your schema, copy it, change the copy to replace bulk of the existing definitions with xsd:any here and there and use this schema for validation. Nobody will notice anyway.


7. Fight against the requirement of XML schema validation. Explain. Demonstrate. I know I have this one already above. But still if none of the above solutions worked try this one again.


8. OK, you do not have a choice. XML schema validation is here and you have to implement it. Bite the bullet. If it is a single webservice with 10 or even 20 operations it is not a big deal to do it once. I mean, other options will cost more.


9. You are lazy. This is good, really. What options are left? Again, delegate. But this time delegate to some non-OSB code. There are several possibilities: OSB java callout functionality, xpath external functions, even external web services. All these solutions have their own set of challenges which you would need to solve. And this will cost you. Time to build and test it, runtime performance penalty, whatever. I did not go that far yet. But it looks like I have got myself couple of volunteers who might just go all the way. We'll see what happens.


10. Working with OSB makes you think. OSB actually encourages you to think. Or drink a lot of coffee. All that time it takes to start IDE or the OSB server, to stop the OSB server, and especially to do something in IDE.
    
    I am sorry I can't drink that much. So I ended up thinking. I'll probably switch jobs. But while I am still here I am going to try something. One never knows...

Oracle Service Bus, first impressions

Professionally I consider myself a lucky person. Quite often when I start working on a new (to me) project I get a chance to learn something new: people, techniques, a product, or some technology.

Since beginning of December 2011 I joined a team that is using quite a lot of different Oracle products. One of the products is Oracle Service Bus formerly known as AquaLogic Service Bus. I have not got a chance to work with it before so I took the opportunity to look at it closely.

Oracle Service Bus is really a shiny product that perfectly fits Oracle's SOA strategy and blah-blah-blah standards-based blah-blah-blah mission critical blah-blah-blah and blah-blah-blah. Blah-blah.


Hmmm, does anybody really believe this?!


When I was younger I was naive. Working with something I often thought: "This is baaad. I can't wait to finish this and move on. Next project will be better. Nothing can be worse than this".

Those times are long gone. I know that no matter how strange or convoluted the current project is the next most likely will be no better. The only thing left is a bit of curiosity: one never knows what kind of SNAFU du jour one comes into. But looking at OSB old memories come back. Can anything actually be worse than this?

I started writing down my impressions but researching something on OSB I came across this post. If you ever get a chance to use OSB go read it and be prepared.

The post reflects my experience with OSB and it has more information than I collected so far. Moreover the author expresses itself much more politely than I wanted to.

I am not sure if everything in that post is up to date. After all the post is like a year and a half old, so things might have improved. But do not hold your breath.

There are also some things I have experienced but they are not mentioned in the referenced post. The most amusing one is lack of undo in IDE (Eclipse with a lot of Oracle's plugins). Come on Oracle, it is 2012. No undo? Seriously, how much worse it can get? You can only do mouse-driven development in OSB. You do not want even see their XML, trust me, let alone edit it by hand. And it is really easy to mess something up with a wrong mouse move. Even changing some property or expression has no possibility of undo.


My advice? Maximize your return on investment, stay away from Oracle Service Bus.

And if you are not convinced, read on.

Assorted facts about JBoss. Fact 4: per-application logging is broken

You came here to read about setting up the per-application logging in JBoss 6? Congratulations, this is the right place to be. I have posted some info on this subject before. But if you have not read those posts no need to hurry. And if you have read them and followed the advice then forget it and undo the changes.

The per-application logging in JBoss 6 is broken beyond any possibility of repair. Even more, activating per-application logging makes the situation much worse.

Why the hell?! Need to scratch some itch? Look at the bug database, there is so much to do. "No, it is not for us, let's invent something new." And release this piece of ... software, half baked, and forget about any documentation.

So many words unspoken! Or rather unwritten; spoken they were, and a lot.

Back to the topic: why does it not work? To understand it you need first to understand how it really works.

The per-application logging configuration is bound to a classloader that loads jboss-logging.xml file with <define-context> element. When some component (your application code, some jar that come with JBoss, does not matter) invokes getLogger() the execution ends up in JBoss LogManager class. If the requested logger does not exist it has to be created. If the per-application logging is activated some helper class (ClassLoaderLogContextSelector) traverses the invocation stack starting from the most recent entry. For each entry (class) in the invocation stack the check is done whether the entry's classloader has a bound logging configuration. If such a configuration exists it is used and the traversal is stopped. If no classloader-bound logging configuration is found after the traversal the default one (coming from (deploy/jboss-logging.xml) is used.

For example, if your application with a custom jboss-logging.xml calls getLogger() then your class is very close to the top of the invocation stack:

  Some JBoss logging code
  Some more JBoss logging code
  <your class>.getLogger()
  Some other code from the application
  Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
  Thread.run()

The traversal algorithm starts with Some JBoss logging codeand goes down until it finds <your class>.getLogger(). The application has a per-application logging which is bound to the application's classloader, the very same classloader that has loaded <your class>. Bingo, the logger the application code gets back from JBoss will use the application's custom configuration.

It works even when getLogger() is used by code in some jar packaged with JBoss when your application uses that code. The invocation stack is longer, the traversal takes more time, but this is the only difference:

  Some JBoss logging code
  Some more JBoss logging code
  <library class>.getLogger()
  Some other library code, can be a lot
  Some code from the application calling the library
  Some other code from the application
  Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
  Thread.run()

So what is wrong with this?

A lot actually:

1. What a performance hog this is! Worst of all the code that does not use the per-application logging suffers the most because all the entries in the invocation stack must be checked before JBoss decides to use the default logging configuration. And stack traces under JBoss are known to be looooong. Like hundreds of entries long. To be fair JBoss warns about this problem in deployers/jboss-logging.deployer/META-INF/logmanager-jboss-beans.xml:

   <!--
     ~ These two beans define the per-classloader log context selector which allows per-deployment logging.  Since
     ~ enabling this feature may have a performance impact in certain cases, it's started up lazily (on demand)
     ~ when a separate log context is defined in a user deployment.
     -->

   Of course being JBoss code it does not actually works this way. Bug JBAS-9407 strikes back: the proposed workaround activates this stack traversal algorithm even if no component is using the per-application logging. My patch attached to this bug fixes this and makes sure the stack scanning is activated only if a component with the per-application logging configuration is deployed. But being activated the traversal code is always executed when a logger is created, regardless what component/module asks for a logger.


2. One might say this is not a big problem. After all the traversal is performed only if a new logger is created and not every time it is used to output something. And because loggers are cached it does not matter how many times getLogger() is invoked, creation and hence the traversal happens only once.
   
   But exactly this fact (traversal at creation) is one of the reasons why the per-application logging is broken. Let's look at the example above, the one with the application using some library. Here is the stack trace again:

     Some JBoss logging code
     Some more JBoss logging code
     <library class>.getLogger()
     Some other library code, can be a lot
     Some code from the application calling the library
     Some other code from the application
     Some JBoss EJB/servlet/you name it invocation code, a lot of it actually
     Thread.run()
   

   Your application calls the library, for example, JPA. JPA provider classes, Hibernate under JBoss, call getLogger(). JBoss finds the application classes in the invocation stack, so the application logging configuration is used also for Hibernate classes. Logging output from Hibernate goes to your logging file. Sun is shining, life is good. You go ahead and deploy a second application that uses JPA and per-application logging. The log file for the second application is created. Logging from the application classes goes there. But not the logging from Hibernate: it goes to the log file of the first application. Surprise!
   
   The reason is clear: when the Hibernate logger was created the classes from the first application were on the stack, so the logger became "bound" to the configuration loaded from the first application.
   
   In reality it gets much more interesting: some Hibernate logging output goes to the default JBoss log (Hibernate code is executed during the application deployment/startup), other might go to this application's log, yet another might go to some other application's log. It all depends on the invocation stack at the moment of creation of the logger. Кто первый встал, того и тапки, which roughly translates to "The first man gets the oyster, the second man gets the shell".
   
   And what happens if the first application is undeployed? Where Hibernate log goes then? I did not bother to check this: nothing good anyway.


3. As it were enough. You see, when I am talking about application-specific logging I really want the logging from the shared classes still go to the application log when the shared classes execute on behalf of the application. Even if there is yet no class from the application on the stack. For example, JBoss code that runs before invoking a servlet or an EJB business method from the application. Or a web service: there is a lot going on before the application code is invoked: XML parsing, unmarshaling, you name it. Where the logging, including error stack traces, goes? Most likely to the default logging: there is after all no classes from the application on the stack yet. Or to some other log file: the first man gets the oyster, remember?


4. It can get even stranger. What I have seen in my tests is that the app-specific logging is activated pretty late in the deployed process. If any of the application code calls getLogger() before the logging configuration is hooked up the logging from the application classes goes to the wrong place: to the default logging. Most often there is a static Logger field in a class. This results in getLogger() being invoked during the loading of the class. For example, JPA provider loads classes looking for annotations. Or CXF code looks for JAX-WS annotations. All this loading is happening before the logging configuration is bound to the application classloader.
   
   This problem can be somewhat compensated by not using a static Logger field, but it is applicable only to the code you control and not to 3rd party code. There can also be situations where static initializer does something worth logging.

Nicely implemented feature, isn't it?

You might be tempted to package more 3rd party jars in your application and play some classloading tricks to make sure that the classes are loaded from the application-packaged jars and not from JBoss-provided jars. Don't!

1. This won't buy you anything except maybe the server upgrade. The memory consumption will skyrocket, especially if there are multiple applications doing this.


2. This might help you with problems 2 and 3 above. Problems 1 and 4 remain.


3. You need to understand Java classloading pretty good. Then you have to forget it and learn the mess that JBoss made of it. And even then most likely it will not work. JBoss will not even deploy your application no matter how hard you try.
   
   For example just packaging Hibernate jars in a simplest EJB application that has otherwise no Hibernate or any other persistency dependencies is enough. If the application has JBoss classloading config that instruct JBoss to look for classes first in jars packaged with the application and only then in the parent (JBoss) clasloader the application will not deploy. While I have quite good understanding of JBoss classloading I would not even try to make this application deployable because I also understand the reason why it fails.
   
   Feel lucky? Give it a try. At best you can make this scheme work with some 3rd party jars but not with the most important and interesting, like Hibernate or CXF.

The question remains: is it actually possible to have the application-specific logging in JBoss 6?

Of course! Scrum solved that problem long time ago: a team decides what they want to have done and as they progress they can redefine what "done" means. Pretty neat and useful. You can do the same here: you can define what "application-specific" means in your case and then implement it.

Jokes aside there is not much you can actually do. The simplest and most sane solution is to forget about all that JBoss woodoo with the application-specific logging. Rollback the workaround for bug JBAS-9407. Use the default logging configuration in deploy/jboss-logging.xml. You can direct the output from your classes to a separate file. All the logging from the shared classes still goes to server.log by default. Directing the output from the shared classes to your application's log file is a bad thing to do: imagine if every application tries to do this. Including thread names in the logging output helps matching the records from the default JBoss log (server.log) back to your application if necessary.

JBoss, you never stops to amuse me!

Standalone HornetQ and JBoss, part 2: making it work without embedded server

Rant mode off.

Actually it is not that bad. It is just so happened that HornetQ standalone ended up being last on the list of things I have tried. And it became the last straw.

In reality the biggest single WTF was not HornetQ but ActiveMQ acknowledging received messages despite timed out transaction. The biggest collection of WTFs in a single place was of course (and is, and probably will be forever) OracleAQ.

But back to configuring JBoss AS 6 to work with the standalone HornetQ.

1. The most important thing is to use JBoss AS 6.1.0.Final and not 6.0. Details are here. This is something I already knew and it is not specific to the standalone configuration of HornetQ, but it is worth mentioning here anyway.


2. JBoss will be configured to talk to the external standalone HornetQ. The embedded HornetQ will be removed. This is what I want to achieve. Yes, it is possible to go for the standalone HornetQ environment and still run the embedded HornetQ just in case. But I find it pointless. Note also that no new resource adapter is added to JBoss. Instead the configuration of the existing one is changed.


3. Move JBOSS_HOME/server/<servername>/deploy/hornetq/jms-ds.xml to JBOSS_HOME/server/<servername>/deploy. This is where outbound connection factories are defined. The file will have to be changed, see below.


4. Delete JBOSS_HOME/server/<servername>/deploy/hornetq directory. This is where the configuration of the embedded HornetQ lives.


5. Delete JBOSS_HOME/server/<servername>/deployers/hornetq-deployers-jboss-beans.xml. This file specifies how HornetQ specific configuration files should be read to initialize embedded HornetQ server and its destination objects. No embedded HornetQ means no need to read these configuration files.


6. Change the resource adapter configuration file: JBOSS_HOME/server/<servername>/deploy/jms-ra.rar/META-INF/ra.xml. This is actually documented here: 32.4.4.1.1. Configuring the Incoming Adaptor or here: HORNETQ_HOME/examples/javaee/jca-remote/readme.html, section "configuring the incoming Adapter". Basically you need to change two RA properties:

   <config-property>
     <description>
       The transport type. Multiple connectors can be configured by using a comma separated list,
       i.e. org.hornetq.core.remoting.impl.invm.InVMConnectorFactory,org.hornetq.core.remoting.impl.invm.InVMConnectorFactory.
     </description>
     <config-property-name>ConnectorClassName</config-property-name>
     <config-property-type>java.lang.String</config-property-type>
   <!--  <config-property-value>org.hornetq.core.remoting.impl.invm.InVMConnectorFactory</config-property-value> -->
     <config-property-value>org.hornetq.core.remoting.impl.netty.NettyConnectorFactory</config-property-value>
   </config-property>
   <config-property>
     <description>The transport configuration. These values must be in the form of key=val;key=val;,
       if multiple connectors are used then each set must be separated by a comma i.e. host=host1;port=5445,host=host2;port=5446.
       Each set of params maps to the connector classname specified.
     </description>
     <config-property-name>ConnectionParameters</config-property-name>
     <config-property-type>java.lang.String</config-property-type>
   <!--  <config-property-value>server-id=0</config-property-value> -->
     <config-property-value>host=127.0.0.1;port=5445</config-property-value>
   </config-property>

   The incoming messages will be received from the standalone HornetQ server available at localhost:5445.


7. Change the connection factory configuration file (jms-ds.xml copied to deploy directory at step 3 above). It is also documented 32.4.4.1.2. Configuring the outgoing adaptor or here: HORNETQ_HOME/examples/javaee/jca-remote/readme.html, section "configuring the outgoing Adapter". This is what the resulting file looks like:

   <connection-factories>
     <tx-connection-factory>
       <jndi-name>jms/HornetQ/XACF</jndi-name>
       <xa-transaction/>
       <rar-name>jms-ra.rar</rar-name>
       <connection-definition>org.hornetq.ra.HornetQRAConnectionFactory</connection-definition>
       <config-property name="SessionDefaultType" type="java.lang.String">javax.jms.Topic</config-property>
       <config-property name="ConnectorClassName" type="java.lang.String">org.hornetq.core.remoting.impl.netty.NettyConnectorFactory</config-property>
       <config-property name="ConnectionParameters" type="java.lang.String">host=127.0.0.1;port=5445</config-property>
       <max-pool-size>20</max-pool-size>
     </tx-connection-factory>
   </connection-factories>

The situation now is still not complete because no destination objects are registered in JBoss JNDI. JBoss can be started but deploying an application that uses @Resource will still fail. The good thing: the embedded HornetQ is out of picture.

The remaining piece of configuration depends actually on how the application uses JMS. If the application contains some MDBs to receive messages from destinations, then it is possible to skip JNDI registration completely. Whether it is a good idea is another question. Just add something like this to the MDB code or the equivalent configuration to its deployment descriptor:

@MessageDriven(activationConfig = {
    @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue"),
    @ActivationConfigProperty(propertyName = "destination", propertyValue = "TestQueue"),
    @ActivationConfigProperty(propertyName = "UseJNDI", propertyValue = "false"),
})

The key here is the property named "UseJNDI". The default value is true and the destination has to be registered in the JNDI. Setting the property to false skips JNDI lookup. After all, JNDI registration is just a bit more than a mapping from say "jms/hq/AQueue" JNDI name to the queue name ("TestQueue") known to the server. The HornetQ resource adapter will use "TestQueue" as the queue name in its communication with the server.

If the application needs that kind of indirection or if it sends messages and relies on @Resource injection line that:

@Resource(mappedName = "jms/hq/AQueue")
private Queue queue;

then some more configuration is needed. This configuration can be done at the server level so the destinations are available to all applications as soon as the server is started or at the application level. Note: I did not actually test the application level configuration. There might be initialization order problems: JNDI name must be available for injection but it is not yet there.

This is what is missing in HornetQ documentation. This and also the way to make it easier and less verbose:

Create a file named jboss-beans.xml in META-INF (or WEB-INF) directory of your application if you want to deploy the configuration with your application. Or create a file named <something meaningful>- jboss-beans.xml in JBOSS_HOME/server/<servername>/deploy. Copy the following to the file:

<?xml version="1.0" encoding="UTF-8"?>
<deployment xmlns="urn:jboss:bean-deployer:2.0">
  <bean name="HQ_JNDIBindingService" class="org.jboss.naming.JNDIBindingService">
    <property name="bindings">
      <bean class="org.jboss.naming.JNDIBindings">
        <property name="bindings">
          <array elementClass="org.jboss.naming.JNDIBinding">
            <bean class="org.jboss.naming.JNDIBinding">
              <property name="name">jms/hq/AQueue</property>
              <property name="value">
                <!-- Use org.hornetq.jms.client.HornetQTopic for topic -->                                
                <bean class="org.hornetq.jms.client.HornetQQueue">
                  <constructor>
                    <parameter>TestQueue</parameter>
                  </constructor>
                </bean>
              </property>
            </bean>

            <!-- You can add here more <bean class="org.jboss.naming.JNDIBinding"> definitions for other destinations -->

          </array>
        </property>
      </bean>
    </property>
  </bean>
</deployment>

This configuration creates a JNDI entry under name "jms/hq/AQueue" and makes sure that is it the correct class (org.hornetq.jms.client.HornetQQueue which implements javax.jms.Queue). This entry represents a queue named "TestQueue" on a server. Note: "on a server". As I have mentioned in the previous post this object is just a mapping to the destination name and it comes alive only with the correct ConnectionFactory/ConnectorFactory.

That is it. Hey, HornetQ, was it difficult to document?

Standalone HornetQ and JBoss

For the last couple of weeks I have been busy playing with JBoss and various JMS implementations, like Apache ActiveMQ, HornetQ and even OracleAQ. As usual, with different degree of success. This post is about trying to make HornetQ standalone work with JBoss.

HornetQ comes bundled with JBoss AS 6 as its default JMS provider. As such HornetQ runs embedded in JBoss JVM process. HornetQ home page mentions a lot of nice feature HornetQ has, for example "Solid high availability" or "Flexible clustering". These feature are available only when HornetQ runs as standalone server.

Shall we try it? No problem, HornetQ is downloaded and started. The minor inconvenience is the lack of any admin user interface. All the configuration must be done via config files or via JMX. Fortunately I need just a single queue for testing purposes. TestQueue is created, HornetQ server is restarted. So far so good.

Now it is time to configure JBoss side. I must say this is ... interesting. Very interesting.

Rant mode on.

It is unbelievable: HornetQ comes from the same company as JBoss AS so it must be easy, right? It is even documented, there are samples, and yet...

First of all there is no documentation on how to configure JBoss AS 6 to completely switch from the embedded HornetQ configuration to standalone. The available documentation describes only how to connect to the standalone server. As if it were enough. The documentation says nothing about the rest of HornetQ configuration files in JBoss.

Guess what, it is not enough. I tried to deploy my tests application and immediately got complaints from JBoss saying that my nice TestQueue is not there.

Nowhere could I find any description on how to make a queue configured in the standalone HornetQ server be visible in the JBoss JNDI tree so that @Resource injection worked.

Next thing I tried was adding my queue in JBOSS_HOME/server/<servername>/deploy/hornetq/hornetq-jms.xml. This looked like a very strange thing to do, but this actually worked. Wow, HornetQ is smart! The corresponding JNDI entry is created, the application is deployed and I can send messages and receive them with an MDB.

There are even couple of JMX mbeans corresponding to my test queue available in JBoss JMX console. Except the attributes of those JMX mbeans do not really match the expected values and operations do not do the expected things. It looks like no messages ever went through the queue. What gives?

Nothing new actually: documentation that is incomplete; adding new functionality is much more important than making it work in the useful configurations, you name it. Works in JBoss as embedded? Good enough, let's move on. Need to do something different? Good luck with that.

So why it works and how?

All the configuration files under deploy/hornetq are related to the embedded HornetQ. Adding a queue/topic definition to hornetq-jms.xml adds the destination to the embedded server. The JMX mbeans are created to manage this local destination. And do not get me started on the story of two JMX beans per queue/topic and the difference between "core" HornetQ and "jms" HornetQ. Layered architecture in practice.

As part of a queue/topic creation HornetQ registers it in JBoss JNDI. This registered object is more or less the destination's name on the server. Yes, the object is an implementation of javax.jms.Queue/Topic interface but this does not really matter. It is useless by itself. The "magic" happens only in combination with the configured ConnectionFactory (for the outbound communication) or ConnectorFactory (for the inbound communication). Is it local "InVM" connection? Then the embedded server is doing the work. Is it "Netty" connection pointing to the standalone HornetQ? Then messages go to/from that server.

The net result: since there is no documented way to register such "destination names" in JBoss JNDI directly one must keep the embedded HornetQ running. And then for each remote destination one must create the corresponding local destination to get the correct JNDI objects in place as a side effect. Really a way to go, HornetQ! Clear and understandable architecture. And you get (for free!) a pair of useless JMX mbeans per destination so that you can waste your time trying to understand what the hell is going on with the messages.

It is even more interesting for people who want to use HornetQ from other application servers. There is no <adminobject> in ra.xml (<adminobject>s are those "destination names" in JNDI). Naturally, since embedded HornetQ creates them programmatically. It works in JBoss as embedded? Good enough then.

javax.namespace.QName and serialization

I have already mentioned a particular quirk of javax.namespace.QName under JBoss AS 6 and how to avoid it. Unfortunately it is not the end of the story.

You see long time ago somebody made a mistake. Different JDK versions were shipped with serialization-incompatible versions of javax.namespace.QName. Ooops.

I did not try to find out when it was made and what exactly happened, like just forgotten serialVersionUID or something else. Can happen, was fixed. You can see the fix in the JDK source code. Of course the fix is not really complete if we take into account some versions of stax-api jar floating around.

Anyway, stax-api.jar in JBoss AS6 is taken care of. But our application started to fail after it was deployed in the test environment. The application is just migrated to JBoss and is running against an existing test database. And here is the problem: the application stores some JAXB unmarshalled objects in the database. JAXB really likes to use javax.xml.bind.JAXBElement class which has a field of type QName. And the previous version of the application was running under a different version of JDK. You've got the picture.

The "fix" provided by JDK does not help here. It just allows me to select the current serialVersionUID from a limited set of supported values. Deserializing an instance of javax.namespace.QName serialized with a different serialVersionUID fails.

It is possible to go to the database, identify the records that have a wrong serialVersionUID and try to change them. Hmm, understanding the format of serialized instances of java classes and Oracle BLOB functions is not what I really wanted to do. On top of that there are other situations where one might need to be able to support multiple values of serialVersionUID like for example remote invocations.

Fortunately these other situations were not applicable in my case. And I was also lucky because the framework that the application is using allows configuring the way the data is read from and written into a database. Sort of. Several configuration files and several classes after I actually could concentrate on the solution itself:

public class CustomObjectInputStream extends ObjectInputStream {

...
    //
    protected ObjectStreamClass readClassDescriptor() throws IOException, ClassNotFoundException {
        // This is the fix: if the description of QName class is read, check what value of
        // serialVersionUID it has. And if it is not the "current good" value, but matches
        // one of the "known good" values, just return the "current good" descriptor.
        ObjectStreamClass  desc = super.readClassDescriptor();

        if (desc != null && platformQNameDesc != null && platformQNameDesc.getName().equals(desc.getName())) {
            // OK, this is QName descriptor
            long  readVerUID = desc.getSerialVersionUID();

            if (readVerUID != platformQNameDesc.getSerialVersionUID()) {
                // SerialVersionUID of the serialised class DOES NOT match
                // the value used by this JDK process.
                if (readVerUID == JDK_defaultSerialVersionUID ||
                    readVerUID == JDK_compatibleSerialVersionUID ||
                    readVerUID == STAXAPI_SerialVersionUID)
                {
                    // OK, one of the "known good values". Pretend we read the correct one.
                    //
                    // This is not a very nice way, but the thing is: ObjectStreamClass
                    // is a class, not interface, and has a lot of (package) private fields
                    // that are directly read by other JDK classes. So it is either
                    // reflection and changing the private field or this one:
                    desc = platformQNameDesc;
                }
            }
        }

        return desc;
    }

    //
    private ObjectStreamClass  platformQNameDesc = ObjectStreamClass.lookup(QName.class);

    //
    private static final long  JDK_defaultSerialVersionUID = -9120448754896609940L;
    private static final long  JDK_compatibleSerialVersionUID = 4418622981026545151L;
    private static final long  STAXAPI_SerialVersionUID = -711357515002332258L;
}

I really think that something like this must be implemented by JDK, and not only for QName. Allowing to override serialVersionUID is not enough. And maybe class java.io.ObjectInputStream should be changed as well to be able to serialize objects with non-default values of serialVersionUID.