[POC] add client side logging

.github/workflows/ci.yaml

@@ -255,6 +255,15 @@ jobs:
             -P enable-integration-tests \
             --batch-mode \
             --no-transfer-progress
+      # The `envVarLoggingTest` profile runs tests that require an environment variable
+      - name: Showcase integration tests - Logging
+        run: |
+          mvn verify -P '!showcase,enable-integration-tests,envVarLoggingTest' \
+            --batch-mode \
+            --no-transfer-progress
+        # Set the Env Var for this step only
+        env:
+          GOOGLE_SDK_JAVA_LOGGING: true
 
   showcase-native:
     runs-on: ubuntu-22.04

gapic-generator-java-pom-parent/pom.xml

@@ -38,6 +38,7 @@
     <j2objc-annotations.version>3.0.0</j2objc-annotations.version>
     <threetenbp.version>1.7.0</threetenbp.version>
     <junit.version>5.11.3</junit.version>
+    <slf4j.version>2.0.16</slf4j.version>
   </properties>
 
   <developers>

gax-java/gax-grpc/src/main/java/com/google/api/gax/grpc/GrpcLoggingInterceptor.java

@@ -0,0 +1,202 @@
+/*
+ * Copyright 2024 Google LLC
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are
+ * met:
+ *
+ *     * Redistributions of source code must retain the above copyright
+ * notice, this list of conditions and the following disclaimer.
+ *     * Redistributions in binary form must reproduce the above
+ * copyright notice, this list of conditions and the following disclaimer
+ * in the documentation and/or other materials provided with the
+ * distribution.
+ *     * Neither the name of Google LLC nor the names of its
+ * contributors may be used to endorse or promote products derived from
+ * this software without specific prior written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+ * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+ * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+ * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+ * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+ * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+
+package com.google.api.gax.grpc;
+
+import com.google.api.core.InternalApi;
+import com.google.api.gax.logging.LogData;
+import com.google.api.gax.logging.LoggingUtils;
+import com.google.gson.Gson;
+import com.google.gson.JsonObject;
+import io.grpc.CallOptions;
+import io.grpc.Channel;
+import io.grpc.ClientCall;
+import io.grpc.ClientInterceptor;
+import io.grpc.ForwardingClientCall;
+import io.grpc.ForwardingClientCallListener.SimpleForwardingClientCallListener;
+import io.grpc.Metadata;
+import io.grpc.MethodDescriptor;
+import io.grpc.Status;
+import java.util.Map;
+import org.slf4j.Logger;
+import org.slf4j.event.Level;
+
+@InternalApi
+public class GrpcLoggingInterceptor implements ClientInterceptor {
+
+  private static final Logger logger = LoggingUtils.getLogger(GrpcLoggingInterceptor.class);
+  private static final Gson gson = new Gson();
+
+  ClientCall.Listener<?> currentListener; // expose for test setup
+
+  @Override
+  public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
+      MethodDescriptor<ReqT, RespT> method, CallOptions callOptions, Channel next) {
+
+    return new ForwardingClientCall.SimpleForwardingClientCall<ReqT, RespT>(
+        next.newCall(method, callOptions)) {
+      LogData.Builder logDataBuilder = LogData.builder();
+
+      @Override
+      public void start(Listener<RespT> responseListener, Metadata headers) {
+        logRequestInfo(method, logDataBuilder, logger);
+        recordRequestHeaders(headers, logDataBuilder);
+        SimpleForwardingClientCallListener<RespT> responseLoggingListener =
+            new SimpleForwardingClientCallListener<RespT>(responseListener) {
+              @Override
+              public void onHeaders(Metadata headers) {
+                recordResponseHeaders(headers, logDataBuilder);
+                super.onHeaders(headers);
+              }
+
+              @Override
+              public void onMessage(RespT message) {
+                recordResponsePayload(message, logDataBuilder);
+                super.onMessage(message);
+              }
+
+              @Override
+              public void onClose(Status status, Metadata trailers) {
+                try {
+                  logResponse(status.getCode().toString(), logDataBuilder);
+                } finally {
+                  logDataBuilder = null; // release resource
+                }
+                super.onClose(status, trailers);
+              }
+            };
+        currentListener = responseLoggingListener;
+        super.start(responseLoggingListener, headers);
+      }
+
+      @Override
+      public void sendMessage(ReqT message) {
+        logRequestDetails(message, logDataBuilder);
+        super.sendMessage(message);
+      }
+    };
+  }
+
+  // Helper methods for logging
+  // some duplications with http equivalent to avoid exposing as public method for now
+  <ReqT, RespT> void logRequestInfo(
+      MethodDescriptor<ReqT, RespT> method, LogData.Builder logDataBuilder, Logger logger) {
+    try {
+      if (logger.isInfoEnabled()) {
+        logDataBuilder.serviceName(method.getServiceName()).rpcName(method.getFullMethodName());
+
+        if (!logger.isDebugEnabled()) {
+          LoggingUtils.logWithMDC(
+              logger, Level.INFO, logDataBuilder.build().toMapRequest(), "Sending gRPC request");
+        }
+      }
+    } catch (Exception e) {
+      logger.error("Error logging request info (and headers)", e);
+    }
+  }
+
+  private void recordRequestHeaders(Metadata headers, LogData.Builder logDataBuilder) {
+    try {
+      if (logger.isDebugEnabled()) {
+        JsonObject requestHeaders = mapHeadersToJsonObject(headers);
+        logDataBuilder.requestHeaders(gson.toJson(requestHeaders));
+      }
+    } catch (Exception e) {
+      logger.error("Error recording request headers", e);
+    }
+  }
+
+  void recordResponseHeaders(Metadata headers, LogData.Builder logDataBuilder) {
+    try {
+      if (logger.isDebugEnabled()) {
+        JsonObject responseHeaders = mapHeadersToJsonObject(headers);
+        logDataBuilder.responseHeaders(gson.toJson(responseHeaders));
+      }
+    } catch (Exception e) {
+      logger.error("Error recording response headers", e);
+    }
+  }
+
+  <RespT> void recordResponsePayload(RespT message, LogData.Builder logDataBuilder) {
+    try {
+      if (logger.isDebugEnabled()) {
+        logDataBuilder.responsePayload(gson.toJsonTree(message));
+      }
+    } catch (Exception e) {
+      logger.error("Error recording response payload", e);
+    }
+  }
+
+  void logResponse(String statusCode, LogData.Builder logDataBuilder) {
+    try {
+
+      if (logger.isInfoEnabled()) {
+        logDataBuilder.responseStatus(statusCode);
+      }
+      if (logger.isInfoEnabled() && !logger.isDebugEnabled()) {
+        Map<String, String> responseData = logDataBuilder.build().toMapResponse();
+        LoggingUtils.logWithMDC(logger, Level.INFO, responseData, "Received Grpc response");
+      }
+      if (logger.isDebugEnabled()) {
+        Map<String, String> responsedDetailsMap = logDataBuilder.build().toMapResponse();
+        LoggingUtils.logWithMDC(logger, Level.DEBUG, responsedDetailsMap, "Received Grpc response");
+      }
+    } catch (Exception e) {
+      logger.error("Error logging request response", e);
+    }
+  }
+
+  <RespT> void logRequestDetails(RespT message, LogData.Builder logDataBuilder) {
+    try {
+      if (logger.isDebugEnabled()) {
+        logDataBuilder.requestPayload(gson.toJson(message));
+        Map<String, String> requestDetailsMap = logDataBuilder.build().toMapRequest();
+        LoggingUtils.logWithMDC(
+            logger, Level.DEBUG, requestDetailsMap, "Sending gRPC request: request payload");
+      }
+    } catch (Exception e) {
+      logger.error("Error logging request details", e);
+    }
+  }
+
+  private static JsonObject mapHeadersToJsonObject(Metadata headers) {
+    JsonObject jsonHeaders = new JsonObject();
+    headers
+        .keys()
+        .forEach(
+            key -> {
+              Metadata.Key<String> metadataKey =
+                  Metadata.Key.of(key, Metadata.ASCII_STRING_MARSHALLER);
+              String headerValue = headers.get(metadataKey);
+              jsonHeaders.addProperty(key, headerValue);
+            });
+    return jsonHeaders;
+  }
+}

gax-java/gax-grpc/src/main/java/com/google/api/gax/grpc/InstantiatingGrpcChannelProvider.java

@@ -467,6 +467,7 @@ private ManagedChannel createSingleChannel() throws IOException {
     builder =
         builder
             .intercept(new GrpcChannelUUIDInterceptor())
+            .intercept(new GrpcLoggingInterceptor())
             .intercept(headerInterceptor)
             .intercept(metadataHandlerInterceptor)
             .userAgent(headerInterceptor.getUserAgentHeader())

gax-java/gax-grpc/src/test/java/com/google/api/gax/grpc/GrpcLoggingInterceptorTest.java

@@ -0,0 +1,143 @@
+/*
+ * Copyright 2024 Google LLC
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are
+ * met:
+ *
+ *     * Redistributions of source code must retain the above copyright
+ * notice, this list of conditions and the following disclaimer.
+ *     * Redistributions in binary form must reproduce the above
+ * copyright notice, this list of conditions and the following disclaimer
+ * in the documentation and/or other materials provided with the
+ * distribution.
+ *     * Neither the name of Google LLC nor the names of its
+ * contributors may be used to endorse or promote products derived from
+ * this software without specific prior written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+ * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+ * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+ * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+ * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+ * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+
+package com.google.api.gax.grpc;
+
+import static org.junit.Assert.assertEquals;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.eq;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.spy;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
+
+import ch.qos.logback.classic.Level;
+import com.google.api.gax.grpc.testing.FakeMethodDescriptor;
+import com.google.api.gax.logging.LogData;
+import io.grpc.CallOptions;
+import io.grpc.Channel;
+import io.grpc.ClientCall;
+import io.grpc.ClientInterceptors;
+import io.grpc.Metadata;
+import io.grpc.MethodDescriptor;
+import io.grpc.Status;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.mockito.Mock;
+import org.mockito.Mockito;
+import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+class GrpcLoggingInterceptorTest {
+  @Mock private Channel channel;
+
+  @Mock private ClientCall<String, Integer> call;
+
+  private static final MethodDescriptor<String, Integer> method = FakeMethodDescriptor.create();
+
+  private static final Logger LOGGER = LoggerFactory.getLogger(GrpcLoggingInterceptorTest.class);
+  /** Sets up mocks. */
+  @BeforeEach
+  void setUp() {
+    MockitoAnnotations.initMocks(this);
+    when(channel.newCall(Mockito.<MethodDescriptor<String, Integer>>any(), any(CallOptions.class)))
+        .thenReturn(call);
+  }
+
+  @Test
+  void testInterceptor_basic() {
+    GrpcLoggingInterceptor interceptor = new GrpcLoggingInterceptor();
+    Channel intercepted = ClientInterceptors.intercept(channel, interceptor);
+    @SuppressWarnings("unchecked")
+    ClientCall.Listener<Integer> listener = mock(ClientCall.Listener.class);
+    ClientCall<String, Integer> interceptedCall = intercepted.newCall(method, CallOptions.DEFAULT);
+    // Simulate starting the call
+    interceptedCall.start(listener, new Metadata());
+    // Verify that the underlying call's start() method is invoked
+    verify(call).start(any(ClientCall.Listener.class), any(Metadata.class));
+
+    // Simulate sending a message
+    String requestMessage = "test request";
+    interceptedCall.sendMessage(requestMessage);
+    // Verify that the underlying call's sendMessage() method is invoked
+    verify(call).sendMessage(requestMessage);
+  }
+
+  @Test
+  void testInterceptor_responseListener() {
+    GrpcLoggingInterceptor interceptor = spy(new GrpcLoggingInterceptor());
+    Channel intercepted = ClientInterceptors.intercept(channel, interceptor);
+    @SuppressWarnings("unchecked")
+    ClientCall.Listener<Integer> listener = mock(ClientCall.Listener.class);
+    ClientCall<String, Integer> interceptedCall = intercepted.newCall(method, CallOptions.DEFAULT);
+    interceptedCall.start(listener, new Metadata());
+
+    // Simulate respond interceptor calls
+    Metadata responseHeaders = new Metadata();
+    responseHeaders.put(
+        Metadata.Key.of("test-header", Metadata.ASCII_STRING_MARSHALLER), "header-value");
+    interceptor.currentListener.onHeaders(responseHeaders);
+
+    interceptor.currentListener.onMessage(null);
+
+    Status status = Status.OK;
+    interceptor.currentListener.onClose(status, new Metadata());
+
+    // --- Verify that the response listener's methods were called ---
+    verify(interceptor).recordResponseHeaders(eq(responseHeaders), any(LogData.Builder.class));
+    verify(interceptor).recordResponsePayload(any(), any(LogData.Builder.class));
+    verify(interceptor).logResponse(eq(status.getCode().toString()), any(LogData.Builder.class));
+  }
+
+  @Test
+  void testLogRequestInfo() {
+
+    TestAppender testAppender = setupTestLogger(GrpcLoggingInterceptorTest.class);
+    GrpcLoggingInterceptor interceptor = new GrpcLoggingInterceptor();
+    interceptor.logRequestInfo(method, LogData.builder(), LOGGER);
+
+    Assertions.assertEquals(1, testAppender.events.size());
+    assertEquals(Level.INFO, testAppender.events.get(0).getLevel());
+    assertEquals(
+        "{\"serviceName\":\"FakeClient\",\"message\":\"Sending gRPC request\",\"rpcName\":\"FakeClient/fake-method\"}",
+        testAppender.events.get(0).getMessage());
+    testAppender.stop();
+  }
+
+  private TestAppender setupTestLogger(Class<?> clazz) {
+    TestAppender testAppender = new TestAppender();
+    testAppender.start();
+    Logger logger = LoggerFactory.getLogger(clazz);
+    ((ch.qos.logback.classic.Logger) logger).addAppender(testAppender);
+    return testAppender;
+  }
+}