Sunday, January 11, 2009

JSF and Nested Diagnostic Context

One of the important design criteria for any large concurrent system is to be able to audit and debug production logs. Any real-world web applications need to deal with multiple clients simultaneously. In a typical java web application implementation of such a system, different threads will handle different clients. A possible but discouraged approach to differentiate the logging output of one client from another consists of instantiating a new and separate logger for each client. This technique promotes the proliferation of loggers and considerably increases their management overhead.

Interleaved log output can still be meaningful if each log entry from different contexts had a distinctive stamp. This is where Nested Diagnostic Context or NDC in short come into play. Web App frameworks like JSF which provide well defined life cycle provide additional hooks to implement NDC.

The six phases of the JSF application lifecycle are as follows:
1. Restore view
2. Apply request values; process events
3. Process validations; process events
4. Update model values; process events
5. Invoke application; process events
6. Render response




JSF provides PhaseListner that can be implemented by objects that wish to be notified at the beginning and ending of processing for each standard phase of the request processing lifecycle. This can be used to add Context before Restoring View which can be removed after Response is Rendered.

Log4J provides a nested diagnostic contexts implementation using NDC class.


Lets see how these two can be used to add User Id to every log statement. Implement NDCLogger as follows:


package com.km.logging.util;

import javax.faces.context.FacesContext;
import javax.faces.event.PhaseEvent;
import javax.faces.event.PhaseId;
import javax.faces.event.PhaseListener;

import org.apache.log4j.NDC;

/**
* Log4j NDC Logger to add Remote User in all the log entries.
*/
public class NDCLogger implements PhaseListener {


public void beforePhase(PhaseEvent e) {
PhaseId phaseId = phaseEvent.getPhaseId();
if (phaseId == PhaseId.RESTORE_VIEW) {
NDC.push((String) FacesContext.getCurrentInstance()
.getExternalContext().getRemoteUser());
}
}

public void afterPhase(PhaseEvent e) {
PhaseId phaseId = phaseEvent.getPhaseId();
if (phaseId == PhaseId.RENDER_RESPONSE) {
NDC.pop();
NDC.remove();
}
}

public PhaseId getPhaseId() {
return PhaseId.ANY_PHASE;
}
}



Add your PhaseListener to your faces config as follows:




com.km.logging.util.NDCLogger




If configured to do so, PatternLayout and TTCCLayout instances automatically retrieve the nested diagnostic context for the current thread without any user intervention. Hence, even if a servlet is serving multiple clients simultaneously, the logs emanating from the same code (belonging to the same category) can still be distinguished because each client request will have a different NDC tag.