Fork me on GitHub

n. Slang a rough lawless young Kuali developer.
[perhaps variant of Houlihan, Irish surname]
kualiganism n

Blog of an rSmart Java Developer. Full of code examples, solutions, best practices, et al.

Sunday, April 10, 2011

The Only Logger You'll Ever Need

The Status Quo for Logging in Kuali

One of the most frustrating things about developing with Kuali Foundation Software is the logging. Setup aside, just adding the logging is frustrating. Mostly because of the immense amounts of copy/paste that is encouraged by it. Here's an example of some of the boiler plate.
...
...
import org.apache.log4j.Logger;
import org.apache.ojb.broker.query.Criteria;
import org.apache.ojb.broker.query.QueryByCriteria;
import org.kuali.kfs.coa.dataaccess.impl.ChartDaoOjb;
import org.kuali.kfs.fp.businessobject.TravelMileageRate;
import org.kuali.kfs.fp.document.dataaccess.TravelMileageRateDao;
import org.kuali.rice.kns.dao.impl.PlatformAwareDaoBaseOjb;

/**
* This class is the OJB implementation of the TravelMileageRate interface.
*/
public class TravelMileageRateDaoOjb extends PlatformAwareDaoBaseOjb implements TravelMileageRateDao {
private static Logger LOG = Logger.getLogger(ChartDaoOjb.class);
...
...
Let's go through this. First, examine the import:
import org.apache.log4j.Logger;
Every single class you write with logging will require this weird, foreign class that really has nothing to do with the functionality of your software. It's awkward, and it's boilerplate. It's everywhere needlessly, and in some cases can cause you to neglect that it's there. Next, is my favorite part. We declare the logger on top of having to import it:
public class TravelMileageRateDaoOjb extends PlatformAwareDaoBaseOjb implements TravelMileageRateDao {
private static Logger LOG = Logger.getLogger(ChartDaoOjb.class);
See anything unusual? This is really what I was getting at behind the copy/paste. To my knowledge, this still exists in the KFS source code. It's misleading. This TravelMileageRateDao is logging as the ChartDaoOjb I doubt this is on purpose. Rather, it is the result of copy/pasting the logger declaration from another class. Many do this because it is tedious. As a result, many forget to change the class name.

I am not going to blame the developer for this. In my mind, it shouldn't even be necessary to do this. Shouldn't the framework just know what class I'm logging from? Is that really so hard?

Researching the Performance of Logging

After putting together this post on another blog, I became determined to devise a simpler way to handle logging. Here were my goals.

  • Limit Logger boilerplate to the import statement
  • Efficient logging where the full log message is not concatenated until it is determined whether the message would be used or not
  • printf style formatting if possible.

Back to the Question

Shouldn't the framework just know what class I'm logging from? Is that really so hard?

No. It's not.

I have created two classes called BufferedLogger and FormattedLogger. These are "The Only Loggers You'll Ever Need".

How to use them

It's easy. Before now, you probably thought static imports are pretty useless. Think again.
import static org.kuali.kra.logging.BufferedLogger.*;

That's your boilerplate. Next, let's use it:
public ActionForward insertProposalPerson(ActionMapping mapping, ActionForm form, HttpServletRequest request, HttpServletResponse response) throws Exception {
...
...
// if the rule evaluation passed, let's add it
if (rulePassed) {
document.getDevelopmentProposal().addProposalPerson(pdform.getNewProposalPerson());
info(ADDED_PERSON_MSG, pdform.getNewProposalPerson().getProposalNumber(), pdform.getNewProposalPerson().getProposalPersonNumber());
// handle lead unit for investigators respective to coi or pi
if (getKeyPersonnelService().isPrincipalInvestigator(pdform.getNewProposalPerson())) {
getKeyPersonnelService().assignLeadUnit(pdform.getNewProposalPerson(), document.getDevelopmentProposal().getOwnedByUnitNumber());
}
...
...

Very easy stuff. Notice that there are multiple objects being passed to the info method. They are not concatenated yet. The info method first checks if the message will be used before concatenating. This is actually a huge timesaver if you consider that the '+' and '+=' concatenation is pretty time consuming.

What about printf style logging? Here's another example:
void prepare(ActionForm form, HttpServletRequest request) {
ProposalDevelopmentForm pdform = (ProposalDevelopmentForm) form;
request.setAttribute(NEW_PERSON_LOOKUP_FLAG, EMPTY_STRING);
ProposalDevelopmentDocument document=pdform.getDocument();
List proposalpersons=document.getDevelopmentProposal().getProposalPersons();
for (Iterator iter = proposalpersons.iterator(); iter.hasNext();) {
ProposalPerson person=(ProposalPerson) iter.next();
if (person.getRole() != null) {
person.getRole().setReadOnly(getKeyPersonnelService().isRoleReadOnly(person.getRole()));
}
}

pdform.populatePersonEditableFields();
handleRoleChangeEvents(pdform.getDocument());

debug(INV_SIZE_MSG, pdform.getDocument().getDevelopmentProposal().getInvestigators().size());

try {
boolean creditSplitEnabled = this.getParameterService().getIndicatorParameter(ProposalDevelopmentDocument.class, CREDIT_SPLIT_ENABLED_RULE_NAME)
&& pdform.getDocument().getDevelopmentProposal().getInvestigators().size() > 0;
request.setAttribute(CREDIT_SPLIT_ENABLED_FLAG, new Boolean(creditSplitEnabled));
pdform.setCreditSplitEnabled(creditSplitEnabled);
}
catch (Exception e) {
warn(MISSING_PARAM_MSG, CREDIT_SPLIT_ENABLED_RULE_NAME);
warn(e.getMessage());
}        
}
You can see that this looks no different than the info illustrated earlier. There is one difference though. Examine the warn statement:
warn(MISSING_PARAM_MSG, CREDIT_SPLIT_ENABLED_RULE_NAME);
It uses a constant called MISSING_PARAM_MSG. This is actually a format string that looks like:
private static final String MISSING_PARAM_MSG = "Couldn't find parameter '%s'";

Which is better? BufferedLogger or FormattedLogger

FormattedLogger has its downside. Formatting actually takes more clock cycles than concatenation. It's friendlier to developers though. With a rather large number of parameters to format, it can be relatively fast. I fall on BufferedLogger the most, but FormattedLogger has its uses.

There you have it. No more copy paste. printf style logging.

No comments:

Post a Comment