Merge pull request #1373 from microsoft/trask/logging-improvements

Logging improvements

Author: trask

agent/agent-bootstrap/src/main/java/com/microsoft/applicationinsights/agent/bootstrap/MainEntryPoint.java

@@ -21,17 +21,21 @@
 package com.microsoft.applicationinsights.agent.bootstrap;
 
 import java.io.File;
+import java.lang.instrument.ClassFileTransformer;
+import java.lang.instrument.IllegalClassFormatException;
 import java.lang.instrument.Instrumentation;
 import java.net.URL;
 import java.nio.file.Path;
+import java.security.ProtectionDomain;
 
+import ch.qos.logback.classic.Level;
 import com.microsoft.applicationinsights.agent.bootstrap.configuration.Configuration;
-import com.microsoft.applicationinsights.agent.bootstrap.configuration.ConfigurationBuilder;
 import com.microsoft.applicationinsights.agent.bootstrap.configuration.Configuration.SelfDiagnostics;
+import com.microsoft.applicationinsights.agent.bootstrap.configuration.ConfigurationBuilder;
 import com.microsoft.applicationinsights.agent.bootstrap.diagnostics.DiagnosticsHelper;
 import com.microsoft.applicationinsights.agent.bootstrap.diagnostics.status.StatusFile;
-import io.opentelemetry.javaagent.bootstrap.ConfigureLogging;
 import io.opentelemetry.javaagent.bootstrap.AgentInitializer;
+import io.opentelemetry.javaagent.bootstrap.ConfigureLogging;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
@@ -62,41 +66,45 @@ public static void start(Instrumentation instrumentation, URL bootstrapURL) {
         boolean success = false;
         Logger startupLogger = null;
         try {
-            File agentJarFile = new File(bootstrapURL.toURI());
-            DiagnosticsHelper.setAgentJarFile(agentJarFile);
+            Path agentPath = new File(bootstrapURL.toURI()).toPath();
+            DiagnosticsHelper.setAgentJarFile(agentPath);
             // configuration is only read this early in order to extract logging configuration
-            configuration = ConfigurationBuilder.create(agentJarFile.toPath());
+            configuration = ConfigurationBuilder.create(agentPath);
             configPath = configuration.configPath;
             lastModifiedTime = configuration.lastModifiedTime;
-            startupLogger = configureLogging(configuration.preview.selfDiagnostics);
+            startupLogger = configureLogging(configuration.selfDiagnostics, agentPath);
             ConfigurationBuilder.logConfigurationMessages();
             MDC.put(DiagnosticsHelper.MDC_PROP_OPERATION, "Startup");
             AgentInitializer.start(instrumentation, bootstrapURL, false);
+            startupLogger.info("ApplicationInsights Java Agent started successfully");
             success = true;
             LoggerFactory.getLogger(DiagnosticsHelper.DIAGNOSTICS_LOGGER_NAME)
                     .info("Application Insights Codeless Agent Attach Successful");
         } catch (ThreadDeath td) {
             throw td;
         } catch (Throwable t) {
             if (startupLogger != null) {
-                startupLogger.error("Agent failed to start.", t);
+                startupLogger.error("ApplicationInsights Java Agent failed to start", t);
             } else {
                 t.printStackTrace();
             }
         } finally {
             try {
-                StatusFile.putValueAndWrite("AgentInitializedSuccessfully", success);
+                StatusFile.putValueAndWrite("AgentInitializedSuccessfully", success, startupLogger != null);
             } catch (Exception e) {
-                startupLogger.error("Error writing status.json", e); // lgtm[java/dereferenced-value-may-be-null]
+                if (startupLogger != null) {
+                    startupLogger.error("Error writing status.json", e);
+                } else {
+                    e.printStackTrace();
+                }
             }
             MDC.clear();
         }
     }
 
