Debugging Orion Applications

This document will show you a few tricks that might help you debug your J2EE applications.

1 Introduction

    In a modern application server, a great number of tasks are being made for you in an automatic way. This often enables you to increase your own efficiency and helps you write better code and focus on the problem you are solving rather than on a problem that has been solved many times before. In short, it helps you move to a higher level of abstraction when programming.

    Now this might sound like it's just fine and dandy, but of course this can also make a few things more difficult. When things are being made by the application server and are out of your control, it's easy to feel powerless when the application server gives you an error. You realize that it's probably something you've done wrong, maybe a configuration error, maybe you have misunderstood how something is supposed to work or maybe you just made some mistake somewhere. In some cases it might also mean that you are not the one that have committed an error but it could actually be being the application server or even the JVM that is in error. Reaching a conclusion on what really is the source of the error can be an enormous task. You read your code to make sure it's correct and you read the configuration and the specification to make sure everything is fine. You might also step through your code in a debugger to see what happens.

    A debugger might often not give you enough information though. You will easily find exactly where the problem happens, but it might be very difficult to really find out why it happens there.

    This document aim to help you in this task. It shows how you can make Orion give verbose information on what exactly it is doing and how this information can be interpreted. It also explains how to interpret different error messages and how you can use debuggers in a few popular IDE's to help your task.

2 The different logs

    A log file is a place where certain events are stored for future reference. In an application server with many deployed applications of different kinds a great deal of events are happening all the time. Because of this there is a need to use more than one log file. Orion uses 5 different kind of log files:

      Application log

      Server log

      Web access log

      RMI log

      JMS log

    2.1 The Web Access log

      The Web Access log is a somewhat odd fellow among log files. Its purpose is not mainly to help finding errors but to find out what activity happens on your web site. Since this document is not about how to analyze the traffic on your web site but about debugging your applications, we will not describe how to use this file here. A full description can be found here.

    2.2 The Application log

      This is the most important log file for most developers. Actually it is not one log file but one per application. It is normally located in application-deployments/<applicationname>/application.log but this location can be changed in orion-application.xml and of course the deployment directory can be changed in server.xml.

      The application log contain all events that are connected to a certain application. A typical example might look like this:


      2000-09-11 17:01 Started
      2000-09-11 17:01 Auto-deploying shop-ejb... done.
      2000-09-11 17:01 shop-web: 1.3.3 Started
      2000-09-11 17:01 shop-wap: 1.3.3 Started
      2000-09-11 17:02 shop-web: Servlet error
        java.lang.SecurityException: JspFactory already set
        at javax.servlet.jsp.JspFactory.setDefaultFactory(JspFactory.java)
        at /shop/listProducts.jsp._jspService(/shop/listProducts.jsp.java:47) (JSP page line 14)
      2000-09-11 17:03 Stopped
      Listing 1: Sample Application log

      1. The first line means that the application was started at the specified time.

      2. The second lines tells us that an EJB module was successfully deployed.

      3. The third and fourth lines show that the application contained two web modules that were started, shop-web and shop-wap.

      4. The fifth line says that a Servlet error occured in the module shop-web. After that comes a stack trace, which can look somewhat different for different exceptions and errors.

      5. In this case the next line tells us that the nature of the problem is that we are trying to set the JspFactory when it is already set, which causes a SecurityException.

      6. We see that the problem occurred in a call to setDefaultFactory() in the class javax.servlet.jsp.JspFactory.

      7. That method was in turn being called bt the jsp page /shop/listProducts.jsp and the JSP line number for the line that called setDefaultFactory() is 14.

    2.3 The Server log

      The server log is where events that are not associated to a certain application or to a certain subsytem show up. It logs:

        Server startup

        Server shutdown

        Internal server errors

      The nature of the errors that show up here can be pretty difficult to debug, and may have cryptical error messages. It is usually a sign of either bad error reporting from Orion (the error should have been printed in a nicer way in some other log, because they are a programmer error), or a sign of a bug in Orion. Anyway, the structure of the file looks like this:


      2000-09-10 12:12 1.3.3 Started
      2000-09-10 12:14 Internal error in HttpServer
        java.lang.NullPointerException at java.io.File.(File.java:181)
        at com.evermind.server.http.HttpApplication.v5(JAX)
        at com.evermind.server.http.HttpApplication.ty(JAX)
        at com.evermind.server.http.d9.r5(JAX)
        at com.evermind.server.http.d9.r4(JAX)
        at com.evermind.util.f.run(JAX)
      2000-09-10 12:15 1.3.3 Stopped
      Listing 2: Sample Server log

      1. The first line tells us when the server was started and what version was started (in this case 1.3.3)

      2. The second line tells us that an error occured at the specified time. In this case it's an Internal Error in the Http Server.

      3. Following this is a stack trace of the exception. In this case all useful information we can get out of this is that an invalid reference has been used (also called a NullPointer). However, the NullPointerException has occured in an internal server class. In this case it was actually a programmer error that prompted this report, and the error in Orion was to not report the error correctly. If any bug reports are made based on an error here, this stack trace should be submitted with the bug since it can sometimes be useful when correcting the bug.

      4. The last line tells us that the server (with the version 1.3.3) was stopped at the specified time.

    2.4 The RMI log and the JMS log

      The RMI log is (not surprisingly) logging RMI events and errors. It follows the common log file layout that we have seen described when talking about the server log and application log. The JMS log works in the same way, but for JMS events and errors. The most common kinds of errors for these logs are related to failed marshalling of object.

