From b7cd606e93c25340ddfc869df8c2b2e489b1120e Mon Sep 17 00:00:00 2001 From: Aled Sage Date: Sat, 9 Jul 2016 18:41:29 +0100 Subject: [PATCH] BROOKLYN-313: log.debug exceptions thrown by effectors --- .../brooklyn/core/effector/EffectorTasks.java | 2 +- .../core/mgmt/internal/EffectorUtils.java | 7 +- .../effector/EffectorExceptionLoggedTest.java | 178 ++++++++++++++++++ test-support/pom.xml | 4 + .../org/apache/brooklyn/test/LogWatcher.java | 145 ++++++++++++++ 5 files changed, 331 insertions(+), 5 deletions(-) create mode 100644 core/src/test/java/org/apache/brooklyn/core/effector/EffectorExceptionLoggedTest.java create mode 100644 test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java diff --git a/core/src/main/java/org/apache/brooklyn/core/effector/EffectorTasks.java b/core/src/main/java/org/apache/brooklyn/core/effector/EffectorTasks.java index 68d45a57a9..b9429a0ac1 100644 --- a/core/src/main/java/org/apache/brooklyn/core/effector/EffectorTasks.java +++ b/core/src/main/java/org/apache/brooklyn/core/effector/EffectorTasks.java @@ -87,7 +87,7 @@ public T call() throws Exception { }) { @Override public void handleException(Throwable throwable) throws Exception { - EffectorUtils.handleEffectorException(entity, effector, throwable); + throw EffectorUtils.handleEffectorException(entity, effector, throwable); } }); return dst.get(); diff --git a/core/src/main/java/org/apache/brooklyn/core/mgmt/internal/EffectorUtils.java b/core/src/main/java/org/apache/brooklyn/core/mgmt/internal/EffectorUtils.java index d2a8424ee7..1b298e3687 100644 --- a/core/src/main/java/org/apache/brooklyn/core/mgmt/internal/EffectorUtils.java +++ b/core/src/main/java/org/apache/brooklyn/core/mgmt/internal/EffectorUtils.java @@ -278,9 +278,7 @@ public static T invokeMethodEffector(Entity entity, Effector eff, Map effector, T EffectorCallPropagatedRuntimeException result = new EffectorCallPropagatedRuntimeException(entity, effector, throwable); log.warn(Exceptions.collapseText(result)); + log.debug(makeMessage(entity, effector), throwable); throw result; } } - public static void handleEffectorException(Entity entity, Effector effector, Throwable throwable) { + public static RuntimeException handleEffectorException(Entity entity, Effector effector, Throwable throwable) { throw EffectorCallPropagatedRuntimeException.propagate(entity, effector, throwable); } diff --git a/core/src/test/java/org/apache/brooklyn/core/effector/EffectorExceptionLoggedTest.java b/core/src/test/java/org/apache/brooklyn/core/effector/EffectorExceptionLoggedTest.java new file mode 100644 index 0000000000..f3854f19c6 --- /dev/null +++ b/core/src/test/java/org/apache/brooklyn/core/effector/EffectorExceptionLoggedTest.java @@ -0,0 +1,178 @@ +/* + * 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. + */ +package org.apache.brooklyn.core.effector; + +import java.io.ByteArrayOutputStream; +import java.io.PrintWriter; +import java.util.concurrent.Callable; + +import org.apache.brooklyn.api.effector.Effector; +import org.apache.brooklyn.api.effector.ParameterType; +import org.apache.brooklyn.api.entity.Entity; +import org.apache.brooklyn.api.entity.EntitySpec; +import org.apache.brooklyn.api.mgmt.Task; +import org.apache.brooklyn.api.mgmt.entitlement.EntitlementClass; +import org.apache.brooklyn.api.mgmt.entitlement.EntitlementContext; +import org.apache.brooklyn.api.mgmt.entitlement.EntitlementManager; +import org.apache.brooklyn.core.effector.EffectorTasks.EffectorTaskFactory; +import org.apache.brooklyn.core.entity.AbstractEntity; +import org.apache.brooklyn.core.entity.Entities; +import org.apache.brooklyn.core.internal.BrooklynProperties; +import org.apache.brooklyn.core.mgmt.BrooklynTaskTags; +import org.apache.brooklyn.core.mgmt.entitlement.Entitlements; +import org.apache.brooklyn.core.mgmt.entitlement.Entitlements.EntityAndItem; +import org.apache.brooklyn.core.mgmt.entitlement.Entitlements.StringAndArgument; +import org.apache.brooklyn.core.mgmt.internal.EffectorUtils; +import org.apache.brooklyn.core.test.BrooklynAppUnitTestSupport; +import org.apache.brooklyn.core.test.entity.TestEntity; +import org.apache.brooklyn.test.LogWatcher; +import org.apache.brooklyn.test.LogWatcher.EventPredicates; +import org.apache.brooklyn.util.core.config.ConfigBag; +import org.apache.brooklyn.util.core.task.Tasks; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.testng.annotations.BeforeMethod; +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.spi.ILoggingEvent; + +public class EffectorExceptionLoggedTest extends BrooklynAppUnitTestSupport { + + private static final Logger LOG = LoggerFactory.getLogger(AbstractEntity.class); + + private TestEntity entity; + + public static class ThrowingEntitlementManager implements EntitlementManager { + @Override + public boolean isEntitled(EntitlementContext context, EntitlementClass entitlementClass, T entitlementClassArgument) { + String type = entitlementClass.entitlementClassIdentifier(); + if (Entitlements.INVOKE_EFFECTOR.entitlementClassIdentifier().equals(type)) { + @SuppressWarnings("unchecked") + String effectorName = ((EntityAndItem)entitlementClassArgument).getItem().getString(); + if ("myEffector".equals(effectorName)) { + LOG.info("Simulating NPE in entitlement manager"); + throw new NullPointerException(); + } + } + return true; + } + } + + protected BrooklynProperties getBrooklynProperties() { + BrooklynProperties result = BrooklynProperties.Factory.newEmpty(); + result.put(Entitlements.GLOBAL_ENTITLEMENT_MANAGER, ThrowingEntitlementManager.class.getName()); + return result; + } + + @BeforeMethod(alwaysRun=true) + @Override + public void setUp() throws Exception { + super.setUp(); + entity = app.addChild(EntitySpec.create(TestEntity.class)); + } + + @Test + public void testInvokeEffectorDirectlyIncludesException() throws Exception { + try { + entity.myEffector(); + } catch (Exception e) { + assertExceptionContainsIsEntitledStack(e); + } + + try { + Entities.invokeEffector(app, entity, TestEntity.MY_EFFECTOR).get(); + } catch (Exception e) { + assertExceptionContainsIsEntitledStack(e); + } + } + + @Test + public void testInvokeViaOtherEffectorIncludesException() throws Exception { + EffectorTaskFactory body = new EffectorTaskFactory() { + @Override public Task newTask(final Entity entity, final Effector effector, final ConfigBag parameters) { + return Tasks.builder() + .body(new Callable() { + @Override public Void call() throws Exception { + EffectorExceptionLoggedTest.this.entity.myEffector(); + return null; + }}) + .build(); + } + }; + EffectorAndBody effector = new EffectorAndBody("callingEffector", Void.class, ImmutableList.>of(), "my description", body); + + try { + Entities.invokeEffector(app, app, effector).get(); + } catch (Exception e) { + assertExceptionContainsIsEntitledStack(e); + } + } + + /** + * This task-invocation pattern matches that used in AutoScaler. + * + * Confirm that we log the real stacktrace of the exception. + * + * This requires adding a mock appender, asserting it gets called with our desired + * class+method name, and then removing the appender! + */ + @Test + public void testInvokeInTask() throws Exception { + String loggerName = EffectorUtils.class.getName(); + ch.qos.logback.classic.Level logLevel = ch.qos.logback.classic.Level.DEBUG; + Predicate filter = Predicates.and(EventPredicates.containsMessage("Error invoking myEffector"), + EventPredicates.containsExceptionStackLine(ThrowingEntitlementManager.class, "isEntitled")); + LogWatcher watcher = new LogWatcher(loggerName, logLevel, filter); + + watcher.start(); + try { + Entities.submit(entity, Tasks.builder().displayName("Effector-invoker") + .description("Invoke in task") + .tag(BrooklynTaskTags.NON_TRANSIENT_TASK_TAG) + .body(new Callable() { + @Override + public Void call() throws Exception { + entity.myEffector(); + return null; + } + }).build()) + .blockUntilEnded(); + + watcher.assertHasEventEventually(); + } finally { + watcher.close(); + } + } + + private void assertExceptionContainsIsEntitledStack(Exception e) throws Exception { + String expected = ThrowingEntitlementManager.class.getSimpleName()+".isEntitled"; + ByteArrayOutputStream baos = new ByteArrayOutputStream(); + PrintWriter writer = new PrintWriter(baos); + e.printStackTrace(writer); + writer.flush(); + String eString = new String(baos.toByteArray()); + if (!eString.contains(expected)) { + throw new Exception("Original exception does not contain '"+expected+"'", e); + } + } +} diff --git a/test-support/pom.xml b/test-support/pom.xml index 84beaf6da8..1cb977e891 100644 --- a/test-support/pom.xml +++ b/test-support/pom.xml @@ -59,5 +59,9 @@ org.testng testng + + org.mockito + mockito-core + 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 new file mode 100644 index 0000000000..9326f1b17d --- /dev/null +++ b/test-support/src/main/java/org/apache/brooklyn/test/LogWatcher.java @@ -0,0 +1,145 @@ +/* + * 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. + */ +package org.apache.brooklyn.test; + +import static com.google.common.base.Preconditions.checkNotNull; +import static com.google.common.base.Preconditions.checkState; +import static org.testng.Assert.assertFalse; + +import java.io.Closeable; +import java.util.Collections; +import java.util.List; +import java.util.concurrent.atomic.AtomicBoolean; + +import org.mockito.Mockito; +import org.mockito.invocation.InvocationOnMock; +import org.mockito.stubbing.Answer; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import com.google.common.annotations.Beta; +import com.google.common.base.Predicate; +import com.google.common.collect.ImmutableList; +import com.google.common.collect.Lists; + +import ch.qos.logback.classic.Level; +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; + +/** + * Testing utility that registers an appender to watch a given logback logger, and records events + * that match a given predicate. + * + * Callers should first call {@link #start()}, and must call {@link #close()} to de-register the + * appender (doing this in a finally block). + */ +@Beta +public class LogWatcher implements Closeable { + + private static final Logger LOG = LoggerFactory.getLogger(LogWatcher.class); + + public static class EventPredicates { + public static Predicate containsMessage(final String expected) { + return new Predicate() { + @Override public boolean apply(ILoggingEvent input) { + if (input == null) return false; + String msg = input.getFormattedMessage(); + return (msg != null) && msg.contains(expected); + } + }; + } + + public static Predicate containsExceptionStackLine(final Class clazz, final String methodName) { + return new Predicate() { + @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 false; + } + }; + } + } + + private final List events = Collections.synchronizedList(Lists.newLinkedList()); + private final AtomicBoolean closed = new AtomicBoolean(); + private final ch.qos.logback.classic.Level loggerLevel; + private final ch.qos.logback.classic.Logger watchedLogger; + private final Appender appender; + private volatile Level origLevel; + + @SuppressWarnings("unchecked") + public LogWatcher(String loggerName, ch.qos.logback.classic.Level loggerLevel, final Predicate filter) { + this.watchedLogger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(checkNotNull(loggerName, "loggerName")); + this.loggerLevel = checkNotNull(loggerLevel, "loggerLevel"); + this.appender = Mockito.mock(Appender.class); + + Mockito.when(appender.getName()).thenReturn("MOCK"); + Answer answer = new Answer() { + @Override + public Void answer(InvocationOnMock invocation) throws Throwable { + ILoggingEvent event = invocation.getArgumentAt(0, ILoggingEvent.class); + if (event != null && filter.apply(event)) { + events.add(event); + } + LOG.trace("level="+event.getLevel()+"; event="+event+"; msg="+event.getFormattedMessage()); + return null; + } + }; + Mockito.doAnswer(answer).when(appender).doAppend(Mockito.any()); + } + + public void start() { + checkState(!closed.get(), "Cannot start LogWatcher after closed"); + origLevel = watchedLogger.getLevel(); + watchedLogger.setLevel(loggerLevel); + watchedLogger.addAppender(appender); + } + + @Override + public void close() { + if (closed.compareAndSet(false, true)) { + if (watchedLogger != null) { + if (origLevel != null) watchedLogger.setLevel(origLevel); + watchedLogger.detachAppender(appender); + } + } + } + + public void assertHasEventEventually() { + Asserts.succeedsEventually(new Runnable() { + public void run() { + assertFalse(events.isEmpty()); + }}); + } + + public List getEvents() { + synchronized (events) { + return ImmutableList.copyOf(events); + } + } +}