2014/01/03

back to the beginning ... logging

In the second half of the 1990s I was an IDMS database administrator for Belgium's biggest retailer. When our resident guru almost got killed by the job I got most of the main databases in my care ... and I must admit I ruled supreme. If you've never heard of the BOFH, check him out here and here. I don't know if any of those stories are based on reality, but they are nothing compared to some of the stuff I pulled off.

I hated logging.

Let me place that statement in the correct context. PL/I did not allow asynchronous actions, logging ate processing time. Also, disk storage was not cheap, the estimated costs of storage could and would often kill a project before it even started. Database storage was even more expensive. Migration to tape was an option but it made consultation afterwards very impractical.

This brings me to the why of logging. Opinions may differ but I see only two reasons :
  • Audit
  • Bug fixing by means of postmortem analysis
Audit. You want to know what was requested and - if you're a security auditor - who requested it. This is a - and in my view the only - legitimate reason for logging. However, even back then tools existed that allowed auditing without having to put it in the code. A fellow database administrator that was a bit too curious about the wages of the others and looked them up on the database found that out the hard way.

Bug fixing by means of postmortem analysis. You want to know what the state of the system was at the time of an error. This requires excessive amounts of logging. It did back then and it does today. And let me tell you something ... it's never enough.

You might say I'm an old fart that's not up to speed with the current state of technology. Storage is very cheap, asynchronous logging has become the standard ... and doesn't everybody say that you should log everything because it can be big stash of useful data itself ?

As a matter of fact, they - whoever they are - don't. They mean audit data collected on the edges of your system, not the things you'd typically put in a put skip list or System.out.println.


I still hate logging. And therefore I was very happy that when NetKernel 4 was released, it contained a back-in-time machine. Such was the power that 1060 Research also released a backport for NetKernel 3. This time machine is also known as the Visualizer. When running, it captures the complete (!) state of any request in the NetKernel system. Anybody that has worked with it agrees that it is sheer magic, for you can pinpoint any error almost immediately. Such a powerful tool warrants its own blogpost, so that's for next time.

All personal opinion aside, how does one log in NetKernel then ? Well, lets see how we can add some to our introduction module. First I want to have some audit of the incoming requests. We could write our own transparent overlay - another topic for a future blogpost - for this, but as it happens the HTTP Jetty Fulcrums have everything that's needed.


Open [installationdirectory]/modules/urn.org.netkernel.fulcrum.frontend-1.7.12/etc/HTTPServerConfig.xml in your favorite text/xml editor.
Remove the 
<!--Uncomment for NCSA Logging 
and the matching 
--> 
line. You can also change the settings and/or the name of the logfile. Restart NetKernel (this change is not picked up dynamically). You should now find a new logfile under [installationdirectory]/log.

Now try http://localhost:8080/introduction/helloworld-file in your browser. Open up the logfile and you should see something like this (given date, locale and browser differences) :

0:0:0:0:0:0:0:1 -  -  [03/jan/2014:09:42:35 +0000] "GET /introduction/helloworld-file HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0"

That's audit taken care of. Do I have to mention the fact that this logfile can easily be picked up by tools like Splunk and Logstash ?

If you need help with integrations like that, feel free to contact me. I've been there and done that.

Maybe you think I'm full of shit in my rant above or maybe you just have to comply with the rules and regulations of a customer. If so, yes, you can also do explicit logging in NetKernel.

Since the HelloWorldAccessor is the only piece of code we have, it's in there that we'll add it. The onSource method looks like this :

    public void onSource(INKFRequestContext aContext) throws Exception {
        aContext.createResponseFrom("Hello World");
    }


Adding logging is as simple as :

    public void onSource(INKFRequestContext aContext) throws Exception {
        aContext.logRaw(INKFLocale.LEVEL_INFO,"Logging from HelloWorldAccessor");
        aContext.createResponseFrom("Hello World");
    }


You'll notice the logging appears in two places. Firstly in the standard output of the NetKernel process :

I 11:00:34 HelloWorldAc~ Logging from HelloWorldAccessor

Secondly in [installationdirectory]/log/netkernel-0.log :

<record>
  <date>2014-01-03T11:00:34</date>
  <millis>1388743234821</millis>
  <sequence>278</sequence>
  <logger>NetKernel</logger>
  <level>INFO</level>
  <class>HelloWorldAccessor</class>
  <thread>167</thread>
  <message>Logging from HelloWorldAccessor</message>
</record>


Why is this ? Well, the log methods look for a configuration resource. Either you pass this resource in the method, or the resource res:/etc/system/LogConfig.xml is used (if it can be found), or - as a final resort - [installationdirectory]/etc/KernelLogConfig.xml is used. Check it out, it has two handlers.

So, to preempt a couple of questions, if you want a different log for each application, you can. If you want a JSON formatted log, no problem. Another common request these days (for yes, I am up to speed) is that the log messages themselves have to be formatted.

In order to do that, your module requires a res:/etc/messages.properties file resource. An actual file yes, logging is provided at such a low level that not all the resource abstractions are in place yet. The file can contain things like :

AUDIT_BEGIN={"timestamp":"%1","component":"%2", "verb":"%3", "type": "AUDIT_BEGIN"}
AUDIT_END={"timestamp":"%1","component":"%2", "verb":"%3", "type": "AUDIT_END"}


In your code you can then write :

aContext.logFormatted(INKFLocale.LEVEL_INFO,"AUDIT_BEGIN",         System.currentTimeMillis(), "HelloWorldAccessor" , "SOURCE");

And the results look like this :

I 11:42:03 HelloWorldAc~{"timestamp":"1388745723359","component":"HelloWorldAccessor", "verb":"SOURCE", "type": "AUDIT_BEGIN"}

and :

<record>
  <date>2014-01-03T11:42:03</date>
  <millis>1388745723360</millis>
  <sequence>263</sequence>
  <logger>NetKernel</logger>
  <level>INFO</level>
  <class>HelloWorldAccessor</class>
  <thread>176</thread>
  <message>{"timestamp":"1388745723359","component":"HelloWorldAccessor", "verb":"SOURCE", "type": "AUDIT_BEGIN"}</message>
</record>


Again I'll mention the fact that these logfiles can easily be picked up by tools like Splunk and Logstash. And there you have it, a complete - and customizable - logging system. To close my post I'm going to talk about the loglevels for a moment, NetKernel provides :
  • INKFLocale.LEVEL_DEBUG
  • INKFLocale.LEVEL_FINEST
  • INKFLocale.LEVEL_FINER
  • INKFLocale.LEVEL_INFO
  • INKFLocale.LEVEL_WARNING
  • INKFLocale.LEVEL_SEVERE
Not only can these be easily matched to ITIL aware operations systems, you can also turn them off and on in NetKernel itself. This will allow you to safe quite a bit of storage ... you never know when that might come in handy ;-).