Author: ceki Date: Wed Jul 8 15:02:33 2009 New Revision: 2328 Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/MultiThreadedRollingTest.java Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/PeriodicityType.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/RollingCalendar.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/ThreadedThroughputCalculator.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java Log: Working on thread safety of RollingAppender, related to LBCLASSIC-142 Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java Wed Jul 8 15:02:33 2009 @@ -22,8 +22,8 @@ /** * FileAppender appends log events to a file. * - * For more informatio about this appender, please refer to the online manual at - * http://logback.qos.ch/manual/appenders.html#FileAppender + * For more information about this appender, please refer to the online manual + * at http://logback.qos.ch/manual/appenders.html#FileAppender * * @author Ceki Gülcü */ @@ -66,13 +66,13 @@ * the file to append to. */ public void setFile(String file) { - if(file == null) { + if (file == null) { fileName = file; } else { // Trim spaces from both ends. The users probably does not want // trailing spaces in file names. String val = file.trim(); - fileName = val; + fileName = val; } } @@ -90,7 +90,6 @@ return append; } - /** * This method is used by derived classes to obtain the raw file property. * Regular users should not be calling this method. Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java Wed Jul 8 15:02:33 2009 @@ -52,13 +52,13 @@ addError("For more information, please visit http://logback.qos.ch/codes.html#rfa_no_rp"); return; } - - if(isPrudent()) { - if(rawFileProperty() != null) { + + if (isPrudent()) { + if (rawFileProperty() != null) { addWarn("Setting \"File\" property to null on account of prudent mode"); - setFile(null); + setFile(null); } - if(rollingPolicy.getCompressionMode() != CompressionMode.NONE) { + if (rollingPolicy.getCompressionMode() != CompressionMode.NONE) { addError("Compression is not supported in prudent mode. Aborting"); return; } @@ -73,14 +73,13 @@ public void setFile(String file) { // http://jira.qos.ch/browse/LBCORE-94 // allow setting the file name to null if mandated by prudent mode - if(file != null && ((triggeringPolicy != null) || (rollingPolicy != null))) { + if (file != null && ((triggeringPolicy != null) || (rollingPolicy != null))) { addError("File property must be set before any triggeringPolicy or rollingPolicy properties"); addError("Visit http://logback.qos.ch/codes.html#rfa_file_after for more information"); } super.setFile(file); } - @Override public String getFile() { return rollingPolicy.getActiveFileName(); @@ -131,8 +130,10 @@ protected void subAppend(E event) { // The roll-over check must precede actual writing. This is the // only correct behavior for time driven triggers. - if (triggeringPolicy.isTriggeringEvent(activeFile, event)) { - rollover(); + synchronized (triggeringPolicy) { + if (triggeringPolicy.isTriggeringEvent(activeFile, event)) { + rollover(); + } } super.subAppend(event); Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/PeriodicityType.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/PeriodicityType.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/PeriodicityType.java Wed Jul 8 15:02:33 2009 @@ -1,16 +1,24 @@ +/** + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 2000-2009, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. + */ package ch.qos.logback.core.rolling.helper; public enum PeriodicityType { - ERRONEOUS, TOP_OF_SECOND, TOP_OF_MINUTE, TOP_OF_HOUR, HALF_DAY, TOP_OF_DAY, TOP_OF_WEEK, TOP_OF_MONTH; + ERRONEOUS, TOP_OF_MILLISECOND, TOP_OF_SECOND, TOP_OF_MINUTE, TOP_OF_HOUR, HALF_DAY, TOP_OF_DAY, TOP_OF_WEEK, TOP_OF_MONTH; - // The followed list is assued to be in + // The followed list consists of valid periodicy types in increasing period + // lengths static PeriodicityType[] VALID_ORDERED_LIST = new PeriodicityType[] { - PeriodicityType.TOP_OF_SECOND, - PeriodicityType.TOP_OF_MINUTE, - PeriodicityType.TOP_OF_HOUR, - PeriodicityType.TOP_OF_DAY, - PeriodicityType.TOP_OF_WEEK, + TOP_OF_MILLISECOND, PeriodicityType.TOP_OF_SECOND, + PeriodicityType.TOP_OF_MINUTE, PeriodicityType.TOP_OF_HOUR, + PeriodicityType.TOP_OF_DAY, PeriodicityType.TOP_OF_WEEK, PeriodicityType.TOP_OF_MONTH }; } Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/RollingCalendar.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/RollingCalendar.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/RollingCalendar.java Wed Jul 8 15:02:33 2009 @@ -75,7 +75,8 @@ if (datePattern != null) { for (PeriodicityType i : PeriodicityType.VALID_ORDERED_LIST) { SimpleDateFormat simpleDateFormat = new SimpleDateFormat(datePattern); - simpleDateFormat.setTimeZone(GMT_TIMEZONE); // all date formatting done in GMT + simpleDateFormat.setTimeZone(GMT_TIMEZONE); // all date formatting done + // in GMT String r0 = simpleDateFormat.format(epoch); rollingCalendar.setType(i); @@ -90,44 +91,41 @@ } } // we failed - return PeriodicityType.ERRONEOUS; + return PeriodicityType.ERRONEOUS; } public void printPeriodicity(ContextAwareBase cab) { switch (type) { + case TOP_OF_MILLISECOND: + cab.addInfo("Roll-over every millisecond."); + break; + case TOP_OF_SECOND: cab.addInfo("Roll-over every second."); - break; case TOP_OF_MINUTE: cab.addInfo("Roll-over every minute."); - break; case TOP_OF_HOUR: cab.addInfo("Roll-over at the top of every hour."); - break; case HALF_DAY: cab.addInfo("Roll-over at midday and midnight."); - break; case TOP_OF_DAY: cab.addInfo("Roll-over at midnight."); - break; case TOP_OF_WEEK: cab.addInfo("Rollover at the start of week."); - break; case TOP_OF_MONTH: cab.addInfo("Rollover at start of every month."); - break; default: @@ -139,17 +137,19 @@ this.setTime(now); switch (type) { + case TOP_OF_MILLISECOND: + this.add(Calendar.MILLISECOND, periods); + break; + case TOP_OF_SECOND: this.set(Calendar.MILLISECOND, 0); this.add(Calendar.SECOND, periods); - break; case TOP_OF_MINUTE: this.set(Calendar.SECOND, 0); this.set(Calendar.MILLISECOND, 0); this.add(Calendar.MINUTE, periods); - break; case TOP_OF_HOUR: @@ -157,7 +157,6 @@ this.set(Calendar.SECOND, 0); this.set(Calendar.MILLISECOND, 0); this.add(Calendar.HOUR_OF_DAY, periods); - break; case TOP_OF_DAY: @@ -166,7 +165,6 @@ this.set(Calendar.SECOND, 0); this.set(Calendar.MILLISECOND, 0); this.add(Calendar.DATE, periods); - break; case TOP_OF_WEEK: @@ -176,7 +174,6 @@ this.set(Calendar.SECOND, 0); this.set(Calendar.MILLISECOND, 0); this.add(Calendar.WEEK_OF_YEAR, periods); - break; case TOP_OF_MONTH: @@ -186,7 +183,6 @@ this.set(Calendar.SECOND, 0); this.set(Calendar.MILLISECOND, 0); this.add(Calendar.MONTH, periods); - break; default: @@ -195,7 +191,7 @@ return getTime(); } - + public Date getNextTriggeringDate(Date now) { return getRelativeDate(now, 1); } Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java Wed Jul 8 15:02:33 2009 @@ -0,0 +1,65 @@ +/** + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 2000-2009, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. + */ +package ch.qos.logback.core.contention; + + +/** + * Useful scaffolding/harness to start and stop multiple threads. + * + * @author Joern Huxhorn + * @author Ralph Goers + * @author Ceki Gulcu + */ +public class MultiThreadedHarness { + + RunnableWithCounterAndDone[] runnableArray; + Thread[] threadArray; + final long overallDurationInMillis; + + public MultiThreadedHarness(long overallDurationInMillis) { + this.overallDurationInMillis = overallDurationInMillis; + } + + public void printEnvironmentInfo(String msg) { + System.out.println("=== " + msg + " ==="); + System.out.println("java.runtime.version = " + + System.getProperty("java.runtime.version")); + System.out.println("java.vendor = " + + System.getProperty("java.vendor")); + System.out.println("java.version = " + + System.getProperty("java.version")); + System.out.println("os.name = " + + System.getProperty("os.name")); + System.out.println("os.version = " + + System.getProperty("os.version")); + } + + public void execute(RunnableWithCounterAndDone[] runnableArray) + throws InterruptedException { + this.runnableArray = runnableArray; + Thread[] threadArray = new Thread[runnableArray.length]; + + for (int i = 0; i < runnableArray.length; i++) { + threadArray[i] = new Thread(runnableArray[i]); + } + for (Thread t : threadArray) { + t.start(); + } + // let the threads run for a while + Thread.sleep(overallDurationInMillis); + + for (RunnableWithCounterAndDone r : runnableArray) { + r.setDone(true); + } + for (Thread t : threadArray) { + t.join(); + } + } +} Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/ThreadedThroughputCalculator.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/ThreadedThroughputCalculator.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/ThreadedThroughputCalculator.java Wed Jul 8 15:02:33 2009 @@ -1,8 +1,16 @@ +/** + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 2000-2009, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. + */ package ch.qos.logback.core.contention; /** - * * Useful scaffolding to measure the throughput of certain operations when * invoked by multiple threads. * @@ -10,51 +18,13 @@ * @author Ralph Goers * @author Ceki Gulcu */ -public class ThreadedThroughputCalculator { +public class ThreadedThroughputCalculator extends MultiThreadedHarness { - RunnableWithCounterAndDone[] runnableArray; - Thread[] threadArray; - final long overallDurationInMillis; public ThreadedThroughputCalculator(long overallDurationInMillis) { - this.overallDurationInMillis = overallDurationInMillis; - } - - public void printEnvironmentInfo(String msg) { - System.out.println("=== " + msg + " ==="); - System.out.println("java.runtime.version = " - + System.getProperty("java.runtime.version")); - System.out.println("java.vendor = " - + System.getProperty("java.vendor")); - System.out.println("java.version = " - + System.getProperty("java.version")); - System.out.println("os.name = " - + System.getProperty("os.name")); - System.out.println("os.version = " - + System.getProperty("os.version")); + super(overallDurationInMillis); } - public void execute(RunnableWithCounterAndDone[] runnableArray) - throws InterruptedException { - this.runnableArray = runnableArray; - Thread[] threadArray = new Thread[runnableArray.length]; - - for (int i = 0; i < runnableArray.length; i++) { - threadArray[i] = new Thread(runnableArray[i]); - } - for (Thread t : threadArray) { - t.start(); - } - // let the threads run for a while - Thread.sleep(overallDurationInMillis); - - for (RunnableWithCounterAndDone r : runnableArray) { - r.setDone(true); - } - for (Thread t : threadArray) { - t.join(); - } - } public void printThroughput(String msg) throws InterruptedException { printThroughput(msg, false); } Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/MultiThreadedRollingTest.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/MultiThreadedRollingTest.java Wed Jul 8 15:02:33 2009 @@ -0,0 +1,108 @@ +package ch.qos.logback.core.rolling; + +import static org.junit.Assert.fail; + +import java.io.File; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import ch.qos.logback.core.Context; +import ch.qos.logback.core.ContextBase; +import ch.qos.logback.core.Layout; +import ch.qos.logback.core.contention.MultiThreadedHarness; +import ch.qos.logback.core.contention.RunnableWithCounterAndDone; +import ch.qos.logback.core.layout.EchoLayout; +import ch.qos.logback.core.status.StatusChecker; +import ch.qos.logback.core.testUtil.RandomUtil; +import ch.qos.logback.core.util.CoreTestConstants; +import ch.qos.logback.core.util.StatusPrinter; + +public class MultiThreadedRollingTest { + + final static int NUM_THREADS = 5; + final static int TOTAL_DURATION = 2000; + + Layout<Object> layout; + Context context = new ContextBase(); + + int diff = RandomUtil.getPositiveInt(); + String outputDirStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "multi-" + diff + + "/"; + + RollingFileAppender<Object> rfa = new RollingFileAppender<Object>(); + + @Before + public void setUp() throws Exception { + layout = new EchoLayout<Object>(); + File outputDir = new File(outputDirStr); + outputDir.mkdirs(); + + rfa.setName("rolling"); + rfa.setLayout(layout); + rfa.setContext(context); + rfa.setFile(outputDirStr + "output.log"); + String datePattern = "yyyy-MM-dd'T'HH_mm_ss_SSS"; + + TimeBasedRollingPolicy tbrp = new TimeBasedRollingPolicy(); + tbrp.setFileNamePattern(outputDirStr + "test-%d{" + datePattern + "}"); + tbrp.setContext(context); + tbrp.setParent(rfa); + tbrp.start(); + + rfa.setRollingPolicy(tbrp); + rfa.start(); + } + + @After + public void tearDown() throws Exception { + rfa.stop(); + } + + RunnableWithCounterAndDone[] buildRunnableArray() { + RunnableWithCounterAndDone[] runnableArray = new RunnableWithCounterAndDone[NUM_THREADS]; + for (int i = 0; i < NUM_THREADS; i++) { + runnableArray[i] = new RFARunnable(i, rfa); + } + return runnableArray; + } + + @Test + public void executeHarness() throws InterruptedException { + MultiThreadedHarness multiThreadedHarness = new MultiThreadedHarness(TOTAL_DURATION); + RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(); + multiThreadedHarness.execute(runnableArray); + StatusPrinter.print(context); + + StatusChecker checker = new StatusChecker(context.getStatusManager()); + if(!checker.isErrorFree()) { + fail("errors reported"); + StatusPrinter.print(context); + } + + } + + long diff(long start) { + return System.currentTimeMillis() - start; + } + + static class RFARunnable extends RunnableWithCounterAndDone { + RollingFileAppender<Object> rfa; + int id; + RFARunnable(int id, RollingFileAppender<Object> rfa) { + this.id = id; + this.rfa = rfa; + } + + public void run() { + while (!isDone()) { + counter++; + rfa.doAppend(id + " " + counter); + } + System.out.println("id="+id + ", counter="+counter + " on exit"); + } + + } + +} Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java Wed Jul 8 15:02:33 2009 @@ -5,7 +5,7 @@ @RunWith(Suite.class) @Suite.SuiteClasses( { RenamingTest.class, SizeBasedRollingTest.class, - TimeBasedRollingTest.class, + TimeBasedRollingTest.class, TimeBasedRollingWithCleanTest.class, ch.qos.logback.core.rolling.helper.PackageTest.class }) public class PackageTest { } Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java Wed Jul 8 15:02:33 2009 @@ -24,6 +24,11 @@ this.sm = sm; } + public boolean isErrorFree() { + int level = sm.getLevel(); + return level < Status.ERROR; + } + public boolean containsMatch(int level, String regex) { Pattern p = Pattern.compile(regex);