Introduce a new file-based logging handler for Bazel.

It provides a number of features that we want and whose combination cannot be
accomplished using the standard FileHandler:
* Using a different filename per server process, by putting a timestamp and
  process ID in the filename. This means Bazel will no longer overwrite its
  log when the server is restarted, making it easier for developers and
  maintainers to diagnose issues.
* Putting the hostname and username in the filename (useful when running on a
  shared network filesystem).
* Automatically setting a symlink to the latest log file, ensuring that the
  latest log can still be found under the usual Bazel server log path.
* Providing an API for getting the filename of the current log file, for use
  by Bazel itself.
* Cleaning up old log files when their total size exceeds a set limit.

This commit only introduces the handler; its usage in Bazel will be enabled by
a follow-up commit.

RELNOTES: None.
PiperOrigin-RevId: 207274587

2 files changed, 390 insertions, 0 deletions

diff --git a/src/test/java/com/google/devtools/build/lib/BUILD b/src/test/java/com/google/devtools/build/lib/BUILD
index e782ac7ae7..f030b0abe0 100644
--- a/src/test/java/com/google/devtools/build/lib/BUILD
+++ b/src/test/java/com/google/devtools/build/lib/BUILD
@@ -316,6 +316,7 @@ java_test(
         ":guava_junit_truth",
         ":test_runner",
         ":testutil",
+        "//src/main/java/com/google/devtools/build/lib:simple-log-handler",
         "//src/main/java/com/google/devtools/build/lib:single-line-formatter",
         "//src/main/java/com/google/devtools/build/lib:util",
         "//src/main/java/com/google/devtools/build/lib/shell",
diff --git a/src/test/java/com/google/devtools/build/lib/util/SimpleLogHandlerTest.java b/src/test/java/com/google/devtools/build/lib/util/SimpleLogHandlerTest.java
new file mode 100644
index 0000000000..a8f95727f7
--- /dev/null
+++ b/src/test/java/com/google/devtools/build/lib/util/SimpleLogHandlerTest.java
@@ -0,0 +1,389 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.util;
+
+import static com.google.common.truth.Truth.assertThat;
+import static com.google.devtools.build.lib.testutil.MoreAsserts.assertThrows;
+import static java.nio.charset.StandardCharsets.UTF_8;
+
+import com.google.common.base.Strings;
+import java.io.BufferedReader;
+import java.io.File;
+import java.io.FileInputStream;
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.io.InputStreamReader;
+import java.io.OutputStreamWriter;
+import java.nio.file.DirectoryStream;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.nio.file.Paths;
+import java.text.SimpleDateFormat;
+import java.time.Clock;
+import java.time.Instant;
+import java.time.ZoneId;
+import java.time.ZoneOffset;
+import java.util.Arrays;
+import java.util.Date;
+import java.util.Optional;
+import java.util.TimeZone;
+import java.util.logging.Formatter;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.rules.TemporaryFolder;
+import org.junit.runner.RunWith;
+import org.junit.runners.JUnit4;
+
+/** Tests for the {@link SimpleLogHandler} class. */
+@RunWith(JUnit4.class)
+public final class SimpleLogHandlerTest {
+
+  @Rule public TemporaryFolder tmp = new TemporaryFolder();
+
+  @Test
+  public void testPrefix() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello_world_%u%h%%_")
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+    assertThat(handler.getCurrentLogFilePath().get().toString())
+        .startsWith(tmp.getRoot() + File.separator + "hello_world_%u%h%%_");
+  }
+
+  @Test
+  public void testPatternVariables() throws Exception {
+    String username = System.getProperty("user.name");
+    if (Strings.isNullOrEmpty(username)) {
+      username = "unknown_user";
+    }
+    String hostname = SimpleLogHandler.getLocalHostnameFirstComponent();
+
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello_")
+            .setPattern("world_%u%%%h_")
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+    assertThat(handler.getCurrentLogFilePath().get().toString())
+        .startsWith(
+            tmp.getRoot() + File.separator + "hello_world_" + username + "%" + hostname + "_");
+  }
+
+  @Test
+  public void testPatternInvalidVariable() throws Exception {
+    assertThrows(
+        IllegalArgumentException.class,
+        () -> SimpleLogHandler.builder().setPattern("hello_%t").build());
+  }
+
+  @Test
+  public void testExtensionDefaults() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder().setPrefix(tmp.getRoot() + File.separator + "hello").build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+    assertThat(handler.getCurrentLogFilePath().get().toString())
+        .endsWith("." + SimpleLogHandler.getPidString());
+  }
+
+  @Test
+  public void testExtensionSetter() throws Exception {
+    SimpleLogHandler handler1 =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setExtension("xyz")
+            .build();
+    handler1.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+    assertThat(handler1.getCurrentLogFilePath().get().toString()).endsWith(".xyz");
+  }
+
+  private static final class FakeClock extends Clock {
+    private Instant now;
+    private final ZoneId zone;
+
+    FakeClock(Instant now, ZoneId zone) {
+      this.now = now;
+      this.zone = zone;
+    }
+
+    void set(Instant now) {
+      this.now = now;
+    }
+
+    @Override
+    public Instant instant() {
+      return now;
+    }
+
+    @Override
+    public ZoneId getZone() {
+      return zone;
+    }
+
+    @Override
+    public Clock withZone(ZoneId zone) {
+      return new FakeClock(this.now, zone);
+    }
+  }
+
+  @Test
+  public void testTimestamp() throws Exception {
+    Instant instant = Instant.parse("2015-09-01T15:17:54Z");
+    FakeClock clock = new FakeClock(instant, ZoneOffset.UTC);
+    SimpleDateFormat dateFormat = new SimpleDateFormat(SimpleLogHandler.DEFAULT_TIMESTAMP_FORMAT);
+    dateFormat.setTimeZone(TimeZone.getTimeZone(ZoneOffset.UTC));
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setClockForTesting(clock)
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+
+    assertThat(dateFormat.format(Date.from(instant))).isEqualTo("20150901-151754.");
+    assertThat(handler.getCurrentLogFilePath().get().toString()).contains("20150901-151754.");
+  }
+
+  private static final class TrivialFormatter extends Formatter {
+    @Override
+    public String format(LogRecord rec) {
+      return formatMessage(rec) + "\n";
+    }
+  }
+
+  @Test
+  public void testPublish() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setFormatter(new TrivialFormatter())
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+    Path logPath = handler.getCurrentLogFilePath().get();
+    handler.close();
+
+    assertThat(new String(Files.readAllBytes(logPath), UTF_8)).isEqualTo("Hello world\n");
+  }
+
+  @Test
+  public void testSymbolicLinkDefaults() throws Exception {
+    Path symlinkPath = Paths.get(tmp.getRoot().toString(), "hello");
+    Files.createFile(symlinkPath);
+
+    // Expected to delete the file at symlinkPath and replace with a symlink to the log.
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder().setPrefix(symlinkPath.toString()).build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+
+    assertThat(handler.getSymbolicLinkPath().toString()).isEqualTo(symlinkPath.toString());
+    assertThat(Files.isSymbolicLink(handler.getSymbolicLinkPath())).isTrue();
+    assertThat(Files.readSymbolicLink(handler.getSymbolicLinkPath()).toString())
+        .isEqualTo(handler.getCurrentLogFilePath().get().getFileName().toString());
+  }
+
+  @Test
+  public void testSymbolicLinkSetter() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setSymlink("bye")
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "Hello world")); // To open the log file.
+
+    assertThat(handler.getSymbolicLinkPath().toString())
+        .isEqualTo(tmp.getRoot() + File.separator + "bye");
+    assertThat(Files.isSymbolicLink(handler.getSymbolicLinkPath())).isTrue();
+    assertThat(Files.readSymbolicLink(handler.getSymbolicLinkPath()).toString())
+        .isEqualTo(handler.getCurrentLogFilePath().get().getFileName().toString());
+  }
+
+  @Test
+  public void testSymbolicLinkInvalidPath() throws Exception {
+    SimpleLogHandler.Builder builder =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setSymlink("bye/bye"); // Invalid symlink path (not at top level of log directory).
+    assertThrows(IllegalArgumentException.class, () -> builder.build());
+  }
+
+  @Test
+  public void testLogLevelEqualPublished() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "info")
+            .setLogLevel(Level.INFO)
+            .build();
+    handler.publish(new LogRecord(Level.INFO, "Hello"));
+    Optional<Path> logPath = handler.getCurrentLogFilePath();
+    handler.close();
+
+    assertThat(Files.size(logPath.get())).isGreaterThan(0L);
+  }
+
+  @Test
+  public void testLogLevelHigherPublished() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "info")
+            .setLogLevel(Level.INFO)
+            .build();
+    handler.publish(new LogRecord(Level.WARNING, "Hello"));
+    Optional<Path> logPath = handler.getCurrentLogFilePath();
+    handler.close();
+
+    assertThat(Files.size(logPath.get())).isGreaterThan(0L);
+  }
+
+  @Test
+  public void testLogLevelLowerNotPublished() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "info")
+            .setLogLevel(Level.INFO)
+            .build();
+    handler.publish(new LogRecord(Level.FINE, "Hello"));
+    Optional<Path> logPath = handler.getCurrentLogFilePath();
+    handler.close();
+
+    assertThat(logPath.isPresent()).isFalse();
+  }
+
+  @Test
+  public void testLogLevelDefaultAllPublished() throws Exception {
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder().setPrefix(tmp.getRoot() + File.separator + "all").build();
+    handler.publish(new LogRecord(Level.FINEST, "Hello"));
+    Optional<Path> logPath = handler.getCurrentLogFilePath();
+    handler.close();
+
+    assertThat(Files.size(logPath.get())).isGreaterThan(0L);
+  }
+
+  @Test
+  public void testRotateLimitBytes() throws Exception {
+    FakeClock clock = new FakeClock(Instant.parse("2018-01-01T12:00:00Z"), ZoneOffset.UTC);
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "limits")
+            .setFormatter(new TrivialFormatter())
+            .setRotateLimitBytes(16)
+            .setClockForTesting(clock)
+            .build();
+    Path symlinkPath = handler.getSymbolicLinkPath();
+    handler.publish(new LogRecord(Level.SEVERE, "1234567" /* 8 bytes including "\n" */));
+    Path firstLogPath = handler.getCurrentLogFilePath().get();
+    clock.set(Instant.parse("2018-01-01T12:00:01Z")); // Ensure the next file has a different name.
+    handler.publish(new LogRecord(Level.SEVERE, "1234567" /* 8 bytes including "\n" */));
+    Path secondLogPath = handler.getCurrentLogFilePath().get();
+    handler.publish(new LogRecord(Level.SEVERE, "1234567" /* 8 bytes including "\n" */));
+    handler.close();
+
+    assertThat(Files.isSymbolicLink(symlinkPath)).isTrue();
+    assertThat(Files.readSymbolicLink(symlinkPath).toString())
+        .isEqualTo(secondLogPath.getFileName().toString());
+    assertThat(Files.size(firstLogPath)).isEqualTo(16L /* including two "\n" */);
+    assertThat(Files.size(secondLogPath)).isEqualTo(8L /* including "\n" */);
+    try (DirectoryStream<Path> dirStream = Files.newDirectoryStream(tmp.getRoot().toPath())) {
+      assertThat(dirStream).hasSize(3);
+    }
+  }
+
+  private Path newFileWithContent(String name, String content) throws IOException {
+    File file = tmp.newFile(name);
+    try (OutputStreamWriter writer =
+        new OutputStreamWriter(new FileOutputStream(file.getPath()), UTF_8)) {
+      writer.write(content);
+    }
+    return file.toPath();
+  }
+
+  private Path newFileOfSize(String name, int size) throws IOException {
+    char[] buf = new char[size];
+    Arrays.fill(buf, '\n');
+    return newFileWithContent(name, new String(buf));
+  }
+
+  @Test
+  public void testOpenInAppendMode() throws Exception {
+    Path logPath = newFileWithContent("hello.20150901-151754.log", "Previous logs\n");
+    Instant instant = Instant.parse("2015-09-01T15:17:54Z");
+    FakeClock clock = new FakeClock(instant, ZoneOffset.UTC);
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setPattern(".")
+            .setExtension("log")
+            .setFormatter(new TrivialFormatter())
+            .setClockForTesting(clock)
+            .build();
+    handler.publish(new LogRecord(Level.SEVERE, "New logs"));
+    assertThat(handler.getCurrentLogFilePath().get().toString()).isEqualTo(logPath.toString());
+    handler.close();
+    try (BufferedReader logReader =
+        new BufferedReader(new InputStreamReader(new FileInputStream(logPath.toFile()), UTF_8))) {
+      assertThat(logReader.readLine()).isEqualTo("Previous logs");
+      assertThat(logReader.readLine()).isEqualTo("New logs");
+    }
+  }
+
+  @Test
+  public void testTotalLimit() throws Exception {
+    String username = System.getProperty("user.name");
+    if (Strings.isNullOrEmpty(username)) {
+      username = "unknown_user";
+    }
+    String hostname = SimpleLogHandler.getLocalHostnameFirstComponent();
+    String baseFilename = "hello." + hostname + "." + username + ".log.java.";
+    Path nonLog = newFileOfSize("non_log", 16);
+    Path missingDate = newFileOfSize(baseFilename + ".123", 16);
+    Path invalidExtension = newFileOfSize(baseFilename + "19900101-120000.invalid", 16);
+    Path oldDeleted1 = newFileOfSize(baseFilename + "19900101-120000.123", 16);
+    Path oldDeleted2 = newFileOfSize(baseFilename + "19950101-120000.123", 16);
+    Path keptThenDeleted = newFileOfSize(baseFilename + "19990101-120000.123", 16);
+    Path kept = newFileOfSize(baseFilename + "19990606-060000.123", 16);
+
+    FakeClock clock = new FakeClock(Instant.parse("2018-01-01T12:00:00Z"), ZoneOffset.UTC);
+    SimpleLogHandler handler =
+        SimpleLogHandler.builder()
+            .setPrefix(tmp.getRoot() + File.separator + "hello")
+            .setPattern(".%h.%u.log.java.")
+            .setFormatter(new TrivialFormatter())
+            .setRotateLimitBytes(16)
+            .setTotalLimitBytes(40)
+            .setClockForTesting(clock)
+            .build();
+    // Print 8 bytes into the log file. Opening the log file triggers deletion of old logs.
+    handler.publish(new LogRecord(Level.SEVERE, "1234567" /* 8 bytes including "\n" */));
+
+    // We expect handler to delete all but 32 = 40 - 8 bytes worth of old log files.
+    assertThat(Files.exists(nonLog)).isTrue();
+    assertThat(Files.exists(missingDate)).isTrue();
+    assertThat(Files.exists(invalidExtension)).isTrue();
+    assertThat(Files.exists(oldDeleted1)).isFalse();
+    assertThat(Files.exists(oldDeleted2)).isFalse();
+    assertThat(Files.exists(keptThenDeleted)).isTrue();
+    assertThat(Files.exists(kept)).isTrue();
+
+    handler.publish(new LogRecord(Level.SEVERE, "1234567" /* 8 bytes including "\n" */));
+    Path currentLogPath = handler.getCurrentLogFilePath().get();
+    handler.close();
+
+    // We expect another old log file to be deleted after rotation.
+    assertThat(Files.exists(keptThenDeleted)).isFalse();
+    assertThat(Files.exists(kept)).isTrue();
+    assertThat(Files.exists(currentLogPath)).isTrue();
+  }
+}