1
2
3
4
5
6
7
8
9
10
11
12
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
64
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
103
104
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
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
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
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
360
361 configure(file);
362
363
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
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
389
390
391
392
393
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
410
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
453
454
455
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 }