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