Source code

001/**
002 * Logback: the reliable, generic, fast and flexible logging framework.
003 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
004 *
005 * This program and the accompanying materials are dual-licensed under
006 * either the terms of the Eclipse Public License v1.0 as published by
007 * the Eclipse Foundation
008 *
009 *   or (per the licensee's choosing)
010 *
011 * under the terms of the GNU Lesser General Public License version 2.1
012 * as published by the Free Software Foundation.
013 */
014package ch.qos.logback.classic.joran;
015
016import static ch.qos.logback.classic.ClassicTestConstants.JORAN_INPUT_PREFIX;
017import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.DETECTED_CHANGE_IN_CONFIGURATION_FILES;
018import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.FALLING_BACK_TO_SAFE_CONFIGURATION;
019import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION;
020import static ch.qos.logback.core.CoreConstants.RECONFIGURE_ON_CHANGE_TASK;
021import static org.junit.Assert.assertEquals;
022import static org.junit.Assert.assertFalse;
023import static org.junit.Assert.assertNotNull;
024import static org.junit.Assert.assertNull;
025import static org.junit.Assert.assertTrue;
026import static org.junit.Assert.fail;
027
028import java.io.ByteArrayInputStream;
029import java.io.File;
030import java.io.FileWriter;
031import java.io.IOException;
032import java.io.InputStream;
033import java.util.List;
034import java.util.concurrent.CountDownLatch;
035import java.util.concurrent.ExecutionException;
036import java.util.concurrent.ScheduledFuture;
037
038import org.junit.BeforeClass;
039import org.junit.Test;
040
041import ch.qos.logback.classic.Logger;
042import ch.qos.logback.classic.LoggerContext;
043import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable;
044import ch.qos.logback.core.CoreConstants;
045import ch.qos.logback.core.contention.AbstractMultiThreadedHarness;
046import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
047import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
048import ch.qos.logback.core.joran.spi.JoranException;
049import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
050import ch.qos.logback.core.status.InfoStatus;
051import ch.qos.logback.core.status.Status;
052import ch.qos.logback.core.testUtil.CoreTestConstants;
053import ch.qos.logback.core.testUtil.FileTestUtil;
054import ch.qos.logback.core.testUtil.RandomUtil;
055import ch.qos.logback.core.testUtil.StatusChecker;
056import ch.qos.logback.core.util.StatusPrinter;
057
058public class ReconfigureOnChangeTaskTest {
059    final static int THREAD_COUNT = 5;
060
061    int diff = RandomUtil.getPositiveInt();
062
063    // the space in the file name mandated by
064    // http://jira.qos.ch/browse/LBCORE-119
065    final static String SCAN1_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan 1.xml";
066
067    final static String G_SCAN1_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan 1.groovy";
068
069    final static String SCAN_LOGBACK_474_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan_logback_474.xml";
070
071    final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topLevel0.xml";
072
073    final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topByResource.xml";
074
075    final static String INCLUSION_SCAN_INNER0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/inner0.xml";
076
077    final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
078
079    private static final String SCAN_PERIOD_DEFAULT_FILE_AS_STR =  JORAN_INPUT_PREFIX + "roct/scan_period_default.xml";
080    
081    LoggerContext loggerContext = new LoggerContext();
082    Logger logger = loggerContext.getLogger(this.getClass());
083    StatusChecker statusChecker = new StatusChecker(loggerContext);
084
085    @BeforeClass
086    static public void classSetup() {
087        FileTestUtil.makeTestOutputDir();
088    }
089
090    void configure(File file) throws JoranException {
091        JoranConfigurator jc = new JoranConfigurator();
092        jc.setContext(loggerContext);
093        jc.doConfigure(file);
094    }
095
096    void configure(InputStream is) throws JoranException {
097        JoranConfigurator jc = new JoranConfigurator();
098        jc.setContext(loggerContext);
099        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}