Integrating log4j with SWIG/JNI?

Question

I'm working on a Java program which has a C++ module. I'd like for my C++'s stdout/stderr to be sent to a slf4j/log4j logger.

Some possibilities:

1. Have my C++ module capture stdout/stderr in a string which is returned and sent to a logger. A downside is the C++ module might be expensive and this would be asynchronous.
2. Have my Java software create/manage a temp file to which the C++ module can write. Upon completion, my software would read and then delete the file and send the data to slf4j.
3. is there some way to get an ostream from log4j I could pass through my swig interface?
4. it looks like I could create a Director in swig to pass a string to Java from C++ to forward to the logger.

How have other people solved this problem?

Answer 1

There are three problems you need to solve to get C++ (called via SWIG generated wrappers) logging to log4j:

1. How we capture the C++ output (i.e. hook the iostream objects).
2. How we insert this hooking into the generated wrapper.
3. How we actually call log4j with the stuff we've captured.

In answering this question I wrote the following header file to demonstrate how my solution works:

#include <iostream>

void test1() {
  std::cout << "OUT: " << "test1\n";
  std::cerr << "ERR: " << "test1\n";
}

struct HelloWorld {
  static void test2() {
    std::cout << "OUT: " << "test2\n";
    std::cerr << "ERR: " << "test2\n";
  }

  void test3() const {
    std::cout << "OUT: " << "test3\n";
    std::cerr << "ERR: " << "test3\n";
  }
};

At the end of this I wanted to see both std::cout and std::cerr going to log4j in the correct order. I've answered that question before, in this instance to keep it simple and portable I started out using rdbuf() to swap the internal buffer used by std::cout and std::cerr to one that I'd actually created inside a std::stringstream, something like:

std::stringstream out; // Capture into this

// Save state so we can restore it
auto old_buf = std::cout.rdbuf();
// Swap buffer on cout
std::cout.rdbuf(out.rdbuf());

// Do the real call to C++ here
// ...

// Reset things
std::cout.rdbuf(old_buf);

// Walk through what we captured in out

Of course this won't capture output from libc functions (printf() etc.) or system calls (write() etc.) but it will get all your standard C++ output.

So that's problem #1 crossed off our list. For problem #2 SWIG has the %exception directive that matches what we want to do quite nicely, it gives us a chance to execute C++ code before and after a call into a wrapped function gets dispatched. In the above example all we need to do is use the special variable $action to get the substitution to happen where the comment "do the real call to C++ here".

For problem #3 we need to make some Java calls happen. I started out thinking that JNI wouldn't be too bad, perhaps a little verbose. Basically all we want to do is duplicate the following Java code (from the log4j docs):

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class HelloWorld {
    private static final Logger logger = LogManager.getLogger("HelloWorld");
    public static void main(String[] args) {
        logger.info("Hello, World!");
    }
}

but inside JNI rather than Java and passing the right string into the getLogger call.

So putting this all together into a SWIG interface we get:

%module test

%{
#include "test.hh"
#include <sstream>
#include <cassert>
static const char *defaultLogname="$module"; // Use if we're not in a class
%}

