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  
19  import java.io.File;
20  import java.io.FileOutputStream;
21  import java.io.FilenameFilter;
22  import java.io.IOException;
23  import java.io.OutputStream;
24  
25  import ch.qos.logback.core.testUtil.CoreTestConstants;
26  import ch.qos.logback.core.testUtil.EnvUtilForTests;
27  
28  import org.junit.jupiter.api.AfterEach;
29  import org.junit.jupiter.api.Assertions;
30  import org.junit.jupiter.api.BeforeEach;
31  import org.junit.jupiter.api.Test;
32  
33  import ch.qos.logback.core.Context;
34  import ch.qos.logback.core.ContextBase;
35  import ch.qos.logback.core.contention.MultiThreadedHarness;
36  import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
37  import ch.qos.logback.core.encoder.EchoEncoder;
38  import ch.qos.logback.core.encoder.Encoder;
39  import ch.qos.logback.core.testUtil.RandomUtil;
40  import ch.qos.logback.core.status.testUtil.StatusChecker;
41  import ch.qos.logback.core.util.FileSize;
42  import ch.qos.logback.core.util.StatusPrinter;
43  
44  public class MultiThreadedRollingTest {
45  
46      final static int NUM_THREADS = 10;
47      final static int TOTAL_DURATION = 600;
48      RunnableWithCounterAndDone[] runnableArray;
49  
50      Encoder<Object> encoder;
51      Context context = new ContextBase();
52  
53      static String VERIFY_SH = "verify.sh";
54  
55      int diff = RandomUtil.getPositiveInt();
56      String outputDirStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "multi-" + diff + "/";
57  
58      RollingFileAppender<Object> rfa = new RollingFileAppender<Object>();
59  
60      String pathToBash = EnvUtilForTests.getPathToBash();
61      OutputStream scriptOS;
62  
63      @BeforeEach
64      public void setUp() throws Exception {
65          encoder = new EchoEncoder<Object>();
66          File outputDir = new File(outputDirStr);
67          boolean result = outputDir.mkdirs();
68          if(!result) {
69              System.out.println("Failed to create folder "+outputDirStr);
70          }
71          System.out.println("Output dir [" + outputDirStr + "]");
72  
73          scriptOS = openScript();
74  
75          rfa.setName("rolling");
76          rfa.setEncoder(encoder);
77          rfa.setContext(context);
78          rfa.setFile(outputDirStr + "output.log");
79  
80      }
81  
82      void close(OutputStream os) {
83          if (os != null) {
84              try {
85                  os.close();
86              } catch (IOException e) {
87              }
88          }
89      }
90  
91      @AfterEach
92      public void tearDown() throws Exception {
93          rfa.stop();
94      }
95  
96      public void setUpTimeBasedTriggeringPolicy(RollingFileAppender<Object> rfa) {
97          String datePattern = "yyyy-MM-dd'T'HH_mm_ss_SSS";
98          TimeBasedRollingPolicy<Object> tbrp = new TimeBasedRollingPolicy<>();
99          tbrp.setFileNamePattern(outputDirStr + "test-%d{" + datePattern + "}");
100         tbrp.setContext(context);
101         tbrp.setParent(rfa);
102         tbrp.start();
103 
104         rfa.setRollingPolicy(tbrp);
105         rfa.start();
106     }
107 
108     public void setUpSizeBasedTriggeringPolicy(RollingFileAppender<Object> rfa) {
109         SizeBasedTriggeringPolicy<Object> zbtp = new SizeBasedTriggeringPolicy<>();
110         zbtp.setContext(context);
111         zbtp.setMaxFileSize(FileSize.valueOf("100KB"));
112 
113         zbtp.start();
114         rfa.setTriggeringPolicy(zbtp);
115 
116         FixedWindowRollingPolicy fwrp = new FixedWindowRollingPolicy();
117         fwrp.setContext(context);
118         fwrp.setFileNamePattern(outputDirStr + "test-%i.log");
119         fwrp.setMaxIndex(20);
120         fwrp.setMinIndex(0);
121         fwrp.setParent(rfa);
122         fwrp.start();
123         rfa.setRollingPolicy(fwrp);
124         rfa.start();
125     }
126 
127     RunnableWithCounterAndDone[] buildRunnableArray(boolean withDelay) {
128         RunnableWithCounterAndDone[] runnableArray = new RunnableWithCounterAndDone[NUM_THREADS];
129         for (int i = 0; i < NUM_THREADS; i++) {
130             runnableArray[i] = new RFARunnable(i, rfa, withDelay);
131         }
132         return runnableArray;
133     }
134 
135     OutputStream openScript() throws IOException {
136         return new FileOutputStream(outputDirStr + VERIFY_SH);
137     }
138 
139     @Test
140     public void multiThreadedTimedBased() throws InterruptedException, IOException {
141         setUpTimeBasedTriggeringPolicy(rfa);
142         executeHarness(TOTAL_DURATION, false);
143         printScriptForTimeBased();
144         verify();
145     }
146 
147     int testFileCount() {
148         File outputDir = new File(outputDirStr);
149         FilenameFilter filter = new FilenameFilter() {
150             public boolean accept(File dir, String name) {
151                 if (name.matches("test-\\d{1,2}.log")) {
152                     return true;
153                 }
154                 return false;
155             }
156         };
157         File[] files = outputDir.listFiles(filter);
158         return files.length;
159     }
160 
161     void verify() throws IOException, InterruptedException {
162         close(scriptOS);
163         // no point in this test if we don't have bash
164         if (pathToBash == null) {
165             return;
166         }
167         ProcessBuilder pb = new ProcessBuilder();
168         pb.command(pathToBash, VERIFY_SH);
169         pb.directory(new File(outputDirStr));
170         Process process = pb.start();
171         process.waitFor();
172         int exitCode = process.exitValue();
173 
174         Assertions.assertEquals(SUCCESSFUL_EXIT_CODE, exitCode);
175         System.out.println("External script based verification returned with exit code " + exitCode);
176     }
177 
178     @Test
179     public void multiThreadedSizeBased() throws InterruptedException, IOException {
180         setUpSizeBasedTriggeringPolicy(rfa);
181         // on a fast machine with a fast hard disk, if the tests runs for too
182         // long the MAX_WINDOW_SIZE is reached, resulting in data loss which
183         // we cannot test for.
184         executeHarness(TOTAL_DURATION, true);
185         int numFiles = testFileCount();
186         printScriptForSizeBased(numFiles);
187         verify();
188     }
189 
190     private void printScriptHeader(String type) throws IOException {
191         out("# ====================================================");
192         out("# A script to check the exactness of the output ");
193         out("# produced by " + type + " test");
194         out("# ====================================================");
195         out("# ");
196     }
197 
198     private void printCommonScriptCore() throws IOException {
199         out("");
200         out("for t in $(seq 0 1 " + (NUM_THREADS - 1) + ")");
201         out("do");
202         out("  echo \"Testing results of thread $t\"");
203         out("  grep \"$t \" aggregated | cut -d ' ' -f 2 > ${t}-sample");
204         out("  for j in $(seq 1 1 ${end[$t]}); do echo $j; done > ${t}-witness");
205         out("  diff -q -w ${t}-sample ${t}-witness;");
206         out("  res=$?");
207         out("  if [ $res != \"0\" ]; then");
208         out("    echo \"FAILED for $t\"");
209         out("    exit " + FAILURE_EXIT_CODE);
210         out("  fi");
211         out("done");
212         out("");
213         out("exit " + SUCCESSFUL_EXIT_CODE);
214     }
215 
216     private void printScriptForTimeBased() throws IOException {
217         printScriptHeader("TimeBased");
218         for (int i = 0; i < NUM_THREADS; i++) {
219             out("end[" + i + "]=" + this.runnableArray[i].getCounter());
220         }
221         out("");
222         out("rm aggregated");
223         out("cat test* output.log >> aggregated");
224         printCommonScriptCore();
225 
226     }
227 
228     private void printScriptForSizeBased(int numfiles) throws IOException {
229         printScriptHeader("SizeBased");
230 
231         for (int i = 0; i < NUM_THREADS; i++) {
232             out("end[" + i + "]=" + this.runnableArray[i].getCounter());
233         }
234         out("");
235         out("rm aggregated");
236         out("for i in $(seq " + (numfiles - 1) + " -1 0); do cat test-$i.log >> aggregated; done");
237         out("cat output.log >> aggregated");
238         out("");
239         printCommonScriptCore();
240     }
241 
242     private void out(String msg) throws IOException {
243         scriptOS.write(msg.getBytes());
244         scriptOS.write("\n".getBytes());
245     }
246 
247     private void executeHarness(int duration, boolean withDelay) throws InterruptedException {
248         MultiThreadedHarness multiThreadedHarness = new MultiThreadedHarness(duration);
249         this.runnableArray = buildRunnableArray(withDelay);
250         multiThreadedHarness.execute(runnableArray);
251 
252         StatusChecker checker = new StatusChecker(context.getStatusManager());
253         if (!checker.isErrorFree(0)) {
254             StatusPrinter.print(context);
255             Assertions.fail("errors reported");
256         }
257     }
258 
259     long diff(long start) {
260         return System.currentTimeMillis() - start;
261     }
262 
263     static class RFARunnable extends RunnableWithCounterAndDone {
264         RollingFileAppender<Object> rfa;
265         int id;
266         boolean withInducedDelay;
267 
268         RFARunnable(int id, RollingFileAppender<Object> rfa, boolean withInducedDelay) {
269             this.id = id;
270             this.rfa = rfa;
271             this.withInducedDelay = withInducedDelay;
272         }
273 
274         public void run() {
275             while (!isDone()) {
276                 counter++;
277                 rfa.doAppend(id + " " + counter);
278                 if ((counter % 64 == 0) && withInducedDelay) {
279                     try {
280                         Thread.sleep(10);
281                     } catch (InterruptedException e) {
282                     }
283                 }
284             }
285         }
286     }
287 }