mirrors/nomulus
1
0
Fork 0
mirror of https://github.com/google/nomulus synced 2025-12-23 14:25:44 +00:00
Code Issues Releases Wiki Activity

Update GcpJsonFormatter (#2437)

Browse Source 
Use the correct JSON field to store the source location info so it can
be parsed by Stackdriver.
This commit is contained in:
Lai Jiang
2024-05-10 12:47:52 -04:00
committed by GitHub
parent 7b34659a8f
commit 94dc9fd0d5
4 changed files with 159 additions and 110 deletions
Download Patch File Download Diff File Expand all files Collapse all files

15
jetty/src/test/java/google/registry/jetty/LoggingPropertiesTest.java
View File

@@ -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<String> log =
@@ -77,16 +77,7 @@ class LoggingPropertiesTest {
.filter(line -> line.contains("My log message."))
.findAny();
assertThat(log).isPresent();
Map<String, String> logRecord = new Gson().fromJson(log.get(), Map.class);
assertThat(logRecord).containsEntry("severity", "INFO");
Map<String, ?> 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()));
}
}

3
proxy/src/main/java/google/registry/proxy/ProxyModule.java
View File

@@ -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.

92
util/src/main/java/google/registry/util/GcpJsonFormatter.java
View File

@@ -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.
*
* <p>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..
* <p>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 <a
* href="https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry">{@code Log Entry}</a>
* fields and parsed by Log Explorer.
*
* @see <a
* href="https://medium.com/retailmenot-engineering/formatting-python-logs-for-stackdriver-5a5ddd80761c">
* Formatting Python Logs from Stackdriver</a> <a
* href="https://stackoverflow.com/questions/44164730/gke-stackdriver-java-logback-logging-format">
* GKE &amp; Stackdriver: Java logback logging format?</a>
* href="https://cloud.google.com/logging/docs/structured-logging#structured_logging_special_fields">
* Logging agent: special JSON fields</a>
*/
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.
*
* <p>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();
}
}
String line = "";
String file = "";
if (record instanceof SimpleLogRecord simpleLogRecord) {
Optional<Integer> lineNumber =
Optional.ofNullable(simpleLogRecord.getLogData())
.map(LogData::getLogSite)
.map(LogSite::getLineNumber);
if (lineNumber.isPresent()) {
source += " line:" + lineNumber.get();
Optional<LogSite> logSite =
Optional.ofNullable(simpleLogRecord.getLogData()).map(LogData::getLogSite);
if (logSite.isPresent()) {
line = String.valueOf(logSite.get().getLineNumber());
file = logSite.get().getFileName();
}
}
} else {
source = record.getLoggerName();
Map<String, String> 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 <a
* href="https://github.com/googleapis/google-cloud-java/blob/master/google-cloud-clients/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java#L325">{@code LoggingHandler}</a>
* href="https://github.com/googleapis/java-logging/blob/main/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java">
* LoggingHandler.java</a>
*/
private static String severityFor(Level level) {
return switch (level.intValue()) {

153
util/src/test/java/google/registry/util/GcpJsonFormatterTest.java
View File

@@ -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 <a
* href="https://github.com/google/flogger/blob/master/google/src/test/java/com/google/common/flogger/GoogleLoggerTest.java">
* GoogleLoggerTest.java</a>
*/
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);
}
}