Showing posts with label log4j. Show all posts
Showing posts with label log4j. Show all posts

Saturday, August 4, 2012

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*

Monday, July 16, 2012

Different ways of logging in WSO2ESB

All wso2 carbon products have a standard way to define a logs .  All logging mechanisms are handled by a carbon logging-mgt component, which is controlled by a central log4j properties file. According to user   needs, he can edit the properties file to get desired log level info in different package level.

When consider ESB product, users have different requirements to acquire the log information in different layers/level of the mediation flow. There are number of ways you can get certain log info in wso2esb.
  • Log mediators :- Users can keep the log mediator in the sequence, and could get certain info about the messages which are passing through certain ESB artifacts
eg:
<log level='full'>
         <property name ='Request message' value='message arrived to insequence'/>
</log> 
  • Editing log4j.properties file to get proxy service level log info:- In this way, user might need to add separate blocks of configuration for all configured proxies. This may be inappropriate in a real production system,where there are hundreds of proxy services deployed and user might need to add hundreds of lines configuration in the log4j.properties file for each proxy service
eg:
 log4j.category.SERVICE_LOGGER.SimpleStockQuoteProxy=INFO, PROXY_APPENDER
log4j.additivity.PROXY_APPENDER=false
log4j.appender.PROXY_APPENDER=org.apache.log4j.DailyRollingFileAppender
log4j.appender.PROXY_APPENDER.File=${carbon.home}/repository/logs/${instance.log}/wso2-esb-stockquote-proxy${instance.log}.log
log4j.appender.PROXY_APPENDER.Append=true
log4j.appender.PROXY_APPENDER.layout=org.apache.log4j.PatternLayout
log4j.appender.PROXY_APPENDER.layout.ConversionPattern=%d{HH:mm:ss,SSS} [%X{ip}-%X{host}] [%t] %5p %c{1} %m%

  •  There is another code level implementation, which can be used to extract some details in certain level of synapse artifacts.
    • eg: Proxy level/Sequence level...
SynapseObserver is an abstract class,which will get notified, whenever a new artifact deployed/undeployed. Each and every  message arrives to the mediation engine will notify the SynapseObserver.
We can extend this observer, to get all proxy service level log information rather adding hundreds line of configuration in the log4j.properties file.
eg:
Code :
import java.io.IOException;
import org.apache.synapse.config.AbstractSynapseObserver;
import org.apache.synapse.core.axis2.ProxyService;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.log4j.DailyRollingFileAppender;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.PatternLayout;

/**
 * This is a custom synapse observer to programatically engage the appender
 * for proxy services.
 *
 */
public class CustomProxyObserver extends AbstractSynapseObserver {
    private static final Log log = LogFactory.getLog(CustomProxyObserver.class);

    public void proxyServiceAdded(ProxyService proxy) {
        try {
            setLogger(proxy);
        } catch (IOException e) {
            log.error("CustomProxyObserver could not set service level logger for the proxy : " +
                      proxy.getName(), e);
        }
    }

    public void proxyServiceRemoved(ProxyService proxy) {
        try {
            setLogger(proxy);
        } catch (IOException e) {
            log.error("CustomProxyObserver could not set service level logger for the proxy : " +
                      proxy.getName(), e);
        }
    }

    /**
     * Method to set proxy service specific logger
     *
     * @param proxy
     * @throws IOException
     */
    private void setLogger(ProxyService proxy) throws IOException {

        String filename = "logs/" + proxy.getName() + ".log";
        String datePattern = "yyyy-MM-dd";
        String SYSTEM_LOG_PATTERN = "[%d] %5p - %x %m {%c}%n";

        PatternLayout layout = new PatternLayout(SYSTEM_LOG_PATTERN);
        DailyRollingFileAppender appender = null;
        appender = new DailyRollingFileAppender(layout, filename, datePattern);
        appender.setName(proxy.getName());       

        Logger proxyLogger = Logger.getLogger("SERVICE_LOGGER." + proxy.getName());
        proxyLogger.setLevel((Level) Level.DEBUG);
        proxyLogger.setAdditivity(false);
        proxyLogger.addAppender(appender);

    }   
   
}
pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">

    <modelVersion>4.0.0</modelVersion>
    <groupId>org.wso2.carbon.customobserver</groupId>
    <artifactId>org.wso2.carbon.customobserver</artifactId>
      <version>1.0</version>
    <packaging>bundle</packaging>
 
    <dependencies>
        <dependency>
            <groupId>org.apache.synapse</groupId>
            <artifactId>synapse-core</artifactId>
              <version>2.1.0-wso2v4</version>
            <exclusions>
                <exclusion>
                    <groupId>org.apache.axis2</groupId>
                    <artifactId>axis2-codegen</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
    <dependency>
            <groupId>org.eclipse.equinox</groupId>
            <artifactId>org.apache.log4j</artifactId>
            <version>1.2.13</version>
    </dependency>
    <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>1.1.1</version>
    </dependency>       
    </dependencies>

    <build>
        <plugins>       
            <plugin>
                <groupId>org.apache.felix</groupId>
                <artifactId>maven-bundle-plugin</artifactId>
                <version>1.4.0</version>
                <extensions>true</extensions>
                <configuration>
                    <instructions>
                        <Bundle-SymbolicName>${pom.artifactId}</Bundle-SymbolicName>
                        <Bundle-Name>${pom.artifactId}</Bundle-Name>
                          <Export-Package>
                           org.wso2.carbon.customobserver.*,
                        </Export-Package>
                        <Import-Package>
                           !org.apache.log4j.*,
                            !org.apache.commons.logging.*,
                            *;resolution:=optional
                        </Import-Package>
                        <DynamicImport-Package>*</DynamicImport-Package>
                    </instructions>
                </configuration>
            </plugin>
        </plugins>
    </build>

</project>
   
 User needs to keep the bundle in the repository/components/dropins folder and need to edit the synapse.properties file to register the CustomObserver

eg:

 synapse.observers=org.wso2.carbon.customobserver.CustomProxyObserver

You will see the generated log files in the ESB_HOME?logs folder.

There is another way, which also needs some coding effort, to extract some specific debug level  information, which are really useful to debug a certain use cases.I'll write about that with sample code and scenario in my next post.

Monday, November 14, 2011

Programmatically enabling log4j appenders

The standard way to enable 'appenders' in log4j is using log4j.properties file..Here lets check out how an user can enable the 'appenders' programmaticly..This is useful , when user wants a logging mechanism separately, which differs from his/her global logging setting..
This is a sample code i have written to grab proxy service level logging information separately..

    private void setLogger(ProxyService proxy) throws IOException {

        String filename = "logs/" + proxy.getName() + ".log";
        String datePattern = "yyyy-MM-dd";
        String SYSTEM_LOG_PATTERN = "[%d] %5p - %x %m {%c}%n";

        PatternLayout layout = new PatternLayout(SYSTEM_LOG_PATTERN);

        DailyRollingFileAppender appender = null;

        appender = new DailyRollingFileAppender(layout, filename, datePattern);

        Logger proxyLogger = Logger.getLogger("SERVICE_LOGGER." + proxy.getName());

        proxyLogger.setLevel((Level) Level.DEBUG);

        proxyLogger.setAdditivity(false);
        proxyLogger.addAppender(appender);

    }