Wednesday, January 8, 2014

osb, logback, logstash, grok and elasticsearch, putting it all together

the Java class that I invoke with a custom XPath to trace events :
  • "interface" is like "service/operation"
  • "eventtype" is like "FileConsumed", "JMSMessageConsumed", "WSInvoked"
  • TechnicalMessageID and BusinessID are usinque identifiers for the request/payload
  • ServerName is the WebLogic managed server
  • Priority is P1... P5 in case of error
  • Payload is the actual request... it's traced only if level is "DEBUG"
  • Fault is the error description
package com.acme.osb.logging;

import org.apache.xmlbeans.XmlObject;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * Used by OSB to report an Event
 * 
 * @author NNVernetPI
 * 
 */

public class MessageTrackerSLF4J {

 public static String logMessage(String technicalMessageid,
   String businessId, String eventType, String interfaceName,
   XmlObject payload) {

  Logger projectLogger = LoggerFactory.getLogger(interfaceName);

  if (projectLogger.isDebugEnabled()) {
   projectLogger.info(" ::InterfaceName:: {} ::EventType:: {} ::TechnicalMessageID:: {} ::BusinessID:: {} ::ServerName:: {} ::Priority:: {} ::Payload:: {} ::Fault:: {}", 
     interfaceName, eventType, technicalMessageid, businessId, System.getProperty("weblogic.Name"), "NONE", payload != null ? payload.xmlText().replaceAll("\\r\\n|\\r|\\n", " ") : "NONE", "NONE");

  } else {
   projectLogger.info(" ::InterfaceName:: {} ::EventType:: {} ::TechnicalMessageID:: {} ::BusinessID:: {} ::ServerName:: {} ::Priority:: {} ::Payload:: {} ::Fault:: {}", 
     interfaceName, eventType, technicalMessageid, businessId, System.getProperty("weblogic.Name"), "NONE", "NONE", "NONE");
  }

  String logmessage = "Info Message Logged for:: " + interfaceName;
  return logmessage;
 }

 public static String errorLogger(String technicalMessageid,
   String businessId, String interfaceName, XmlObject payload,
   String priority, XmlObject fault) {

  Logger projectLogger = LoggerFactory.getLogger(interfaceName);

  projectLogger.error(" ::InterfaceName:: {} ::EventType:: {} ::TechnicalMessageID:: {} ::BusinessID:: {} ::ServerName:: {} ::Priority:: {} ::Payload:: {} ::Fault:: {}", 
    interfaceName, "ERROR", technicalMessageid, businessId, System.getProperty("weblogic.Name"), priority, payload != null ? payload.xmlText().replaceAll("\\r\\n|\\r|\\n", " ") : "NONE", fault != null ? fault.xmlText().replaceAll("\\r\\n|\\r|\\n", " ") : "NONE");

  String responseMessage = "Error Message Logged for:: " + interfaceName;
  return responseMessage;
 }

}



To make my parsing easier, I have decided to remove all newlines from payload and fault, so as to have a single line per event in the logs.

You can also deal with multiline with this codec.

For a valid message, logback will log:
#### 2014-01-08 18:04:01,980 INFO [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] - ::InterfaceName:: ProdDeclAven ::EventType:: FileConsumed ::TechnicalMessageID:: ProdDeclAven^BAD_TST_PDA_REV.xml^AVE^1389200641480 ::BusinessID:: 000000000006741320_00376401092900001530 ::ServerName:: osbdev1ms1 ::Priority:: NONE ::Payload:: NONE ::Fault:: NONE ####

logback.xml file:
<?xml version="1.0" ?>
<configuration debug="true" scan="true" scanPeriod="30 seconds">
 <jmxConfigurator/>
 <property name="LOG_DIR" value="/opt/var/log/weblogic/server/"/>
 <appender class="ch.qos.logback.core.ConsoleAppender" name="STDOUT">
  <encoder>
   <pattern>
    #### %date{ISO8601} %level [%thread] - %msg ####%n            
   </pattern>
  </encoder>
 </appender>
 <appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="MyService">
  <file>
   ${LOG_DIR}acmeMyService.log
  </file>
  <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
   <fileNamePattern>
    acmeMyService.%i.log.zip
   </fileNamePattern>
   <minIndex>
    1
   </minIndex>
   <maxIndex>
    10
   </maxIndex>
  </rollingPolicy>
  <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
   <maxFileSize>
    50MB
   </maxFileSize>
  </triggeringPolicy>
  <encoder>
   <pattern>
    #### %date{ISO8601} %level [%thread] - %msg ####%n                
   </pattern>
  </encoder>
 </appender>

 <logger additivity="false" level="INFO" name="MyService_PSDB_RoutingService">
  <appender-ref ref="MyService"/>
 </logger>

 <root level="DEBUG">
  <appender-ref ref="ALL"/>
 </root>
</configuration>





esgrok.conf will be

input {
  file {
    path => "/opt/var/log/weblogic/server/nesoa2*.log"
  }

}
filter {
  grok {
    match => [ "message", "#### %{TIMESTAMP_ISO8601:timestamp} %{WORD:level} \[\[%{WORD:threadstatus}\] %{GREEDYDATA:threadname}\] -  ::InterfaceName:: %{WORD:interfacename} ::EventType:: %{WORD:eventtype} ::TechnicalMessageID:: %{GREEDYDATA:technicalmessageid} ::BusinessID:: %{GREEDYDATA:businessid} ::ServerName:: %{WORD:servername} ::Priority:: %{WORD:priority} ::Payload:: %{GREEDYDATA:payload} ::Fault:: %{GREEDYDATA:fault} ####" ]
  }
}

output {
  elasticsearch {
    embedded => true
  }
}



Preparing the grok match regexp was very time consuming. Using http://grokdebug.herokuapp.com/ the grok debugger was essential. It worked for me only on Chrome, not on Firefox.

Priceless also the list of grok patterns.

Run with nohup java -jar logstash-1.3.2-flatjar.jar agent -f esgrok.conf -- web > logstash.log 2>&1 &
The result is impressive.
Happy Kibana to you!


No comments: