chore: Improve Logging #634

CharlesDuboisSAP · 2025-10-27T14:09:26Z

Wire logs on unit tests finally

CharlesDuboisSAP · 2025-10-29T14:33:01Z

If you have 2 requests running simultaneously, could the shorter one clear the context of the longer one?

MDC is thread local, so normally this shouldn't be a problem.

That said, we need to make sure that the MDC state is set and consumed per request level as the context is finally cleared after each request. A counter example would be setting the MDC in OrchestrationModuleConfig object and using it across multiple requests. Here the MDC context set in config creation is cleared on first request and cannot be expected to be available on subsequent requests.

I want to point out: If you are ever outside of the thread, you will lose the MDC parameters.
It's not obvious when/whether that happens. For example, if we ever decide to use Resilience (or any other form of TimeLimiter), then the approach will stop working I think.

CharlesDuboisSAP · 2025-10-27T14:11:09Z

logback.xml takes precedence

-Original file line number
+Diff line change
@@ Expand Up / @@ -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>
@@ Expand Down @@

-Original file line number
+Diff line change
@@ Expand Up / @@ -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(
@@ Expand Down @@

-Original file line number
+Diff line change
@@ Expand Up / @@ -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.
@@ Expand Down Expand Up @@
         val content =
             tryGetContent(responseEntity)
                 .getOrElseThrow(e -> exceptionFactory.build(message, e).setHttpResponse(response));
+        logResponseSuccess(response);
         try {
           return objectMapper.readValue(content, successType);
         } catch (final JsonProcessingException e) {
@@ Expand Down Expand Up / @@ -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);
+      }
     }

-Original file line number
+Diff line change
@@ Expand Up / @@ -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>
@@ Expand Down @@

-Original file line number
+Diff line change
@@ Expand Up / @@ -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. *
@@ Expand All / @@ -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;
@@ Expand Down Expand Up / @@ -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());
       }
     }

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: Improve Logging #634

Uh oh!

Diff view

Diff view

There are no files selected for viewing

CharlesDuboisSAP Oct 27, 2025

Uh oh!

CharlesDuboisSAP Oct 29, 2025

Uh oh!

rpanackal Oct 29, 2025

Uh oh!

newtork Oct 30, 2025

Uh oh!

Uh oh!

CharlesDuboisSAP Oct 27, 2025

Uh oh!

Uh oh!

-Original file line number
+Diff line change
@@ Expand Up / @@ -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
@@ Expand Down Expand Up / @@ -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);
       }
@@ Expand All / @@ -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);
       }
@@ Expand All / @@ -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();
         }
       }
@@ Expand All @@
           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"));
+      }
     }

-Original file line number
+Diff line change
@@ Expand Up / @@ -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;
@@ Expand Down @@

-Original file line number
+Diff line change
@@ -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>

-Original file line number
+Diff line change
@@ Expand Up / @@ -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;
@@ Expand All / @@ -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 {
@@ Expand All / @@ -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()));
@@ Expand All / @@ -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) {
@@ Expand All / @@ -66,6 +70,8 @@ <T> T execute( @@
             | IOException e) {
           throw new OrchestrationClientException(
               "Request to Orchestration service failed for " + path, e);
+        } finally {
+          MDC.clear();
         }
       }
@@ Expand All / @@ -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)
@@ Expand All / @@ -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"));
+      }
     }

-Original file line number
+Diff line change
@@ Expand Up / @@ -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;
@@ Expand Down Expand Up / @@ -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;
@@ Expand Down @@

-Original file line number
+Diff line change
@@ Expand Up / @@ -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>
@@ Expand Down Expand Up / @@ -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>
@@ Expand Down Expand Up / @@ -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>
@@ Expand Down Expand Up / @@ -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 -->
@@ Expand Down Expand Up / @@ -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>
@@ Expand Down @@

chore: Improve Logging #634

Uh oh!

chore: Improve Logging #634

Uh oh!

Uh oh!

Diff view

Diff view

There are no files selected for viewing

CharlesDuboisSAP Oct 27, 2025

Choose a reason for hiding this comment

Uh oh!

CharlesDuboisSAP Oct 29, 2025

Choose a reason for hiding this comment

Uh oh!

rpanackal Oct 29, 2025

Choose a reason for hiding this comment

Uh oh!

newtork Oct 30, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

CharlesDuboisSAP Oct 27, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!