Improve error reporting on profiler startup

Author: jbachorik

dd-java-agent/agent-profiling/profiling-controller/src/main/java/com/datadog/profiling/controller/TempLocationManager.java

@@ -16,12 +16,14 @@
 import java.nio.file.Path;
 import java.nio.file.Paths;
 import java.nio.file.attribute.BasicFileAttributes;
+import java.nio.file.attribute.PosixFilePermission;
 import java.nio.file.attribute.PosixFilePermissions;
 import java.time.Instant;
 import java.time.temporal.ChronoUnit;
 import java.util.Set;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicReference;
 import java.util.regex.Pattern;
 import java.util.stream.Stream;
 import org.slf4j.Logger;
@@ -219,6 +221,7 @@ boolean await(long timeout, TimeUnit unit) throws Throwable {
     }
   }
 
+  private final boolean isPosixFs;
   private final Path baseTempDir;
   private final Path tempDir;
   private final long cutoffSeconds;
@@ -262,6 +265,9 @@ private TempLocationManager() {
       ConfigProvider configProvider, boolean runStartupCleanup, CleanupHook testHook) {
     cleanupTestHook = testHook;
 
+    Set<String> supportedViews = FileSystems.getDefault().supportedFileAttributeViews();
+    isPosixFs = supportedViews.contains("posix");
+
     // In order to avoid racy attempts to clean up files which are currently being processed in a
     // JVM which is being shut down (the JVMs far in the shutdown routine may not be reported by
     // 'jps' but still can be eg. processing JFR chunks) we will not clean up any files not older
@@ -317,6 +323,8 @@ private TempLocationManager() {
             },
             "Temp Location Manager Cleanup");
     Runtime.getRuntime().addShutdownHook(selfCleanup);
+
+    createTempDir(tempDir);
   }
 
   // @VisibleForTesting
@@ -362,21 +370,7 @@ public Path getTempDir(Path subPath, boolean create) {
     Path rslt =
         subPath != null && !subPath.toString().isEmpty() ? tempDir.resolve(subPath) : tempDir;
     if (create && !Files.exists(rslt)) {
-      try {
-        Set<String> supportedViews = FileSystems.getDefault().supportedFileAttributeViews();
-        if (supportedViews.contains("posix")) {
-          Files.createDirectories(
-              rslt,
-              PosixFilePermissions.asFileAttribute(PosixFilePermissions.fromString("rwx------")));
-        } else {
-          // non-posix, eg. Windows - let's rely on the created folders being world-writable
-          Files.createDirectories(rslt);
-        }
-
-      } catch (Exception e) {
-        log.warn(SEND_TELEMETRY, "Failed to create temp directory: {}", tempDir, e);
-        throw new IllegalStateException("Failed to create temp directory: " + tempDir, e);
-      }
+      createTempDir(rslt);
     }
     return rslt;
   }
@@ -454,4 +448,79 @@ boolean waitForCleanup(long timeout, TimeUnit unit) {
   void createDirStructure() throws IOException {
     Files.createDirectories(baseTempDir);
   }
+
+  private void createTempDir(Path tempDir) {
+    String msg = "Failed to create temp directory: " + tempDir;
+    try {
+      if (isPosixFs) {
+        Files.createDirectories(
+            tempDir,
+            PosixFilePermissions.asFileAttribute(PosixFilePermissions.fromString("rwx------")));
+      } else {
+        Files.createDirectories(tempDir);
+      }
+    } catch (IOException e) {
+      log.error("Failed to create temp directory {}", tempDir, e);
+      // if on a posix fs, let's check the expected permissions
+      // we will find the first offender not having the expected permissions and fail the check
+      if (isPosixFs) {
+        // take the first subfolder below the base temp dir
+        Path root = baseTempDir.resolve(baseTempDir.relativize(tempDir).getRoot());
+        try {
+          AtomicReference<Path> failed = new AtomicReference<>();
+          Files.walkFileTree(
+              root,
+              new FileVisitor<Path>() {
+                @Override
+                public FileVisitResult preVisitDirectory(Path dir, BasicFileAttributes attrs)
+                    throws IOException {
+                  Set<PosixFilePermission> perms = Files.getPosixFilePermissions(dir);
+                  if (!perms.contains(PosixFilePermission.OWNER_READ)
+                      || !perms.contains(PosixFilePermission.OWNER_WRITE)
+                      || !perms.contains(PosixFilePermission.OWNER_EXECUTE)) {
+                    failed.set(dir);
+                    return FileVisitResult.TERMINATE;
+                  }
+                  return FileVisitResult.CONTINUE;
+                }
+
+                @Override
+                public FileVisitResult visitFile(Path file, BasicFileAttributes attrs)
+                    throws IOException {
+                  return FileVisitResult.SKIP_SIBLINGS;
+                }
+
+                @Override
+                public FileVisitResult visitFileFailed(Path file, IOException exc)
+                    throws IOException {
+                  return FileVisitResult.TERMINATE;
+                }
+
+                @Override
+                public FileVisitResult postVisitDirectory(Path dir, IOException exc)
+                    throws IOException {
+                  return FileVisitResult.CONTINUE;
+                }
+              });
+          Path failedDir = failed.get();
+
+          if (failedDir != null) {
+            msg +=
+                " (offender: "
+                    + failedDir
+                    + ", permissions: "
+                    + PosixFilePermissions.toString(Files.getPosixFilePermissions(failedDir))
+                    + ")";
+            log.warn(SEND_TELEMETRY, msg, e);
+          }
+        } catch (IOException ignored) {
+          // should not happen, but let's ignore it anyway'
+        }
+        throw new IllegalStateException(msg, e);
+      } else {
+        log.warn(SEND_TELEMETRY, msg, e);
+        throw new IllegalStateException(msg, e);
+      }
+    }
+  }
 }

dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/CompositeController.java

@@ -1,5 +1,7 @@
 package com.datadog.profiling.agent;
 
+import static datadog.trace.api.telemetry.LogCollector.SEND_TELEMETRY;
+
 import com.datadog.profiling.controller.Controller;
 import com.datadog.profiling.controller.ControllerContext;
 import com.datadog.profiling.controller.OngoingRecording;
@@ -140,26 +142,33 @@ public static Controller build(ConfigProvider provider, ControllerContext contex
     List<Controller> controllers = new ArrayList<>();
     boolean isOracleJDK8 = Platform.isOracleJDK8();
     boolean isDatadogProfilerEnabled = Config.get().isDatadogProfilerEnabled();
-    if (provider.getBoolean(ProfilingConfig.PROFILING_DEBUG_JFR_DISABLED, false)) {
-      log.warn("JFR is disabled by configuration");
+    boolean isJfrEnabled =
+        !provider.getBoolean(ProfilingConfig.PROFILING_DEBUG_JFR_DISABLED, false);
+    if (!isJfrEnabled) {
+      log.warn(SEND_TELEMETRY, "JFR is disabled by configuration");
     } else {
       if (isOracleJDK8 && !isDatadogProfilerEnabled) {
         try {
           Class.forName("com.oracle.jrockit.jfr.Producer");
           controllers.add(OracleJdkController.instance(provider));
-        } catch (Throwable ignored) {
-          log.debug("Failed to load oracle profiler", ignored);
+        } catch (Throwable t) {
+          log.debug(SEND_TELEMETRY, "Failed to load oracle profiler: " + t.getMessage(), t);
         }
       }
       if (!isOracleJDK8) {
         try {
           if (Platform.hasJfr()) {
             controllers.add(OpenJdkController.instance(provider));
           } else {
-            log.debug("JFR is not available on this platform");
+            log.debug(
+                SEND_TELEMETRY,
+                "JFR is not available on this platform: "
+                    + OperatingSystem.current()
+                    + ", "
+                    + Arch.current());
           }
-        } catch (Throwable ignored) {
-          log.debug("Failed to load openjdk profiler", ignored);
+        } catch (Throwable t) {
+          log.debug(SEND_TELEMETRY, "Failed to load openjdk profiler: " + t.getMessage(), t);
         }
       }
     }
@@ -175,16 +184,20 @@ public static Controller build(ConfigProvider provider, ControllerContext contex
         context.setDatadogProfilerUnavailableReason(rootCause.getMessage());
         OperatingSystem os = OperatingSystem.current();
         if (os != OperatingSystem.linux) {
-          log.debug("Datadog profiler only supported on Linux", rootCause);
-        } else if (log.isDebugEnabled()) {
-          log.warn(
-              "failed to instantiate Datadog profiler on {} {}", os, Arch.current(), rootCause);
-        } else {
+          log.debug(SEND_TELEMETRY, "Datadog profiler only supported on Linux", rootCause);
+        } else if (!log.isDebugEnabled()) {
           log.warn(
               "failed to instantiate Datadog profiler on {} {} because: {}",
               os,
               Arch.current(),
               rootCause.getMessage());
+        } else {
+          log.debug(
+              SEND_TELEMETRY,
+              "failed to instantiate Datadog profiler on {} {}",
+              os,
+              Arch.current(),
+              rootCause);
         }
       }
     } else {
@@ -202,14 +215,18 @@ public static Controller build(ConfigProvider provider, ControllerContext contex
     }
     controllers.forEach(controller -> controller.configure(context));
     if (controllers.isEmpty()) {
-      throw new UnsupportedEnvironmentException(getFixProposalMessage());
+      throw new UnsupportedEnvironmentException(
+          getFixProposalMessage(isDatadogProfilerEnabled, isJfrEnabled));
     } else if (controllers.size() == 1) {
       return controllers.get(0);
     }
     return new CompositeController(controllers);
   }
 
-  private static String getFixProposalMessage() {
+  private static String getFixProposalMessage(boolean datadogProfilerEnabled, boolean jfrEnabled) {
+    if (!datadogProfilerEnabled && !jfrEnabled) {
+      return "Profiling is disabled by configuration. Please, make sure that your configuration is correct.";
+    }
     final String javaVendor = System.getProperty("java.vendor");
     final String javaVersion = System.getProperty("java.version");
     final String javaRuntimeName = System.getProperty("java.runtime.name");

dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/ProfilingAgent.java

@@ -109,7 +109,7 @@ public static synchronized void run(
         return;
       }
       if (!config.isProfilingEnabled()) {
-        log.debug("Profiling: disabled");
+        log.debug(SEND_TELEMETRY, "Profiling: disabled");
         return;
       }
       if (config.getApiKey() != null && !API_KEY_REGEX.test(config.getApiKey())) {
@@ -167,7 +167,8 @@ public static synchronized void run(
         }
       } catch (final UnsupportedEnvironmentException e) {
         log.warn(e.getMessage());
-        log.debug(SEND_TELEMETRY, "Unsupported environment for Datadog profiler", e);
+        // no need to send telemetry for this aggregate message
+        //   a detailed telemetry message has been sent from the attempts to enable the controllers
       } catch (final ConfigurationException e) {
         log.warn("Failed to initialize profiling agent! {}", e.getMessage());
         log.debug(SEND_TELEMETRY, "Failed to initialize profiling agent!", e);