1
2
3
4
5
6
7
8
9
10
11
12
13
14 package ch.qos.logback.classic.blackbox.joran;
15
16 import ch.qos.logback.classic.Level;
17 import ch.qos.logback.classic.Logger;
18 import ch.qos.logback.classic.LoggerContext;
19 import ch.qos.logback.classic.blackbox.issue.lbclassic135.LoggingRunnable;
20 import ch.qos.logback.classic.joran.*;
21 import ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull;
22 import ch.qos.logback.core.CoreConstants;
23 import ch.qos.logback.core.testUtil.RunnableWithCounterAndDone;
24 import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
25 import ch.qos.logback.core.joran.spi.JoranException;
26 import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
27 import ch.qos.logback.core.spi.ConfigurationEvent;
28 import ch.qos.logback.core.spi.ConfigurationEventListener;
29 import ch.qos.logback.core.status.InfoStatus;
30 import ch.qos.logback.core.status.OnConsoleStatusListener;
31 import ch.qos.logback.core.status.Status;
32 import ch.qos.logback.core.status.WarnStatus;
33 import ch.qos.logback.core.testUtil.CoreTestConstants;
34 import ch.qos.logback.core.testUtil.FileTestUtil;
35 import ch.qos.logback.core.testUtil.RandomUtil;
36 import ch.qos.logback.core.util.Loader;
37 import ch.qos.logback.core.util.StatusPrinter2;
38 import org.junit.jupiter.api.*;
39
40 import java.io.*;
41 import java.net.URL;
42 import java.util.List;
43 import java.util.concurrent.CountDownLatch;
44 import java.util.concurrent.ExecutionException;
45 import java.util.concurrent.ScheduledFuture;
46 import java.util.concurrent.TimeUnit;
47
48 import static ch.qos.logback.classic.blackbox.BlackboxClassicTestConstants.JORAN_INPUT_PREFIX;
49 import static ch.qos.logback.classic.joran.ReconfigureOnChangeTask.*;
50 import static org.junit.jupiter.api.Assertions.*;
51
52 public class ReconfigureOnChangeTaskTest extends ReconfigureTaskTestSupport {
53 final static int THREAD_COUNT = 5;
54
55 final static int TIMEOUT = 4;
56 final static int TIMEOUT_LONG = 10;
57
58 enum ConfigurationDoneType {
59 PARTIAL,
60 FULL
61 }
62
63 @FunctionalInterface
64 interface ThrowingRunnable {
65 void run() throws Exception;
66 }
67
68 void awaitChangeAndConfiguration(ConfigurationDoneType type, ThrowingRunnable trigger) throws Exception {
69 CountDownLatch changeDetected = registerChangeDetectedListener();
70 CountDownLatch configurationDone;
71 if (type == ConfigurationDoneType.PARTIAL) {
72 configurationDone = registerPartialConfigurationEndedSuccessfullyEventListener();
73 } else {
74 configurationDone = registerNewReconfigurationDoneSuccessfullyListener();
75 }
76
77 trigger.run();
78
79 changeDetected.await();
80 configurationDone.await();
81 }
82
83
84
85 final static String SCAN1_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan 1.xml";
86
87 final static String SCAN_LOGBACK_474_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan_logback_474.xml";
88
89 final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topLevel0.xml";
90
91 final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/topByResource.xml";
92
93 final static String INCLUSION_SCAN_INNER0_AS_STR = JORAN_INPUT_PREFIX + "roct/inclusion/inner0.xml";
94
95 final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
96
97 private static final String SCAN_PERIOD_DEFAULT_FILE_AS_STR = JORAN_INPUT_PREFIX + "roct/scan_period_default.xml";
98
99 private static final String TOP_FILE_WITH_INCLUSION = "misc/topWithFileInclusion.xml";
100
101 Logger logger = loggerContext.getLogger(this.getClass());
102 StatusChecker statusChecker = new StatusChecker(loggerContext);
103 StatusPrinter2 statusPrinter2 = new StatusPrinter2();
104
105
106 @BeforeAll
107 static public void classSetup() {
108 FileTestUtil.makeTestOutputDir();
109 }
110
111 @BeforeEach
112 public void before() {
113 loggerContext.setName("ROCTTest-context" + diff);
114 }
115
116 void configure(File file) throws JoranException {
117 JoranConfigurator jc = new JoranConfigurator();
118 jc.setContext(loggerContext);
119 jc.doConfigure(file);
120 }
121
122 void configureAsResource(String filename) throws JoranException {
123 URL url = Loader.getResource(filename, this.getClass().getClassLoader());
124 assertNotNull(url);
125 JoranConfigurator jc = new JoranConfigurator();
126 jc.setContext(loggerContext);
127 jc.doConfigure(url);
128 }
129
130 @Test
131 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
132 public void checkBasicLifecyle() throws JoranException, IOException, InterruptedException {
133 File file = new File(SCAN1_FILE_AS_STR);
134 configure(file);
135 List<File> fileList = getConfigurationWatchList(loggerContext);
136 assertThatListContainsFile(fileList, file);
137 checkThatTaskHasRan();
138 checkThatTaskCanBeStopped();
139 }
140
141 private void checkThatTaskCanBeStopped() {
142 ScheduledFuture<?> future = loggerContext.getCopyOfScheduledFutures().get(0);
143 loggerContext.stop();
144 assertTrue(future.isCancelled());
145 }
146
147 private void checkThatTaskHasRan() throws InterruptedException {
148 waitForReconfigureOnChangeTaskToRun();
149 }
150
151 List<File> getConfigurationWatchList(LoggerContext lc) {
152 ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(lc);
153 return configurationWatchList.getCopyOfFileWatchList();
154 }
155
156 @Test
157 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
158 public void scanWithFileInclusion() throws JoranException, IOException, InterruptedException {
159 File topLevelFile = new File(INCLUSION_SCAN_TOPLEVEL0_AS_STR);
160 File innerFile = new File(INCLUSION_SCAN_INNER0_AS_STR);
161 configure(topLevelFile);
162 List<File> fileList = getConfigurationWatchList(loggerContext);
163 assertThatListContainsFile(fileList, topLevelFile);
164 assertThatListContainsFile(fileList, innerFile);
165 checkThatTaskHasRan();
166 checkThatTaskCanBeStopped();
167 }
168
169
170 @Test
171 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
172 public void scanWithResourceInclusion() throws JoranException, IOException, InterruptedException {
173 File topLevelFile = new File(INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR);
174 File innerFile = new File(INCLUSION_SCAN_INNER1_AS_STR);
175 configure(topLevelFile);
176 List<File> fileList = getConfigurationWatchList(loggerContext);
177 assertThatListContainsFile(fileList, topLevelFile);
178 assertThatListContainsFile(fileList, innerFile);
179 }
180
181 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
182 @Test
183 public void propertiesConfigurationTest() throws Exception {
184 String loggerName = "abc";
185 String propertiesFileStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "roct-" + diff + ".properties";
186 File propertiesFile = new File(propertiesFileStr);
187 String configurationStr = "<configuration debug=\"true\" scan=\"true\" scanPeriod=\"10 millisecond\"><propertiesConfigurator file=\"" + propertiesFileStr + "\"/></configuration>";
188 writeToFile(propertiesFile, PropertiesConfigurator.LOGBACK_LOGGER_PREFIX + loggerName + "=INFO");
189 configure(asBAIS(configurationStr));
190 Logger abcLogger = loggerContext.getLogger(loggerName);
191 assertEquals(Level.INFO, abcLogger.getLevel());
192
193 awaitChangeAndConfiguration(ConfigurationDoneType.PARTIAL, () ->
194 writeToFile(propertiesFile, PropertiesConfigurator.LOGBACK_LOGGER_PREFIX + loggerName + "=WARN")
195 );
196 assertEquals(Level.WARN, abcLogger.getLevel());
197
198 awaitChangeAndConfiguration(ConfigurationDoneType.PARTIAL, () ->
199 writeToFile(propertiesFile, PropertiesConfigurator.LOGBACK_LOGGER_PREFIX + loggerName + "=ERROR")
200 );
201 assertEquals(Level.ERROR, abcLogger.getLevel());
202
203 }
204
205 @Disabled
206 @Test
207 void propertiesFromHTTPS() throws InterruptedException, UnsupportedEncodingException, JoranException {
208 String loggerName = "com.bazinga";
209 String propertiesURLStr = "https://www.qos.ch/foo.properties";
210 Logger aLogger = loggerContext.getLogger(loggerName);
211 String configurationStr = "<configuration debug=\"true\" scan=\"true\" scanPeriod=\"10 millisecond\"><propertiesConfigurator url=\"" + propertiesURLStr + "\"/></configuration>";
212
213 configure(asBAIS(configurationStr));
214 assertEquals(Level.WARN, aLogger.getLevel());
215 System.out.println("first phase OK");
216 CountDownLatch changeDetectedLatch0 = registerChangeDetectedListener();
217 CountDownLatch configurationDoneLatch0 = registerPartialConfigurationEndedSuccessfullyEventListener();
218
219 changeDetectedLatch0.await();
220 System.out.println("after changeDetectedLatch0.await();");
221 configurationDoneLatch0.await();
222 assertEquals(Level.ERROR, aLogger.getLevel());
223 }
224
225
226 @Test
227 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
228 public void reconfigurationIsNotPossibleInTheAbsenceOfATopFile() throws IOException, JoranException, InterruptedException {
229
230 ReconfigurationTaskRegisteredConfigEventListener listener = new ReconfigurationTaskRegisteredConfigEventListener();
231 loggerContext.addConfigurationEventListener(listener);
232 String configurationStr = "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include resource=\"asResource/inner1.xml\"/></configuration>";
233 configure(asBAIS(configurationStr));
234
235 ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil.getConfigurationWatchList(loggerContext);
236
237 assertNotNull(configurationWatchList);
238 assertFalse(ConfigurationWatchListUtil.watchPredicateFulfilled(loggerContext));
239 statusChecker.containsMatch(Status.WARN, ConfigurationModelHandlerFull.FAILED_WATCH_PREDICATE_MESSAGE_1);
240
241 assertFalse(listener.changeDetectorRegisteredEventOccurred);
242 assertEquals(0, loggerContext.getCopyOfScheduledFutures().size());
243 }
244
245 @Test
246 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
247 public void fallbackToSafe_FollowedByRecovery() throws Exception {
248 addInfo("Start fallbackToSafe_FollowedByRecovery", this);
249 String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml";
250 File topLevelFile = new File(path);
251 writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"25 millisecond\"><root level=\"ERROR\"/></configuration> ");
252
253 addResetResistantOnConsoleStatusListener();
254 configure(topLevelFile);
255
256 awaitChangeAndConfiguration(ConfigurationDoneType.FULL, () ->
257 writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"5 millisecond\">\n <root></configuration>")
258 );
259 addInfo("Woke from configurationDoneLatch.await()", this);
260
261 statusChecker.assertContainsMatch(Status.ERROR, CoreConstants.XML_PARSING);
262 statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
263 statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
264
265 statusPrinter2.print(loggerContext);
266
267 loggerContext.getStatusManager().clear();
268
269 awaitChangeAndConfiguration(ConfigurationDoneType.FULL, () ->
270 writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><root level=\"ERROR\"/></configuration> ")
271 );
272
273 statusChecker.assertIsErrorFree();
274 statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
275 }
276
277 private void addResetResistantOnConsoleStatusListener() {
278
279 if (1 == 1)
280 return;
281 OnConsoleStatusListener ocs = new OnConsoleStatusListener();
282 ocs.setContext(loggerContext);
283 ocs.setResetResistant(true);
284 ocs.start();
285 loggerContext.getStatusManager().add(ocs);
286 }
287
288 @Test
289 @Timeout(value = 2, unit = TimeUnit.SECONDS)
290 public void scanWithIncludedFileCreatedLater() throws Exception {
291
292 try {
293 ReconfigurationTaskRegisteredConfigEventListener roctRegisteredListener = new ReconfigurationTaskRegisteredConfigEventListener();
294 loggerContext.addConfigurationEventListener(roctRegisteredListener);
295 addResetResistantOnConsoleStatusListener();
296 String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "scanWithIncludedFileCreatedLater-" + diff + ".xml";
297 System.setProperty("fileCreatedLater", innerFileAsStr);
298 configureAsResource(TOP_FILE_WITH_INCLUSION);
299
300 if(isSurefire()) {
301 statusChecker.assertContainsMatch("URL \\[.*\\] is not of type file");
302 }
303
304 File innerFile = new File(innerFileAsStr);
305
306 List<File> fileList = getConfigurationWatchList(loggerContext);
307 assertThatListContainsFile(fileList, innerFile);
308
309 awaitChangeAndConfiguration(ConfigurationDoneType.FULL, () ->
310 writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ")
311 );
312
313
314 Logger root = loggerContext.getLogger(Logger.ROOT_LOGGER_NAME);
315 assertEquals(Level.ERROR, root.getLevel());
316
317
318 } finally {
319 System.getProperties().remove("fileCreatedLater");
320 }
321 }
322
323
324 @Test
325 @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS)
326 public void scanWithIncludedPropertiesFileCreatedLater() throws Exception {
327 try {
328 ReconfigurationTaskRegisteredConfigEventListener roctRegisteredListener = new ReconfigurationTaskRegisteredConfigEventListener();
329 loggerContext.addConfigurationEventListener(roctRegisteredListener);
330 addResetResistantOnConsoleStatusListener();
331 String propertiesFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "scanWithIncludedPropertiesFileCreatedLater-" + diff + ".properties";
332 System.setProperty("propertiesFileCreatedLater", propertiesFileAsStr);
333 String configurationStr = "<configuration scan=\"true\" scanPeriod=\"5 millisecond\"><propertiesConfigurator file=\"${propertiesFileCreatedLater}\"/></configuration>";
334 configure(asBAIS(configurationStr));
335
336 File propertiesFile = new File(propertiesFileAsStr);
337
338 List<File> fileList = getConfigurationWatchList(loggerContext);
339 assertThatListContainsFile(fileList, propertiesFile);
340
341 awaitChangeAndConfiguration(ConfigurationDoneType.PARTIAL, () ->
342 writeToFile(propertiesFile, "logback.logger.com.test=INFO")
343 );
344
345
346 Logger testLogger = loggerContext.getLogger("com.test");
347 assertEquals(Level.INFO, testLogger.getLevel());
348
349
350 loggerContext.getStatusManager().clear();
351
352 awaitChangeAndConfiguration(ConfigurationDoneType.PARTIAL, () ->
353 writeToFile(propertiesFile, "logback.logger.com.test=WARN")
354 );
355
356 assertEquals(Level.WARN, testLogger.getLevel());
357
358 } finally {
359 System.getProperties().remove("propertiesFileCreatedLater");
360 }
361 }
362
363 @Test
364 @Timeout(value = TIMEOUT_LONG, unit = TimeUnit.SECONDS)
365 public void fallbackToSafeWithIncludedFile_FollowedByRecovery() throws Exception {
366 String topLevelFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_top-" + diff + ".xml";
367 String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_inner-" + diff + ".xml";
368 File topLevelFile = new File(topLevelFileAsStr);
369 writeToFile(topLevelFile,
370 "<configuration xdebug=\"true\" scan=\"true\" scanPeriod=\"5 millisecond\"><include file=\"" + innerFileAsStr + "\"/></configuration> ");
371
372 File innerFile = new File(innerFileAsStr);
373 writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
374 addResetResistantOnConsoleStatusListener();
375
376 configure(topLevelFile);
377
378 awaitChangeAndConfiguration(ConfigurationDoneType.FULL, () ->
379 writeToFile(innerFile, "<included>\n<root>\n</included>")
380 );
381 addInfo("Woke from configurationDoneLatch.await()", this);
382
383 statusChecker.assertContainsMatch(Status.ERROR, CoreConstants.XML_PARSING);
384 statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION);
385 statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION);
386
387 statusPrinter2.print(loggerContext);
388
389 loggerContext.getStatusManager().clear();
390
391 awaitChangeAndConfiguration(ConfigurationDoneType.FULL, () ->
392 writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ")
393 );
394
395 statusChecker.assertIsErrorFree();
396 statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES);
397
398 }
399
400 CountDownLatch registerNewReconfigurationDoneSuccessfullyListener() {
401 CountDownLatch latch = new CountDownLatch(1);
402 ReconfigurationDoneListener reconfigurationDoneListener = new ReconfigurationDoneListener(latch);
403 loggerContext.addConfigurationEventListener(reconfigurationDoneListener);
404 return latch;
405 }
406
407 boolean isSurefire() {
408 if(System.getProperty("surefire.test.class.path") != null) {
409 return true;
410 }
411 if(System.getProperty("surefire.real.class.path") != null) {
412 return true;
413 }
414 return false;
415 }
416
417 static class RunMethodInvokedListener implements ConfigurationEventListener {
418 CountDownLatch countDownLatch;
419 ReconfigureOnChangeTask reconfigureOnChangeTask;
420
421 RunMethodInvokedListener(CountDownLatch countDownLatch) {
422 this.countDownLatch = countDownLatch;
423 }
424
425 @Override
426 public void listen(ConfigurationEvent configurationEvent) {
427 if (configurationEvent.getEventType() == ConfigurationEvent.EventType.CHANGE_DETECTOR_RUNNING) {
428 countDownLatch.countDown();
429 Object data = configurationEvent.getData();
430 if (data instanceof ReconfigureOnChangeTask) {
431 reconfigureOnChangeTask = (ReconfigureOnChangeTask) data;
432 }
433 }
434 }
435 }
436
437 private ReconfigureOnChangeTask waitForReconfigureOnChangeTaskToRun() throws InterruptedException {
438 addInfo("entering waitForReconfigureOnChangeTaskToRun", this);
439
440 CountDownLatch countDownLatch = new CountDownLatch(1);
441 RunMethodInvokedListener runMethodInvokedListener = new RunMethodInvokedListener(countDownLatch);
442
443 loggerContext.addConfigurationEventListener(runMethodInvokedListener);
444 countDownLatch.await();
445 return runMethodInvokedListener.reconfigureOnChangeTask;
446 }
447
448 private RunnableWithCounterAndDone[] buildRunnableArray(File configFile, UpdateType updateType) {
449 RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT];
450 rArray[0] = new UpdaterRunnable(this, configFile, updateType);
451 for (int i = 1; i < THREAD_COUNT; i++) {
452 rArray[i] = new LoggingRunnable(logger);
453 }
454 return rArray;
455 }
456
457 @Test
458 public void checkReconfigureTaskScheduledWhenDefaultScanPeriodUsed() throws JoranException {
459 File file = new File(SCAN_PERIOD_DEFAULT_FILE_AS_STR);
460 configure(file);
461
462 final List<ScheduledFuture<?>> scheduledFutures = loggerContext.getCopyOfScheduledFutures();
463
464 assertFalse(scheduledFutures.isEmpty());
465 statusChecker.containsMatch("No 'scanPeriod' specified. Defaulting to");
466
467 }
468
469
470 @Test
471 @Timeout(value = 4, unit = TimeUnit.SECONDS)
472 public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedException {
473 File file = new File(SCAN_LOGBACK_474_FILE_AS_STR);
474 addResetResistantOnConsoleStatusListener();
475 configure(file);
476
477 int expectedResets = 2;
478 ReconfigureOnChangeTaskHarness harness = new ReconfigureOnChangeTaskHarness(loggerContext, expectedResets);
479
480 RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file, UpdateType.TOUCH);
481 harness.execute(runnableArray);
482
483 addInfo("scan_LOGBACK_474 end of execution ", this);
484 checkResetCount(expectedResets);
485 }
486
487 private void assertThatListContainsFile(List<File> fileList, File file) {
488
489 assertTrue(fileList.contains(file.getAbsoluteFile()));
490 }
491
492 private void checkResetCount(int expected) {
493 StatusChecker checker = new StatusChecker(loggerContext);
494 checker.assertIsErrorFree();
495
496 int effectiveResets = checker.matchCount(CoreConstants.RESET_MSG_PREFIX);
497 assertEquals(expected, effectiveResets);
498
499
500
501
502
503
504
505
506 }
507
508 void addInfo(String msg, Object o) {
509 loggerContext.getStatusManager().add(new InfoStatus(msg, o));
510 }
511
512 void addWarn(String msg, Object o) {
513 loggerContext.getStatusManager().add(new WarnStatus(msg, o));
514 }
515
516 enum UpdateType {
517 TOUCH, MALFORMED, MALFORMED_INNER
518 }
519
520 void writeToFile(File file, String contents) throws IOException {
521 FileWriter fw = new FileWriter(file);
522 fw.write(contents);
523 fw.close();
524
525
526 boolean success = file.setLastModified(System.currentTimeMillis() + RandomUtil.getPositiveInt());
527 if (!success) {
528 addWarn("failed to setLastModified on file " + file, this);
529 }
530 }
531
532 }