View Javadoc
1   /**
2    * Logback: the reliable, generic, fast and flexible logging framework.
3    * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
4    *
5    * This program and the accompanying materials are dual-licensed under
6    * either the terms of the Eclipse Public License v1.0 as published by
7    * the Eclipse Foundation
8    *
9    *   or (per the licensee's choosing)
10   *
11   * under the terms of the GNU Lesser General Public License version 2.1
12   * as published by the Free Software Foundation.
13   */
14  package ch.qos.logback.core.rolling;
15  
16  import static ch.qos.logback.core.testUtil.CoreTestConstants.FAILURE_EXIT_CODE;
17  import static ch.qos.logback.core.testUtil.CoreTestConstants.SUCCESSFUL_EXIT_CODE;
18  import static org.junit.Assert.assertEquals;
19  import static org.junit.Assert.fail;
20  
21  import java.io.File;
22  import java.io.FileOutputStream;
23  import java.io.FilenameFilter;
24  import java.io.IOException;
25  import java.io.OutputStream;
26  
27  import ch.qos.logback.core.testUtil.CoreTestConstants;
28  import ch.qos.logback.core.testUtil.EnvUtilForTests;
29  
30  import org.junit.After;
31  import org.junit.Before;
32  import org.junit.Test;
33  
34  import ch.qos.logback.core.Context;
35  import ch.qos.logback.core.ContextBase;
36  import ch.qos.logback.core.contention.MultiThreadedHarness;
37  import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
38  import ch.qos.logback.core.encoder.EchoEncoder;
39  import ch.qos.logback.core.encoder.Encoder;
40  import ch.qos.logback.core.testUtil.RandomUtil;
41  import ch.qos.logback.core.testUtil.StatusChecker;
42  import ch.qos.logback.core.util.FileSize;
43  import ch.qos.logback.core.util.StatusPrinter;
44  
45  public class MultiThreadedRollingTest {
46  
47      final static int NUM_THREADS = 10;
48      final static int TOTAL_DURATION = 600;
49      RunnableWithCounterAndDone[] runnableArray;
50  
51      Encoder<Object> encoder;
52      Context context = new ContextBase();
53  
54      static String VERIFY_SH = "verify.sh";
55  
56      int diff = RandomUtil.getPositiveInt();
57      String outputDirStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "multi-" + diff + "/";
58  
59      RollingFileAppender<Object> rfa = new RollingFileAppender<Object>();
60  
61      String pathToBash = EnvUtilForTests.getPathToBash();
62      OutputStream scriptOS;
63  
64      @Before
65      public void setUp() throws Exception {
66          encoder = new EchoEncoder<Object>();
67          File outputDir = new File(outputDirStr);
68          outputDir.mkdirs();
69  
70          System.out.println("Output dir [" + outputDirStr + "]");
71  
72          scriptOS = openScript();
73  
74          rfa.setName("rolling");
75          rfa.setEncoder(encoder);
76          rfa.setContext(context);
77          rfa.setFile(outputDirStr + "output.log");
78  
79      }
80  
81      void close(OutputStream os) {
82          if (os != null) {
83              try {
84                  os.close();
85              } catch (IOException e) {
86              }
87          }
88      }
89  
90      @After
91      public void tearDown() throws Exception {
92          rfa.stop();
93      }
94  
95      public void setUpTimeBasedTriggeringPolicy(RollingFileAppender<Object> rfa) {
96          String datePattern = "yyyy-MM-dd'T'HH_mm_ss_SSS";
97          TimeBasedRollingPolicy<Object> tbrp = new TimeBasedRollingPolicy<>();
98          tbrp.setFileNamePattern(outputDirStr + "test-%d{" + datePattern + "}");
99          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 }