Fix azure functions diagnostic logging (#2433)

* Fix azure functions diagnostic logging

* Spotless

* More

* Fix initialization sequence

* Fix another NPE

* Spotless

* Logging

* More

* Fix

* logger

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/configuration/ConfigurationBuilder.java

@@ -773,9 +773,7 @@ static String getJsonEncodingExceptionMessage(@Nullable String message, String l
     if (message != null && !message.isEmpty()) {
       return message;
     }
-    return "Application Insights Java agent's configuration "
-        + location
-        + " has a malformed JSON\n";
+    return "The configuration " + location + " contains malformed JSON\n";
   }
 
   public static Configuration loadJsonConfigFile(Path configPath) throws IOException {

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/httpclient/LazyHttpClient.java

@@ -61,6 +61,7 @@ public class LazyHttpClient implements HttpClient {
   private static final HttpClient INSTANCE = new LazyHttpClient();
 
   public static final CountDownLatch safeToInitLatch = new CountDownLatch(1);
+
   public static volatile String proxyHost;
   public static volatile Integer proxyPortNumber;
   public static volatile String proxyUsername;

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/AfterAgentListener.java

@@ -45,7 +45,7 @@ public void afterAgent(AutoConfiguredOpenTelemetrySdk autoConfiguredOpenTelemetr
     if (!"java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
       // Delay registering and starting AppId retrieval until the connection string becomes
       // available for Linux Consumption Plan.
-      appIdSupplier.startAppIdRetrieval();
+      appIdSupplier.updateAppId();
     }
 
     LazyHttpClient.safeToInitLatch.countDown();

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/AppIdSupplier.java

@@ -60,19 +60,29 @@ public class AppIdSupplier implements AiAppId.Supplier {
   private GetAppIdTask task;
   private final Object taskLock = new Object();
 
-  private final ConnectionString connectionString;
+  private final TelemetryClient telemetryClient;
 
   @Nullable private volatile String appId;
 
   // TODO (kryalama) do we still need this AtomicBoolean, or can we use throttling built in to the
   //  warningLogger?
   private static final AtomicBoolean friendlyExceptionThrown = new AtomicBoolean();
 
-  public AppIdSupplier(ConnectionString connectionString) {
-    this.connectionString = connectionString;
+  public AppIdSupplier(TelemetryClient telemetryClient) {
+    this.telemetryClient = telemetryClient;
   }
 
-  public void startAppIdRetrieval() {
+  public void updateAppId() {
+    ConnectionString connectionString = telemetryClient.getConnectionString();
+    if (connectionString == null) {
+      appId = null;
+      if (task != null) {
+        // in case prior task is still running (can be called multiple times from JsonConfigPolling)
+        task.cancelled = true;
+      }
+      return;
+    }
+
     GetAppIdTask newTask;
     try {
       newTask = new GetAppIdTask(getAppIdUrl(connectionString));
@@ -102,15 +112,8 @@ static URL getAppIdUrl(ConnectionString connectionString) throws MalformedURLExc
 
   @Override
   public String get() {
-    String instrumentationKey = TelemetryClient.getActive().getInstrumentationKey();
-    if (instrumentationKey == null) {
-      // this is possible in Azure Function consumption plan prior to "specialization"
-      return "";
-    }
-
     // it's possible the appId returned is null (e.g. async task is still pending or has failed). In
-    // this case, just
-    // return and let the next request resolve the ikey.
+    // this case, just return and let the next request resolve the ikey.
     if (appId == null) {
       logger.debug("appId has not been retrieved yet (e.g. task may be pending or failed)");
       return "";

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/AzureFunctionsInitializer.java

@@ -22,9 +22,8 @@
 package com.microsoft.applicationinsights.agent.internal.init;
 
 import ch.qos.logback.classic.LoggerContext;
-import com.azure.monitor.opentelemetry.exporter.implementation.configuration.ConnectionString;
-import com.azure.monitor.opentelemetry.exporter.implementation.configuration.StatsbeatConnectionString;
 import com.azure.monitor.opentelemetry.exporter.implementation.utils.Strings;
+import com.microsoft.applicationinsights.agent.bootstrap.diagnostics.DiagnosticsHelper;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration;
 import com.microsoft.applicationinsights.agent.internal.exporter.AgentLogExporter;
 import com.microsoft.applicationinsights.agent.internal.legacyheaders.DelegatingPropagator;
@@ -42,11 +41,11 @@
 
 public class AzureFunctionsInitializer implements Runnable {
 
-  private static final Logger startupLogger =
-      LoggerFactory.getLogger("com.microsoft.applicationinsights.agent");
-
   private static final Logger logger = LoggerFactory.getLogger(AzureFunctionsInitializer.class);
 
+  private static final Logger diagnosticLogger =
+      LoggerFactory.getLogger(DiagnosticsHelper.DIAGNOSTICS_LOGGER_NAME);
+
   private final TelemetryClient telemetryClient;
   private final AgentLogExporter agentLogExporter;
   private final AppIdSupplier appIdSupplier;
@@ -63,10 +62,25 @@ public AzureFunctionsInitializer(
   @Override
   public void run() {
     if (!isAgentEnabled()) {
-      disableBytecodeInstrumentation();
+      try {
+        disableBytecodeInstrumentation();
+        diagnosticLogger.info("Application Insights Java Agent disabled");
+      } catch (Throwable t) {
+        diagnosticLogger.error(
+            "Application Insights Java Agent disablement failed: " + t.getMessage(), t);
+      }
       return;
     }
+    try {
+      initialize();
+      diagnosticLogger.info("Application Insights Java Agent specialized successfully");
+    } catch (Throwable t) {
+      diagnosticLogger.error(
+          "Application Insights Java Agent specialization failed: " + t.getMessage(), t);
+    }
+  }
 
+  private void initialize() {
     String selfDiagnosticsLevel = System.getenv("APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL");
     String connectionString = System.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING");
     String instrumentationKey = System.getenv("APPINSIGHTS_INSTRUMENTATIONKEY");
@@ -86,11 +100,10 @@ public void run() {
     setConnectionString(connectionString, instrumentationKey);
     setWebsiteSiteName(websiteSiteName);
     setSelfDiagnosticsLevel(selfDiagnosticsLevel);
-    agentLogExporter.setThreshold(
-        Configuration.LoggingInstrumentation.getSeverity(instrumentationLoggingLevel));
-
-    startupLogger.info(
-        "ApplicationInsights Java Agent specialization complete for Azure Functions placeholder");
+    if (instrumentationLoggingLevel != null) {
+      agentLogExporter.setThreshold(
+          Configuration.LoggingInstrumentation.getSeverity(instrumentationLoggingLevel));
+    }
   }
 
   private static void disableBytecodeInstrumentation() {
@@ -120,18 +133,13 @@ void setConnectionString(@Nullable String connectionString, @Nullable String ins
   }
 
   private void setValue(String value) {
-    ConnectionString connectionString = ConnectionString.parse(value);
-    telemetryClient.updateConnectionString(connectionString);
-    telemetryClient.updateStatsbeatConnectionString(
-        StatsbeatConnectionString.create(connectionString, null, null));
+    telemetryClient.updateConnectionStrings(value, null, null);
+    appIdSupplier.updateAppId();
 
     // now that we know the user has opted in to tracing, we need to init the propagator and sampler
     DelegatingPropagator.getInstance().setUpStandardDelegate(Collections.emptyList(), false);
     // TODO handle APPLICATIONINSIGHTS_SAMPLING_PERCENTAGE
     DelegatingSampler.getInstance().setAlwaysOnDelegate();
-
-    // start app id retrieval after the connection string becomes available.
-    appIdSupplier.startAppIdRetrieval();
   }
 
   void setWebsiteSiteName(@Nullable String websiteSiteName) {

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/FirstEntryPoint.java

@@ -114,7 +114,7 @@ public void init() {
   @Override
   public void onStartupSuccess() {
     startupLogger.info(
-        "ApplicationInsights Java Agent {} started successfully (PID {})",
+        "Application Insights Java Agent {} started successfully (PID {})",
         agentVersion,
         new PidFinder().getValue());
     startupLogger.info(
@@ -126,7 +126,7 @@ public void onStartupSuccess() {
     MDC.put(DiagnosticsHelper.MDC_PROP_OPERATION, "Startup");
     try (MDC.MDCCloseable ignored = INITIALIZATION_SUCCESS.makeActive()) {
       LoggerFactory.getLogger(DiagnosticsHelper.DIAGNOSTICS_LOGGER_NAME)
-          .info("Application Insights Codeless Agent {} Attach Successful", agentVersion);
+          .info("Application Insights Java Agent {} started successfully", agentVersion);
     } finally {
       MDC.remove(DiagnosticsHelper.MDC_PROP_OPERATION);
     }
@@ -138,9 +138,9 @@ public void onStartupSuccess() {
   public void onStartupFailure(Throwable throwable) {
     FriendlyException friendlyException = getFriendlyException(throwable);
     String banner =
-        "ApplicationInsights Java Agent "
+        "Application Insights Java Agent "
             + agentVersion
-            + " failed to start (PID "
+            + " startup failed (PID "
             + new PidFinder().getValue()
             + ")";
 

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/RpConfigurationPolling.java

@@ -23,9 +23,6 @@
 
 import static java.util.concurrent.TimeUnit.SECONDS;
 
-import com.azure.monitor.opentelemetry.exporter.implementation.configuration.ConnectionString;
-import com.azure.monitor.opentelemetry.exporter.implementation.configuration.StatsbeatConnectionString;
-import com.azure.monitor.opentelemetry.exporter.implementation.utils.Strings;
 import com.azure.monitor.opentelemetry.exporter.implementation.utils.ThreadPoolUtils;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration;
 import com.microsoft.applicationinsights.agent.internal.configuration.ConfigurationBuilder;
@@ -103,18 +100,11 @@ public void run() {
         if (!newRpConfiguration.connectionString.equals(rpConfiguration.connectionString)) {
           logger.debug(
               "Connection string from the JSON config file is overriding the previously configured connection string.");
-          ConnectionString connectionString =
-              ConnectionString.parse(newRpConfiguration.connectionString);
-          telemetryClient.updateConnectionString(connectionString);
-          telemetryClient.updateStatsbeatConnectionString(
-              StatsbeatConnectionString.create(
-                  connectionString,
-                  configuration.internal.statsbeat.instrumentationKey,
-                  configuration.internal.statsbeat.endpoint));
-
-          if (!Strings.isNullOrEmpty(newRpConfiguration.connectionString)) {
-            appIdSupplier.startAppIdRetrieval();
-          }
+          telemetryClient.updateConnectionStrings(
+              newRpConfiguration.connectionString,
+              configuration.internal.statsbeat.instrumentationKey,
+              configuration.internal.statsbeat.endpoint);
+          appIdSupplier.updateAppId();
         }
 
         if (newRpConfiguration.sampling.percentage != rpConfiguration.sampling.percentage) {

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/SecondEntryPoint.java

@@ -174,7 +174,7 @@ public void customize(AutoConfigurationCustomizer autoConfiguration) {
     BytecodeUtilImpl.samplingPercentage = config.sampling.percentage;
     BytecodeUtilImpl.featureStatsbeat = statsbeatModule.getFeatureStatsbeat();
 
-    AppIdSupplier appIdSupplier = new AppIdSupplier(telemetryClient.getConnectionString());
+    AppIdSupplier appIdSupplier = new AppIdSupplier(telemetryClient);
     AiAppId.setSupplier(appIdSupplier);
 
     if (config.preview.profiler.enabled) {

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

@@ -44,6 +44,7 @@
 import com.azure.monitor.opentelemetry.exporter.implementation.pipeline.TelemetryPipeline;
 import com.azure.monitor.opentelemetry.exporter.implementation.pipeline.TelemetryPipelineListener;
 import com.azure.monitor.opentelemetry.exporter.implementation.quickpulse.QuickPulse;
+import com.azure.monitor.opentelemetry.exporter.implementation.utils.Strings;
 import com.azure.monitor.opentelemetry.exporter.implementation.utils.TempDirs;
 import com.microsoft.applicationinsights.agent.internal.common.PropertyHelper;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration;
@@ -409,13 +410,21 @@ public String getRoleInstance() {
   }
 
   // used during Azure Functions placeholder specialization
-  public void updateConnectionString(ConnectionString connectionString) {
-    this.connectionString = connectionString;
-  }
-
-  // used during Azure Functions placeholder specialization
-  public void updateStatsbeatConnectionString(StatsbeatConnectionString statsbeatConnectionString) {
-    this.statsbeatConnectionString = statsbeatConnectionString;
+  // and also used by Azure Spring Apps dynamic configuration
+  public void updateConnectionStrings(
+      @Nullable String connectionString,
+      @Nullable String statsbeatInstrumentationKey,
+      @Nullable String statsbeatEndpoint) {
+
+    if (Strings.isNullOrEmpty(connectionString)) {
+      this.connectionString = null;
+      this.statsbeatConnectionString = null;
+    } else {
+      this.connectionString = ConnectionString.parse(connectionString);
+      this.statsbeatConnectionString =
+          StatsbeatConnectionString.create(
+              this.connectionString, statsbeatInstrumentationKey, statsbeatEndpoint);
+    }
   }
 
   @Nullable
@@ -510,7 +519,11 @@ public Builder setConnectionStrings(
         @Nullable String connectionString,
         @Nullable String statsbeatInstrumentationKey,
         @Nullable String statsbeatEndpoint) {
-      if (connectionString != null) {
+
+      if (Strings.isNullOrEmpty(connectionString)) {
+        this.connectionString = null;
+        this.statsbeatConnectionString = null;
+      } else {
         this.connectionString = ConnectionString.parse(connectionString);
         this.statsbeatConnectionString =
             StatsbeatConnectionString.create(

agent/agent-tooling/src/test/java/com/microsoft/applicationinsights/agent/internal/configuration/ConfigurationBuilderTest.java

@@ -121,12 +121,9 @@ void testGetJsonEncodingExceptionMessage() {
         ConfigurationBuilder.getJsonEncodingExceptionMessage(null, "file path/to/file");
     String pathEmpty =
         ConfigurationBuilder.getJsonEncodingExceptionMessage("", "file path/to/file");
-    assertThat(pathNull)
-        .isEqualTo(
-            "Application Insights Java agent's configuration file path/to/file has a malformed JSON\n");
+    assertThat(pathNull).isEqualTo("The configuration file path/to/file contains malformed JSON\n");
     assertThat(pathEmpty)
-        .isEqualTo(
-            "Application Insights Java agent's configuration file path/to/file has a malformed JSON\n");
+        .isEqualTo("The configuration file path/to/file contains malformed JSON\n");
   }
 
   @Test

agent/agent-tooling/src/test/java/com/microsoft/applicationinsights/agent/internal/init/AzureFunctionsInitializerTestHolder.java

@@ -23,7 +23,6 @@
 
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.mockito.ArgumentMatchers.any;
-import static org.mockito.ArgumentMatchers.argThat;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
 import static org.mockito.Mockito.verify;
@@ -88,7 +87,7 @@ void disableLazySetWithLazySetOptInOffConnectionStringNullInstrumentationKeyNull
     lazyConfigurationAccessor.setConnectionString(null, null);
 
     // then
-    verify(telemetryClient, never()).updateConnectionString(any());
+    verify(telemetryClient, never()).updateConnectionStrings(any(), any(), any());
   }
 
   @Test
@@ -108,9 +107,7 @@ void disableLazySetWithLazySetOptInOffConnectionStringNotNullInstrumentationKeyN
     lazyConfigurationAccessor.setConnectionString(CONNECTION_STRING, null);
 
     // then
-    verify(telemetryClient)
-        .updateConnectionString(
-            argThat(cs -> cs.getInstrumentationKey().equals(INSTRUMENTATION_KEY)));
+    verify(telemetryClient).updateConnectionStrings(CONNECTION_STRING, null, null);
 
     // when
     lazyConfigurationAccessor.setWebsiteSiteName(WEBSITE_SITE_NAME);
@@ -136,9 +133,7 @@ void enableLazySetWithLazySetOptInOffConnectionStringNullInstrumentationKeyNotNu
     lazyConfigurationAccessor.setConnectionString(null, INSTRUMENTATION_KEY);
 
     // then
-    verify(telemetryClient)
-        .updateConnectionString(
-            argThat(cs -> cs.getInstrumentationKey().equals(INSTRUMENTATION_KEY)));
+    verify(telemetryClient).updateConnectionStrings(CONNECTION_STRING, null, null);
   }
 
   @Test
@@ -176,7 +171,7 @@ void disableLazySetWithLazySetOptInOnConnectionStringNullAndInstrumentationKeyNu
     lazyConfigurationAccessor.setConnectionString(null, null);
 
     // then
-    verify(telemetryClient, never()).updateConnectionString(any());
+    verify(telemetryClient, never()).updateConnectionStrings(any(), any(), any());
   }
 
   @Test
@@ -196,9 +191,7 @@ void enableLazySetWithLazySetOptInOnConnectionStringNotNullInstrumentationKeyNul
     lazyConfigurationAccessor.setConnectionString(CONNECTION_STRING, null);
 
     // then
-    verify(telemetryClient)
-        .updateConnectionString(
-            argThat(cs -> cs.getInstrumentationKey().equals(INSTRUMENTATION_KEY)));
+    verify(telemetryClient).updateConnectionStrings(CONNECTION_STRING, null, null);
   }
 
   @Test
@@ -218,8 +211,6 @@ void enableLazySetWithLazySetOptInOnConnectionStringNullInstrumentationKeyNotNul
     lazyConfigurationAccessor.setConnectionString(null, INSTRUMENTATION_KEY);
 
     // then
-    verify(telemetryClient)
-        .updateConnectionString(
-            argThat(cs -> cs.getInstrumentationKey().equals(INSTRUMENTATION_KEY)));
+    verify(telemetryClient).updateConnectionStrings(CONNECTION_STRING, null, null);
   }
 }