chore: Improve Logging

core-services/document-grounding/pom.xml

@@ -76,10 +76,6 @@
       <groupId>com.fasterxml.jackson.core</groupId>
       <artifactId>jackson-annotations</artifactId>
     </dependency>
-    <dependency>
-      <groupId>org.slf4j</groupId>
-      <artifactId>slf4j-api</artifactId>
-    </dependency>
     <dependency>
       <groupId>com.google.guava</groupId>
       <artifactId>guava</artifactId>

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,6 +87,8 @@ private T parseSuccess(@Nonnull final ClassicHttpResponse response) throws E {
     val content =
         tryGetContent(responseEntity)
             .getOrElseThrow(e -> exceptionFactory.build(message, e).setHttpResponse(response));
+    logResponseSuccess(response);
+
     try {
       return objectMapper.readValue(content, successType);
     } catch (final JsonProcessingException e) {
@@ -169,4 +172,16 @@ 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) {
+    if (!log.isDebugEnabled()) {
+      return;
+    }
+    val headerTime = Optional.ofNullable(response.getFirstHeader("x-upstream-service-time"));
+    val duration = headerTime.map(h -> h.getValue() + "ms").orElseGet(() -> "unknown");
+    val entityLength = response.getEntity().getContentLength();
+    val sizeInfo = entityLength >= 0 ? String.format("%.1fKB", entityLength / 1024.0) : "unknown";
+    val msg = "[reqId={}] {} request completed successfully with duration={}, size={}.";
+    log.debug(msg, MDC.get("reqId"), MDC.get("service"), duration, sizeInfo);
+  }
 }

foundation-models/openai/pom.xml

@@ -41,7 +41,7 @@
     <coverage.complexity>81%</coverage.complexity>
     <coverage.line>91%</coverage.line>
     <coverage.instruction>88%</coverage.instruction>
-    <coverage.branch>79%</coverage.branch>
+    <coverage.branch>78%</coverage.branch>
     <coverage.method>90%</coverage.method>
     <coverage.class>92%</coverage.class>
   </properties>

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

@@ -9,11 +9,13 @@
 import com.sap.ai.sdk.foundationmodels.openai.generated.model.CreateChatCompletionResponseChoicesInner;
 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 +25,7 @@
 @Value
 @RequiredArgsConstructor(access = PACKAGE)
 @Setter(value = NONE)
+@Slf4j
 public class OpenAiChatCompletionResponse {
   /** The original response from the OpenAI API. */
   @Nonnull CreateChatCompletionResponse originalResponse;
@@ -110,7 +113,11 @@ 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(List::of);
+    if (log.isDebugEnabled() && !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", "synchronous");
+      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", "OpenAI");
+    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,8 +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.debug("Re-invoking model with tool execution results.");
       return call(new Prompt(toolExecutionResult.conversationHistory(), options));
     }
     return response;

logback.xml

@@ -0,0 +1,20 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+	<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">
+			<pattern>${LOG_PATTERN}</pattern>
+		</encoder>
+	</appender>
+
+	<root level="INFO">
+		<appender-ref ref="CONSOLE"/>
+	</root>
+
+	<!--  <logger name="org.apache.hc.client5.http.wire" level="DEBUG"/>-->
+	<!--  <logger name="org.apache.http.wire" level="DEBUG"/>-->
+	<logger name="com.sap.ai.sdk" level="DEBUG"/>
+	<!-- Disable org.eclipse.jetty logging -->
+	<logger name="org.eclipse.jetty" level="OFF"/>
+</configuration>

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("mode", "streaming");
+      logRequestStart();
       return new ClientStreamingHandler<>(
               OrchestrationChatCompletionDelta.class, OrchestrationError.Streaming.class, FACTORY)
           .objectMapper(JACKSON)
@@ -93,13 +101,24 @@ 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");
+
+    val msg = "[reqId={}] Starting Orchestration {} request to {}, destination={}";
+    log.debug(msg, reqId, MDC.get("mode"), MDC.get("endpoint"), MDC.get("destination"));
+  }
 }

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

@@ -15,6 +15,7 @@
 import java.util.List;
 import java.util.Map;
 import java.util.function.Function;
