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.turbo;
015
016import ch.qos.logback.classic.ClassicTestConstants;
017import ch.qos.logback.classic.Level;
018import ch.qos.logback.classic.Logger;
019import ch.qos.logback.classic.LoggerContext;
020import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable;
021import ch.qos.logback.classic.joran.JoranConfigurator;
022import ch.qos.logback.classic.spi.TurboFilterList;
023import ch.qos.logback.core.CoreConstants;
024import ch.qos.logback.core.contention.AbstractMultiThreadedHarness;
025import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
026import ch.qos.logback.core.contention.WaitOnExecutionMultiThreadedHarness;
027import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
028import ch.qos.logback.core.joran.spi.JoranException;
029import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
030import ch.qos.logback.core.status.InfoStatus;
031import ch.qos.logback.core.status.Status;
032import ch.qos.logback.core.testUtil.CoreTestConstants;
033import ch.qos.logback.core.testUtil.EnvUtilForTests;
034import ch.qos.logback.core.testUtil.FileTestUtil;
035import ch.qos.logback.core.testUtil.RandomUtil;
036import ch.qos.logback.core.testUtil.StatusChecker;
037import ch.qos.logback.core.util.StatusPrinter;
038import org.junit.*;
039
040import java.io.*;
041import java.net.MalformedURLException;
042import java.util.List;
043import java.util.concurrent.ExecutorService;
044import java.util.concurrent.ThreadPoolExecutor;
045import java.util.concurrent.TimeUnit;
046
047import static org.junit.Assert.*;
048
049@Ignore
050public class ReconfigureOnChangeTest {
051    final static int THREAD_COUNT = 5;
052    final static int LOOP_LEN = 1000 * 1000;
053
054    int diff = RandomUtil.getPositiveInt();
055
056    // the space in the file name mandated by
057    // http://jira.qos.ch/browse/LBCORE-119
058    final static String SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.xml";
059
060    final static String G_SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.groovy";
061
062    final static String SCAN_LOGBACK_474_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan_logback_474.xml";
063
064    final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/topLevel0.xml";
065
066    final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/topByResource.xml";
067
068    final static String INCLUSION_SCAN_INNER0_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/inner0.xml";
069
070    final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
071
072    // it actually takes time for Windows to propagate file modification changes
073    // values below 100 milliseconds can be problematic the same propagation
074    // latency occurs in Linux but is even larger (>600 ms)
075    // final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 60;
076
077    int sleepBetweenUpdates = 100;
078
079    LoggerContext loggerContext = new LoggerContext();
080    Logger logger = loggerContext.getLogger(this.getClass());
081    ExecutorService executorService = loggerContext.getExecutorService();
082
083    StatusChecker checker = new StatusChecker(loggerContext);
084    AbstractMultiThreadedHarness harness;
085
086    ThreadPoolExecutor executor = (ThreadPoolExecutor) loggerContext.getExecutorService();
087
088    int expectedResets = 2;
089
090    @BeforeClass
091    static public void classSetup() {
092        FileTestUtil.makeTestOutputDir();
093    }
094
095    @Before
096    public void setUp() {
097        harness = new WaitOnExecutionMultiThreadedHarness(executor, expectedResets);
098    }
099
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}