View Javadoc
1   /*
2    * Copyright 2018 SPF4J.
3    *
4    * Licensed under the Apache License, Version 2.0 (the "License");
5    * you may not use this file except in compliance with the License.
6    * You may obtain a copy of the License at
7    *
8    *      http://www.apache.org/licenses/LICENSE-2.0
9    *
10   * Unless required by applicable law or agreed to in writing, software
11   * distributed under the License is distributed on an "AS IS" BASIS,
12   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13   * See the License for the specific language governing permissions and
14   * limitations under the License.
15   */
16  package org.spf4j.test.log;
17  
18  import com.google.common.annotations.Beta;
19  import com.google.common.collect.ImmutableList;
20  import com.google.common.collect.ImmutableSortedSet;
21  import com.google.common.collect.Maps;
22  import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
23  import java.util.ArrayDeque;
24  import java.util.Collections;
25  import java.util.List;
26  import java.util.Map;
27  import java.util.SortedSet;
28  import java.util.concurrent.ConcurrentHashMap;
29  import java.util.concurrent.ConcurrentMap;
30  import java.util.concurrent.TimeUnit;
31  import java.util.function.Predicate;
32  import java.util.function.ToIntFunction;
33  import java.util.logging.LogManager;
34  import java.util.stream.Collector;
35  import java.util.stream.Collectors;
36  import javax.annotation.CheckReturnValue;
37  import javax.annotation.Nullable;
38  import javax.annotation.concurrent.GuardedBy;
39  import org.hamcrest.Matcher;
40  import org.hamcrest.MatcherAssert;
41  import org.slf4j.ILoggerFactory;
42  import org.slf4j.Logger;
43  import org.slf4j.LoggerFactory;
44  import org.spf4j.base.Env;
45  import org.spf4j.log.SLF4JBridgeHandler;
46  import org.spf4j.base.ExecutionContext;
47  import org.spf4j.base.ExecutionContexts;
48  import org.spf4j.base.XCollectors;
49  import org.spf4j.log.Level;
50  import org.spf4j.test.log.junit4.Spf4jTestLogRunListenerSingleton;
51  //CHECKSTYLE:OFF
52  import sun.misc.Contended;
53  //CHECKSTYLE:ON
54  
55  /**
56   * @author Zoltan Farkas
57   */
58  @SuppressFBWarnings("SIC_INNER_SHOULD_BE_STATIC_ANON")
59  public final class TestLoggers implements ILoggerFactory {
60  
61    public static final boolean EXECUTED_FROM_IDE = TestUtils.isExecutedFromIDE();
62  
63    private final ConcurrentMap<String, Logger> loggerMap;
64  
65    private final Object sync;
66  
67    private final java.util.logging.Logger julGlobal;
68  
69    private final java.util.logging.Logger julRoot;
70  
71    private final SortedSet<String> expectingErrorsIn;
72  
73    private static class Lazy {
74      private static final TestLoggers INSTANCE = new TestLoggers();
75    }
76  
77    @GuardedBy("sync")
78    @Contended
79    private volatile LogConfig config;
80  
81    public static TestLoggers sys() {
82      return Lazy.INSTANCE;
83    }
84  
85    @SuppressWarnings("checkstyle:regexp")
86    private TestLoggers() {
87      sync = new Object();
88      loggerMap = new ConcurrentHashMap<String, Logger>();
89      Level rootPrintLevel = EXECUTED_FROM_IDE
90              ? Level.valueOf(
91                      Env.getSystemProperty("spf4j.test.log.rootPrintLevelIDE",
92                              new String[] {"spf4j.testLog.rootPrintLevelIDE"}, "DEBUG"))
93              : Level.valueOf(
94                      Env.getSystemProperty("spf4j.test.log.rootPrintLevel",
95                               new String[] {"spf4j.testLog.rootPrintLevel"}, "INFO"));
96      final Map<String, List<LogHandler>> catHandlers;
97      Map<String, PrintConfig> loadConfig = null;
98      if (EXECUTED_FROM_IDE) {
99        loadConfig = PrintLogConfigsIO.loadConfigFromResource("spf4j-test-prtcfg-ide.properties");
100     }
101     if (loadConfig == null) {
102       loadConfig = PrintLogConfigsIO.loadConfigFromResource("spf4j-test-prtcfg.properties");
103     }
104     if (loadConfig != null) {
105         catHandlers = Maps.newHashMapWithExpectedSize(loadConfig.size());
106         for (PrintConfig pl : loadConfig.values()) {
107           if (pl.getCategory().isEmpty()) {
108             rootPrintLevel = pl.getMinLevel();
109           } else {
110             LogHandler logPrinter;
111             if (pl.isGreedy()) {
112               logPrinter = new GreedyLogPrinter(new LogPrinter(pl.getMinLevel()));
113             } else {
114               logPrinter = new LogPrinter(pl.getMinLevel());
115             }
116             catHandlers.put(pl.getCategory(), Collections.singletonList(logPrinter));
117           }
118         }
119 
120     } else {
121       catHandlers = Collections.EMPTY_MAP;
122     }
123     String vals = Env.getSystemProperty("spf4j.test.log.expectingErrorsIn", "spf4j.testLog.expectingErrorsIn");
124     if (vals != null) {
125       expectingErrorsIn = ImmutableSortedSet.orderedBy(LogConfigImpl.REV_STR_COMPARATOR).add(vals.split(",")).build();
126     } else {
127       expectingErrorsIn = ImmutableSortedSet.of();
128     }
129     config = new LogConfigImpl(
130             ImmutableList.of(new LogPrinter(rootPrintLevel),
131                     new DefaultAsserter(this::isInExpectingErrorCategories)), catHandlers);
132     LogManager.getLogManager().reset();
133     SLF4JBridgeHandler.removeHandlersForRootLogger();
134     SLF4JBridgeHandler.install();
135     julGlobal = java.util.logging.Logger.getGlobal();
136     julRoot = java.util.logging.Logger.getLogger("");
137     resetJulConfig();
138   }
139 
140   public boolean isInExpectingErrorCategories(final String loggername) {
141     if (expectingErrorsIn.isEmpty()) {
142       return false;
143     }
144     for (String cat : expectingErrorsIn.tailSet(loggername)) {
145       if (loggername.startsWith(cat)) {
146         return true;
147       } else if (!loggername.isEmpty() && cat.charAt(0) != loggername.charAt(0)) {
148         break;
149       }
150     }
151     return false;
152   }
153 
154   private void resetJulConfig() {
155     java.util.logging.Level julLevel = config.minRootLevel().getJulLevel();
156     julGlobal.setLevel(julLevel);
157     julRoot.setLevel(julLevel);
158   }
159 
160   public LogConfig getConfig() {
161     return config;
162   }
163 
164   /**
165    * Print logs above a category and log level.
166    *
167    * @param category the log category.
168    * @param level the log level.
169    */
170   public void print(final String category, final Level level) {
171     interceptInContext(category, new LogPrinter(level));
172   }
173 
174   public void print(final String category, final Level level, final boolean greedy) {
175     if (greedy) {
176       interceptInContext(category, new GreedyLogPrinter(new LogPrinter(level)));
177     } else {
178       interceptInContext(category, new LogPrinter(level));
179     }
180   }
181   /**
182    * Ability to intercept log messages logged under a category
183    *
184    * @param category the logger category name (a.b.c)
185    * @param handler the log handler to register.
186    * @return a registration handle, that you can use to unregister.
187    */
188   @CheckReturnValue
189   public HandlerRegistration intercept(final String category, final LogHandler handler) {
190     HandlerRegistration reg = () -> {
191       synchronized (sync) {
192         config = config.remove(category, handler);
193         resetJulConfig();
194       }
195     };
196     addConfig(category, handler,  ExecutionContexts.current(), reg);
197     return reg;
198   }
199 
200   @CheckReturnValue
201   public void interceptInContext(final String category, final LogHandler handler) {
202     ExecutionContext current = ExecutionContexts.current();
203     if (current == null) {
204       throw new IllegalStateException("No execution context available for " + Thread.currentThread());
205     }
206     addConfig(category, handler, current, () -> {
207       synchronized (sync) {
208         config = config.remove(category, handler);
209         resetJulConfig();
210       }
211     });
212   }
213 
214 
215   /**
216    * Collect a bunch of logs.
217    * @param <T> the type of object to collect into.
218    * @param category the log category (a.b.c)
219    * @param fromLevel from level to collect.
220    * @param passThrough pass the logs to lower category handlers or not.
221    * @param collector the collector to collect the logs.
222    * @return collected logs.
223    */
224   @CheckReturnValue
225   public <T> LogCollection<T> collect(final String category, final Level fromLevel,
226           final boolean passThrough,
227           final Collector<TestLogRecord, ?, T> collector) {
228     return collect(category, fromLevel, Level.ERROR, passThrough, collector);
229   }
230 
231   /**
232    * Collect matching logs.
233    * matched logs are asserted.
234    * @return
235    */
236   @CheckReturnValue
237   public <T> LogCollection<T> collect(final String category, final Level fromLevel,
238           final boolean passThrough, final Matcher<TestLogRecord> matcher,
239           final Collector<TestLogRecord, ?, T> collector) {
240     return collect(category, fromLevel, passThrough, XCollectors.filtering((log) -> {
241               if (matcher.matches(log)) {
242                 log.attach(Attachments.ASSERTED);
243                 return true;
244               }
245               return false;
246             }, collector));
247   }
248 
249 
250   /**
251    * expect a stream of logs filtered by a matcher, this strem will be matched against the matchedMatcher.
252    * @return
253    */
254   @CheckReturnValue
255   public LogAssert expect(final String category, final Level fromLevel,
256           final boolean passThrough, final Matcher<TestLogRecord> matcher,
257           final Matcher<Iterable<TestLogRecord>> matchedMatcher) {
258     LogCollection<List<TestLogRecord>> lc = collect(category, fromLevel, passThrough, XCollectors.filtering((log) -> {
259       if (matcher.matches(log)) {
260         log.attach(Attachments.ASSERTED);
261         return true;
262       }
263       return false;
264     }, Collectors.toList()));
265     return new LogAssert() {
266       @Override
267       public void assertObservation() {
268         MatcherAssert.assertThat(lc.get(), matchedMatcher);
269       }
270 
271       @Override
272       public void close() {
273         assertObservation();
274         lc.close();
275       }
276     };
277   }
278 
279 
280   /**
281    * Collect a bunch of logs.
282    * @param <T> the type of object to collect into.
283    * @param category the log category (a.b.c)
284    * @param fromLevel from level to collect.
285    * @param toLevel to level to collect.
286    * @param passThrough pass the logs to lower category handlers or not.
287    * @param collector the collector to collect the logs.
288    * @return collected logs.
289    */
290   @CheckReturnValue
291   public <T> LogCollection<T> collect(final String category, final Level fromLevel, final Level toLevel,
292           final boolean passThrough,
293           final Collector<TestLogRecord, ?, T> collector) {
294     return collect(category, fromLevel, toLevel, passThrough, collector, (c) -> 0);
295   }
296 
297   @CheckReturnValue
298   public <R> LogCollection<R> collect(final String category, final Level fromLevel, final Level toLevel,
299           final boolean passThrough,
300           final Collector<TestLogRecord, ?, R> collector, final ToIntFunction<List<LogHandler>> whereTo) {
301     LogCollectorHandler<?, R> handler =
302             new LogCollectorHandler<>(fromLevel, toLevel, passThrough, collector,
303     (c) -> {
304        config = config.remove(category, c);
305        resetJulConfig();
306     });
307     addConfig(category, handler, ExecutionContexts.current(),  handler, whereTo);
308     return handler;
309   }
310 
311   private void addConfig(final String category, final LogHandler handler,
312           @Nullable final ExecutionContext ctx, final HandlerRegistration reg) {
313     addConfig(category, handler, ctx, reg, (c) -> 0);
314   }
315 
316 
317   /**
318    * Add a new handler configuration.
319    * @param category the category this handler is registered to.
320    * @param handler the log handler to register.
321    * @param ctx current execution context.
322    * @param reg the handler registration.
323    * @param whereTo if multiple handlers registered at this category level,
324    * this function will provide the insert location.
325    */
326   private void addConfig(final String category, final LogHandler handler,
327           @Nullable final ExecutionContext ctx, final HandlerRegistration reg,
328           final ToIntFunction<List<LogHandler>> whereTo) {
329     validateCorrectLoggingBacked();
330     synchronized (sync) {
331       config = config.add(category, handler, whereTo);
332       resetJulConfig();
333       if (ctx != null) {
334         ctx.addCloseable(reg);
335       }
336     }
337   }
338 
339   @SuppressFBWarnings("LO_SUSPECT_LOG_CLASS") // on purpose
340   private void validateCorrectLoggingBacked() {
341     ValidationUtils.validateLogger(LoggerFactory.getLogger("test"));
342   }
343 
344   /**
345    * Convenience method for functional use.
346    *
347    * @param category the log category.
348    * @param handler a functional handler.
349    * @return a registration handle to allow you to undo the registration.
350    */
351   @CheckReturnValue
352   public HandlerRegistration interceptAllLevels(final String category, final AllLevelsLogHandler handler) {
353     return intercept(category, handler);
354   }
355 
356   /**
357    * all logs from category and specified levels will be ignored... (unless there are more specific handlers)
358    * @param category the log category.
359    * @param from from log level.
360    * @param to to log level.
361    * @return a registration handle to allow you to undo this filtering.
362    */
363   @CheckReturnValue
364   public HandlerRegistration ignore(final String category, final Level from, final Level to) {
365     return intercept(category, new ConsumeAllLogs(from, to));
366   }
367 
368   /**
369    * Create an log expectation that can be asserted like:
370    * <code>
371    * LogAssert expect = TestLoggers.expect("org.spf4j.test", Level.ERROR, Matchers.hasProperty("format",
372    * Matchers.equalTo("Booo")));
373    * LOG.error("Booo", new RuntimeException());
374    * expect.assertObservation();
375    * </code>
376    * @param category the category under which we should expect these messages.
377    * @param minimumLogLevel minimum log level of expected log messages
378    * @param matchers a succession of LogMessages with each matching a Matcher is expected.
379    * @return an assertion handle.
380    */
381   @CheckReturnValue
382   @SafeVarargs
383   public final LogAssert expect(final String category, final Level minimumLogLevel,
384           final Matcher<TestLogRecord>... matchers) {
385     return logAssert(true, minimumLogLevel, category, matchers);
386   }
387 
388   @CheckReturnValue
389   @SafeVarargs
390   public final LogAssert expect(final String category, final Level minimumLogLevel,
391           final long timeout, final TimeUnit unit, final Matcher<TestLogRecord>... matchers) {
392     return logAssert(true, minimumLogLevel, category, timeout, unit, matchers);
393   }
394 
395   /**
396    * the opposite of expect.
397    * @param category the category under which we should expect these messages.
398    * @param minimumLogLevel minimum log level of expected log messages
399    * @param matchers a succession of LogMessages with each matching a Matcher is NOT expected.
400    * @return an assertion handle.
401    */
402   @CheckReturnValue
403   @SafeVarargs
404   public final LogAssert dontExpect(final String category, final Level minimumLogLevel,
405           final Matcher<TestLogRecord>... matchers) {
406     return logAssert(false, minimumLogLevel, category, matchers);
407   }
408 
409   @SafeVarargs
410   private final LogAssert logAssert(final boolean assertSeen, final Level minimumLogLevel,
411           final String category, final long timeout, final TimeUnit unit, final Matcher<TestLogRecord>... matchers) {
412     LogMatchingHandler handler = new LogMatchingHandlerAsync(minimumLogLevel, timeout, unit,
413                     new ExactLogStreamMatcher(assertSeen, matchers)) {
414 
415       private boolean isClosed = false;
416 
417       @Override
418       public void close() {
419         synchronized (sync) {
420           if (!isClosed) {
421             config = config.remove(category, this);
422             isClosed = true;
423             resetJulConfig();
424           }
425         }
426       }
427 
428     };
429     addConfig(category, handler,  ExecutionContexts.current(), handler);
430     return handler;
431   }
432 
433 
434   @SafeVarargs
435   private final LogAssert logAssert(final boolean assertSeen, final Level minimumLogLevel,
436           final String category,  final Matcher<TestLogRecord>... matchers) {
437     LogMatchingHandler handler = new LogMatchingHandler(minimumLogLevel,
438             new ExactLogStreamMatcher(assertSeen, matchers)) {
439 
440       private boolean isClosed = false;
441 
442       @Override
443       public void close() {
444         synchronized (sync) {
445           if (!isClosed) {
446             config = config.remove(category, this);
447             isClosed = true;
448             resetJulConfig();
449           }
450         }
451       }
452 
453     };
454     addConfig(category, handler,  ExecutionContexts.current(), handler);
455     return handler;
456   }
457 
458   /**
459    * Ability to assert is you expect a sequence of logs to be repeated.
460    *
461    * @param category the log category (a.b.c)
462    * @param minimumLogLevel the minimum log level of expected messages.
463    * @param nrTimes number of time the sequence should appear.
464    * @param matchers the sequence of matchers.
465    * @return the assertion handle.
466    */
467   @SafeVarargs
468   public final LogAssert expect(final String category, final Level minimumLogLevel,
469           final int nrTimes, final Matcher<TestLogRecord>... matchers) {
470     Matcher<TestLogRecord>[] newMatchers = new Matcher[matchers.length * nrTimes];
471     for (int i = 0, j = 0; i < nrTimes; i++) {
472       for (Matcher<TestLogRecord> m : matchers) {
473         newMatchers[j++] = m;
474       }
475     }
476     return expect(category, minimumLogLevel, newMatchers);
477   }
478 
479   @SafeVarargs
480   public final LogAssert expect(final String category, final Level minimumLogLevel,
481           final int nrTimes, final long timeout, final TimeUnit unit, final Matcher<TestLogRecord>... matchers) {
482     Matcher<TestLogRecord>[] newMatchers = new Matcher[matchers.length * nrTimes];
483     for (int i = 0, j = 0; i < nrTimes; i++) {
484       for (Matcher<TestLogRecord> m : matchers) {
485         newMatchers[j++] = m;
486       }
487     }
488     return expect(category, minimumLogLevel, timeout, unit, newMatchers);
489   }
490 
491 
492   /**
493    * Assert uncaught exceptions.(from threads)
494    * @param timeout timeout to wait for this assertion. from the point in time of assertion invocation.
495    * @param unit
496    * @param matcher the exception matcher.
497    * @return the assertion handle.
498    */
499   @Beta
500   public LogAssert expectUncaughtException(final long timeout, final TimeUnit unit,
501           final Matcher<UncaughtExceptionDetail> matcher) {
502     ExceptionHandoverRegistry reg = Spf4jTestLogRunListenerSingleton.getListenerInstance()
503             .getUncaughtExceptionHandler();
504     UncaughtExceptionAsserter asserter = new UncaughtExceptionAsserter(timeout, unit, matcher) {
505 
506       @Override
507       public void close() {
508         reg.remove(this);
509       }
510     };
511     reg.add(asserter);
512     return asserter;
513   }
514 
515   /**
516    * Collect up to a number of log messages.
517    * @param minimumLogLevel the minimum log level of the messages.
518    * @param maxNrLogs the max number of messages to collect.
519    * @param collectPrinted collect messages that have been printed or not.
520    * @return the collection of messages.
521    */
522   public LogCollection<ArrayDeque<TestLogRecord>> collect(final Level minimumLogLevel, final int maxNrLogs,
523           final boolean collectPrinted) {
524     return collect("", minimumLogLevel, maxNrLogs, collectPrinted, null);
525   }
526 
527   public LogCollection<ArrayDeque<TestLogRecord>> collect(final Level minimumLogLevel, final int maxNrLogs,
528           final boolean collectPrinted, final String include, final String... excludeCategories) {
529     ArrayDeque adq = new ArrayDeque(maxNrLogs + 1);
530     Collector<TestLogRecord, ArrayDeque<TestLogRecord>, ArrayDeque<TestLogRecord>> truncationCollector
531             = XCollectors.last(() -> adq, maxNrLogs,
532                     new TestLogRecordImpl("test", Level.INFO, "Truncated beyond {} ", maxNrLogs));
533       if (excludeCategories.length == 0) {
534          return collect(include, minimumLogLevel, collectPrinted, (Predicate<TestLogRecord>) null, truncationCollector);
535       } else {
536          return collect(include, minimumLogLevel, collectPrinted, (log) -> {
537           String loggerName = log.getLoggerName();
538           for (String cat : excludeCategories) {
539             if (loggerName.startsWith(cat)) {
540               return false;
541             }
542           }
543           return true;
544         }, truncationCollector);
545       }
546   }
547 
548 
549   public LogCollection<ArrayDeque<TestLogRecord>> collect(final String category, final Level minimumLogLevel,
550           final int maxNrLogs,
551           final boolean collectPrinted, @Nullable final Predicate<TestLogRecord> collectorFilter) {
552     Collector<TestLogRecord, ArrayDeque<TestLogRecord>, ArrayDeque<TestLogRecord>> truncationCollector
553             = XCollectors.last(maxNrLogs,
554             new TestLogRecordImpl("test", Level.INFO, "Truncated beyond {} ", maxNrLogs));
555     return collect(category, minimumLogLevel, collectPrinted, collectorFilter, truncationCollector);
556   }
557 
558   public LogCollection<ArrayDeque<TestLogRecord>> collect(
559           final String category, final Level minimumLogLevel,
560           final boolean collectPrinted,
561           final Predicate<TestLogRecord> collectorFilter,
562           final Collector<TestLogRecord, ?, ArrayDeque<TestLogRecord>> pcollector) {
563     Collector<TestLogRecord, ?, ArrayDeque<TestLogRecord>>  collector = pcollector;
564     if (collectorFilter != null) {
565       collector = XCollectors.filtering(collectorFilter, collector);
566     }
567     if (!collectPrinted) {
568       return collect(category,
569               minimumLogLevel,
570               Level.ERROR,
571               true,
572               XCollectors.filtering((l) -> !l.hasAttachment(Attachments.PRINTED), collector),
573               List::size);
574     } else {
575       return collect(category, minimumLogLevel, Level.ERROR, true, collector, (c)  -> 0);
576     }
577   }
578 
579   /**
580    * Return an appropriate {@link SimpleLogger} instance by name.
581    */
582   public Logger getLogger(final String name) {
583     Logger result = loggerMap.get(name);
584     if (result == null) {
585       // Racy on purpose. computeIfAbsent is not really re-entrant.
586       result = new TestLogger(name, TestLoggers.this::getConfig);
587       loggerMap.put(name, result);
588     }
589     return result;
590   }
591 
592   @SuppressFBWarnings("EI_EXPOSE_REP")
593   public java.util.logging.Logger getJulGlobal() {
594     return julGlobal;
595   }
596 
597   @SuppressFBWarnings("EI_EXPOSE_REP")
598   public java.util.logging.Logger getJulRoot() {
599     return julRoot;
600   }
601 
602   @Override
603   public String toString() {
604     return "TestLoggers{ config=" + config + ", loggerMap=" + loggerMap + '}';
605   }
606 
607 }