diff --git a/core-services/document-grounding/pom.xml b/core-services/document-grounding/pom.xml index 89342cbd4..dd76e0cc0 100644 --- a/core-services/document-grounding/pom.xml +++ b/core-services/document-grounding/pom.xml @@ -76,10 +76,6 @@ com.fasterxml.jackson.core jackson-annotations - - org.slf4j - slf4j-api - com.google.guava guava diff --git a/core/src/main/java/com/sap/ai/sdk/core/DeploymentResolver.java b/core/src/main/java/com/sap/ai/sdk/core/DeploymentResolver.java index 66d674f8d..f42725cc5 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/DeploymentResolver.java +++ b/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( diff --git a/core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java b/core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java index 6588898ba..3cad0bd6d 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/common/ClientResponseHandler.java +++ b/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); + } } diff --git a/foundation-models/openai/pom.xml b/foundation-models/openai/pom.xml index 2e228887a..f8e1fd0a6 100644 --- a/foundation-models/openai/pom.xml +++ b/foundation-models/openai/pom.xml @@ -41,7 +41,7 @@ 81% 91% 88% - 79% + 78% 90% 92% diff --git a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java b/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java index ec9fea99e..1cd42e86c 100644 --- a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java +++ b/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 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()); } } diff --git a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java b/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java index e24eab3e5..f1628a3f9 100644 --- a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiClient.java +++ b/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 execute( @Nonnull final Class 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 Stream executeStream( @Nonnull final Class 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 executeRequest( final BasicClassicHttpRequest request, @Nonnull final Class 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 Stream streamRequest( final BasicClassicHttpRequest request, @Nonnull final Class 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")); + } } diff --git a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/spring/OpenAiChatModel.java b/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/spring/OpenAiChatModel.java index c31287907..280bbee7c 100644 --- a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/spring/OpenAiChatModel.java +++ b/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; diff --git a/logback.xml b/logback.xml new file mode 100644 index 000000000..2bbaaa365 --- /dev/null +++ b/logback.xml @@ -0,0 +1,20 @@ + + + + + + + ${LOG_PATTERN} + + + + + + + + + + + + + diff --git a/orchestration/src/main/java/com/sap/ai/sdk/orchestration/OrchestrationHttpExecutor.java b/orchestration/src/main/java/com/sap/ai/sdk/orchestration/OrchestrationHttpExecutor.java index 65f4e3ece..d7b488ca8 100644 --- a/orchestration/src/main/java/com/sap/ai/sdk/orchestration/OrchestrationHttpExecutor.java +++ b/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 execute( @Nonnull final List
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 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 execute( | IOException e) { throw new OrchestrationClientException( "Request to Orchestration service failed for " + path, e); + } finally { + MDC.clear(); } } @@ -81,7 +87,9 @@ Stream 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 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")); + } } diff --git a/orchestration/src/main/java/com/sap/ai/sdk/orchestration/spring/OrchestrationChatModel.java b/orchestration/src/main/java/com/sap/ai/sdk/orchestration/spring/OrchestrationChatModel.java index 23f51833b..ababae33c 100644 --- a/orchestration/src/main/java/com/sap/ai/sdk/orchestration/spring/OrchestrationChatModel.java +++ b/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; diff --git a/pom.xml b/pom.xml index 6bf8b7cb0..a586ecb7e 100644 --- a/pom.xml +++ b/pom.xml @@ -71,6 +71,7 @@ 3.27.1 4.38.0 2.20.0 + 1.5.20 1.15.5 20250517 @@ -258,9 +259,9 @@ - org.slf4j - slf4j-simple - ${slf4j.version} + ch.qos.logback + logback-classic + ${logback.version} test @@ -365,7 +366,7 @@ org.tinylog - org.slf4j:slf4j-simple:*:*:test + ch.qos.logback:*:*:*:test @@ -554,9 +555,7 @@ com.google.code.findbugs:jsr305 - org.slf4j:slf4j-api - org.slf4j:jcl-over-slf4j - org.slf4j:slf4j-simple + ch.qos.logback:logback-classic org.projectlombok:lombok @@ -598,6 +597,11 @@ org.apache.maven.plugins maven-surefire-plugin ${surefire.version} + + + ${project.rootdir}/logback.xml + + diff --git a/sample-code/spring-app/src/main/resources/logback-spring.xml b/sample-code/spring-app/src/main/resources/logback-spring.xml index b1d413914..7aac1238d 100644 --- a/sample-code/spring-app/src/main/resources/logback-spring.xml +++ b/sample-code/spring-app/src/main/resources/logback-spring.xml @@ -6,6 +6,7 @@ +