// Exception handling for all wrapped calls
%exception {
  // Hook output into this:
  std::stringstream out;

  // Save old states
  auto old_outbuf = std::cout.rdbuf();
  auto old_errbuf = std::cerr.rdbuf();
  // Do actual buffer switch
  std::cout.rdbuf(out.rdbuf());
  std::cerr.rdbuf(out.rdbuf());
  try {
    $action
  }
  catch (...) {
    // TODO: use RAII instead of poor finally substitute?
    std::cout.rdbuf(old_outbuf);
    std::cerr.rdbuf(old_errbuf);
    throw;
  }
  // Restore state
  std::cout.rdbuf(old_outbuf);
  std::cerr.rdbuf(old_errbuf);

  // JNI calls to find mid and instance for Logger.error(String) for the right name
  static const std::string class_name = "$parentclassname";
  // prepare static call to org.apache.logging.log4j.LogManager.getLogger(String)
  // start with class lookup:
  jclass logmanagercls = JCALL1(FindClass, jenv, "org/apache/logging/log4j/LogManager");
  assert(logmanagercls);
  // find method ID for right overload of getLogger
  jmethodID getloggermid = JCALL3(GetStaticMethodID, jenv, logmanagercls, "getLogger", "(Ljava/lang/String;)Lorg/apache/logging/log4j/Logger;");
  assert(getloggermid);

  // Prep name strign to pass into getLogger
  jstring logname = JCALL1(NewStringUTF, jenv, (class_name.size() ? class_name.c_str(): defaultLogname));

  // Actually get the Logger instance for us to use
  jobject logger = JCALL3(CallStaticObjectMethod, jenv, logmanagercls, getloggermid, logname);
  assert(logger);
  // Lookup .error() method ID on logger, we need the jclass to start
  jclass loggercls = JCALL1(GetObjectClass, jenv, logger);
  assert(loggercls);
  // and the method ID of the right overload
  jmethodID errormid = JCALL3(GetMethodID, jenv, loggercls, "error", "(Ljava/lang/String;)V");
  assert(errormid);

  // Loop over all the lines we got from C++:
  std::string msg;
  while(std::getline(out, msg)) {
    // Pass string into Java logger
    jstring jmsg = JCALL1(NewStringUTF, jenv, msg.c_str());
    JCALL3(CallVoidMethod, jenv, logger, errormid, jmsg);
  }
}

// And of course actually wrap our test header    
%include "test.hh"

I added some Java to prove this works:

public class run {
  public static void main(String[] argv) {
    System.loadLibrary("test");
    test.test1();
    HelloWorld.test2();
    HelloWorld h1 = new HelloWorld();
    h1.test3();    
  }
}

Compiled and ran with log4j 2.6 jars in current directory:

swig3.0 -c++ -java -Wall test.i
javac *.java
g++ -std=c++1y -Wall -Wextra -shared -o libtest.so test_wrap.cxx -I/usr/lib/jvm/default-java/include/ -I/usr/lib/jvm/default-java/include/linux -fPIC 
LD_LIBRARY_PATH=. java -classpath log4j-api-2.6.jar:log4j-core-2.6.jar:. run

When runs gives:

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.
22:31:08.383 [main] ERROR test - OUT: test1
22:31:08.384 [main] ERROR test - ERR: test1
22:31:08.386 [main] ERROR HelloWorld - OUT: test2
22:31:08.386 [main] ERROR HelloWorld - ERR: test2
22:31:08.386 [main] ERROR HelloWorld - OUT: test3
22:31:08.386 [main] ERROR HelloWorld - ERR: test3

Discussion points:

• Is the JNI verbose? Definitely yes, but is that bad enough to go down another road? For me not (although the directors idea is viable it's not as simple as it sounds due to complexities with producing interfaces)
• The timestamps on your log events will be "wrong" here because all the log information that gets captured will be pushed out after the underlying C++ function call returns, not during its execution
• The cout/cerr messages get mixed and logged at the same level. I did this because of the previous point, if they weren't intermixed like this getting the relative ordering would be impossible without more work
• If your C++ methods produce large quantities of output the buffer will grow rather large
• If you've got a large C++ project I'd hope you had a better logging framework in use than just iostreams. If that's the case you're probably better off implementing its output interface(s) with an adaptor that passes directly to Java with timestamps, log level etc. info retained. (Or vice versa)
• Even sticking with iostream the Boost iostreams library makes it easier¹ to write something that would actually hook the output writes at the point they happen rather than the current hooking technique (but introduce bigger dependencies so it's a trade off). You could also do it without boost, but the basic_streambuf class is fairly unwieldy.

¹ I can probably illustrate the boost version in this answer if you're interested.