Merge pull request #49 from Nordstrom/pr/add-debug-logging

sbabcoc · web-flow · commit 51670511ecd7 · 2019-04-24T15:09:36.000-07:00
Add debug logging and assertion messages
diff --git a/src/main/java/com/nordstrom/automation/junit/AtomicTest.java b/src/main/java/com/nordstrom/automation/junit/AtomicTest.java
@@ -107,4 +107,12 @@ public Throwable getThrowable() {
     public boolean includes(FrameworkMethod method) {
         return particles.contains(method);
     }
+    
+    /**
+     * {@inheritDoc}
+     */
+    @Override
+    public String toString() {
+        return description.toString();
+    }
 }
diff --git a/src/main/java/com/nordstrom/automation/junit/CreateTest.java b/src/main/java/com/nordstrom/automation/junit/CreateTest.java
@@ -5,6 +5,9 @@
 import java.util.concurrent.Callable;
 import java.util.concurrent.ConcurrentHashMap;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import com.google.common.base.Optional;
 
 import net.bytebuddy.implementation.bind.annotation.RuntimeType;
@@ -22,6 +25,7 @@ public class CreateTest {
     private static final Map<Object, Object> TARGET_TO_RUNNER = new ConcurrentHashMap<>();
     private static final Map<Object, Object> RUNNER_TO_TARGET = new ConcurrentHashMap<>();
     private static final ThreadLocal<DepthGauge> DEPTH;
+    private static final Logger LOGGER = LoggerFactory.getLogger(CreateTest.class);
     
     static {
         objectWatcherLoader = ServiceLoader.load(TestObjectWatcher.class);
@@ -57,6 +61,7 @@ public static Object intercept(@This final Object runner,
         RUNNER_TO_TARGET.put(runner, testObj);
         
         if (DEPTH.get().atGroundLevel()) {
+            LOGGER.debug("testObjectCreated: {}", testObj);
             synchronized(objectWatcherLoader) {
                 for (TestObjectWatcher watcher : objectWatcherLoader) {
                     watcher.testObjectCreated(testObj, runner);
diff --git a/src/main/java/com/nordstrom/automation/junit/LifecycleHooks.java b/src/main/java/com/nordstrom/automation/junit/LifecycleHooks.java
@@ -12,14 +12,12 @@
 import java.util.concurrent.Callable;
 import java.util.concurrent.ConcurrentMap;
 
-import org.junit.Test;
 import org.junit.runner.Description;
 import org.junit.runner.notification.RunListener;
 import org.junit.runners.model.TestClass;
 
 import com.google.common.base.Function;
 import com.google.common.base.Optional;
-import com.nordstrom.automation.junit.JUnitConfig.JUnitSettings;
 import com.nordstrom.common.base.UncheckedThrow;
 import com.nordstrom.common.file.PathUtils.ReportsDirectory;
 
diff --git a/src/main/java/com/nordstrom/automation/junit/Run.java b/src/main/java/com/nordstrom/automation/junit/Run.java
@@ -13,6 +13,8 @@
 import org.junit.runner.Description;
 import org.junit.runner.notification.RunListener;
 import org.junit.runner.notification.RunNotifier;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import com.google.common.base.Optional;
 
@@ -32,6 +34,7 @@ public class Run {
     private static final ServiceLoader<RunnerWatcher> runnerWatcherLoader;
     private static final Map<Object, Object> CHILD_TO_PARENT = new ConcurrentHashMap<>();
     private static final Set<RunNotifier> NOTIFIERS = new CopyOnWriteArraySet<>();
+    private static final Logger LOGGER = LoggerFactory.getLogger(Run.class);
     
     static {
         runnerStack = new ThreadLocal<Deque<Object>>() {
@@ -139,6 +142,7 @@ static boolean fireRunStarted(Object runner) {
             for (Object grandchild : grandchildren) {
                 CHILD_TO_PARENT.put(grandchild, runner);
             }
+            LOGGER.debug("runStarted: {}", runner);
             synchronized(runnerWatcherLoader) {
                 for (RunnerWatcher watcher : runnerWatcherLoader) {
                     watcher.runStarted(runner);
@@ -158,6 +162,7 @@ static boolean fireRunStarted(Object runner) {
      */
     static boolean fireRunFinished(Object runner) {
         if (finishNotified.add(runner.toString())) {
+            LOGGER.debug("runFinished: {}", runner);
             synchronized(runnerWatcherLoader) {
                 for (RunnerWatcher watcher : runnerWatcherLoader) {
                     watcher.runFinished(runner);
diff --git a/src/main/java/com/nordstrom/automation/junit/RunAnnouncer.java b/src/main/java/com/nordstrom/automation/junit/RunAnnouncer.java
@@ -9,13 +9,16 @@
 import org.junit.runner.notification.Failure;
 import org.junit.runner.notification.RunListener;
 import org.junit.runners.model.FrameworkMethod;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import com.google.common.base.Optional;
 
 public class RunAnnouncer extends RunListener {
     
     private static final ServiceLoader<RunWatcher> runWatcherLoader;
     private static final Map<Object, AtomicTest> RUNNER_TO_ATOMICTEST = new ConcurrentHashMap<>();
+    private static final Logger LOGGER = LoggerFactory.getLogger(RunAnnouncer.class);
     
     static {
         runWatcherLoader = ServiceLoader.load(RunWatcher.class);
@@ -26,6 +29,7 @@ public class RunAnnouncer extends RunListener {
      */
     @Override
     public void testStarted(Description description) throws Exception {
+        LOGGER.debug("testStarted: {}", description);
         AtomicTest atomicTest = getAtomicTestOf(description);
         synchronized(runWatcherLoader) {
             for (RunWatcher watcher : runWatcherLoader) {
@@ -39,6 +43,7 @@ public void testStarted(Description description) throws Exception {
      */
     @Override
     public void testFinished(Description description) throws Exception {
+        LOGGER.debug("testFinished: {}", description);
         AtomicTest atomicTest = getAtomicTestOf(description);
         synchronized(runWatcherLoader) {
             for (RunWatcher watcher : runWatcherLoader) {
@@ -52,6 +57,7 @@ public void testFinished(Description description) throws Exception {
      */
     @Override
     public void testFailure(Failure failure) throws Exception {
+        LOGGER.debug("testFailure: {}", failure);
         AtomicTest atomicTest = setTestFailure(failure);
         synchronized(runWatcherLoader) {
             for (RunWatcher watcher : runWatcherLoader) {
@@ -65,6 +71,7 @@ public void testFailure(Failure failure) throws Exception {
      */
     @Override
     public void testAssumptionFailure(Failure failure) {
+        LOGGER.debug("testAssumptionFailure: {}", failure);
         AtomicTest atomicTest = setTestFailure(failure);
         synchronized(runWatcherLoader) {
             for (RunWatcher watcher : runWatcherLoader) {
@@ -78,6 +85,7 @@ public void testAssumptionFailure(Failure failure) {
      */
     @Override
     public void testIgnored(Description description) throws Exception {
+        LOGGER.debug("testIgnored: {}", description);
         AtomicTest atomicTest = getAtomicTestOf(description);
         synchronized(runWatcherLoader) {
             for (RunWatcher watcher : runWatcherLoader) {
diff --git a/src/main/java/com/nordstrom/automation/junit/RunReflectiveCall.java b/src/main/java/com/nordstrom/automation/junit/RunReflectiveCall.java
@@ -13,6 +13,8 @@
 import org.junit.BeforeClass;
 import org.junit.Test;
 import org.junit.runners.model.FrameworkMethod;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import com.google.common.base.Function;
 import com.google.common.base.Optional;
@@ -32,6 +34,7 @@ public class RunReflectiveCall {
     private static final ServiceLoader<MethodWatcher> methodWatcherLoader;
     private static final ThreadLocal<ConcurrentMap<Integer, DepthGauge>> methodDepth;
     private static final Function<Integer, DepthGauge> newInstance;
+    private static final Logger LOGGER = LoggerFactory.getLogger(RunReflectiveCall.class);
     
     static {
         methodWatcherLoader = ServiceLoader.load(MethodWatcher.class);
@@ -161,6 +164,9 @@ private static boolean fireBeforeInvocation(Object runner, Object target, Framew
         if ((runner != null) && (method != null)) {
             DepthGauge depthGauge = LifecycleHooks.computeIfAbsent(methodDepth.get(), methodHash(runner, method), newInstance);
             if (0 == depthGauge.increaseDepth()) {
+                if (LOGGER.isDebugEnabled()) {
+                    LOGGER.debug("beforeInvocation: {}", LifecycleHooks.invoke(runner, "describeChild", method));
+                }
                 synchronized(methodWatcherLoader) {
                     for (MethodWatcher watcher : methodWatcherLoader) {
                         watcher.beforeInvocation(runner, target, method, params);
@@ -187,6 +193,9 @@ private static boolean fireAfterInvocation(Object runner, Object target, Framewo
         if ((runner != null) && (method != null)) {
             DepthGauge depthGauge = LifecycleHooks.computeIfAbsent(methodDepth.get(), methodHash(runner, method), newInstance);
             if (0 == depthGauge.decreaseDepth()) {
+                if (LOGGER.isDebugEnabled()) {
+                    LOGGER.debug("afterInvocation: {}", LifecycleHooks.invoke(runner, "describeChild", method));
+                }
                 synchronized(methodWatcherLoader) {
                     for (MethodWatcher watcher : methodWatcherLoader) {
                         watcher.afterInvocation(runner, target, method, thrown);
diff --git a/src/test/java/com/nordstrom/automation/junit/AutomaticRetryFailing.java b/src/test/java/com/nordstrom/automation/junit/AutomaticRetryFailing.java
@@ -9,7 +9,7 @@ public class AutomaticRetryFailing {
     @Test
     public void testFailed() {
         System.out.println("testFailed");
-        assertTrue(false);
+        assertTrue("testFailed", false);
     }
     
 }
diff --git a/src/test/java/com/nordstrom/automation/junit/AutomaticRetryNoRetry.java b/src/test/java/com/nordstrom/automation/junit/AutomaticRetryNoRetry.java
@@ -12,7 +12,7 @@ public class AutomaticRetryNoRetry {
     @NoRetry
     public void testNoRetry() {
         System.out.println("testNoRetry: " + count);
-        assertTrue(count++ > 0);
+        assertTrue("testNoRetry: " + count, count++ > 0);
     }
     
 }
diff --git a/src/test/java/com/nordstrom/automation/junit/AutomaticRetryPassOnRetry.java b/src/test/java/com/nordstrom/automation/junit/AutomaticRetryPassOnRetry.java
@@ -11,7 +11,7 @@ public class AutomaticRetryPassOnRetry {
     @Test
     public void testPassOnRetry() {
         System.out.println("testPassOnRetry: " + count);
-        assertTrue(count++ > 0);
+        assertTrue("testPassOnRetry: " + count, count++ > 0);
     }
     
 }

Original file line number	Diff line number	Diff line change
`@@ -107,4 +107,12 @@ public Throwable getThrowable() {`
`107`	`107`	`public boolean includes(FrameworkMethod method) {`
`108`	`108`	`return particles.contains(method);`
`109`	`109`	`}`
	`110`	`+`
	`111`	`+ /**`
	`112`	`+ * {@inheritDoc}`
	`113`	`+ */`
	`114`	`+ @Override`
	`115`	`+ public String toString() {`
	`116`	`+ return description.toString();`
	`117`	`+ }`
`110`	`118`	`}`
Original file line number	Diff line number	Diff line change
`@@ -9,7 +9,7 @@ public class AutomaticRetryFailing {`
`9`	`9`	`@Test`
`10`	`10`	`public void testFailed() {`
`11`	`11`	`System.out.println("testFailed");`
`12`		`- assertTrue(false);`
	`12`	`+ assertTrue("testFailed", false);`
`13`	`13`	`}`
`14`	`14`
`15`	`15`	`}`
Original file line number	Diff line number	Diff line change
`@@ -12,7 +12,7 @@ public class AutomaticRetryNoRetry {`
`12`	`12`	`@NoRetry`
`13`	`13`	`public void testNoRetry() {`
`14`	`14`	`System.out.println("testNoRetry: " + count);`
`15`		`- assertTrue(count++ > 0);`
	`15`	`+ assertTrue("testNoRetry: " + count, count++ > 0);`
`16`	`16`	`}`
`17`	`17`
`18`	`18`	`}`
Original file line number	Diff line number	Diff line change
`@@ -11,7 +11,7 @@ public class AutomaticRetryPassOnRetry {`
`11`	`11`	`@Test`
`12`	`12`	`public void testPassOnRetry() {`
`13`	`13`	`System.out.println("testPassOnRetry: " + count);`
`14`		`- assertTrue(count++ > 0);`
	`14`	`+ assertTrue("testPassOnRetry: " + count, count++ > 0);`
`15`	`15`	`}`
`16`	`16`
`17`	`17`	`}`