Thursday, 12 October 2017

Textual Representation of logo

Integrate CloudWatch Logs with Cloudhub Mule

In this blog, i will explain how to enable AWS Cloudwatch Logs for your Mule CloudHub Application. Cloudwatch Logs Services are provided by AWS so that you can better mange your logs. It is relatively cheaper than splunk. Since cloudhub automatically rolls over logs more than 100 MB, we require a mechanism to manage our logs more efficiently. For this, we create this Custom appender which will send the logs to cloudwatch.

package com.javaroots.appenders;

import static java.util.Comparator.comparing;
import static java.util.stream.Collectors.toList;

import java.io.Serializable;
import java.nio.charset.StandardCharsets;
import java.util.ArrayList;
import java.util.Formatter;
import java.util.List;
import java.util.Optional;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicReference;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.status.StatusLogger;

import com.amazonaws.regions.Regions;
import com.amazonaws.services.logs.AWSLogs;
import com.amazonaws.services.logs.model.CreateLogGroupRequest;
import com.amazonaws.services.logs.model.CreateLogStreamRequest;
import com.amazonaws.services.logs.model.CreateLogStreamResult;
import com.amazonaws.services.logs.model.DataAlreadyAcceptedException;
import com.amazonaws.services.logs.model.DescribeLogGroupsRequest;
import com.amazonaws.services.logs.model.DescribeLogStreamsRequest;
import com.amazonaws.services.logs.model.InputLogEvent;
import com.amazonaws.services.logs.model.InvalidSequenceTokenException;
import com.amazonaws.services.logs.model.LogGroup;
import com.amazonaws.services.logs.model.LogStream;
import com.amazonaws.services.logs.model.PutLogEventsRequest;
import com.amazonaws.services.logs.model.PutLogEventsResult;

@Plugin(name = "CLOUDW", category = "Core", elementType = "appender", printObject = true)
public class CloudwatchAppender extends AbstractAppender {
 
 /**
  * 
  */
 private static final long serialVersionUID = 12321345L;
 
 private static Logger logger2 = LogManager.getLogger(CloudwatchAppender.class);

 private final Boolean DEBUG_MODE = System.getProperty("log4j.debug") != null;

    /**
     * Used to make sure that on close() our daemon thread isn't also trying to sendMessage()s
     */
    private Object sendMessagesLock = new Object();

    /**
     * The queue used to buffer log entries
     */
    private LinkedBlockingQueue loggingEventsQueue;

    /**
     * the AWS Cloudwatch Logs API client
     */
    private AWSLogs awsLogsClient;

    private AtomicReference lastSequenceToken = new AtomicReference<>();

    /**
     * The AWS Cloudwatch Log group name
     */
    private String logGroupName;

    /**
     * The AWS Cloudwatch Log stream name
     */
    private String logStreamName;

    /**
     * The queue / buffer size
     */
    private int queueLength = 1024;

    /**
     * The maximum number of log entries to send in one go to the AWS Cloudwatch Log service
     */
    private int messagesBatchSize = 128;

    private AtomicBoolean cloudwatchAppenderInitialised = new AtomicBoolean(false);
 

    private CloudwatchAppender(final String name,
                           final Layout layout,
                           final Filter filter,
                           final boolean ignoreExceptions,String logGroupName, 
                           String logStreamName,
                           Integer queueLength,
                           Integer messagesBatchSize) {
        super(name, filter, layout, ignoreExceptions);
        this.logGroupName = logGroupName;
        this.logStreamName = logStreamName;
        this.queueLength = queueLength;
        this.messagesBatchSize = messagesBatchSize;
        this.activateOptions();
    }

    @Override
    public void append(LogEvent event) {
      if (cloudwatchAppenderInitialised.get()) {
             loggingEventsQueue.offer(event);
         } else {
             // just do nothing
         }
    }
    
