Java – isn’t log4j thread safe after all?
(this is in sles11, Java 7, Tomcat 6, log4j-1.2.16)
We use log4j to write different things to different log files I inherited this code, so for better or worse, the general structure will stay for a while
The logger will create two log files: main Log and stats log. The two recorders are logged to a statistic (you'll see below) through a separate call, and a large number of other contents are logged to the main log
Therefore, through our code, you will see such as log logMain(someMessageToLog); Something like that In one place in our code (executed by multiple threads), there are the following:
String statsMessage = createStatsMessage(); Log.logMain(statsMessage); Log.logStats(statsMessage);
The name of the main recorder is main and the name of the statistical recorder is stats The problem is that sometimes when the load is heavy, we will be in main Log to see the line containing string statistics info main. All contents in the log should contain only the main info, because this is the only recorder recorded to the file, and we see mixed output in some lines This seems to be a thread safety issue, but the log4j document says log4j is thread safe This is an example of what I mean:
2012-03-21 16:01:34,7742012-03-21 16:01:34,774| | stats main INFO [INFO http-8080-18]: [message redacted]. 2012-03-21 16:01:36,380| main 2012-03-21 16:01:36,380| INFO [stats INFO http-8080-15]: [message redacted]. 2012-03-21 16:01:37,465| main INFO 2012-03-21 16:01:37,465 [| stats http-8080-1]: [message redacted].
This is the log class (stripped to show only the recorders in question – there is actually a bunch of other recorders, all of which are similar):
import org.apache.log4j.*;
import java.io.IOException;
final public class Log
{
private static final String LOG_IDENTIFIER_MAINLOG = "main";
private static final String LOG_IDENTIFIER_STATSLOG = "stats";
private static final String MAIN_FILENAME = "/var/log/app_main.log";
private static final String STATS_FILENAME = "/var/log/app_stats.log";
private static final int BACKUP_INDEX = 40;
private static final String BACKUP_SIZE = "10MB";
private static final PatternLayout COMMON_LAYOUT =
new PatternLayout("%d| %c %-6p [%t]: %m.%n");
private static Logger mainLogger;
private static Logger statsLogger;
public static void init() {
init(MAIN_FILENAME,STATS_FILENAME);
}
public static void init(String mainLogFilename,String statsLogFilename) {
mainLogger = initializeMainLogger(mainLogFilename);
statsLogger = initializeStatsLogger(statsLogFilename);
}
public static void logMain(String message) {
if (mainLogger != null) {
mainLogger.info(message);
}
}
public static void logStats(String message) {
if (statsLogger != null) {
statsLogger.info(message);
}
}
private static Logger getLogger(String loggerIdentifier) {
Logger logger = Logger.getLogger(loggerIdentifier);
logger.setAdditivity(false);
return logger;
}
private static boolean addFileAppender(Logger logger,String logFilename,int maxBackupIndex,String maxSize) {
try {
RollingFileAppender appender =
new RollingFileAppender(COMMON_LAYOUT,logFilename);
appender.setMaxBackupIndex(maxBackupIndex);
appender.setMaxFileSize(maxSize);
logger.addAppender(appender);
}
catch (IOException ex) {
ex.printStackTrace();
return false;
}
return true;
}
private static Logger initializeMainLogger(String filename) {
Logger logger = getLogger(LOG_IDENTIFIER_MAINLOG);
addFileAppender(logger,filename,BACKUP_INDEX,BACKUP_SIZE);
logger.setLevel(Level.INFO);
return logger;
}
private static Logger initializeStatsLogger(String filename) {
Logger logger = getLogger(LOG_IDENTIFIER_STATSLOG);
addFileAppender(logger,BACKUP_SIZE);
logger.setLevel(Level.INFO);
return logger;
}
}
to update:
This is an applet (at least for me) that will reproduce the problem using the above log class:
final public class Stress
{
public static void main(String[] args) throws Exception {
if (args.length != 2) {
Log.init();
}
else {
Log.init(args[0],args[1]);
}
for (;;) {
// I kNow Executors are preferred,but this
// is a quick & dirty test program
Thread t = new Thread(new TestLogging());
t.start();
}
}
private static final class TestLogging implements Runnable
{
private static int counter = 0;
@Override
public void run() {
String msg = new StringBuilder("Count is: ")
.append(counter++).toString();
Log.logMain(msg);
Log.logStats(msg);
try {
Thread.sleep(1);
}
catch (InterruptedException e) {
Log.logMain(e.getMessage());
}
}
}
}
And some sample outputs in the log:
$grep stats main.log 2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO INFO [ [Thread-313037]: Thread-313036]: Count is: 312987. 2012-03-23 15:30:35,929| stats INFO [Thread-313100]: Count is: 313050. 2012-03-23 15:30:35,937| stats INFO [Thread-313168]: Count is: 313112. 2012-03-23 15:30:35,945| stats INFO [Thread-313240]: Count is: 313190. 2012-03-23 15:30:35,946| stats INFO [Thread-313251]: Count is: 313201. 2012-03-23 15:30:35,949| stats INFO [2012-03-23 15:30:35,949| main INFO Thread-313281]: Count is: 313231. 2012-03-23 15:30:35,954| stats INFO [Thread-313331]: Count is: 313281. 2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO [ [Thread-313356]: Count is: 313306. 2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO stats [INFOThread-313359]: Count is: 313309. 2012-03-23 15:30:35,962| stats INFO 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
and
$grep main stats.log 2012-03-23 15:30:35,913| 2012-03-23 15:30:35,913| main INFO [Thread-312998]: Count is: 312948. 2012-03-23 15:30:35,915| main INFO [Thread-313014]: Count is: 312964. 2012-03-23 15:30:35,931| main INFO [Thread-313116]: Count is: 313066. 2012-03-23 15:30:35,947| main INFO [2012-03-23 15:30:35,947Thread-313264]: | Count is: 313214. 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
For its value, in a 145516 line of main In the log file, "stats" appears 2452 times So it's not uncommon, but it doesn't happen all the time (of course, this test is very extreme)
Solution
http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html
You can share patternlayout between two Appenders according to the API link above:
This code is known to have synchronization and org apache. log4j. Other problems that do not exist in enhancedpatternlayout Enhanced patternlayout should be used in preference to patternlayout Enhanced pattern layout is distributed in log4j extras
Therefore, create a new patternlayout for each appender