diff --git a/jetty/src/test/java/google/registry/jetty/LoggingPropertiesTest.java b/jetty/src/test/java/google/registry/jetty/LoggingPropertiesTest.java index 973e2e6e2..9f830381b 100644 --- a/jetty/src/test/java/google/registry/jetty/LoggingPropertiesTest.java +++ b/jetty/src/test/java/google/registry/jetty/LoggingPropertiesTest.java @@ -21,6 +21,7 @@ import static java.nio.charset.StandardCharsets.UTF_8; import com.google.common.base.Splitter; import com.google.common.flogger.FluentLogger; import com.google.gson.Gson; +import com.google.gson.reflect.TypeToken; import java.io.ByteArrayOutputStream; import java.io.PrintStream; import java.util.Map; @@ -28,7 +29,6 @@ import java.util.Optional; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.TestInfo; /** * Unit tests for verifying the `logging.properties` used by the Nomulus image. @@ -68,7 +68,7 @@ class LoggingPropertiesTest { } @Test - void success_messageLogged_withTraceIdAndSourceLocation(TestInfo testInfo) { + void success_messageLogged_withTraceId() { logger.atInfo().log("My log message."); String logs = stdout.toString(UTF_8); Optional log = @@ -77,16 +77,7 @@ class LoggingPropertiesTest { .filter(line -> line.contains("My log message.")) .findAny(); assertThat(log).isPresent(); - Map logRecord = new Gson().fromJson(log.get(), Map.class); - assertThat(logRecord).containsEntry("severity", "INFO"); + Map logRecord = new Gson().fromJson(log.get(), new TypeToken<>() {}); assertThat(logRecord).containsEntry("logging.googleapis.com/trace", "my custom trace id"); - assertThat(logRecord).containsKey("message"); - assertThat(logRecord.get("message")).contains("My log message."); - // Verify that log contains full log site info: `{class_name} {method_name} line:{line_number}` - assertThat(logRecord.get("message")) - .containsMatch( - String.format( - "%s %s line:\\d+", - LoggingPropertiesTest.class.getName(), testInfo.getTestMethod().get().getName())); } } diff --git a/proxy/src/main/java/google/registry/proxy/ProxyModule.java b/proxy/src/main/java/google/registry/proxy/ProxyModule.java index a77fb8784..b1353018b 100644 --- a/proxy/src/main/java/google/registry/proxy/ProxyModule.java +++ b/proxy/src/main/java/google/registry/proxy/ProxyModule.java @@ -139,8 +139,7 @@ public class ProxyModule { // "io.netty.handler.logging.LoggingHandler" to actually process the logs. This JUL logger is // set to Level.FINE if the --log parameter is passed, so that it does not filter out logs // that the LoggingHandler writes. Otherwise, the logs are silently ignored because the - // default - // JUL logger level is Level.INFO. + // default JUL logger level is Level.INFO. JdkLoggerConfig.getConfig(LoggingHandler.class).setLevel(Level.FINE); // Log source IP information if --log parameter is passed. This is considered PII and should // only be used in non-production environment for debugging purpose. diff --git a/util/src/main/java/google/registry/util/GcpJsonFormatter.java b/util/src/main/java/google/registry/util/GcpJsonFormatter.java index c7d2de9ed..8cbafd708 100644 --- a/util/src/main/java/google/registry/util/GcpJsonFormatter.java +++ b/util/src/main/java/google/registry/util/GcpJsonFormatter.java @@ -21,6 +21,8 @@ import com.google.common.flogger.backend.system.SimpleLogRecord; import com.google.gson.Gson; import java.io.PrintWriter; import java.io.StringWriter; +import java.util.LinkedHashMap; +import java.util.Map; import java.util.Optional; import java.util.logging.Formatter; import java.util.logging.Level; @@ -29,17 +31,15 @@ import java.util.logging.LogRecord; /** * JUL formatter that formats log messages in a single-line JSON that Stackdriver logging can parse. * - *

There is no clear documentation on how to achieve this or on the format of the JSON. This is - * much a trial and error process, plus a lot of searching. To summarize, if the logs are printed to - * {@code STDOUT} or {@code STDERR} in a single-line JSON, with the content in the {@code message} - * field and the log level in the {@code severity} field, it will be picked up by Stackdriver - * logging agent running in GKE containers and logged at correct level.. + *

The structured logs written to {@code STDOUT} and {@code STDERR} will be picked up by GAE/GKE + * logging agent and automatically ingested by Stackdriver. Certain fields (see below) in the JSON + * will be converted to the corresponding {@code Log Entry} + * fields and parsed by Log Explorer. * * @see - * Formatting Python Logs from Stackdriver - * GKE & Stackdriver: Java logback logging format? + * href="https://cloud.google.com/logging/docs/structured-logging#structured_logging_special_fields"> + * Logging agent: special JSON fields */ public class GcpJsonFormatter extends Formatter { @@ -47,26 +47,30 @@ public class GcpJsonFormatter extends Formatter { private static final String SEVERITY = "severity"; /** - * JSON field that stores the calling class and function when the log occurs. - * - *

This field is not used by Stackdriver, but it is useful and can be found when the log - * entries are expanded + * JSON field that stores information regarding the source code location information associated + * with the log entry, if any. */ - private static final String SOURCE = "source"; + private static final String SOURCE_LOCATION = "logging.googleapis.com/sourceLocation"; /** JSON field that contains the content, this will show up as the main entry in a log. */ private static final String MESSAGE = "message"; + private static final String FILE = "file"; + + private static final String FUNCTION = "function"; + + private static final String LINE = "line"; + private static final Gson gson = new Gson(); @Override public String format(LogRecord record) { - // Add an extra newline before the message. Stackdriver does not show newlines correctly, and - // treats them as whitespace. If you want to see correctly formatted log message, expand the - // log and look for the jsonPayload.message field. This newline makes sure that the entire - // message starts on its own line, so that indentation within the message is correct. + // Add an extra newline before the message for better displaying of multi-line logs. To see the + // correctly indented multi-line logs, expand the log and look for the textPayload field. This + // newline makes sure that the entire message starts on its own line, so that indentation within + // the message is correct. - String message = "\n" + record.getMessage(); + String message = '\n' + record.getMessage(); String severity = severityFor(record.getLevel()); // The rest is mostly lifted from java.util.logging.SimpleFormatter. @@ -80,36 +84,56 @@ public class GcpJsonFormatter extends Formatter { stacktrace = sw.toString(); } - String source; + String function = ""; if (record.getSourceClassName() != null) { - source = record.getSourceClassName(); + function = record.getSourceClassName(); if (record.getSourceMethodName() != null) { - source += " " + record.getSourceMethodName(); + function += "." + record.getSourceMethodName(); } - if (record instanceof SimpleLogRecord simpleLogRecord) { - Optional lineNumber = - Optional.ofNullable(simpleLogRecord.getLogData()) - .map(LogData::getLogSite) - .map(LogSite::getLineNumber); - if (lineNumber.isPresent()) { - source += " line:" + lineNumber.get(); - } - } - - } else { - source = record.getLoggerName(); } + String line = ""; + String file = ""; + if (record instanceof SimpleLogRecord simpleLogRecord) { + Optional logSite = + Optional.ofNullable(simpleLogRecord.getLogData()).map(LogData::getLogSite); + if (logSite.isPresent()) { + line = String.valueOf(logSite.get().getLineNumber()); + file = logSite.get().getFileName(); + } + } + + Map sourceLocation = new LinkedHashMap<>(); + if (!file.isEmpty()) { + sourceLocation.put(FILE, file); + } + if (!line.isEmpty()) { + sourceLocation.put(LINE, line); + } + if (!function.isEmpty()) { + sourceLocation.put(FUNCTION, function); + } return gson.toJson( - ImmutableMap.of(SEVERITY, severity, SOURCE, source, MESSAGE, message + stacktrace)) + ImmutableMap.of( + SEVERITY, + severity, + SOURCE_LOCATION, + sourceLocation, + // ImmutableMap.of(FILE, file, LINE, line, FUNCTION, function), + MESSAGE, + message + stacktrace)) + // This trailing newline is required for the proxy because otherwise multiple logs might be + // sent to Stackdriver together (due to the async nature of the proxy), and not parsed + // correctly. + '\n'; } /** - * Map {@link Level} to a severity string that Stackdriver understands. + * Maps a {@link Level} to a severity string that Stackdriver understands. * * @see {@code LoggingHandler} + * href="https://github.com/googleapis/java-logging/blob/main/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java"> + * LoggingHandler.java */ private static String severityFor(Level level) { return switch (level.intValue()) { diff --git a/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java b/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java index 9dbfaa39f..a70a797fa 100644 --- a/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java +++ b/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java @@ -16,87 +16,122 @@ package google.registry.util; import static com.google.common.truth.Truth.assertThat; -import com.google.common.base.Joiner; +import com.google.common.flogger.FluentLogger; +import com.google.common.flogger.StackSize; +import java.io.ByteArrayOutputStream; +import java.nio.charset.StandardCharsets; +import java.util.logging.Handler; import java.util.logging.Level; -import java.util.logging.LogRecord; +import java.util.logging.Logger; +import java.util.logging.StreamHandler; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; -/** Unit tests for {@link GcpJsonFormatter}. */ +/** + * Unit tests for {@link GcpJsonFormatter}. + * + * @see + * GoogleLoggerTest.java + */ class GcpJsonFormatterTest { - private static final String LOGGER_NAME = "example.company.app.logger"; - private static final String SOURCE_CLASS_NAME = "example.company.app.component.Doer"; - private static final String SOURCE_METHOD_NAME = "doStuff"; - private static final String MESSAGE = "Something I have to say"; + private Logger jdkLogger; + private FluentLogger logger; + private Handler handler; + private ByteArrayOutputStream ostream; - private final GcpJsonFormatter formatter = new GcpJsonFormatter(); - private final LogRecord logRecord = new LogRecord(Level.WARNING, MESSAGE); + private static final String LOG_TEMPLATE = + """ + {"severity":"@@SEVERITY@@","logging.googleapis.com/sourceLocation":{"file":"GcpJsonFormatterTest.java","line":"@@LINE@@","function":"google.registry.util.GcpJsonFormatterTest.@@FUNCTION@@"},"message":"\\n@@MESSAGE@@"} + """; - private static String makeJson(String severity, String source, String message) { - return "{" - + Joiner.on(",") - .join( - makeJsonField("severity", severity), - makeJsonField("source", source), - makeJsonField("message", "\\n" + message)) - + "}\n"; - } - - private static String makeJsonField(String name, String content) { - return Joiner.on(":").join(addQuoteAndReplaceNewline(name), addQuoteAndReplaceNewline(content)); - } - - private static String addQuoteAndReplaceNewline(String content) { - // This quadruple escaping is hurting my eyes. - return "\"" + content.replaceAll("\n", "\\\\n") + "\""; + private static String makeJson(String severity, int line, String function, String message) { + return LOG_TEMPLATE + .replace("@@SEVERITY@@", severity) + .replace("@@LINE@@", String.valueOf(line)) + .replace("@@FUNCTION@@", function) + .replace("@@MESSAGE@@", message); } @BeforeEach void beforeEach() { - logRecord.setLoggerName(LOGGER_NAME); + logger = FluentLogger.forEnclosingClass(); + ostream = new ByteArrayOutputStream(); + handler = new StreamHandler(ostream, new GcpJsonFormatter()); + jdkLogger = Logger.getLogger(GcpJsonFormatterTest.class.getName()); + jdkLogger.setUseParentHandlers(false); + jdkLogger.addHandler(handler); + jdkLogger.setLevel(Level.INFO); + } + + @AfterEach + void afterEach() { + jdkLogger.removeHandler(handler); } @Test void testSuccess() { - String actual = formatter.format(logRecord); - String expected = makeJson("WARNING", LOGGER_NAME, MESSAGE); - assertThat(actual).isEqualTo(expected); + logger.atInfo().log("Something I have to say"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + assertThat(output).isEqualTo(makeJson("INFO", 76, "testSuccess", "Something I have to say")); } @Test - void testSuccess_sourceClassAndMethod() { - logRecord.setSourceClassName(SOURCE_CLASS_NAME); - logRecord.setSourceMethodName(SOURCE_METHOD_NAME); - String actual = formatter.format(logRecord); - String expected = makeJson("WARNING", SOURCE_CLASS_NAME + " " + SOURCE_METHOD_NAME, MESSAGE); - assertThat(actual).isEqualTo(expected); - } - - @Test - void testSuccess_multilineMessage() { - String multilineMessage = "First line message\nSecond line message\n"; - logRecord.setMessage(multilineMessage); - String actual = formatter.format(logRecord); - String expected = makeJson("WARNING", LOGGER_NAME, multilineMessage); - assertThat(actual).isEqualTo(expected); + void testSuccess_logLevel() { + logger.atSevere().log("Something went terribly wrong"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + assertThat(output) + .isEqualTo(makeJson("ERROR", 84, "testSuccess_logLevel", "Something went terribly wrong")); } @Test void testSuccess_withCause() { - Throwable throwable = new Throwable("Some reason"); - StackTraceElement[] stacktrace = { - new StackTraceElement("class1", "method1", "file1", 5), - new StackTraceElement("class2", "method2", "file2", 10), - }; - String stacktraceString = - "java.lang.Throwable: Some reason\\n" - + "\\tat class1.method1(file1:5)\\n" - + "\\tat class2.method2(file2:10)\\n"; - throwable.setStackTrace(stacktrace); - logRecord.setThrown(throwable); - String actual = formatter.format(logRecord); - String expected = makeJson("WARNING", LOGGER_NAME, MESSAGE + "\\n" + stacktraceString); - assertThat(actual).isEqualTo(expected); + logger.atSevere().withCause(new RuntimeException("boom!")).log("Something went terribly wrong"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + String prefix = + makeJson( + "ERROR", + 93, + "testSuccess_withCause", + "Something went terribly wrong\\njava.lang.RuntimeException: boom!"); + // Remove the last three characters (", }, \n) from the template as the actual output contains + // the full stack trace. + prefix = prefix.substring(0, prefix.length() - 3); + assertThat(output).startsWith(prefix); + } + + @Test + void testSuccess_withStackTrace() { + logger.atSevere().withStackTrace(StackSize.FULL).log("Something is worth checking"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + String prefix = + makeJson( + "ERROR", + 110, + "testSuccess_withStackTrace", + "Something is worth checking\\ncom.google.common.flogger.LogSiteStackTrace: FULL"); + // Remove the last three characters (", }, \n) from the template as the actual output contains + // the full stack trace. + prefix = prefix.substring(0, prefix.length() - 3); + assertThat(output).startsWith(prefix); + } + + @Test + void testSuccess_notFlogger() { + jdkLogger.log(Level.INFO, "Something I have to say"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + // Only flogger populates the file and line fields. + String expected = + makeJson("INFO", 4321, "testSuccess_notFlogger", "Something I have to say") + .replace("\"file\":\"GcpJsonFormatterTest.java\",", "") + .replace("\"line\":\"4321\",", ""); + assertThat(output).isEqualTo(expected); } }