+import java.util.stream.Collectors;
 import javax.annotation.Nonnull;
 import lombok.extern.slf4j.Slf4j;
 import lombok.val;
@@ -72,8 +73,17 @@ public ChatResponse call(@Nonnull final Prompt prompt) {
 
       if (ToolCallingChatOptions.isInternalToolExecutionEnabled(prompt.getOptions())
           && response.hasToolCalls()) {
+
+        if (log.isDebugEnabled()) {
+          val tools = response.getResult().getOutput().getToolCalls();
+          val toolsStr = tools.stream().map(ToolCall::name).collect(Collectors.joining(", "));
+          log.debug("Executing {} tool call(s) - {}", tools.size(), toolsStr);
+        }
+
         val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response);
+
         // Send the tool execution result back to the model.
+        log.debug("Re-invoking LLM with tool execution results.");
         return call(new Prompt(toolExecutionResult.conversationHistory(), prompt.getOptions()));
       }
       return response;

pom.xml

@@ -71,6 +71,7 @@
     <javaparser.version>3.27.1</javaparser.version>
     <jsonschema-generator.version>4.38.0</jsonschema-generator.version>
     <jackson.version>2.20.0</jackson.version>
+    <logback.version>1.5.20</logback.version>
     <!-- conflicts resolution -->
     <micrometer.version>1.15.5</micrometer.version>
     <json.version>20250517</json.version>
@@ -258,9 +259,9 @@
   </dependencyManagement>
   <dependencies>
     <dependency>
-      <groupId>org.slf4j</groupId>
-      <artifactId>slf4j-simple</artifactId>
-      <version>${slf4j.version}</version>
+      <groupId>ch.qos.logback</groupId>
+      <artifactId>logback-classic</artifactId>
+      <version>${logback.version}</version>
       <scope>test</scope>
     </dependency>
   </dependencies>
@@ -365,7 +366,7 @@
                     <exclude>org.tinylog</exclude>
                   </excludes>
                   <includes>
-                    <include>org.slf4j:slf4j-simple:*:*:test</include>
+                    <include>ch.qos.logback:*:*:*:test</include>
                   </includes>
                 </bannedDependencies>
               </rules>
@@ -554,9 +555,7 @@
             <!--  ignore annotations that are not visible on bytecode level  -->
             <ignoredUnusedDeclaredDependency>com.google.code.findbugs:jsr305</ignoredUnusedDeclaredDependency>
             <!-- Logging API, adapters and default implementation for tests -->
-            <ignoredUnusedDeclaredDependency>org.slf4j:slf4j-api</ignoredUnusedDeclaredDependency>
-            <ignoredUnusedDeclaredDependency>org.slf4j:jcl-over-slf4j</ignoredUnusedDeclaredDependency>
-            <ignoredUnusedDeclaredDependency>org.slf4j:slf4j-simple</ignoredUnusedDeclaredDependency>
+            <ignoredUnusedDeclaredDependency>ch.qos.logback:logback-classic</ignoredUnusedDeclaredDependency>
             <!-- Lombok usage for code generation -->
             <ignoredUnusedDeclaredDependency>org.projectlombok:lombok</ignoredUnusedDeclaredDependency>
             <!-- By default, JUnit5 adapters are added to every module to ensure no tests are skipped -->
@@ -598,6 +597,11 @@
         <groupId>org.apache.maven.plugins</groupId>
         <artifactId>maven-surefire-plugin</artifactId>
         <version>${surefire.version}</version>
+        <configuration>
+          <systemPropertyVariables>
+            <logback.configurationFile>${project.rootdir}/logback.xml</logback.configurationFile>
+          </systemPropertyVariables>
+        </configuration>
       </plugin>
       <!-- phase: verify -->
       <plugin>

sample-code/spring-app/src/main/resources/logback-spring.xml

@@ -6,6 +6,7 @@
         <logger name="org.springframework.web" level="INFO"/>
         <logger name="org.apache.hc.client5.http.wire" level="DEBUG"/>
         <logger name="org.apache.http.wire" level="DEBUG"/>
+        <logger name="com.sap.ai.sdk" level="DEBUG"/>
     </springProfile>
 
     <springProfile name="cloud">