    public void activateOptions() {
        if (isBlank(logGroupName) || isBlank(logStreamName)) {
            logger2.error("Could not initialise CloudwatchAppender because either or both LogGroupName(" + logGroupName + ") and LogStreamName(" + logStreamName + ") are null or empty");
            this.stop();
        } else {
          //below lines work with aws version 1.9.40 for local build
          //this.awsLogsClient = new AWSLogsClient();
          //awsLogsClient.setRegion(Region.getRegion(Regions.AP_SOUTHEAST_2));
          this.awsLogsClient = com.amazonaws.services.logs.AWSLogsClientBuilder.standard().withRegion(Regions.AP_SOUTHEAST_2).build();
            loggingEventsQueue = new LinkedBlockingQueue<>(queueLength);
            try {
                initializeCloudwatchResources();
                initCloudwatchDaemon();
                cloudwatchAppenderInitialised.set(true);
            } catch (Exception e) {
                logger2.error("Could not initialise Cloudwatch Logs for LogGroupName: " + logGroupName + " and LogStreamName: " + logStreamName, e);
                if (DEBUG_MODE) {
                    System.err.println("Could not initialise Cloudwatch Logs for LogGroupName: " + logGroupName + " and LogStreamName: " + logStreamName);
                    e.printStackTrace();
                }
            }
        }
    }
    
    private void initCloudwatchDaemon() {
     Thread t = new Thread(() -> {
            while (true) {
                try {
                    if (loggingEventsQueue.size() > 0) {
                        sendMessages();
                    }
                    Thread.currentThread().sleep(20L);
                } catch (InterruptedException e) {
                    if (DEBUG_MODE) {
                        e.printStackTrace();
                    }
                }
            }
        });
     t.setName("CloudwatchThread");
     t.setDaemon(true);
     t.start();
    }
    
    private void sendMessages() {
        synchronized (sendMessagesLock) {
            LogEvent polledLoggingEvent;
            final Layout layout = getLayout();
            List loggingEvents = new ArrayList<>();

            try {

                while ((polledLoggingEvent = loggingEventsQueue.poll()) != null && loggingEvents.size() <= messagesBatchSize) {
                    loggingEvents.add(polledLoggingEvent);
                }
                List inputLogEvents = loggingEvents.stream()
                        .map(loggingEvent -> new InputLogEvent().withTimestamp(loggingEvent.getTimeMillis())
                          .withMessage
                          (
                            layout == null ?
                            loggingEvent.getMessage().getFormattedMessage():
                            new String(layout.toByteArray(loggingEvent), StandardCharsets.UTF_8)
                            )
                          )
                        .sorted(comparing(InputLogEvent::getTimestamp))
                        .collect(toList());

                if (!inputLogEvents.isEmpty()) {

                    PutLogEventsRequest putLogEventsRequest = new PutLogEventsRequest(
                            logGroupName,
                            logStreamName,
                            inputLogEvents);

                    try {
                        putLogEventsRequest.setSequenceToken(lastSequenceToken.get());
                        PutLogEventsResult result = awsLogsClient.putLogEvents(putLogEventsRequest);
                        lastSequenceToken.set(result.getNextSequenceToken());
                    } catch (DataAlreadyAcceptedException dataAlreadyAcceptedExcepted) {
                     
                        putLogEventsRequest.setSequenceToken(dataAlreadyAcceptedExcepted.getExpectedSequenceToken());
                        PutLogEventsResult result = awsLogsClient.putLogEvents(putLogEventsRequest);
                        lastSequenceToken.set(result.getNextSequenceToken());
                        if (DEBUG_MODE) {
                            dataAlreadyAcceptedExcepted.printStackTrace();
                        }
                    } catch (InvalidSequenceTokenException invalidSequenceTokenException) {
                        putLogEventsRequest.setSequenceToken(invalidSequenceTokenException.getExpectedSequenceToken());
                        PutLogEventsResult result = awsLogsClient.putLogEvents(putLogEventsRequest);
                        lastSequenceToken.set(result.getNextSequenceToken());
                        if (DEBUG_MODE) {
                            invalidSequenceTokenException.printStackTrace();
                        }
                    }
                }
            } catch (Exception e) {
                if (DEBUG_MODE) {
                 logger2.error(" error inserting cloudwatch:",e);
                    e.printStackTrace();
                }
            }
        }
    }

