Better Azure Functions consumption plan behavior (#2397)

* Better Azure Functions consumption plan behavior

* Spotless

* Fix

* Fixes

* Lazy endpoints

* simplify

* Logging

* Update log location

Author: trask

agent/agent-bootstrap/src/main/java/com/microsoft/applicationinsights/agent/bootstrap/AiLazyConfiguration.java renamed to agent/agent-bootstrap/src/main/java/com/microsoft/applicationinsights/agent/bootstrap/AzureFunctions.java

@@ -21,23 +21,31 @@
 
 package com.microsoft.applicationinsights.agent.bootstrap;
 
-public class AiLazyConfiguration {
+import java.util.function.Supplier;
+import javax.annotation.Nullable;
 
-  private static volatile Accessor accessor;
+public class AzureFunctions {
 
-  public static void setAccessor(Accessor accessor) {
-    AiLazyConfiguration.accessor = accessor;
+  private static volatile Supplier<Boolean> hasConnectionString;
+  @Nullable private static volatile Runnable configure;
+
+  public static void setup(Supplier<Boolean> hasConnectionString, Runnable initializer) {
+    AzureFunctions.hasConnectionString = hasConnectionString;
+    AzureFunctions.configure = initializer;
   }
 
-  public static void lazyLoad() {
-    if (accessor != null) {
-      accessor.lazyLoad();
-    }
+  public static boolean hasConnectionString() {
+    return hasConnectionString.get();
   }
 
-  public interface Accessor {
-    void lazyLoad();
+  public static void configureOnce() {
+    if (configure != null) {
+      if (!hasConnectionString()) {
+        configure.run();
+      }
+      configure = null;
+    }
   }
 
-  private AiLazyConfiguration() {}
+  private AzureFunctions() {}
 }

agent/agent-bootstrap/src/main/java/com/microsoft/applicationinsights/agent/bootstrap/diagnostics/log/ApplicationInsightsCsvLayout.java

@@ -23,13 +23,19 @@
 
 import ch.qos.logback.classic.PatternLayout;
 import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.spi.IThrowableProxy;
+import ch.qos.logback.classic.spi.ThrowableProxy;
 import com.microsoft.applicationinsights.agent.bootstrap.diagnostics.ApplicationMetadataFactory;
 import com.microsoft.applicationinsights.agent.bootstrap.diagnostics.DiagnosticsHelper;
+import java.io.PrintWriter;
+import java.io.StringWriter;
 
 public class ApplicationInsightsCsvLayout extends PatternLayout {
 
   private static final String PREFIX = "LanguageWorkerConsoleLogMS_APPLICATION_INSIGHTS_LOGS";
 
+  private static final String LINE_SEPARATOR = System.getProperty("line.separator");
+
   private static final ApplicationMetadataFactory applicationMetadataFactory =
       DiagnosticsHelper.getMetadataFactory();
   private final String qualifiedSdkVersion;
@@ -40,28 +46,43 @@ public ApplicationInsightsCsvLayout(String qualifiedSdkVersion) {
 
   @Override
   public String doLayout(ILoggingEvent event) {
-    StringBuilder stringBuilder = new StringBuilder();
-    stringBuilder.append(PREFIX);
-    stringBuilder.append(" ");
-    stringBuilder.append(event.getTimeStamp());
-    stringBuilder.append(",");
-    stringBuilder.append(event.getLevel().toString());
-    stringBuilder.append(",");
-    stringBuilder.append(event.getLoggerName());
-    stringBuilder.append(",");
-    stringBuilder.append("\"");
-    stringBuilder.append(event.getFormattedMessage());
-    stringBuilder.append("\"");
-    stringBuilder.append(",");
-    stringBuilder.append(applicationMetadataFactory.getSiteName().getValue());
-    stringBuilder.append(",");
-    stringBuilder.append(applicationMetadataFactory.getInstrumentationKey().getValue());
-    stringBuilder.append(",");
-    stringBuilder.append(qualifiedSdkVersion);
-    stringBuilder.append(",");
-    stringBuilder.append("java");
-    stringBuilder.append(System.getProperty("line.separator"));
+    String message = event.getFormattedMessage();
+    IThrowableProxy throwableProxy = event.getThrowableProxy();
+    Throwable throwable = null;
+    if (throwableProxy instanceof ThrowableProxy) {
+      // there is only one other subclass of ch.qos.logback.classic.spi.IThrowableProxy
+      // and it is only used for logging exceptions over the wire
+      throwable = ((ThrowableProxy) throwableProxy).getThrowable();
+    }
+    if (throwable != null) {
+      message += " ";
+      StringWriter sw = new StringWriter();
+      throwable.printStackTrace(new PrintWriter(sw, true));
+      message += sw;
+    }
+    return PREFIX
+        + " "
+        + event.getTimeStamp()
+        + ","
+        + event.getLevel().toString()
+        + ","
+        + event.getLoggerName()
+        + ","
+        + "\""
+        + formatForCsv(message)
+        + "\""
+        + ","
+        + applicationMetadataFactory.getSiteName().getValue()
+        + ","
+        + applicationMetadataFactory.getInstrumentationKey().getValue()
+        + ","
+        + qualifiedSdkVersion
+        + ","
+        + "java"
+        + System.getProperty("line.separator");
+  }
 
-    return stringBuilder.toString();
+  private static String formatForCsv(String str) {
+    return str.replace(LINE_SEPARATOR, " ").replace('\"', '\'');
   }
 }

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

@@ -539,11 +539,7 @@ private static String getDefaultPath() {
       if (DiagnosticsHelper.useAppSvcRpIntegrationLogging()) {
         return StatusFile.getLogDir() + "/" + DEFAULT_NAME;
       }
-      if (DiagnosticsHelper.useFunctionsRpIntegrationLogging()
-          && !DiagnosticsHelper.isOsWindows()) {
-        return "/var/log/applicationinsights/" + DEFAULT_NAME;
-      }
-      // azure spring cloud
+      // azure functions and azure spring cloud
       return DEFAULT_NAME;
     }
   }

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

@@ -592,8 +592,7 @@ private static String getConfigPath() {
 
   private static String getWebsiteSiteNameEnvVar() {
     String value = getEnvVar(WEBSITE_SITE_NAME);
-    // TODO what is the best way to identify running as Azure Functions worker?
-    // TODO is this the correct way to match role name from Azure Functions IIS host?
+    // TODO we can update this check after the new functions model is deployed.
     if (value != null && "java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
       // special case for Azure Functions
       return value.toLowerCase(Locale.ENGLISH);

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

@@ -41,6 +41,7 @@ public void afterAgent(AutoConfiguredOpenTelemetrySdk autoConfiguredOpenTelemetr
     // triggers loading of java.util.logging (starting with Java 8u231)
     // and JBoss/Wildfly need to install their own JUL manager before JUL is initialized.
 
+    // TODO we can update this check after the new functions model is deployed.
     if (!"java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
       // Delay registering and starting AppId retrieval until the connection string becomes
       // available for Linux Consumption Plan.

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

@@ -23,27 +23,35 @@
 
 import ch.qos.logback.classic.LoggerContext;
 import com.azure.monitor.opentelemetry.exporter.implementation.configuration.ConnectionString;
-import com.microsoft.applicationinsights.agent.bootstrap.AiLazyConfiguration;
+import com.azure.monitor.opentelemetry.exporter.implementation.configuration.StatsbeatConnectionString;
+import com.azure.monitor.opentelemetry.exporter.implementation.utils.Strings;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration;
 import com.microsoft.applicationinsights.agent.internal.exporter.AgentLogExporter;
 import com.microsoft.applicationinsights.agent.internal.legacyheaders.DelegatingPropagator;
 import com.microsoft.applicationinsights.agent.internal.sampling.DelegatingSampler;
 import com.microsoft.applicationinsights.agent.internal.telemetry.TelemetryClient;
+import io.opentelemetry.javaagent.bootstrap.ClassFileTransformerHolder;
+import io.opentelemetry.javaagent.bootstrap.InstrumentationHolder;
+import java.lang.instrument.ClassFileTransformer;
+import java.lang.instrument.Instrumentation;
 import java.util.Collections;
 import java.util.List;
 import javax.annotation.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
-public class LazyConfigurationAccessor implements AiLazyConfiguration.Accessor {
+public class AzureFunctionsInitializer implements Runnable {
 
-  private static final Logger logger = LoggerFactory.getLogger(LazyConfigurationAccessor.class);
+  private static final Logger startupLogger =
+      LoggerFactory.getLogger("com.microsoft.applicationinsights.agent");
+
+  private static final Logger logger = LoggerFactory.getLogger(AzureFunctionsInitializer.class);
 
   private final TelemetryClient telemetryClient;
   private final AgentLogExporter agentLogExporter;
   private final AppIdSupplier appIdSupplier;
 
-  public LazyConfigurationAccessor(
+  public AzureFunctionsInitializer(
       TelemetryClient telemetryClient,
       AgentLogExporter agentLogExporter,
       AppIdSupplier appIdSupplier) {
@@ -53,30 +61,50 @@ public LazyConfigurationAccessor(
   }
 
   @Override
-  public void lazyLoad() {
-    String instrumentationKey = telemetryClient.getInstrumentationKey();
-    String roleName = telemetryClient.getRoleName();
-    if (instrumentationKey != null
-        && !instrumentationKey.isEmpty()
-        && roleName != null
-        && !roleName.isEmpty()) {
+  public void run() {
+    if (!isAgentEnabled()) {
+      disableBytecodeInstrumentation();
       return;
     }
 
-    if (!isAgentEnabled()) {
-      return;
+    String selfDiagnosticsLevel = System.getenv("APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL");
+    String connectionString = System.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING");
+    String instrumentationKey = System.getenv("APPINSIGHTS_INSTRUMENTATIONKEY");
+    String websiteSiteName = System.getenv("WEBSITE_SITE_NAME");
+    String instrumentationLoggingLevel =
+        System.getenv("APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL");
+
+    logger.debug("APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL: {}", selfDiagnosticsLevel);
+    logger.debug("APPLICATIONINSIGHTS_CONNECTION_STRING: {}", connectionString);
+    if (Strings.isNullOrEmpty(connectionString)) {
+      logger.debug("APPINSIGHTS_INSTRUMENTATIONKEY: {}", instrumentationKey);
     }
+    logger.debug("WEBSITE_SITE_NAME: {}", websiteSiteName);
+    logger.debug(
+        "APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL: {}", instrumentationLoggingLevel);
 
-    setConnectionString(
-        System.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING"),
-        System.getenv("APPINSIGHTS_INSTRUMENTATIONKEY"));
-    setWebsiteSiteName(System.getenv("WEBSITE_SITE_NAME"));
-    setSelfDiagnosticsLevel(System.getenv("APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL"));
+    setConnectionString(connectionString, instrumentationKey);
+    setWebsiteSiteName(websiteSiteName);
+    setSelfDiagnosticsLevel(selfDiagnosticsLevel);
     agentLogExporter.setThreshold(
-        Configuration.LoggingInstrumentation.getSeverity(
-            System.getenv("APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL")));
+        Configuration.LoggingInstrumentation.getSeverity(instrumentationLoggingLevel));
+
+    startupLogger.info(
+        "ApplicationInsights Java Agent specialization complete for Azure Functions placeholder");
+  }
+
+  private static void disableBytecodeInstrumentation() {
+    Instrumentation instrumentation = InstrumentationHolder.getInstrumentation();
+    ClassFileTransformer transformer = ClassFileTransformerHolder.getClassFileTransformer();
+    if (instrumentation == null || transformer == null) {
+      return;
+    }
+    if (instrumentation.removeTransformer(transformer)) {
+      ClassFileTransformerHolder.setClassFileTransformer(null);
+    }
   }
 
+  // visible for testing
   void setConnectionString(@Nullable String connectionString, @Nullable String instrumentationKey) {
     if (connectionString != null && !connectionString.isEmpty()) {
       setValue(connectionString);
@@ -92,24 +120,23 @@ void setConnectionString(@Nullable String connectionString, @Nullable String ins
   }
 
   private void setValue(String value) {
-    // passing nulls because lazy configuration doesn't support manual statsbeat overrides
-    telemetryClient.setConnectionString(ConnectionString.parse(value));
+    ConnectionString connectionString = ConnectionString.parse(value);
+    telemetryClient.updateConnectionString(connectionString);
+    telemetryClient.updateStatsbeatConnectionString(
+        StatsbeatConnectionString.create(connectionString, null, null));
+
     // 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();
-    logger.debug("Set connection string {} lazily for the Azure Function Consumption Plan.", value);
 
     // start app id retrieval after the connection string becomes available.
     appIdSupplier.startAppIdRetrieval();
   }
 
   void setWebsiteSiteName(@Nullable String websiteSiteName) {
     if (websiteSiteName != null && !websiteSiteName.isEmpty()) {
-      telemetryClient.setRoleName(websiteSiteName);
-      logger.debug(
-          "Set WEBSITE_SITE_NAME: {} lazily for the Azure Function Consumption Plan.",
-          websiteSiteName);
+      telemetryClient.updateRoleName(websiteSiteName);
     }
   }
 
@@ -118,8 +145,6 @@ static void setSelfDiagnosticsLevel(@Nullable String loggingLevel) {
       return;
     }
 
-    logger.debug("setting APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL to {}", loggingLevel);
-
     LoggingLevelConfigurator configurator;
     try {
       configurator = new LoggingLevelConfigurator(loggingLevel);
@@ -135,15 +160,14 @@ static void setSelfDiagnosticsLevel(@Nullable String loggingLevel) {
     // also need to update any previously created loggers
     List<ch.qos.logback.classic.Logger> loggerList = loggerContext.getLoggerList();
     loggerList.forEach(configurator::updateLoggerLevel);
-    logger.debug("self-diagnostics logging level has been updated.");
   }
 
   // since the agent is already running at this point, this really just determines whether the
   // telemetry is sent to the ingestion service or not (essentially behaving to the user as if the
   // agent is not enabled)
   static boolean isAgentEnabled() {
     String enableAgent = System.getenv("APPLICATIONINSIGHTS_ENABLE_AGENT");
-    boolean enableAgentDefault = Boolean.parseBoolean(System.getProperty("LazySetOptIn"));
+    boolean enableAgentDefault = Boolean.getBoolean("LazySetOptIn");
     logger.debug("APPLICATIONINSIGHTS_ENABLE_AGENT: {}", enableAgent);
     logger.debug("LazySetOptIn: {}", enableAgentDefault);
     return isAgentEnabled(enableAgent, enableAgentDefault);

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

@@ -130,16 +130,16 @@ private void configureAppSvc() {
 
   private void configureFunctions() {
     Logger rootLogger = loggerContext.getLogger(ROOT_LOGGER_NAME);
-    rootLogger.addAppender(configureConsoleAppender());
+    rootLogger.addAppender(configureFileAppender());
     Logger diagnosticLogger = loggerContext.getLogger(DiagnosticsHelper.DIAGNOSTICS_LOGGER_NAME);
     diagnosticLogger.setLevel(Level.INFO);
     diagnosticLogger.setAdditive(false);
-    Appender<ILoggingEvent> appender = configureConsoleAppender();
-    diagnosticLogger.addAppender(appender);
+    Appender<ILoggingEvent> diagnosticAppender = configureConsoleAppender();
+    diagnosticLogger.addAppender(diagnosticAppender);
 
     // errors reported by other loggers should also go to diagnostic log
     // (level filter for these is applied in ApplicationInsightsDiagnosticsLogFilter)
-    rootLogger.addAppender(appender);
+    rootLogger.addAppender(diagnosticAppender);
 
     loggingLevelConfigurator.initLoggerLevels(loggerContext);
   }

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

@@ -105,8 +105,8 @@ public void run() {
               "Connection string from the JSON config file is overriding the previously configured connection string.");
           ConnectionString connectionString =
               ConnectionString.parse(newRpConfiguration.connectionString);
-          telemetryClient.setConnectionString(connectionString);
-          telemetryClient.setStatsbeatConnectionString(
+          telemetryClient.updateConnectionString(connectionString);
+          telemetryClient.updateStatsbeatConnectionString(
               StatsbeatConnectionString.create(
                   connectionString,
                   configuration.internal.statsbeat.instrumentationKey,

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

@@ -35,7 +35,7 @@
 import com.azure.monitor.opentelemetry.exporter.implementation.utils.TempDirs;
 import com.google.auto.service.AutoService;
 import com.microsoft.applicationinsights.agent.bootstrap.AiAppId;
-import com.microsoft.applicationinsights.agent.bootstrap.AiLazyConfiguration;
+import com.microsoft.applicationinsights.agent.bootstrap.AzureFunctions;
 import com.microsoft.applicationinsights.agent.internal.common.FriendlyException;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration;
 import com.microsoft.applicationinsights.agent.internal.configuration.Configuration.ProcessorConfig;
@@ -114,6 +114,7 @@ public void customize(AutoConfigurationCustomizer autoConfiguration) {
 
     Configuration config = FirstEntryPoint.getConfiguration();
     if (Strings.isNullOrEmpty(config.connectionString)) {
+      // TODO we can update this check after the new functions model is deployed.
       if (!"java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
         throw new FriendlyException(
             "No connection string provided", "Please provide connection string.");
@@ -185,9 +186,11 @@ public void customize(AutoConfigurationCustomizer autoConfiguration) {
     }
 
     // this is for Azure Function Linux consumption plan support.
+    // TODO we can update this check after the new functions model is deployed.
     if ("java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
-      AiLazyConfiguration.setAccessor(
-          new LazyConfigurationAccessor(
+      AzureFunctions.setup(
+          () -> telemetryClient.getConnectionString() != null,
+          new AzureFunctionsInitializer(
               telemetryClient, SecondEntryPoint.agentLogExporter, appIdSupplier));
     }