ADFLogger JAX-WS SoapHandler to log request, reponse and faults

Lately I see a lot of ADF projects consuming SOAP web services. This is typically done by creating a JAX-WS Proxy in JDeveloper and invoking this proxy from java beans exposed through the Bean Data Control or through programmatic ADF Business Components. This post will show how to instrument your JAX-WS proxy so it can log the SOAP request, payload and potential fault to an ADFLogger. This can be a very valuable tool during development and when diagnosing production issues.

Let's start with the final result, the weblogic console when invoking a web service that returns a soap fault. The nice thing is that it not only logs the fault but also the request that caused it:

SOAP request and response logged when receiving SOAP fault

When you crank up the log level you can even see all requests and responses that complete successful. As I described earlier this also allows for performance analysis with the Log Analyzer. This breaks down your entire request and our LoggingSoapHandler times the milliseconds it took to invoke the web service.

Log Analyzer showing this web service call took 5 msecs

This magic is performed by a JAX-WS SoapHandler. It can be registered with a JAX-WS proxy and has access to the web service request and response messages. Handlers can even change these, but in this example all we do is logging to the ADFLogger. You can setup handlers when creating the web service proxy or by right clicking an existing one and changing its properties.

Add LoggingSoapHandler as a Handler on the JAX-WS Proxy

You can get the full source code for the com.redheap.soaplog.LoggingSoapHandler class so you can add it to your own project or library. The embedded documentation is rather elaborate but I'll also explain the most important bits here.

Configuring ADF Faces for development

This post will describe how to configure your ADF Faces project for development through web.xml context parameters as well as enabling debug mode in trinidad-config.xml. It will also show how to override these settings for production deployment with a deployment plan even though the setting in trinidad-config.xml cannot be altered directly with a deployment plan.

More background information on all ADF Faces configuration parameters can be found in the appendix of the Web User Interface Developer's Guide. The ones we want to change during development are:

• org.apache.myfaces.trinidad.CHECK_FILE_MODIFICATION to true to check for source files being modified on disk while the application is running and reloading them. Be sure to clear your browser cache after changing this value to clear out any old cached versions.
• org.apache.myfaces.trinidad.resource.DEBUG to true to enable resource debugging and prevent the client from caching resources (eg javascript libraries, images, CSS, etc)
• org.apache.myfaces.trinidad.DISABLE_CONTENT_COMPRESSION to true to disable CSS content compression and use human-readable CSS class names for skinning
• org.apache.myfaces.trinidad.DEBUG_JAVASCRIPT to true to non-obfuscated javascript
• oracle.adf.view.rich.LOGGER_LEVEL to FINE to enable client side javascript logging. Other allowed values are SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST, and ALL
• oracle.adf.view.rich.ASSERT_ENABLED to true to enable client-side javascript assertions

JDeveloper Extension To Suppress Warnings

The JDeveloper auditing framework can be a very valuable tool in delivering high quality code. It not only gives you warnings and errors during development, but can also be run from the command-line on a build server. One thing that always annoyed me is the limited possibilities for suppressing individual warnings. Sure, there is the @SuppressWarnings annotation for Java code. JDeveloper 12c can even use this annotation to suppress any warning, not only the ones supported by the java compiler.

However, much of an ADF (or SOA) application is XML files, not java. JDeveloper 12c doesn't offer a way to suppress warnings in these files. Luckily the auditing framework is highly pluggable and after some inspection how the @SuppressWarning annotation is implemented in the auditing framework, I could create something similar for XML files.

Suppressing a warning in a JSF file

The screenshot above shows how the extension works. See the warning for the value property of the af:outputText component and how it marks this entire document as warning. Simply click the balloon in the gutter of the editor and select to suppress this warning. This adds a comment to the XML file to suppress the warning, very similar to a @SuppressWarnings annotation in java.

Suppressed warning in a JSF file

