Add smoke test showing OOM due to recursive log capture on Wildfly (#…

…3796)

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/exporter/AgentLogExporter.java

@@ -15,7 +15,9 @@
 import com.microsoft.applicationinsights.agent.internal.telemetry.BatchItemProcessor;
 import com.microsoft.applicationinsights.agent.internal.telemetry.TelemetryClient;
 import com.microsoft.applicationinsights.agent.internal.telemetry.TelemetryObservers;
+import io.opentelemetry.api.logs.LoggerProvider;
 import io.opentelemetry.api.trace.SpanContext;
+import io.opentelemetry.javaagent.bootstrap.CallDepth;
 import io.opentelemetry.sdk.common.CompletableResultCode;
 import io.opentelemetry.sdk.logs.data.LogRecordData;
 import io.opentelemetry.sdk.logs.export.LogRecordExporter;
@@ -71,6 +73,23 @@ public void setSeverityThreshold(int severityThreshold) {
 
   @Override
   public CompletableResultCode export(Collection<LogRecordData> logs) {
+    // incrementing CallDepth for LoggerProvider causes the OpenTelemetry Java agent logging
+    // instrumentation to back off
+    //
+    // note: recursive log capture is only known to be an issue on Wildfly, because it redirects
+    // System.out back to a logging library which is itself instrumented by the Java agent
+    //
+    // see OutOfMemoryWithDebugLevelTest for repro that will fail without this code
+    CallDepth callDepth = CallDepth.forClass(LoggerProvider.class);
+    callDepth.getAndIncrement();
+    try {
+      return internalExport(logs);
+    } finally {
+      callDepth.decrementAndGet();
+    }
+  }
+
+  private CompletableResultCode internalExport(Collection<LogRecordData> logs) {
     if (TelemetryClient.getActive().getConnectionString() == null) {
       // Azure Functions consumption plan
       logger.debug("Instrumentation key is null or empty. Fail to export logs.");

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/telemetry/BatchItemProcessor.java

@@ -9,7 +9,9 @@
 import com.azure.monitor.opentelemetry.exporter.implementation.logging.OperationLogger;
 import com.azure.monitor.opentelemetry.exporter.implementation.models.TelemetryItem;
 import com.azure.monitor.opentelemetry.exporter.implementation.pipeline.TelemetryItemExporter;
+import io.opentelemetry.api.logs.LoggerProvider;
 import io.opentelemetry.internal.shaded.jctools.queues.MpscArrayQueue;
+import io.opentelemetry.javaagent.bootstrap.CallDepth;
 import io.opentelemetry.sdk.common.CompletableResultCode;
 import io.opentelemetry.sdk.internal.DaemonThreadFactory;
 import java.util.ArrayList;
@@ -169,6 +171,23 @@ private void addItem(TelemetryItem item) {
 
     @Override
     public void run() {
+      // incrementing CallDepth for LoggerProvider causes the OpenTelemetry Java agent logging
+      // instrumentation to back off
+      //
+      // note: recursive log capture is only known to be an issue on Wildfly, because it redirects
+      // System.out back to a logging library which is itself instrumented by the Java agent
+      //
+      // see OutOfMemoryWithDebugLevelTest for repro that will fail without this code
+      CallDepth callDepth = CallDepth.forClass(LoggerProvider.class);
+      callDepth.getAndIncrement();
+      try {
+        internalRun();
+      } finally {
+        callDepth.decrementAndGet();
+      }
+    }
+
+    public void internalRun() {
       updateNextExportTime();
 
       while (continueWork) {

settings.gradle.kts

@@ -128,6 +128,7 @@ hideFromDependabot(":smoke-tests:apps:OpenTelemetryApiLogBridge")
 hideFromDependabot(":smoke-tests:apps:OpenTelemetryMetric")
 hideFromDependabot(":smoke-tests:apps:OtelResourceCustomMetric")
 hideFromDependabot(":smoke-tests:apps:OtlpMetrics")
+hideFromDependabot(":smoke-tests:apps:OutOfMemoryWithDebugLevel")
 hideFromDependabot(":smoke-tests:apps:PreAggMetricsWithRoleNameOverridesAndSampling")
 hideFromDependabot(":smoke-tests:apps:PreferForwardedUrlScheme")
 hideFromDependabot(":smoke-tests:apps:RateLimitedSampling")

smoke-tests/apps/OutOfMemoryWithDebugLevel/build.gradle.kts

@@ -0,0 +1,3 @@
+plugins {
+  id("ai.smoke-test-war")
+}

smoke-tests/apps/OutOfMemoryWithDebugLevel/src/main/java/com/microsoft/applicationinsights/smoketestapp/HealthCheckServlet.java

@@ -0,0 +1,18 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package com.microsoft.applicationinsights.smoketestapp;
+
+import java.io.IOException;
+import javax.servlet.annotation.WebServlet;
+import javax.servlet.http.HttpServlet;
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+
+// this is used by the test infra in order to know when it's ok to start running the tests
+@WebServlet("")
+public class HealthCheckServlet extends HttpServlet {
+
+  @Override
+  protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws IOException {}
+}

smoke-tests/apps/OutOfMemoryWithDebugLevel/src/main/java/com/microsoft/applicationinsights/smoketestapp/OutOfMemoryWithDebugLevelServlet.java

@@ -0,0 +1,25 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package com.microsoft.applicationinsights.smoketestapp;
+
+import java.io.IOException;
+import java.util.logging.Logger;
+import javax.servlet.ServletException;
+import javax.servlet.annotation.WebServlet;
+import javax.servlet.http.HttpServlet;
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+
+@WebServlet("/*")
+public class OutOfMemoryWithDebugLevelServlet extends HttpServlet {
+
+  private static final Logger logger = Logger.getLogger("smoketestapp");
+
+  @Override
+  protected void doGet(HttpServletRequest req, HttpServletResponse resp)
+      throws ServletException, IOException {
+
+    logger.info("hello");
+  }
+}

smoke-tests/apps/OutOfMemoryWithDebugLevel/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/OutOfMemoryWithDebugLevelTest.java

@@ -0,0 +1,72 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package com.microsoft.applicationinsights.smoketest;
+
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_11;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_11_OPENJ9;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_17;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_21;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_8;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.TOMCAT_8_JAVA_8_OPENJ9;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.WILDFLY_13_JAVA_8;
+import static com.microsoft.applicationinsights.smoketest.EnvironmentValue.WILDFLY_13_JAVA_8_OPENJ9;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+import static java.util.concurrent.TimeUnit.SECONDS;
+import static org.assertj.core.api.Assertions.assertThat;
+
+import com.microsoft.applicationinsights.smoketest.schemav2.MessageData;
+import java.util.List;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+
+@UseAgent
+abstract class OutOfMemoryWithDebugLevelTest {
+
+  @RegisterExtension
+  static final SmokeTestExtension testing =
+      SmokeTestExtension.builder()
+          .setSelfDiagnosticsLevel(
+              "debug") // intentionally running with selfDiagnosticLevel "debug"
+          .build();
+
+  private static final int COUNT = 100;
+
+  @Test
+  @TargetUri(value = "/test", callCount = COUNT)
+  void test() throws Exception {
+    long start = System.nanoTime();
+    while (testing.mockedIngestion.getCountForType("RequestData") < COUNT
+        && NANOSECONDS.toSeconds(System.nanoTime() - start) < 10) {}
+    // wait ten more seconds before checking that we didn't receive too many
+    Thread.sleep(SECONDS.toMillis(10));
+
+    List<MessageData> messages = testing.mockedIngestion.getMessageDataInRequest(COUNT);
+
+    assertThat(messages).hasSize(COUNT);
+  }
+
+  @Environment(TOMCAT_8_JAVA_8)
+  static class Tomcat8Java8Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(TOMCAT_8_JAVA_8_OPENJ9)
+  static class Tomcat8Java8OpenJ9Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(TOMCAT_8_JAVA_11)
+  static class Tomcat8Java11Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(TOMCAT_8_JAVA_11_OPENJ9)
+  static class Tomcat8Java11OpenJ9Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(TOMCAT_8_JAVA_17)
+  static class Tomcat8Java17Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(TOMCAT_8_JAVA_21)
+  static class Tomcat8Java21Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(WILDFLY_13_JAVA_8)
+  static class Wildfly13Java8Test extends OutOfMemoryWithDebugLevelTest {}
+
+  @Environment(WILDFLY_13_JAVA_8_OPENJ9)
+  static class Wildfly13Java8OpenJ9Test extends OutOfMemoryWithDebugLevelTest {}
+}

smoke-tests/framework/src/main/java/com/microsoft/applicationinsights/smoketest/fakeingestion/MockedAppInsightsIngestionServer.java

@@ -103,13 +103,12 @@ public <T extends Domain> List<T> getTelemetryDataByTypeInRequest(String type) {
 
   public <T extends Domain> List<T> getMessageDataInRequest(int numItems)
       throws ExecutionException, InterruptedException, TimeoutException {
-    List<Envelope> items = waitForItems("MessageData", numItems);
+    List<Envelope> items =
+        waitForItems("MessageData", e -> e.getTags().containsKey("ai.operation.id"), numItems);
     List<T> dataItems = new ArrayList<>();
     for (Envelope e : items) {
-      if (e.getTags().containsKey("ai.operation.id")) {
-        Data<T> dt = (Data<T>) e.getData();
-        dataItems.add(dt.getBaseData());
-      }
+      Data<T> dt = (Data<T>) e.getData();
+      dataItems.add(dt.getBaseData());
     }
     return dataItems;
   }