feat: log actionable errors on operation failure in LoggingTracer (#14460)

Implement operationFailed in LoggingTracer to log actionable errors for
logical operation failures.

b/564459813

Author: jinseopkim0

java-showcase/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/logging/ITActionableErrorsLogging.java

@@ -20,6 +20,7 @@
 import static org.junit.jupiter.api.Assertions.assertThrows;
 
 import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import com.google.api.client.http.LowLevelHttpRequest;
 import com.google.api.client.http.LowLevelHttpResponse;
@@ -38,9 +39,11 @@
 import com.google.showcase.v1beta1.EchoSettings;
 import com.google.showcase.v1beta1.it.util.TestClientInitializer;
 import java.io.IOException;
+import java.time.Duration;
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
+import org.awaitility.Awaitility;
 import org.junit.jupiter.api.AfterAll;
 import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.BeforeAll;
@@ -76,9 +79,9 @@ static void destroyClients() throws InterruptedException {
   private TestAppender setupTestLogger(String loggerName, Level level) {
     TestAppender appender = new TestAppender();
     appender.start();
-    org.slf4j.Logger logger = LoggerFactory.getLogger(loggerName);
-    ((ch.qos.logback.classic.Logger) logger).setLevel(level);
-    ((ch.qos.logback.classic.Logger) logger).addAppender(appender);
+    Logger logger = (Logger) LoggerFactory.getLogger(loggerName);
+    logger.setLevel(level);
+    logger.addAppender(appender);
     return appender;
   }
 
@@ -92,9 +95,31 @@ void setupTestLogger() {
   void teardownTestLogger() {
     if (testAppender != null) {
       testAppender.stop();
+      Logger logger = (Logger) LoggerFactory.getLogger("com.google.api.gax.tracing.LoggingTracer");
+      logger.detachAppender(testAppender);
+      testAppender.clearEvents();
     }
   }
 
+  /**
+   * Polls asynchronously until an ERROR logging event is appended or timeout is reached.
+   *
+   * <p>Logging of operation failure in TraceFinisher occurs asynchronously on a background executor
+   * thread, so Awaitility is used to prevent test flakiness and race conditions.
+   *
+   * @return the first {@link ILoggingEvent} with ERROR level
+   */
+  private ILoggingEvent getErrorLoggingEvent() {
+    Awaitility.await()
+        .atMost(Duration.ofSeconds(5))
+        .until(() -> testAppender.events.stream().anyMatch(e -> e.getLevel() == Level.ERROR));
+    return testAppender.events.stream()
+        .filter(event -> event.getLevel() == Level.ERROR)
+        .findFirst()
+        .orElseThrow(
+            () -> new AssertionError("Expected an ERROR log event in: " + testAppender.events));
+  }
+
   private Map<String, Object> getKvps(ILoggingEvent loggingEvent) {
     Map<String, Object> map = new HashMap<>();
     if (loggingEvent.getKeyValuePairs() != null) {
@@ -174,38 +199,40 @@ public LowLevelHttpResponse execute() throws IOException {
                 .build();
     com.google.showcase.v1beta1.stub.EchoStub stub = echoStubSettings.createStub();
     EchoClient mockHttpJsonClient = EchoClient.create(stub);
+    try {
+      EchoRequest request = EchoRequest.newBuilder().build();
+      assertThrows(ApiException.class, () -> mockHttpJsonClient.echo(request));
 
-    EchoRequest request = EchoRequest.newBuilder().build();
-    assertThrows(ApiException.class, () -> mockHttpJsonClient.echo(request));
-
-    assertThat(testAppender.events.size()).isAtLeast(1);
-    ILoggingEvent loggingEvent = testAppender.events.get(testAppender.events.size() - 1);
+      ILoggingEvent loggingEvent = getErrorLoggingEvent();
+      assertThat(loggingEvent.getLevel()).isEqualTo(Level.ERROR);
 
-    assertThat(loggingEvent.getMessage())
-        .contains("This is a mock JSON error generated by the server");
+      assertThat(loggingEvent.getMessage())
+          .contains("This is a mock JSON error generated by the server");
 
-    Map<String, Object> kvps = getKvps(loggingEvent);
-    assertThat(kvps).containsEntry(ObservabilityAttributes.RPC_SYSTEM_NAME_ATTRIBUTE, "http");
-    assertThat(kvps).containsEntry(ObservabilityAttributes.HTTP_METHOD_ATTRIBUTE, "POST");
-    assertThat(kvps)
-        .containsEntry(ObservabilityAttributes.HTTP_URL_TEMPLATE_ATTRIBUTE, "v1beta1/echo:echo");
-    assertThat(kvps)
-        .containsEntry(ObservabilityAttributes.RPC_RESPONSE_STATUS_ATTRIBUTE, "ABORTED");
-    assertThat(kvps)
-        .containsEntry(ObservabilityAttributes.ERROR_TYPE_ATTRIBUTE, "mock_error_reason");
-    assertThat(kvps)
-        .containsEntry(ObservabilityAttributes.ERROR_DOMAIN_ATTRIBUTE, "mock.googleapis.com");
-    assertThat(kvps)
-        .containsEntry(
-            ObservabilityAttributes.ERROR_METADATA_ATTRIBUTE_PREFIX + "mock_key", "mock_value");
-
-    mockHttpJsonClient.close();
-    mockHttpJsonClient.awaitTermination(
-        TestClientInitializer.AWAIT_TERMINATION_SECONDS, TimeUnit.SECONDS);
+      Map<String, Object> kvps = getKvps(loggingEvent);
+      assertThat(kvps).containsEntry(ObservabilityAttributes.RPC_SYSTEM_NAME_ATTRIBUTE, "http");
+      assertThat(kvps).containsEntry(ObservabilityAttributes.HTTP_METHOD_ATTRIBUTE, "POST");
+      assertThat(kvps)
+          .containsEntry(ObservabilityAttributes.HTTP_URL_TEMPLATE_ATTRIBUTE, "v1beta1/echo:echo");
+      assertThat(kvps)
+          .containsEntry(ObservabilityAttributes.RPC_RESPONSE_STATUS_ATTRIBUTE, "ABORTED");
+      assertThat(kvps)
+          .containsEntry(ObservabilityAttributes.ERROR_TYPE_ATTRIBUTE, "mock_error_reason");
+      assertThat(kvps)
+          .containsEntry(ObservabilityAttributes.ERROR_DOMAIN_ATTRIBUTE, "mock.googleapis.com");
+      assertThat(kvps)
+          .containsEntry(
+              ObservabilityAttributes.ERROR_METADATA_ATTRIBUTE_PREFIX + "mock_key", "mock_value");
+    } finally {
+      mockHttpJsonClient.close();
+      mockHttpJsonClient.awaitTermination(
+          TestClientInitializer.AWAIT_TERMINATION_SECONDS, TimeUnit.SECONDS);
+    }
   }
 
   @Test
   void testHttpJson_noLogEmittedForSuccess() {
+    testAppender.clearEvents();
     EchoRequest request = EchoRequest.newBuilder().setContent("Success").build();
     httpjsonClient.echo(request);
     assertThat(testAppender.events.size()).isEqualTo(0);
@@ -218,22 +245,23 @@ void testHttpJson_clientLevelFailureAttributes() throws Exception {
     stubSettingsBuilder
         .echoSettings()
         .setRetrySettings(
-            com.google.api.gax.retrying.RetrySettings.newBuilder()
-                .setInitialRpcTimeoutDuration(java.time.Duration.ofMillis(0))
-                .setTotalTimeoutDuration(java.time.Duration.ofMillis(0))
-                .setMaxAttempts(1)
-                .build());
+            com.google.api.gax.retrying.RetrySettings.newBuilder().setMaxAttempts(1).build());
     stubSettingsBuilder.setTracerFactory(new LoggingTracerFactory());
     stubSettingsBuilder.setCredentialsProvider(NoCredentialsProvider.create());
     stubSettingsBuilder.setEndpoint("localhost:1");
 
-    try (com.google.showcase.v1beta1.stub.EchoStub stub = stubSettingsBuilder.build().createStub();
-        EchoClient client = EchoClient.create(stub)) {
+    com.google.showcase.v1beta1.stub.EchoStub stub = stubSettingsBuilder.build().createStub();
+    EchoClient client = EchoClient.create(stub);
+    try {
       assertThrows(ApiException.class, () -> client.echo(EchoRequest.newBuilder().build()));
-      assertThat(testAppender.events.size()).isAtLeast(1);
-      ILoggingEvent loggingEvent = testAppender.events.get(testAppender.events.size() - 1);
+      ILoggingEvent loggingEvent = getErrorLoggingEvent();
+      assertThat(loggingEvent.getLevel()).isEqualTo(Level.ERROR);
+      assertThat(loggingEvent.getMessage()).isNotEmpty();
       Map<String, Object> kvps = getKvps(loggingEvent);
       assertThat(kvps).containsEntry(ObservabilityAttributes.RPC_SYSTEM_NAME_ATTRIBUTE, "http");
+    } finally {
+      client.shutdownNow();
+      client.awaitTermination(TestClientInitializer.AWAIT_TERMINATION_SECONDS, TimeUnit.SECONDS);
     }
   }
 
@@ -242,8 +270,8 @@ void testGrpc_logEmittedForLowLevelRequestFailure() {
     EchoRequest request = buildErrorRequest();
     assertThrows(ApiException.class, () -> grpcClient.echo(request));
 
-    assertThat(testAppender.events.size()).isAtLeast(1);
-    ILoggingEvent loggingEvent = testAppender.events.get(testAppender.events.size() - 1);
+    ILoggingEvent loggingEvent = getErrorLoggingEvent();
+    assertThat(loggingEvent.getLevel()).isEqualTo(Level.ERROR);
     assertThat(loggingEvent.getMessage()).contains("This is a test error");
 
     Map<String, Object> kvps = getKvps(loggingEvent);
@@ -264,6 +292,7 @@ void testGrpc_logEmittedForLowLevelRequestFailure() {
 
   @Test
   void testGrpc_noLogEmittedForSuccess() {
+    testAppender.clearEvents();
     EchoRequest request = EchoRequest.newBuilder().setContent("Success").build();
     grpcClient.echo(request);
     assertThat(testAppender.events.size()).isEqualTo(0);
@@ -276,22 +305,23 @@ void testGrpc_clientLevelFailureAttributes() throws Exception {
     stubSettingsBuilder
         .echoSettings()
         .setRetrySettings(
-            com.google.api.gax.retrying.RetrySettings.newBuilder()
-                .setInitialRpcTimeoutDuration(java.time.Duration.ofMillis(0))
-                .setTotalTimeoutDuration(java.time.Duration.ofMillis(0))
-                .setMaxAttempts(1)
-                .build());
+            com.google.api.gax.retrying.RetrySettings.newBuilder().setMaxAttempts(1).build());
     stubSettingsBuilder.setTracerFactory(new LoggingTracerFactory());
     stubSettingsBuilder.setCredentialsProvider(NoCredentialsProvider.create());
     stubSettingsBuilder.setEndpoint("localhost:1");
 
-    try (com.google.showcase.v1beta1.stub.EchoStub stub = stubSettingsBuilder.build().createStub();
-        EchoClient client = EchoClient.create(stub)) {
+    com.google.showcase.v1beta1.stub.EchoStub stub = stubSettingsBuilder.build().createStub();
+    EchoClient client = EchoClient.create(stub);
+    try {
       assertThrows(ApiException.class, () -> client.echo(EchoRequest.newBuilder().build()));
-      assertThat(testAppender.events.size()).isAtLeast(1);
-      ILoggingEvent loggingEvent = testAppender.events.get(testAppender.events.size() - 1);
+      ILoggingEvent loggingEvent = getErrorLoggingEvent();
+      assertThat(loggingEvent.getLevel()).isEqualTo(Level.ERROR);
+      assertThat(loggingEvent.getMessage()).isNotEmpty();
       Map<String, Object> kvps = getKvps(loggingEvent);
       assertThat(kvps).containsEntry(ObservabilityAttributes.RPC_SYSTEM_NAME_ATTRIBUTE, "grpc");
+    } finally {
+      client.shutdownNow();
+      client.awaitTermination(TestClientInitializer.AWAIT_TERMINATION_SECONDS, TimeUnit.SECONDS);
     }
   }
 }

java-showcase/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/logging/TestAppender.java

@@ -18,12 +18,12 @@
 
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.core.AppenderBase;
-import java.util.ArrayList;
 import java.util.List;
+import java.util.concurrent.CopyOnWriteArrayList;
 
 /** Logback appender used to set up tests. */
 public class TestAppender extends AppenderBase<ILoggingEvent> {
-  public List<ILoggingEvent> events = new ArrayList<>();
+  public List<ILoggingEvent> events = new CopyOnWriteArrayList<>();
 
   @Override
   protected void append(ILoggingEvent eventObject) {

sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/logging/LoggingUtils.java

@@ -33,6 +33,8 @@
 import com.google.api.core.InternalApi;
 import java.util.Map;
 import org.jspecify.annotations.NullMarked;
+import org.slf4j.Logger;
+import org.slf4j.event.Level;
 
 @NullMarked
 @InternalApi
@@ -149,18 +151,19 @@ public static <RespT> void logRequest(
   }
 
   /**
-   * Logs an actionable error message with structured context at a specific log level.
+   * Logs an actionable error message with structured context at a specified log level.
    *
    * @param logContext A map containing the structured logging context (e.g., RPC service, method,
    *     error details).
    * @param loggerProvider The provider used to obtain the logger.
    * @param message The human-readable error message.
+   * @param level The SLF4J log level at which to emit the error log.
    */
   public static void logActionableError(
-      Map<String, Object> logContext, LoggerProvider loggerProvider, String message) {
+      Map<String, Object> logContext, LoggerProvider loggerProvider, String message, Level level) {
     if (loggingEnabled) {
-      org.slf4j.Logger logger = loggerProvider.getLogger();
-      Slf4jUtils.log(logger, org.slf4j.event.Level.DEBUG, logContext, message);
+      Logger logger = loggerProvider.getLogger();
+      Slf4jUtils.log(logger, level, logContext, message);
     }
   }
 

sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/tracing/LoggingTracer.java

@@ -38,6 +38,7 @@
 import java.util.HashMap;
 import java.util.Map;
 import org.jspecify.annotations.NullMarked;
+import org.slf4j.event.Level;
 
 /**
  * An {@link ApiTracer} that logs actionable errors using {@link LoggingUtils} when an RPC attempt
@@ -56,21 +57,37 @@ class LoggingTracer extends BaseApiTracer {
 
   @Override
   public void attemptFailedDuration(Throwable error, java.time.Duration delay) {
-    recordActionableError(error);
+    recordActionableError(error, Level.DEBUG);
   }
 
   @Override
   public void attemptFailedRetriesExhausted(Throwable error) {
-    recordActionableError(error);
+    recordActionableError(error, Level.DEBUG);
+  }
+
+  /**
+   * Records an actionable error log entry at ERROR level when the logical operation fails.
+   *
+   * @param error the exception that caused the logical operation to fail
+   */
+  @Override
+  public void operationFailed(Throwable error) {
+    recordActionableError(error, Level.ERROR);
   }
 
   @Override
   public void attemptPermanentFailure(Throwable error) {
-    recordActionableError(error);
+    recordActionableError(error, Level.DEBUG);
   }
 
+  /**
+   * Records an actionable error log entry with the specified log level.
+   *
+   * @param error the exception that occurred
+   * @param level the SLF4J log level at which to emit the error log
+   */
   @VisibleForTesting
-  void recordActionableError(Throwable error) {
+  void recordActionableError(Throwable error, Level level) {
     if (error == null) {
       return;
     }
@@ -98,6 +115,6 @@ void recordActionableError(Throwable error) {
     }
 
     String message = error.getMessage() != null ? error.getMessage() : error.getClass().getName();
-    LoggingUtils.logActionableError(logContext, LOGGER_PROVIDER, message);
+    LoggingUtils.logActionableError(logContext, LOGGER_PROVIDER, message, level);
   }
 }

sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/logging/LoggingUtilsTest.java

@@ -101,7 +101,10 @@ void testLogActionableError_loggingDisabled() {
         mock(LoggerProvider.class, Mockito.withSettings().withoutAnnotations());
 
     LoggingUtils.logActionableError(
-        Collections.<String, Object>emptyMap(), loggerProvider, "message");
+        Collections.<String, Object>emptyMap(),
+        loggerProvider,
+        "message",
+        org.slf4j.event.Level.DEBUG);
 
     verify(loggerProvider, never()).getLogger();
   }
@@ -119,8 +122,29 @@ void testLogActionableError_success() {
     when(eventBuilder.addKeyValue(anyString(), any())).thenReturn(eventBuilder);
 
     Map<String, Object> context = Collections.singletonMap("key", "value");
-    LoggingUtils.logActionableError(context, loggerProvider, "message");
+    LoggingUtils.logActionableError(
+        context, loggerProvider, "message", org.slf4j.event.Level.DEBUG);
+
+    verify(loggerProvider).getLogger();
+  }
+
+  @Test
+  void testLogActionableError_withLevel_success() {
+    LoggingUtils.setLoggingEnabled(true);
+    LoggerProvider loggerProvider =
+        mock(LoggerProvider.class, Mockito.withSettings().withoutAnnotations());
+    Logger logger = mock(Logger.class, Mockito.withSettings().withoutAnnotations());
+    when(loggerProvider.getLogger()).thenReturn(logger);
+
+    org.slf4j.spi.LoggingEventBuilder eventBuilder = mock(org.slf4j.spi.LoggingEventBuilder.class);
+    when(logger.atError()).thenReturn(eventBuilder);
+    when(eventBuilder.addKeyValue(anyString(), any())).thenReturn(eventBuilder);
+
+    Map<String, Object> context = Collections.singletonMap("key", "value");
+    LoggingUtils.logActionableError(
+        context, loggerProvider, "message", org.slf4j.event.Level.ERROR);
 
     verify(loggerProvider).getLogger();
+    verify(logger).atError();
   }
 }

sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/logging/TestLogger.java

@@ -52,6 +52,24 @@ public List<String> getMessageList() {
     return messageList;
   }
 
+  /**
+   * Returns the most recent log level recorded by this test logger.
+   *
+   * @return the SLF4J {@link Level} or null if no level has been recorded
+   */
+  public Level getLevel() {
+    return level;
+  }
+
+  /**
+   * Sets or clears the log level recorded by this test logger.
+   *
+   * @param level the SLF4J {@link Level} to set
+   */
+  public void setLevel(Level level) {
+    this.level = level;
+  }
+
   Map<String, Object> keyValuePairsMap = new HashMap<>();
 
   public Map<String, String> getMDCMap() {
@@ -261,7 +279,7 @@ public void warn(Marker marker, String msg, Throwable t) {}
 
   @Override
   public boolean isErrorEnabled() {
-    return false;
+    return true;
   }
 
   @Override