Notice how the document is now marked green an no more warnings appear. With this extension you can keep the number of warnings down so the real warnings get the attention they need.

I have plans on building a SonarQube extension to run ojaudit (the command line JDeveloper auditing tool) to keep track of your quality. Suppressing warnings can be especially valuable in that situation where you can use SonarQube to keep metrics and track unexpected warnings and errors.

The extension is already live, so simply start JDeveloper 12c and use the Help > Check for Updates feature. Be sure to check "Open Source and Partner Extensions". You should be able to find the "Suppress Audit Warnings" extension. Please leave a comment below if you have any questions or suggestions for a future version.

If you want to see how a custom suppression scheme is built you can download the full workspace or simply browse the subversion repository to look at the source code.

Overriding Entity doDML or prepareForDml Causes Locking Issues

It is not uncommon for people to override the doDML or prepareForDml method in an ADF BC Entity to do some additional work just before posting changes to the database. The official documentation even describes this extension point as being an equivalent to the Oracle Forms Post Processing triggers.
Today I discovered this can lead to locking issues in the database when this additional work changes other view objects or entities. The investigation is based on JDeveloper version 11.1.1.7 and this behavior might differ for other versions.

Update Nov 14: The issue doesn't reproduce in ADF 12.1.2.0. Inspecting of the source code seems to indicate (unpublished) bug 11896369 is to blame. Currently working with Oracle support to further investigate and ask for fix backport to 11.1.1.7

Update Jan 2: Oracle development acknowledged this behavior is caused by bug 11896369 and a backport request has been filed to bring the fix to 11.1.1.7.

Update Jan 10: Patch 11896369 is now available for download.

Let's start with an simplified example of an entity mutation another one. Below is the doDML method of the Department entity. Whenever a change happens to a department it sets the commission of its first employee to 99%. Not a very likely business scenario, but enough to demonstrate the issue.

@Override
protected void doDML(int i, TransactionEvent transactionEvent) {
    RowIterator employees = getEmployees();
    EmployeeImpl firstEmployee = (EmployeeImpl)employees.first();
    try {
        firstEmployee.setCommissionPct(new Number(0.99));
    } catch (SQLException e) {
        throw new JboException(e);
    }
    super.doDML(i, transactionEvent);
}

What we also need is a entity level validation on Employee that will be violated by this change. For demonstration purposes I've setup a range validation for CommissionPct to be between 0.00 and 0.50:

Entity-level Validation Rule

Now let's build a very simple ADF page to change a department and try to save the changes to the database. Here is what happens:

Validation Error in ADF Application

Everything appears to be okay. The user is confronted with the validation error as expected. But now let's try to update the same record from a different database session:

Database record locked after validation exception

Vodafone Content Tampering Making Sites Very Slow On Wi-Fi

I've had issues with this blog sometimes being very slow on my iPhone when using Wi-Fi. I finally figured out what is going and it seems like Vodafone (Netherlands) are to blame.

I noticed my browser is trying to download http://1.2.3.50/jsi/flash.php?file=gordon.js&max-age=3600 which never succeeds on Wi-Fi. A whois search seems to indicate the entire 1.2.3.0/24 address block is invalid and shouldn't be used on the public internet. All traffic to this address block is dropped along the route and it takes the browser (or TCP/IP stack) a full minute to give up and continu loading my blog. Strangely enough downloading this script on a Vodafone NL 3G connection does succeed.

But why is my client requesting this bizarre URL? It is actually part of http://googleads.g.doubleclick.net/pagead/blank.html which is used on my blog pages. When requesting this page over a Vodafone NL 3G mobile connection the content of this blank page is:

<html><script src="http://1.2.3.50/jsi/flash.php?file=gordon.js&max-age=3600" language="javascript"></script>
<body style="background-color: transparent"></body></html>

There it is; this blank.html page contains a script tag to load the mysterious resource from 1.2.3.50. When requesting this same blank.html from my Wi-Fi connection I get a trully blank page:

