(This is on 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 a good or bad overall structure here to stay on time.
The registrar will create two logfiles: main.log and stats.log . Some statistics message is written to both registrars via separate calls (you will see below), and the whole chain of other records is recorded in the main log.
Thus, through our code you will see things like Log.logMain(someMessageToLog); . In one place of our code (which is executed by several threads), the following exists:
String statsMessage = createStatsMessage(); Log.logMain(statsMessage); Log.logStats(statsMessage);
The name of the main logger is main , the name of the statistics logger is stats . The problem is that sometimes, under heavy load, we see lines in main.log that contain the line stats INFO . Everything in main.log should contain only main INFO , because this is the only log in this file, plus we see mixed output in some lines. This seems like a thread safety issue, but log4j docs say log4j is thread safe. Here 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].
Here is the Log class (trimmed to show only registered logs), in fact, there are many other registrars in it, they are all configured similarly to these:
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, filename, BACKUP_INDEX, BACKUP_SIZE); logger.setLevel(Level.INFO); return logger; } }
Update:
Here's a small program that (at least for me) will reproduce the problem with 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 (;;) {
And some example output in logs:
$ 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,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,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,949| stats INFO [2012-03-23 15:30:35,949| main INFO Thread-313281]: Count is: 313231. 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.
For what it's worth, from the main.log file in 145516 lines, "statistics" appeared 2452 times in it. So this is not uncommon, but it is not, as it happens all the time (and, of course, this test is quite extreme).