Hotfixes for Linux Consumption Plan (#1737)

* Fix verbose logging in Linux Consumption Plan when self diagnostic logging level is updated at runtime * Update java doc * Turn off Quick Pulse when the instrummentation key is null * Update RoleName for Linux Consumption Plan * Fix invalid instrumentation key * Reword * DefaultQuickPulsePingSender * Fix statsbeat is not sent in Linux Consumption Plan * RoleName is used in both header and payload * Turn off azure metadata service on functions and appsvc and AKS * Fix verbose logging * Fix null resourceProviderId for Linux Consumption Plan * Use scheduleWithFixedDelay * Fix a compilation error * Fix failing unit tests * Unify logging configuration a little more * Refactor Co-authored-by: Trask Stalnaker <[email protected]> Co-authored-by: Trask Stalnaker <[email protected]>
microsoft · Jun 10, 2021 · cea5fd9 · cea5fd9
1 parent 0b3f9ce
commit cea5fd9
Show file tree

Hide file tree

Showing 12 changed files with 150 additions and 71 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -5,6 +5,7 @@
 * Add metric filtering to telemetry processor [#1728](https://github.com/microsoft/ApplicationInsights-Java/pull/1728).
 * Add log processor to telemetry processor [#1713](https://github.com/microsoft/ApplicationInsights-Java/pull/1713).
 * Fix app id retrieval 404 for Linux Consumption Plan [#1730](https://github.com/microsoft/ApplicationInsights-Java/pull/1730).
+* Fix invalid instrumentation keys for Linux Consumption Plan [#1737](https://github.com/microsoft/ApplicationInsights-Java/pull/1737).
 
 # Version 3.1.1-BETA.4
 * Reduce agent jar file size back to normal [#1716](https://github.com/microsoft/ApplicationInsights-Java/pull/1716).

diff --git a/...main/java/com/microsoft/applicationinsights/agent/internal/LazyConfigurationAccessor.java b/...main/java/com/microsoft/applicationinsights/agent/internal/LazyConfigurationAccessor.java
@@ -27,6 +27,8 @@
 import com.microsoft.applicationinsights.TelemetryConfiguration;
 import com.microsoft.applicationinsights.agent.internal.propagator.DelegatingPropagator;
 import com.microsoft.applicationinsights.agent.internal.sampling.DelegatingSampler;
+import com.microsoft.applicationinsights.agent.internal.wasbootstrap.LoggingConfigurator;
+import com.microsoft.applicationinsights.agent.internal.wasbootstrap.LoggingLevelConfigurator;
 import io.opentelemetry.instrumentation.api.aisdk.AiLazyConfiguration;
 import io.opentelemetry.instrumentation.api.config.Config;
 import org.slf4j.Logger;
@@ -100,15 +102,21 @@ static void setWebsiteSiteName(String websiteSiteName) {
     }
 
     static void setSelfDiagnosticsLevel(String loggingLevel) {
-        if (loggingLevel != null && !loggingLevel.isEmpty()) {
-            LoggerContext loggerContext = (LoggerContext)LoggerFactory.getILoggerFactory();
-            List<ch.qos.logback.classic.Logger> loggerList = loggerContext.getLoggerList();
-            logger.info("setting APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL to {}", loggingLevel);
-            loggerList.stream().forEach(tmpLogger -> tmpLogger.setLevel(Level.toLevel(loggingLevel)));
-            if (Level.toLevel(loggingLevel) == Level.DEBUG) {
-                logger.debug("This should get logged after the logging level update.");
-            }
+        if (loggingLevel == null || !loggingLevel.isEmpty()) {
+            return;
+        }
+        LoggerContext loggerContext = (LoggerContext)LoggerFactory.getILoggerFactory();
+        List<ch.qos.logback.classic.Logger> loggerList = loggerContext.getLoggerList();
+        logger.info("setting APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL to {}", loggingLevel);
+        LoggingLevelConfigurator configurator;
+        try {
+            configurator = new LoggingLevelConfigurator(loggingLevel);
+        } catch (IllegalArgumentException exception) {
+            logger.warn("unexpected self-diagnostic level: {}", loggingLevel);
+            return;
         }
+        loggerList.forEach(configurator::updateLoggerLevel);
+        logger.debug("self-diagnostics logging level has been updated.");
     }
 
     static boolean shouldSetConnectionString(boolean lazySetOptIn, String enableAgent) {

diff --git a/...va/com/microsoft/applicationinsights/agent/internal/wasbootstrap/LoggingConfigurator.java b/...va/com/microsoft/applicationinsights/agent/internal/wasbootstrap/LoggingConfigurator.java
@@ -23,29 +23,30 @@
 import org.slf4j.LoggerFactory;
 
 import java.nio.file.Path;
-import java.util.Locale;
 
 import static org.slf4j.Logger.ROOT_LOGGER_NAME;
 
-class LoggingConfigurator {
+public class LoggingConfigurator {
 
     private final LoggerContext loggerContext;
 
-    private final Level level;
     private final String destination;
 
     private final Path filePath;
     private final int fileMaxSizeMb;
     private final int fileMaxHistory;
 
+    private final LoggingLevelConfigurator loggingLevelConfigurator;
+
     LoggingConfigurator(Configuration.SelfDiagnostics selfDiagnostics, Path agentPath) {
         loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
 
-        level = getLevel(selfDiagnostics.level);
         destination = selfDiagnostics.destination;
         filePath = agentPath.resolveSibling(selfDiagnostics.file.path);
         fileMaxSizeMb = selfDiagnostics.file.maxSizeMb;
         fileMaxHistory = selfDiagnostics.file.maxHistory;
+
+        loggingLevelConfigurator = new LoggingLevelConfigurator(selfDiagnostics.level);
     }
 
     void configure() {
@@ -228,23 +229,11 @@ private Appender<ILoggingEvent> configureEtwAppender() {
     }
 
     private void configureLoggingLevels() {
-        // never want to log apache http at trace or debug, it's just way to verbose
-        Level atLeastInfoLevel = getMaxLevel(level, Level.INFO);
-
-        Level otherLibsLevel = level == Level.INFO ? Level.WARN : level;
-
-        // TODO need something more reliable, currently will log too much WARN if "muzzleMatcher" logger name changes
-        // muzzleMatcher logs at WARN level in order to make them visible, but really should only be enabled when debugging
-        Level muzzleMatcherLevel = level.toInt() <= Level.DEBUG.toInt() ? level : getMaxLevel(level, Level.ERROR);
-
-        // never want to log apache http at trace or debug, it's just way to verbose
-        loggerContext.getLogger("org.apache.http").setLevel(atLeastInfoLevel);
-        // never want to log io.grpc.Context at trace or debug, as it logs confusing stack trace that looks like error but isn't
-        loggerContext.getLogger("io.grpc.Context").setLevel(atLeastInfoLevel);
-        // muzzleMatcher logs at WARN level, so by default this is OFF, but enabled when DEBUG logging is enabled
-        loggerContext.getLogger("muzzleMatcher").setLevel(muzzleMatcherLevel);
-        loggerContext.getLogger("com.microsoft.applicationinsights").setLevel(level);
-        loggerContext.getLogger(ROOT_LOGGER_NAME).setLevel(otherLibsLevel);
+        loggingLevelConfigurator.updateLoggerLevel(loggerContext.getLogger("org.apache.http"));
+        loggingLevelConfigurator.updateLoggerLevel(loggerContext.getLogger("io.grpc.Context"));
+        loggingLevelConfigurator.updateLoggerLevel(loggerContext.getLogger("muzzleMatcher"));
+        loggingLevelConfigurator.updateLoggerLevel(loggerContext.getLogger("com.microsoft.applicationinsights"));
+        loggingLevelConfigurator.updateLoggerLevel(loggerContext.getLogger(ROOT_LOGGER_NAME));
     }
 
     private Encoder<ILoggingEvent> createEncoder() {
@@ -254,16 +243,4 @@ private Encoder<ILoggingEvent> createEncoder() {
         encoder.start();
         return encoder;
     }
-
-    private static Level getMaxLevel(Level level1, Level level2) {
-        return level1.toInt() >= level2.toInt() ? level1 : level2;
-    }
-
-    private static Level getLevel(String levelStr) {
-        try {
-            return Level.valueOf(levelStr.toUpperCase(Locale.ROOT));
-        } catch (IllegalArgumentException e) {
-            throw new IllegalStateException("Unexpected self-diagnostic level: " + levelStr);
-        }
-    }
 }
diff --git a/...m/microsoft/applicationinsights/agent/internal/wasbootstrap/LoggingLevelConfigurator.java b/...m/microsoft/applicationinsights/agent/internal/wasbootstrap/LoggingLevelConfigurator.java
@@ -0,0 +1,58 @@
+package com.microsoft.applicationinsights.agent.internal.wasbootstrap;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+
+import java.util.Locale;
+
+public class LoggingLevelConfigurator {
+
+    private final Level level;
+
+    public LoggingLevelConfigurator(String levelStr) {
+        try {
+            this.level = Level.valueOf(levelStr.toUpperCase(Locale.ROOT));
+        } catch (IllegalArgumentException e) {
+            throw new IllegalStateException("Unexpected self-diagnostic level: " + levelStr);
+        }
+    }
+
+    public void updateLoggerLevel(Logger logger) {
+        Level loggerLevel;
+        String name = logger.getName();
+        if (name.startsWith("org.apache.http")) {
+            // never want to log apache http at trace or debug, it's just way too verbose
+            loggerLevel = getAtLeastInfoLevel(level);
+        } else if (name.startsWith("io.grpc.Context")) {
+            // never want to log io.grpc.Context at trace or debug, as it logs confusing stack trace that looks like error but isn't
+            loggerLevel = getAtLeastInfoLevel(level);
+        } else if (name.startsWith("muzzleMatcher")) {
+            // muzzleMatcher logs at WARN level, so by default this is OFF, but enabled when DEBUG logging is enabled
+            loggerLevel = getMuzzleMatcherLevel(level);
+        } else if (name.startsWith("com.microsoft.applicationinsights")) {
+            loggerLevel = level;
+        } else {
+            loggerLevel = getOtherLibLevel(level);
+        }
+        logger.setLevel(loggerLevel);
+    }
+
+    // never want to log apache http at trace or debug, it's just way to verbose
+    private static Level getAtLeastInfoLevel(Level level) {
+        return getMaxLevel(level, Level.INFO);
+    }
+
+    private static Level getOtherLibLevel(Level level) {
+        return level == Level.INFO ? Level.WARN : level;
+    }
+
+    // TODO need something more reliable, currently will log too much WARN if "muzzleMatcher" logger name changes
+    // muzzleMatcher logs at WARN level in order to make them visible, but really should only be enabled when debugging
+    private static Level getMuzzleMatcherLevel(Level level) {
+        return level.toInt() <= Level.DEBUG.toInt() ? level : getMaxLevel(level, Level.ERROR);
+    }
+
+    private static Level getMaxLevel(Level level1, Level level2) {
+        return level1.toInt() >= level2.toInt() ? level1 : level2;
+    }
+}
diff --git a/core/src/main/java/com/microsoft/applicationinsights/TelemetryClient.java b/core/src/main/java/com/microsoft/applicationinsights/TelemetryClient.java
@@ -95,10 +95,10 @@ public TelemetryClient() {
      * application session.
      */
     public TelemetryContext getContext() {
-        if (context == null || (context.getInstrumentationKey() != null &&  !context.getInstrumentationKey().equals(configuration.getInstrumentationKey()))) {
+        if (context == null || (configuration.getInstrumentationKey() != null &&  !configuration.getInstrumentationKey().equals(context.getInstrumentationKey()))) {
             // lock and recheck there is still no initialized context. If so, create one.
             synchronized (TELEMETRY_CONTEXT_LOCK) {
-                if (context==null || (context.getInstrumentationKey() != null && !context.getInstrumentationKey().equals(configuration.getInstrumentationKey()))) {
+                if (context==null || (configuration.getInstrumentationKey() != null && !configuration.getInstrumentationKey().equals(context.getInstrumentationKey()))) {
                     context = createInitializedContext();
                 }
             }

diff --git a/...va/com/microsoft/applicationinsights/internal/quickpulse/DefaultQuickPulsePingSender.java b/...va/com/microsoft/applicationinsights/internal/quickpulse/DefaultQuickPulsePingSender.java
@@ -26,6 +26,7 @@
 import java.util.concurrent.atomic.AtomicBoolean;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Strings;
 import com.microsoft.applicationinsights.customExceptions.FriendlyException;
 import com.microsoft.applicationinsights.internal.channel.common.LazyHttpClient;
 import com.microsoft.applicationinsights.internal.util.LocalStringsUtils;
@@ -50,37 +51,23 @@ final class DefaultQuickPulsePingSender implements QuickPulsePingSender {
     private final TelemetryConfiguration configuration;
     private final HttpClient httpClient;
     private final QuickPulseNetworkHelper networkHelper = new QuickPulseNetworkHelper();
-    private final String pingPrefix;
-    private final String roleName;
+    private volatile String pingPrefix; // cached for performance
     private final String instanceName;
     private final String machineName;
     private final String quickPulseId;
     private long lastValidTransmission = 0;
+    private String roleName;
     private static final AtomicBoolean friendlyExceptionThrown = new AtomicBoolean();
 
+    // TODO (trask) roleName is ignored, clean this up after merging to AAD branch
     public DefaultQuickPulsePingSender(HttpClient httpClient, TelemetryConfiguration configuration, String machineName, String instanceName, String roleName, String quickPulseId) {
         this.configuration = configuration;
         this.httpClient = httpClient;
-        this.roleName = roleName;
         this.instanceName = instanceName;
+        this.roleName = roleName;
         this.machineName = machineName;
         this.quickPulseId = quickPulseId;
 
-        if (!LocalStringsUtils.isNullOrEmpty(roleName)) {
-            roleName = "\"" + roleName + "\"";
-        }
-
-        pingPrefix = "{" +
-                "\"Documents\": null," +
-                "\"Instance\":\"" + instanceName + "\"," +
-                "\"InstrumentationKey\": null," +
-                "\"InvariantVersion\": " + QuickPulse.QP_INVARIANT_VERSION + "," +
-                "\"MachineName\":\"" + machineName + "\"," +
-                "\"RoleName\":" + roleName + "," +
-                "\"Metrics\": null," +
-                "\"StreamId\": \"" + quickPulseId + "\"," +
-                "\"Timestamp\": \"\\/Date(";
-
         if (logger.isTraceEnabled()) {
             logger.trace("{} using endpoint {}", DefaultQuickPulsePingSender.class.getSimpleName(), getQuickPulseEndpoint());
         }
@@ -96,6 +83,12 @@ public DefaultQuickPulsePingSender(final HttpClient httpClient, final String mac
 
     @Override
     public QuickPulseHeaderInfo ping(String redirectedEndpoint) {
+        String instrumentationKey = getInstrumentationKey();
+        if (Strings.isNullOrEmpty(instrumentationKey) && "java".equals(System.getenv("FUNCTIONS_WORKER_RUNTIME"))) {
+            // Quick Pulse Ping uri will be null when the instrumentation key is null. When that happens, turn off quick pulse.
+            return new QuickPulseHeaderInfo(QuickPulseStatus.QP_IS_OFF);
+        }
+
         final Date currentDate = new Date();
         final String endpointPrefix = LocalStringsUtils.isNullOrEmpty(redirectedEndpoint) ? getQuickPulseEndpoint() : redirectedEndpoint;
         final HttpPost request = networkHelper.buildPingRequest(currentDate, getQuickPulsePingUri(endpointPrefix), quickPulseId, machineName, roleName, instanceName);
@@ -133,6 +126,29 @@ public QuickPulseHeaderInfo ping(String redirectedEndpoint) {
         return onPingError(sendTime);
     }
 
+    // Linux Consumption Plan role name is lazily set
+    private String getPingPrefix() {
+        if (pingPrefix == null) {
+            roleName = TelemetryConfiguration.getActive().getRoleName();
+
+            if (!LocalStringsUtils.isNullOrEmpty(roleName)) {
+                roleName = "\"" + roleName + "\"";
+            }
+
+            pingPrefix = "{" +
+                    "\"Documents\": null," +
+                    "\"Instance\":\"" + instanceName + "\"," +
+                    "\"InstrumentationKey\": null," +
+                    "\"InvariantVersion\": " + QuickPulse.QP_INVARIANT_VERSION + "," +
+                    "\"MachineName\":\"" + machineName + "\"," +
+                    "\"RoleName\":" + roleName + "," +
+                    "\"Metrics\": null," +
+                    "\"StreamId\": \"" + quickPulseId + "\"," +
+                    "\"Timestamp\": \"\\/Date(";
+        }
+        return pingPrefix;
+    }
+
     @VisibleForTesting
     String getQuickPulsePingUri(String endpointPrefix) {
         return endpointPrefix + "/ping?ikey=" + getInstrumentationKey();
@@ -142,6 +158,7 @@ private String getInstrumentationKey() {
         TelemetryConfiguration config = this.configuration == null ? TelemetryConfiguration.getActive() : configuration;
         return config.getInstrumentationKey();
     }
+
     @VisibleForTesting
     String getQuickPulseEndpoint() {
         if (configuration != null) {
@@ -152,7 +169,7 @@ String getQuickPulseEndpoint() {
     }
 
     private ByteArrayEntity buildPingEntity(long timeInMillis) {
-        String sb = pingPrefix + timeInMillis +
+        String sb = getPingPrefix() + timeInMillis +
                 ")\\/\"," +
                 "\"Version\":\"2.2.0-738\"" +
                 "}";

diff --git a/core/src/main/java/com/microsoft/applicationinsights/internal/statsbeat/AttachStatsbeat.java b/core/src/main/java/com/microsoft/applicationinsights/internal/statsbeat/AttachStatsbeat.java
@@ -21,6 +21,7 @@
 
 package com.microsoft.applicationinsights.internal.statsbeat;
 
+import com.google.common.base.Strings;
 import com.microsoft.applicationinsights.TelemetryClient;
 import com.microsoft.applicationinsights.telemetry.MetricTelemetry;
 
@@ -44,6 +45,11 @@ class AttachStatsbeat extends BaseStatsbeat {
 
     @Override
     protected void send() {
+        // WEBSITE_HOSTNAME is lazily set in Linux Consumption Plan.
+        if (Strings.isNullOrEmpty(resourceProviderId)) {
+            resourceProviderId = initResourceProviderId(CustomDimensions.get().getResourceProvider(), null);
+        }
+
         MetricTelemetry statsbeatTelemetry = createStatsbeatTelemetry(ATTACH_METRIC_NAME, 0);
         statsbeatTelemetry.getProperties().put("rpId", resourceProviderId);
         telemetryClient.track(statsbeatTelemetry);
@@ -69,9 +75,10 @@ void updateMetadataInstance(MetadataInstanceResponse response) {
     static String initResourceProviderId(ResourceProvider resourceProvider, MetadataInstanceResponse response) {
         switch (resourceProvider) {
             case RP_APPSVC:
+                // FIXME (heya) Need to test these env vars on App Services Linux & Windows
                 return System.getenv(WEBSITE_SITE_NAME) + "/" + System.getenv(WEBSITE_HOME_STAMPNAME) + "/" + System.getenv(WEBSITE_HOSTNAME);
             case RP_FUNCTIONS:
-                return System.getenv(WEBSITE_HOSTNAME);
+                return System.getenv("WEBSITE_HOSTNAME");
             case RP_VM:
                 if (response != null) {
                     return response.getVmId() + "/" + response.getSubscriptionId();

diff --git a/.../main/java/com/microsoft/applicationinsights/internal/statsbeat/AzureMetadataService.java b/.../main/java/com/microsoft/applicationinsights/internal/statsbeat/AzureMetadataService.java
@@ -37,11 +37,11 @@ class AzureMetadataService implements Runnable {
         this.customDimensions = customDimensions;
     }
 
-    void scheduleAtFixedRate(long interval) {
+    void scheduleWithFixedDelay(long interval) {
         // Querying Azure Metadata Service is required for every 15 mins since VM id will get updated frequently.
         // Starting and restarting a VM will generate a new VM id each time.
         // TODO (heya) need to confirm if restarting VM will also restart the Java Agent
-        scheduledExecutor.scheduleAtFixedRate(this, interval, interval, TimeUnit.SECONDS);
+        scheduledExecutor.scheduleWithFixedDelay(this, interval, interval, TimeUnit.SECONDS);
     }
 
     // visible for testing

diff --git a/core/src/main/java/com/microsoft/applicationinsights/internal/statsbeat/BaseStatsbeat.java b/core/src/main/java/com/microsoft/applicationinsights/internal/statsbeat/BaseStatsbeat.java
@@ -67,7 +67,7 @@ public void run() {
             try {
                 // For Linux Consumption Plan, connection string is lazily set.
                 // There is no need to send statsbeat when cikey is empty.
-                if (Strings.isNullOrEmpty(CustomDimensions.get().getCustomerIkey())) {
+                if (Strings.isNullOrEmpty(TelemetryConfiguration.getActive().getInstrumentationKey())) {
                     return;
                 }
                 send();

diff --git a/.../src/main/java/com/microsoft/applicationinsights/internal/statsbeat/CustomDimensions.java b/.../src/main/java/com/microsoft/applicationinsights/internal/statsbeat/CustomDimensions.java
@@ -21,6 +21,7 @@
 
 package com.microsoft.applicationinsights.internal.statsbeat;
 
+import com.google.common.base.Strings;
 import com.microsoft.applicationinsights.TelemetryConfiguration;
 import com.microsoft.applicationinsights.internal.system.SystemInformation;
 import com.microsoft.applicationinsights.internal.util.PropertyHelper;
@@ -35,10 +36,10 @@ class CustomDimensions {
     private volatile OperatingSystem operatingSystem;
 
     private final String attachType;
-    private final String customerIkey;
     private final String runtimeVersion;
     private final String language;
     private final String sdkVersion;
+    private String customerIkey;
 
     static CustomDimensions get() {
         return instance;
@@ -101,6 +102,10 @@ void populateProperties(Map<String, String> properties) {
         properties.put("rp", resourceProvider.getValue());
         properties.put("os", operatingSystem.getValue());
         properties.put("attach", attachType);
+        // For Linux Consumption Plan, customer iKey needs to be updated here since it's lazily set.
+        if (Strings.isNullOrEmpty(customerIkey)) {
+            customerIkey = TelemetryConfiguration.getActive().getInstrumentationKey();
+        }
         properties.put("cikey", customerIkey);
         properties.put("runtimeVersion", runtimeVersion);
         properties.put("language", language);