3 The modes for debugging certain aspects

    It is often easy to track down a few parts of the problem. It is normally simple to find what application it happens to and it might be able to understand which sub-system the problem occurs in. After having looked at the log files and gone through your code thoroughly you might be able to solve most of the problems. However, there are cases when this is not enough and you want the ability to dig down deeper. You want to find out exactly what Orion is doing and when it is doing it. Since you have usually tracked down the problem to a certain sub-system, for example transactions or clustering, you want to get the information about what is happening in exactly the sub-system that the error occurs in.

    For this purpose Orion provides a number of system properties, that you either define in a properties file called orion.properties or by giving them to Orion on the command line using the -D switch with the java executable (java -Dproperty=value -jar orion.jar). This section describes the big number of debug modes that you can enable for Orion.

    Before using this I have to a warning that these properties are sometimes added for testing very specific things related to the internals of Orion and some might disappear at any time as the internals change. Also some settings may not ever be useful to you. We want to provide this information anyway since we believe that they are often useful to finding problems with j2ee applications and we let you decide whether to try them or not. No guarantees about the behaviour when these are added can be made, so do not run it on a live mission-critical server. The most useful ones will get promoted to appear in the normal log files.

    Let us group the debug modes to get a more clear picture.

    PropertyDescription
    http.session.debugSetting this to true gives you console output about session events, for example:"Created session with id 'MLKAJFMKIFDA' at Mon Sep 11 01:16:25 GMT+02:00 2000, secure-only: false"
    http.cluster.debugSee Cluster debugging below.
    http.virtualdirectory.debugSetting this to true gives you verbose console output about the creation of virtual directories.
    jsp.reuse.tagsIf set to false, JSP Tags will not be pooled, but a fresh instance will be gotten every time you use a tag. If your application is correct, the behavior of the application shouldn't change when you change this value and if it does, you are using optional tag attributes incorrectly (relying on optional attributes being cleared).
    debug.http.contentLengthSetting this to true gives you console output when the content length is set and when error page are sent.
    http.single.threadedTells static file serving to just use one thread. It's unlikely that you'll want to play with this
    http.server.headerNot really useful for debugging. Simply changes the Server: header reported by the server.
    Table 1: HTTP debugging

    PropertyDescription
    datasource.verboseSetting this to true gives you verbose info on datasource-creation. When a new datasource is created (at startup) it will print something like this to the console: "jdbc:HypersonicSQL:defaultdb: Started" or "Orion Pooled jdbc:oracle:thin:@test.foo.com:1521:oracle8i: Started". You will also be notified when connections are opened, when connections are released to the pool, etc.
    jdbc.debugSetting this to true gives you some very verbose information when jdbc calls are made. This information is not as useful as the one for datasource.verbose.
    jdbc.nontx.autocommitCan be used to set whether autocommit should be on for non-transaction connections. Specify false to turn it off, normally it is on.
    jdbc.connection.debugIf you are having trouble with leaking jdbc connections, set this to true to find out where the leaked connection was created.
    debug.jdbc.checkSet this to true to perform additional tests when using jdbc.debug="true".
    Table 2: JDBC debugging

    PropertyDescription
    transaction.logIf set to "console" (transaction.log="console") this tells the server to print verbose information regarding transactions to the console. You will see the message "Transaction log activated..." when Orion is starting up.
    ejb.debug.statecurrently undocumented
    ejb.assertcurrently undocumented
    Table 3: EJB debugging

    PropertyDescription
    xml.validateSetting this to true turns on XML validation for the configuration files.
    xml.rewriteSetting this to true makes Orion try to rewrite configuration files that fail the xml validation.
    xml.parserSpecifies which XML parser to use. javax.xml for the JAXP parser or xerces for xerces.
    Table 4: Configuration debugging

    PropertyDescription
    http.cluster.debugIf set to true, prints verbose information about http clustering events to the console.
    cluster.debugIf set to true, prints verbose information about server clustering events to the console.
    Table 5: Cluster debugging

    PropertyDescription
    jms.debugSet to true for JMS debug info
    multicast.debugSet to true for Multicast debug info
    Table 6: JMS debugging

    PropertyDescription
    rmi.debugSet to true for RMI debug info
    rmi.verboseSet to true for RMI verbose info
    Table 7: RMI debugging

    PropertyDescription
    poll.filescurrently undocumented
    socket.so.timeoutSets the socket timeout
    ssl.providerSets the SSL provider
    native.userUsed to run Orion under another user than root for unix systems
    Table 8: RMI Miscellaneous

