Rationalize logging statements across codebase

This fixes up the following problems:
1. Using string concatenation instead of the formatting variant methods.
2. Logging or swallowing exception messages without logging the exception
   itself (this swallows the stack trace).
3. Unnecessary logging on re-thrown exceptions.
4. Unnecessary use of formatting variant methods when not necessary.
5. Complicated logging statements involving significant processing not being
   wrapped inside of a logging level check.
6. Redundant logging both of an exception itself and its message (this is
   unnecessary duplication).
7. Use of the base Logger class instead of our FormattingLogger class.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=182419837
This commit is contained in:
mcilwain 2018-01-18 12:27:06 -08:00 committed by Ben McIlwain
parent f22a42cd42
commit 81dc2bbbc3
47 changed files with 172 additions and 154 deletions

View file

@ -35,6 +35,7 @@ import google.registry.monitoring.whitebox.BigQueryMetricsEnqueuer;
import google.registry.monitoring.whitebox.EppMetric;
import google.registry.util.FormattingLogger;
import java.util.Optional;
import java.util.logging.Level;
import javax.inject.Inject;
import org.json.simple.JSONValue;
@ -70,19 +71,25 @@ public final class EppController {
eppInput = unmarshal(EppInput.class, inputXmlBytes);
} catch (EppException e) {
// Log the unmarshalling error, with the raw bytes (in base64) to help with debugging.
logger.infofmt(
e,
"EPP request XML unmarshalling failed - \"%s\":\n%s\n%s\n%s\n%s",
e.getMessage(),
JSONValue.toJSONString(
ImmutableMap.<String, Object>of(
"clientId", nullToEmpty(sessionMetadata.getClientId()),
"resultCode", e.getResult().getCode().code,
"resultMessage", e.getResult().getCode().msg,
"xmlBytes", base64().encode(inputXmlBytes))),
Strings.repeat("=", 40),
new String(inputXmlBytes, UTF_8).trim(), // Charset decoding failures are swallowed.
Strings.repeat("=", 40));
if (logger.isLoggable(Level.INFO)) {
logger.infofmt(
e,
"EPP request XML unmarshalling failed - \"%s\":\n%s\n%s\n%s\n%s",
e.getMessage(),
JSONValue.toJSONString(
ImmutableMap.<String, Object>of(
"clientId",
nullToEmpty(sessionMetadata.getClientId()),
"resultCode",
e.getResult().getCode().code,
"resultMessage",
e.getResult().getCode().msg,
"xmlBytes",
base64().encode(inputXmlBytes))),
Strings.repeat("=", 40),
new String(inputXmlBytes, UTF_8).trim(), // Charset decoding failures are swallowed.
Strings.repeat("=", 40));
}
// Return early by sending an error message, with no clTRID since we couldn't unmarshal it.
eppMetricBuilder.setStatus(e.getResult().getCode());
return getErrorResponse(

View file

@ -130,7 +130,8 @@ public class EppXmlTransformer {
try {
byte[] lenient = EppXmlTransformer.marshal(eppOutput, LENIENT);
// Marshaling worked even though the results didn't validate against the schema.
logger.severe(e, "Result marshaled but did not validate: " + new String(lenient, UTF_8));
logger.severefmt(
e, "Result marshaled but did not validate: %s", new String(lenient, UTF_8));
return lenient;
} catch (XmlException e2) {
throw new RuntimeException(e2); // Failing to marshal at all is not recoverable.

View file

@ -31,6 +31,7 @@ import google.registry.model.eppcommon.Trid;
import google.registry.model.eppinput.EppInput;
import google.registry.util.FormattingLogger;
import java.util.Optional;
import java.util.logging.Level;
import javax.inject.Inject;
import org.json.simple.JSONValue;
@ -64,37 +65,44 @@ public class FlowReporter {
public void recordToLogs() {
// WARNING: These log statements are parsed by reporting pipelines - be careful when changing.
// It should be safe to add new keys, but be very cautious in changing existing keys.
logger.infofmt(
"%s: %s",
EPPINPUT_LOG_SIGNATURE,
JSONValue.toJSONString(
ImmutableMap.<String, Object>of(
"xml", prettyPrint(inputXmlBytes),
"xmlBytes", base64().encode(inputXmlBytes))));
if (logger.isLoggable(Level.INFO)) {
logger.infofmt(
"%s: %s",
EPPINPUT_LOG_SIGNATURE,
JSONValue.toJSONString(
ImmutableMap.<String, Object>of(
"xml", prettyPrint(inputXmlBytes),
"xmlBytes", base64().encode(inputXmlBytes))));
}
// Explicitly log flow metadata separately from the EPP XML itself so that it stays compact
// enough to be sure to fit in a single log entry (the XML part in rare cases could be long
// enough to overflow into multiple log entries, breaking routine parsing of the JSON format).
String singleTargetId = eppInput.getSingleTargetId().orElse("");
ImmutableList<String> targetIds = eppInput.getTargetIds();
logger.infofmt(
"%s: %s",
METADATA_LOG_SIGNATURE,
JSONValue.toJSONString(
new ImmutableMap.Builder<String, Object>()
.put("serverTrid", trid.getServerTransactionId())
.put("clientId", clientId)
.put("commandType", eppInput.getCommandType())
.put("resourceType", eppInput.getResourceType().orElse(""))
.put("flowClassName", flowClass.getSimpleName())
.put("targetId", singleTargetId)
.put("targetIds", targetIds)
.put(
"tld", eppInput.isDomainResourceType() ? extractTld(singleTargetId).orElse("") : "")
.put(
"tlds",
eppInput.isDomainResourceType() ? extractTlds(targetIds).asList() : EMPTY_LIST)
.put("icannActivityReportField", extractActivityReportField(flowClass))
.build()));
if (logger.isLoggable(Level.INFO)) {
logger.infofmt(
"%s: %s",
METADATA_LOG_SIGNATURE,
JSONValue.toJSONString(
new ImmutableMap.Builder<String, Object>()
.put("serverTrid", trid.getServerTransactionId())
.put("clientId", clientId)
.put("commandType", eppInput.getCommandType())
.put("resourceType", eppInput.getResourceType().orElse(""))
.put("flowClassName", flowClass.getSimpleName())
.put("targetId", singleTargetId)
.put("targetIds", targetIds)
.put(
"tld",
eppInput.isDomainResourceType() ? extractTld(singleTargetId).orElse("") : "")
.put(
"tlds",
eppInput.isDomainResourceType()
? extractTlds(targetIds).asList()
: EMPTY_LIST)
.put("icannActivityReportField", extractActivityReportField(flowClass))
.build()));
}
}
/**

View file

@ -28,6 +28,7 @@ import google.registry.model.eppcommon.Trid;
import google.registry.model.eppoutput.EppOutput;
import google.registry.monitoring.whitebox.EppMetric;
import google.registry.util.FormattingLogger;
import java.util.logging.Level;
import javax.inject.Inject;
import javax.inject.Provider;
@ -62,16 +63,18 @@ public class FlowRunner {
// New data to be logged should be added only to the JSON log statement below.
// TODO(b/20725722): remove this log statement entirely once we've transitioned to using the
// log line below instead, or change this one to be for human consumption only.
logger.infofmt(
COMMAND_LOG_FORMAT,
trid.getServerTransactionId(),
clientId,
sessionMetadata,
prettyXml.replaceAll("\n", "\n\t"),
credentials,
eppRequestSource,
isDryRun ? "DRY_RUN" : "LIVE",
isSuperuser ? "SUPERUSER" : "NORMAL");
if (logger.isLoggable(Level.INFO)) {
logger.infofmt(
COMMAND_LOG_FORMAT,
trid.getServerTransactionId(),
clientId,
sessionMetadata,
prettyXml.replace("\n", "\n\t"),
credentials,
eppRequestSource,
isDryRun ? "DRY_RUN" : "LIVE",
isSuperuser ? "SUPERUSER" : "NORMAL");
}
// Record flow info to the GAE request logs for reporting purposes if it's not a dry run.
if (!isDryRun) {
flowReporter.recordToLogs();