How to Write Your Own Sensor for the Open Source APM Solution InspectIT

In this tutorial blog series, I will show you an example of how you can extend the open source APM solution inspectIT with additional sensors. If you never heard about inspectIT please check by our GitHub page for more information.

For this series, we will create a sensor that can capture logging output and put them into inspectIT. I wrote these posts during the development of the actual logging sensor that we will have in inspectIT, so this is closely aligned. At some points I might remove and simplify matters to make them easier to understand. Please feel free to also check out the logging sensor that inspectIT now comes with – as we are open source, this is pretty simple. (note that at the time of this writing the feature is not yet released in inspectIT)

I will strip down code examples to highlight the important facets and link to the open source code at GitHub. Thus I remove javadoc and sometimes entire methods for the sake of readability.

Requirements

For our logging sensor, we want to be able to capture the logging output of applications. As there are many different logging approaches (say log4j, logback, java.util.logging, and there are still projects that build their own logging API … who knows why), we need to make sure that we can address them all, or, at least, a meaningful set.

As inspectIT should not become the next log management system, we do not really care to capture all log output (if we want sth like that, we can easily use the great Logstash, ElasticSearch, Kibana combination (or Splunk if you like it more commercially)). In fact we are most likely only interested in logging output that signals an error or that helps us to diagnose errors. This means we want to be able to filter out some logging entries. For us this means, we will allow the user to configure which logging levels should in fact be captured.

For now, we will only focus on the logging message and ignore further information (like exception stacktraces, logger names, etc).

General Design

inspectIT allows to easily put sensors onto specific classes and methods. We also gain access to the parameters of this method. With this in mind, we can have a brief look at the logging frameworks (I will now take log4j as an example) to find a meaningful class/method that we can put our sensor on. Having a look at grepcode, we can analyze the Logger class. What we see it that the logging methods, like an error, warn, info all call to a method forcedLog which gets the logging level and the logging message. In fact, this is all we need.

We can simply put our logging sensor (for log4j) on this class and method and read the level to understand if we need to capture the message. If so, we get the logging message and we are finished. The nice thing is, that we only need to instrument one method. The only thing to note is that the current inspectIT instrumentation expects to find the instrumented method directly within the given class (and not inherited from another class). As log4j Logger class extends the Category class and inherits the forcedLog method, we actually need to instrument the Category

From a configuration point of view, we need to integrate our sensor in the inspectIT agent configuration (note that this changes as soon as we have the server-side configuration interface. I will provide an update then).

method-sensor-type log4jlogger info.novatec.inspectit.agent.sensor.method.logging.Log4JLoggingSensor MIN minlevel=ERROR

sensor log4jlogger org.apache.log4j.Category forcedLog(java.lang.String,org.apache.log4j.Priority,java.lang.Object,java.lang.Throwable)

This configuration tells inspectIT about our new LoggingSensor and configures the sensor to only capture logging entries of a certain minimum level (minlevel). Note that the minlevel property is not standard, so you are free to add your own extensions here easily. We will use this configuration later in the hook to check if we should capture a logging output or not. Afterwards, we place the sensor on the method of log4j that we found to be most suitable.

The Log4JLoggingSensor and Log4JLoggingHook

inspectIT uses the concept of sensors that are placed on methods. To be more specific, the sensor itself only places a hook which does the capturing and creation of the measurements. The bytecode instrumentation itself (that we do not have to care about if we just write normal sensors), will simply place a dispatching logic, that calls all hooks that are configured for this method.

The sensor is responsible for gathering all necessary input data for the hooks and to create the concrete hook. Here is the example of the Log4JLoggingSensor.

public class Log4JLoggingSensor extends AbstractMethodSensor implements IMethodSensor {

/** Configuration key for the minimum level that should be captured. */
public static final String CONFIG_KEY_MINIMUM_LEVEL = "minlevel";

@Autowired
private IIdManager idManager;
private Log4JLoggingHook hook;

public void init(Map<String, Object> parameter) {
// read the desired minimum level and pass it to the hook
                String minimumLevelToCapture = (String) parameter.get(CONFIG_KEY_MINIMUM_LEVEL);
                hook = new Log4JLoggingHook(idManager, minimumLevelToCapture);
}

public IHook getHook() {
return hook;
}
}