4 Understanding error messages

    This section will contain a list of common Error messages and what they mean. So far it only contains a few but we will be adding more as we go along.

    1. java.io.StreamCorruptedException - Thrown when control information that was read from an object stream violates internal consistency checks. Means you are probably trying to connect to a port that is not listning to ormi calls but to some other protocol, like http or ftp.

    2. Orion crashes with a "SIGBUS 10* bus error" (or similar Operating System error message) and exits to the command prompt - A SIGBUS 10* bus error is not a Java error, but a native error, which means that it is caused by a JVM bug that is pretty much out of our control. We try to work around JVM bugs as much as possible, but obviously, some JVM bugs are fatal. When you get hit by a JVM bug, this is what you should do:

      1. Get the absolutely latest version of your JVM.

      2. If the latest version is still buggy, report the bug to your JVM vendor and send a mail to bugs@orionserver.com. We will try to work around the bug if we can reproduce it, but there are no guarantees that this is doable. If it is not doable we can at least keep track of which JVMs are buggy which will help us help you. After reporting the bug to the VM vendor, try a JVM from another vendor. If this fails too, repeat the steps again.

      The Solaris JVMs are unfortunately known to contain many bugs that affect server software. Do try the latest release to see if this fixes your problem.

    3. When starting Orion's web service with IP="[ALL]" for the Orion web site and you get an error saying that the address is already in use - The problem with this behaviour, is with how the ServerSocket class handles this. When you want a Java ServerSocket to bind to all IP's, you use the special 0.0.0.0 IP address. This works fine normally.

      However, if there is one IP being used, for example by another web server, the creation of the ServerSocket will fail.

      Normally, 0.0.0.0 should actually mean "all available" IP:s and deal with the situation fine, but obviously it doesn't in this case.

      Now you might say, if 0.0.0.0 fails, you can open 1 ServerSocket per available IP and not care about the IP:s it can get. Besides the possible performance issues, the problem with this is how to actually get a collection of all available IP:s on a box. The obvious way to do it would be to use InetAddress.getAllByName(InetAddress.getLocalHost().getHostName()); That should return an array of all IP:s, but unfortunately it doesn't on certain systems. This could be an issue with how these systems resolve localhost.

