diff --git a/dd-java-agent/agent-logging/build.gradle b/dd-java-agent/agent-logging/build.gradle index 8e8b9d97fc8..ca2da6ec8c0 100644 --- a/dd-java-agent/agent-logging/build.gradle +++ b/dd-java-agent/agent-logging/build.gradle @@ -21,6 +21,11 @@ excludedClassesCoverage += [ 'datadog.trace.logging.LogReporter', ] +excludedClassesInstructionCoverage += [ + // The PID lookup has separate Java 8 and Java 9+ paths, and no single JVM runs both + 'datadog.trace.logging.simplelogger.AasPerProcessLogFile', +] + dependencies { // This is fine since this project is shadowed into the agent-jar by dd-java-agent:agent-bootstrap api libs.slf4j diff --git a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/AasPerProcessLogFile.java b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/AasPerProcessLogFile.java new file mode 100644 index 00000000000..6fe32891ec2 --- /dev/null +++ b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/AasPerProcessLogFile.java @@ -0,0 +1,186 @@ +package datadog.trace.logging.simplelogger; + +import static datadog.trace.config.inversion.ConfigHelper.env; + +import de.thetaphi.forbiddenapis.SuppressForbidden; +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.lang.management.ManagementFactory; +import java.util.concurrent.TimeUnit; +import java.util.regex.Pattern; + +/** + * In Azure App Service, overlapping worker processes run several JVMs that share one configured log + * file, and each new JVM truncates it. This gives each JVM its own file, the same way the .NET + * tracer does: the PID goes in the name, the file rolls over at a size limit, and old per-process + * files are deleted at startup. + * + *

Settings mirror the .NET tracer: DD_TRACE_LOGFILE_RETENTION_DAYS (default 32, 0 disables + * cleanup) and DD_MAX_LOGFILE_SIZE in bytes (default 10 MB). + */ +@SuppressForbidden +final class AasPerProcessLogFile { + private static final int DEFAULT_RETENTION_DAYS = 32; + private static final long DEFAULT_MAX_SIZE_BYTES = 10L * 1024 * 1024; + + private AasPerProcessLogFile() {} + + static boolean isEnabled() { + String aas = env("DD_AZURE_APP_SERVICES"); + return "1".equals(aas) || "true".equalsIgnoreCase(aas); + } + + /** Opens the per-process log file and starts the cleanup of old per-process files. */ + static RollingFileOutputStream open(File configuredFile) throws IOException { + String pid = currentPid(); + String name = configuredFile.getName(); + int dot = name.lastIndexOf('.'); + String stem = dot > 0 ? name.substring(0, dot) : name; + String extension = dot > 0 ? name.substring(dot) : ""; + File directory = configuredFile.getAbsoluteFile().getParentFile(); + + startCleanup(directory, stem, extension); + return new RollingFileOutputStream(directory, stem + "-" + pid, extension, maxSizeBytes()); + } + + static String currentPid() { + try { + // Java 9+; reflection keeps this class loadable on Java 8. + Class handle = Class.forName("java.lang.ProcessHandle"); + Object current = handle.getMethod("current").invoke(null); + return String.valueOf(handle.getMethod("pid").invoke(current)); + } catch (Throwable ignored) { + // Java 8 + } + try { + String vmName = ManagementFactory.getRuntimeMXBean().getName(); + int at = vmName.indexOf('@'); + if (at > 0) { + return vmName.substring(0, at); + } + } catch (Throwable ignored) { + // fall through + } + return "unknown"; + } + + private static long maxSizeBytes() { + return parseLong(env("DD_MAX_LOGFILE_SIZE"), DEFAULT_MAX_SIZE_BYTES); + } + + private static int retentionDays() { + return (int) parseLong(env("DD_TRACE_LOGFILE_RETENTION_DAYS"), DEFAULT_RETENTION_DAYS); + } + + private static long parseLong(String value, long defaultValue) { + if (value == null) { + return defaultValue; + } + try { + return Long.parseLong(value.trim()); + } catch (NumberFormatException e) { + return defaultValue; + } + } + + private static void startCleanup(final File directory, String stem, String extension) { + final int days = retentionDays(); + if (days <= 0 || directory == null) { + return; + } + // Only this tracer's per-process files: -. and rolled -_. + final Pattern ownFiles = + Pattern.compile(Pattern.quote(stem) + "-\\d+(_\\d+)?" + Pattern.quote(extension)); + Thread cleanup = + new Thread( + () -> { + long cutoff = System.currentTimeMillis() - TimeUnit.DAYS.toMillis(days); + try { + File[] files = directory.listFiles(); + if (files == null) { + return; + } + for (File file : files) { + if (ownFiles.matcher(file.getName()).matches() + && file.lastModified() < cutoff + && !file.delete()) { + return; // stop at the first failure, like the .NET tracer + } + } + } catch (Throwable ignored) { + // stop quietly at the first IO problem + } + }, + "dd-log-file-cleanup"); + cleanup.setDaemon(true); + cleanup.start(); + } + + /** Appends to base.ext, then base_001.ext, base_002.ext, ... once each reaches maxSizeBytes. */ + static final class RollingFileOutputStream extends OutputStream { + private final File directory; + private final String base; + private final String extension; + private final long maxSizeBytes; + private FileOutputStream current; + private long currentSize; + private int sequence; + + RollingFileOutputStream(File directory, String base, String extension, long maxSizeBytes) + throws IOException { + this.directory = directory; + this.base = base; + this.extension = extension; + this.maxSizeBytes = maxSizeBytes; + if (directory != null) { + directory.mkdirs(); + } + openNext(); + } + + File currentFile() { + String suffix = sequence == 0 ? "" : String.format("_%03d", sequence); + return new File(directory, base + suffix + extension); + } + + private void openNext() throws IOException { + File file = currentFile(); + current = new FileOutputStream(file, true); + currentSize = file.length(); + } + + private void rollIfNeeded(int incoming) throws IOException { + if (maxSizeBytes > 0 && currentSize > 0 && currentSize + incoming > maxSizeBytes) { + current.close(); + sequence++; + openNext(); + } + } + + @Override + public synchronized void write(int b) throws IOException { + rollIfNeeded(1); + current.write(b); + currentSize++; + } + + @Override + public synchronized void write(byte[] b, int off, int len) throws IOException { + rollIfNeeded(len); + current.write(b, off, len); + currentSize += len; + } + + @Override + public synchronized void flush() throws IOException { + current.flush(); + } + + @Override + public synchronized void close() throws IOException { + current.close(); + } + } +} diff --git a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java index f3cc1a57a27..f345606ad01 100644 --- a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java +++ b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java @@ -181,14 +181,22 @@ static PrintStream getPrintStream(String logFile) { printStreamWrapper = new PrintStreamWrapper(System.out); break; default: - FileOutputStream outputStream = null; + java.io.OutputStream outputStream = null; try { File outputFile = new File(logFile); File parentFile = outputFile.getParentFile(); if (parentFile != null) { parentFile.mkdirs(); } - outputStream = new FileOutputStream(outputFile); + if (AasPerProcessLogFile.isEnabled()) { + // one file per JVM instead of truncating a shared file + AasPerProcessLogFile.RollingFileOutputStream rolling = + AasPerProcessLogFile.open(outputFile); + outputStream = rolling; + outputFile = rolling.currentFile(); + } else { + outputStream = new FileOutputStream(outputFile); + } PrintStream printStream = new PrintStream(outputStream, true); LogReporter.register(outputFile); return printStream; diff --git a/dd-java-agent/agent-logging/src/test/java/datadog/trace/logging/simplelogger/AasPerProcessLogFileTest.java b/dd-java-agent/agent-logging/src/test/java/datadog/trace/logging/simplelogger/AasPerProcessLogFileTest.java new file mode 100644 index 00000000000..c3e6d0ccad3 --- /dev/null +++ b/dd-java-agent/agent-logging/src/test/java/datadog/trace/logging/simplelogger/AasPerProcessLogFileTest.java @@ -0,0 +1,263 @@ +package datadog.trace.logging.simplelogger; + +import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.concurrent.TimeUnit.DAYS; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import datadog.environment.EnvironmentVariables; +import datadog.environment.EnvironmentVariables.EnvironmentVariablesProvider; +import datadog.trace.logging.PrintStreamWrapper; +import java.io.File; +import java.io.IOException; +import java.io.PrintStream; +import java.lang.management.ManagementFactory; +import java.nio.file.Files; +import java.util.Arrays; +import java.util.HashMap; +import java.util.Map; +import java.util.TreeSet; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.tabletest.junit.TableTest; + +class AasPerProcessLogFileTest { + private static final String PID = ManagementFactory.getRuntimeMXBean().getName().split("@", 2)[0]; + + private final Map environment = new HashMap<>(); + private EnvironmentVariablesProvider originalEnvironment; + + @TempDir File logDirectory; + + @BeforeEach + void useTestEnvironment() { + originalEnvironment = EnvironmentVariables.provider; + EnvironmentVariables.provider = + new EnvironmentVariablesProvider() { + @Override + public String get(String name) { + return environment.get(name); + } + + @Override + public Map getAll() { + return environment; + } + }; + } + + @AfterEach + void restoreEnvironment() { + EnvironmentVariables.provider = originalEnvironment; + } + + @TableTest({ + "scenario | azureAppServices | perProcessFile", + "enabled with 1 | 1 | true ", + "enabled with true | true | true ", + "enabled with TRUE | TRUE | true ", + "disabled with false | false | false ", + "not set | | false " + }) + void writesThisJvmsLogToItsOwnFileOnlyInAzureAppService( + String azureAppServices, boolean perProcessFile) throws Exception { + environment.put("DD_AZURE_APP_SERVICES", azureAppServices); + environment.put("DD_TRACE_LOGFILE_RETENTION_DAYS", "0"); + File configuredFile = new File(logDirectory, "dd-java-tracer.log"); + + PrintStream printStream = SLCompatSettings.getPrintStream(configuredFile.getPath()); + printStream.print("a log line"); + printStream.close(); + + File expectedFile = + perProcessFile ? new File(logDirectory, "dd-java-tracer-" + PID + ".log") : configuredFile; + assertEquals(fileNames(expectedFile.getName()), fileNames(logDirectory.list())); + assertEquals("a log line", contents(expectedFile)); + } + + @Test + void fallsBackToStandardErrorWhenThePerProcessLogFileCannotBeOpened() throws Exception { + environment.put("DD_AZURE_APP_SERVICES", "true"); + File notADirectory = new File(logDirectory, "not-a-directory"); + assertTrue(notADirectory.createNewFile()); + + PrintStream printStream = + SLCompatSettings.getPrintStream(new File(notADirectory, "dd-java-tracer.log").getPath()); + waitForCleanup(); + + assertSame(System.err, ((PrintStreamWrapper) printStream).getOriginalPrintStream()); + } + + @TableTest({ + "scenario | configuredName | perProcessName ", + "with extension | dd-java-tracer.log | dd-java-tracer-{pid}.log", + "without extension | dd-java-tracer | dd-java-tracer-{pid} ", + "only an extension | .log | .log-{pid} " + }) + void namesThePerProcessFileAfterTheConfiguredFileAndThePid( + String configuredName, String perProcessName) throws IOException { + environment.put("DD_TRACE_LOGFILE_RETENTION_DAYS", "0"); + + try (AasPerProcessLogFile.RollingFileOutputStream out = + AasPerProcessLogFile.open(new File(logDirectory, configuredName))) { + assertEquals( + new File(logDirectory, perProcessName.replace("{pid}", PID)).getAbsoluteFile(), + out.currentFile().getAbsoluteFile()); + } + } + + @Test + void rollsOverToNumberedFilesAtTheConfiguredSize() throws IOException { + environment.put("DD_MAX_LOGFILE_SIZE", "10"); + environment.put("DD_TRACE_LOGFILE_RETENTION_DAYS", "0"); + + try (AasPerProcessLogFile.RollingFileOutputStream out = + AasPerProcessLogFile.open(new File(logDirectory, "tracer.log"))) { + // a write larger than the limit still goes to the empty file instead of leaving it empty + out.write(bytes("0123456789ABC")); + out.write(bytes("1234")); + out.write(bytes("567890")); + out.write('!'); + out.flush(); + + assertEquals(new File(logDirectory, "tracer-" + PID + "_002.log"), out.currentFile()); + } + assertEquals( + fileNames( + "tracer-" + PID + ".log", "tracer-" + PID + "_001.log", "tracer-" + PID + "_002.log"), + fileNames(logDirectory.list())); + assertEquals("0123456789ABC", contents(new File(logDirectory, "tracer-" + PID + ".log"))); + assertEquals("1234567890", contents(new File(logDirectory, "tracer-" + PID + "_001.log"))); + assertEquals("!", contents(new File(logDirectory, "tracer-" + PID + "_002.log"))); + } + + @TableTest({ + "scenario | maxLogFileSize | files", + "limit reached | 150 | 2 ", + "zero disables | 0 | 1 ", + "invalid: default | not-a-number | 1 ", + "unset: default | | 1 " + }) + void rollsOverOnlyWhenAPositiveSizeIsConfigured(String maxLogFileSize, int files) + throws IOException { + environment.put("DD_MAX_LOGFILE_SIZE", maxLogFileSize); + environment.put("DD_TRACE_LOGFILE_RETENTION_DAYS", "0"); + + try (AasPerProcessLogFile.RollingFileOutputStream out = + AasPerProcessLogFile.open(new File(logDirectory, "tracer.log"))) { + out.write(new byte[100]); + out.write(new byte[100]); + } + assertEquals(files, logDirectory.list().length); + } + + @Test + void appendsToAnExistingFileAndCountsItTowardsTheSize() throws IOException { + File existing = new File(logDirectory, "tracer-" + PID + ".log"); + Files.write(existing.toPath(), bytes("earlier")); + + try (AasPerProcessLogFile.RollingFileOutputStream out = + new AasPerProcessLogFile.RollingFileOutputStream( + logDirectory, "tracer-" + PID, ".log", 10)) { + out.write(bytes("later")); + } + + assertEquals("earlier", contents(existing)); + assertEquals("later", contents(new File(logDirectory, "tracer-" + PID + "_001.log"))); + } + + @TableTest({ + "scenario | retentionDays | ageDays | deleted", + "default keeps 32 days | | 20 | false ", + "default deletes after | | 40 | true ", + "configured keeps | 5 | 1 | false ", + "configured deletes after | 5 | 10 | true ", + "zero disables cleanup | 0 | 400 | false ", + "invalid: default keeps | soon | 20 | false ", + "invalid: default deletes | soon | 40 | true " + }) + void deletesThisTracersPerProcessFilesOlderThanTheRetention( + String retentionDays, int ageDays, boolean deleted) throws Exception { + environment.put("DD_TRACE_LOGFILE_RETENTION_DAYS", retentionDays); + File oldFile = oldFile("dd-java-tracer-1234.log", ageDays); + + AasPerProcessLogFile.open(new File(logDirectory, "dd-java-tracer.log")).close(); + waitForCleanup(); + + assertEquals(deleted, !oldFile.exists()); + } + + @Test + void cleanupDeletesOnlyThisTracersPerProcessFiles() throws Exception { + File ownFile = oldFile("dd-java-tracer-1234.log", 40); + File ownRolledFile = oldFile("dd-java-tracer-1234_001.log", 40); + File configuredFile = oldFile("dd-java-tracer.log", 40); + File otherTracerFile = oldFile("dotnet-tracer-managed-1234.log", 40); + File otherExtension = oldFile("dd-java-tracer-1234.txt", 40); + File notAPid = oldFile("dd-java-tracer-old.log", 40); + + AasPerProcessLogFile.open(new File(logDirectory, "dd-java-tracer.log")).close(); + waitForCleanup(); + + assertFalse(ownFile.exists()); + assertFalse(ownRolledFile.exists()); + assertTrue(configuredFile.exists()); + assertTrue(otherTracerFile.exists()); + assertTrue(otherExtension.exists()); + assertTrue(notAPid.exists()); + } + + @Test + void cleanupStopsQuietlyWhenAFileCannotBeDeleted() throws Exception { + // a non-empty directory with a per-process file name cannot be deleted + File undeletable = new File(logDirectory, "dd-java-tracer-1234.log"); + assertTrue(new File(undeletable, "child").mkdirs()); + assertTrue(undeletable.setLastModified(daysAgo(40))); + + try (AasPerProcessLogFile.RollingFileOutputStream out = + AasPerProcessLogFile.open(new File(logDirectory, "dd-java-tracer.log"))) { + waitForCleanup(); + out.write(bytes("still logging")); + out.flush(); + + assertTrue(undeletable.exists()); + assertEquals("still logging", contents(out.currentFile())); + } + } + + private File oldFile(String name, int ageDays) throws IOException { + File file = new File(logDirectory, name); + assertTrue(file.createNewFile()); + assertTrue(file.setLastModified(daysAgo(ageDays))); + return file; + } + + private static long daysAgo(int days) { + return System.currentTimeMillis() - DAYS.toMillis(days); + } + + /** Waits for the background cleanup that opening a per-process log file starts. */ + private static void waitForCleanup() throws InterruptedException { + for (Thread thread : Thread.getAllStackTraces().keySet()) { + if ("dd-log-file-cleanup".equals(thread.getName())) { + thread.join(10_000); + } + } + } + + private static TreeSet fileNames(String... names) { + return new TreeSet<>(Arrays.asList(names)); + } + + private static byte[] bytes(String text) { + return text.getBytes(UTF_8); + } + + private static String contents(File file) throws IOException { + return new String(Files.readAllBytes(file.toPath()), UTF_8); + } +} diff --git a/metadata/supported-configurations.json b/metadata/supported-configurations.json index 4b71411c15d..e37a9823b6b 100644 --- a/metadata/supported-configurations.json +++ b/metadata/supported-configurations.json @@ -2525,6 +2525,14 @@ "aliases": [] } ], + "DD_MAX_LOGFILE_SIZE": [ + { + "version": "A", + "type": "int", + "default": "10485760", + "aliases": [] + } + ], "DD_MEASURE_METHODS": [ { "version": "A", @@ -8196,6 +8204,14 @@ "aliases": ["DD_TRACE_INTEGRATION_LOGBACK_ENABLED", "DD_INTEGRATION_LOGBACK_ENABLED"] } ], + "DD_TRACE_LOGFILE_RETENTION_DAYS": [ + { + "version": "A", + "type": "int", + "default": "32", + "aliases": [] + } + ], "DD_TRACE_LOGS_INTAKE_ENABLED": [ { "version": "A",