From c12a97f14ee44701f3194f1979be10c8b2a5eb85 Mon Sep 17 00:00:00 2001 From: minherz Date: Tue, 28 Dec 2021 16:37:24 +0000 Subject: [PATCH 01/12] feat: serialize LogEntry to oneline Json string resolve warnings change type for trace an spanId to be strings create more realistic and visual test data: - timestamp with more recent date - json payload with various data types --- .../com/google/cloud/logging/LogEntry.java | 159 +++++++++++++++++- .../google/cloud/logging/LogEntryTest.java | 52 +++--- 2 files changed, 182 insertions(+), 29 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java index 16b469cd8..32aa1f456 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java @@ -19,9 +19,17 @@ import static com.google.common.base.Preconditions.checkNotNull; import com.google.cloud.MonitoredResource; +import com.google.cloud.logging.Payload.Type; import com.google.common.base.Function; import com.google.common.base.MoreObjects; import com.google.common.collect.ImmutableMap; +import com.google.gson.Gson; +import com.google.gson.GsonBuilder; +import com.google.gson.JsonElement; +import com.google.gson.JsonObject; +import com.google.gson.JsonPrimitive; +import com.google.gson.JsonSerializationContext; +import com.google.gson.JsonSerializer; import com.google.logging.v2.LogEntryOperation; import com.google.logging.v2.LogEntrySourceLocation; import com.google.logging.v2.LogName; @@ -61,8 +69,8 @@ public LogEntry apply(com.google.logging.v2.LogEntry pb) { private final HttpRequest httpRequest; private final Map labels; private final Operation operation; - private final Object trace; - private final Object spanId; + private final String trace; + private final String spanId; private final boolean traceSampled; private final SourceLocation sourceLocation; private final Payload payload; @@ -80,8 +88,8 @@ public static class Builder { private HttpRequest httpRequest; private Map labels = new HashMap<>(); private Operation operation; - private Object trace; - private Object spanId; + private String trace; + private String spanId; private boolean traceSampled; private SourceLocation sourceLocation; private Payload payload; @@ -245,7 +253,7 @@ public Builder setTrace(String trace) { * relative resource name, the name is assumed to be relative to `//tracing.googleapis.com`. */ public Builder setTrace(Object trace) { - this.trace = trace; + this.trace = trace != null ? trace.toString() : null; return this; } @@ -257,7 +265,7 @@ public Builder setSpanId(String spanId) { /** Sets the ID of the trace span associated with the log entry, if any. */ public Builder setSpanId(Object spanId) { - this.spanId = spanId; + this.spanId = spanId != null ? spanId.toString() : null; return this; } @@ -575,6 +583,145 @@ com.google.logging.v2.LogEntry toPb(String projectId) { return builder.build(); } + /** + * Customized serializers to match the expected format for timestamp, source location and request + * method + */ + static final class InstantSerializer implements JsonSerializer { + @Override + public JsonElement serialize( + Instant src, java.lang.reflect.Type typeOfSrc, JsonSerializationContext context) { + return new JsonPrimitive(src.toString()); + } + } + + static final class SourceLocationSerializer implements JsonSerializer { + @Override + public JsonElement serialize( + SourceLocation src, java.lang.reflect.Type typeOfSrc, JsonSerializationContext context) { + JsonObject obj = new JsonObject(); + if (src.getFile() != null) { + obj.addProperty("file", src.getFile()); + } + if (src.getLine() != null) { + obj.addProperty("line", src.getLine().toString()); + } + if (src.getFunction() != null) { + obj.addProperty("function", src.getFunction()); + } + return obj; + } + } + + static final class RequestMethodSerializer implements JsonSerializer { + @Override + public JsonElement serialize( + HttpRequest.RequestMethod src, + java.lang.reflect.Type typeOfSrc, + JsonSerializationContext context) { + return new JsonPrimitive(src.name()); + } + } + + /** Helper class to format one line Json representation of the LogEntry for structured log. */ + static final class StructuredLogFormatter { + private final Gson gson; + private final StringBuilder builder; + + public StructuredLogFormatter(StringBuilder builder) { + checkNotNull(builder); + this.gson = + new GsonBuilder() + .registerTypeAdapter(Instant.class, new InstantSerializer()) + .registerTypeAdapter(SourceLocation.class, new SourceLocationSerializer()) + .registerTypeAdapter(HttpRequest.RequestMethod.class, new RequestMethodSerializer()) + .create(); + this.builder = builder; + } + + /** + * Adds a Json field and value pair to the current string representation. Method does not + * validate parameters to be multi-line strings. Nothing is added if {@code value} parameter is + * {@code null}. + * + * @param name a valid Json field name string. + * @param value an object to be serialized to Json using {@link Gson}. + * @param appendComma a flag to add a trailing comma. + * @return a reference to this object. + */ + public StructuredLogFormatter appendField(String name, Object value, boolean appendComma) { + checkNotNull(name); + if (value != null) { + builder.append(gson.toJson(name)).append(":").append(gson.toJson(value)); + if (!appendComma) { + builder.append(","); + } + } + return this; + } + + public StructuredLogFormatter appendField(String name, Object value) { + return appendField(name, value, false); + } + + /** + * Adds a collection of Json fields that {@code value} parameter is serialized to to the current + * string representation. Nothing is added if {@code value} parameter is {@code null}. + * + * @param value an object to be serialized to Json using {@link Gson}. + * @param appendComma a flag to add a trailing comma. + * @return a reference to this object. + */ + public StructuredLogFormatter appendJson(Object value, boolean appendComma) { + if (value != null) { + String json = gson.toJson(value); + // append json object without brackets + if (json.length() > 1) { + builder.append(json.substring(0, json.length() - 1).substring(1)); + if (!appendComma) { + builder.append(","); + } + } + } + return this; + } + + public StructuredLogFormatter appendJson(Object value) { + return appendJson(value, false); + } + } + + /** + * Serializes the object to a one line JSON string in the simplified format that can be parsed by + * the logging agents that run on Google Cloud resources. + */ + public String toStructuredJsonString() { + final StringBuilder builder = new StringBuilder("{"); + final StructuredLogFormatter formatter = new StructuredLogFormatter(builder); + + formatter + .appendField("severity", severity) + .appendField("timestamp", timestamp) + .appendField("httpRequest", httpRequest) + .appendField("logging.googleapis.com/insertId", insertId) + .appendField("logging.googleapis.com/labels", labels) + .appendField("logging.googleapis.com/operation", operation) + .appendField("logging.googleapis.com/sourceLocation", sourceLocation) + .appendField("logging.googleapis.com/spanId", spanId) + .appendField("logging.googleapis.com/trace", trace) + .appendField("logging.googleapis.com/trace_sampled", traceSampled); + if (payload.getType() == Type.STRING) { + formatter.appendField("message", payload.getData(), true); + } else if (payload.getType() == Type.JSON) { + Payload.JsonPayload jsonPayload = (Payload.JsonPayload) payload; + formatter.appendJson(jsonPayload.getDataAsMap(), true); + } else if (payload.getType() == Type.PROTO) { + throw new UnsupportedOperationException("LogEntry with protobuf payload cannot be converted"); + } + builder.append("}"); + return builder.toString(); + } + /** Returns a builder for {@code LogEntry} objects given the entry payload. */ public static Builder newBuilder(Payload payload) { return new Builder(payload); diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/LogEntryTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/LogEntryTest.java index fe10893f1..015bebe23 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/LogEntryTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/LogEntryTest.java @@ -31,6 +31,7 @@ import java.util.Map; import org.junit.Test; +@SuppressWarnings("deprecation") public class LogEntryTest { private static final String LOG_NAME = "syslog"; @@ -39,8 +40,8 @@ public class LogEntryTest { MonitoredResource.newBuilder("cloudsql_database") .setLabels(ImmutableMap.of("datasetId", "myDataset", "zone", "myZone")) .build(); - private static final Instant TIMESTAMP = Instant.ofEpochMilli(42); - private static final Instant RECEIVE_TIMESTAMP = Instant.ofEpochMilli(24); + private static final Instant TIMESTAMP = Instant.parse("1984-08-13T15:35:30.123Z"); + private static final Instant RECEIVE_TIMESTAMP = Instant.parse("1984-08-13T15:35:31.0Z"); private static final Severity SEVERITY = Severity.ALERT; private static final String INSERT_ID = "insertId"; private static final HttpRequest HTTP_REQUEST = @@ -52,27 +53,13 @@ public class LogEntryTest { ImmutableMap.of("key1", "value1", "key2", "value2"); private static final Operation OPERATION = Operation.of("id", "producer"); private static final String TRACE = "trace"; - private static final Object TRACE_FORMATTER = - new Object() { - @Override - public String toString() { - return TRACE; - } - }; private static final String SPAN_ID = "spanId"; - private static final Object SPAN_ID_FORMATTER = - new Object() { - @Override - public String toString() { - return SPAN_ID; - } - }; private static final boolean TRACE_SAMPLED = true; private static final SourceLocation SOURCE_LOCATION = new SourceLocation.Builder().setFile("file").setLine(42L).setFunction("function").build(); private static final StringPayload STRING_PAYLOAD = StringPayload.of("payload"); private static final JsonPayload JSON_PAYLOAD = - JsonPayload.of(ImmutableMap.of("key", "val")); + JsonPayload.of(ImmutableMap.of("key1", "val", "key2", 123, "key3", false)); private static final ProtoPayload PROTO_PAYLOAD = ProtoPayload.of(Any.pack(Empty.getDefaultInstance())); private static final LogDestinationName BILLING_NAME = @@ -91,8 +78,8 @@ public String toString() { .setHttpRequest(HTTP_REQUEST) .setLabels(LABELS) .setOperation(OPERATION) - .setTrace(TRACE_FORMATTER) - .setSpanId(SPAN_ID_FORMATTER) + .setTrace(TRACE) + .setSpanId(SPAN_ID) .setTraceSampled(TRACE_SAMPLED) .setSourceLocation(SOURCE_LOCATION) .build(); @@ -107,8 +94,8 @@ public String toString() { .setHttpRequest(HTTP_REQUEST) .setLabels(LABELS) .setOperation(OPERATION) - .setTrace(TRACE_FORMATTER) - .setSpanId(SPAN_ID_FORMATTER) + .setTrace(TRACE) + .setSpanId(SPAN_ID) .setTraceSampled(TRACE_SAMPLED) .setSourceLocation(SOURCE_LOCATION) .build(); @@ -123,8 +110,8 @@ public String toString() { .setHttpRequest(HTTP_REQUEST) .setLabels(LABELS) .setOperation(OPERATION) - .setTrace(TRACE_FORMATTER) - .setSpanId(SPAN_ID_FORMATTER) + .setTrace(TRACE) + .setSpanId(SPAN_ID) .setTraceSampled(TRACE_SAMPLED) .setSourceLocation(SOURCE_LOCATION) .build(); @@ -379,4 +366,23 @@ private void compareLogEntry(LogEntry expected, LogEntry value, Boolean extraVal assertEquals(expected.getSourceLocation(), value.getSourceLocation()); assertEquals(expected.getPayload(), value.getPayload()); } + + private static final String[] EXPECTED_STRUCTURED_LOGS = { + "{\"severity\":\"ALERT\",\"timestamp\":\"1984-08-13T15:35:30.123Z\",\"httpRequest\":{\"requestMethod\":\"GET\",\"status\":404,\"cacheLookup\":false,\"cacheHit\":false,\"cacheValidatedWithOriginServer\":false},\"logging.googleapis.com/insertId\":\"insertId\",\"logging.googleapis.com/labels\":{\"key1\":\"value1\",\"key2\":\"value2\"},\"logging.googleapis.com/operation\":{\"id\":\"id\",\"producer\":\"producer\",\"first\":false,\"last\":false},\"logging.googleapis.com/sourceLocation\":{\"file\":\"file\",\"line\":\"42\",\"function\":\"function\"},\"logging.googleapis.com/spanId\":\"spanId\",\"logging.googleapis.com/trace\":\"trace\",\"logging.googleapis.com/trace_sampled\":true,\"message\":\"payload\"}", + "{\"severity\":\"ALERT\",\"timestamp\":\"1984-08-13T15:35:30.123Z\",\"httpRequest\":{\"requestMethod\":\"GET\",\"status\":404,\"cacheLookup\":false,\"cacheHit\":false,\"cacheValidatedWithOriginServer\":false},\"logging.googleapis.com/insertId\":\"insertId\",\"logging.googleapis.com/labels\":{\"key1\":\"value1\",\"key2\":\"value2\"},\"logging.googleapis.com/operation\":{\"id\":\"id\",\"producer\":\"producer\",\"first\":false,\"last\":false},\"logging.googleapis.com/sourceLocation\":{\"file\":\"file\",\"line\":\"42\",\"function\":\"function\"},\"logging.googleapis.com/spanId\":\"spanId\",\"logging.googleapis.com/trace\":\"trace\",\"logging.googleapis.com/trace_sampled\":true,\"key1\":\"val\",\"key2\":123.0,\"key3\":false}" + }; + private static final LogEntry[] TEST_LOG_ENTRIES = {STRING_ENTRY, JSON_ENTRY}; + + @Test + public void testStructureLogPresentations() { + for (int i = 0; i < TEST_LOG_ENTRIES.length; i++) { + String structured_log = TEST_LOG_ENTRIES[i].toStructuredJsonString(); + assertEquals(EXPECTED_STRUCTURED_LOGS[i], structured_log); + } + } + + @Test(expected = UnsupportedOperationException.class) + public void testStructureLogPresentationWithProtobufPayload() { + PROTO_ENTRY.toStructuredJsonString(); + } } From bfa5457be2a39920bf6be4ef5f96bf0d9229f399 Mon Sep 17 00:00:00 2001 From: minherz Date: Wed, 29 Dec 2021 12:23:42 +0000 Subject: [PATCH 02/12] chore: add populateMetadata API to Logging --- .../clirr-ignored-differences.xml | 9 +++++++ .../com/google/cloud/logging/Logging.java | 26 +++++++++++++++++-- 2 files changed, 33 insertions(+), 2 deletions(-) create mode 100644 google-cloud-logging/clirr-ignored-differences.xml diff --git a/google-cloud-logging/clirr-ignored-differences.xml b/google-cloud-logging/clirr-ignored-differences.xml new file mode 100644 index 000000000..0d780d1a4 --- /dev/null +++ b/google-cloud-logging/clirr-ignored-differences.xml @@ -0,0 +1,9 @@ + + + + + 7012 + com/google/cloud/logging/Logging + java.lang.Iterable populateMetadata(java.lang.Iterable, com.google.cloud.MonitoredResource, java.lang.String[]) + + diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/Logging.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/Logging.java index f029602b2..a765c73e0 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/Logging.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/Logging.java @@ -1286,8 +1286,30 @@ ApiFuture> listMonitoredResourceDescripto * */ @BetaApi("The surface for the tail streaming is not stable yet and may change in the future.") - default LogEntryServerStream tailLogEntries(TailOption... options) { + LogEntryServerStream tailLogEntries(TailOption... options); + + /** + * Populates metadata fields of the immutable collection of {@link LogEntry} items. Only empty + * fields are populated. The {@link SourceLocation} is populated only for items with the severity + * set to {@link Severity.DEBUG}. The information about {@link HttpRequest}, trace and span Id is + * retrieved using {@link ContextHandler}. + * + * @param logEntries an immutable collection of {@link LogEntry} items. + * @param customResource a customized instance of the {@link MonitoredResource}. If this parameter + * is {@code null} then the new instance will be generated using {@link + * MonitoredResourceUtil#getResource(String, String)}. + * @param exclusionClassPaths a list of exclussion class path prefixes. If left empty then {@link + * SourceLocation} instance is built based on the caller's stack trace information. Otherwise, + * the information from the first {@link StackTraceElement} along the call stack which class + * name does not start with any not {@code null} exclusion class paths is used. + * @return A collection of {@link LogEntry} items composed from the {@code logEntries} parameter + * with populated metadata fields. + */ + default Iterable populateMetadata( + Iterable logEntries, + MonitoredResource customResource, + String... exclusionClassPaths) { throw new UnsupportedOperationException( - "method tailLogEntriesCallable() does not have default implementation"); + "method populateMetadata() does not have default implementation"); } } From a012d3847e862b730ee6d5500b95cc4951ae7049 Mon Sep 17 00:00:00 2001 From: minherz Date: Wed, 29 Dec 2021 12:24:23 +0000 Subject: [PATCH 03/12] chore: add useStructuredLogging configuration --- .../google/cloud/logging/LoggingConfig.java | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java index 561edb228..50b4a3066 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java @@ -42,6 +42,7 @@ class LoggingConfig { private static final String ENHANCERS_TAG = "enhancers"; private static final String USE_INHERITED_CONTEXT = "useInheritedContext"; private static final String AUTO_POPULATE_METADATA = "autoPopulateMetadata"; + private static final String USE_STRUCTURED_LOGGING = "useStructuredLogging"; public LoggingConfig(String className) { this.className = className; @@ -78,11 +79,11 @@ Formatter getFormatter() { } Boolean getAutoPopulateMetadata() { - String flag = getProperty(AUTO_POPULATE_METADATA); - if (flag != null) { - return Boolean.parseBoolean(flag); - } - return null; + return getBooleanProperty(AUTO_POPULATE_METADATA, null); + } + + Boolean getUseStructuredLogging() { + return getBooleanProperty(USE_STRUCTURED_LOGGING, null); } MonitoredResource getMonitoredResource(String projectId) { @@ -127,6 +128,14 @@ private String getProperty(String name, String defaultValue) { return firstNonNull(getProperty(name), defaultValue); } + private Boolean getBooleanProperty(String name, Boolean defaultValue) { + String flag = getProperty(name); + if (flag != null) { + return Boolean.parseBoolean(flag); + } + return defaultValue; + } + private Level getLevelProperty(String name, Level defaultValue) { String stringLevel = getProperty(name); if (stringLevel == null) { From 5eb9dce1d0707c486c441eecbbe654f227ccb1df Mon Sep 17 00:00:00 2001 From: minherz Date: Wed, 29 Dec 2021 12:26:30 +0000 Subject: [PATCH 04/12] chore: add useStructuredLogging flag to LoggingHandler refactor setAutoPopulateMetadata() to avoid setting flag to null --- .../google/cloud/logging/LoggingHandler.java | 24 ++++++++++++++++--- 1 file changed, 21 insertions(+), 3 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java index f2fc036eb..ec5d75f3a 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java @@ -17,7 +17,6 @@ package com.google.cloud.logging; import static com.google.common.base.MoreObjects.firstNonNull; -import static com.google.common.base.Preconditions.checkNotNull; import com.google.cloud.MonitoredResource; import com.google.cloud.logging.Logging.WriteOption; @@ -114,6 +113,10 @@ *
  • {@code com.google.cloud.logging.LoggingHandler.autoPopulateMetadata} is a boolean flag that * opts-out the population of the log entries metadata before the logs are sent to Cloud * Logging (defaults to {@code true}). + *
  • {@code com.google.cloud.logging.LoggingHandler.useStructuredLogging} is a boolean flag that + * opts-in redirecting the output of the handler to STDOUT (instead of ingesting it using + * Logging API) by formatting the log following structured logging guidelines. Logging + * (defaults to {@code true}). * * *

    To add a {@code LoggingHandler} to an existing {@link Logger} and be sure to avoid infinite @@ -123,6 +126,8 @@ * 

      * {@code com.example.mypackage.handlers=com.google.cloud.logging.LoggingHandler}
  *
    + * + * @see Structured logging */ public class LoggingHandler extends Handler { @@ -145,6 +150,7 @@ public class LoggingHandler extends Handler { private volatile Level flushLevel; private volatile Boolean autoPopulateMetadata; + private volatile Boolean useStructuredLogging; private WriteOption[] defaultWriteOptions; @@ -235,6 +241,7 @@ public LoggingHandler( Boolean f1 = options.getAutoPopulateMetadata(); Boolean f2 = config.getAutoPopulateMetadata(); autoPopulateMetadata = isTrueOrNull(f1) && isTrueOrNull(f2); + useStructuredLogging = firstNonNull(config.getUseStructuredLogging(), Boolean.FALSE); String logName = log != null ? log : config.getLogName(); MonitoredResource resource = firstNonNull( @@ -381,8 +388,7 @@ public Synchronicity getSynchronicity() { } /** Sets the metadata auto population flag. */ - public void setAutoPopulateMetadata(Boolean value) { - checkNotNull(value); + public void setAutoPopulateMetadata(boolean value) { this.autoPopulateMetadata = value; List writeOptions = Arrays.asList(defaultWriteOptions); for (int i = 0; i < writeOptions.size(); i++) { @@ -400,6 +406,18 @@ public Boolean getAutoPopulateMetadata() { return this.autoPopulateMetadata; } + /** + * Enable/disable use of structured logging. When enabled, logs will be printed to STDOUT in the + * structured logging format. Otherwise, logs will be ingested using Logging API. + */ + public void setUseStructuredLogging(boolean value) { + this.useStructuredLogging = value; + } + + public Boolean getUseStructuredLogging() { + return useStructuredLogging; + } + /** * Adds the provided {@code LoggingHandler} to {@code logger}. Use this method to register Cloud * Logging handlers instead of {@link Logger#addHandler(Handler)} to avoid infinite recursion when From c25732099f0a89b9e8b263db3170977d5848e605 Mon Sep 17 00:00:00 2001 From: minherz Date: Wed, 29 Dec 2021 12:28:26 +0000 Subject: [PATCH 05/12] chore: refactor write() by implementing populateMetadata() implement populateMetadata() API. change write() to use the new API. refactor SourceLocation.fromCurrentContext() to use a list of exclusion prefixes instead of depth level as parameter. change relevant unit tests to support the refactored changes. --- .../com/google/cloud/logging/LoggingImpl.java | 85 ++++++++++--------- .../google/cloud/logging/SourceLocation.java | 45 +++++----- .../logging/AutoPopulateMetadataTests.java | 5 +- .../cloud/logging/SourceLocationTest.java | 31 +++++-- 4 files changed, 98 insertions(+), 68 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java index a4a52d2f6..72e325d69 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java @@ -792,6 +792,50 @@ private static LogName getLogName( return destination.toLogName(logName); } + public Iterable populateMetadata( + Iterable logEntries, + MonitoredResource customResource, + String... exclusionClassPaths) { + final Boolean needDebugInfo = + Iterables.any( + logEntries, + log -> log.getSeverity() == Severity.DEBUG && log.getSourceLocation() == null); + final SourceLocation sourceLocation = + needDebugInfo ? SourceLocation.fromCurrentContext(exclusionClassPaths) : null; + // populate monitored resource metadata by prioritizing the one set via + // WriteOption + final MonitoredResource resourceMetadata = + customResource == null + ? MonitoredResourceUtil.getResource(getOptions().getProjectId(), null) + : customResource; + final Context context = (new ContextHandler()).getCurrentContext(); + final ArrayList populatedLogEntries = Lists.newArrayList(); + + // populate empty metadata fields of log entries before calling write API + for (LogEntry entry : logEntries) { + LogEntry.Builder builder = entry.toBuilder(); + if (resourceMetadata != null && entry.getResource() == null) { + builder.setResource(resourceMetadata); + } + if (context != null && entry.getHttpRequest() == null) { + builder.setHttpRequest(context.getHttpRequest()); + } + if (context != null && Strings.isNullOrEmpty(entry.getTrace())) { + MonitoredResource resource = + entry.getResource() != null ? entry.getResource() : resourceMetadata; + builder.setTrace(getFormattedTrace(context.getTraceId(), resource)); + } + if (context != null && Strings.isNullOrEmpty(entry.getSpanId())) { + builder.setSpanId(context.getSpanId()); + } + if (entry.getSeverity() == Severity.DEBUG && entry.getSourceLocation() == null) { + builder.setSourceLocation(sourceLocation); + } + populatedLogEntries.add(builder.build()); + } + return populatedLogEntries; + } + public void write(Iterable logEntries, WriteOption... options) { if (inWriteCall.get() != null) { return; @@ -806,46 +850,9 @@ public void write(Iterable logEntries, WriteOption... options) { if (populateMetadata2 == Boolean.TRUE || (populateMetadata2 == null && populateMetadata1 == Boolean.TRUE)) { - final Boolean needDebugInfo = - Iterables.any( - logEntries, - log -> log.getSeverity() == Severity.DEBUG && log.getSourceLocation() == null); - final SourceLocation sourceLocation = - needDebugInfo ? SourceLocation.fromCurrentContext(1) : null; final MonitoredResource sharedResourceMetadata = RESOURCE.get(writeOptions); - // populate monitored resource metadata by prioritizing the one set via WriteOption - final MonitoredResource resourceMetadata = - sharedResourceMetadata == null - ? MonitoredResourceUtil.getResource(getOptions().getProjectId(), null) - : sharedResourceMetadata; - final Context context = (new ContextHandler()).getCurrentContext(); - final ArrayList populatedLogEntries = Lists.newArrayList(); - - // populate empty metadata fields of log entries before calling write API - for (LogEntry entry : logEntries) { - LogEntry.Builder builder = entry.toBuilder(); - if (resourceMetadata != null && entry.getResource() == null) { - builder.setResource(resourceMetadata); - } - if (context != null && entry.getHttpRequest() == null) { - builder.setHttpRequest(context.getHttpRequest()); - } - if (context != null && Strings.isNullOrEmpty(entry.getTrace())) { - MonitoredResource resource = - entry.getResource() != null ? entry.getResource() : resourceMetadata; - builder.setTrace(getFormattedTrace(context.getTraceId(), resource)); - } - if (context != null && Strings.isNullOrEmpty(entry.getSpanId())) { - builder.setSpanId(context.getSpanId()); - } - if (entry.getSeverity() != null - && entry.getSeverity() == Severity.DEBUG - && entry.getSourceLocation() == null) { - builder.setSourceLocation(sourceLocation); - } - populatedLogEntries.add(builder.build()); - } - logEntries = populatedLogEntries; + logEntries = + populateMetadata(logEntries, sharedResourceMetadata, this.getClass().getName()); } writeLogEntries(logEntries, options); diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java index df9126687..a0d0eec0c 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java @@ -16,11 +16,10 @@ package com.google.cloud.logging; -import static com.google.common.base.Preconditions.checkElementIndex; - import com.google.common.base.MoreObjects; import com.google.logging.v2.LogEntrySourceLocation; import java.io.Serializable; +import java.util.Arrays; import java.util.Objects; /** Additional information about the source code location that produced the log entry. */ @@ -158,28 +157,34 @@ static SourceLocation fromPb(LogEntrySourceLocation sourceLocationPb) { } /** - * Creates instance of {@link SourceLocation} based on stack trace information. Caller should - * provide the level in the stack where the information can be located. The stack trace level - * should be {@code 0} to display information for the caller of the method. + * Creates an instance of {@link SourceLocation} based on stack trace information. The stack trace + * level is determined based on the exclusion list of the class paths provided in the {@code + * exclusionClassPaths} parameter. If the list is empty or not defined the caller's stack trace + * information is used. Otherwise, the first {@link StackTraceElement} along the stack which class + * name does not start with any not {@code null} exclusion class paths will be used. * - * @param level Zero-based non-negative integer defining the level in the stack trace where {@code - * 0} is topmost element. + * @param exclusionClassPaths a varargs array of strings containing class path prefixes. * @return a new instance of {@link SourceLocation} populated with file name, method and line * number information. - * @throws IndexOutOfBoundsException if the provided {@link level} is negative or greater than the - * current call stack. */ - static SourceLocation fromCurrentContext(int level) { + static SourceLocation fromCurrentContext(String... exclusionClassPaths) { StackTraceElement[] stackTrace = (new Exception()).getStackTrace(); - Builder builder = newBuilder(); - // need to take info from 1 level down the stack to compensate the call to this - // method - int indexPlus = checkElementIndex(level, stackTrace.length - 1) + 1; - StackTraceElement ste = stackTrace[indexPlus]; - return builder - .setFile(ste.getFileName()) - .setLine(Long.valueOf(ste.getLineNumber())) - .setFunction(ste.getMethodName()) - .build(); + + for (int level = 1; level < stackTrace.length; level++) { + StackTraceElement ste = stackTrace[level]; + String className = ste.getClassName(); + + if (exclusionClassPaths != null) { + if (Arrays.stream(exclusionClassPaths).anyMatch(prefix -> className.startsWith(prefix))) { + continue; + } + } + return newBuilder() + .setFile(ste.getFileName()) + .setLine(Long.valueOf(ste.getLineNumber())) + .setFunction(ste.getMethodName()) + .build(); + } + return null; } } diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/AutoPopulateMetadataTests.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/AutoPopulateMetadataTests.java index 9101f765a..882df1fd3 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/AutoPopulateMetadataTests.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/AutoPopulateMetadataTests.java @@ -89,7 +89,8 @@ public void setup() { expect(mockedRpc.write(capture(rpcWriteArgument))) .andReturn(ApiFutures.immediateFuture(EMPTY_WRITE_RESPONSE)); MonitoredResourceUtil.setEnvironmentGetter(mockedEnvGetter); - // the following mocks generate MonitoredResource instance same as RESOURCE constant + // the following mocks generate MonitoredResource instance same as RESOURCE + // constant expect(mockedEnvGetter.getAttribute("project/project-id")).andStubReturn(RESOURCE_PROJECT_ID); expect(mockedEnvGetter.getAttribute("")).andStubReturn(null); replay(mockedRpcFactory, mockedRpc, mockedEnvGetter); @@ -158,7 +159,7 @@ public void testAutoPopulationDisabledInWriteOptions() { @Test public void testSourceLocationPopulation() { - SourceLocation expected = SourceLocation.fromCurrentContext(0); + SourceLocation expected = SourceLocation.fromCurrentContext(); logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY_WITH_DEBUG)); LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0)); diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java index e9feb2f9f..a9035f332 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java @@ -17,6 +17,7 @@ package com.google.cloud.logging; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNull; import org.junit.Test; @@ -61,22 +62,38 @@ public void testToAndFromPb() { @Test public void testFromCurrentContext() { StackTraceElement expectedData = (new Exception()).getStackTrace()[0]; - SourceLocation data = SourceLocation.fromCurrentContext(0); + SourceLocation data = SourceLocation.fromCurrentContext(); assertEquals(expectedData.getFileName(), data.getFile()); assertEquals(expectedData.getMethodName(), data.getFunction()); - // mind the assertion is vs (expectedData.lineNumber + 1). it is because the source location - // info of the expectedData is one line above the source location of the tested data. + // mind the assertion is vs (expectedData.lineNumber + 1). it is because the + // source location + // info of the expectedData is one line above the source location of the tested + // data. + assertEquals(Long.valueOf(expectedData.getLineNumber() + 1), data.getLine()); + } + + @Test + public void testFromCurrentContextWithExclusionList() { + StackTraceElement expectedData = (new Exception()).getStackTrace()[0]; + SourceLocation data = SourceLocation.fromCurrentContext(LoggingImpl.class.getName()); + assertEquals(expectedData.getFileName(), data.getFile()); + assertEquals(expectedData.getMethodName(), data.getFunction()); + // mind the assertion is vs (expectedData.lineNumber + 1). it is because the + // source location + // info of the expectedData is one line above the source location of the tested + // data. assertEquals(Long.valueOf(expectedData.getLineNumber() + 1), data.getLine()); } - @Test(expected = IndexOutOfBoundsException.class) public void testFromCurrentContextWithNegativeLevel() { - SourceLocation.fromCurrentContext(-1); + SourceLocation data = SourceLocation.fromCurrentContext((String[]) null); + assertNull(data); } - @Test(expected = IndexOutOfBoundsException.class) + @Test public void testFromCurrentContextWithVeryLargeLevel() { - SourceLocation.fromCurrentContext(10000); + SourceLocation data = SourceLocation.fromCurrentContext("com.google", "sun", "java", "org"); + assertNull(data); } private void compareSourceLocation(SourceLocation expected, SourceLocation value) { From 8e2619441bc1e515bc0b862e2651527a4f91eb83 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 08:53:39 +0000 Subject: [PATCH 06/12] chore: print structured logging modify publish() method to print structured logging if configured instead of calling to Logging.write(). populate created LogEntry instance with metadata separately instead of adding WriteOption.AUTO_POPULATE_METADATA. refactor LoggingHandler to remove getLogging() method. refactor unit tests to reflect the change in LoggingHandler.publish() implementation. --- .../google/cloud/logging/LoggingHandler.java | 59 ++++++++++--------- .../cloud/logging/LoggingHandlerTest.java | 40 +++++++------ 2 files changed, 52 insertions(+), 47 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java index ec5d75f3a..474faa41e 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java @@ -29,6 +29,7 @@ import java.util.Collections; import java.util.LinkedList; import java.util.List; +import java.util.Optional; import java.util.logging.ErrorManager; import java.util.logging.Filter; import java.util.logging.Formatter; @@ -261,11 +262,11 @@ public LoggingHandler( if (destination != null) { writeOptions.add(WriteOption.destination(destination)); } - writeOptions.add(WriteOption.autoPopulateMetadata(autoPopulateMetadata)); defaultWriteOptions = Iterables.toArray(writeOptions, WriteOption.class); - getLogging().setFlushSeverity(severityFor(flushLevel)); - getLogging().setWriteSynchronicity(config.getSynchronicity()); + logging = loggingOptions.getService(); + logging.setFlushSeverity(severityFor(flushLevel)); + logging.setWriteSynchronicity(config.getSynchronicity()); this.enhancers = new LinkedList<>(); @@ -309,13 +310,34 @@ public void publish(LogRecord record) { } if (logEntry != null) { try { - getLogging().write(ImmutableList.of(logEntry), defaultWriteOptions); + Iterable logEntries = ImmutableList.of(logEntry); + if (autoPopulateMetadata) { + logEntries = + logging.populateMetadata( + logEntries, getMonitoredResource(), "com.google.cloud.logging", "java"); + } + if (useStructuredLogging) { + logEntries.forEach(log -> System.out.println(log.toStructuredJsonString())); + } else { + logging.write(logEntries, defaultWriteOptions); + } } catch (Exception ex) { getErrorManager().error(null, ex, ErrorManager.WRITE_FAILURE); } } } + private MonitoredResource getMonitoredResource() { + Optional resourceOption = + Arrays.stream(defaultWriteOptions) + .filter(o -> o.getOptionType() == WriteOption.OptionType.RESOURCE) + .findFirst(); + if (resourceOption.isPresent()) { + return (MonitoredResource) resourceOption.get().getValue(); + } + return null; + } + private LogEntry logEntryFor(LogRecord record) throws Exception { String payload = getFormatter().format(record); Level level = record.getLevel(); @@ -339,7 +361,7 @@ private LogEntry logEntryFor(LogRecord record) throws Exception { @Override public void flush() { try { - getLogging().flush(); + logging.flush(); } catch (Exception ex) { getErrorManager().error(null, ex, ErrorManager.FLUSH_FAILURE); } @@ -370,7 +392,7 @@ public Level getFlushLevel() { */ public void setFlushLevel(Level flushLevel) { this.flushLevel = flushLevel; - getLogging().setFlushSeverity(severityFor(flushLevel)); + logging.setFlushSeverity(severityFor(flushLevel)); } /** @@ -379,26 +401,17 @@ public void setFlushLevel(Level flushLevel) { * @param synchronicity {@link Synchronicity} */ public void setSynchronicity(Synchronicity synchronicity) { - getLogging().setWriteSynchronicity(synchronicity); + logging.setWriteSynchronicity(synchronicity); } /** Get the flush log level. */ public Synchronicity getSynchronicity() { - return getLogging().getWriteSynchronicity(); + return logging.getWriteSynchronicity(); } /** Sets the metadata auto population flag. */ public void setAutoPopulateMetadata(boolean value) { this.autoPopulateMetadata = value; - List writeOptions = Arrays.asList(defaultWriteOptions); - for (int i = 0; i < writeOptions.size(); i++) { - if (writeOptions.get(i).getOptionType() == WriteOption.OptionType.AUTO_POPULATE_METADATA) { - writeOptions.remove(i); - break; - } - } - writeOptions.add(WriteOption.autoPopulateMetadata(value)); - defaultWriteOptions = Iterables.toArray(writeOptions, WriteOption.class); } /** Gets the metadata auto population flag. */ @@ -459,18 +472,6 @@ private static Severity severityFor(Level level) { } } - /** Returns an instance of the logging service. */ - private Logging getLogging() { - if (logging == null) { - synchronized (this) { - if (logging == null) { - logging = loggingOptions.getService(); - } - } - } - return logging; - } - private static boolean isTrueOrNull(Boolean b) { return b == null || b == Boolean.TRUE; } diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java index 6fc2f2fb5..d274e6469 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java @@ -165,7 +165,6 @@ public class LoggingHandlerTest { WriteOption.logName(LOG_NAME), WriteOption.resource(DEFAULT_RESOURCE), WriteOption.labels(BASE_SEVERITY_MAP), - WriteOption.autoPopulateMetadata(false), }; private Logging logging; @@ -277,8 +276,7 @@ public void testPublishCustomResource() { ImmutableList.of(FINEST_ENTRY), WriteOption.logName(LOG_NAME), WriteOption.resource(resource), - WriteOption.labels(BASE_SEVERITY_MAP), - WriteOption.autoPopulateMetadata(false)); + WriteOption.labels(BASE_SEVERITY_MAP)); expectLastCall().once(); replay(options, logging); Handler handler = new LoggingHandler(LOG_NAME, options, resource); @@ -333,8 +331,7 @@ public void testPublishKubernetesContainerResource() { ImmutableList.of(FINEST_ENTRY), WriteOption.logName(LOG_NAME), WriteOption.resource(resource), - WriteOption.labels(BASE_SEVERITY_MAP), - WriteOption.autoPopulateMetadata(false)); + WriteOption.labels(BASE_SEVERITY_MAP)); expectLastCall().once(); replay(options, logging); Handler handler = new LoggingHandler(LOG_NAME, options, resource); @@ -560,19 +557,27 @@ public void testAutoPopulationEnabled() { options = EasyMock.createMock(LoggingOptions.class); expect(options.getProjectId()).andStubReturn(PROJECT); expect(options.getService()).andStubReturn(logging); - expect(options.getAutoPopulateMetadata()).andStubReturn(true); - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().andVoid(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().andVoid(); - logging.write( - ImmutableList.of(INFO_ENTRY), - WriteOption.logName(LOG_NAME), - WriteOption.resource(DEFAULT_RESOURCE), - WriteOption.labels(BASE_SEVERITY_MAP), - WriteOption.autoPopulateMetadata(true)); + expect(options.getAutoPopulateMetadata()).andStubReturn(Boolean.TRUE); + logging.setFlushSeverity(EasyMock.anyObject(Severity.class)); + expectLastCall().once(); + logging.setWriteSynchronicity(EasyMock.anyObject(Synchronicity.class)); + expectLastCall().once(); + // due to the EasyMock bug https://github.com/easymock/easymock/issues/130 + // it is impossible to define expectation for varargs using anyObject() matcher + // the following mock uses the known fact that the method pass two exclusion prefixes + // the following mocks should be replaced with anyObject() matchers when the bug is fixed + expect( + logging.populateMetadata( + EasyMock.eq(ImmutableList.of(INFO_ENTRY)), + EasyMock.eq(DEFAULT_RESOURCE), + EasyMock.anyString(), + EasyMock.anyString())) + .andReturn(ImmutableList.of(INFO_ENTRY)) + .once(); + logging.write(ImmutableList.of(INFO_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); + Handler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); @@ -591,8 +596,7 @@ private void testPublishCustomResourceWithDestination( WriteOption.logName(LOG_NAME), WriteOption.resource(resource), WriteOption.labels(BASE_SEVERITY_MAP), - WriteOption.destination(destination), - WriteOption.autoPopulateMetadata(false)); + WriteOption.destination(destination)); expectLastCall().once(); replay(options, logging); Handler handler = new LoggingHandler(LOG_NAME, options, resource, null, destination); From 2dcd7fbf914b2ed172d51add35806f17d8b8d358 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 09:13:31 +0000 Subject: [PATCH 07/12] chore: add unit testing for structured logging refactor LoggingHandlerTest. --- .../cloud/logging/LoggingHandlerTest.java | 111 +++++++++--------- 1 file changed, 53 insertions(+), 58 deletions(-) diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java index d274e6469..440abfeb2 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java @@ -21,13 +21,17 @@ import static org.easymock.EasyMock.replay; import static org.easymock.EasyMock.reset; import static org.easymock.EasyMock.verify; +import static org.junit.Assert.assertTrue; +import com.google.api.client.util.Strings; import com.google.cloud.MonitoredResource; import com.google.cloud.logging.LogEntry.Builder; import com.google.cloud.logging.Logging.WriteOption; import com.google.cloud.logging.Payload.StringPayload; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; import java.util.Collections; import java.util.logging.ErrorManager; import java.util.logging.Filter; @@ -199,6 +203,10 @@ public void setUp() { expect(options.getProjectId()).andStubReturn(PROJECT); expect(options.getService()).andStubReturn(logging); expect(options.getAutoPopulateMetadata()).andStubReturn(Boolean.FALSE); + logging.setFlushSeverity(EasyMock.anyObject(Severity.class)); + expectLastCall().once(); + logging.setWriteSynchronicity(EasyMock.anyObject(Synchronicity.class)); + expectLastCall().once(); } @After @@ -214,10 +222,6 @@ private static LogRecord newLogRecord(Level level, String message) { @Test public void testPublishLevels() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(FINEST_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); logging.write(ImmutableList.of(FINER_ENTRY), DEFAULT_OPTIONS); @@ -267,10 +271,6 @@ public void testPublishLevels() { @Test public void testPublishCustomResource() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); MonitoredResource resource = MonitoredResource.of("custom", ImmutableMap.of()); logging.write( ImmutableList.of(FINEST_ENTRY), @@ -309,10 +309,6 @@ public void testPublishCustomResourceWithProject() { @Test public void testPublishKubernetesContainerResource() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); MonitoredResource resource = MonitoredResource.of( "k8s_container", @@ -342,10 +338,6 @@ public void testPublishKubernetesContainerResource() { @Test public void testEnhancedLogEntry() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(FINEST_ENHANCED_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); @@ -366,10 +358,6 @@ public void enhanceLogEntry(Builder builder) { @Test public void testTraceEnhancedLogEntry() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(TRACE_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); @@ -386,10 +374,6 @@ public void testTraceEnhancedLogEntry() { @Test public void testReportWriteError() { RuntimeException ex = new RuntimeException(); - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(FINEST_ENTRY), DEFAULT_OPTIONS); expectLastCall().andStubThrow(ex); replay(options, logging); @@ -408,10 +392,6 @@ public void testReportWriteError() { @Test public void testReportFlushError() { RuntimeException ex = new RuntimeException(); - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(FINEST_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); logging.flush(); @@ -432,10 +412,6 @@ public void testReportFlushError() { @Test public void testReportFormatError() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); replay(options, logging); Formatter formatter = EasyMock.createStrictMock(Formatter.class); RuntimeException ex = new RuntimeException(); @@ -456,10 +432,6 @@ public void testReportFormatError() { // BUG(1795): rewrite this test when flush actually works. // @Test public void testFlushLevel() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.setFlushSeverity(Severity.WARNING); expectLastCall().once(); logging.write( @@ -490,10 +462,6 @@ public void testSyncWrite() { .setTimestamp(123456789L) .build(); - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.setWriteSynchronicity(Synchronicity.SYNC); expectLastCall().once(); logging.write(ImmutableList.of(entry), DEFAULT_OPTIONS); @@ -511,10 +479,6 @@ public void testSyncWrite() { @Test public void testAddHandler() { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().andVoid(); logging.write(ImmutableList.of(FINEST_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); @@ -535,10 +499,6 @@ public void close() { @Test public void testClose() throws Exception { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); logging.write(ImmutableList.of(FINEST_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); logging.close(); @@ -551,17 +511,17 @@ public void testClose() throws Exception { handler.close(); } - @Test - public void testAutoPopulationEnabled() { + private void setupOptionsToEnableAutoPopulation() { reset(options); options = EasyMock.createMock(LoggingOptions.class); expect(options.getProjectId()).andStubReturn(PROJECT); expect(options.getService()).andStubReturn(logging); expect(options.getAutoPopulateMetadata()).andStubReturn(Boolean.TRUE); - logging.setFlushSeverity(EasyMock.anyObject(Severity.class)); - expectLastCall().once(); - logging.setWriteSynchronicity(EasyMock.anyObject(Synchronicity.class)); - expectLastCall().once(); + } + + @Test + public void testAutoPopulationEnabled() { + setupOptionsToEnableAutoPopulation(); // due to the EasyMock bug https://github.com/easymock/easymock/issues/130 // it is impossible to define expectation for varargs using anyObject() matcher // the following mock uses the known fact that the method pass two exclusion prefixes @@ -584,12 +544,47 @@ public void testAutoPopulationEnabled() { handler.publish(newLogRecord(Level.INFO, MESSAGE)); } + @Test + public void testStructuredLoggingEnabled() { + setupOptionsToEnableAutoPopulation(); + expect( + logging.populateMetadata( + EasyMock.eq(ImmutableList.of(INFO_ENTRY)), + EasyMock.eq(DEFAULT_RESOURCE), + EasyMock.anyString(), + EasyMock.anyString())) + .andReturn(ImmutableList.of(INFO_ENTRY)) + .once(); + replay(options, logging); + ByteArrayOutputStream bout = new ByteArrayOutputStream(); + PrintStream out = new PrintStream(bout); + System.setOut(out); + + LoggingHandler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); + handler.setLevel(Level.ALL); + handler.setFormatter(new TestFormatter()); + handler.setUseStructuredLogging(true); + handler.publish(newLogRecord(Level.INFO, MESSAGE)); + + assertTrue(null, !Strings.isNullOrEmpty(bout.toString())); + System.setOut(null); + } + + @Test + /** Validate that nothing is printed to STDOUT */ + public void testStructuredLoggingDisabled() { + ByteArrayOutputStream bout = new ByteArrayOutputStream(); + PrintStream out = new PrintStream(bout); + System.setOut(out); + + testAutoPopulationEnabled(); + + assertTrue(null, Strings.isNullOrEmpty(bout.toString())); + System.setOut(null); + } + private void testPublishCustomResourceWithDestination( LogEntry entry, LogDestinationName destination) { - logging.setFlushSeverity(Severity.ERROR); - expectLastCall().once(); - logging.setWriteSynchronicity(Synchronicity.ASYNC); - expectLastCall().once(); MonitoredResource resource = MonitoredResource.of("custom", ImmutableMap.of()); logging.write( ImmutableList.of(entry), From 08a563d1fe634c0000835e4e68783e2a73cc7b98 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 14:39:41 +0000 Subject: [PATCH 08/12] chore: fix errors in dependencies and unit test --- google-cloud-logging/pom.xml | 5 +++++ .../main/java/com/google/cloud/logging/SourceLocation.java | 3 ++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/google-cloud-logging/pom.xml b/google-cloud-logging/pom.xml index 48204b2b2..a8bbb8bba 100644 --- a/google-cloud-logging/pom.xml +++ b/google-cloud-logging/pom.xml @@ -21,6 +21,11 @@ com.google.guava guava + + com.google.code.gson + gson + 2.8.9 + io.grpc grpc-api diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java index a0d0eec0c..78092cf7b 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java @@ -16,6 +16,7 @@ package com.google.cloud.logging; +import com.google.api.client.util.Strings; import com.google.common.base.MoreObjects; import com.google.logging.v2.LogEntrySourceLocation; import java.io.Serializable; @@ -175,7 +176,7 @@ static SourceLocation fromCurrentContext(String... exclusionClassPaths) { String className = ste.getClassName(); if (exclusionClassPaths != null) { - if (Arrays.stream(exclusionClassPaths).anyMatch(prefix -> className.startsWith(prefix))) { + if (Strings.isNullOrEmpty(className) || Arrays.stream(exclusionClassPaths).anyMatch(prefix -> prefix != null && className.startsWith(prefix))) { continue; } } From bc99faf219bdd49efdc487ebd177ac9524582a10 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 14:45:45 +0000 Subject: [PATCH 09/12] chore: fix lint and add debug printing --- .../java/com/google/cloud/logging/SourceLocation.java | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java index 78092cf7b..a114dbac1 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java @@ -171,15 +171,21 @@ static SourceLocation fromPb(LogEntrySourceLocation sourceLocationPb) { static SourceLocation fromCurrentContext(String... exclusionClassPaths) { StackTraceElement[] stackTrace = (new Exception()).getStackTrace(); + if (exclusionClassPaths != null) { + System.out.println("DEBUG: list of exclusions: " + String.join(", ", exclusionClassPaths)); + } for (int level = 1; level < stackTrace.length; level++) { StackTraceElement ste = stackTrace[level]; String className = ste.getClassName(); if (exclusionClassPaths != null) { - if (Strings.isNullOrEmpty(className) || Arrays.stream(exclusionClassPaths).anyMatch(prefix -> prefix != null && className.startsWith(prefix))) { + if (Strings.isNullOrEmpty(className) + || Arrays.stream(exclusionClassPaths) + .anyMatch(prefix -> prefix != null && className.startsWith(prefix))) { continue; } } + System.out.println("DEBUG: selected element class nName: '" + className + "'"); return newBuilder() .setFile(ste.getFileName()) .setLine(Long.valueOf(ste.getLineNumber())) From 3ab2b5ad03b5e77e541b3a866439da6ed75abba8 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 14:53:13 +0000 Subject: [PATCH 10/12] chore: remove debug info and fix unit test fixes testFromCurrentContextWithVeryLargeLevel by excluding classes from OS JDK --- .../main/java/com/google/cloud/logging/SourceLocation.java | 4 ---- .../java/com/google/cloud/logging/SourceLocationTest.java | 2 +- 2 files changed, 1 insertion(+), 5 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java index a114dbac1..14b6f2ab2 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/SourceLocation.java @@ -171,9 +171,6 @@ static SourceLocation fromPb(LogEntrySourceLocation sourceLocationPb) { static SourceLocation fromCurrentContext(String... exclusionClassPaths) { StackTraceElement[] stackTrace = (new Exception()).getStackTrace(); - if (exclusionClassPaths != null) { - System.out.println("DEBUG: list of exclusions: " + String.join(", ", exclusionClassPaths)); - } for (int level = 1; level < stackTrace.length; level++) { StackTraceElement ste = stackTrace[level]; String className = ste.getClassName(); @@ -185,7 +182,6 @@ static SourceLocation fromCurrentContext(String... exclusionClassPaths) { continue; } } - System.out.println("DEBUG: selected element class nName: '" + className + "'"); return newBuilder() .setFile(ste.getFileName()) .setLine(Long.valueOf(ste.getLineNumber())) diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java index a9035f332..c8314a153 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java @@ -92,7 +92,7 @@ public void testFromCurrentContextWithNegativeLevel() { @Test public void testFromCurrentContextWithVeryLargeLevel() { - SourceLocation data = SourceLocation.fromCurrentContext("com.google", "sun", "java", "org"); + SourceLocation data = SourceLocation.fromCurrentContext("com.google", "sun", "java", "jdk", "org"); assertNull(data); } From 70d6403da5ca7b8f6408abe82e8583e7c47dc036 Mon Sep 17 00:00:00 2001 From: minherz Date: Thu, 30 Dec 2021 14:57:44 +0000 Subject: [PATCH 11/12] chore: fix lint --- .../test/java/com/google/cloud/logging/SourceLocationTest.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java index c8314a153..a49d02127 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/SourceLocationTest.java @@ -92,7 +92,8 @@ public void testFromCurrentContextWithNegativeLevel() { @Test public void testFromCurrentContextWithVeryLargeLevel() { - SourceLocation data = SourceLocation.fromCurrentContext("com.google", "sun", "java", "jdk", "org"); + SourceLocation data = + SourceLocation.fromCurrentContext("com.google", "sun", "java", "jdk", "org"); assertNull(data); } From 4c0561c37955c3b97f1f79e44c77a6c44e28b569 Mon Sep 17 00:00:00 2001 From: minherz Date: Fri, 31 Dec 2021 07:53:16 +0000 Subject: [PATCH 12/12] chore: refactor to improve reliability and readability --- .../com/google/cloud/logging/LogEntry.java | 19 +++++------- .../google/cloud/logging/LoggingConfig.java | 6 ++-- .../google/cloud/logging/LoggingHandler.java | 29 ++++++++++--------- .../com/google/cloud/logging/LoggingImpl.java | 24 ++++++++------- .../cloud/logging/LoggingHandlerTest.java | 2 +- 5 files changed, 42 insertions(+), 38 deletions(-) diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java index 32aa1f456..d53c95306 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java @@ -665,14 +665,13 @@ public StructuredLogFormatter appendField(String name, Object value) { } /** - * Adds a collection of Json fields that {@code value} parameter is serialized to to the current - * string representation. Nothing is added if {@code value} parameter is {@code null}. + * Serializes a dictionary of key, values as Json fields. * - * @param value an object to be serialized to Json using {@link Gson}. + * @param value a {@link Map} of key, value arguments to be serialized using {@link Gson}. * @param appendComma a flag to add a trailing comma. * @return a reference to this object. */ - public StructuredLogFormatter appendJson(Object value, boolean appendComma) { + public StructuredLogFormatter appendDict(Map value, boolean appendComma) { if (value != null) { String json = gson.toJson(value); // append json object without brackets @@ -685,10 +684,6 @@ public StructuredLogFormatter appendJson(Object value, boolean appendComma) { } return this; } - - public StructuredLogFormatter appendJson(Object value) { - return appendJson(value, false); - } } /** @@ -696,6 +691,10 @@ public StructuredLogFormatter appendJson(Object value) { * the logging agents that run on Google Cloud resources. */ public String toStructuredJsonString() { + if (payload.getType() == Type.PROTO) { + throw new UnsupportedOperationException("LogEntry with protobuf payload cannot be converted"); + } + final StringBuilder builder = new StringBuilder("{"); final StructuredLogFormatter formatter = new StructuredLogFormatter(builder); @@ -714,9 +713,7 @@ public String toStructuredJsonString() { formatter.appendField("message", payload.getData(), true); } else if (payload.getType() == Type.JSON) { Payload.JsonPayload jsonPayload = (Payload.JsonPayload) payload; - formatter.appendJson(jsonPayload.getDataAsMap(), true); - } else if (payload.getType() == Type.PROTO) { - throw new UnsupportedOperationException("LogEntry with protobuf payload cannot be converted"); + formatter.appendDict(jsonPayload.getDataAsMap(), true); } builder.append("}"); return builder.toString(); diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java index 50b4a3066..923fa6b52 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingConfig.java @@ -42,7 +42,7 @@ class LoggingConfig { private static final String ENHANCERS_TAG = "enhancers"; private static final String USE_INHERITED_CONTEXT = "useInheritedContext"; private static final String AUTO_POPULATE_METADATA = "autoPopulateMetadata"; - private static final String USE_STRUCTURED_LOGGING = "useStructuredLogging"; + private static final String REDIRECT_TO_STDOUT = "redirectToStdout"; public LoggingConfig(String className) { this.className = className; @@ -82,8 +82,8 @@ Boolean getAutoPopulateMetadata() { return getBooleanProperty(AUTO_POPULATE_METADATA, null); } - Boolean getUseStructuredLogging() { - return getBooleanProperty(USE_STRUCTURED_LOGGING, null); + Boolean getRedirectToStdout() { + return getBooleanProperty(REDIRECT_TO_STDOUT, null); } MonitoredResource getMonitoredResource(String projectId) { diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java index 474faa41e..983127d5a 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingHandler.java @@ -114,10 +114,12 @@ *
  • {@code com.google.cloud.logging.LoggingHandler.autoPopulateMetadata} is a boolean flag that * opts-out the population of the log entries metadata before the logs are sent to Cloud * Logging (defaults to {@code true}). - *
  • {@code com.google.cloud.logging.LoggingHandler.useStructuredLogging} is a boolean flag that - * opts-in redirecting the output of the handler to STDOUT (instead of ingesting it using - * Logging API) by formatting the log following structured logging guidelines. Logging - * (defaults to {@code true}). + *
  • {@code com.google.cloud.logging.LoggingHandler.redirectToStdout} is a boolean flag that + * opts-in redirecting the output of the handler to STDOUT instead of ingesting logs to Cloud + * Logging using Logging API (defaults to {@code true}). Redirecting logs can be used in + * Google Cloud environments with installed logging agent to delegate log ingestions to the + * agent. Redirected logs are formatted as one line Json string following the structured + * logging guidelines. * * *

    To add a {@code LoggingHandler} to an existing {@link Logger} and be sure to avoid infinite @@ -151,7 +153,7 @@ public class LoggingHandler extends Handler { private volatile Level flushLevel; private volatile Boolean autoPopulateMetadata; - private volatile Boolean useStructuredLogging; + private volatile Boolean redirectToStdout; private WriteOption[] defaultWriteOptions; @@ -242,7 +244,7 @@ public LoggingHandler( Boolean f1 = options.getAutoPopulateMetadata(); Boolean f2 = config.getAutoPopulateMetadata(); autoPopulateMetadata = isTrueOrNull(f1) && isTrueOrNull(f2); - useStructuredLogging = firstNonNull(config.getUseStructuredLogging(), Boolean.FALSE); + redirectToStdout = firstNonNull(config.getRedirectToStdout(), Boolean.FALSE); String logName = log != null ? log : config.getLogName(); MonitoredResource resource = firstNonNull( @@ -316,7 +318,7 @@ public void publish(LogRecord record) { logging.populateMetadata( logEntries, getMonitoredResource(), "com.google.cloud.logging", "java"); } - if (useStructuredLogging) { + if (redirectToStdout) { logEntries.forEach(log -> System.out.println(log.toStructuredJsonString())); } else { logging.write(logEntries, defaultWriteOptions); @@ -420,15 +422,16 @@ public Boolean getAutoPopulateMetadata() { } /** - * Enable/disable use of structured logging. When enabled, logs will be printed to STDOUT in the - * structured logging format. Otherwise, logs will be ingested using Logging API. + * Enable/disable redirection to STDOUT. If set to {@code true}, logs will be printed to STDOUT in + * the Json format that can be parsed by the logging agent. If set to {@code false}, logs will be + * ingested to Cloud Logging by calling Logging API. */ - public void setUseStructuredLogging(boolean value) { - this.useStructuredLogging = value; + public void setRedirectToStdout(boolean value) { + this.redirectToStdout = value; } - public Boolean getUseStructuredLogging() { - return useStructuredLogging; + public Boolean getRedirectToStdout() { + return redirectToStdout; } /** diff --git a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java index 72e325d69..0a5cab80c 100644 --- a/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java +++ b/google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java @@ -24,6 +24,7 @@ import static com.google.cloud.logging.Logging.WriteOption.OptionType.LOG_DESTINATION; import static com.google.cloud.logging.Logging.WriteOption.OptionType.LOG_NAME; import static com.google.cloud.logging.Logging.WriteOption.OptionType.RESOURCE; +import static com.google.common.base.Preconditions.checkNotNull; import com.google.api.client.util.Strings; import com.google.api.core.ApiFunction; @@ -41,7 +42,6 @@ import com.google.cloud.logging.spi.v2.LoggingRpc; import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Function; -import com.google.common.base.Preconditions; import com.google.common.base.Throwables; import com.google.common.collect.ImmutableList; import com.google.common.collect.Iterables; @@ -459,10 +459,10 @@ public ApiFuture deleteLogAsync(String log) { @Override public ApiFuture deleteLogAsync(String log, LogDestinationName destination) { - Preconditions.checkNotNull(log, "log parameter cannot be null"); + checkNotNull(log, "log parameter cannot be null"); String projectId = getOptions().getProjectId(); if (destination == null) { - Preconditions.checkNotNull(projectId, "projectId parameter cannot be null"); + checkNotNull(projectId, "projectId parameter cannot be null"); } LogName name = getLogName(projectId, log, destination); DeleteLogRequest request = DeleteLogRequest.newBuilder().setLogName(name.toString()).build(); @@ -796,6 +796,7 @@ public Iterable populateMetadata( Iterable logEntries, MonitoredResource customResource, String... exclusionClassPaths) { + checkNotNull(logEntries); final Boolean needDebugInfo = Iterables.any( logEntries, @@ -813,25 +814,28 @@ public Iterable populateMetadata( // populate empty metadata fields of log entries before calling write API for (LogEntry entry : logEntries) { - LogEntry.Builder builder = entry.toBuilder(); + if (entry == null) { + continue; + } + LogEntry.Builder entityBuilder = entry.toBuilder(); if (resourceMetadata != null && entry.getResource() == null) { - builder.setResource(resourceMetadata); + entityBuilder.setResource(resourceMetadata); } if (context != null && entry.getHttpRequest() == null) { - builder.setHttpRequest(context.getHttpRequest()); + entityBuilder.setHttpRequest(context.getHttpRequest()); } if (context != null && Strings.isNullOrEmpty(entry.getTrace())) { MonitoredResource resource = entry.getResource() != null ? entry.getResource() : resourceMetadata; - builder.setTrace(getFormattedTrace(context.getTraceId(), resource)); + entityBuilder.setTrace(getFormattedTrace(context.getTraceId(), resource)); } if (context != null && Strings.isNullOrEmpty(entry.getSpanId())) { - builder.setSpanId(context.getSpanId()); + entityBuilder.setSpanId(context.getSpanId()); } if (entry.getSeverity() == Severity.DEBUG && entry.getSourceLocation() == null) { - builder.setSourceLocation(sourceLocation); + entityBuilder.setSourceLocation(sourceLocation); } - populatedLogEntries.add(builder.build()); + populatedLogEntries.add(entityBuilder.build()); } return populatedLogEntries; } diff --git a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java index 440abfeb2..bb65f9775 100644 --- a/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java +++ b/google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingHandlerTest.java @@ -563,7 +563,7 @@ public void testStructuredLoggingEnabled() { LoggingHandler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); - handler.setUseStructuredLogging(true); + handler.setRedirectToStdout(true); handler.publish(newLogRecord(Level.INFO, MESSAGE)); assertTrue(null, !Strings.isNullOrEmpty(bout.toString()));