We are facing an issue with one of our applications where the peak load is causing the log4j2 to hang and the application doesn't repond. log4j2.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" name="myApplication" packages="com.application.logging.log4j">
<Properties>
<Property name="logLocation">./log</Property> <!-- current directory-->
<Property name="filename">application</Property>
<Property name="maxLogFileSize">50 MB</Property>
<Property name="rolloverCount">20</Property>
</Properties>
<Loggers>
<AsyncRoot level="WARN">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncRoot>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
<AsyncLogger name="CustomLogger" level="INFO" additivity="false">
<AppenderRef ref="Message"/>
</AsyncLogger>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
</Loggers>
<Appenders>
<Console name="STDOUT" target="SYSTEM_OUT">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<Console name="STDERR" target="SYSTEM_ERR">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<RollingRandomAccessFile name="File" fileName="${logLocation}/${filename}.log" filePattern="${logLocation}/${filename}-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileErr" fileName="${logLocation}/${filename}_err.log" filePattern="${logLocation}/${filename}_err-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileMetrics" fileName="${logLocation}/${filename}_metrics.log" filePattern="${logLocation}/${filename}_metrics-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="%msg%n"/>
<Policies>
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<AppMessageAppender name="Message" directory="${logLocation}/messages"/>
</Appenders>
</Configuration>
package com.application.logging;
import java.net.URL;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public final class Log4j2Logger {
private static final String DEFAULT_CATEGORY = "com.application";
private Logger log;
static {
configureLogger();
}
public Logger(String category){
this.category = category;
}
/**
* Constructs Log4jLogger with default ("com.application") category
*/
public Log4j2Logger(){
log = LogManager.getLogger(DEFAULT_CATEGORY);
}
/**
* Constructs Log4jLogger with given category
* @param category
*/
public Log4j2Logger(String category){
super(category);
log = LogManager.getLogger(category);
}
/**
* Constructs Log4jLogger with given class
* @param clazz
*/
public Log4j2Logger(Class clazz){
super(clazz);
log = LogManager.getLogger(clazz.getName());
}
/**
* Log message at debug level
* @param message
*/
public void debug(Object message){
log.debug(message);
}
/**
* Log exception with given message at debug level
* @param message
* @param t
*/
public void debug(Object message, Throwable t){
log.debug(message,t);
}
/**
* Log message at info level
* @param message
*/
public void info(Object message){
log.info(message);
}
/**
* Log exception with given message at info level
* @param message
* @param t
*/
public void info(Object message, Throwable t){
log.info(message,t);
}
/**
* Log message at warn level
* @param message
*/
public void warn(Object message){
log.warn(message);
}
/**
* Log exception with given message at warn level
* @param message
* @param t
*/
public void warn(Object message, Throwable t){
log.warn(message,t);
}
/**
* Log message at error level
* @param message
*/
public void error(Object message){
log.error(message);
}
/**
* Log exception with given message at error level
* @param message
* @param t
*/
public void error(Object message, Throwable t){
log.error(message,t);
}
/**
* Log message at fatal level
* @param message
*/
public void fatal(Object message){
log.fatal(message);
}
/**
* Log exception with given message at fatal level
* @param message
* @param t
*/
public void fatal(Object message, Throwable t){
log.fatal(message,t);
}
@Override
public void debug(String message) {
log.debug(message);
}
@Override
public void debug(String message, Throwable t) {
log.debug(message,t);
}
@Override
public void error(String message) {
log.error(message);
}
@Override
public void error(String message, Throwable t) {
log.error(message,t);
}
@Override
public void fatal(String message) {
log.fatal(message);
}
@Override
public void fatal(String message, Throwable t) {
log.fatal(message,t);
}
@Override
public void info(String message) {
log.info(message);
}
@Override
public void info(String message, Throwable t) {
log.info(message,t);
}
@Override
public void warn(String message) {
log.warn(message);
}
@Override
public void warn(String message, Throwable t) {
log.warn(message,t);
}
@Override
public boolean isTraceEnabled() {
return log.isTraceEnabled();
}
@Override
public void trace(Object message) {
log.trace(message);
}
@Override
public void trace(Object message, Throwable t) {
log.trace(message,t);
}
@Override
public void trace(String message) {
log.trace(message);
}
@Override
public void trace(String message, Throwable t) {
log.trace(message,t);
}
/**
* @return true if debug level log is enabled
*/
public boolean isDebugEnabled(){
return log.isDebugEnabled();
}
public boolean isInfoEnabled(){
return log.isInfoEnabled();
}
public boolean isEnableForLevel(com.application.Level level){
return log.isEnabled(((Log4j2Level)level).getLog4jLevel());
}
public com.application.loggging.Level getLogLevel(){
return Log4j2Level.convert2Log4j(log.getLevel());
}
public void setLogLevel(com.application.Level level){
((org.apache.logging.log4j.core.Logger)log).setLevel(((Log4j2Level)level).getLog4jLevel());
}
private static void configureLogger(){
System.setProperty("Log4jContextSelector","org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
System.setProperty("AsyncLogger.ThreadNameStrategy","UNCACHED");
mbean.setSystemProperties();
try{
URL url = Thread.currentThread().getContextClassLoader().getResource("log4j2.xml");
if(url != null){
System.setProperty("log4j.configurationFile",url.toString());
}else{
System.err.println("No log4j2.xml configuration found in the classpath logger");
}
Log4j2Logger logger = new Log4j2Logger();
logger.info("Log4j2 logger configured");
}catch(Exception e){
e.printStackTrace();
}
}
}
package com.application.logging;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileWriter;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.Date;`
import java.util.Properties;
import java.util.concurrent.atomic.AtomicLong;
import org.apache.commons.lang.time.FastDateFormat;
import org.apache.log4j.helpers.LogLog;
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.Configuration;
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.PluginConfiguration;
import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.layout.PatternLayout;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.application.logging.CustomMessage;
import com.application.framework.utils.PropertiesCache;
import com.application.utils.xml.SpringBeanFactory;
@Plugin(name = "AppMessageAppender", category = "Core", elementType = "appender", printObject = true)
public final class AppMessageAppender extends AbstractAppender {
private static final long serialVersionUID = 1L;
private static final String DEFAULT_DATE_FORMAT = "dd_MM_yyyy/HH";
private static final String DEFAULT_TIME_FORMAT = "HHmmss_SSS";
private static Logger logger = LoggerFactory.getLogger(AppMessageAppender.class);
private String directoryName;
private String dirTimeFormat = DEFAULT_DATE_FORMAT;
private FastDateFormat dateFormatter;
private static FastDateFormat timeFormatter = FastDateFormat.getInstance(DEFAULT_TIME_FORMAT);
private AtomicLong sequenceNo = new AtomicLong();
protected AppMessageAppender(String name, Filter filter, Layout<? extends Serializable> layout,
String directoryName, String subDirectoryDateFormat) {
super(name, filter, layout);
this.directoryName = directoryName;
if (subDirectoryDateFormat != null)
this.dirTimeFormat = subDirectoryDateFormat;
dateFormatter = FastDateFormat.getInstance(dirTimeFormat);
}
@Override
public void append(LogEvent event) {
Writer writer = null;
try {
CustomMessage logMessage = (CustomMessage) event.getMessage().getParameters()[0];
StringBuilder sb = new StringBuilder();
if (directoryName != null) {
sb.append(directoryName).append("/");
}
Date d = new Date(event.getTimeMillis());
sb.append(dateFormatter.format(d)).append("/").append(logMessage.getChannel());
String dir = sb.toString();
String processMessageId = logMessage.getMessageId();
sb.append("/Msg_").append(logMessage.getMessageId().replaceAll("/", "")).append("_")
.append(timeFormatter.format(d)).append("_").append(sequenceNo.getAndIncrement())
.append(".log");
String absFile = sb.toString();
writer = writeToFile(logMessage, dir, absFile);
logger.info("AppMessageAppender message logged: {} ", absFile);
String channelType = logMessage.getChannel();
Properties auditPropConfig = PropertiesCache.getAuditChannelCapability();
String beanName = auditPropConfig.getProperty(channelType);
} catch (IOException e) {
LogLog.error("Exception in writing to file", e);
} finally {
if (writer != null) {
try {
writer.close();
} catch (IOException e) {
logger.error("Error in closing the stream");
}
}
}
}
private Writer writeToFile(CustomMessage logMessage, String dir, String absFile) throws IOException {
Writer writer;
try {
writer = new BufferedWriter(new FileWriter(absFile));
} catch (FileNotFoundException fne) {
File f = new File(dir);
f.mkdirs();
writer = new BufferedWriter(new FileWriter(absFile));
}
logMessage.write(writer);
writer.flush();
return writer;
}
@PluginFactory
public static AppMessageAppender createAppender(@PluginAttribute("name") String name,
@PluginElement("Filter")
final Filter filter, @PluginElement("Layout") Layout<? extends Serializable> layout,
@PluginAttribute("directory")
final String directoryName, @PluginAttribute("subDirectoryDateFormat")
final String subDirectoryDateFormat, @PluginConfiguration
final Configuration config) {
if (layout == null) {
layout = PatternLayout.createDefaultLayout();
}
return new AppMessageAppender(name, filter, layout, directoryName, subDirectoryDateFormat);
}
}
package com.application.logging;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.LinkedHashMap;
import java.util.Map;
public class CustomMessage implements Serializable{
private static final String HEADER_SEP = ": ";
private static final String NEWLINE = "\r\n";
private static final String CHANNEL_HEADER_NAME = "Channel";
private static final String MESSAGEID_HEADER_NAME = "MessageId";
private static final String DEFAULT_CHANNEL = "DefaultChannel";
private static final String DEFAULT_MESSAGEID = "Message";
protected Map<String,String> headers = new LinkedHashMap<String,String>(4);
protected String body;
public CustomMessage(String channel, String messageId){
addHeader(CHANNEL_HEADER_NAME,channel != null ? channel : DEFAULT_CHANNEL);
addHeader(MESSAGEID_HEADER_NAME,messageId != null ? messageId : DEFAULT_MESSAGEID);
}
public String getChannel(){
return headers.get(CHANNEL_HEADER_NAME);
}
public String getMessageId(){
return headers.get(MESSAGEID_HEADER_NAME);
}
public void addHeader(String name, String value){
headers.put(name, value);
}
public void setBody(String body){
this.body = body;
}
public void write(Writer w) throws IOException{
writeHeaders(w);
writeLine(w);
writeBody(w);
}
private void writeHeaders(Writer w) throws IOException {
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
w.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
writeLine(w);
}
}
}
private void writeBody(Writer w) throws IOException {
if(body != null)
w.write(body);
}
private void writeLine(Writer w) throws IOException{
w.write(NEWLINE);
}
public String toString(){
StringBuilder sb = new StringBuilder();
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
sb.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
sb.append(NEWLINE);
}
}
sb.append(NEWLINE);
sb.append(body);
return sb.toString();
}
}
"[STUCK] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'" #91 daemon prio=1 os_prio=0 tid=0x00007fe644022800 nid=0x3928 runnable [0x00007fe5b6ceb000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:465)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:331)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:222)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:181)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:166)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:161)
at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:131)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2002)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1974)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:318)
at com.application.logging.log4j.Log4j2Logger.debug(Log4j2Logger.java:129)
at com.application.services.process.ejb.EventSubscriberBean.onMessage(EventSubscriberBean.java:52)
at weblogic.ejb.container.internal.MDListener.execute(MDListener.java:451)
at weblogic.ejb.container.internal.MDListener.transactionalOnMessage(MDListener.java:375)
at weblogic.ejb.container.internal.MDListener.onMessage(MDListener.java:310)
at weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4855)
at weblogic.jms.client.JMSSession.execute(JMSSession.java:4529)
at weblogic.jms.client.JMSSession.executeMessage(JMSSession.java:3976)
at weblogic.jms.client.JMSSession.access$000(JMSSession.java:120)
at weblogic.jms.client.JMSSession$UseForRunnable.run(JMSSession.java:5375)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:553)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
Questions:
Happy to clarify anything more asked.
Quick Edit -: We have seen this over a period of time. Initially the logs are in sync with the server time stamp i.e. logs match the server timestamp. As time progresses, the logging starts slowing down and we see logs which are 3 hours earlier (sometime it goes to 8 hours) getting printed in the logs. I hope that rings a bell somewhere.
Thanks
I suspect that your application is producing log events faster than the Appenders can handle. The configuration shows two ConsoleAppenders. Logging to the console is extremely slow, literally 50x slower than logging to a file.
Async Loggers use a ringbuffer. If this buffer is full (because the Appender cannot take out events fast enough), then the application will not be able to add new events to the queue, so effectively the application is blocked from making progress.
My advice is to only log WARN or ERROR events to the Console, and everything else to files.
Another potential bottleneck is the custom Appender. Note that it opens a new FileWriter for every event. This is going to be slow. Better to open the file once and keep appending to it.