In this tutorial blog series, I will show you an example of how you can extend inspectIT with additional sensors. 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 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).

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.

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 there 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)

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 on 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.

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.

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:

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

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 🙂

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

–Stefan
Homepage: http://inspectit.rocks
GitHub: https://github.com/inspectIT/inspectIT
Chat: https://gitter.im/inspectIT/chat

Leave a Comment

By continuing to use the site, you agree to the use of cookies. more information

The cookie settings on this website are set to "allow cookies" to give you the best browsing experience possible. If you continue to use this website without changing your cookie settings or you click "Accept" below then you are consenting to this.

Close