slf4j-4f(ortran)! Yes, You Read That Right...

2 October 2012 By Stuart Archibald

In my last post I wrote about autogenerating JNI wrappers to native (typically Fortran-based) maths libraries. This post is an addendum to the series and it addresses the problem of capturing error/runtime logging produced by native code.

In many Fortran libraries some sort of logging is implemented so that messages about errors or state can be recorded for later inspection, or to act as a trace if something goes wrong. In Java, logging is also an important tool; at OpenGamma we use the slf4j interface to provide various levels of logging.

As we started using the native wrappers more it became apparent that we really wanted the Fortran logs to go to the same slf4j stream as the Java logs such that we have a universal logger. Practically this means taking some of the techniques from the previous articles (here, here and here) and combining them with some slightly more involved JNI.

How we do it

To motivate the discussion, let's assume there is some Fortran routine called f_log that, when truncated, looks like:

subroutine f_log(log_message)
character*(*):: log_message
!> Code that implements logging by writing "log_message" to some output stream goes here
end subroutine f_log

As we saw last time, we can override symbols in the native shared library by creating our own routine with the same prototype and putting it higher up in the link chain so it is used in preference to the shared library version.

Normally we'd do something along the lines of:

#define F_LOG_F77 F77_FUNC(f_log,F_LOG)
#ifdef __cplusplus
extern "C"
#endif
void F_LOG_F77(char * log_message)
{
// code to process message
}

However, we now have a problem. The

char * log_message

is of unknown length and not necessarily NUL terminated. This sort of information is not needed in Fortran because the dope vector associated with the character array can be queried by invoking the Fortran intrinsic len() function on the array and the length can be ascertained. In C, this is not possible as the dope vector struct is (usually) dereferenced to give the character pointer only.

To get around this problem we have to buffer the call to our C function through a Fortran routine that will call len() on the character array. From this buffering routine we can then make a call to an appropriately designed C routine, as we now have enough information to do something useful with the message. In our example we'd do something like:

subroutine f_log(log_message)
character*(*):: log_message
integer:: length
length = len(log_message)
f_log_buffered(log_message, length)
end subroutine f_log

A corresponding C routine to handle the message - now we know the amount of data - would look something like:

#define F_LOG_BUFFERED_F77 F77_FUNC(f_log_buffered,F_LOG_BUFFERED)
#ifdef __cplusplus
extern "C"
#endif
void F_LOG_BUFFERED_F77(char * log_message, int * length)
{
        // handle message
}

As in the previous articles, we cache the JavaVM pointer globally in the library and this is set through the JNI_OnLoad() function. This is so that when the thread that is running the native code reaches the logging routines, and its flow is intercepted, we can reattach it to the JavaVM to get access to the data "inside".

As mentioned previously, at OpenGamma we use the slf4j interface for logging purposes. So to continue our example we'll write some Java code that has a static slf4j logger (aptly named "log") as a field in the class, and then statically initialise it via a LoggerFactory method.

Fortran-C-JNI-Java Callback

From C, the pattern for accessing the logger within this class is as follows:

1. Find the Java class that contains the static logger (lookup OGNativeCodeWrapper) and point a native jclass type to it.
2. Find the Java class for the slf4j API (lookup slf4j) and point a jclass type to it.
3. Within the static logger class (OGNativeCodeWrapper) find the ID of the static field "log".

1. Get the concrete logger object associated with the ID found in the above. This is a jobject type and is the instantiated concrete class that implements the slf4j API.

1. From the logger object above, or for efficiency from the class pointer to the slf4j API, obtain the method ID for the logging methods required e.g. "error()", "warn()", "info()".
2. From the char * log_message create a NUL terminated UTF8 string buffer (AND with 0x7F or replace non-UTF8 sequences with ? or similar).
3. Call NewStringUTF() on the UTF8 string buffer to instantiate a Java string type suitable for the slf4j logger methods.
4. Call CallVoidMethod() on the logger object with the methodID of the logging method and the Java string containing the message.
5. As we are finished with the string buffer and the Java string, delete the local reference to the string and free() the buffer.

To speed all this up we can actually cache a lot of this information at a global level in the C library. To ensure all the pointers of type fieldID, methodID and jclass are valid, we can write a C function that refreshes the cache when the static initialisation of the Java class is performed. In this way, should the class be garbage collected (invalidating the global pointers), the next instantiation of the class will refresh them to usable values. We therefore split the code as follows:

Java

C library code

This works as the methodID in the logging class API is looked up in the vtable which cascades through to finding the equivalent methodID in the instantiated concrete class object on which the method is then called.

Just for completeness, here is some output from a quick test wrapper we threw together to Netlib's SLATEC. We call the DERFC() function with x=28 which causes an underflow:

(And yes, of course we autogenerate it all ;-))