Interesting to note is that the sensor autowires the IIdManager via Spring. This object is necessary to lookup ids for methods, sensortypes, etc. In this example we need this service in order to communicate with the communication facility (coreservice), we will see this later. For now, simply notice, that sensors should autowire all services and pass them to the hooks. The init method does the main initialization. The passed map is the configuration setting that we created with the sensor definition (so example we have their minlevel=ERROR). As you see, we just read the information and pass it along to the hook.

Each (method-based) hook must implement the interface info.novatec.inspectit.agent.hooking.IMethodHook (view on GitHub)

public interface IMethodHook extends IHook {
   void beforeBody(long methodId, long sensorTypeId, Object object, Object[] parameters, RegisteredSensorConfig rsc);
   void firstAfterBody(long methodId, long sensorTypeId, Object object, Object[] parameters, Object result, RegisteredSensorConfig rsc);
   void secondAfterBody(ICoreService coreService, long methodId, long sensorTypeId, Object object, Object[] parameters, Object result, RegisteredSensorConfig rsc);
}

The dispatching calls the method beforeBody for each hook that is associated with the method. So in our case we could add monitoring code before the call forcedLog. If we were to create a timer sensor, this would be the place to start time measurement. firstAfterBody is called right after the method body is performed, so in case of a timer sensor, we could simply stop the timer here again. As you see, there is an additional secondAfterBody. The dispatcher calls this method after it called the afterBody for each hook. The reason for having this method is to allow us to improve the quality of time-based measurement. For now, simply understand, that beforeBody and firstAfterBody should do as little as possible and all calculation and sending logic should be placed into secondAfterBody.

You also notice, that inspectIT hands you information about the method that is currently being called as parameters. You get:

• methodId: which is uniquely identifying the class/method combination. You can use this Id to ask the IdManager to give you the classname and methodname if you need this in your sensor. (Also see the chapter “ids in inspectIT” below)
• sensorTypeId: the unique id of the sensor that is placed on the method. Usually this is not used in the sensors, but only necessary to send data to the central server (Also see the chapter “ids in inspectIT” below)
• object: This is the instance of the class. So you can access it to capture the state of the instance at the time the method is called. We do that for context capturing
• parameters: the parameter values provided to the method. As we discussed earlier this is very important to the logging sensor as this provides us with the logging level and the logging message.
• rsc: This provides additional configuration settings that the sensor was created with, we skip this for now.
• coreService: the secondAfterBody provides us with the service that is used to send information to the central server. We will briefly see how this can be used to send data.

So for our Log4JLoggingHook we basically just need to read the parameter values. We could do that in the beforeBody or in the firstAfterBody and store the information until the secondAfterBody is called (if you want to do something like this, think of using a ThreadLocal pattern). But an even simpler approach is to just ignore these two methods, and only go for the secondAfterBody. As this is easier (and thus better) we go for this solution.

package info.novatec.inspectit.agent.sensor.method.logging;

public class Log4JLoggingHook implements IMethodHook {

  private static final Logger LOG = LoggerFactory.getLogger(Log4JLoggingHook.class);
  private IIdManager idManager;
  private SeverityHelper checker;

  public Log4JLoggingHook(IIdManager idManager, String minimumLevelToCapture) {
    this.idManager = idManager;
    checker <span class="pl-k">=</span> <span class="pl-smi">SeverityHelperFactory</span><span class="pl-k">.</span>getForFramework(<span class="pl-smi">Framework</span><span class="pl-c1"><span class="pl-k">.</span>LOG4J</span>, minimumLevelToCapture);
  }

  public void beforeBody(long methodId, long sensorTypeId, Object object, Object[] parameters, RegisteredSensorConfig rsc) {
    // not needed for this hook
  }

  public void firstAfterBody(long methodId, long sensorTypeId, Object object, Object[] parameters, Object result, RegisteredSensorConfig rsc) {
    // not needed for this hook
  }

