1
2
3
4
5
6
7
8
9
10
11
12
13
14 package ch.qos.logback.classic.turbo;
15
16 import ch.qos.logback.classic.ClassicTestConstants;
17 import ch.qos.logback.classic.Level;
18 import ch.qos.logback.classic.Logger;
19 import ch.qos.logback.classic.LoggerContext;
20 import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable;
21 import ch.qos.logback.classic.joran.JoranConfigurator;
22 import ch.qos.logback.classic.spi.TurboFilterList;
23 import ch.qos.logback.core.CoreConstants;
24 import ch.qos.logback.core.contention.AbstractMultiThreadedHarness;
25 import ch.qos.logback.core.contention.RunnableWithCounterAndDone;
26 import ch.qos.logback.core.contention.WaitOnExecutionMultiThreadedHarness;
27 import ch.qos.logback.core.joran.spi.ConfigurationWatchList;
28 import ch.qos.logback.core.joran.spi.JoranException;
29 import ch.qos.logback.core.joran.util.ConfigurationWatchListUtil;
30 import ch.qos.logback.core.status.InfoStatus;
31 import ch.qos.logback.core.status.Status;
32 import ch.qos.logback.core.testUtil.CoreTestConstants;
33 import ch.qos.logback.core.testUtil.EnvUtilForTests;
34 import ch.qos.logback.core.testUtil.FileTestUtil;
35 import ch.qos.logback.core.testUtil.RandomUtil;
36 import ch.qos.logback.core.status.testUtil.StatusChecker;
37 import ch.qos.logback.core.util.StatusPrinter;
38 import org.junit.jupiter.api.AfterEach;
39 import org.junit.jupiter.api.BeforeAll;
40 import org.junit.jupiter.api.BeforeEach;
41 import org.junit.jupiter.api.Disabled;
42 import org.junit.jupiter.api.Test;
43 import org.junit.jupiter.api.Timeout;
44
45 import java.io.ByteArrayInputStream;
46 import java.io.File;
47 import java.io.FileWriter;
48 import java.io.IOException;
49 import java.io.InputStream;
50 import java.net.MalformedURLException;
51 import java.util.List;
52 import java.util.concurrent.ExecutorService;
53 import java.util.concurrent.ThreadPoolExecutor;
54 import java.util.concurrent.TimeUnit;
55
56 import static org.junit.jupiter.api.Assertions.assertFalse;
57 import static org.junit.jupiter.api.Assertions.assertNull;
58 import static org.junit.jupiter.api.Assertions.assertTrue;
59 import static org.junit.jupiter.api.Assertions.fail;
60 @Disabled
61 public class ReconfigureOnChangeTest {
62 final static int THREAD_COUNT = 5;
63 final static int LOOP_LEN = 1000 * 1000;
64
65 int diff = RandomUtil.getPositiveInt();
66
67
68
69 final static String SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.xml";
70
71 final static String G_SCAN1_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan 1.groovy";
72
73 final static String SCAN_LOGBACK_474_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/scan_logback_474.xml";
74
75 final static String INCLUSION_SCAN_TOPLEVEL0_AS_STR = ClassicTestConstants.INPUT_PREFIX
76 + "turbo/inclusion/topLevel0.xml";
77
78 final static String INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR = ClassicTestConstants.INPUT_PREFIX
79 + "turbo/inclusion/topByResource.xml";
80
81 final static String INCLUSION_SCAN_INNER0_AS_STR = ClassicTestConstants.INPUT_PREFIX + "turbo/inclusion/inner0.xml";
82
83 final static String INCLUSION_SCAN_INNER1_AS_STR = "target/test-classes/asResource/inner1.xml";
84
85
86
87
88
89
90 int sleepBetweenUpdates = 100;
91
92 LoggerContext loggerContext = new LoggerContext();
93 Logger logger = loggerContext.getLogger(this.getClass());
94 ExecutorService executorService = loggerContext.getScheduledExecutorService();
95
96 StatusChecker checker = new StatusChecker(loggerContext);
97 AbstractMultiThreadedHarness harness;
98
99 ThreadPoolExecutor executor = (ThreadPoolExecutor) loggerContext.getScheduledExecutorService();
100
101 int expectedResets = 2;
102
103 @BeforeAll
104 static public void classSetup() {
105 FileTestUtil.makeTestOutputDir();
106 }
107
108 @BeforeEach
109 public void setUp() {
110 harness = new WaitOnExecutionMultiThreadedHarness(executor, expectedResets);
111 }
112
113 @AfterEach
114 public void tearDown() {
115 }
116
117 void configure(File file) throws JoranException {
118 JoranConfigurator jc = new JoranConfigurator();
119 jc.setContext(loggerContext);
120 jc.doConfigure(file);
121 }
122
123 void configure(InputStream is) throws JoranException {
124 JoranConfigurator jc = new JoranConfigurator();
125 jc.setContext(loggerContext);
126 jc.doConfigure(is);
127 }
128
129
130
131
132
133
134 RunnableWithCounterAndDone[] buildRunnableArray(File configFile, UpdateType updateType) {
135 RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT];
136 rArray[0] = new Updater(configFile, updateType);
137 for (int i = 1; i < THREAD_COUNT; i++) {
138 rArray[i] = new LoggingRunnable(logger);
139 }
140 return rArray;
141 }
142
143
144 @Test
145 public void installFilter() throws JoranException, IOException, InterruptedException {
146 File file = new File(SCAN1_FILE_AS_STR);
147 configure(file);
148 List<File> fileList = getConfigurationFileList(loggerContext);
149 assertThatListContainsFile(fileList, file);
150 assertThatFirstFilterIsROCF();
151 StatusPrinter.print(loggerContext);
152 }
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172 private void rocfDetachReconfigurationToNewThreadAndAwaitTermination() throws InterruptedException {
173 ReconfigureOnChangeFilter reconfigureOnChangeFilter = (ReconfigureOnChangeFilter) getFirstTurboFilter();
174 reconfigureOnChangeFilter.detachReconfigurationToNewThread();
175 executorService.shutdown();
176 executorService.awaitTermination(1000, TimeUnit.MILLISECONDS);
177 }
178
179 List<File> getConfigurationFileList(LoggerContext context) {
180 ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil
181 .getConfigurationWatchList(loggerContext);
182 return configurationWatchList.getCopyOfFileWatchList();
183 }
184
185 @Test
186 @Timeout(value = 4)
187 public void scanWithFileInclusion() throws JoranException, IOException, InterruptedException {
188 File topLevelFile = new File(INCLUSION_SCAN_TOPLEVEL0_AS_STR);
189 File innerFile = new File(INCLUSION_SCAN_INNER0_AS_STR);
190 configure(topLevelFile);
191 List<File> fileList = getConfigurationFileList(loggerContext);
192 assertThatListContainsFile(fileList, topLevelFile);
193 assertThatListContainsFile(fileList, innerFile);
194 }
195
196 @Test
197 @Timeout(value = 4, unit= TimeUnit.SECONDS)
198 public void scanWithResourceInclusion() throws JoranException, IOException, InterruptedException {
199 File topLevelFile = new File(INCLUSION_SCAN_TOP_BY_RESOURCE_AS_STR);
200 File innerFile = new File(INCLUSION_SCAN_INNER1_AS_STR);
201 configure(topLevelFile);
202
203 List<File> fileList = getConfigurationFileList(loggerContext);
204 assertThatListContainsFile(fileList, topLevelFile);
205 assertThatListContainsFile(fileList, innerFile);
206 }
207
208
209 @Test
210 public void includeScanViaInputStreamSuppliedConfigFile() throws IOException, JoranException, InterruptedException {
211 String configurationStr = "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include resource=\"asResource/inner1.xml\"/></configuration>";
212 configure(new ByteArrayInputStream(configurationStr.getBytes("UTF-8")));
213
214 ConfigurationWatchList configurationWatchList = ConfigurationWatchListUtil
215 .getConfigurationWatchList(loggerContext);
216 assertNull(configurationWatchList.getMainURL());
217
218 ReconfigureOnChangeFilter reconfigureOnChangeFilter = (ReconfigureOnChangeFilter) getFirstTurboFilter();
219
220 assertFalse(reconfigureOnChangeFilter.isStarted());
221 }
222
223 @Test
224 @Timeout(value = 4, unit= TimeUnit.SECONDS)
225 public void fallbackToSafe() throws IOException, JoranException, InterruptedException {
226 String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml";
227 File topLevelFile = new File(path);
228 writeToFile(topLevelFile,
229 "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><root level=\"ERROR\"/></configuration> ");
230 configure(topLevelFile);
231
232 writeToFile(topLevelFile,
233 "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n" + " <root></configuration>");
234
235 rocfDetachReconfigurationToNewThreadAndAwaitTermination();
236
237 checker.assertContainsMatch(Status.WARN, "Falling back to previously registered safe configuration.");
238 checker.assertContainsMatch(Status.INFO, "Re-registering previous fallback configuration once more");
239
240 assertThatFirstFilterIsROCF();
241 }
242
243 @Test
244 @Timeout(value = 4)
245 public void fallbackToSafeWithIncludedFile() throws IOException, JoranException, InterruptedException {
246 String topLevelFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_top-" + diff
247 + ".xml";
248 String innerFileAsStr = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_inner-" + diff
249 + ".xml";
250 File topLevelFile = new File(topLevelFileAsStr);
251 writeToFile(topLevelFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\"><include file=\""
252 + innerFileAsStr + "\"/></configuration> ");
253
254 File innerFile = new File(innerFileAsStr);
255 writeToFile(innerFile, "<included><root level=\"ERROR\"/></included> ");
256 configure(topLevelFile);
257 writeToFile(innerFile, "<included>\n<root>\n</included>");
258 rocfDetachReconfigurationToNewThreadAndAwaitTermination();
259
260 checker.assertContainsMatch(Status.WARN, "Falling back to previously registered safe configuration.");
261 checker.assertContainsMatch(Status.INFO, "Re-registering previous fallback configuration once more");
262
263 assertThatFirstFilterIsROCF();
264 }
265
266
267 @Test
268 @Timeout(value = 4)
269 public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedException {
270 File file = new File(SCAN_LOGBACK_474_FILE_AS_STR);
271 configure(file);
272
273 RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file, UpdateType.TOUCH);
274 harness.execute(runnableArray);
275
276 loggerContext.getStatusManager().add(new InfoStatus("end of execution ", this));
277
278 verify(expectedResets);
279 }
280
281 private void assertThatListContainsFile(List<File> fileList, File file) {
282
283 assertTrue(fileList.contains(file.getAbsoluteFile()));
284 }
285
286 private TurboFilter getFirstTurboFilter() {
287 TurboFilterList turboFilterList = loggerContext.getTurboFilterList();
288 return turboFilterList.get(0);
289 }
290
291 private void assertThatFirstFilterIsROCF() {
292 assertTrue(getFirstTurboFilter() instanceof ReconfigureOnChangeFilter);
293 }
294
295 private void verify(int expected) {
296 StatusChecker checker = new StatusChecker(loggerContext);
297
298 checker.assertIsErrorFree();
299
300 int effectiveResets = checker.matchCount(CoreConstants.RESET_MSG_PREFIX);
301
302 String failMsg = "effective=" + effectiveResets + ", expected=" + expected;
303
304
305
306 assertTrue(expected <= effectiveResets && (expected + 2) >= effectiveResets, failMsg);
307
308 }
309
310 ReconfigureOnChangeFilter initROCF() throws MalformedURLException {
311 ReconfigureOnChangeFilter rocf = new ReconfigureOnChangeFilter();
312 rocf.setContext(loggerContext);
313 File file = new File(SCAN1_FILE_AS_STR);
314 ConfigurationWatchListUtil.setMainWatchURL(loggerContext, file.toURI().toURL());
315 rocf.start();
316 return rocf;
317 }
318
319 @Test
320 @Disabled
321 public void directPerfTest() throws MalformedURLException {
322 if (EnvUtilForTests.isLinux()) {
323
324
325 return;
326 }
327
328 ReconfigureOnChangeFilter rocf = initROCF();
329 assertTrue(rocf.isStarted());
330
331 for (int i = 0; i < 30; i++) {
332 directLoop(rocf);
333 }
334 double avg = directLoop(rocf);
335 System.out.println("directPerfTest: " + avg);
336 }
337
338 public double directLoop(ReconfigureOnChangeFilter rocf) {
339 long start = System.nanoTime();
340 for (int i = 0; i < LOOP_LEN; i++) {
341 rocf.decide(null, logger, Level.DEBUG, " ", null, null);
342 }
343 long end = System.nanoTime();
344 return (end - start) / (1.0d * LOOP_LEN);
345 }
346
347 @Disabled
348 @Test
349 public void indirectPerfTest() throws MalformedURLException {
350 if (EnvUtilForTests.isLinux()) {
351
352
353
354 return;
355 }
356
357 ReconfigureOnChangeFilter rocf = initROCF();
358 assertTrue(rocf.isStarted());
359 loggerContext.addTurboFilter(rocf);
360 logger.setLevel(Level.ERROR);
361
362 indirectLoop();
363 double avg = indirectLoop();
364 System.out.println(avg);
365
366 @SuppressWarnings("unused")
367 long referencePerf = 68;
368
369 }
370
371 void addInfo(String msg, Object o) {
372 loggerContext.getStatusManager().add(new InfoStatus(msg, o));
373 }
374
375 public double indirectLoop() {
376 long start = System.nanoTime();
377 for (int i = 0; i < LOOP_LEN; i++) {
378 logger.debug("hello");
379 }
380 long end = System.nanoTime();
381 return (end - start) / (1.0d * LOOP_LEN);
382 }
383
384 enum UpdateType {
385 TOUCH, MALFORMED, MALFORMED_INNER
386 }
387
388 void writeToFile(File file, String contents) throws IOException {
389 FileWriter fw = new FileWriter(file);
390 fw.write(contents);
391 fw.close();
392 }
393
394 class Updater extends RunnableWithCounterAndDone {
395 File configFile;
396 UpdateType updateType;
397
398 Updater(File configFile, UpdateType updateType) {
399 this.configFile = configFile;
400 this.updateType = updateType;
401 }
402
403 Updater(File configFile) {
404 this(configFile, UpdateType.TOUCH);
405 }
406
407 public void run() {
408 while (!isDone()) {
409 try {
410 Thread.sleep(sleepBetweenUpdates);
411 } catch (InterruptedException e) {
412 }
413 if (isDone()) {
414 return;
415 }
416 counter++;
417 ReconfigureOnChangeTest.this.addInfo("***settting last modified", this);
418 switch (updateType) {
419 case TOUCH:
420 touchFile();
421 break;
422 case MALFORMED:
423 try {
424 malformedUpdate();
425 } catch (IOException e) {
426 e.printStackTrace();
427 fail("malformedUpdate failed");
428 }
429 break;
430 case MALFORMED_INNER:
431 try {
432 malformedInnerUpdate();
433 } catch (IOException e) {
434 e.printStackTrace();
435 fail("malformedInnerUpdate failed");
436 }
437 }
438 }
439 }
440
441 private void malformedUpdate() throws IOException {
442 writeToFile(configFile, "<configuration scan=\"true\" scanPeriod=\"50 millisecond\">\n"
443 + " <root level=\"ERROR\">\n" + "</configuration>");
444 }
445
446 private void malformedInnerUpdate() throws IOException {
447 writeToFile(configFile, "<included>\n" + " <root>\n" + "</included>");
448 }
449
450 void touchFile() {
451 configFile.setLastModified(System.currentTimeMillis());
452 }
453 }
454
455 }