<html><body style="background-color: transparent"></body></html>

You don't really notice the difference while your are on Vodafone NL 3G network. Your browser will download the file from 1.2.3.50 and the site seems to function okay. But what happens when your device (re)connects to Wi-Fi? Google sends response headers with blank.html telling your browser it is okay to cache the page for 24 hours. So your device will simply use the cached (tampered) version of blank.html it retrieved through Vodafone's network. But now you are on Wi-Fi and your device can't load the file from 1.2.3.50 and the site is dead slow.

Okay, this is bad, but let's hope the problem clears after 24 hours. After all your browser is only allowed to cache the tampered blank.html page for 24 hours. Unfortunately the problem doesn't disappear after 24 hours. This is caused by Google sending an ETag response header with blank.html as well. An ETag is an opaque identifier assigned by a web server to a specific version of a resource found at a URL. If the resource content at that URL ever changes, a new and different ETag should be assigned. Google sending an ETag is a good thing, but Vodafone is altering the content so they should also change the ETag. Unfortunately they don't so your browser is caching this altered version under Google's original ETag. So even when the cache expires after 24 hours and your browser is asking for a fresh copy of blank.html it will include the ETag with this request. Whether you are on Wi-Fi or 3G, Google will always respond that blank.html hasn't changed since your request includes their original ETag. This instructs your browser to keep using the (tampered) cached version. In the end, you are stuck with the altered version of blank.html until you clear your browser cache.

Vodafone is altering pages I request from the internet and to make things worse they are altering them in such a way that these pages won't work outside of their network while allowing my browser to cache this crippled content. This really sucks! I want the real internet and not some crippled version! Vodafone support is acknowledging they are injecting javascript through a transparent proxy. They state the only way to get rid of this is to use a different APN setting on your mobile device which first has to be activated for your account through technical support. This sucks big time! Sure I can get my account fixed, but who knows how many more people are running into this issue without ever figuring out what is going on.

Hopefully this rant can help others understand what is going on when they see this failed downloads from the 1.2.3.50 or 1.2.3.4 IP address.

Decimal Comma with Numeric Keypad as ADF Client Behavior

According to wikipedia 24% of the world's population uses a comma as decimal separator, including The Netherlands where I live. This means entering numeric information with the numeric keypad on the keyboard can be challenging. You can only use it to type a decimal point (.) while we need a decimal comma (,). To make things ADF simply ignores the decimal point in our locale. When a user enters 1.23 it is converted to 123 and wrong information is entered into the system.

Numeric keypad decimal point

We came up with a solution based on a custom ADF Behavior tag. I've recently posted how to create your own ADF (client side) behavior. The first post was a simple version without properties, while the second post expanded this example with properties. Now it is time for the sequel showing how you can handle key presses in an input item and replace any decimal point keystroke with a decimal separator (possibly comma) keystroke. The user can simply use the decimal point on the numeric keypad and when using a European locale it will simply type a comma.

Check for postChanges without commit or rollback in ADF BC

It is not uncommon for an ADF application to invoke DBTransactionImpl::postChanges() to perform database DML without invoking commit (or rollback). This is typically done in environments where we also want to invoke PL/SQL logic in the database that already needs to see these pending changes.

The developer should make sure a commit or rollback is executed in the same JSF request. If this is not done, the database session has pending changes and as we know there is no guarantee a subsequent request by the same user will get the same Application Module and JDBC Connection. It is considered bad practice to have these pending changes survive a single request and today we had a situation where this accidentally happened with all sorts of nasty side-effects. One of the things that happens is that the pending changes also could mean long-lived database locks. We added some code to our ADF BC base classes to detect this and throw an exception so we at least know what is going on and to alert a developer he/she is implementing this bad practice.

First thing we need is to configure our application module to use a custom database transaction class. This is described in the ADF documentation. First we need to create our own DatabaseTransactionFactory so we can use our own subclass of DBTransactionImpl2:

