adding logging

Author: mhlidd

dd-java-agent/instrumentation/jms/javax-jms-1.1/src/main/java/datadog/trace/instrumentation/jms/JMSMessageConsumerInstrumentation.java

@@ -39,10 +39,14 @@
 import net.bytebuddy.asm.Advice;
 import net.bytebuddy.description.type.TypeDescription;
 import net.bytebuddy.matcher.ElementMatcher;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public final class JMSMessageConsumerInstrumentation
     implements Instrumenter.ForTypeHierarchy, Instrumenter.HasMethodAdvice {
   private final String namespace;
+  private static final Logger log =
+      LoggerFactory.getLogger(JMSMessageConsumerInstrumentation.class);
 
   public JMSMessageConsumerInstrumentation(String namespace) {
     this.namespace = namespace;
@@ -164,6 +168,7 @@ public static void afterReceive(
       CONSUMER_DECORATE.onError(span, throwable);
 
       activateNext(span); // scope is left open until next message or it times out
+      log.debug("Expecting the following `ITERATION` span to be finished {}", span);
 
       SessionState sessionState = consumerState.getSessionState();
       if (sessionState.isClientAcknowledge()) {

dd-trace-core/src/main/java/datadog/trace/core/scopemanager/ContinuableScopeManager.java

@@ -1,6 +1,7 @@
 package datadog.trace.core.scopemanager;
 
 import static datadog.trace.api.ConfigDefaults.DEFAULT_ASYNC_PROPAGATING;
+import static datadog.trace.api.telemetry.LogCollector.SEND_TELEMETRY;
 import static datadog.trace.bootstrap.instrumentation.api.AgentTracer.noopScope;
 import static datadog.trace.bootstrap.instrumentation.api.AgentTracer.noopSpan;
 import static datadog.trace.core.scopemanager.ContinuableScope.CONTEXT;
@@ -238,15 +239,24 @@ public void closePrevious(final boolean finishSpan) {
 
     // close any immediately previous iteration scope
     final ContinuableScope top = scopeStack.top;
-    if (top != null && top.source() == ITERATION) {
-      if (iterationKeepAlive > 0) { // skip depth check because cancelling is cheap
-        cancelRootIterationScopeCleanup(scopeStack, top);
-      }
-      top.close();
-      scopeStack.cleanup();
-      AgentSpan span = top.span();
-      if (finishSpan && span != null) {
-        span.finishWithEndToEnd();
+    if (top != null) {
+      if (top.source() == ITERATION) {
+        if (iterationKeepAlive > 0) { // skip depth check because cancelling is cheap
+          cancelRootIterationScopeCleanup(scopeStack, top);
+        }
+        top.close();
+        scopeStack.cleanup();
+        AgentSpan span = top.span();
+        if (finishSpan && span != null) {
+          span.finishWithEndToEnd();
+        }
+      } else {
+        log.debug(
+            SEND_TELEMETRY,
+            "Scope found at top of stack has source {} when we expect {}. Current span at the top of the stack {}.",
+            top,
+            ITERATION,
+            top.span());
       }
     }
   }