From b202f5c4bee753b5516bb084ffdf029c8fc3f1ee Mon Sep 17 00:00:00 2001 From: bpcreech <35012922+bpcreech@users.noreply.github.com> Date: Wed, 7 Sep 2022 21:57:07 -0400 Subject: [PATCH] feat: Add support for JSON logging to stderr (#1027) Co-authored-by: Ben Creech --- .../google/cloud/logging/LoggingConfig.java | 6 + .../google/cloud/logging/LoggingHandler.java | 77 ++++++-- .../cloud/logging/LoggingHandlerTest.java | 175 ++++++++++++------ 3 files changed, 187 insertions(+), 71 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 702ef1a5a..199754b58 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 @@ -23,6 +23,7 @@ import com.google.common.collect.ImmutableList; import java.util.ArrayList; import java.util.List; +import java.util.Optional; import java.util.logging.Filter; import java.util.logging.Formatter; import java.util.logging.Level; @@ -44,6 +45,7 @@ class LoggingConfig { private static final String USE_INHERITED_CONTEXT = "useInheritedContext"; private static final String AUTO_POPULATE_METADATA = "autoPopulateMetadata"; private static final String REDIRECT_TO_STDOUT = "redirectToStdout"; + private static final String LOG_TARGET = "logTarget"; public LoggingConfig(String className) { this.className = className; @@ -87,6 +89,10 @@ Boolean getRedirectToStdout() { return getBooleanProperty(REDIRECT_TO_STDOUT, null); } + Optional getLogTarget() { + return Optional.ofNullable(getProperty(LOG_TARGET)).map(LoggingHandler.LogTarget::valueOf); + } + MonitoredResource getMonitoredResource(String projectId) { String resourceType = getProperty(RESOURCE_TYPE_TAG, ""); return MonitoredResourceUtil.getResource(projectId, resourceType); 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 768209b46..8acad5a41 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 @@ -115,10 +115,15 @@ * 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 + * Logging using Logging API (defaults to {@code false}). 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. + * logging guidelines. This flag is deprecated; use {@code + * com.google.cloud.logging.LoggingHandler.logTarget} instead. + *
  • {@code com.google.cloud.logging.LoggingHandler.logTarget} is an enumeration controlling log + * routing (defaults to {@code CLOUD_LOGGING}). If set to STDOUT or STDERR, logs will be + * printed to the corresponding stream in the Json format that can be parsed by the logging + * agent. If set to CLOUD_LOGGING, logs will be sent directly to the Google Cloud Logging API. * * *

    To add a {@code LoggingHandler} to an existing {@link Logger} and be sure to avoid infinite @@ -136,6 +141,16 @@ public class LoggingHandler extends Handler { private static final String LEVEL_NAME_KEY = "levelName"; private static final String LEVEL_VALUE_KEY = "levelValue"; + /** Where to send logs. */ + public enum LogTarget { + /** Sends logs to the Cloud Logging API. */ + CLOUD_LOGGING, + /** Sends JSON-formatted logs to stdout, for use with the Google Cloud logging agent. */ + STDOUT, + /** Sends JSON-formatted logs to stderr, for use with the Google Cloud logging agent. */ + STDERR + } + private final List enhancers; private final LoggingOptions loggingOptions; @@ -152,7 +167,7 @@ public class LoggingHandler extends Handler { private volatile Level flushLevel; private volatile Boolean autoPopulateMetadata; - private volatile Boolean redirectToStdout; + private volatile LogTarget logTarget; private final WriteOption[] defaultWriteOptions; @@ -243,7 +258,13 @@ public LoggingHandler( Boolean f1 = loggingOptions.getAutoPopulateMetadata(); Boolean f2 = config.getAutoPopulateMetadata(); autoPopulateMetadata = isTrueOrNull(f1) && isTrueOrNull(f2); - redirectToStdout = firstNonNull(config.getRedirectToStdout(), Boolean.FALSE); + logTarget = + config + .getLogTarget() + .orElse( + firstNonNull(config.getRedirectToStdout(), Boolean.FALSE) + ? LogTarget.STDOUT + : LogTarget.CLOUD_LOGGING); String logName = log != null ? log : config.getLogName(); MonitoredResource resource = firstNonNull( @@ -310,18 +331,24 @@ public void publish(LogRecord record) { if (logEntry != null) { try { Iterable logEntries = - redirectToStdout - ? Instrumentation.populateInstrumentationInfo(ImmutableList.of(logEntry)).y() - : ImmutableList.of(logEntry); + logTarget == LogTarget.CLOUD_LOGGING + ? ImmutableList.of(logEntry) + : Instrumentation.populateInstrumentationInfo(ImmutableList.of(logEntry)).y(); if (autoPopulateMetadata) { logEntries = logging.populateMetadata( logEntries, getMonitoredResource(), "com.google.cloud.logging", "java"); } - if (redirectToStdout) { - logEntries.forEach(log -> System.out.println(log.toStructuredJsonString())); - } else { - logging.write(logEntries, defaultWriteOptions); + switch (logTarget) { + case STDOUT: + logEntries.forEach(log -> System.out.println(log.toStructuredJsonString())); + break; + case STDERR: + logEntries.forEach(log -> System.err.println(log.toStructuredJsonString())); + break; + case CLOUD_LOGGING: + logging.write(logEntries, defaultWriteOptions); + break; } } catch (RuntimeException ex) { getErrorManager().error(null, ex, ErrorManager.WRITE_FAILURE); @@ -425,13 +452,37 @@ public Boolean getAutoPopulateMetadata() { * 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. + * + *

    This method is mutually exclusive with {@link #setLogTarget()}. + * + * @deprecated Use {@link #setLogTarget()}. */ + @Deprecated public void setRedirectToStdout(boolean value) { - this.redirectToStdout = value; + this.logTarget = value ? LogTarget.STDOUT : LogTarget.CLOUD_LOGGING; } + /* + * @deprecated Use {@link #getLogTarget()}. + */ + @Deprecated public Boolean getRedirectToStdout() { - return redirectToStdout; + return this.logTarget == LogTarget.STDOUT; + } + + /** + * Configure the destination for ingested logs. If set to STDOUT or STDERR, logs will be printed + * to the corresponding stream in the Json format that can be parsed by the logging agent. If set + * to CLOUD_LOGGING, logs will be sent directly to the Google Cloud Logging API. + * + *

    This method is mutually exclusive with {@link #setRedirectToStdout()}. + */ + public void setLogTarget(LogTarget value) { + this.logTarget = value; + } + + public LogTarget getLogTarget() { + return logTarget; } /** 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 c1e3f3d48..a03ac04bf 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 @@ -16,21 +16,20 @@ package com.google.cloud.logging; +import static com.google.common.truth.Truth.assertThat; import static org.easymock.EasyMock.expect; import static org.easymock.EasyMock.expectLastCall; import static org.easymock.EasyMock.replay; import static org.easymock.EasyMock.reset; import static org.easymock.EasyMock.verify; import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertFalse; -import static org.junit.Assert.assertTrue; -import com.google.api.client.util.Strings; import com.google.cloud.MonitoredResource; 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 com.google.gson.JsonParser; import java.io.ByteArrayOutputStream; import java.io.PrintStream; import java.util.logging.ErrorManager; @@ -44,11 +43,13 @@ import org.junit.After; import org.junit.Before; import org.junit.Ignore; +import org.junit.Rule; import org.junit.Test; +import org.junit.rules.ExternalResource; import org.junit.runner.RunWith; import org.junit.runners.JUnit4; -@RunWith(JUnit4.class) +@RunWith(JUnit4.class) // We're testing our own deprecated Builder methods. @SuppressWarnings("deprecation") public class LoggingHandlerTest { @@ -165,6 +166,13 @@ public class LoggingHandlerTest { .setTrace("projects/projectId/traces/traceId") .setTimestamp(123456789L) .build(); + private static final LogEntry DIAGNOSTIC_ENTRY = + LogEntry.newBuilder( + InstrumentationTest.generateInstrumentationPayload( + Instrumentation.JAVA_LIBRARY_NAME_PREFIX, + Instrumentation.getLibraryVersion(Instrumentation.class))) + .setLogName(Instrumentation.INSTRUMENTATION_LOG_NAME) + .build(); private static final ImmutableMap BASE_SEVERITY_MAP = ImmutableMap.of( @@ -201,6 +209,28 @@ public void enhanceLogEntry(LogEntry.Builder builder) { } } + static class OutputStreamPatcher extends ExternalResource { + ByteArrayOutputStream out = new ByteArrayOutputStream(); + ByteArrayOutputStream err = new ByteArrayOutputStream(); + PrintStream oldOut = System.out; + PrintStream oldErr = System.err; + + // Note that we don't apply the patch in the before() method, because we don't need every test + // in this class to run with a patched System.out and System.err. + void patch() { + System.setOut(new PrintStream(out)); + System.setErr(new PrintStream(err)); + } + + @Override + protected void after() { + System.setOut(oldOut); + System.setErr(oldErr); + } + } + + @Rule public final OutputStreamPatcher outputStreamPatcher = new OutputStreamPatcher(); + @Before public void setUp() { Instrumentation.setInstrumentationStatus(true); @@ -360,45 +390,52 @@ public void testEnhancedLogEntry() { logging.write(ImmutableList.of(FINEST_ENHANCED_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); - LoggingEnhancer enhancer = - new LoggingEnhancer() { - @Override - public void enhanceLogEntry(LogEntry.Builder builder) { - builder.addLabel("enhanced", "true"); - } - }; Handler handler = - new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(enhancer)); + new LoggingHandler( + LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(new TestLoggingEnhancer())); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); handler.publish(newLogRecord(Level.FINEST, MESSAGE)); } + void validateJsonOutput(ByteArrayOutputStream bout) { + final String expectedOutput = + "{\"severity\":\"INFO\",\"time\":\"1970-01-02T10:17:36.789Z\",\"logging.googleapis.com/labels\":{\"enhanced\":\"true\"},\"logging.googleapis.com/trace_sampled\":false,\"message\":\"message\"}"; + assertEquals(JsonParser.parseString(expectedOutput), JsonParser.parseString(bout.toString())); + } + @Test public void testEnhancedLogEntryPrintToStdout() { - final String ExpectedOutput = - "{\"severity\":\"INFO\",\"time\":\"1970-01-02T10:17:36.789Z\",\"logging.googleapis.com/labels\":{\"enhanced\":\"true\"},\"logging.googleapis.com/trace_sampled\":false,\"message\":\"message\"}"; + outputStreamPatcher.patch(); + replay(options, logging); - ByteArrayOutputStream bout = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(bout); - System.setOut(out); - LoggingEnhancer enhancer = - new LoggingEnhancer() { - @Override - public void enhanceLogEntry(LogEntry.Builder builder) { - builder.addLabel("enhanced", "true"); - } - }; LoggingHandler handler = - new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(enhancer)); + new LoggingHandler( + LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(new TestLoggingEnhancer())); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); - handler.setRedirectToStdout(true); + handler.setLogTarget(LoggingHandler.LogTarget.STDOUT); + handler.publish(newLogRecord(Level.INFO, MESSAGE)); + + validateJsonOutput(outputStreamPatcher.out); + } + + @Test + public void testEnhancedLogEntryPrintToStderr() { + outputStreamPatcher.patch(); + + replay(options, logging); + + LoggingHandler handler = + new LoggingHandler( + LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(new TestLoggingEnhancer())); + handler.setLevel(Level.ALL); + handler.setFormatter(new TestFormatter()); + handler.setLogTarget(LoggingHandler.LogTarget.STDERR); handler.publish(newLogRecord(Level.INFO, MESSAGE)); - assertEquals(ExpectedOutput, bout.toString().trim()); // ignore trailing newline! - System.setOut(null); + validateJsonOutput(outputStreamPatcher.err); } @Test @@ -557,76 +594,98 @@ public void testClose() throws Exception { handler.close(); } - private void setupOptionsToEnableAutoPopulation() { + private void setupOptionsToEnableAutoPopulation(boolean expectDiagnostic) { + // Reset the one-time instrumentation status population flag so it happens again on this test: + Instrumentation.setInstrumentationStatus(false); + reset(options); options = EasyMock.createMock(LoggingOptions.class); expect(options.getProjectId()).andStubReturn(PROJECT); expect(options.getService()).andStubReturn(logging); expect(options.getAutoPopulateMetadata()).andStubReturn(Boolean.TRUE); - } - @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 // 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( + expectDiagnostic + ? ImmutableList.of(INFO_ENTRY, DIAGNOSTIC_ENTRY) + : ImmutableList.of(INFO_ENTRY)), EasyMock.eq(DEFAULT_RESOURCE), EasyMock.anyString(), EasyMock.anyString())) .andReturn(ImmutableList.of(INFO_ENTRY)) .once(); + } + + @Test + public void testAutoPopulationEnabled() { + setupOptionsToEnableAutoPopulation(/* expectDiagnostic= */ false); logging.write(ImmutableList.of(INFO_ENTRY), DEFAULT_OPTIONS); expectLastCall().once(); replay(options, logging); + outputStreamPatcher.patch(); Handler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); handler.publish(newLogRecord(Level.INFO, MESSAGE)); + + // Validate that nothing is printed to STDOUT or STDERR since we don't ask for it. + assertThat(outputStreamPatcher.out.size()).isEqualTo(0); + assertThat(outputStreamPatcher.err.size()).isEqualTo(0); } + // Test the deprecated get/setRedirectToStdout methods. + @SuppressWarnings("deprecation") @Test - public void testRedirectToStdoutEnabled() { - setupOptionsToEnableAutoPopulation(); - expect( - logging.populateMetadata( - EasyMock.eq(ImmutableList.of(INFO_ENTRY)), - EasyMock.eq(DEFAULT_RESOURCE), - EasyMock.anyString(), - EasyMock.anyString())) - .andReturn(ImmutableList.of(INFO_ENTRY)) - .once(); + public void testSetRedirectToStdoutImpliesLogTarget() { replay(options, logging); - ByteArrayOutputStream bout = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(bout); - System.setOut(out); + LoggingHandler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); + + assertThat(handler.getLogTarget()).isEqualTo(LoggingHandler.LogTarget.CLOUD_LOGGING); + assertThat(handler.getRedirectToStdout()).isFalse(); + + handler.setRedirectToStdout(true); + assertThat(handler.getLogTarget()).isEqualTo(LoggingHandler.LogTarget.STDOUT); + assertThat(handler.getRedirectToStdout()).isTrue(); + } + + @Test + public void testRedirectToStdout() { + setupOptionsToEnableAutoPopulation(/* expectDiagnostic= */ true); + replay(options, logging); + outputStreamPatcher.patch(); LoggingHandler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); - handler.setRedirectToStdout(true); + handler.setLogTarget(LoggingHandler.LogTarget.STDOUT); + handler.publish(newLogRecord(Level.INFO, MESSAGE)); - assertFalse(null, Strings.isNullOrEmpty(bout.toString())); - System.setOut(null); + assertThat(outputStreamPatcher.out.size()).isGreaterThan(0); + assertThat(outputStreamPatcher.err.size()).isEqualTo(0); } @Test - /** Validate that nothing is printed to STDOUT */ - public void testRedirectToStdoutDisabled() { - ByteArrayOutputStream bout = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(bout); - System.setOut(out); + public void testRedirectToStderr() { + setupOptionsToEnableAutoPopulation(/* expectDiagnostic= */ true); + replay(options, logging); + outputStreamPatcher.patch(); + + LoggingHandler handler = new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE); + handler.setLevel(Level.ALL); + handler.setFormatter(new TestFormatter()); + handler.setLogTarget(LoggingHandler.LogTarget.STDERR); - testAutoPopulationEnabled(); + handler.publish(newLogRecord(Level.INFO, MESSAGE)); - assertTrue(null, Strings.isNullOrEmpty(bout.toString())); - System.setOut(null); + assertThat(outputStreamPatcher.out.size()).isEqualTo(0); + assertThat(outputStreamPatcher.err.size()).isGreaterThan(0); } private void testPublishCustomResourceWithDestination(