Logging with Log4j Nested Diagnostic Contexts(NDC) in WSO2ESB

As I explained in my previous post this is another way to grab more information from various clients in a  multi-threaded environment.

A Nested Diagnostic Context, or NDC in short, is an instrument to distinguish interleaved log output from different sources. Log output is typically interleaved when a server handles multiple clients near-simultaneously. Note that NDCs are managed on a per thread basis.

User may have to get more contextual information in the logs, it would be good to them to have some centralized configuration to control information in the logs for all the services.
eg: If user wants to track a clientIP address, he needs to add "REMOTE_ADDR'/'REMOTE_HOST' in the log mediator, within the proxy service. He has to do this for all proxy services  and it is a performance hit.

To achieve above requirement, we could use NDC API in an axis2 handler, which can be kept at in/out message flow, where we can keep NDC stack to store all required data.

If we keep such handler, it can pick only axis2 level info. If user needs to pick some error information , (of course it is the main  purpose to keep logs) which occurred at synapse level, we could keep a custom mediator, which can pick all error information and set them in the Axis2MessageContext. From the axis2 handler we can extract those information and could keep them in the NDC stack.

Here is a  simple example  applies NDC to an axis2 handler.

    import org.apache.axis2.AxisFault;
    import org.apache.axis2.context.MessageContext;
    import org.apache.axis2.description.AxisService;
    import org.apache.axis2.description.Parameter;
    import org.apache.axis2.description.WSDL2Constants;
    import org.apache.axis2.handlers.AbstractHandler;
    import org.apache.log4j.Logger;
    import org.apache.log4j.NDC;

    /**
     *Custom handler for NDC type logging
     *
     */
    public class CustomLog4jDiagnosticContextSettHandler extends AbstractHandler {
        private static final Logger LOG = Logger. getLogger      (CustomLog4jDiagnosticContextSettHandler.class);

        public InvocationResponse invoke(MessageContext messageContext) throws AxisFault {
            boolean loggingContextIsSet = addLoggingContextData(messageContext);
            if (loggingContextIsSet) {
                removeLoggingContextData();
            }
            // Before leaving remove the diagnostic context for this thread.
            NDC.remove();         
            return InvocationResponse.CONTINUE;
        }

        private boolean addLoggingContextData(MessageContext messageContext) {
            if (LOG.isDebugEnabled() || LOG.isTraceEnabled()) {
                try {
                    getLoggData(messageContext);
                } catch (Exception e) {
                    LOG.error("Error pushing log data onto Log4J NDC stack.", e);
                    return false;
                }
                return true;
            } else {
                return false;
            }
        }

        private void getLoggData(MessageContext messageContext) {

                 AxisService service = messageContext.getAxisService();
                 String service_name = service.getName();

                String remote_ip = (String) messageContext.getProperty ("REMOTE_ADDR");
                String operation_name = messageContext.getAxisOperation(). getSoapAction();
                // log all the requests
                String log = "Request comes from the client '" + remote_ip + "' for the service '" +
                                     service_name + "' and operation is '" + operation_name + "'";

                NDC.push(log);
                Exception failure_reason = messageContext.getFailureReason();
                // if axis2 error occurred log that details
                if (failure_reason != null) {
                    String axis_error_msg = failure_reason.getLocalizedMessage();
                    String axis_error_log =
                                            "Exception occured for the client '" + remote_ip +
                                                    "' sent request for the service '" + service_name +
                                                    "'. The root cause is '" + axis_error_msg + "'";
                    NDC.push(axis_error_log);
                }
                // get synapse error logs
                getSynapseFaultSeqLogData(messageContext);
         
        }

        private void removeLoggingContextData() {
            try {
                while (NDC.getDepth() != 0) {
                    LOG.debug(NDC.pop());
                }
            } catch (Exception e) {
                LOG.error("Error popping log data off of Log4J NDC stack.", e);
            }
        }



    /**
         * if synapse error occurs log that also(these details are retrieved from
         * custom mediator)
         *
         * @param messageContext
         */

        private void getSynapseFaultSeqLogData(MessageContext messageContext) {
            MessageContext axis2InMsgcontext = null;
            try {
                axis2InMsgcontext = messageContext.getOperationContext()
                                                  .getMessageContext (WSDL2Constants.                                                                                                                        MESSAGE_LABEL_IN);
            } catch (AxisFault e) {
                e.printStackTrace();
            }

            if (axis2InMsgcontext.getProperty("custom_errorMesssage") != null ||
                messageContext.getProperty("custom_errorMesssage") != null) {
                String synapse_error_msg = null;
                String synapse_error_code = null;
                String synapse_error_detail = null;
                Object synapse_error_exceptionObj;
                Exception synapse_error_exception = null;
                String remote_ip = null;
             
                // if fault sequence invoked in the messageInflow, properties
                // will be set to InMessageContext.
                if (axis2InMsgcontext.getProperty("custom_errorMesssage") != null) {
                    synapse_error_msg = (String) axis2InMsgcontext.getProperty ("custom_errorMesssage");
                    synapse_error_code = (String) axis2InMsgcontext.getProperty ("custom_errorCode");
                    synapse_error_detail = (String) axis2InMsgcontext.getProperty ("custom_errorDetail");
                    synapse_error_exceptionObj = axis2InMsgcontext.getProperty ("custom_exception");
                    synapse_error_exception = (Exception) synapse_error_exceptionObj;
                    remote_ip = (String) axis2InMsgcontext.getProperty("REMOTE_ADDR");
                }
         
                String synapse_error_log = "Exception occured at ESB. The clientIP is '"+                                                                     remote_ip +"' Error message is '" +
                                                   (synapse_error_msg == null ? " not available *"
                                                                             : synapse_error_msg) +
                                                   "' Eror code is '" +
                                                   (synapse_error_code == null ? " not available*"
                                                                              : synapse_error_code) +
                                                   "'. Error detail is '" +
                                                   (synapse_error_detail == null ? " not available*"
                                                                                : synapse_error_detail) +
                                                   "'. Exception is '" +
                                                   (synapse_error_exception == null ? " not available*"
                                                     :synapse_error_exception.getLocalizedMessage());

                NDC.push(synapse_error_log);
            }
        }
    }

In the above sample, you can see that we are extarcting some synapse level information(synapse_error_msg/synapse_error_code etc..), which we can set via a custom mediator as i explained earlier.

To test above sample,

• Make it as a jar file and keep it in the ESB_HOME/repository/components/lib folder .
• Add the handler in axis2.xml
  

  <phase name="LoggingInPhase">
  <handler name="CustomLog4jDiagnosticContextSetterHandler"
                       class="org.wso2.carbon.customlogging.CustomLog4jDiagnosticContextSettHandler"/>
  </phase> ;
  

  Do, this for inflow, outflow, infault flow, outfault flow phases ..(ie: we are registering the handler for all phases..) 
• Add following line at log4j.properties file (ESB\lib\log4j.properties)
    log4j.category.org.wso2.carbon.customlogging=DEBUG 

Now, you will see following type logs;

]2012-07-13 15:30:26,410 [-] [HttpServerWorker-1] DEBUG CustomLog4jDiagnosticContextSetterHandler Request comes from the client '127.0.0.1' for the service 'testProxy' and operation is 'urn:mediate'
2012-07-13  15:30:26,481 [-] [HttpClientWorker-1] DEBUG CustomLog4jDiagnosticContextSetterHandler Exception occured at ESB. The clientIP is '127.0.0.1' Error message is 'Couldn't find the endpoint with the key : bogus' Eror code is '305100'. Error detail is 'Couldn't find the endpoint with the key : bogus'. Exception is ' not available*