  public void secondAfterBody(ICoreService coreService, long methodId, long sensorTypeId, Object object, Object[] parameters, Object result, RegisteredSensorConfig rsc) {
    if (checker<span class="pl-k">.</span>isValid()) {
// get the information from the parameters. We are expecting the
// method: Priority.forcedLog (String, Priority, Object, Throwable)
      String level = parameters[1].toString();
      if (!checker.shouldCapture(level)) {
        return;
      }

      try {
        LoggingData data = new LoggingData();

        data.setLevel(level);
        data.setMessage(parameters[2].toString());
        data.setPlatformIdent(idManager.getPlatformId());
        data.setSensorTypeIdent(idManager.getRegisteredSensorTypeId(sensorTypeId));
        data.setMethodIdent(idManager.getRegisteredMethodId(methodId));
        data.setTimeStamp(new Timestamp(System.currentTimeMillis()));

        coreService.addMethodSensorData(sensorTypeId, methodId, null, data);
      } catch (IdNotAvailableException e) {
        if (LOG.isDebugEnabled()) {
          LOG.debug("Could not save the timer data because of an unavailable id. " + e.getMessage());
        }
      }
    }
  }
}

Let’s have a look at the interesting parts:

• During initialization, we check if the given minimum level is, in fact, a level that log4j defines else, we mark the hook as not being correctly initialized and log a warning.
• I extracted the check if a logging entry should be captured to a utility class SeverityHelper. Using a factory approach, I can easily get a SeverityHelper for the given logging framework and keep the code easily to read in the hook.
• In the secondAfterBody we get the parameters from the method that is being called. As we expect this hook to be placed on the forcedLog method, we know that the second parameter will be the org.apache.log4j.Level object, and the third parameter will be the logging message. We check if we need to capture and return if the level is too low. Afterwards we build up the LoggingData (quite a simple class that we will have a look in a second) that is sent to the central server
• You saw that you have to set some identifications – I will go deeper into them in the chapter “ids in inspectIT” below

As we want to see output directly I put a simple System.out.println to display the logging data that is captures (not shown in the code). Before firing up this agent with a sample application, lets have a brief look at the LoggingData class.

package info.novatec.inspectit.communication.data;

import info.novatec.inspectit.communication.MethodSensorData;

public class LoggingData extends MethodSensorData {

private static final long serialVersionUID = 6428356462914363539L;
private String level;
private String message;

// getters and setters removed
        // hashcode removed
        // equals removed

@Override
public String toString() {
return "LoggingData [level=" + level + ", message=" + message + "]";
}

}

One thing to note is that this class needs to be put into the Commons project. The classes of the Commons project are provided to the agent, the CMR (central server) and the UI.

Let’s Do a Test

inspectIT provide some simple sample applications (in the samples project). I like to use the calculator project for trying out newly created sensors. To try this out I simply place loggings into the Calculator:

// Constructor
public Calculator() {
 Logger log4JLogger = Logger.getLogger("My Sample Logger");
 BasicConfigurator.configure();
 log4JLogger.error("some error string");
 log4JLogger.debug("some debug string");
[...]
}

I set the configuration to capture only loggings of level INFO and higher

method-sensor-type log4jlogger info.novatec.inspectit.agent.sensor.method.logging.Log4JLoggingSensor MIN minlevel=INFO
sensor log4jlogger org.apache.log4j.Category forcedLog

So I expect to see the first logging of the calculator, but not the second logging. So lets fire up the calculator together with the agent (I build the agent using the build.xml file and called clean, release-all). For further information about the calculator and the integration of the agent, have a look at our documentation.

So here is the output of the calculator. In line 21 you see the first logging of the application and directly afterwards you see that the log4j hook prints out that it captured the data. Afterwards, we see the debug logging of the application. As this level is lower than INFO, the hook does not capture the information. Works as expected 

