Add a custom single-line formatter for java.log.

This logger makes it easier to parse log statements and is now enabled for Bazel's java.log.

RELNOTES[INC]: Bazel now prints logs in single lines to java.log

PiperOrigin-RevId: 152954337

src/main/cpp/startup_options.cc

@@ -55,7 +55,8 @@ StartupOptions::StartupOptions(const string &product_name,
       connect_timeout_secs(10),
       invocation_policy(NULL),
       client_debug(false),
-      java_logging_formatter("java.util.logging.SimpleFormatter") {
+      java_logging_formatter(
+          "com.google.devtools.build.lib.util.SingleLineFormatter") {
   bool testing = !blaze::GetEnv("TEST_TMPDIR").empty();
   if (testing) {
     output_root = MakeAbsolute(blaze::GetEnv("TEST_TMPDIR"));

src/main/java/com/google/devtools/build/lib/BUILD

@@ -274,6 +274,15 @@ java_library(
     ],
 )
 
+java_library(
+    name = "single-line-formatter",
+    srcs = ["util/SingleLineFormatter.java"],
+    deps = [
+        "//third_party:guava",
+        "//third_party:joda_time",
+    ],
+)
+
 java_library(
     name = "util",
     srcs = glob(
@@ -286,6 +295,7 @@ java_library(
             "util/OS.java",
             "util/Preconditions.java",
             "util/ProcessUtils.java",
+            "util/SingleLineFormatter.java",
             "util/StringCanonicalizer.java",
             "util/StringTrie.java",
             "util/VarInt.java",
@@ -1192,6 +1202,7 @@ java_binary(
     main_class = "com.google.devtools.build.lib.bazel.BazelMain",
     runtime_deps = [
         ":bazel-main",
+        ":single-line-formatter",  # See startup_options.cc
     ],
 )
 

src/main/java/com/google/devtools/build/lib/util/SingleLineFormatter.java

@@ -0,0 +1,87 @@
+// Copyright 2017 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 com.google.common.collect.ImmutableRangeMap;
+import com.google.common.collect.Range;
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.util.logging.Formatter;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import org.joda.time.format.DateTimeFormat;
+import org.joda.time.format.DateTimeFormatter;
+
+/**
+ * Formatter to write java.util.logging messages out in single-line format.
+ *
+ * <p>Log entries contain the date and time (in UTC), log level (as letter and numerical value),
+ * source location, thread ID, message and, if applicable, a stack trace.
+ */
+public class SingleLineFormatter extends Formatter {
+
+  /** Single-character codes based on {@link Level}s. */
+  private static final ImmutableRangeMap<Integer, Character> CODES_BY_LEVEL =
+      ImmutableRangeMap.<Integer, Character>builder()
+          .put(Range.atMost(Level.FINE.intValue()), 'D')
+          .put(Range.open(Level.FINE.intValue(), Level.WARNING.intValue()), 'I')
+          .put(Range.closedOpen(Level.WARNING.intValue(), Level.SEVERE.intValue()), 'W')
+          .put(Range.atLeast(Level.SEVERE.intValue()), 'X')
+          .build();
+
+  /** A thread safe, immutable formatter that can be used by all without contention. */
+  private static final DateTimeFormatter DATE_TIME_FORMAT =
+      DateTimeFormat.forPattern("yyMMdd HH:mm:ss.SSS").withZoneUTC();
+
+  @Override
+  public String format(LogRecord rec) {
+    StringBuilder buf = new StringBuilder();
+
+    // Timestamp
+    buf.append(DATE_TIME_FORMAT.print(rec.getMillis()))
+        .append(':');
+
+    // One character code for level
+    buf.append(CODES_BY_LEVEL.get(rec.getLevel().intValue()));
+
+    // The stack trace, if any
+    Throwable thrown = rec.getThrown();
+    if (thrown != null) {
+      buf.append('T');
+    }
+
+    buf.append(' ');
+
+    // Information about the source of the exception
+    buf.append(rec.getThreadID())
+        .append(" [")
+        .append(rec.getSourceClassName())
+        .append('.')
+        .append(rec.getSourceMethodName())
+        .append("] ");
+
+    // The actual message
+    buf.append(formatMessage(rec)).append('\n');
+
+    if (thrown != null) {
+      StringWriter sw = new StringWriter();
+      PrintWriter pw = new PrintWriter(sw);
+      thrown.printStackTrace(pw);
+      pw.flush();
+      buf.append(sw.toString());
+    }
+
+    return buf.toString();
+  }
+}

src/test/cpp/startup_options_test.cc

@@ -61,7 +61,7 @@ TEST_F(StartupOptionsTest, ProductName) {
 }
 
 TEST_F(StartupOptionsTest, JavaLoggingOptions) {
-  ASSERT_EQ("java.util.logging.SimpleFormatter",
+  ASSERT_EQ("com.google.devtools.build.lib.util.SingleLineFormatter",
       startup_options_->java_logging_formatter);
 }
 

src/test/java/com/google/devtools/build/lib/BUILD

@@ -167,12 +167,14 @@ java_test(
         "//src/main/java/com/google/devtools/build/lib:os_util",
         "//src/main/java/com/google/devtools/build/lib:packages",
         "//src/main/java/com/google/devtools/build/lib:shell",
+        "//src/main/java/com/google/devtools/build/lib:single-line-formatter",
         "//src/main/java/com/google/devtools/build/lib:unix",
         "//src/main/java/com/google/devtools/build/lib:util",
         "//src/main/java/com/google/devtools/build/lib:vfs",
         "//src/main/java/com/google/devtools/common/options",
         "//third_party:guava",
         "//third_party:guava-testlib",
+        "//third_party:joda_time",
         "//third_party:junit4",
         "//third_party:truth",
     ],

src/test/java/com/google/devtools/build/lib/util/SingleLineFormatterTest.java

@@ -0,0 +1,82 @@
+// Copyright 2017 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 java.util.logging.Level;
+import java.util.logging.LogRecord;
+import org.joda.time.DateTime;
+import org.joda.time.DateTimeZone;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.junit.runners.JUnit4;
+
+@RunWith(JUnit4.class)
+public class SingleLineFormatterTest {
+
+  private static final DateTime TIMESTAMP =
+      new DateTime(2017, 04, 01, 17, 03, 43, 142, DateTimeZone.UTC);
+
+  @Test
+  public void testFormat() {
+    LogRecord logRecord = createLogRecord(Level.SEVERE, TIMESTAMP);
+    assertThat(new SingleLineFormatter().format(logRecord))
+        .isEqualTo("170401 17:03:43.142:X 543 [SomeSourceClass.aSourceMethod] some message\n");
+  }
+
+  @Test
+  public void testLevel() {
+    LogRecord logRecord = createLogRecord(Level.WARNING, TIMESTAMP);
+    String formatted = new SingleLineFormatter().format(logRecord);
+    assertThat(formatted).contains("W");
+    assertThat(formatted).doesNotContain("X");
+  }
+
+  @Test
+  public void testTime() {
+    LogRecord logRecord =
+        createLogRecord(
+            Level.SEVERE, new DateTime(1999, 11, 30, 03, 04, 05, 722, DateTimeZone.UTC));
+    assertThat(new SingleLineFormatter().format(logRecord)).contains("991130 03:04:05.722");
+  }
+
+  @Test
+  public void testStackTrace() {
+    LogRecord logRecord = createLogRecord(
+        Level.SEVERE, TIMESTAMP, new RuntimeException("something wrong"));
+    assertThat(new SingleLineFormatter().format(logRecord))
+        .startsWith(
+            "170401 17:03:43.142:XT 543 [SomeSourceClass.aSourceMethod] some message\n"
+            + "java.lang.RuntimeException: something wrong\n"
+            + "\tat com.google.devtools.build.lib.util.SingleLineFormatterTest.testStackTrace");
+  }
+
+  private static LogRecord createLogRecord(Level level, DateTime dateTime) {
+    return createLogRecord(level, dateTime, null);
+  }
+
+  private static LogRecord createLogRecord(
+      Level level, DateTime dateTime, RuntimeException thrown) {
+    LogRecord record = new LogRecord(level, "some message");
+    record.setMillis(dateTime.getMillis());
+    record.setSourceClassName("SomeSourceClass");
+    record.setSourceMethodName("aSourceMethod");
+    record.setThreadID(543);
+    if (thrown != null) {
+      record.setThrown(thrown);
+    }
+    return record;
+  }
+}

src/test/shell/integration/BUILD

@@ -258,6 +258,13 @@ sh_test(
     tags = ["jdk8"],
 )
 
+sh_test(
+    name = "logging_test",
+    size = "medium",
+    srcs = ["logging_test.sh"],
+    data = [":test-deps"],
+)
+
 test_suite(
     name = "all_tests",
     visibility = ["//visibility:public"],

src/test/shell/integration/execution_phase_tests.sh

@@ -47,7 +47,7 @@ function assert_last_log() {
   local log="${1}"; shift
   local fail_message="${1}"; shift
 
-  if ! grep -A1 "${context}" "${log}" | tail -n1 | grep -q "${message}" ; then
+  if ! grep "${context}" "${log}" | grep -q "${message}" ; then
     cat "${log}" >>"${TEST_log}"  # Help debugging when we fail.
     fail "${fail_message}"
   fi
@@ -60,7 +60,7 @@ function assert_cache_stats() {
   local exp_value="${1}"; shift
 
   local java_log="$(bazel info output_base 2>/dev/null)/java.log"
-  local last="$(grep -A1 "CacheFileDigestsModule" "${java_log}" | tail -n1)"
+  local last="$(grep "CacheFileDigestsModule" "${java_log}")"
   [ -n "${last}" ] || fail "Could not find cache stats in log"
   if ! echo "${last}" | grep -q "${metric}=${exp_value}"; then
     echo "Last cache stats: ${last}" >>"${TEST_log}"

src/test/shell/integration/logging_test.sh

@@ -0,0 +1,43 @@
+#!/bin/bash
+#
+# Copyright 2017 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.
+#
+# Test of Bazel's java logging.
+
+set -e
+
+# Load the test setup defined in the parent directory
+CURRENT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
+source "${CURRENT_DIR}/../integration_test_setup.sh" \
+  || { echo "integration_test_setup.sh not found!" >&2; exit 1; }
+
+function test_log_file_uses_single_line_formatter() {
+  local client_log="$(bazel info output_base)/java.log"
+
+  # Construct a regular expression to match a sample message in the log using
+  # the single-line format.  More specifically, we expect the log entry's
+  # context (timestamp, severity and class) to appear in the same line as the
+  # actual log message.
+  local timestamp_re='[0-9]{6} [0-9]{2}:[0-9]{2}:[0-9]{2}.[0-9]{3}'
+  local sample_re="^${timestamp_re}:I .*BlazeVersionInfo"
+
+  if ! grep -E "${sample_re}" "${client_log}"; then
+    # Dump some client log lines on stdout for debugging of this test failure.
+    head -n 10 "${client_log}"
+    fail "invalid format in java.log; see output for sample lines"
+  fi
+}
+
+run_suite "${PRODUCT_NAME} logging test"