Source code

001/**
002 * Logback: the reliable, generic, fast and flexible logging framework.
003 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
004 *
005 * This program and the accompanying materials are dual-licensed under
006 * either the terms of the Eclipse Public License v1.0 as published by
007 * the Eclipse Foundation
008 *
009 *   or (per the licensee's choosing)
010 *
011 * under the terms of the GNU Lesser General Public License version 2.1
012 * as published by the Free Software Foundation.
013 */
014package ch.qos.logback.core.rolling;
015
016import static ch.qos.logback.core.testUtil.CoreTestConstants.FAILURE_EXIT_CODE;
017import static ch.qos.logback.core.testUtil.CoreTestConstants.SUCCESSFUL_EXIT_CODE;
018import static org.junit.Assert.assertEquals;
019import static org.junit.Assert.fail;
020
021import java.io.File;
022import java.io.FileOutputStream;
023import java.io.FilenameFilter;
024import java.io.IOException;
025import java.io.OutputStream;
026
027import ch.qos.logback.core.testUtil.CoreTestConstants;
028import ch.qos.logback.core.testUtil.EnvUtilForTests;
029
030import org.junit.After;
031import org.junit.Before;
032import org.junit.Test;
033
034import ch.qos.logback.core.Context;
035import ch.qos.logback.core.ContextBase;
036import ch.qos.logback.core.contention.MultiThreadedHarness;
037import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
038import ch.qos.logback.core.encoder.EchoEncoder;
039import ch.qos.logback.core.encoder.Encoder;
040import ch.qos.logback.core.testUtil.RandomUtil;
041import ch.qos.logback.core.testUtil.StatusChecker;
042import ch.qos.logback.core.util.FileSize;
043import ch.qos.logback.core.util.StatusPrinter;
044
045public class MultiThreadedRollingTest {
046
047    final static int NUM_THREADS = 10;
048    final static int TOTAL_DURATION = 600;
049    RunnableWithCounterAndDone[] runnableArray;
050
051    Encoder<Object> encoder;
052    Context context = new ContextBase();
053
054    static String VERIFY_SH = "verify.sh";
055
056    int diff = RandomUtil.getPositiveInt();
057    String outputDirStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "multi-" + diff + "/";
058
059    RollingFileAppender<Object> rfa = new RollingFileAppender<Object>();
060
061    String pathToBash = EnvUtilForTests.getPathToBash();
062    OutputStream scriptOS;
063
064    @Before
065    public void setUp() throws Exception {
066        encoder = new EchoEncoder<Object>();
067        File outputDir = new File(outputDirStr);
068        outputDir.mkdirs();
069
070        System.out.println("Output dir [" + outputDirStr + "]");
071
072        scriptOS = openScript();
073
074        rfa.setName("rolling");
075        rfa.setEncoder(encoder);
076        rfa.setContext(context);
077        rfa.setFile(outputDirStr + "output.log");
078
079    }
080
081    void close(OutputStream os) {
082        if (os != null) {
083            try {
084                os.close();
085            } catch (IOException e) {
086            }
087        }
088    }
089
090    @After
091    public void tearDown() throws Exception {
092        rfa.stop();
093    }
094
095    public void setUpTimeBasedTriggeringPolicy(RollingFileAppender<Object> rfa) {
096        String datePattern = "yyyy-MM-dd'T'HH_mm_ss_SSS";
097        TimeBasedRollingPolicy<Object> tbrp = new TimeBasedRollingPolicy<>();
098        tbrp.setFileNamePattern(outputDirStr + "test-%d{" + datePattern + "}");
099        tbrp.setContext(context);
100        tbrp.setParent(rfa);
101        tbrp.start();
102
103        rfa.setRollingPolicy(tbrp);
104        rfa.start();
105    }
106
107    public void setUpSizeBasedTriggeringPolicy(RollingFileAppender<Object> rfa) {
108        SizeBasedTriggeringPolicy<Object> zbtp = new SizeBasedTriggeringPolicy<>();
109        zbtp.setContext(context);
110        zbtp.setMaxFileSize(FileSize.valueOf("100KB"));
111
112        zbtp.start();
113        rfa.setTriggeringPolicy(zbtp);
114
115        FixedWindowRollingPolicy fwrp = new FixedWindowRollingPolicy();
116        fwrp.setContext(context);
117        fwrp.setFileNamePattern(outputDirStr + "test-%i.log");
118        fwrp.setMaxIndex(20);
119        fwrp.setMinIndex(0);
120        fwrp.setParent(rfa);
121        fwrp.start();
122        rfa.setRollingPolicy(fwrp);
123        rfa.start();
124    }
125
126    RunnableWithCounterAndDone[] buildRunnableArray(boolean withDelay) {
127        RunnableWithCounterAndDone[] runnableArray = new RunnableWithCounterAndDone[NUM_THREADS];
128        for (int i = 0; i < NUM_THREADS; i++) {
129            runnableArray[i] = new RFARunnable(i, rfa, withDelay);
130        }
131        return runnableArray;
132    }
133
134    OutputStream openScript() throws IOException {
135        return new FileOutputStream(outputDirStr + VERIFY_SH);
136    }
137
138    @Test
139    public void multiThreadedTimedBased() throws InterruptedException, IOException {
140        setUpTimeBasedTriggeringPolicy(rfa);
141        executeHarness(TOTAL_DURATION, false);
142        printScriptForTimeBased();
143        verify();
144    }
145
146    int testFileCount() {
147        File outputDir = new File(outputDirStr);
148        FilenameFilter filter = new FilenameFilter() {
149            public boolean accept(File dir, String name) {
150                if (name.matches("test-\\d{1,2}.log")) {
151                    return true;
152                }
153                return false;
154            }
155        };
156        File[] files = outputDir.listFiles(filter);
157        return files.length;
158    }
159
160    void verify() throws IOException, InterruptedException {
161        close(scriptOS);
162        // no point in this test if we don't have bash
163        if (pathToBash == null) {
164            return;
165        }
166        ProcessBuilder pb = new ProcessBuilder();
167        pb.command(pathToBash, VERIFY_SH);
168        pb.directory(new File(outputDirStr));
169        Process process = pb.start();
170        process.waitFor();
171        int exitCode = process.exitValue();
172
173        assertEquals(SUCCESSFUL_EXIT_CODE, exitCode);
174        System.out.println("External script based verification returned with exit code " + exitCode);
175    }
176
177    @Test
178    public void multiThreadedSizeBased() throws InterruptedException, IOException {
179        setUpSizeBasedTriggeringPolicy(rfa);
180        // on a fast machine with a fast hard disk, if the tests runs for too
181        // long the MAX_WINDOW_SIZE is reached, resulting in data loss which
182        // we cannot test for.
183        executeHarness(TOTAL_DURATION, true);
184        int numFiles = testFileCount();
185        printScriptForSizeBased(numFiles);
186        verify();
187    }
188
189    private void printScriptHeader(String type) throws IOException {
190        out("# ====================================================");
191        out("# A script to check the exactness of the output ");
192        out("# produced by " + type + " test");
193        out("# ====================================================");
194        out("# ");
195    }
196
197    private void printCommonScriptCore() throws IOException {
198        out("");
199        out("for t in $(seq 0 1 " + (NUM_THREADS - 1) + ")");
200        out("do");
201        out("  echo \"Testing results of thread $t\"");
202        out("  grep \"$t \" aggregated | cut -d ' ' -f 2 > ${t}-sample");
203        out("  for j in $(seq 1 1 ${end[$t]}); do echo $j; done > ${t}-witness");
204        out("  diff -q -w ${t}-sample ${t}-witness;");
205        out("  res=$?");
206        out("  if [ $res != \"0\" ]; then");
207        out("    echo \"FAILED for $t\"");
208        out("    exit " + FAILURE_EXIT_CODE);
209        out("  fi");
210        out("done");
211        out("");
212        out("exit " + SUCCESSFUL_EXIT_CODE);
213    }
214
215    private void printScriptForTimeBased() throws IOException {
216        printScriptHeader("TimeBased");
217        for (int i = 0; i < NUM_THREADS; i++) {
218            out("end[" + i + "]=" + this.runnableArray[i].getCounter());
219        }
220        out("");
221        out("rm aggregated");
222        out("cat test* output.log >> aggregated");
223        printCommonScriptCore();
224
225    }
226
227    private void printScriptForSizeBased(int numfiles) throws IOException {
228        printScriptHeader("SizeBased");
229
230        for (int i = 0; i < NUM_THREADS; i++) {
231            out("end[" + i + "]=" + this.runnableArray[i].getCounter());
232        }
233        out("");
234        out("rm aggregated");
235        out("for i in $(seq " + (numfiles - 1) + " -1 0); do cat test-$i.log >> aggregated; done");
236        out("cat output.log >> aggregated");
237        out("");
238        printCommonScriptCore();
239    }
240
241    private void out(String msg) throws IOException {
242        scriptOS.write(msg.getBytes());
243        scriptOS.write("\n".getBytes());
244    }
245
246    private void executeHarness(int duration, boolean withDelay) throws InterruptedException {
247        MultiThreadedHarness multiThreadedHarness = new MultiThreadedHarness(duration);
248        this.runnableArray = buildRunnableArray(withDelay);
249        multiThreadedHarness.execute(runnableArray);
250
251        StatusChecker checker = new StatusChecker(context.getStatusManager());
252        if (!checker.isErrorFree(0)) {
253            StatusPrinter.print(context);
254            fail("errors reported");
255        }
256    }
257
258    long diff(long start) {
259        return System.currentTimeMillis() - start;
260    }
261
262    static class RFARunnable extends RunnableWithCounterAndDone {
263        RollingFileAppender<Object> rfa;
264        int id;
265        boolean withInducedDelay;
266
267        RFARunnable(int id, RollingFileAppender<Object> rfa, boolean withInducedDelay) {
268            this.id = id;
269            this.rfa = rfa;
270            this.withInducedDelay = withInducedDelay;
271        }
272
273        public void run() {
274            while (!isDone()) {
275                counter++;
276                rfa.doAppend(id + " " + counter);
277                if ((counter % 64 == 0) && withInducedDelay) {
278                    try {
279                        Thread.sleep(10);
280                    } catch (InterruptedException e) {
281                    }
282                }
283            }
284        }
285    }
286}