Feb 20, 2015 3:36:01 PM info.novatec.inspectit.agent.javaagent.JavaAgent premain
INFO: inspectIT Agent: Starting initialization...
2015-02-20 15:36:02,538: [inspectIT] 180    [           main] INFO  ec.inspectit.agent.SpringAgent - Initializing Spring on inspectIT Agent...
2015-02-20 15:36:03,214: [inspectIT] 856    [           main] INFO  nfig.impl.ConfigurationStorage - Agent name set to: CalculatorAgent2
2015-02-20 15:36:03,214: [inspectIT] 856    [           main] INFO  nfig.impl.ConfigurationStorage - Repository definition added. Host: 127.0.0.1 Port: 1099
2015-02-20 15:36:03,275: [inspectIT] 917    [           main] INFO  nection.impl.KryoNetConnection - KryoNet: Connecting to 127.0.0.1:1099
2015-02-20 15:36:03,315: [inspectIT] 957    [           main] INFO  izer.schema.ClassSchemaManager - ||-Class Schema Manager started..
00:00  INFO: Connecting: /127.0.0.1:1099
2015-02-20 15:36:04,466: [inspectIT] 2108   [           main] INFO  nection.impl.KryoNetConnection - KryoNet: Connection to the server failed.
2015-02-20 15:36:04,660: [inspectIT] 2302   [           main] INFO  ec.inspectit.agent.SpringAgent - Spring successfully initialized
2015-02-20 15:36:04,660: [inspectIT] 2302   [           main] INFO  ec.inspectit.agent.SpringAgent - Using agent version dev
Feb 20, 2015 3:36:04 PM info.novatec.inspectit.agent.javaagent.JavaAgent preloadClasses
INFO: Preloading classes ...
Feb 20, 2015 3:36:04 PM info.novatec.inspectit.agent.javaagent.JavaAgent preloadClasses
INFO: Preloading classes complete...
Feb 20, 2015 3:36:04 PM info.novatec.inspectit.agent.javaagent.JavaAgent premain
INFO: inspectIT Agent: Initialization complete...
00:01  INFO: Connecting: /127.0.0.1:1099
Feb 20, 2015 3:36:06 PM info.novatec.inspectit.agent.javaagent.JavaAgent analyzeAlreadyLoadedClasses
INFO: inspectIT Agent: Instrumentation of core classes finished...
0 [main] ERROR My Sample Logger  - some error string
captured: LoggingData [level=ERROR, message=some error string]
0 [main] DEBUG My Sample Logger  - some debug string
00:12  INFO: Connecting: /127.0.0.1:1099
00:23  INFO: Connecting: /127.0.0.1:1099

Nice to Know Section

So this section is about stuff that is not absolutely necessary to write an own sensor but might be interesting to you nonetheless.

Nice to Know: Ids in InspectIT

in inspectIT we often deal with classes, packages, methods etc. This information is identified by a (often quite long) String, like the classname, the packagename, the whole signature of the method, etc. If we capture information on a method, the resulting data object has to have this kind of information and this information needs to be sent to the central server. For each data object, over and over again. As you might guess this is quite some overhead. This is why we use identifiers in inspectIT. So on the agent, whenever you deal with methods, you get a methodId. You can use the IdManager to retrieve the method information for a methodId if you need additional information about the method. When communicating with the server, we only transfer the method information once, and afterwards only communicate the id. This leads to less data.

In fact the registration process calls to the central server to get an identifier for a method. If this method was called before and is already registered the same id is returned. It goes without saying that the agent caches this information as well. If you have a closer look at inspectIT ids you might notice that we differentiate between (agent) local ids and registered ids. The reason is simple. Calling the server for an identifier for a method would block the agent quite some time and thus impose overhead into the application. We thus allow the agent to offer agent-wide unique identifiers that are good only for as long as the agent runs. These ids can be issued real fast. A parallel process ensures that each local ids are mapped to registered ids on the server and a mapping is built up. Before data is sent the local id needs to be transformed to registered ids (this is what the IdManager provides) and we are set.

Nice to Know: What About Loggings from inspectIT Itself?

Ha! I am wondering how many of you asked yourself: WAIIIT, if we put the logging sensor on the logging methods, what about the loggings that you placed in the logging hook itself. Would this logging not also be instrumented and call the logging hook, which calls the logging, which calls the logging hook…yeah, endless loop?!

Here is another nice thing that we already built into inspectIT. All inspectIT classes themselves and all required dependencies that the agent needs are loaded in an own classloader and do not use any of the application classloaders. In addition, we instructed our class loader to never instrument any classes loaded with this specific class loader.

What Will Come Next?

In the next posts I will show you

• what we need to do on the CMR to deal with our logging data
• how we can integrate the logging information into invocation sequences and display this information on the inspectIT UI
• and I will also show you how we can easily unit test the sensors to ensure that they work as expected (A test like above with the calculator is nice, but lets be honest only automated tests are really improving the quality)

So long! Hope this helps understanding the basics. And do not forget, we are open source, bring your own sensor if you want. I hope this was interesting to you guys

–Stefan