    private void initializeCloudwatchResources() {

        DescribeLogGroupsRequest describeLogGroupsRequest = new DescribeLogGroupsRequest();
        describeLogGroupsRequest.setLogGroupNamePrefix(logGroupName);

        Optional logGroupOptional = awsLogsClient
                .describeLogGroups(describeLogGroupsRequest)
                .getLogGroups()
                .stream()
                .filter(logGroup -> logGroup.getLogGroupName().equals(logGroupName))
                .findFirst();

        if (!logGroupOptional.isPresent()) {
            CreateLogGroupRequest createLogGroupRequest = new CreateLogGroupRequest().withLogGroupName(logGroupName);
            awsLogsClient.createLogGroup(createLogGroupRequest);
        }

        DescribeLogStreamsRequest describeLogStreamsRequest = new DescribeLogStreamsRequest().withLogGroupName(logGroupName).withLogStreamNamePrefix(logStreamName);

        Optional logStreamOptional = awsLogsClient
                .describeLogStreams(describeLogStreamsRequest)
                .getLogStreams()
                .stream()
                .filter(logStream -> logStream.getLogStreamName().equals(logStreamName))
                .findFirst();
        if (!logStreamOptional.isPresent()) {
            CreateLogStreamRequest createLogStreamRequest = new CreateLogStreamRequest().withLogGroupName(logGroupName).withLogStreamName(logStreamName);
            CreateLogStreamResult o = awsLogsClient.createLogStream(createLogStreamRequest);
        }

    }
    
    private boolean isBlank(String string) {
        return null == string || string.trim().length() == 0;
    }
    protected String getSimpleStacktraceAsString(final Throwable thrown) {
        final StringBuilder stackTraceBuilder = new StringBuilder();
        for (StackTraceElement stackTraceElement : thrown.getStackTrace()) {
            new Formatter(stackTraceBuilder).format("%s.%s(%s:%d)%n",
                    stackTraceElement.getClassName(),
                    stackTraceElement.getMethodName(),
                    stackTraceElement.getFileName(),
                    stackTraceElement.getLineNumber());
        }
        return stackTraceBuilder.toString();
    }

    @Override
    public void start() {
        super.start();
    }

    @Override
    public void stop() {
        super.stop();
        while (loggingEventsQueue != null && !loggingEventsQueue.isEmpty()) {
            this.sendMessages();
        }
    }

    @Override
    public String toString() {
        return CloudwatchAppender.class.getSimpleName() + "{"
                + "name=" + getName() + " loggroupName=" + logGroupName
                +" logstreamName=" + logStreamName;
               
    }

    @PluginFactory
    @SuppressWarnings("unused")
    public static CloudwatchAppender createCloudWatchAppender(
      @PluginAttribute(value = "queueLength" ) Integer queueLength,
                                                  @PluginElement("Layout") Layout layout,
                                                  @PluginAttribute(value = "logGroupName") String logGroupName,
                                                  @PluginAttribute(value = "logStreamName") String logStreamName,
                                                  @PluginAttribute(value = "name") String name,
                                                  @PluginAttribute(value = "ignoreExceptions", defaultBoolean = false) Boolean ignoreExceptions,
                                                  
                                                  @PluginAttribute(value = "messagesBatchSize") Integer messagesBatchSize)
    {
     return new CloudwatchAppender(name, layout, null, ignoreExceptions, logGroupName, logStreamName ,queueLength,messagesBatchSize);
    }
}

We add the dependency in our pom.xml file.
<dependency>
   <groupId>com.amazonaws</groupId>
   <artifactId>aws-java-sdk-logs</artifactId>
   <!-- for local 3.8.5 we need to use this version cloudhub 3.8.5 has jackson 2.6.6 -->
   <!-- <version>1.9.40</version> -->
   <version>1.11.105</version>
   <exclusions>
    <exclusion>  <!-- declare the exclusion here -->
     <groupId>org.apache.logging.log4j</groupId>
     <artifactId>log4j-1.2-api</artifactId>
    </exclusion>
    <exclusion>  <!-- declare the exclusion here -->
     <groupId>com.fasterxml.jackson.core</groupId>
     <artifactId>jackson-core</artifactId>
    </exclusion>
    <exclusion>  <!-- declare the exclusion here -->
     <groupId>com.fasterxml.jackson.core</groupId>
     <artifactId>jackson-databind</artifactId>
    </exclusion>
   </exclusions>
  </dependency>
  <!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-api -->
  <dependency>
   <groupId>org.apache.logging.log4j</groupId>
   <artifactId>log4j-api</artifactId>
   <version>2.5</version>
  </dependency>
  <!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-core -->
  <dependency>
   <groupId>org.apache.logging.log4j</groupId>
   <artifactId>log4j-core</artifactId>
   <version>2.5</version>
  </dependency>
