Assert on log output
Project: http://git-wip-us.apache.org/repos/asf/brooklyn-server/repo Commit: http://git-wip-us.apache.org/repos/asf/brooklyn-server/commit/643aa9c1 Tree: http://git-wip-us.apache.org/repos/asf/brooklyn-server/tree/643aa9c1 Diff: http://git-wip-us.apache.org/repos/asf/brooklyn-server/diff/643aa9c1 Branch: refs/heads/master Commit: 643aa9c1e4643b37ec96f7dcebfcf4cb3c78c6bd Parents: d456333 Author: Geoff Macartney <geoff.macart...@cloudsoftcorp.com> Authored: Fri Jan 26 17:38:34 2018 +0000 Committer: Geoff Macartney <geoff.macart...@cloudsoftcorp.com> Committed: Fri Feb 9 21:09:20 2018 +0000 ---------------------------------------------------------------------- .../core/entity/ApplicationLoggingTest.java | 51 +++++++- .../brooklyn/logback-appender-stdout.xml | 35 ----- .../org/apache/brooklyn/test/LogWatcher.java | 131 ++++++++++++------- 3 files changed, 129 insertions(+), 88 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/643aa9c1/core/src/test/java/org/apache/brooklyn/core/entity/ApplicationLoggingTest.java ---------------------------------------------------------------------- diff --git a/core/src/test/java/org/apache/brooklyn/core/entity/ApplicationLoggingTest.java b/core/src/test/java/org/apache/brooklyn/core/entity/ApplicationLoggingTest.java index 3fc57ec..2e74593 100644 --- a/core/src/test/java/org/apache/brooklyn/core/entity/ApplicationLoggingTest.java +++ b/core/src/test/java/org/apache/brooklyn/core/entity/ApplicationLoggingTest.java @@ -18,6 +18,10 @@ */ package org.apache.brooklyn.core.entity; +import static com.google.common.base.Predicates.and; +import static org.apache.brooklyn.test.LogWatcher.EventPredicates.containsMessage; +import static org.apache.brooklyn.test.LogWatcher.EventPredicates.matchesPatterns; + import java.util.ArrayDeque; import java.util.Collection; import java.util.Deque; @@ -34,15 +38,21 @@ import org.apache.brooklyn.core.test.entity.TestApplication; import org.apache.brooklyn.core.test.entity.TestApplicationImpl; import org.apache.brooklyn.core.test.entity.TestEntity; import org.apache.brooklyn.core.test.entity.TestEntityImpl; +import org.apache.brooklyn.test.LogWatcher; import org.apache.brooklyn.util.collections.QuorumCheck; import org.apache.brooklyn.util.exceptions.Exceptions; +import org.apache.brooklyn.util.text.Strings; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import org.slf4j.MDC; import org.testng.annotations.Test; +import com.google.common.base.Predicate; +import com.google.common.base.Predicates; import com.google.common.collect.ImmutableList; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.spi.ILoggingEvent; + @Test public class ApplicationLoggingTest extends BrooklynAppUnitTestSupport { private static final Logger LOG = LoggerFactory.getLogger(ApplicationLoggingTest.class); @@ -131,18 +141,49 @@ public class ApplicationLoggingTest extends BrooklynAppUnitTestSupport { @Test public void testLogging() throws Exception { + String loggerName = ApplicationLoggingTest.class.getName(); + ch.qos.logback.classic.Level logLevel = ch.qos.logback.classic.Level.INFO; Deque<String> ids = new ArrayDeque<>(); ids.push(app.getId()); final TestEntityWithLogging entity = app.createAndManageChild(EntitySpec.create(TestEntityWithLogging.class)); final TestEntityWithLogging child = entity.addChild(EntitySpec.create(EntitySpec.create(TestEntityWithLogging.class))); - app.start(ImmutableList.of(app.newSimulatedLocation())); - assertHealthEventually(app, Lifecycle.RUNNING, true); - app.stop(); - assertHealthEventually(app, Lifecycle.STOPPED, false); + LogWatcher watcher = new LogWatcher(loggerName, logLevel, containsMessage(app.getId())); + + watcher.start(); + try { + app.start(ImmutableList.of(app.newSimulatedLocation())); + assertHealthEventually(app, Lifecycle.RUNNING, true); + app.stop(); + assertHealthEventually(app, Lifecycle.STOPPED, false); + watcher.assertHasEvent(matchesPatterns(".*" + app.getApplicationId() + ".*Hello world.*")); + watcher.assertHasEvent(matchesPatterns(".*" + + ImmutableList.of(app.getId(), entity.getId()).toString() + + ".*from entity.*" + entity.getId() + ".*")); + watcher.assertHasEvent(matchesPatterns(".*" + + ImmutableList.of(app.getId(), entity.getId()).toString() + + ".*from entity.*" + entity.getId() + ".*")); + watcher.assertHasEvent(matchesPatterns(".*" + + ImmutableList.of(app.getId(), entity.getId(), child.getId()).toString() + + ".*from entity.*" + child.getId() + ".*")); + } finally { + watcher.close(); + } } + @Test + public void testOne() { + LogWatcher watcher = new LogWatcher(LOG.getName(), Level.DEBUG, Predicates.alwaysTrue()); + + watcher.start(); + try { + LOG.error("Test message"); + } finally { + watcher.close(); + } + } + private void assertHealthEventually(Entity entity, Lifecycle expectedState, Boolean expectedUp) { EntityAsserts.assertAttributeEqualsEventually(entity, Attributes.SERVICE_STATE_ACTUAL, expectedState); EntityAsserts.assertAttributeEqualsEventually(entity, Attributes.SERVICE_UP, expectedUp); http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/643aa9c1/core/src/test/resources/brooklyn/logback-appender-stdout.xml ---------------------------------------------------------------------- diff --git a/core/src/test/resources/brooklyn/logback-appender-stdout.xml b/core/src/test/resources/brooklyn/logback-appender-stdout.xml deleted file mode 100644 index e612042..0000000 --- a/core/src/test/resources/brooklyn/logback-appender-stdout.xml +++ /dev/null @@ -1,35 +0,0 @@ -<?xml version="1.0" encoding="UTF-8"?> -<!-- - Licensed to the Apache Software Foundation (ASF) under one - or more contributor license agreements. See the NOTICE file - distributed with this work for additional information - regarding copyright ownership. The ASF licenses this file - to you under the Apache License, Version 2.0 (the - "License"); you may not use this file except in compliance - with the License. You may obtain a copy of the License at - - http://www.apache.org/licenses/LICENSE-2.0 - - Unless required by applicable law or agreed to in writing, - software distributed under the License is distributed on an - "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY - KIND, either express or implied. See the License for the - specific language governing permissions and limitations - under the License. ---> -<included> - - <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> - <encoder> - <pattern>%d %-5level %X{entity.ids} %msg%n%xEx{0}</pattern> - </encoder> - <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> - <level>INFO</level> - </filter> - </appender> - - <root> - <appender-ref ref="STDOUT" /> - </root> - -</included> http://git-wip-us.apache.org/repos/asf/brooklyn-server/blob/643aa9c1/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java ---------------------------------------------------------------------- diff --git a/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java b/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java index 90b87e4..16d27b0 100644 --- a/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java +++ b/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java @@ -24,17 +24,17 @@ import static org.testng.Assert.assertFalse; import java.io.ByteArrayOutputStream; import java.io.Closeable; +import java.io.IOException; +import java.lang.reflect.Proxy; import java.io.PrintStream; import java.util.Collections; import java.util.List; import java.util.Map; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicReference; +import java.util.function.BiPredicate; import org.apache.brooklyn.util.time.Time; -import org.mockito.Mockito; -import org.mockito.invocation.InvocationOnMock; -import org.mockito.stubbing.Answer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -46,10 +46,12 @@ import com.google.common.collect.Lists; import com.google.common.collect.Maps; import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.encoder.PatternLayoutEncoder; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.IThrowableProxy; import ch.qos.logback.classic.spi.StackTraceElementProxy; -import ch.qos.logback.core.Appender; +import ch.qos.logback.core.OutputStreamAppender; /** * Testing utility that registers an appender to watch a given logback logger, and records events @@ -67,35 +69,40 @@ public class LogWatcher implements Closeable { public static Predicate<ILoggingEvent> containsMessage(final String expected) { return containsMessages(expected); } - - public static Predicate<ILoggingEvent> containsMessages(final String... expecteds) { - return new Predicate<ILoggingEvent>() { - @Override public boolean apply(ILoggingEvent input) { - if (input == null) return false; - String msg = input.getFormattedMessage(); - if (msg == null) return false; - for (String expected : expecteds) { - if (!msg.contains(expected)) return false; - } - return true; + + public static Predicate<ILoggingEvent> matchPredicate(BiPredicate<String, String> pred, + final String... expecteds) { + return event -> { + if (event == null) return false; + String msg = event.getFormattedMessage(); + if (msg == null) return false; + for (String expected : expecteds) { + if (!pred.test(msg.trim(), expected)) return false; } + return true; }; } - + + public static Predicate<ILoggingEvent> matchesPatterns(final String... patterns) { + return matchPredicate(String::matches, patterns); + } + + public static Predicate<ILoggingEvent> containsMessages(final String... expecteds) { + return matchPredicate(String::contains, expecteds); + } + public static Predicate<ILoggingEvent> containsExceptionStackLine(final Class<?> clazz, final String methodName) { - return new Predicate<ILoggingEvent>() { - @Override public boolean apply(ILoggingEvent input) { - IThrowableProxy throwable = (input != null) ? input.getThrowableProxy() : null; - if (throwable != null) { - for (StackTraceElementProxy line : throwable.getStackTraceElementProxyArray()) { - if (line.getStackTraceElement().getClassName().contains(clazz.getSimpleName()) - && line.getStackTraceElement().getMethodName().contains(methodName)) { - return true; - } + return event -> { + IThrowableProxy throwable = (event != null) ? event.getThrowableProxy() : null; + if (throwable != null) { + for (StackTraceElementProxy line : throwable.getStackTraceElementProxyArray()) { + if (line.getStackTraceElement().getClassName().contains(clazz.getSimpleName()) + && line.getStackTraceElement().getMethodName().contains(methodName)) { + return true; } } - return false; } + return false; }; } @@ -124,7 +131,6 @@ public class LogWatcher implements Closeable { } }; } - public static Predicate<ILoggingEvent> containsExceptionClassname(final String expected) { return new Predicate<ILoggingEvent>() { @Override public boolean apply(ILoggingEvent input) { @@ -135,7 +141,6 @@ public class LogWatcher implements Closeable { } }; } - public static Predicate<ILoggingEvent> levelGeaterOrEqual(final Level expectedLevel) { return new Predicate<ILoggingEvent>() { @Override public boolean apply(ILoggingEvent input) { @@ -150,7 +155,7 @@ public class LogWatcher implements Closeable { private final List<ILoggingEvent> events = Collections.synchronizedList(Lists.<ILoggingEvent>newLinkedList()); private final AtomicBoolean closed = new AtomicBoolean(); private final ch.qos.logback.classic.Level loggerLevel; - private final Appender<ILoggingEvent> appender; + private final OutputStreamAppender<ILoggingEvent> appender; private final List<ch.qos.logback.classic.Logger> watchedLoggers = Lists.newArrayList(); private volatile Map<ch.qos.logback.classic.Logger, Level> origLevels = Maps.newLinkedHashMap(); @@ -160,29 +165,61 @@ public class LogWatcher implements Closeable { @SuppressWarnings("unchecked") public LogWatcher(Iterable<String> loggerNames, ch.qos.logback.classic.Level loggerLevel, final Predicate<? super ILoggingEvent> filter) { - for (String loggerName : loggerNames) { - Logger logger = LoggerFactory.getLogger(checkNotNull(loggerName, "loggerName")); - watchedLoggers.add((ch.qos.logback.classic.Logger) logger); - } + this.loggerLevel = checkNotNull(loggerLevel, "loggerLevel"); - this.appender = Mockito.mock(Appender.class); - - Mockito.when(appender.getName()).thenReturn("MOCK"); - Answer<Void> answer = new Answer<Void>() { + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); + + this.appender = new OutputStreamAppender<ILoggingEvent>() { @Override - public Void answer(InvocationOnMock invocation) throws Throwable { - ILoggingEvent event = invocation.getArgument(0); - if (event != null && filter.apply(event)) { - events.add(event); - } + protected void append(ILoggingEvent event) { + super.append(event); + LOG.trace("level="+event.getLevel()+"; event="+event+"; msg="+event.getFormattedMessage()); - return null; } }; - Mockito.doAnswer(answer).when(appender).doAppend(Mockito.<ILoggingEvent>any()); + + PatternLayoutEncoder ple = new PatternLayoutEncoder() { + @Override + public void doEncode(ILoggingEvent event) throws IOException { + final String txt = layout.doLayout(event); + ILoggingEvent formatted = (ILoggingEvent) Proxy.newProxyInstance( + ILoggingEvent.class.getClassLoader(), + new Class<?>[]{ILoggingEvent.class}, + (proxy, method, args) -> { + if (method.getName().endsWith("Message") || method.getName().equals("toString")) { + return txt; + } else { + return method.invoke(event, args); + } + }); + if (event != null && filter.apply(formatted)) { + events.add(formatted); + } + + super.doEncode(event); + } + }; + + ple.setPattern(">>>> %d{ISO8601} %X{entity.ids} %-5.5p %3X{bundle.id} %c{1.} [%.16t] %m%n"); + ple.setContext(lc); + ple.start(); + + this.appender.setContext(lc); + this.appender.setEncoder(ple); + this.appender.setOutputStream(System.out); + this.appender.start(); + + for (String loggerName : loggerNames) { + final ch.qos.logback.classic.Logger logger = (ch.qos.logback.classic.Logger)LoggerFactory.getLogger(checkNotNull(loggerName, "loggerName")); + logger.addAppender(this.appender); + logger.setLevel(this.loggerLevel); + logger.setAdditive(false); + watchedLoggers.add((ch.qos.logback.classic.Logger) logger); + } } public void start() { + checkState(!closed.get(), "Cannot start LogWatcher after closed"); for (ch.qos.logback.classic.Logger watchedLogger : watchedLoggers) { origLevels.put(watchedLogger, watchedLogger.getLevel()); @@ -252,20 +289,18 @@ public class LogWatcher implements Closeable { public void printEvents() { printEvents(System.out, getEvents()); } - public String printEventsToString() { return printEventsToString(getEvents()); } - + public String printEventsToString(Iterable<? extends ILoggingEvent> events) { ByteArrayOutputStream baos = new ByteArrayOutputStream(); printEvents(new PrintStream(baos), events); return new String(baos.toByteArray()); } - public void printEvents(PrintStream stream, Iterable<? extends ILoggingEvent> events) { for (ILoggingEvent event : events) { - stream.println(Time.makeDateString(event.getTimeStamp()) + ": " + event.getThreadName() + stream.println(Time.makeDateString(event.getTimeStamp()) + ": " + event.getThreadName() + ": " + event.getLevel() + ": " + event.getMessage()); IThrowableProxy throwable = event.getThrowableProxy(); if (throwable != null) {