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     private void checkThatTaskCanBeStopped() {
118         ScheduledFuture<?> future = loggerContext.getCopyOfScheduledFutures().get(0);
119         loggerContext.stop();
120         assertTrue(future.isCancelled());
121     }
122 
123     private void checkThatTaskHasRan() throws InterruptedException {
124         waitForReconfigureOnChangeTaskToRun();
125     }
126 
127     List<File> getConfigurationWatchList(LoggerContext context) {
128         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil
129                 .getConfigurationWatchList(loggerContext);
130         return configurationWatchList.getCopyOfFileWatchList();
131     }
132 
133     @Test(timeout = 4000L)
134     public void scanWithFileInclusion() throws JoranException, IOException, InterruptedException {
135         File topLevelFile = new File(INCLUSION_SCAN_TOPLEVEL0_AS_STR);
136         File innerFile = new File(INCLUSION_SCAN_INNER0_AS_STR);
137         configure(topLevelFile);
138         List<File> fileList = getConfigurationWatchList(loggerContext);
139         assertThatListContainsFile(fileList, topLevelFile);
140         assertThatListContainsFile(fileList, innerFile);
141         checkThatTaskHasRan();
142         checkThatTaskCanBeStopped();
143     }
144 
145     @Test(timeout = 4000L)
146     public void scanWithResourceInclusion() throws JoranException, IOException, InterruptedException {
147         File topLevelFile = new File(INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR);
148         File innerFile = new File(INCLUSION_SCAN_INNER1_AS_STR);
149         configure(topLevelFile);
150         List<File> fileList = getConfigurationWatchList(loggerContext);
151         assertThatListContainsFile(fileList, topLevelFile);
152         assertThatListContainsFile(fileList, innerFile);
153     }
154 
155     // See also http://jira.qos.ch/browse/LOGBACK-338
156     @Test(timeout = 4000L)
157     public void reconfigurationIsNotPossibleInTheAbsenceOfATopFile()
158             throws IOException, JoranException, InterruptedException {
159         String configurationStr = "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include resource=\"asResource/inner1.xml\"/></configuration>";
160         configure(new ByteArrayInputStream(configurationStr.getBytes("UTF-8")));
161 
162         ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil
163                 .getConfigurationWatchList(loggerContext);
164         assertNull(configurationWatchList);
165         // assertNull(configurationWatchList.getMainURL());
166 
167         statusChecker.containsMatch(Status.WARN, "Due to missing top level");
168         StatusPrinter.print(loggerContext);
169         ReconfigureOnChangeTask roct = getRegisteredReconfigureTask();
170         assertNull(roct);
171         assertEquals(0, loggerContext.getCopyOfScheduledFutures().size());
172     }
173 
174     @Test(timeout = 3000L)
175     public void fallbackToSafe_FollowedByRecovery() throws IOException, JoranException, InterruptedException {
176         String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml";
177         File topLevelFile = new File(path);
178         writeToFile(topLevelFile,
179                 "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><root level=\"ERROR\"/></configuration> ");
180         configure(topLevelFile);
181         StatusPrinter.print(loggerContext);
182         CountDownLatch changeDetectedLatch = waitForReconfigurationToBeDone(null);
183         ReconfigureOnChangeTask oldRoct = getRegisteredReconfigureTask();
184 
185         addInfo("registered ReconfigureOnChangeTask ", oldRoct);
186         assertNotNull(oldRoct);
187 
188         String badXML = "<configuration scan=\"true\" scanPeriod=\"5 millisecond\">\n" + "  <root></configuration>";
189         writeToFile(topLevelFile, badXML);
190         addInfo("Waiting for changeDetectedLatch.await()", this);
191         changeDetectedLatch.await();
192         addInfo("Woke from changeDetectedLatch.await()", this);
193         StatusPrinter.print(loggerContext);
194         
195         try {
196             statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
197             statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
198 
199             loggerContext.getStatusManager().clear();
200 
201             addInfo("after loggerContext.getStatusManager().clear() oldRoct="+ oldRoct, this);
202             CountDownLatch secondDoneLatch = waitForReconfigurationToBeDone(oldRoct);
203             writeToFile(topLevelFile,
204                     "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><root level=\"ERROR\"/></configuration> ");
205 
206             secondDoneLatch.await();
207             StatusPrinter.print(loggerContext);
208             statusChecker.assertIsErrorFree();
209             statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
210 
211         } finally {
212             StatusPrinter.print(loggerContext);
213         }
214     }
215 
216     @Test(timeout = 4000L)
217     public void fallbackToSafeWithIncludedFile_FollowedByRecovery()
218             throws IOException, JoranException, InterruptedException, ExecutionException {
219         String topLevelFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_top-" + diff
220                 + ".xml";
221         String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_inner-" + diff
222                 + ".xml";
223         File topLevelFile = new File(topLevelFileAsStr);
224         writeToFile(topLevelFile,
225                 "<configuration xdebug=\"true\" scan=\"true\" scanPeriod=\"5 millisecond\"><include file=\""
226                         + innerFileAsStr + "\"/></configuration> ");
227 
228         File innerFile = new File(innerFileAsStr);
229         writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
230         configure(topLevelFile);
231 
232         CountDownLatch doneLatch = waitForReconfigurationToBeDone(null);
233         ReconfigureOnChangeTask oldRoct = getRegisteredReconfigureTask();
234         assertNotNull(oldRoct);
235 
236         writeToFile(innerFile, "<included>\n<root>\n</included>");
237         doneLatch.await();
238 
239         statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
240         statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
241 
242         loggerContext.getStatusManager().clear();
243 
244         try {
245             CountDownLatch secondDoneLatch = waitForReconfigurationToBeDone(oldRoct);
246             writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
247             secondDoneLatch.await();
248 
249             statusChecker.assertIsErrorFree();
250             statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
251         } finally {
252             StatusPrinter.print(loggerContext);
253         }
254 
255     }
256 
257     private ReconfigureOnChangeTask getRegisteredReconfigureTask() {
258         return (ReconfigureOnChangeTask) loggerContext.getObject(RECONFIGURE_ON_CHANGE_TASK);
259     }
260 
261     class RunMethodInvokedListener extends ReconfigureOnChangeTaskListener {
262         CountDownLatch countDownLatch;
263 
264         RunMethodInvokedListener(CountDownLatch countDownLatch) {
265             this.countDownLatch = countDownLatch;
266         }
267 
268         @Override
269         public void enteredRunMethod() {
270             countDownLatch.countDown();
271         }
272     };
273 
274     class ChangeDetectedListener extends ReconfigureOnChangeTaskListener {
275         CountDownLatch countDownLatch;
276 
277         ChangeDetectedListener(CountDownLatch countDownLatch) {
278             this.countDownLatch = countDownLatch;
279         }
280 
281         @Override
282         public void changeDetected() {
283             countDownLatch.countDown();
284         }
285     };
286 
287     class ReconfigurationDoneListener extends ReconfigureOnChangeTaskListener {
288         CountDownLatch countDownLatch;
289 
290         ReconfigurationDoneListener(CountDownLatch countDownLatch) {
291             this.countDownLatch = countDownLatch;
292         }
293 
294         @Override
295         public void doneReconfiguring() {
296             System.out.println("ReconfigurationDoneListener now invoking countDownLatch.countDown()");
297             countDownLatch.countDown();
298         }
299     };
300 
301     private ReconfigureOnChangeTask waitForReconfigureOnChangeTaskToRun() throws InterruptedException {
302         ReconfigureOnChangeTask roct = null;
303         while (roct == null) {
304             roct = getRegisteredReconfigureTask();
305             Thread.yield();
306         }
307 
308         CountDownLatch countDownLatch = new CountDownLatch(1);
309         roct.addListener(new RunMethodInvokedListener(countDownLatch));
310         countDownLatch.await();
311         return roct;
312     }
313 
314     private CountDownLatch waitForReconfigurationToBeDone(ReconfigureOnChangeTask oldTask) throws InterruptedException {
315 
316         addInfo("waitForReconfigurationToBeDone oldTask=" + oldTask, this);
317         ReconfigureOnChangeTask roct = oldTask;
318         while (roct == oldTask) {
319             roct = getRegisteredReconfigureTask();
320             Thread.yield();
321             Thread.sleep(10);
322         }
323 
324         CountDownLatch countDownLatch = new CountDownLatch(1);
325         if (roct == null) {
326             addInfo("roct is null", oldTask);
327         } else {
328             roct.addListener(new ReconfigurationDoneListener(countDownLatch));
329         }
330         return countDownLatch;
331     }
332 
333     private RunnableWithCounterAndDone[] buildRunnableArray(File configFile, UpdateType updateType) {
334         RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT];
335         rArray[0] = new Updater(configFile, updateType);
336         for (int i = 1; i < THREAD_COUNT; i++) {
337             rArray[i] = new LoggingRunnable(logger);
338         }
339         return rArray;
340     }
341 
342     @Test
343     public void checkReconfigureTaskScheduledWhenDefaultScanPeriodUsed() throws JoranException {
344         File file = new File(SCAN_PERIOD_DEFAULT_FILE_AS_STR);
345         configure(file);
346 
347         final List<ScheduledFuture<?>> scheduledFutures = loggerContext.getCopyOfScheduledFutures();
348         StatusPrinter.print(loggerContext);
349         assertFalse(scheduledFutures.isEmpty());
350         statusChecker.containsMatch("No 'scanPeriod' specified. Defaulting to");
351 
352     }
353 
354     // check for deadlocks
355     @Test(timeout = 4000L)
356     public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedException {
357         loggerContext.setName("scan_LOGBACK_474");
358         File file = new File(SCAN_LOGBACK_474_FILE_AS_STR);
359         // StatusListenerConfigHelper.addOnConsoleListenerInstance(loggerContext, new
360         // OnConsoleStatusListener());
361         configure(file);
362 
363         // ReconfigureOnChangeTask roct = waitForReconfigureOnChangeTaskToRun();
364 
365         int expectedResets = 2;
366         Harness harness = new Harness(expectedResets);
367 
368         RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file, UpdateType.TOUCH);
369         harness.execute(runnableArray);
370 
371         loggerContext.getStatusManager().add(new InfoStatus("end of execution ", this));
372         StatusPrinter.print(loggerContext);
373         checkResetCount(expectedResets);
374     }
375 
376     private void assertThatListContainsFile(List<File> fileList, File file) {
377         // conversion to absolute file seems to work nicely
378         assertTrue(fileList.contains(file.getAbsoluteFile()));
379     }
380 
381     private void checkResetCount(int expected) {
382         StatusChecker checker = new StatusChecker(loggerContext);
383         checker.assertIsErrorFree();
384 
385         int effectiveResets = checker.matchCount(CoreConstants.RESET_MSG_PREFIX);
386         assertEquals(expected, effectiveResets);
387 
388         // String failMsg = "effective=" + effectiveResets + ", expected=" + expected;
389         //
390         // there might be more effective resets than the expected amount
391         // since the harness may be sleeping while a reset occurs
392         // assertTrue(failMsg, expected <= effectiveResets && (expected + 2) >=
393         // effectiveResets);
394 
395     }
396 
397     void addInfo(String msg, Object o) {
398         loggerContext.getStatusManager().add(new InfoStatus(msg, o));
399     }
400 
401     enum UpdateType {
402         TOUCH, MALFORMED, MALFORMED_INNER
403     }
404 
405     void writeToFile(File file, String contents) throws IOException {
406         FileWriter fw = new FileWriter(file);
407         fw.write(contents);
408         fw.close();
409         // on linux changes to last modified are not propagated if the
410         // time stamp is near the previous time stamp hence the random delta
411         file.setLastModified(System.currentTimeMillis() + RandomUtil.getPositiveInt());
412     }
413 
414     class Harness extends AbstractMultiThreadedHarness {
415         int changeCountLimit;
416 
417         Harness(int changeCount) {
418             this.changeCountLimit = changeCount;
419         }
420 
421         public void waitUntilEndCondition() throws InterruptedException {
422             ReconfigureOnChangeTaskTest.this.addInfo("Entering " + this.getClass() + ".waitUntilEndCondition()", this);
423 
424             int changeCount = 0;
425             ReconfigureOnChangeTask lastRoct = null;
426             CountDownLatch countDownLatch = null;
427 
428             while (changeCount < changeCountLimit) {
429                 ReconfigureOnChangeTask roct = (ReconfigureOnChangeTask) loggerContext
430                         .getObject(RECONFIGURE_ON_CHANGE_TASK);
431                 if (lastRoct != roct && roct != null) {
432                     lastRoct = roct;
433                     countDownLatch = new CountDownLatch(1);
434                     roct.addListener(new ChangeDetectedListener(countDownLatch));
435                 } else if (countDownLatch != null) {
436                     countDownLatch.await();
437                     countDownLatch = null;
438                     changeCount++;
439                 }
440                 Thread.yield();
441             }
442             ReconfigureOnChangeTaskTest.this.addInfo("*****Exiting " + this.getClass() + ".waitUntilEndCondition()",
443                     this);
444         }
445 
446     }
447 
448     class Updater extends RunnableWithCounterAndDone {
449         File configFile;
450         UpdateType updateType;
451 
452         // it actually takes time for Windows to propagate file modification changes
453         // values below 100 milliseconds can be problematic the same propagation
454         // latency occurs in Linux but is even larger (>600 ms)
455         // final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 60;
456 
457         int sleepBetweenUpdates = 100;
458 
459         Updater(File configFile, UpdateType updateType) {
460             this.configFile = configFile;
461             this.updateType = updateType;
462         }
463 
464         Updater(File configFile) {
465             this(configFile, UpdateType.TOUCH);
466         }
467 
468         public void run() {
469             while (!isDone()) {
470                 try {
471                     Thread.sleep(sleepBetweenUpdates);
472                 } catch (InterruptedException e) {
473                 }
474                 if (isDone()) {
475                     ReconfigureOnChangeTaskTest.this.addInfo("Exiting Updater.run()", this);
476                     return;
477                 }
478                 counter++;
479                 ReconfigureOnChangeTaskTest.this.addInfo("Touching [" + configFile + "]", this);
480                 switch (updateType) {
481                 case TOUCH:
482                     touchFile();
483                     break;
484                 case MALFORMED:
485                     try {
486                         malformedUpdate();
487                     } catch (IOException e) {
488                         e.printStackTrace();
489                         fail("malformedUpdate failed");
490                     }
491                     break;
492                 case MALFORMED_INNER:
493                     try {
494                         malformedInnerUpdate();
495                     } catch (IOException e) {
496                         e.printStackTrace();
497                         fail("malformedInnerUpdate failed");
498                     }
499                 }
500             }
501             ReconfigureOnChangeTaskTest.this.addInfo("Exiting Updater.run()", this);
502         }
503 
504         private void malformedUpdate() throws IOException {
505             writeToFile(configFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n"
506                     + "  <root level=\"ERROR\">\n" + "</configuration>");
507         }
508 
509         private void malformedInnerUpdate() throws IOException {
510             writeToFile(configFile, "<included>\n" + "  <root>\n" + "</included>");
511         }
512 
513         void touchFile() {
514             configFile.setLastModified(System.currentTimeMillis());
515         }
516     }
517 
518 }