Per request logging update

Author: rpanackal

core/src/main/java/com/sap/ai/sdk/core/DeploymentResolver.java

@@ -46,6 +46,7 @@ void reloadDeployments(@Nonnull final String resourceGroup) {
     try {
       val apiClient = new DeploymentApi(service);
       val deployments = new HashSet<>(apiClient.query(resourceGroup).getResources());
+      log.info("Found {} deployments in resource group '{}'", deployments.size(), resourceGroup);
       cache.put(resourceGroup, deployments);
     } catch (final RuntimeException e) {
       throw new DeploymentResolutionException(

core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java

@@ -18,6 +18,7 @@
 import org.apache.hc.core5.http.HttpEntity;
 import org.apache.hc.core5.http.io.HttpClientResponseHandler;
 import org.apache.hc.core5.http.io.entity.EntityUtils;
+import org.slf4j.MDC;
 
 /**
  * Parse incoming JSON responses and handles any errors. For internal use only.
@@ -86,16 +87,10 @@ private T parseSuccess(@Nonnull final ClassicHttpResponse response) throws E {
     val content =
         tryGetContent(responseEntity)
             .getOrElseThrow(e -> exceptionFactory.build(message, e).setHttpResponse(response));
+    logResponseSuccess(response);
+
     try {
-      final T value = objectMapper.readValue(content, successType);
-      val timeHeaders = response.getHeaders("x-upstream-service-time");
-      if (timeHeaders.length > 0) {
-        log.info("LLM request success with duration:{}", timeHeaders[0].getValue());
-      } else {
-        log.info("LLM request success");
-      }
-      log.debug("Response content:\n{}", content);
-      return value;
+      return objectMapper.readValue(content, successType);
     } catch (final JsonProcessingException e) {
       log.error("Failed to parse response to type {}", successType);
       throw exceptionFactory.build("Failed to parse response", e).setHttpResponse(response);
@@ -177,4 +172,19 @@ private static String getErrorMessage(
     val message = Optional.ofNullable(additionalMessage).orElse("");
     return message.isEmpty() ? baseErrorMessage : "%s: %s".formatted(baseErrorMessage, message);
   }
+
+  private static void logResponseSuccess(final @Nonnull ClassicHttpResponse response) {
+    val latency =
+        Optional.ofNullable(response.getFirstHeader("x-upstream-service-time"))
+            .map(h -> h.getValue() + "ms")
+            .orElseGet(() -> "unknown");
+    val entityLength = response.getEntity().getContentLength();
+    val sizeInfo = entityLength >= 0 ? String.format("%.1fKB", entityLength / 1024.0) : "unknown";
+    log.debug(
+        "[reqId={}] {} request completed successfully with latency={}, size={}.",
+        MDC.get("reqId"),
+        MDC.get("service"),
+        latency,
+        sizeInfo);
+  }
 }

foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java

@@ -7,13 +7,16 @@
 import com.sap.ai.sdk.foundationmodels.openai.generated.model.CompletionUsage;
 import com.sap.ai.sdk.foundationmodels.openai.generated.model.CreateChatCompletionResponse;
 import com.sap.ai.sdk.foundationmodels.openai.generated.model.CreateChatCompletionResponseChoicesInner;
+import java.util.Collections;
 import java.util.List;
 import java.util.Objects;
+import java.util.Optional;
 import javax.annotation.Nonnull;
 import lombok.Getter;
 import lombok.RequiredArgsConstructor;
 import lombok.Setter;
 import lombok.Value;
+import lombok.extern.slf4j.Slf4j;
 
 /**
  * Represents the output of an OpenAI chat completion. *
@@ -23,6 +26,7 @@
 @Value
 @RequiredArgsConstructor(access = PACKAGE)
 @Setter(value = NONE)
+@Slf4j
 public class OpenAiChatCompletionResponse {
   /** The original response from the OpenAI API. */
   @Nonnull CreateChatCompletionResponse originalResponse;
@@ -110,7 +114,12 @@ public OpenAiAssistantMessage getMessage() {
    */
   @Nonnull
   public List<OpenAiToolMessage> executeTools() {
-    final var tools = originalRequest.getToolsExecutable();
-    return OpenAiTool.execute(tools != null ? tools : List.of(), getMessage());
+    final var tools =
+        Optional.ofNullable(originalRequest.getToolsExecutable()).orElseGet(Collections::emptyList);
+    if (!tools.isEmpty()) {
+      final var toolNames = tools.stream().map(OpenAiTool::getName).toList();
+      log.debug("Executing {} tool call(s) - {}", toolNames.size(), toolNames);
+    }
+    return OpenAiTool.execute(tools, getMessage());
   }
 }

foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java

@@ -30,16 +30,19 @@
 import java.io.IOException;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.UUID;
 import java.util.stream.Stream;
 import javax.annotation.Nonnull;
 import javax.annotation.Nullable;
 import lombok.AccessLevel;
 import lombok.RequiredArgsConstructor;
 import lombok.extern.slf4j.Slf4j;
+import lombok.val;
 import org.apache.hc.client5.http.classic.methods.HttpPost;
 import org.apache.hc.core5.http.ContentType;
 import org.apache.hc.core5.http.io.entity.StringEntity;
 import org.apache.hc.core5.http.message.BasicClassicHttpRequest;
+import org.slf4j.MDC;
 
 /** Client for interacting with OpenAI models. */
 @Slf4j
@@ -417,6 +420,7 @@ private <T> T execute(
       @Nonnull final Class<T> responseType) {
     final var request = new HttpPost(path);
     serializeAndSetHttpEntity(request, payload, this.customHeaders);
+    MDC.put("endpoint", path);
     return executeRequest(request, responseType);
   }
 
@@ -427,6 +431,7 @@ private <D extends StreamedDelta> Stream<D> executeStream(
       @Nonnull final Class<D> deltaType) {
     final var request = new HttpPost(path);
     serializeAndSetHttpEntity(request, payload, this.customHeaders);
+    MDC.put("endpoint", path);
     return streamRequest(request, deltaType);
   }
 
@@ -449,10 +454,15 @@ private <T> T executeRequest(
       final BasicClassicHttpRequest request, @Nonnull final Class<T> responseType) {
     try {
       final var client = ApacheHttpClient5Accessor.getHttpClient(destination);
+      MDC.put("destination", ((HttpDestination) destination).getUri().toASCIIString());
+      MDC.put("mode", "streaming");
+      logRequestStart();
       return client.execute(
           request, new ClientResponseHandler<>(responseType, OpenAiError.class, FACTORY));
     } catch (final IOException e) {
       throw new OpenAiClientException("Request to OpenAI model failed", e).setHttpRequest(request);
+    } finally {
+      MDC.clear();
     }
   }
 
@@ -461,11 +471,28 @@ private <D extends StreamedDelta> Stream<D> streamRequest(
       final BasicClassicHttpRequest request, @Nonnull final Class<D> deltaType) {
     try {
       final var client = ApacheHttpClient5Accessor.getHttpClient(destination);
+      MDC.put("destination", ((HttpDestination) destination).getUri().toASCIIString());
+      MDC.put("mode", "streaming");
+      logRequestStart();
       return new ClientStreamingHandler<>(deltaType, OpenAiError.class, FACTORY)
           .objectMapper(JACKSON)
           .handleStreamingResponse(client.executeOpen(null, request, null));
     } catch (final IOException e) {
       throw new OpenAiClientException("Request to OpenAI model failed", e).setHttpRequest(request);
+    } finally {
+      MDC.clear();
     }
   }
+
+  private static void logRequestStart() {
+    val reqId = UUID.randomUUID().toString().substring(0, 8);
+    MDC.put("reqId", reqId);
+    MDC.put("service", "Orchestration");
+    log.debug(
+        "[reqId={}] Starting OpenAI {} request to {}, destination={}",
+        reqId,
+        MDC.get("mode"),
+        MDC.get("endpoint"),
+        MDC.get("destination"));
+  }
 }

foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/spring/OpenAiChatModel.java

@@ -69,9 +69,12 @@ public ChatResponse call(@Nonnull final Prompt prompt) {
     val response = new ChatResponse(toGenerations(result));
 
     if (options != null && isInternalToolExecutionEnabled(options) && response.hasToolCalls()) {
+      val toolCalls =
+          response.getResult().getOutput().getToolCalls().stream().map(ToolCall::name).toList();
+      log.info("Executing {} tool call(s) - {}", toolCalls.size(), toolCalls);
       val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response);
       // Send the tool execution result back to the model.
-      log.info("Re-invoking model with tool execution results.");
+      log.debug("Re-invoking model with tool execution results.");
       return call(new Prompt(toolExecutionResult.conversationHistory(), options));
     }
     return response;

logback.xml

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <configuration>
-	<property name="LOG_PATTERN" value="%d{HH:mm:ss.SSS} %-5level [%thread] %logger{36} - %msg%n"/>
+	<property name="LOG_PATTERN" value="%d{HH:mm:ss.SSS} %-5level [%thread] %logger{36} : %msg%n"/>
 
 	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
 		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">

orchestration/src/main/java/com/sap/ai/sdk/orchestration/OrchestrationHttpExecutor.java

@@ -16,6 +16,7 @@
 import com.sap.cloud.sdk.cloudplatform.connectivity.exception.HttpClientInstantiationException;
 import java.io.IOException;
 import java.util.List;
+import java.util.UUID;
 import java.util.function.Supplier;
 import java.util.stream.Stream;
 import javax.annotation.Nonnull;
@@ -25,6 +26,7 @@
 import org.apache.hc.client5.http.classic.methods.HttpPost;
 import org.apache.hc.core5.http.ContentType;
 import org.apache.hc.core5.http.io.entity.StringEntity;
+import org.slf4j.MDC;
 
 @Slf4j
 class OrchestrationHttpExecutor {
@@ -45,7 +47,6 @@ <T> T execute(
       @Nonnull final List<Header> customHeaders) {
     try {
       val json = JACKSON.writeValueAsString(payload);
-      log.debug("Successfully serialized request into JSON payload");
       val request = new HttpPost(path);
       request.setEntity(new StringEntity(json, ContentType.APPLICATION_JSON));
       customHeaders.forEach(h -> request.addHeader(h.getName(), h.getValue()));
@@ -55,6 +56,9 @@ <T> T execute(
       val handler =
           new ClientResponseHandler<>(responseType, OrchestrationError.Synchronous.class, FACTORY)
               .objectMapper(JACKSON);
+      MDC.put("endpoint", path);
+      MDC.put("mode", "synchronous");
+      logRequestStart();
       return client.execute(request, handler);
 
     } catch (JsonProcessingException e) {
@@ -66,6 +70,8 @@ <T> T execute(
         | IOException e) {
       throw new OrchestrationClientException(
           "Request to Orchestration service failed for " + path, e);
+    } finally {
+      MDC.clear();
     }
   }
 
@@ -81,7 +87,9 @@ Stream<OrchestrationChatCompletionDelta> stream(
       customHeaders.forEach(h -> request.addHeader(h.getName(), h.getValue()));
 
       val client = getHttpClient();
-
+      MDC.put("endpoint", path);
+      MDC.put("method", "streaming");
+      logRequestStart();
       return new ClientStreamingHandler<>(
               OrchestrationChatCompletionDelta.class, OrchestrationError.Streaming.class, FACTORY)
           .objectMapper(JACKSON)
@@ -93,13 +101,27 @@ Stream<OrchestrationChatCompletionDelta> stream(
     } catch (IOException e) {
       throw new OrchestrationClientException(
           "Streaming request to the Orchestration service failed", e);
+    } finally {
+      MDC.clear();
     }
   }
 
   @Nonnull
   private HttpClient getHttpClient() {
     val destination = destinationSupplier.get();
-    log.debug("Using destination {} to connect to orchestration service", destination);
+    MDC.put("destination", destination.getUri().toASCIIString());
     return ApacheHttpClient5Accessor.getHttpClient(destination);
   }
+
+  private static void logRequestStart() {
+    val reqId = UUID.randomUUID().toString().substring(0, 8);
+    MDC.put("reqId", reqId);
+    MDC.put("service", "Orchestration");
+    log.debug(
+        "[reqId={}] Starting Orchestration {} request to {}, destination={}",
+        reqId,
+        MDC.get("mode"),
+        MDC.get("endpoint"),
+        MDC.get("destination"));
+  }
 }

orchestration/src/main/java/com/sap/ai/sdk/orchestration/spring/OrchestrationChatModel.java

@@ -72,9 +72,13 @@ public ChatResponse call(@Nonnull final Prompt prompt) {
 
       if (ToolCallingChatOptions.isInternalToolExecutionEnabled(prompt.getOptions())
           && response.hasToolCalls()) {
+
+        val toolCalls =
+            response.getResult().getOutput().getToolCalls().stream().map(ToolCall::name).toList();
+        log.debug("Executing {} tool call(s) - {}", toolCalls.size(), toolCalls);
         val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response);
         // Send the tool execution result back to the model.
-        log.info("Re-invoking model with tool execution results.");
+        log.debug("Re-invoking LLM with tool execution results.");
         return call(new Prompt(toolExecutionResult.conversationHistory(), prompt.getOptions()));
       }
       return response;