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.joran;
15  
16  import static ch.qos.logback.classic.ClassicTestConstants.JORAN_INPUT_PREFIX;
17  import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.DETECTED_CHANGE_IN_CONFIGURATION_FILES;
18  import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.FALLING_BACK_TO_SAFE_CONFIGURATION;
19  import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION;
20  import static ch.qos.logback.core.CoreConstants.RECONFIGURE_ON_CHANGE_TASK;
21  import static org.junit.Assert.assertEquals;
22  import static org.junit.Assert.assertFalse;
23  import static org.junit.Assert.assertNotNull;
24  import static org.junit.Assert.assertNull;
25  import static org.junit.Assert.assertTrue;
26  import static org.junit.Assert.fail;
27  
28  import java.io.ByteArrayInputStream;
29  import java.io.File;
30  import java.io.FileWriter;
31  import java.io.IOException;
32  import java.io.InputStream;
33  import java.util.List;
34  import java.util.concurrent.CountDownLatch;
35  import java.util.concurrent.ExecutionException;
36  import java.util.concurrent.ScheduledFuture;
37  
38  import org.junit.BeforeClass;
39  import org.junit.Test;
40  
41  import ch.qos.logback.classic.Logger;
42  import ch.qos.logback.classic.LoggerContext;
43  import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable;
44  import ch.qos.logback.core.CoreConstants;
45  import ch.qos.logback.core.contention.AbstractMultiThreadedHarness;
46  import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
47  import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
48  import ch.qos.logback.core.joran.spi.JoranException;
49  import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
50  import ch.qos.logback.core.status.InfoStatus;
51  import ch.qos.logback.core.status.Status;
52  import ch.qos.logback.core.testUtil.CoreTestConstants;
53  import ch.qos.logback.core.testUtil.FileTestUtil;
54  import ch.qos.logback.core.testUtil.RandomUtil;
55  import ch.qos.logback.core.testUtil.StatusChecker;
56  import ch.qos.logback.core.util.StatusPrinter;
57  
58  public class ReconfigureOnChangeTaskTest {
59      final static int THREAD_COUNT = 5;
60  
61      int diff = RandomUtil.getPositiveInt();
62  
63      // the space in the file name mandated by
64      // http://jira.qos.ch/browse/LBCORE-119
65      final static String SCAN1_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan 1.xml";
66  
67      final static String G_SCAN1_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan 1.groovy";
68  
69      final static String SCAN_LOGBACK_474_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan_logback_474.xml";
70  
71      final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topLevel0.xml";
72  
73      final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topByResource.xml";
74  
75      final static String INCLUSION_SCAN_INNER0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/inner0.xml";
76  
77      final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
78  
79      private static final String SCAN_PERIOD_DEFAULT_FILE_AS_STR =  JORAN_INPUT_PREFIX + "roct/scan_period_default.xml";
80      
81      LoggerContext loggerContext = new LoggerContext();
82      Logger logger = loggerContext.getLogger(this.getClass());
83      StatusChecker statusChecker = new StatusChecker(loggerContext);
84  
85      @BeforeClass
86      static public void classSetup() {
87          FileTestUtil.makeTestOutputDir();
88      }
89  
90      void configure(File file) throws JoranException {
91          JoranConfigurator jc = new JoranConfigurator();
92          jc.setContext(loggerContext);
93          jc.doConfigure(file);
94      }
95  
96      void configure(InputStream is) throws JoranException {
97          JoranConfigurator jc = new JoranConfigurator();
98          jc.setContext(loggerContext);
99          jc.doConfigure(is);
100     }
101 
102 //    void gConfigure(File file) throws JoranException {
103 //        GafferConfigurator gc = new GafferConfigurator(loggerContext);
104 //        gc.run(file);
105 //    }
106 
107     @Test(timeout = 4000L)
108     public void checkBasicLifecyle() throws JoranException, IOException, InterruptedException {
109         File file = new File(SCAN1_FILE_AS_STR);
110         configure(file);
111         List<File> fileList = getConfigurationWatchList(loggerContext);
112         assertThatListContainsFile(fileList, file);
113         checkThatTaskHasRan();
114         checkThatTaskCanBeStopped();
115     }
116 
117 //    @Test(timeout = 4000L)
118 //    public void checkBasicLifecyleWithGaffer() throws JoranException, IOException, InterruptedException {
119 //        File file = new File(G_SCAN1_FILE_AS_STR);
120 //        gConfigure(file);
121 //        List<File> fileList = getConfigurationWatchList(loggerContext);
122 //        assertThatListContainsFile(fileList, file);
123 //        checkThatTaskHasRan();
124 //        checkThatTaskCanBeStopped();
125 //    }
126 
127     private void checkThatTaskCanBeStopped() {
128         ScheduledFuture<?> future = loggerContext.getScheduledFutures().get(0);
129         loggerContext.stop();
130         assertTrue(future.isCancelled());
131     }
132 
133     private void checkThatTaskHasRan() throws InterruptedException {
134         waitForReconfigureOnChangeTaskToRun();
135     }
136 
137     List<File> getConfigurationWatchList(LoggerContext context) {
138         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(loggerContext);
139         return configurationWatchList.getCopyOfFileWatchList();
140     }
141 
142     @Test(timeout = 4000L)
143     public void scanWithFileInclusion() throws JoranException, IOException, InterruptedException {
144         File topLevelFile = new File(INCLUSION_SCAN_TOPLEVEL0_AS_STR);
145         File innerFile = new File(INCLUSION_SCAN_INNER0_AS_STR);
146         configure(topLevelFile);
147         List<File> fileList = getConfigurationWatchList(loggerContext);
148         assertThatListContainsFile(fileList, topLevelFile);
149         assertThatListContainsFile(fileList, innerFile);
150         checkThatTaskHasRan();
151         checkThatTaskCanBeStopped();
152     }
153 
154     @Test(timeout = 4000L)
155     public void scanWithResourceInclusion() throws JoranException, IOException, InterruptedException {
156         File topLevelFile = new File(INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR);
157         File innerFile = new File(INCLUSION_SCAN_INNER1_AS_STR);
158         configure(topLevelFile);
159         List<File> fileList = getConfigurationWatchList(loggerContext);
160         assertThatListContainsFile(fileList, topLevelFile);
161         assertThatListContainsFile(fileList, innerFile);
162     }
163 
164     // See also http://jira.qos.ch/browse/LOGBACK-338
165     @Test(timeout = 4000L)
166     public void reconfigurationIsNotPossibleInTheAbsenceOfATopFile() throws IOException, JoranException, InterruptedException {
167         String configurationStr = "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include resource=\"asResource/inner1.xml\"/></configuration>";
168         configure(new ByteArrayInputStream(configurationStr.getBytes("UTF-8")));
169 
170         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(loggerContext);
171         assertNull(configurationWatchList);
172         // assertNull(configurationWatchList.getMainURL());
173 
174         statusChecker.containsMatch(Status.WARN, "Due to missing top level");
175         StatusPrinter.print(loggerContext);
176         ReconfigureOnChangeTask roct = getRegisteredReconfigureTask();
177         assertNull(roct);
178         assertEquals(0, loggerContext.getScheduledFutures().size());
179     }
180 
181     @Test(timeout = 3000L)
182     public void fallbackToSafe_FollowedByRecovery() throws IOException, JoranException, InterruptedException {
183         String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml";
184         File topLevelFile = new File(path);
185         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><root level=\"ERROR\"/></configuration> ");
186         configure(topLevelFile);
187         CountDownLatch changeDetectedLatch = waitForReconfigurationToBeDone(null);
188         ReconfigureOnChangeTask oldRoct = getRegisteredReconfigureTask();
189         assertNotNull(oldRoct);
190         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"5 millisecond\">\n" + "  <root></configuration>");
191         changeDetectedLatch.await();
192         statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
193         statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
194 
195         loggerContext.getStatusManager().clear();
196 
197         CountDownLatch secondDoneLatch = waitForReconfigurationToBeDone(oldRoct);
198         writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><root level=\"ERROR\"/></configuration> ");
199         secondDoneLatch.await();
200         StatusPrinter.print(loggerContext);
201         statusChecker.assertIsErrorFree();
202         statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
203     }
204 
205     @Test(timeout = 4000L)
206     public void fallbackToSafeWithIncludedFile_FollowedByRecovery() throws IOException, JoranException, InterruptedException, ExecutionException {
207         String topLevelFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_top-" + diff + ".xml";
208         String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_inner-" + diff + ".xml";
209         File topLevelFile = new File(topLevelFileAsStr);
210         writeToFile(topLevelFile, "<configuration xdebug=\"true\" scan=\"true\" scanPeriod=\"5 millisecond\"><include file=\"" + innerFileAsStr
211                         + "\"/></configuration> ");
212 
213         File innerFile = new File(innerFileAsStr);
214         writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
215         configure(topLevelFile);
216 
217         CountDownLatch doneLatch = waitForReconfigurationToBeDone(null);
218         ReconfigureOnChangeTask oldRoct = getRegisteredReconfigureTask();
219         assertNotNull(oldRoct);
220         
221         writeToFile(innerFile, "<included>\n<root>\n</included>");
222         doneLatch.await();
223 
224         statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
225         statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
226 
227         loggerContext.getStatusManager().clear();
228 
229         CountDownLatch secondDoneLatch = waitForReconfigurationToBeDone(oldRoct);
230         writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
231         secondDoneLatch.await();
232         
233         StatusPrinter.print(loggerContext);
234         statusChecker.assertIsErrorFree();
235         statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
236     }
237 
238     private ReconfigureOnChangeTask getRegisteredReconfigureTask() {
239         return (ReconfigureOnChangeTask) loggerContext.getObject(RECONFIGURE_ON_CHANGE_TASK);
240     }
241 
242     class RunMethodInvokedListener extends ReconfigureOnChangeTaskListener {
243         CountDownLatch countDownLatch;
244 
245         RunMethodInvokedListener(CountDownLatch countDownLatch) {
246             this.countDownLatch = countDownLatch;
247         }
248 
249         @Override
250         public void enteredRunMethod() {
251             countDownLatch.countDown();
252         }
253     };
254 
255     class ChangeDetectedListener extends ReconfigureOnChangeTaskListener {
256         CountDownLatch countDownLatch;
257 
258         ChangeDetectedListener(CountDownLatch countDownLatch) {
259             this.countDownLatch = countDownLatch;
260         }
261 
262         @Override
263         public void changeDetected() {
264             countDownLatch.countDown();
265         }
266     };
267 
268     class ReconfigurationDoneListener extends ReconfigureOnChangeTaskListener {
269         CountDownLatch countDownLatch;
270 
271         ReconfigurationDoneListener(CountDownLatch countDownLatch) {
272             this.countDownLatch = countDownLatch;
273         }
274 
275         @Override
276         public void doneReconfiguring() {
277             countDownLatch.countDown();
278         }
279     };
280 
281     private ReconfigureOnChangeTask waitForReconfigureOnChangeTaskToRun() throws InterruptedException {
282         ReconfigureOnChangeTask roct = null;
283         while (roct == null) {
284             roct = getRegisteredReconfigureTask();
285             Thread.yield();
286         }
287 
288         CountDownLatch countDownLatch = new CountDownLatch(1);
289         roct.addListener(new RunMethodInvokedListener(countDownLatch));
290         countDownLatch.await();
291         return roct;
292     }
293 
294     private CountDownLatch waitForReconfigurationToBeDone(ReconfigureOnChangeTask oldTask) throws InterruptedException {
295         ReconfigureOnChangeTask roct = oldTask;
296         while (roct == oldTask) {
297             roct = getRegisteredReconfigureTask();
298             Thread.yield();
299         }
300 
301         CountDownLatch countDownLatch = new CountDownLatch(1);
302         roct.addListener(new ReconfigurationDoneListener(countDownLatch));
303         return countDownLatch;
304     }
305 
306     private RunnableWithCounterAndDone[] buildRunnableArray(File configFile, UpdateType updateType) {
307         RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT];
308         rArray[0] = new Updater(configFile, updateType);
309         for (int i = 1; i < THREAD_COUNT; i++) {
310             rArray[i] = new LoggingRunnable(logger);
311         }
312         return rArray;
313     }
314 
315     @Test
316     public void checkReconfigureTaskScheduledWhenDefaultScanPeriodUsed() throws JoranException {
317         File file = new File(SCAN_PERIOD_DEFAULT_FILE_AS_STR);
318         configure(file);
319 
320         final List<ScheduledFuture<?>> scheduledFutures = loggerContext.getScheduledFutures();
321         StatusPrinter.print(loggerContext);
322         assertFalse(scheduledFutures.isEmpty());
323         statusChecker.containsMatch("No 'scanPeriod' specified. Defaulting to");
324    
325     }
326 
327     // check for deadlocks
328     @Test(timeout = 4000L)
329     public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedException {
330         loggerContext.setName("scan_LOGBACK_474");
331         File file = new File(SCAN_LOGBACK_474_FILE_AS_STR);
332         // StatusListenerConfigHelper.addOnConsoleListenerInstance(loggerContext, new OnConsoleStatusListener());
333         configure(file);
334 
335         // ReconfigureOnChangeTask roct = waitForReconfigureOnChangeTaskToRun();
336 
337         int expectedResets = 2;
338         Harness harness = new Harness(expectedResets);
339 
340         RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file, UpdateType.TOUCH);
341         harness.execute(runnableArray);
342 
343         loggerContext.getStatusManager().add(new InfoStatus("end of execution ", this));
344         StatusPrinter.print(loggerContext);
345         checkResetCount(expectedResets);
346     }
347 
348     private void assertThatListContainsFile(List<File> fileList, File file) {
349         // conversion to absolute file seems to work nicely
350         assertTrue(fileList.contains(file.getAbsoluteFile()));
351     }
352 
353     private void checkResetCount(int expected) {
354         StatusChecker checker = new StatusChecker(loggerContext);
355         checker.assertIsErrorFree();
356 
357         int effectiveResets = checker.matchCount(CoreConstants.RESET_MSG_PREFIX);
358         assertEquals(expected, effectiveResets);
359 
360         // String failMsg = "effective=" + effectiveResets + ", expected=" + expected;
361         //
362         // there might be more effective resets than the expected amount
363         // since the harness may be sleeping while a reset occurs
364         // assertTrue(failMsg, expected <= effectiveResets && (expected + 2) >= effectiveResets);
365 
366     }
367 
368     void addInfo(String msg, Object o) {
369         loggerContext.getStatusManager().add(new InfoStatus(msg, o));
370     }
371 
372     enum UpdateType {
373         TOUCH, MALFORMED, MALFORMED_INNER
374     }
375 
376     void writeToFile(File file, String contents) throws IOException {
377     	FileWriter fw = new FileWriter(file);
378         fw.write(contents);
379         fw.close();
380         // on linux changes to last modified are not propagated if the
381         // time stamp is near the previous time stamp hence the random delta
382         file.setLastModified(System.currentTimeMillis()+RandomUtil.getPositiveInt());
383     }
384 
385     class Harness extends AbstractMultiThreadedHarness {
386         int changeCountLimit;
387 
388         Harness(int changeCount) {
389             this.changeCountLimit = changeCount;
390         }
391 
392         public void waitUntilEndCondition() throws InterruptedException {
393             ReconfigureOnChangeTaskTest.this.addInfo("Entering " + this.getClass() + ".waitUntilEndCondition()", this);
394 
395             int changeCount = 0;
396             ReconfigureOnChangeTask lastRoct = null;
397             CountDownLatch countDownLatch = null;
398 
399             while (changeCount < changeCountLimit) {
400                 ReconfigureOnChangeTask roct = (ReconfigureOnChangeTask) loggerContext.getObject(RECONFIGURE_ON_CHANGE_TASK);
401                 if (lastRoct != roct && roct != null) {
402                     lastRoct = roct;
403                     countDownLatch = new CountDownLatch(1);
404                     roct.addListener(new ChangeDetectedListener(countDownLatch));
405                 } else if (countDownLatch != null) {
406                     countDownLatch.await();
407                     countDownLatch = null;
408                     changeCount++;
409                 }
410                 Thread.yield();
411             }
412             ReconfigureOnChangeTaskTest.this.addInfo("*****Exiting " + this.getClass() + ".waitUntilEndCondition()", this);
413         }
414 
415     }
416 
417     class Updater extends RunnableWithCounterAndDone {
418         File configFile;
419         UpdateType updateType;
420 
421         // it actually takes time for Windows to propagate file modification changes
422         // values below 100 milliseconds can be problematic the same propagation
423         // latency occurs in Linux but is even larger (>600 ms)
424         // final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 60;
425 
426         int sleepBetweenUpdates = 100;
427 
428         Updater(File configFile, UpdateType updateType) {
429             this.configFile = configFile;
430             this.updateType = updateType;
431         }
432 
433         Updater(File configFile) {
434             this(configFile, UpdateType.TOUCH);
435         }
436 
437         public void run() {
438             while (!isDone()) {
439                 try {
440                     Thread.sleep(sleepBetweenUpdates);
441                 } catch (InterruptedException e) {
442                 }
443                 if (isDone()) {
444                     ReconfigureOnChangeTaskTest.this.addInfo("Exiting Updater.run()", this);
445                     return;
446                 }
447                 counter++;
448                 ReconfigureOnChangeTaskTest.this.addInfo("Touching [" + configFile + "]", this);
449                 switch (updateType) {
450                 case TOUCH:
451                     touchFile();
452                     break;
453                 case MALFORMED:
454                     try {
455                         malformedUpdate();
456                     } catch (IOException e) {
457                         e.printStackTrace();
458                         fail("malformedUpdate failed");
459                     }
460                     break;
461                 case MALFORMED_INNER:
462                     try {
463                         malformedInnerUpdate();
464                     } catch (IOException e) {
465                         e.printStackTrace();
466                         fail("malformedInnerUpdate failed");
467                     }
468                 }
469             }
470             ReconfigureOnChangeTaskTest.this.addInfo("Exiting Updater.run()", this);
471         }
472 
473         private void malformedUpdate() throws IOException {
474             writeToFile(configFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n" + "  <root level=\"ERROR\">\n" + "</configuration>");
475         }
476 
477         private void malformedInnerUpdate() throws IOException {
478             writeToFile(configFile, "<included>\n" + "  <root>\n" + "</included>");
479         }
480 
481         void touchFile() {
482             configFile.setLastModified(System.currentTimeMillis());
483         }
484     }
485 
486 }