feat: auto-populate metadata of log entries at write() (#803)

Populate empty metadata fields of each log entry on write().

google-cloud-logging/src/main/java/com/google/cloud/logging/Context.java

@@ -49,7 +49,7 @@ public static final class Builder {
 
     /** Sets the HTTP request. */
     public Builder setRequest(HttpRequest request) {
-      this.requestBuilder = request.toBuilder();
+      this.requestBuilder = request != null ? request.toBuilder() : HttpRequest.newBuilder();
       return this;
     }
 

google-cloud-logging/src/main/java/com/google/cloud/logging/LoggingImpl.java

@@ -25,6 +25,7 @@
 import static com.google.cloud.logging.Logging.WriteOption.OptionType.LOG_NAME;
 import static com.google.cloud.logging.Logging.WriteOption.OptionType.RESOURCE;
 
+import com.google.api.client.util.Strings;
 import com.google.api.core.ApiFunction;
 import com.google.api.core.ApiFuture;
 import com.google.api.core.ApiFutureCallback;
@@ -92,6 +93,7 @@
 
 class LoggingImpl extends BaseService<LoggingOptions> implements Logging {
 
+  protected static final String RESOURCE_NAME_FORMAT = "projects/%s/traces/%s";
   private static final int FLUSH_WAIT_TIMEOUT_SECONDS = 6;
   private final LoggingRpc rpc;
   private final Map<Object, ApiFuture<Void>> pendingWrites = new ConcurrentHashMap<>();
@@ -797,6 +799,55 @@ public void write(Iterable<LogEntry> logEntries, WriteOption... options) {
     inWriteCall.set(true);
 
     try {
+      final Map<Option.OptionType, ?> writeOptions = optionMap(options);
+      final Boolean populateMetadata1 = getOptions().getAutoPopulateMetadata();
+      final Boolean populateMetadata2 =
+          WriteOption.OptionType.AUTO_POPULATE_METADATA.get(writeOptions);
+
+      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<LogEntry> 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;
+      }
+
       writeLogEntries(logEntries, options);
       if (flushSeverity != null) {
         for (LogEntry logEntry : logEntries) {
@@ -824,6 +875,27 @@ public void flush() {
     }
   }
 
+  /**
+   * Formats trace following resource name template if the resource metadata has project id.
+   *
+   * @param traceId A trace id string or {@code null} if trace info is missing.
+   * @param resource A {@see MonitoredResource} describing environment metadata.
+   * @return A formatted trace id string.
+   */
+  private String getFormattedTrace(String traceId, MonitoredResource resource) {
+    if (traceId == null) {
+      return null;
+    }
+    String projectId = null;
+    if (resource != null) {
+      projectId = resource.getLabels().getOrDefault(MonitoredResourceUtil.PORJECTID_LABEL, null);
+    }
+    if (projectId != null) {
+      return String.format(RESOURCE_NAME_FORMAT, projectId, traceId);
+    }
+    return traceId;
+  }
+
   /*
    * Write logs synchronously or asynchronously based on writeSynchronicity
    * setting.

google-cloud-logging/src/main/java/com/google/cloud/logging/MonitoredResourceUtil.java

@@ -33,6 +33,7 @@
 public class MonitoredResourceUtil {
 
   private static final String APPENGINE_LABEL_PREFIX = "appengine.googleapis.com/";
+  protected static final String PORJECTID_LABEL = Label.ProjectId.getKey();
 
   protected enum Label {
     ClusterName("cluster_name"),

google-cloud-logging/src/test/java/com/google/cloud/logging/AutoPopulateMetadataTests.java

@@ -0,0 +1,194 @@
+/*
+ * Copyright 2021 Google LLC
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.google.cloud.logging;
+
+import static org.easymock.EasyMock.anyObject;
+import static org.easymock.EasyMock.capture;
+import static org.easymock.EasyMock.createMock;
+import static org.easymock.EasyMock.expect;
+import static org.easymock.EasyMock.newCapture;
+import static org.easymock.EasyMock.replay;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNull;
+
+import com.google.api.core.ApiFutures;
+import com.google.cloud.MonitoredResource;
+import com.google.cloud.logging.HttpRequest.RequestMethod;
+import com.google.cloud.logging.Logging.WriteOption;
+import com.google.cloud.logging.spi.LoggingRpcFactory;
+import com.google.cloud.logging.spi.v2.LoggingRpc;
+import com.google.common.collect.ImmutableList;
+import com.google.logging.v2.WriteLogEntriesRequest;
+import com.google.logging.v2.WriteLogEntriesResponse;
+import org.easymock.Capture;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+
+public class AutoPopulateMetadataTests {
+
+  private static final String LOG_NAME = "test-log";
+  private static final String RESOURCE_PROJECT_ID = "env-project-id";
+  private static final String LOGGING_PROJECT_ID = "log-project-id";
+  private static final MonitoredResource RESOURCE =
+      MonitoredResource.newBuilder("global")
+          .addLabel(MonitoredResourceUtil.PORJECTID_LABEL, RESOURCE_PROJECT_ID)
+          .build();
+  private static final LogEntry SIMPLE_LOG_ENTRY =
+      LogEntry.newBuilder(Payload.StringPayload.of("hello"))
+          .setLogName(LOG_NAME)
+          .setDestination(LogDestinationName.project(LOGGING_PROJECT_ID))
+          .build();
+  private static final LogEntry SIMPLE_LOG_ENTRY_WITH_DEBUG =
+      LogEntry.newBuilder(Payload.StringPayload.of("hello"))
+          .setLogName(LOG_NAME)
+          .setSeverity(Severity.DEBUG)
+          .setDestination(LogDestinationName.project(LOGGING_PROJECT_ID))
+          .build();
+  private static final WriteLogEntriesResponse EMPTY_WRITE_RESPONSE =
+      WriteLogEntriesResponse.newBuilder().build();
+  private static final HttpRequest HTTP_REQUEST =
+      HttpRequest.newBuilder()
+          .setRequestMethod(RequestMethod.GET)
+          .setRequestUrl("https://example.com")
+          .setUserAgent("Test User Agent")
+          .build();
+  private static final String TRACE_ID = "01010101010101010101010101010101";
+  private static final String FORMATTED_TRACE_ID =
+      String.format(LoggingImpl.RESOURCE_NAME_FORMAT, RESOURCE_PROJECT_ID, TRACE_ID);
+  private static final String SPAN_ID = "1";
+
+  private LoggingRpcFactory mockedRpcFactory;
+  private LoggingRpc mockedRpc;
+  private Logging logging;
+  private Capture<WriteLogEntriesRequest> rpcWriteArgument = newCapture();
+  private ResourceTypeEnvironmentGetter mockedEnvGetter;
+
+  @Before
+  public void setup() {
+    mockedEnvGetter = createMock(ResourceTypeEnvironmentGetter.class);
+    mockedRpcFactory = createMock(LoggingRpcFactory.class);
+    mockedRpc = createMock(LoggingRpc.class);
+    expect(mockedRpcFactory.create(anyObject(LoggingOptions.class)))
+        .andReturn(mockedRpc)
+        .anyTimes();
+    expect(mockedRpc.write(capture(rpcWriteArgument)))
+        .andReturn(ApiFutures.immediateFuture(EMPTY_WRITE_RESPONSE));
+    MonitoredResourceUtil.setEnvironmentGetter(mockedEnvGetter);
+    // 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);
+
+    LoggingOptions options =
+        LoggingOptions.newBuilder()
+            .setProjectId(RESOURCE_PROJECT_ID)
+            .setServiceRpcFactory(mockedRpcFactory)
+            .build();
+    logging = options.getService();
+  }
+
+  @After
+  public void teardown() {
+    (new ContextHandler()).removeCurrentContext();
+  }
+
+  private void mockCurrentContext(HttpRequest request, String traceId, String spanId) {
+    Context mockedContext =
+        Context.newBuilder().setRequest(request).setTraceId(traceId).setSpanId(spanId).build();
+    (new ContextHandler()).setCurrentContext(mockedContext);
+  }
+
+  @Test
+  public void testAutoPopulationEnabledInLoggingOptions() {
+    mockCurrentContext(HTTP_REQUEST, TRACE_ID, SPAN_ID);
+
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertEquals(HTTP_REQUEST, actual.getHttpRequest());
+    assertEquals(FORMATTED_TRACE_ID, actual.getTrace());
+    assertEquals(SPAN_ID, actual.getSpanId());
+    assertEquals(RESOURCE, actual.getResource());
+  }
+
+  @Test
+  public void testAutoPopulationEnabledInWriteOptionsAndDisabledInLoggingOptions() {
+    // redefine logging option to opt out auto-populating
+    LoggingOptions options =
+        logging.getOptions().toBuilder().setAutoPopulateMetadata(false).build();
+    logging = options.getService();
+    mockCurrentContext(HTTP_REQUEST, TRACE_ID, SPAN_ID);
+
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY), WriteOption.autoPopulateMetadata(true));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertEquals(HTTP_REQUEST, actual.getHttpRequest());
+    assertEquals(FORMATTED_TRACE_ID, actual.getTrace());
+    assertEquals(SPAN_ID, actual.getSpanId());
+    assertEquals(RESOURCE, actual.getResource());
+  }
+
+  @Test
+  public void testAutoPopulationDisabledInWriteOptions() {
+    mockCurrentContext(HTTP_REQUEST, TRACE_ID, SPAN_ID);
+
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY), WriteOption.autoPopulateMetadata(false));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertNull(actual.getHttpRequest());
+    assertNull(actual.getTrace());
+    assertNull(actual.getSpanId());
+    assertNull(actual.getResource());
+  }
+
+  @Test
+  public void testSourceLocationPopulation() {
+    SourceLocation expected = SourceLocation.fromCurrentContext(0);
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY_WITH_DEBUG));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertEquals(expected.getFile(), actual.getSourceLocation().getFile());
+    assertEquals(expected.getClass(), actual.getSourceLocation().getClass());
+    assertEquals(expected.getFunction(), actual.getSourceLocation().getFunction());
+    assertEquals(new Long(expected.getLine() + 1), actual.getSourceLocation().getLine());
+  }
+
+  @Test
+  public void testNotFormattedTraceId() {
+    mockCurrentContext(HTTP_REQUEST, TRACE_ID, SPAN_ID);
+
+    final MonitoredResource expectedResource = MonitoredResource.newBuilder("custom").build();
+
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY), WriteOption.resource(expectedResource));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertEquals(TRACE_ID, actual.getTrace());
+  }
+
+  @Test
+  public void testMonitoredResourcePopulationInWriteOptions() {
+    mockCurrentContext(HTTP_REQUEST, TRACE_ID, SPAN_ID);
+
+    final MonitoredResource expectedResource = MonitoredResource.newBuilder("custom").build();
+
+    logging.write(ImmutableList.of(SIMPLE_LOG_ENTRY), WriteOption.resource(expectedResource));
+
+    LogEntry actual = LogEntry.fromPb(rpcWriteArgument.getValue().getEntries(0));
+    assertEquals(expectedResource, actual.getResource());
+  }
+}

google-cloud-logging/src/test/java/com/google/cloud/logging/BaseSystemTest.java

@@ -130,8 +130,6 @@ protected static Iterator<LogEntry> waitForLogs(LogName logName) throws Interrup
     return waitForLogs(logName, null, 1);
   }
 
-  private static final DateFormat DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
-
   protected static Iterator<LogEntry> waitForLogs(Logging.EntryListOption[] options, int minLogs)
       throws InterruptedException {
     Page<LogEntry> page = logging.listLogEntries(options);

google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingImplTest.java

@@ -261,6 +261,9 @@ public void setUp() {
             .setProjectId(PROJECT)
             .setServiceRpcFactory(rpcFactoryMock)
             .setRetrySettings(ServiceOptions.getNoRetrySettings())
+            // disable auto-population for LoggingImpl class tests
+            // see {@see AutoPopulationTests} for auto-population tests
+            .setAutoPopulateMetadata(false)
             .build();
 
     // By default when calling ListLogEntries, we append a filter of last 24 hours.

google-cloud-logging/src/test/java/com/google/cloud/logging/LoggingOptionsTest.java

@@ -24,6 +24,7 @@
 
 public class LoggingOptionsTest {
   private static final Boolean DONT_AUTO_POPULATE_METADATA = false;
+  private static final String PROJECT_ID = "fake-project-id";
 
   @Test(expected = IllegalArgumentException.class)
   public void testNonGrpcTransportOptions() {
@@ -34,13 +35,16 @@ public void testNonGrpcTransportOptions() {
   @Test
   public void testAutoPopulateMetadataOption() {
     LoggingOptions actual =
-        LoggingOptions.newBuilder().setAutoPopulateMetadata(DONT_AUTO_POPULATE_METADATA).build();
+        LoggingOptions.newBuilder()
+            .setProjectId(PROJECT_ID)
+            .setAutoPopulateMetadata(DONT_AUTO_POPULATE_METADATA)
+            .build();
     assertEquals(DONT_AUTO_POPULATE_METADATA, actual.getAutoPopulateMetadata());
   }
 
   @Test
   public void testAutoPopulateMetadataDefaultOption() {
-    LoggingOptions actual = LoggingOptions.getDefaultInstance();
+    LoggingOptions actual = LoggingOptions.newBuilder().setProjectId(PROJECT_ID).build();
     assertEquals(Boolean.TRUE, actual.getAutoPopulateMetadata());
   }
 }