import oracle.jbo.server.DBTransactionImpl2;
import oracle.jbo.server.DatabaseTransactionFactory;

public class MyDatabaseTransactionFactory
  extends DatabaseTransactionFactory
{
  @Override
  public DBTransactionImpl2 create()
  {
    return new MyDBTransactionImpl2();
  }
}

Then we need to make sure this factory class is used instead of the default by setting the TransactionFactory property of the ADF Application Module configuration to the full class name of our own transaction factory:

Set TransactionFactory property of AM Configuration

Next, we can create our own subclass of DBTransactionImpl2 that keeps track of pending postChanges. It sets a flag when postChanges is executed and clears this flag when performing a commit or rollback. We are going to check this flag later on when releasing an Application Module at the end of a request:

import oracle.jbo.server.DBTransactionImpl2;
import oracle.jbo.server.TransactionEvent;

public class MyDBTransactionImpl2
  extends DBTransactionImpl2
{
  private boolean postedChanges = false;

  @Override
  protected void postChanges(TransactionEvent te)
  {
    super.postChanges(te);
    setPostedChanges(true);
  }

  @Override
  protected void doCommit()
  {
    setPostedChanges(false);
    super.doCommit();
  }

  @Override
  protected void doRollback()
  {
    setPostedChanges(false);
    super.doRollback();
  }

  private void setPostedChanges(boolean postedChanges)
  {
    this.postedChanges = postedChanges;
  }

  public boolean isPostedChanges()
  {
    return postedChanges;
  }

}

Final step is to check for pending postChanges at the end of each request. We can do this from our Application Module. This would typically be code you add to your own ADF BC base classes:

import oracle.jbo.ApplicationPoolSvcMsgContext;
import oracle.jbo.JboException;
import oracle.jbo.server.ApplicationModuleImpl;
import oracle.jbo.server.DBTransaction;

public class MyBaseAppModuleImpl
  extends ApplicationModuleImpl
{
  /**
   * This is invoked by the Application Module Pool whenever an 
   * application module is being used, released, removed or recycled
   * from the pool.
   */
  @Override
  public ApplicationPoolSvcMsgContext doPoolMessage(ApplicationPoolSvcMsgContext ctx)
  {
    if (ctx.getMessageType() == 
        ApplicationPoolSvcMsgContext.MESSAGE_TYPE_RELEASING)
    {
      DBTransaction txn = getDBTransaction();
      if (txn instanceof MyDBTransactionImpl2 && 
          ((MyDBTransactionImpl2) txn).isPostedChanges())
      {
        // throwing exception will mark AM as dead and close tainted
        // DBTransaction and JDBC connection
        throw new JboException("Application Module released to the pool with pending posted changes");
      }
    }
    return super.doPoolMessage(ctx);
  }

}

ApplicationModule::doPoolMessage is invoked whenever the pool uses, releases, removes or recycles an application module instance. This can be seen by inspecting ApplicationPoolSvcMsgContext::getMessageType() and comparing to any of the MESSAGE_* constants in ApplicationPoolSvcMsgContext. We check for uncommitted postChanges whenever the application module instance is released to the pool (aka at the end of each request). If these exist we simply throw a JboException. This will not be visible to the end-user as the JSF response has already been completed by then. It will show up in the log for administrators and developers. Because we are throwing an exception during pool management the AM instance will be destroyed together with its JDBC connection. This is actually good as we don't want the AM instance with pending changes, and potential database locks, to linger around.

Update 2 jan: We changed the code to no longer throw an exception thus destroying the applicationModuke, but only log a warning message. Due to an ADF bug we have quite a few AM instances with posted changes at the end of their request. When they get destroyed all ViewObjects loose their where clause and other (or all) records are fetched on the next page request. So until that bug is we fixed we reverted to only logging a warning.