diff options
4 files changed, 1247 insertions, 0 deletions
diff --git a/src/main/java/com/google/devtools/build/lib/BUILD b/src/main/java/com/google/devtools/build/lib/BUILD index 9455863933..454c3ec42d 100644 --- a/src/main/java/com/google/devtools/build/lib/BUILD +++ b/src/main/java/com/google/devtools/build/lib/BUILD @@ -171,6 +171,17 @@ java_library( ) java_library( + name = "simple-log-handler", + srcs = ["util/SimpleLogHandler.java"], + deps = [ + ":single-line-formatter", + ":util", + "//third_party:guava", + "//third_party:jsr305", + ], +) + +java_library( name = "util", srcs = glob( ["util/*.java"], @@ -184,6 +195,7 @@ java_library( "util/OS.java", "util/ProcessUtils.java", "util/ResourceUsage.java", + "util/SimpleLogHandler.java", "util/SingleLineFormatter.java", "util/StringCanonicalizer.java", "util/StringTrie.java", diff --git a/src/main/java/com/google/devtools/build/lib/util/SimpleLogHandler.java b/src/main/java/com/google/devtools/build/lib/util/SimpleLogHandler.java new file mode 100644 index 0000000000..5b46123dbd --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/util/SimpleLogHandler.java @@ -0,0 +1,845 @@ +// 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.base.Preconditions.checkArgument; +import static com.google.common.base.Preconditions.checkNotNull; +import static com.google.common.base.Preconditions.checkState; +import static java.nio.charset.StandardCharsets.UTF_8; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.Strings; +import com.google.common.io.CountingOutputStream; +import com.google.common.net.InetAddresses; +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.io.OutputStreamWriter; +import java.lang.management.ManagementFactory; +import java.nio.file.DirectoryStream; +import java.nio.file.Files; +import java.nio.file.Path; +import java.text.ParseException; +import java.text.ParsePosition; +import java.text.SimpleDateFormat; +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneId; +import java.util.Date; +import java.util.Optional; +import java.util.PriorityQueue; +import java.util.TimeZone; +import java.util.function.Function; +import java.util.logging.ErrorManager; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.LogRecord; +import javax.annotation.Nullable; +import javax.annotation.concurrent.GuardedBy; + +/** + * A simple file-based logging handler that points a short symlink to the current log file and + * provides an API for getting the current log file. + * + * <p>The log file path is concatenated from 4 elements: the prefix (a fixed string, typically a + * directory); the pattern (allowing some % variable substitutions); the timestamp; and the + * extension. + * + * <p>The handler can be configured from the JVM command line: <code> + * -Djava.util.logging.config.file=/foo/bar/javalog.properties + * </code> where the javalog.properties file might contain something like <code> + * handlers=com.google.devtools.build.lib.util.SimpleLogHandler + * com.google.devtools.build.lib.util.SimpleLogHandler.level=INFO + * com.google.devtools.build.lib.util.SimpleLogHandler.prefix=/foo/bar/logs/java.log + * com.google.devtools.build.lib.util.SimpleLogHandler.rotate_limit_bytes=1048576 + * com.google.devtools.build.lib.util.SimpleLogHandler.total_limit_bytes=10485760 + * com.google.devtools.build.lib.util.SimpleLogHandler.formatter=com.google.devtools.build.lib.util.SingleLineFormatter + * </code> + * + * <p>The handler is thread-safe. IO operations ({@link #publish}, {@link #flush}, {@link #close}) + * and {@link #getCurrentLogFilePath} block other access to the handler until completed. + */ +public final class SimpleLogHandler extends Handler { + /** Max number of bytes to write before rotating the log. */ + private final int rotateLimitBytes; + /** Max number of bytes in all logs to keep before deleting oldest ones. */ + private final int totalLimitBytes; + /** Log file extension; the current process ID by default. */ + private final String extension; + /** True if the log file extension is not the process ID. */ + private final boolean isStaticExtension; + /** Absolute path to symbolic link to current log file. */ + private final Path symlinkPath; + /** Absolute path to common base name of log files. */ + @VisibleForTesting final Path baseFilePath; + /** Log file currently in use. */ + @GuardedBy("this") + private final Output output = new Output(); + + private static final String DEFAULT_PREFIX_STRING = "java.log"; + private static final String DEFAULT_BASE_FILE_NAME_PATTERN = ".%h.%u.log.java."; + /** Source for timestamps in filenames; non-static for testing. */ + private final Clock clock; + + @VisibleForTesting static final String DEFAULT_TIMESTAMP_FORMAT = "yyyyMMdd-HHmmss."; + /** + * Timestamp format for log filenames; non-static because {@link SimpleDateFormat} is not + * thread-safe. + */ + @GuardedBy("this") + private final SimpleDateFormat timestampFormat = new SimpleDateFormat(DEFAULT_TIMESTAMP_FORMAT); + + /** Creates a new {@link Builder}. */ + public static Builder builder() { + return new Builder(); + } + + /** + * Builder class for {@link SimpleLogHandler}. + * + * <p>All setters are optional; if unset, values from the JVM logging configuration or (if those + * too are unset) reasonable fallback values will be used. See individual setter documentation. + */ + public static final class Builder { + private String prefix; + private String pattern; + private String extension; + private String symlink; + private Integer rotateLimitBytes; + private Integer totalLimitBytes; + private Level logLevel; + private Formatter formatter; + private Clock clock; + + public Builder setPrefix(String prefix) { + this.prefix = prefix; + return this; + } + + /** + * Sets the pattern for the log file name. The pattern may contain the following variables: + * + * <ul> + * <li><code>%u</code> will be expanded to the username + * <li><code>%h</code> will be expanded to the hostname + * <li><code>%%</code> will be expanded to % + * </ul> + * + * <p>The log file name will be constructed by appending the expanded pattern to the prefix and + * then by appending a timestamp and the extension. + * + * <p>If unset, the value of "pattern" from the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, {@link #DEFAULT_BASE_FILE_NAME_PATTERN} + * will be used. + * + * @param pattern the pattern string, possibly containing <code>%u</code>, <code>%h</code>, + * <code>%%</code> variables as above + * @return this {@code Builder} object + */ + public Builder setPattern(String pattern) { + this.pattern = pattern; + return this; + } + + /** + * Sets the log file extension. + * + * <p>If unset, the value of "extension" from the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, the process ID will be used. + * + * @param extension log file extension + * @return this {@code Builder} object + */ + public Builder setExtension(String extension) { + this.extension = extension; + return this; + } + + /** + * Sets the log file symlink filename. + * + * <p>If unset, the value of "symlink" from the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, the prefix will be used. + * + * @param symlink either symlink filename without a directory part, or an absolute path whose + * directory part matches the prefix + * @return this {@code Builder} object + */ + public Builder setSymlink(String symlink) { + this.symlink = symlink; + return this; + } + + /** + * Sets the log file size limit; if unset or 0, log size is unlimited. + * + * <p>If unset, the value of "rotate_limit_bytes" from the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, the log fie size is unlimited. + * + * @param rotateLimitBytes maximum log file size in bytes; must be >= 0; 0 means unlimited + * @return this {@code Builder} object + */ + public Builder setRotateLimitBytes(int rotateLimitBytes) { + this.rotateLimitBytes = Integer.valueOf(rotateLimitBytes); + return this; + } + + /** + * Sets the total rotateLimitBytes for log files. + * + * <p>If set, when opening a new handler or rotating a log file, the handler will scan for all + * log files with names matching the expected prefix, pattern, timestamp format, and extension, + * and delete the oldest ones to keep the total size under rotateLimitBytes. + * + * <p>If unset, the value of "total_limit_bytes" from the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, the total log size is unlimited. + * + * @param totalLimitBytes maximum total log file size in bytes; must be >= 0; 0 means unlimited + * @return this {@code Builder} object + */ + public Builder setTotalLimitBytes(int totalLimitBytes) { + this.totalLimitBytes = Integer.valueOf(totalLimitBytes); + return this; + } + + /** + * Sets the minimum level at which to log records. + * + * <p>If unset, the level named by the "level" field in the JVM logging configuration for {@link + * SimpleLogHandler} will be used; and if that's unset, all records are logged. + * + * @param logLevel minimum log level + * @return this {@code Builder} object + */ + public Builder setLogLevel(Level logLevel) { + this.logLevel = logLevel; + return this; + } + + /** + * Sets the log formatter. + * + * <p>If unset, the class named by the "formatter" field in the JVM logging configuration for + * {@link SimpleLogHandler} will be used; and if that's unset, {@link SingleLineFormatter} will + * be used. + * + * @param formatter log formatter + * @return this {@code Builder} object + */ + public Builder setFormatter(Formatter formatter) { + this.formatter = formatter; + return this; + } + + /** + * Sets the time source for timestamps in log filenames. + * + * <p>Intended for testing. If unset, the system clock in the system timezone will be used. + * + * @param clock time source for timestamps + * @return this {@code Builder} object + */ + @VisibleForTesting + Builder setClockForTesting(Clock clock) { + this.clock = clock; + return this; + } + + /** Builds a {@link SimpleLogHandler} instance. */ + public SimpleLogHandler build() { + return new SimpleLogHandler( + prefix, + pattern, + extension, + symlink, + rotateLimitBytes, + totalLimitBytes, + logLevel, + formatter, + clock); + } + } + + /** + * Constructs a log handler with all state taken from the JVM logging configuration or (as + * fallback) the defaults; see {@link SimpleLogHandler.Builder} documentation. + * + * @throws IllegalArgumentException if invalid JVM logging configuration values are encountered; + * see {@link SimpleLogHandler.Builder} documentation + */ + public SimpleLogHandler() { + this(null, null, null, null, null, null, null, null, null); + } + + /** + * Constructs a log handler, falling back to the JVM logging configuration or (as last fallback) + * the defaults for those arguments which are null; see {@link SimpleLogHandler.Builder} + * documentation. + * + * @throws IllegalArgumentException if invalid non-null arguments or configured values are + * encountered; see {@link SimpleLogHandler.Builder} documentation + */ + private SimpleLogHandler( + @Nullable String prefix, + @Nullable String pattern, + @Nullable String extension, + @Nullable String symlink, + @Nullable Integer rotateLimitBytes, + @Nullable Integer totalLimit, + @Nullable Level logLevel, + @Nullable Formatter formatter, + @Nullable Clock clock) { + this.baseFilePath = + getBaseFilePath( + getConfiguredStringProperty(prefix, "prefix", DEFAULT_PREFIX_STRING), + getConfiguredStringProperty(pattern, "pattern", DEFAULT_BASE_FILE_NAME_PATTERN)); + this.symlinkPath = + getSymlinkAbsolutePath( + this.baseFilePath.getParent(), + getConfiguredStringProperty( + symlink, + "symlink", + getConfiguredStringProperty(prefix, "prefix", DEFAULT_PREFIX_STRING))); + this.extension = getConfiguredStringProperty(extension, "extension", getPidString()); + this.isStaticExtension = (getConfiguredStringProperty(extension, "extension", null) != null); + this.rotateLimitBytes = getConfiguredIntProperty(rotateLimitBytes, "rotate_limit_bytes", 0); + checkArgument(this.rotateLimitBytes >= 0, "File size limits cannot be negative"); + this.totalLimitBytes = getConfiguredIntProperty(totalLimit, "total_limit_bytes", 0); + checkArgument(this.totalLimitBytes >= 0, "File size limits cannot be negative"); + setLevel(getConfiguredLevelProperty(logLevel, "level", Level.ALL)); + setFormatter(getConfiguredFormatterProperty(formatter, "formatter", new SingleLineFormatter())); + if (clock != null) { + this.clock = clock; + this.timestampFormat.setTimeZone(TimeZone.getTimeZone(clock.getZone())); + } else { + this.clock = Clock.system(ZoneId.systemDefault()); + } + } + + /** + * Returns the absolute path of the current log file if a log file is open or {@code + * Optional#empty()} otherwise. + * + * <p>Since the log file is opened lazily, this method is expected to return {@code + * Optional#empty()} if no record has yet been published. + */ + public synchronized Optional<Path> getCurrentLogFilePath() { + return output.isOpen() ? Optional.of(output.getPath()) : Optional.empty(); + } + + /** Returns the expected absolute path for the symbolic link to the current log file. */ + public Path getSymbolicLinkPath() { + return symlinkPath; + } + + @Override + public boolean isLoggable(LogRecord record) { + return record != null && super.isLoggable(record); + } + + @Override + public synchronized void publish(LogRecord record) { + if (!isLoggable(record)) { + // Silently ignore null or filtered records, matching FileHandler behavior. + return; + } + + try { + String message = getFormatter().format(record); + openOutputIfNeeded(); + output.write(message); + } catch (Exception e) { + reportError(null, e, ErrorManager.WRITE_FAILURE); + // Failing to log is non-fatal. Continue to try to rotate the log if necessary, which may fix + // the underlying IO problem with the file. + } + + try { + if (rotateLimitBytes > 0) { + output.closeIfByteCountAtleast(rotateLimitBytes); + openOutputIfNeeded(); + } + } catch (IOException e) { + reportError("Failed to rotate log file", e, ErrorManager.GENERIC_FAILURE); + } + } + + @Override + public synchronized void flush() { + if (output.isOpen()) { + try { + output.flush(); + } catch (IOException e) { + reportError(null, e, ErrorManager.FLUSH_FAILURE); + } + } + } + + @Override + public synchronized void close() { + if (output.isOpen()) { + try { + output.write(getFormatter().getTail(this)); + } catch (IOException e) { + reportError("Failed to write log tail", e, ErrorManager.WRITE_FAILURE); + } + + try { + output.close(); + } catch (IOException e) { + reportError(null, e, ErrorManager.CLOSE_FAILURE); + } + } + } + + /** + * Checks if a value is null, and if it is, falls back to the JVM logging configuration, and if + * that too is missing, to a provided fallback value. + * + * @param builderValue possibly null value provided by the caller, e.g. from {@link + * SimpleLogHandler.Builder} + * @param configuredName field name in the JVM logging configuration for {@link SimpleLogHandler} + * @param parse parser for the string value from the JVM logging configuration + * @param fallbackValue fallback to use if the {@code builderValue} is null and no value is + * configured in the JVM logging configuration + * @param <T> value type + */ + private static @Nullable <T> T getConfiguredProperty( + @Nullable T builderValue, + String configuredName, + Function<String, T> parse, + @Nullable T fallbackValue) { + if (builderValue != null) { + return builderValue; + } + + String configuredValue = + LogManager.getLogManager() + .getProperty(SimpleLogHandler.class.getName() + "." + configuredName); + if (configuredValue != null) { + return parse.apply(configuredValue); + } + return fallbackValue; + } + + /** Matches java.logging.* configuration behavior; configured strings are trimmed. */ + private static String getConfiguredStringProperty( + String builderValue, String configuredName, String fallbackValue) { + return getConfiguredProperty(builderValue, configuredName, val -> val.trim(), fallbackValue); + } + + /** + * Empty configured values are ignored and the fallback is used instead. + * + * @throws NumberFormatException if the configured formatter value is non-numeric + */ + private static int getConfiguredIntProperty( + Integer builderValue, String configuredName, int fallbackValue) { + Integer value = + getConfiguredProperty( + builderValue, + configuredName, + val -> { + val = val.trim(); + return val.length() > 0 ? Integer.parseInt(val) : null; + }, + null); + return value != null ? value.intValue() : fallbackValue; + } + + /** + * Empty configured values are ignored and the fallback is used instead. + * + * @throws IllegalArgumentException if the configured level name cannot be parsed + */ + private static Level getConfiguredLevelProperty( + Level builderValue, String configuredName, Level fallbackValue) { + Level value = + getConfiguredProperty( + builderValue, + configuredName, + val -> { + val = val.trim(); + return val.length() > 0 ? Level.parse(val) : null; + }, + null); + return value != null ? value : fallbackValue; + } + + /** + * Empty configured values are ignored and the fallback is used instead. + * + * @throws IllegalArgumentException if a formatter object cannot be instantiated from the + * configured class name + */ + private static Formatter getConfiguredFormatterProperty( + Formatter builderValue, String configuredName, Formatter fallbackValue) { + return getConfiguredProperty( + builderValue, + configuredName, + val -> { + val = val.trim(); + if (val.length() > 0) { + try { + return (Formatter) + ClassLoader.getSystemClassLoader() + .loadClass(val) + .getDeclaredConstructor() + .newInstance(); + } catch (ReflectiveOperationException e) { + throw new IllegalArgumentException(e); + } + } else { + return fallbackValue; + } + }, + fallbackValue); + } + + @VisibleForTesting + static String getPidString() { + long pid; + try { + // TODO(b/78168359): Replace with ProcessHandle.current().pid() in Java 9 + pid = Long.parseLong(ManagementFactory.getRuntimeMXBean().getName().split("@", -1)[0]); + } catch (NumberFormatException e) { + // getRuntimeMXBean().getName() output is implementation-specific, may be unparseable. + pid = 0; + } + return Long.toString(pid); + } + + @VisibleForTesting + static String getLocalHostnameFirstComponent() { + String name = NetUtil.getCachedShortHostName(); + if (!InetAddresses.isInetAddress(name)) { + // Keep only the first component of the name. + int firstDot = name.indexOf('.'); + if (firstDot >= 0) { + name = name.substring(0, firstDot); + } + } + return name.toLowerCase(); + } + + /** + * Creates the log file absolute base path according to the given pattern. + * + * @param prefix non-null string to prepend to the base path + * @param pattern non-null string which may include the following variables: %h will be expanded + * to the hostname; %u will be expanded to the username; %% will be expanded to % + * @throws IllegalArgumentException if an unknown variable is encountered in the pattern + */ + private static Path getBaseFilePath(String prefix, String pattern) { + checkNotNull(prefix, "prefix"); + checkNotNull(pattern, "pattern"); + + StringBuilder sb = new StringBuilder(100); // Typical name is < 100 bytes + boolean inVar = false; + String username = System.getProperty("user.name"); + + if (Strings.isNullOrEmpty(username)) { + username = "unknown_user"; + } + + sb.append(prefix); + + for (int i = 0; i < pattern.length(); ++i) { + char c = pattern.charAt(i); + if (inVar) { + inVar = false; + switch (c) { + case '%': + sb.append('%'); + break; + case 'h': + sb.append(getLocalHostnameFirstComponent()); + break; + case 'u': + sb.append(username); + break; + default: + throw new IllegalArgumentException("Unknown variable " + c + " in " + pattern); + } + } else { + if (c == '%') { + inVar = true; + } else { + sb.append(c); + } + } + } + + return new File(sb.toString()).getAbsoluteFile().toPath(); + } + + /** + * Returns the absolute path for a symlink in the specified directory. + * + * @throws IllegalArgumentException if the symlink includes a directory component which doesn't + * equal {@code logDir} + */ + private static Path getSymlinkAbsolutePath(Path logDir, String symlink) { + checkNotNull(symlink); + checkArgument(symlink.length() > 0); + File symlinkFile = new File(symlink); + if (!symlinkFile.isAbsolute()) { + symlinkFile = new File(logDir + File.separator + symlink); + } + checkArgument( + symlinkFile.toPath().getParent().equals(logDir), + "symlink is not a top-level file in logDir"); + return symlinkFile.toPath(); + } + + private static final class Output { + /** Log file currently in use. */ + private @Nullable File file; + /** Output stream for {@link #file} which counts the number of bytes written. */ + private @Nullable CountingOutputStream stream; + /** Writer for {@link #stream}. */ + private @Nullable OutputStreamWriter writer; + + public boolean isOpen() { + return writer != null; + } + + /** + * Opens the specified file in append mode, first closing the current file if needed. + * + * @throws IOException if the file could not be opened + */ + public void open(String path) throws IOException { + try { + close(); + file = new File(path); + stream = new CountingOutputStream(new FileOutputStream(file, true)); + writer = new OutputStreamWriter(stream, UTF_8); + } catch (IOException e) { + close(); + throw e; + } + } + + /** + * Returns the currently open file's path. + * + * @throws NullPointerException if not open + */ + public Path getPath() { + return file.toPath(); + } + + /** + * Writes the string to the current file in UTF-8 encoding. + * + * @throws NullPointerException if not open + * @throws IOException if an underlying IO operation failed + */ + public void write(String string) throws IOException { + writer.write(string); + } + + /** + * Flushes the current file. + * + * @throws NullPointerException if not open + * @throws IOException if an underlying IO operation failed + */ + public void flush() throws IOException { + writer.flush(); + } + + /** + * Closes the current file if it is open. + * + * @throws IOException if an underlying IO operation failed + */ + public void close() throws IOException { + try { + if (isOpen()) { + writer.close(); + } + } finally { + writer = null; + stream = null; + file = null; + } + } + + /** + * Closes the current file unless the number of bytes written to it was under the specified + * limit. + * + * @throws NullPointerException if not open + * @throws IOException if an underlying IO operation failed + */ + public void closeIfByteCountAtleast(int limit) throws IOException { + if (stream.getCount() < limit && stream.getCount() + 8192L >= limit) { + // The writer and its internal encoder buffer output before writing to the output stream. + // The default size of the encoder's buffer is 8192 bytes. To count the bytes in the output + // stream accurately, we have to flush. But flushing unnecessarily harms performance; let's + // flush only when it matters - per record and within expected buffer size from the limit. + flush(); + } + if (stream.getCount() >= limit) { + close(); + } + } + } + + /** + * Opens a new log file if one is not open, updating the symbolic link and deleting old logs if + * needed. + */ + @GuardedBy("this") + private void openOutputIfNeeded() { + if (!output.isOpen()) { + // Ensure the log file's directory exists. + checkState(baseFilePath.isAbsolute()); + baseFilePath.getParent().toFile().mkdirs(); + + try { + output.open( + baseFilePath + timestampFormat.format(Date.from(Instant.now(clock))) + extension); + output.write(getFormatter().getHead(this)); + } catch (IOException e) { + try { + output.close(); + } catch (IOException eClose) { + // Already handling a prior IO failure. + } + reportError("Failed to open log file", e, ErrorManager.OPEN_FAILURE); + return; + } + + if (totalLimitBytes > 0) { + deleteOldLogs(); + } + + // Try to create relative symlink from currentLogFile to baseFile, but don't treat a failure + // as fatal. + try { + checkState(symlinkPath.getParent().equals(output.getPath().getParent())); + if (Files.exists(symlinkPath)) { + Files.delete(symlinkPath); + } + Files.createSymbolicLink(symlinkPath, output.getPath().getFileName()); + } catch (IOException e) { + reportError("Failed to create symbolic link to log file", e, ErrorManager.GENERIC_FAILURE); + } + } + } + + /** + * Parses the absolute path of a logfile (e.g from a previous run of the program) and extracts the + * timestamp. + * + * @throws ParseException if the path does not match the expected prefix, resolved pattern, + * timestamp format, or extension + */ + @GuardedBy("this") + private Date parseLogFileTimestamp(Path path) throws ParseException { + String pathString = path.toString(); + if (!pathString.startsWith(baseFilePath.toString())) { + throw new ParseException("Wrong prefix or pattern", 0); + } + ParsePosition parsePosition = new ParsePosition(baseFilePath.toString().length()); + Date timestamp = timestampFormat.parse(pathString, parsePosition); + if (timestamp == null) { + throw new ParseException("Wrong timestamp format", parsePosition.getErrorIndex()); + } + if (isStaticExtension) { + if (!pathString.substring(parsePosition.getIndex()).equals(extension)) { + throw new ParseException("Wrong file extension", parsePosition.getIndex()); + } + } else { + try { + Long.parseLong(pathString.substring(parsePosition.getIndex())); + } catch (NumberFormatException e) { + throw new ParseException("File extension is not a numeric PID", parsePosition.getIndex()); + } + } + return timestamp; + } + + /** + * File path ordered by timestamp. + */ + private static final class PathByTimestamp implements Comparable<PathByTimestamp> { + private final Path path; + private final Date timestamp; + private final long size; + + PathByTimestamp(Path path, Date timestamp, long size) { + this.path = path; + this.timestamp = timestamp; + this.size = size; + } + + Path getPath() { + return path; + } + + long getSize() { + return size; + } + + @Override + public int compareTo(PathByTimestamp rhs) { + return this.timestamp.compareTo(rhs.timestamp); + } + } + + /** + * Deletes the oldest log files matching the expected prefix, pattern, timestamp format, and + * extension, to keep the total size under {@link #totalLimitBytes} (if set to non-0). + * + * <p>Each log file's timestamp is determined only from the filename. The current log file will + * not be deleted. + */ + @GuardedBy("this") + private void deleteOldLogs() { + checkState(baseFilePath.isAbsolute()); + PriorityQueue<PathByTimestamp> queue = new PriorityQueue<>(); + long totalSize = 0; + try (DirectoryStream<Path> dirStream = Files.newDirectoryStream(baseFilePath.getParent())) { + for (Path path : dirStream) { + try { + Date timestamp = parseLogFileTimestamp(path); + long size = Files.size(path); + totalSize += size; + if (!output.getPath().equals(path)) { + queue.add(new PathByTimestamp(path, timestamp, size)); + } + } catch (ParseException e) { + // Ignore files which don't look like our logs. + } + } + + if (totalLimitBytes > 0) { + while (totalSize > totalLimitBytes && !queue.isEmpty()) { + PathByTimestamp entry = queue.poll(); + Files.delete(entry.getPath()); + totalSize -= entry.getSize(); + } + } + } catch (IOException e) { + reportError("Failed to clean up old log files", e, ErrorManager.GENERIC_FAILURE); + } + } +} 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(); + } +} |