-    private static Logger configureLogging(SelfDiagnostics selfDiagnostics) {
+    private static Logger configureLogging(SelfDiagnostics selfDiagnostics, Path agentPath) {
         String logbackXml;
         String destination = selfDiagnostics.destination;
-        boolean logUnknownDestination = false;
         if (DiagnosticsHelper.isAppServiceCodeless()) {
             // User-accessible IPA log file. Enabled by default.
             if ("false".equalsIgnoreCase(System.getenv(DiagnosticsHelper.IPA_LOG_FILE_ENABLED_ENV_VAR))) {
@@ -114,58 +122,80 @@ private static Logger configureLogging(SelfDiagnostics selfDiagnostics) {
                 System.setProperty("ai.config.appender.etw.location", "");
             }
             logbackXml = "applicationinsights.appsvc.logback.xml";
-        } else if (destination == null || destination.equalsIgnoreCase("console")) {
-            logbackXml = "applicationinsights.console.logback.xml";
+        } else if (destination == null || destination.equalsIgnoreCase("file+console")) {
+            logbackXml = "applicationinsights.file-and-console.logback.xml";
         } else if (destination.equalsIgnoreCase("file")) {
             logbackXml = "applicationinsights.file.logback.xml";
-        } else {
-            logUnknownDestination = true;
+        } else if (destination.equalsIgnoreCase("console")) {
             logbackXml = "applicationinsights.console.logback.xml";
+        } else {
+            throw new IllegalStateException("Unknown self-diagnostics destination: " + destination);
         }
         ClassLoader cl = ConfigureLogging.class.getClassLoader();
         if (cl == null) {
             cl = ClassLoader.getSystemClassLoader();
         }
         final URL configurationFile = cl.getResource(logbackXml);
-        System.setProperty("applicationinsights.logback.configurationFile", configurationFile.toString());
 
-        String logbackDirectory = selfDiagnostics.directory;
-        String logbackLevel = selfDiagnostics.level;
-        int logbackMaxFileSizeMB = selfDiagnostics.maxSizeMB;
+        Level level = getLevel(selfDiagnostics.level);
 
-        if (logbackDirectory == null) {
-            logbackDirectory = System.getProperty("java.io.tmpdir");
-        }
-        if (logbackDirectory == null) {
-            // this should never get to here, but just in case, otherwise setProperty() will fail below
-            logbackDirectory = ".";
+        Path logFilePath = agentPath.resolveSibling(selfDiagnostics.file.path);
+        Path logFileNamePath = logFilePath.getFileName();
+        if (logFileNamePath == null) {
+            throw new IllegalStateException("Unexpected empty self-diagnostics file path");
         }
-        System.setProperty("applicationinsights.logback.directory", logbackDirectory);
-        System.setProperty("applicationinsights.logback.level", logbackLevel);
-        System.setProperty("applicationinsights.logback.maxFileSize", logbackMaxFileSizeMB + "MB");
-        System.setProperty("applicationinsights.logback.totalSizeCap", logbackMaxFileSizeMB * 2 + "MB");
-        if (isDebugOrLower(logbackLevel)) {
-            // never want to log apache http at trace or debug, it's just way to verbose
-            System.setProperty("applicationinsights.logback.level.org.apache.http", "info");
+        String logFileName = logFileNamePath.toString();
+        String rollingFileName;
+        int index = logFileName.lastIndexOf('.');
+        if (index != -1) {
+            rollingFileName = logFileName.substring(0, index) + ".%i" + logFileName.substring(index);
         } else {
-            System.setProperty("applicationinsights.logback.level.org.apache.http", logbackLevel);
+            rollingFileName = logFileName + ".%i";
         }
+        Path rollingFilePath = logFilePath.resolveSibling(rollingFileName);
+
+        // 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;
+
         try {
-            Logger logger = LoggerFactory.getLogger("com.microsoft.applicationinsights.agent");
-            if (logUnknownDestination) {
-                logger.error("Unknown self-diagnostics destination: {}", destination);
-            }
-            return logger;
+            System.setProperty("applicationinsights.logback.configurationFile", configurationFile.toString());
+
+            System.setProperty("applicationinsights.logback.file.path", logFilePath.toString());
+            System.setProperty("applicationinsights.logback.file.rollingPath", rollingFilePath.toString());
+            System.setProperty("applicationinsights.logback.file.maxSize", selfDiagnostics.file.maxSizeMb + "MB");
+            System.setProperty("applicationinsights.logback.file.maxIndex", Integer.toString(selfDiagnostics.file.maxHistory));
+
+            System.setProperty("applicationinsights.logback.level.other", otherLibsLevel.toString());
+            System.setProperty("applicationinsights.logback.level", level.levelStr);
+
+            System.setProperty("applicationinsights.logback.level.atLeastInfo", atLeastInfoLevel.levelStr);
+
+            return LoggerFactory.getLogger("com.microsoft.applicationinsights.agent");
         } finally {
             System.clearProperty("applicationinsights.logback.configurationFile");
-            System.clearProperty("applicationinsights.logback.directory");
+            System.clearProperty("applicationinsights.logback.file.path");
+            System.clearProperty("applicationinsights.logback.file.rollingPath");
+            System.clearProperty("applicationinsights.logback.file.maxSize");
+            System.clearProperty("applicationinsights.logback.file.maxIndex");
             System.clearProperty("applicationinsights.logback.level");
-            System.clearProperty("applicationinsights.logback.maxFileSize");
-            System.clearProperty("applicationinsights.logback.totalSizeCap");
             System.clearProperty("applicationinsights.logback.level.org.apache.http");
         }
     }
 
+    private static Level getMaxLevel(Level level1, Level level2) {
+        return level1.isGreaterOrEqual(level2) ? level1 : level2;
+    }
+
+    private static Level getLevel(String levelStr) {
+        Level level = Level.valueOf(levelStr);
+        if (!level.levelStr.equalsIgnoreCase(levelStr)) {
+            throw new IllegalStateException("Unexpected self-diagnostic level: " + levelStr);
+        }
+        return level;
+    }
+
     private static boolean isDebugOrLower(String level) {
         return level.equalsIgnoreCase("all") || level.equalsIgnoreCase("trace") || level.equalsIgnoreCase("debug");
     }

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

@@ -43,8 +43,12 @@ public class Configuration {
     public Map<String, Map<String, Object>> instrumentation = new HashMap<String, Map<String, Object>>();
     public Heartbeat heartbeat = new Heartbeat();
     public Proxy proxy = new Proxy();
+    public SelfDiagnostics selfDiagnostics = new SelfDiagnostics();
     public PreviewConfiguration preview = new PreviewConfiguration();
 
+    // this is just here to detect if using old format in order to give a helpful error message
+    public Map<String, Object> instrumentationSettings;
+
     public enum ProcessorMatchType {
         //Moshi JSON builder donot allow case insensitive mapping
         strict, regexp
@@ -91,18 +95,23 @@ public static class Proxy {
 
     public static class PreviewConfiguration {
 
-        public SelfDiagnostics selfDiagnostics = new SelfDiagnostics();
         public boolean developerMode;
         public List<ProcessorConfig> processors = new ArrayList<>();
         public boolean openTelemetryApiSupport;
     }
 
     public static class SelfDiagnostics {
 
-        public String destination;
-        public String directory;
-        public String level = "error";
-        public int maxSizeMB = 10;
+        public String level = "info";
+        public String destination = "file+console";
+        public DestinationFile file = new DestinationFile();
+    }
+
+    public static class DestinationFile {
+
+        public String path = "applicationinsights.log"; // relative to the directory where agent jar is located
+        public int maxSizeMb = 5;
+        public int maxHistory = 1;
     }
 
     public static class ProcessorConfig {

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

@@ -84,7 +84,7 @@ private static void loadLogCaptureEnvVar(Configuration config) {
     private static void loadJmxMetrics(Configuration config) throws IOException {
         String jmxMetricsEnvVarJson = overlayWithEnvVar(APPLICATIONINSIGHTS_JMX_METRICS, (String)null);
 
-        // JmxMetrics env variable has higher precedence over jmxMetrics config from ApplicationInsights.json
+        // JmxMetrics env variable has higher precedence over jmxMetrics config from applicationinsights.json
         if (jmxMetricsEnvVarJson != null && !jmxMetricsEnvVarJson.isEmpty()) {
             Moshi moshi = new Moshi.Builder().build();
             Type listOfJmxMetrics = Types.newParameterizedType(List.class, JmxMetric.class);
@@ -124,25 +124,28 @@ private static Configuration loadConfigurationFile(Path agentJarPath) throws IOE
             return new Configuration();
         }
 
-        Path configPath;
-        boolean warnIfMissing;
         String configPathStr = getEnvVarOrProperty(APPLICATIONINSIGHTS_CONFIGURATION_FILE, "applicationinsights.configuration.file");
-        if (configPathStr == null) {
-            configPath = agentJarPath.resolveSibling("ApplicationInsights.json");
-            warnIfMissing = false;
-        } else {
-            configPath = agentJarPath.resolveSibling(configPathStr);
-            warnIfMissing = true;
+        if (configPathStr != null) {
+            Path configPath = agentJarPath.resolveSibling(configPathStr);
+            if (Files.exists(configPath)) {
+                return loadJsonConfigFile(configPath);
+            } else {
+                // fail fast any time configuration is invalid
+                throw new IllegalStateException("could not find requested configuration file: " + configPathStr);
+            }
         }
 
+        Path configPath = agentJarPath.resolveSibling("applicationinsights.json");
         if (Files.exists(configPath)) {
             return loadJsonConfigFile(configPath);
-        } else {
-            if (warnIfMissing) {
-                configurationMessages.add(new ConfigurationMessage("could not find configuration file: {}", configPathStr));
-            }
-            return new Configuration();
         }
+
+        if (Files.exists(agentJarPath.resolveSibling("ApplicationInsights.json"))) {
+            throw new IllegalStateException("found ApplicationInsights.json, but it should be lowercase: applicationinsights.json");
+        }
+
+        // json configuration file is not required, ok to configure via env var alone
+        return new Configuration();
     }
 
     public static void logConfigurationMessages() {
@@ -293,6 +296,11 @@ public static Configuration loadJsonConfigFile(Path configPath) throws IOExcepti
             buffer.readFrom(in);
             try {
                 Configuration configuration = jsonAdapter.fromJson(buffer);
+                if (configuration.instrumentationSettings != null) {
+                    throw new IllegalStateException("It looks like you are using an old applicationinsights.json file" +
+                            " which still has \"instrumentationSettings\", please see the docs for the new format:" +
+                            " https://docs.microsoft.com/en-us/azure/azure-monitor/app/java-standalone-config");
+                }
                 configuration.configPath = configPath;
                 configuration.lastModifiedTime = lastModifiedTime;
                 return configuration;

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

@@ -45,8 +45,7 @@ private DiagnosticsHelper() { }
         isWindows = osName != null && osName.startsWith("Windows");
     }
 
-    public static void setAgentJarFile(File agentJarFile) {
-        Path agentPath = agentJarFile.toPath();
+    public static void setAgentJarFile(Path agentPath) {
         if (Files.exists(agentPath.resolveSibling("appsvc.codeless"))) {
             appServiceCodeless = true;
         } else if (Files.exists(agentPath.resolveSibling("aks.codeless"))) {

agent/agent-bootstrap/src/main/java/com/microsoft/applicationinsights/agent/bootstrap/diagnostics/status/StatusFile.java

@@ -30,8 +30,6 @@
 
 public class StatusFile {
 
-    private static final Logger logger = LoggerFactory.getLogger(StatusFile.class);
-
     private static final List<DiagnosticsValueFinder> VALUE_FINDERS = new ArrayList<>();
 
     // visible for testing
@@ -131,11 +129,15 @@ static boolean shouldWrite() {
     }
 
     public static <T> void putValueAndWrite(String key, T value) {
+        putValueAndWrite(key, value, true);
+    }
+
+    public static <T> void putValueAndWrite(String key, T value, boolean loggingInitialized) {
         if (!shouldWrite()) {
             return;
         }
         CONSTANT_VALUES.put(key, value);
-        write();
+        write(loggingInitialized);
     }
 
     public static <T> void putValue(String key, T value) {
@@ -146,6 +148,10 @@ public static <T> void putValue(String key, T value) {
     }
 
     public static void write() {
+        write(false);
+    }
+
+    private static void write(boolean loggingInitialized) {
         if (!shouldWrite()) {
             return;
         }
@@ -161,15 +167,26 @@ public void run() {
                 synchronized (lock) {
                     final File file = new File(directory, fileName);
                     boolean dirsWereCreated = file.getParentFile().mkdirs();
+
+                    Logger logger = loggingInitialized ? LoggerFactory.getLogger(StatusFile.class) : null;
+
                     if (dirsWereCreated || file.getParentFile().exists()) {
                         BufferedSink b = null;
                         try {
                             b = getBuffer(file);
                             new Moshi.Builder().build().adapter(Map.class).indent(" ").nullSafe().toJson(b, map);
                             b.flush();
-                            logger.info("Wrote status to file: {}", file.getAbsolutePath());
+                            if (logger != null) {
+                                logger.info("Wrote status to file: {}", file.getAbsolutePath());
+                            } else {
+                                System.out.println("Wrote status to file: " + file.getAbsolutePath());
+                            }
                         } catch (Exception e) {
-                            logger.error("Error writing {}", file.getAbsolutePath(), e);
+                            if (logger != null) {
+                                logger.error("Error writing {}", file.getAbsolutePath(), e);
+                            } else {
+                                e.printStackTrace();
+                            }
                             if (b != null) {
                                 try {
                                     b.close();
@@ -179,8 +196,13 @@ public void run() {
                             }
                         }
                     } else {
-                        logger.error("Parent directories for status file could not be created: {}",
-                                file.getAbsolutePath());
+                        if (logger != null) {
+                            logger.error("Parent directories for status file could not be created: {}",
+                                    file.getAbsolutePath());
+                        } else {
+                            System.err.println("Parent directories for status file could not be created: "
+                                    + file.getAbsolutePath());
+                        }
                     }
                 }
             }