Enhance logging of negative amount in AbstractTimer.record() by printing stack trace (#6530)

In order to help identify the code that is resulting in calling record with a negative amount, include the stacktrace in the log.
Nothing will be logged after the first time if debug level logging is not enabled. We can avoid the cost of instantiating the exception in that case.

---------

Signed-off-by: thonra <[email protected]>
Co-authored-by: Tommy Ludwig <[email protected]>

Author: thonra

micrometer-commons/src/main/java/io/micrometer/common/util/internal/logging/WarnThenDebugLogger.java

@@ -46,6 +46,15 @@ public WarnThenDebugLogger(String name) {
         this.logger = InternalLoggerFactory.getInstance(name);
     }
 
+    /**
+     * This may be useful to have different behavior before/after logging once.
+     * @return whether the warn-level log has been made or not
+     * @since 1.16.0
+     */
+    public boolean isWarnLogged() {
+        return warnLogged.get();
+    }
+
     public void log(String message, @Nullable Throwable ex) {
         if (this.warnLogged.compareAndSet(false, true)) {
             log(InternalLogLevel.WARN, getWarnMessage(message), ex);

micrometer-core/src/main/java/io/micrometer/core/instrument/AbstractTimer.java

@@ -15,6 +15,8 @@
  */
 package io.micrometer.core.instrument;
 
+import io.micrometer.common.util.internal.logging.InternalLogger;
+import io.micrometer.common.util.internal.logging.InternalLoggerFactory;
 import io.micrometer.common.util.internal.logging.WarnThenDebugLogger;
 import io.micrometer.core.instrument.distribution.*;
 import io.micrometer.core.instrument.distribution.pause.ClockDriftPauseDetector;
@@ -37,7 +39,9 @@
 
 public abstract class AbstractTimer extends AbstractMeter implements Timer {
 
-    private static final WarnThenDebugLogger log = new WarnThenDebugLogger(AbstractTimer.class);
+    private static final WarnThenDebugLogger warnThenDebugLogger = new WarnThenDebugLogger(AbstractTimer.class);
+
+    private static final InternalLogger LOGGER = InternalLoggerFactory.getInstance(AbstractTimer.class);
 
     private static final Map<PauseDetector, Object> pauseDetectorCache = new ConcurrentHashMap<>();
 
@@ -264,7 +268,10 @@ public final void record(long amount, TimeUnit unit) {
             }
         }
         else {
-            log.log(() -> "'amount' should not be negative but was: " + amount);
+            if (!warnThenDebugLogger.isWarnLogged() || LOGGER.isDebugEnabled()) {
+                warnThenDebugLogger.log(() -> "'amount' should not be negative but was: " + amount,
+                        new IllegalArgumentException("Timer measurements cannot be negative"));
+            }
         }
     }