5 Using a debugger

    There are many IDEs and stand-alone debuggers on the market today. This section is dedicated to explaining how to set up different debuggers with Orion. The descriptions written here are provided by Orion users and we greatly appreciate any other texts about using other debuggers. The people contributing the texts are mentioned at the end of every instruction.

    5.1 NetBeans/Forte

      Required Components:

      Go through the following steps to setup debugging with Net.Beans:

      1. Install JDK 1.2.2 to d:\jdk1.2.2

        After installation check/clean up your PATH and CLASSPATH environment variables. Remove anything that points to any other JVM. CLASSPATH is not really needed by JDK 1.2.2, so you can probably remove any entries safely. And make absolutely sure there are no entries like <another JVM>\bin in your path.

        Add d:\jdk1.2.2\bin to your PATH variable.

      2. Install JPDA to d:\jpda

        For JPDA to work, you must add d:\jpda\bin to your PATH variable

      3. Install JPDA as a Java Extension

        Copy d:\jpda\lib\jpda.jar to d:\jdk1.2.2\jre\lib\ext

      4. Install NetBeans to d:\NetBeans

        Unpack the .zip file to d:\, this will autmatically create the d:\NetBeans folder.

        (at this point NetBeans is configured to allow debugging of remote JVMs)

      5. Install Orion to d:\orion

        If you already have orion installed, there is no need to re-install.

      6. Create a batch file that starts Orion with the JPDA options turned on.

        I created d:\orion\oriondebug.bat with the following contents:

        set CLASSPATH=%CLASSPATH%;.\orion.jar;.\ejb.jar;.\jndi.jar;.\lib\tools.jar;d:\jpda\lib\jpda.jar

        java -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=y,address=8000 -jar orion.jar

        (This will run orion in a debug-enabled JVM that is listening on port 8000 for debug connections. The JVM will wait untill a connection is made to continue execution)

      7. Run NetBeans and connect the debugger to the Orion JVM.

        Start Orion with the batch file described above.

        Run NetBeans by double-clicking d:\NetBeans\bin\runide.exe.

        After netbeans comes up, select "Connect..." from the "Debug" menu. If JPDA is installed properly you should see "Default Debugger (JPDA)" in the dialog under "Connector type". If so...

        Select "SocketAttach" for the connector, and enter "8000" in the "port" field.

        Click "OK".

        If you don't get an error, you have successfully connected the debugger to the Orion JVM. This will allow the JVM to continue executing, and Orion will initialize.

        Have a source file for one of the Orion components (servlet, EJB, etc.) open, with a breakpoint set. (The source code for the class(es) you want to debug must be in the NetBeans classpath (i.e. "Filesystem"), otherwise the debugger will halt at the breakpoint(s), but you will not be able to trace through the source.) As soon as that code executes, the debugger will halt execution, allowing you to trace through it, watch variables, etc.

        If you are using a browser to invoke the server-side code, you will want to use IE. Try it with Netscape and you will understand why... (the CPU gets pegged and everything slows to a crawl while Netscape blocks waiting for data).

      Thanks to P. Taylor Goetz for these instructions

    5.2 Kawa

      Get Kawa Pro (not the enterprise version) from Tek-Tools and install it. Configure your JDK as required when you first run Kawa.

      Create a new project for your servlets or EJBs. Add orion.jar, any additional jars required by the application, and the deployed class directory (i.e., c:\applications\myApp\myApp-web\WEB-INF\classes or c:\applications\myApp\myApp-ejb, or both).

      From the Project/Interpreter menu, set the Java class to run to com.evermind.server.ApplicationServer and remember to tell it to use this class. Turn off JVMDI debugger from the Customize/Options/Advanced Paths form, which is for performance only and is not vital.

      Add the breakpoints to your servlets and/or EJBs. F5 starts debugging.

      You can also use use Jikes: Customize/Options/Advanced Paths/Compiler = D:\jikes\jikes.exe +E and set Orion to use jikes from $ORION/server.xml.

      Thanks to Dave Smith for this contribution.

    5.3 IntelliJ IDEA

      Get IDEA from IntelliJ and install it.

      Create a new project for your servlets or EJBs.

      Add orion.jar and any additional jars to your project classpath.

      Go the projects preferenses and select Project|Run/Debug. Add a new run/debug target, name it something like "Orion Embedded".

      Set 'Main class' to "com.evermind.server.ApplicationServer".

      Set 'Working directory' to the Orion installation directory.

      Save configuration by pressing Ok.

      Set breakpoints in your servlets and/or your EJB's.

      Run "Orion Embedded" in debug-mode. Orion will now break into the debugger whenever it encounters a valid breakpoint.

      Thanks to Niclas Olofsson for this contribution.

6 Adding your own info for debugging

    The most basic step for debugging your application is probably to add some debug information and even now, a long time after debuggers made their break-through a lot of people still think sprinkling the code with debug prints is the only way to go. And in many cases it might actually still be a solution that does the job faster than anything else.

Copyright © 2005 IronFlare AB