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.classic.turbo;
15  
16  import ch.qos.logback.classic.ClassicTestConstants;
17  import ch.qos.logback.classic.Level;
18  import ch.qos.logback.classic.Logger;
19  import ch.qos.logback.classic.LoggerContext;
20  import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable;
21  import ch.qos.logback.classic.joran.JoranConfigurator;
22  import ch.qos.logback.classic.spi.TurboFilterList;
23  import ch.qos.logback.core.CoreConstants;
24  import ch.qos.logback.core.contention.AbstractMultiThreadedHarness;
25  import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
26  import ch.qos.logback.core.contention.WaitOnExecutionMultiThreadedHarness;
27  import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
28  import ch.qos.logback.core.joran.spi.JoranException;
29  import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
30  import ch.qos.logback.core.status.InfoStatus;
31  import ch.qos.logback.core.status.Status;
32  import ch.qos.logback.core.testUtil.CoreTestConstants;
33  import ch.qos.logback.core.testUtil.EnvUtilForTests;
34  import ch.qos.logback.core.testUtil.FileTestUtil;
35  import ch.qos.logback.core.testUtil.RandomUtil;
36  import ch.qos.logback.core.testUtil.StatusChecker;
37  import ch.qos.logback.core.util.StatusPrinter;
38  import org.junit.*;
39  
40  import java.io.*;
41  import java.net.MalformedURLException;
42  import java.util.List;
43  import java.util.concurrent.ExecutorService;
44  import java.util.concurrent.ThreadPoolExecutor;
45  import java.util.concurrent.TimeUnit;
46  
47  import static org.junit.Assert.*;
48  
49  @Ignore
50  public class ReconfigureOnChangeTest {
51      final static int THREAD_COUNT = 5;
52      final static int LOOP_LEN = 1000 * 1000;
53  
54      int diff = RandomUtil.getPositiveInt();
55  
56      // the space in the file name mandated by
57      // http://jira.qos.ch/browse/LBCORE-119
58      final static String SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.xml";
59  
60      final static String G_SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.groovy";
61  
62      final static String SCAN_LOGBACK_474_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan_logback_474.xml";
63  
64      final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/topLevel0.xml";
65  
66      final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/topByResource.xml";
67  
68      final static String INCLUSION_SCAN_INNER0_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/inner0.xml";
69  
70      final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
71  
72      // it actually takes time for Windows to propagate file modification changes
73      // values below 100 milliseconds can be problematic the same propagation
74      // latency occurs in Linux but is even larger (>600 ms)
75      // final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 60;
76  
77      int sleepBetweenUpdates = 100;
78  
79      LoggerContext loggerContext = new LoggerContext();
80      Logger logger = loggerContext.getLogger(this.getClass());
81      ExecutorService executorService = loggerContext.getExecutorService();
82  
83      StatusChecker checker = new StatusChecker(loggerContext);
84      AbstractMultiThreadedHarness harness;
85  
86      ThreadPoolExecutor executor = (ThreadPoolExecutor) loggerContext.getExecutorService();
87  
88      int expectedResets = 2;
89  
90      @BeforeClass
91      static public void classSetup() {
92          FileTestUtil.makeTestOutputDir();
93      }
94  
95      @Before
96      public void setUp() {
97          harness = new WaitOnExecutionMultiThreadedHarness(executor, expectedResets);
98      }
99  
100     @After
101     public void tearDown() {
102     }
103 
104     void configure(File file) throws JoranException {
105         JoranConfigurator jc = new JoranConfigurator();
106         jc.setContext(loggerContext);
107         jc.doConfigure(file);
108     }
109 
110     void configure(InputStream is) throws JoranException {
111         JoranConfigurator jc = new JoranConfigurator();
112         jc.setContext(loggerContext);
113         jc.doConfigure(is);
114     }
115 
116 //    void gConfigure(File file) throws JoranException {
117 //        GafferConfigurator gc = new GafferConfigurator(loggerContext);
118 //        gc.run(file);
119 //    }
120 
121     RunnableWithCounterAndDone[] buildRunnableArray(File configFile, UpdateType updateType) {
122         RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT];
123         rArray[0] = new Updater(configFile, updateType);
124         for (int i = 1; i < THREAD_COUNT; i++) {
125             rArray[i] = new LoggingRunnable(logger);
126         }
127         return rArray;
128     }
129 
130     // Tests whether ConfigurationAction is installing ReconfigureOnChangeFilter
131     @Test
132     public void installFilter() throws JoranException, IOException, InterruptedException {
133         File file = new File(SCAN1_FILE_AS_STR);
134         configure(file);
135         List<File> fileList = getConfigurationFileList(loggerContext);
136         assertThatListContainsFile(fileList, file);
137         assertThatFirstFilterIsROCF();
138         StatusPrinter.print(loggerContext);
139     }
140 
141 //    @Test
142 //    public void gafferInstallFilter() throws JoranException, IOException, InterruptedException {
143 //        File file = new File(G_SCAN1_FILE_AS_STR);
144 //        gConfigure(file);
145 //        List<File> fileList = getConfigurationFileList(loggerContext);
146 //        assertThatListContainsFile(fileList, file);
147 //        assertThatFirstFilterIsROCF();
148 //
149 //        rocfDetachReconfigurationToNewThreadAndAwaitTermination();
150 //
151 //        fileList = getConfigurationFileList(loggerContext);
152 //        assertThatListContainsFile(fileList, file);
153 //        assertThatFirstFilterIsROCF();
154 //
155 //        // check that rcof filter installed on two occasions
156 //        assertEquals(2, checker.matchCount("Will scan for changes in"));
157 //    }
158 
159     private void rocfDetachReconfigurationToNewThreadAndAwaitTermination() throws InterruptedException {
160         ReconfigureOnChangeFilter reconfigureOnChangeFilter = (ReconfigureOnChangeFilter) getFirstTurboFilter();
161         reconfigureOnChangeFilter.detachReconfigurationToNewThread();
162         executorService.shutdown();
163         executorService.awaitTermination(1000, TimeUnit.MILLISECONDS);
164     }
165 
166     List<File> getConfigurationFileList(LoggerContext context) {
167         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(loggerContext);
168         return configurationWatchList.getCopyOfFileWatchList();
169     }
170 
171     @Test(timeout = 4000L)
172     public void scanWithFileInclusion() throws JoranException, IOException, InterruptedException {
173         File topLevelFile = new File(INCLUSION_SCAN_TOPLEVEL0_AS_STR);
174         File innerFile = new File(INCLUSION_SCAN_INNER0_AS_STR);
175         configure(topLevelFile);
176         List<File> fileList = getConfigurationFileList(loggerContext);
177         assertThatListContainsFile(fileList, topLevelFile);
178         assertThatListContainsFile(fileList, innerFile);
179     }
180 
181     @Test(timeout = 4000L)
182     public void scanWithResourceInclusion() throws JoranException, IOException, InterruptedException {
183         File topLevelFile = new File(INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR);
184         File innerFile = new File(INCLUSION_SCAN_INNER1_AS_STR);
185         configure(topLevelFile);
186 
187         List<File> fileList = getConfigurationFileList(loggerContext);
188         assertThatListContainsFile(fileList, topLevelFile);
189         assertThatListContainsFile(fileList, innerFile);
190     }
191 
192     // See also http://jira.qos.ch/browse/LOGBACK-338
193     @Test
194     public void includeScanViaInputStreamSuppliedConfigFile() throws IOException, JoranException, InterruptedException {
195         String configurationStr = "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include resource=\"asResource/inner1.xml\"/></configuration>";
196         configure(new ByteArrayInputStream(configurationStr.getBytes("UTF-8")));
197 
198         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(loggerContext);
199         assertNull(configurationWatchList.getMainURL());
200 
201         ReconfigureOnChangeFilter reconfigureOnChangeFilter = (ReconfigureOnChangeFilter) getFirstTurboFilter();
202         // without a top level file, reconfigureOnChangeFilter should not start
203         assertFalse(reconfigureOnChangeFilter.isStarted());
204     }
205 
206     @Test(timeout = 4000L)
207     public void fallbackToSafe() throws IOException, JoranException, InterruptedException {
208         String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml";
209         File topLevelFile = new File(path);
210         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><root level=\"ERROR\"/></configuration> ");
211         configure(topLevelFile);
212 
213         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n" + "  <root></configuration>");
214 
215         rocfDetachReconfigurationToNewThreadAndAwaitTermination();
216 
217         checker.assertContainsMatch(Status.WARN, "Falling back to previously registered safe configuration.");
218         checker.assertContainsMatch(Status.INFO, "Re-registering previous fallback configuration once more");
219 
220         assertThatFirstFilterIsROCF();
221     }
222 
223     @Test(timeout = 4000L)
224     public void fallbackToSafeWithIncludedFile() throws IOException, JoranException, InterruptedException {
225         String topLevelFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_top-" + diff + ".xml";
226         String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_inner-" + diff + ".xml";
227         File topLevelFile = new File(topLevelFileAsStr);
228         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include file=\"" + innerFileAsStr + "\"/></configuration> ");
229 
230         File innerFile = new File(innerFileAsStr);
231         writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
232         configure(topLevelFile);
233         writeToFile(innerFile, "<included>\n<root>\n</included>");
234         rocfDetachReconfigurationToNewThreadAndAwaitTermination();
235 
236         checker.assertContainsMatch(Status.WARN, "Falling back to previously registered safe configuration.");
237         checker.assertContainsMatch(Status.INFO, "Re-registering previous fallback configuration once more");
238 
239         assertThatFirstFilterIsROCF();
240     }
241 
242     // check for deadlocks
243     @Test(timeout = 4000L)
244     public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedException {
245         File file = new File(SCAN_LOGBACK_474_FILE_AS_STR);
246         configure(file);
247 
248         RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file, UpdateType.TOUCH);
249         harness.execute(runnableArray);
250 
251         loggerContext.getStatusManager().add(new InfoStatus("end of execution ", this));
252 
253         verify(expectedResets);
254     }
255 
256     private void assertThatListContainsFile(List<File> fileList, File file) {
257         // conversion to absolute file seems to work nicely
258         assertTrue(fileList.contains(file.getAbsoluteFile()));
259     }
260 
261     private TurboFilter getFirstTurboFilter() {
262         TurboFilterList turboFilterList = loggerContext.getTurboFilterList();
263         return turboFilterList.get(0);
264     }
265 
266     private void assertThatFirstFilterIsROCF() {
267         assertTrue(getFirstTurboFilter() instanceof ReconfigureOnChangeFilter);
268     }
269 
270     private void verify(int expected) {
271         StatusChecker checker = new StatusChecker(loggerContext);
272         // StatusPrinter.print(loggerContext);
273         checker.assertIsErrorFree();
274 
275         int effectiveResets = checker.matchCount(CoreConstants.RESET_MSG_PREFIX);
276 
277         String failMsg = "effective=" + effectiveResets + ", expected=" + expected;
278 
279         // there might be more effective resets than the expected amount
280         // since the harness may be sleeping while a reset occurs
281         assertTrue(failMsg, expected <= effectiveResets && (expected + 2) >= effectiveResets);
282 
283     }
284 
285     ReconfigureOnChangeFilter initROCF() throws MalformedURLException {
286         ReconfigureOnChangeFilter rocf = new ReconfigureOnChangeFilter();
287         rocf.setContext(loggerContext);
288         File file = new File(SCAN1_FILE_AS_STR);
289         ConfigurationWatchListUtil.setMainWatchURL(loggerContext, file.toURI().toURL());
290         rocf.start();
291         return rocf;
292     }
293 
294     @Test
295     @Ignore
296     public void directPerfTest() throws MalformedURLException {
297         if (EnvUtilForTests.isLinux()) {
298             // for some reason this test does not pass on Linux (AMD 64 bit,
299             // Dual Core Opteron 170)
300             return;
301         }
302 
303         ReconfigureOnChangeFilter rocf = initROCF();
304         assertTrue(rocf.isStarted());
305 
306         for (int i = 0; i < 30; i++) {
307             directLoop(rocf);
308         }
309         double avg = directLoop(rocf);
310         System.out.println("directPerfTest: " + avg);
311     }
312 
313     public double directLoop(ReconfigureOnChangeFilter rocf) {
314         long start = System.nanoTime();
315         for (int i = 0; i < LOOP_LEN; i++) {
316             rocf.decide(null, logger, Level.DEBUG, " ", null, null);
317         }
318         long end = System.nanoTime();
319         return (end - start) / (1.0d * LOOP_LEN);
320     }
321 
322     @Ignore
323     @Test
324     public void indirectPerfTest() throws MalformedURLException {
325         if (EnvUtilForTests.isLinux()) {
326             // for some reason this test does not pass on Linux (AMD 64 bit,
327             // Dual Core
328             // Opteron 170)
329             return;
330         }
331 
332         ReconfigureOnChangeFilter rocf = initROCF();
333         assertTrue(rocf.isStarted());
334         loggerContext.addTurboFilter(rocf);
335         logger.setLevel(Level.ERROR);
336 
337         indirectLoop();
338         double avg = indirectLoop();
339         System.out.println(avg);
340         // the reference was computed on Orion (Ceki's computer)
341         @SuppressWarnings("unused")
342         long referencePerf = 68;
343         //BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS);
344     }
345 
346     void addInfo(String msg, Object o) {
347         loggerContext.getStatusManager().add(new InfoStatus(msg, o));
348     }
349 
350     public double indirectLoop() {
351         long start = System.nanoTime();
352         for (int i = 0; i < LOOP_LEN; i++) {
353             logger.debug("hello");
354         }
355         long end = System.nanoTime();
356         return (end - start) / (1.0d * LOOP_LEN);
357     }
358 
359     enum UpdateType {
360         TOUCH, MALFORMED, MALFORMED_INNER
361     }
362 
363     void writeToFile(File file, String contents) throws IOException {
364         FileWriter fw = new FileWriter(file);
365         fw.write(contents);
366         fw.close();
367     }
368 
369     class Updater extends RunnableWithCounterAndDone {
370         File configFile;
371         UpdateType updateType;
372 
373         Updater(File configFile, UpdateType updateType) {
374             this.configFile = configFile;
375             this.updateType = updateType;
376         }
377 
378         Updater(File configFile) {
379             this(configFile, UpdateType.TOUCH);
380         }
381 
382         public void run() {
383             while (!isDone()) {
384                 try {
385                     Thread.sleep(sleepBetweenUpdates);
386                 } catch (InterruptedException e) {
387                 }
388                 if (isDone()) {
389                     return;
390                 }
391                 counter++;
392                 ReconfigureOnChangeTest.this.addInfo("***settting last modified", this);
393                 switch (updateType) {
394                 case TOUCH:
395                     touchFile();
396                     break;
397                 case MALFORMED:
398                     try {
399                         malformedUpdate();
400                     } catch (IOException e) {
401                         e.printStackTrace();
402                         fail("malformedUpdate failed");
403                     }
404                     break;
405                 case MALFORMED_INNER:
406                     try {
407                         malformedInnerUpdate();
408                     } catch (IOException e) {
409                         e.printStackTrace();
410                         fail("malformedInnerUpdate failed");
411                     }
412                 }
413             }
414         }
415 
416         private void malformedUpdate() throws IOException {
417             writeToFile(configFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n" + "  <root level=\"ERROR\">\n" + "</configuration>");
418         }
419 
420         private void malformedInnerUpdate() throws IOException {
421             writeToFile(configFile, "<included>\n" + "  <root>\n" + "</included>");
422         }
423 
424         void touchFile() {
425             configFile.setLastModified(System.currentTimeMillis());
426         }
427     }
428 
429 }