From cb9168d46a0e21cc3dedf192b18c951c98c644f5 Mon Sep 17 00:00:00 2001
From: tomas mccandless <tomas.mccandless@workday.com>
Date: Mon, 9 Oct 2023 17:24:36 -0700
Subject: [PATCH] spike filter logging

---
 .../workday/warp/arbiters/ArbiterLike.scala   | 23 +++++++++++++++----
 .../warp/arbiters/ResponseTimeArbiter.scala   |  5 ++--
 .../arbiters/ResponseTimeArbiterSpec.scala    | 10 ++++----
 3 files changed, 28 insertions(+), 10 deletions(-)

diff --git a/warp-core/src/main/scala/com/workday/warp/arbiters/ArbiterLike.scala b/warp-core/src/main/scala/com/workday/warp/arbiters/ArbiterLike.scala
index 4e4d78bf..a1833f2e 100644
--- a/warp-core/src/main/scala/com/workday/warp/arbiters/ArbiterLike.scala
+++ b/warp-core/src/main/scala/com/workday/warp/arbiters/ArbiterLike.scala
@@ -52,13 +52,21 @@ trait ArbiterLike extends PersistenceAware with CanReadHistory {
     }
 
     if (spikeFilterEnabled) {
+      logger.trace(s"voting, spike filter is enabled")
       // check the last executions to see if they have a failure tag that matches
       val priorExecutionHasFailureTag: Boolean = priorExecutionsFailed(testExecution, tagName, alertOnNth)
-      if (priorExecutionHasFailureTag) maybeFailure
+      if (priorExecutionHasFailureTag) {
+        logger.trace(s"sufficient prior consecutive failures, vote=${maybeFailure.nonEmpty}")
+        maybeFailure
+      }
       // no failure tag on the last execution, (first time failure), don't vote as a failure
-      else None
+      else {
+        logger.trace(s"last executions did not fail, vote=false")
+        None
+      }
     }
     else {
+      logger.trace(s"spike filter is disabled, vote=${maybeFailure.nonEmpty}")
       maybeFailure
     }
   }
@@ -91,9 +99,16 @@ trait ArbiterLike extends PersistenceAware with CanReadHistory {
     var settings: (Boolean, Int) = this.persistenceUtils.getSpikeFilterSettings(idTestDefinition)
       .map(setting => (setting.spikeFilterEnabled, setting.alertOnNth))
       .getOrElse((false, 1))
+    logger.trace(s"base spike filter settings: $settings")
     // allow individual overrides from properties if they are present
-    Option(WARP_ARBITER_SPIKE_FILTER_ENABLED.value).foreach(f => settings = settings.copy(_1 = f.toBoolean))
-    Option(WARP_ARBITER_SPIKE_FILTER_ALERT_ON_NTH.value).foreach(f => settings = settings.copy(_2 = f.toInt))
+    Option(WARP_ARBITER_SPIKE_FILTER_ENABLED.value).foreach { f =>
+      logger.trace(s"spike filter enabled override: $f")
+      settings = settings.copy(_1 = f.toBoolean)
+    }
+    Option(WARP_ARBITER_SPIKE_FILTER_ALERT_ON_NTH.value).foreach { f =>
+      logger.trace(s"spike filter alert on nth override: $f")
+      settings = settings.copy(_2 = f.toInt)
+    }
     settings
   }
 
diff --git a/warp-core/src/main/scala/com/workday/warp/arbiters/ResponseTimeArbiter.scala b/warp-core/src/main/scala/com/workday/warp/arbiters/ResponseTimeArbiter.scala
index 9ef0b08e..1c81417f 100644
--- a/warp-core/src/main/scala/com/workday/warp/arbiters/ResponseTimeArbiter.scala
+++ b/warp-core/src/main/scala/com/workday/warp/arbiters/ResponseTimeArbiter.scala
@@ -35,8 +35,9 @@ class ResponseTimeArbiter extends ArbiterLike with CorePersistenceAware {
 
     if (threshold.isPositive && responseTime > threshold) {
       Option(new RequirementViolationException(
-        s"$testId violated response time requirement: expected ${threshold.humanReadable} (${threshold.toMillis} ms)" +
-        s", but measured ${responseTime.humanReadable} (${responseTime.toMillis} ms)"
+        s"$testId violated response time requirement (imposed by ${this.getClass.getCanonicalName}): " +
+          s"expected ${threshold.humanReadable} (${threshold.toMillis} ms), " +
+        s"but measured ${responseTime.humanReadable} (${responseTime.toMillis} ms)"
       ))
     }
     else {
diff --git a/warp-core/src/test/scala/com/workday/warp/arbiters/ResponseTimeArbiterSpec.scala b/warp-core/src/test/scala/com/workday/warp/arbiters/ResponseTimeArbiterSpec.scala
index 1a9aea29..c49dbd4c 100644
--- a/warp-core/src/test/scala/com/workday/warp/arbiters/ResponseTimeArbiterSpec.scala
+++ b/warp-core/src/test/scala/com/workday/warp/arbiters/ResponseTimeArbiterSpec.scala
@@ -52,8 +52,9 @@ class ResponseTimeArbiterSpec extends WarpJUnitSpec with CorePersistenceAware {
 
     val vote: Option[Throwable] = arbiter.vote(ballot, testExecution)
     vote should not be empty
-    vote.get.getMessage should be (s"$testId violated response time requirement: expected 0:00:03.000 (3000 ms), but " +
-      "measured 0:00:04.000 (4000 ms)")
+    vote.get.getMessage should be (s"$testId violated response time requirement" +
+      " (imposed by com.workday.warp.arbiters.ResponseTimeArbiter):" +
+      " expected 0:00:03.000 (3000 ms), but measured 0:00:04.000 (4000 ms)")
   }
 
 
@@ -68,7 +69,8 @@ class ResponseTimeArbiterSpec extends WarpJUnitSpec with CorePersistenceAware {
 
     val vote: Option[Throwable] = arbiter.vote(ballot, testExecution)
     vote should not be empty
-    vote.get.getMessage should be (s"$testId violated response time requirement: expected 0:00:03.000 (3000 ms), but " +
-      "measured 0:00:04.000 (4000 ms)")
+    vote.get.getMessage should be (s"$testId violated response time requirement" +
+      " (imposed by com.workday.warp.arbiters.ResponseTimeArbiter):" +
+      " expected 0:00:03.000 (3000 ms), but measured 0:00:04.000 (4000 ms)")
   }
 }