From c3a364d0c8eb1802f4e54e181171cc11442551d6 Mon Sep 17 00:00:00 2001 From: Ben Creech Date: Mon, 8 Aug 2022 20:07:33 +0000 Subject: [PATCH] Add support for JSON logging to stderr --- .../google/cloud/logging/LoggingConfig.java | 6 + .../google/cloud/logging/LoggingHandler.java | 77 ++++++-- .../cloud/logging/LoggingHandlerTest.java | 187 ++++++++++++------ 3 files changed, 192 insertions(+), 78 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 923fa6b52..945709ef4 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 @@ -22,6 +22,7 @@ import java.util.ArrayList; import java.util.Collections; import java.util.List; +import java.util.Optional; import java.util.logging.Filter; import java.util.logging.Formatter; import java.util.logging.Level; @@ -43,6 +44,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; @@ -86,6 +88,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 ffa4c6273..e3f6a49c0 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 @@ -116,10 +116,14 @@ * 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}). See {@link + * com.google.cloud.logging.LoggingHandler.LogTarget}. * * *

    To add a {@code LoggingHandler} to an existing {@link Logger} and be sure to avoid infinite @@ -137,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 to. */ + 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; @@ -153,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 WriteOption[] defaultWriteOptions; @@ -244,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( @@ -313,18 +333,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 (Exception ex) { getErrorManager().error(null, ex, ErrorManager.WRITE_FAILURE); @@ -426,15 +452,36 @@ 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. + * the Json format that can be parsed by the logging agent. If {@code setRedirectToStdout} and + * {@link setRedirectToStdout} are both set to {@code false}, logs will be ingested to Cloud + * Logging by calling Logging API. + * + * @deprecated Use setLogTarget. */ + @Deprecated public void setRedirectToStdout(boolean value) { - this.redirectToStdout = value; + this.logTarget = value ? LogTarget.STDOUT : LogTarget.CLOUD_LOGGING; } + /* + * @deprecated Use 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. + */ + 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 d55a3e786..5d93c5dd7 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,25 +16,23 @@ package com.google.cloud.logging; +import static com.google.common.truth.Truth.assertThat; +import static java.nio.charset.StandardCharsets.UTF_8; 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.assertNotNull; -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 com.google.gson.JsonParser; import java.io.ByteArrayOutputStream; import java.io.PrintStream; -import java.util.Collections; import java.util.logging.ErrorManager; import java.util.logging.Filter; import java.util.logging.Formatter; @@ -45,8 +43,14 @@ import org.easymock.EasyMock; 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) // We're testing our own deprecated Builder methods. @SuppressWarnings("deprecation") public class LoggingHandlerTest { @@ -163,6 +167,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( @@ -199,6 +210,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); @@ -229,7 +262,7 @@ public void testDefaultHandlerCreation() { String oldProject = System.getProperty(PROJECT_ENV_NAME); System.setProperty(PROJECT_ENV_NAME, PROJECT); replay(options, logging); - assertNotNull(new LoggingHandler()); + LoggingHandler unused = new LoggingHandler(); if (oldProject != null) { System.setProperty(PROJECT_ENV_NAME, oldProject); } else { @@ -358,47 +391,53 @@ 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(Builder builder) { - builder.addLabel("enhanced", "true"); - } - }; Handler handler = new LoggingHandler( - LOG_NAME, options, DEFAULT_RESOURCE, Collections.singletonList(enhancer)); + 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(UTF_8))); + } + @Test public void testEnhancedLogEntryPrintToStdout() { - final String ExpectedOutput = - "{\"severity\":\"INFO\",\"timestamp\":\"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(Builder builder) { - builder.addLabel("enhanced", "true"); - } - }; LoggingHandler handler = new LoggingHandler( - LOG_NAME, options, DEFAULT_RESOURCE, Collections.singletonList(enhancer)); + 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 @@ -409,8 +448,7 @@ public void testTraceEnhancedLogEntry() { LoggingEnhancer enhancer = new TraceLoggingEnhancer(); TraceLoggingEnhancer.setCurrentTraceId("projects/projectId/traces/traceId"); Handler handler = - new LoggingHandler( - LOG_NAME, options, DEFAULT_RESOURCE, Collections.singletonList(enhancer)); + new LoggingHandler(LOG_NAME, options, DEFAULT_RESOURCE, ImmutableList.of(enhancer)); handler.setLevel(Level.ALL); handler.setFormatter(new TestFormatter()); handler.publish(newLogRecord(Level.FINEST, MESSAGE)); @@ -475,7 +513,8 @@ public void testReportFormatError() { } // BUG(1795): rewrite this test when flush actually works. - // @Test + @Ignore + @Test public void testFlushLevel() { logging.setFlushSeverity(Severity.WARNING); expectLastCall().once(); @@ -557,76 +596,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)); - assertTrue(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(