Now we need to modify our log4j2.xml. add out custom cloudwatch appender and CloudhubLogs appender as well so that we get the logs on cloudhub as well.
<?xml version="1.0" encoding="utf-8"?>
<Configuration status="trace" packages="au.edu.vu.appenders,com.mulesoft.ch.logging.appender">

 <!--These are some of the loggers you can enable. 
     There are several more you can find in the documentation. 
        Besides this log4j configuration, you can also use Java VM environment variables
        to enable other logs like network (-Djavax.net.debug=ssl or all) and 
        Garbage Collector (-XX:+PrintGC). These will be append to the console, so you will 
        see them in the mule_ee.log file. -->


    <Appenders>
         <CLOUDW name="CloudW" logGroupName="test-log-stream" 
        logStreamName="test44" messagesBatchSize="${sys:cloudwatch.msg.batch.size}" queueLength="${sys:cloudwatch.queue.length}">
   <PatternLayout pattern="%d [%t] %-5p %c - %m%n"/>
  </CLOUDW>
  
  <Log4J2CloudhubLogAppender name="CLOUDHUB"
                                   addressProvider="com.mulesoft.ch.logging.DefaultAggregatorAddressProvider"
                                   applicationContext="com.mulesoft.ch.logging.DefaultApplicationContext"
                                   appendRetryIntervalMs="${sys:logging.appendRetryInterval}"
                                   appendMaxAttempts="${sys:logging.appendMaxAttempts}"
                                   batchSendIntervalMs="${sys:logging.batchSendInterval}"
                                   batchMaxRecords="${sys:logging.batchMaxRecords}"
                                   memBufferMaxSize="${sys:logging.memBufferMaxSize}"
                                   journalMaxWriteBatchSize="${sys:logging.journalMaxBatchSize}"
                                   journalMaxFileSize="${sys:logging.journalMaxFileSize}"
                                   clientMaxPacketSize="${sys:logging.clientMaxPacketSize}"
                                   clientConnectTimeoutMs="${sys:logging.clientConnectTimeout}"
                                   clientSocketTimeoutMs="${sys:logging.clientSocketTimeout}"
                                   serverAddressPollIntervalMs="${sys:logging.serverAddressPollInterval}"
                                   serverHeartbeatSendIntervalMs="${sys:logging.serverHeartbeatSendIntervalMs}"
                                   statisticsPrintIntervalMs="${sys:logging.statisticsPrintIntervalMs}">

            <PatternLayout pattern="[%d{MM-dd HH:mm:ss}] %-5p %c{1} [%t] CUSTOM: %m%n"/>
        </Log4J2CloudhubLogAppender>
        
    </Appenders>
    <Loggers>
     
     
  <!-- Http Logger shows wire traffic on DEBUG -->
  <AsyncLogger name="org.mule.module.http.internal.HttpMessageLogger" level="WARN"/>
 
  <!-- JDBC Logger shows queries and parameters values on DEBUG -->
  <AsyncLogger name="com.mulesoft.mule.transport.jdbc" level="WARN"/>
    
        <!-- CXF is used heavily by Mule for web services -->
        <AsyncLogger name="org.apache.cxf" level="WARN"/>

        <!-- Apache Commons tend to make a lot of noise which can clutter the log-->
        <AsyncLogger name="org.apache" level="WARN"/>

        <!-- Reduce startup noise -->
        <AsyncLogger name="org.springframework.beans.factory" level="WARN"/>

        <!-- Mule classes -->
        <AsyncLogger name="org.mule" level="INFO"/>
        <AsyncLogger name="com.mulesoft" level="INFO"/>

        <!-- Reduce DM verbosity -->
        <AsyncLogger name="org.jetel" level="WARN"/>
        <AsyncLogger name="Tracking" level="WARN"/>
        
        <AsyncRoot level="INFO">
            <AppenderRef ref="CLOUDHUB" level="INFO"/>
            <AppenderRef ref="CloudW" level="INFO"/>
        </AsyncRoot>
    </Loggers>
</Configuration>
Finally we need to disable cloudhub logs on cloudhub run time manager.

This is working with cloudhub mule runtime version 3.8.4. some issue with cloudhub 3.8.5 version, where it is getting initilized properly, and sending logs, but events and messages are missing.