Skip to content

Commit bb64261

Browse files
n-o-u-r-h-a-nCharlesDuboisSAPrpanackalnewtorkbot-sdk-js
authored
chore: Improve Logging (#634)
* Reducing service key logs to minimum. * Some formatting * Custom Info Logs per LLM call * Formatting the ClientResponseHandler.java class. * Removing unused dependency from grounding pom * Added Implicit Tool Calls Logging * Added LLM Calls Logging * Some Formatting * Some Formatting * Some Formatting * Some Formatting * formatting * Updating Pom Dependencies * service bindings static * fix tests * Added useful debug log but as an info one as log.debug() does not show/appear in terminal for some reason. * logback config file * Per request logging update * Review suggestion * fix minor * Update foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiChatCompletionResponse.java * Formatting * Minor format * Minor format * Fix PMD * Fix jacoco --------- Co-authored-by: I538344 <[email protected]> Co-authored-by: Roshin Rajan Panackal <[email protected]> Co-authored-by: Alexander Dümont <[email protected]> Co-authored-by: SAP Cloud SDK Bot <[email protected]> Co-authored-by: Alexander Dümont <[email protected]>
1 parent 2ae2827 commit bb64261

File tree

12 files changed

+121
-17
lines changed

12 files changed

+121
-17
lines changed

‎core-services/document-grounding/pom.xml‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -76,10 +76,6 @@
7676
<groupId>com.fasterxml.jackson.core</groupId>
7777
<artifactId>jackson-annotations</artifactId>
7878
</dependency>
79-
<dependency>
80-
<groupId>org.slf4j</groupId>
81-
<artifactId>slf4j-api</artifactId>
82-
</dependency>
8379
<dependency>
8480
<groupId>com.google.guava</groupId>
8581
<artifactId>guava</artifactId>

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,7 @@ void reloadDeployments(@Nonnull final String resourceGroup) {
4646
try {
4747
val apiClient = new DeploymentApi(service);
4848
val deployments = new HashSet<>(apiClient.query(resourceGroup).getResources());
49+
log.info("Found {} deployments in resource group '{}'", deployments.size(), resourceGroup);
4950
cache.put(resourceGroup, deployments);
5051
} catch (final RuntimeException e) {
5152
throw new DeploymentResolutionException(

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

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import org.apache.hc.core5.http.HttpEntity;
1919
import org.apache.hc.core5.http.io.HttpClientResponseHandler;
2020
import org.apache.hc.core5.http.io.entity.EntityUtils;
21+
import org.slf4j.MDC;
2122

2223
/**
2324
* 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 {
8687
val content =
8788
tryGetContent(responseEntity)
8889
.getOrElseThrow(e -> exceptionFactory.build(message, e).setHttpResponse(response));
90+
logResponseSuccess(response);
91+
8992
try {
9093
return objectMapper.readValue(content, successType);
9194
} catch (final JsonProcessingException e) {
@@ -169,4 +172,16 @@ private static String getErrorMessage(
169172
val message = Optional.ofNullable(additionalMessage).orElse("");
170173
return message.isEmpty() ? baseErrorMessage : "%s: %s".formatted(baseErrorMessage, message);
171174
}
175+
176+
private static void logResponseSuccess(final @Nonnull ClassicHttpResponse response) {
177+
if (!log.isDebugEnabled()) {
178+
return;
179+
}
180+
val headerTime = Optional.ofNullable(response.getFirstHeader("x-upstream-service-time"));
181+
val duration = headerTime.map(h -> h.getValue() + "ms").orElseGet(() -> "unknown");
182+
val entityLength = response.getEntity().getContentLength();
183+
val sizeInfo = entityLength >= 0 ? String.format("%.1fKB", entityLength / 1024.0) : "unknown";
184+
val msg = "[reqId={}] {} request completed successfully with duration={}, size={}.";
185+
log.debug(msg, MDC.get("reqId"), MDC.get("service"), duration, sizeInfo);
186+
}
172187
}

‎foundation-models/openai/pom.xml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,7 @@
4141
<coverage.complexity>81%</coverage.complexity>
4242
<coverage.line>91%</coverage.line>
4343
<coverage.instruction>88%</coverage.instruction>
44-
<coverage.branch>79%</coverage.branch>
44+
<coverage.branch>78%</coverage.branch>
4545
<coverage.method>90%</coverage.method>
4646
<coverage.class>92%</coverage.class>
4747
</properties>

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

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,11 +9,13 @@
99
import com.sap.ai.sdk.foundationmodels.openai.generated.model.CreateChatCompletionResponseChoicesInner;
1010
import java.util.List;
1111
import java.util.Objects;
12+
import java.util.Optional;
1213
import javax.annotation.Nonnull;
1314
import lombok.Getter;
1415
import lombok.RequiredArgsConstructor;
1516
import lombok.Setter;
1617
import lombok.Value;
18+
import lombok.extern.slf4j.Slf4j;
1719

1820
/**
1921
* Represents the output of an OpenAI chat completion. *
@@ -23,6 +25,7 @@
2325
@Value
2426
@RequiredArgsConstructor(access = PACKAGE)
2527
@Setter(value = NONE)
28+
@Slf4j
2629
public class OpenAiChatCompletionResponse {
2730
/** The original response from the OpenAI API. */
2831
@Nonnull CreateChatCompletionResponse originalResponse;
@@ -110,7 +113,11 @@ public OpenAiAssistantMessage getMessage() {
110113
*/
111114
@Nonnull
112115
public List<OpenAiToolMessage> executeTools() {
113-
final var tools = originalRequest.getToolsExecutable();
114-
return OpenAiTool.execute(tools != null ? tools : List.of(), getMessage());
116+
final var tools = Optional.ofNullable(originalRequest.getToolsExecutable()).orElseGet(List::of);
117+
if (log.isDebugEnabled() && !tools.isEmpty()) {
118+
final var toolNames = tools.stream().map(OpenAiTool::getName).toList();
119+
log.debug("Executing {} tool call(s) - {}", toolNames.size(), toolNames);
120+
}
121+
return OpenAiTool.execute(tools, getMessage());
115122
}
116123
}

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

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -30,16 +30,19 @@
3030
import java.io.IOException;
3131
import java.util.ArrayList;
3232
import java.util.List;
33+
import java.util.UUID;
3334
import java.util.stream.Stream;
3435
import javax.annotation.Nonnull;
3536
import javax.annotation.Nullable;
3637
import lombok.AccessLevel;
3738
import lombok.RequiredArgsConstructor;
3839
import lombok.extern.slf4j.Slf4j;
40+
import lombok.val;
3941
import org.apache.hc.client5.http.classic.methods.HttpPost;
4042
import org.apache.hc.core5.http.ContentType;
4143
import org.apache.hc.core5.http.io.entity.StringEntity;
4244
import org.apache.hc.core5.http.message.BasicClassicHttpRequest;
45+
import org.slf4j.MDC;
4346

4447
/** Client for interacting with OpenAI models. */
4548
@Slf4j
@@ -417,6 +420,7 @@ private <T> T execute(
417420
@Nonnull final Class<T> responseType) {
418421
final var request = new HttpPost(path);
419422
serializeAndSetHttpEntity(request, payload, this.customHeaders);
423+
MDC.put("endpoint", path);
420424
return executeRequest(request, responseType);
421425
}
422426

@@ -427,6 +431,7 @@ private <D extends StreamedDelta> Stream<D> executeStream(
427431
@Nonnull final Class<D> deltaType) {
428432
final var request = new HttpPost(path);
429433
serializeAndSetHttpEntity(request, payload, this.customHeaders);
434+
MDC.put("endpoint", path);
430435
return streamRequest(request, deltaType);
431436
}
432437

@@ -449,10 +454,15 @@ private <T> T executeRequest(
449454
final BasicClassicHttpRequest request, @Nonnull final Class<T> responseType) {
450455
try {
451456
final var client = ApacheHttpClient5Accessor.getHttpClient(destination);
457+
MDC.put("destination", ((HttpDestination) destination).getUri().toASCIIString());
458+
MDC.put("mode", "synchronous");
459+
logRequestStart();
452460
return client.execute(
453461
request, new ClientResponseHandler<>(responseType, OpenAiError.class, FACTORY));
454462
} catch (final IOException e) {
455463
throw new OpenAiClientException("Request to OpenAI model failed", e).setHttpRequest(request);
464+
} finally {
465+
MDC.clear();
456466
}
457467
}
458468

@@ -461,11 +471,28 @@ private <D extends StreamedDelta> Stream<D> streamRequest(
461471
final BasicClassicHttpRequest request, @Nonnull final Class<D> deltaType) {
462472
try {
463473
final var client = ApacheHttpClient5Accessor.getHttpClient(destination);
474+
MDC.put("destination", ((HttpDestination) destination).getUri().toASCIIString());
475+
MDC.put("mode", "streaming");
476+
logRequestStart();
464477
return new ClientStreamingHandler<>(deltaType, OpenAiError.class, FACTORY)
465478
.objectMapper(JACKSON)
466479
.handleStreamingResponse(client.executeOpen(null, request, null));
467480
} catch (final IOException e) {
468481
throw new OpenAiClientException("Request to OpenAI model failed", e).setHttpRequest(request);
482+
} finally {
483+
MDC.clear();
469484
}
470485
}
486+
487+
private static void logRequestStart() {
488+
val reqId = UUID.randomUUID().toString().substring(0, 8);
489+
MDC.put("reqId", reqId);
490+
MDC.put("service", "OpenAI");
491+
log.debug(
492+
"[reqId={}] Starting OpenAI {} request to {}, destination={}",
493+
reqId,
494+
MDC.get("mode"),
495+
MDC.get("endpoint"),
496+
MDC.get("destination"));
497+
}
471498
}

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

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -69,8 +69,12 @@ public ChatResponse call(@Nonnull final Prompt prompt) {
6969
val response = new ChatResponse(toGenerations(result));
7070

7171
if (options != null && isInternalToolExecutionEnabled(options) && response.hasToolCalls()) {
72+
val toolCalls =
73+
response.getResult().getOutput().getToolCalls().stream().map(ToolCall::name).toList();
74+
log.info("Executing {} tool call(s) - {}", toolCalls.size(), toolCalls);
7275
val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response);
7376
// Send the tool execution result back to the model.
77+
log.debug("Re-invoking model with tool execution results.");
7478
return call(new Prompt(toolExecutionResult.conversationHistory(), options));
7579
}
7680
return response;

‎logback.xml‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
<?xml version="1.0" encoding="UTF-8"?>
2+
<configuration>
3+
<property name="LOG_PATTERN" value="%d{HH:mm:ss.SSS} %-5level [%thread] %logger{36} : %msg%n"/>
4+
5+
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
6+
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
7+
<pattern>${LOG_PATTERN}</pattern>
8+
</encoder>
9+
</appender>
10+
11+
<root level="INFO">
12+
<appender-ref ref="CONSOLE"/>
13+
</root>
14+
15+
<!-- <logger name="org.apache.hc.client5.http.wire" level="DEBUG"/>-->
16+
<!-- <logger name="org.apache.http.wire" level="DEBUG"/>-->
17+
<logger name="com.sap.ai.sdk" level="DEBUG"/>
18+
<!-- Disable org.eclipse.jetty logging -->
19+
<logger name="org.eclipse.jetty" level="OFF"/>
20+
</configuration>

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

Lines changed: 22 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
import com.sap.cloud.sdk.cloudplatform.connectivity.exception.HttpClientInstantiationException;
1717
import java.io.IOException;
1818
import java.util.List;
19+
import java.util.UUID;
1920
import java.util.function.Supplier;
2021
import java.util.stream.Stream;
2122
import javax.annotation.Nonnull;
@@ -25,6 +26,7 @@
2526
import org.apache.hc.client5.http.classic.methods.HttpPost;
2627
import org.apache.hc.core5.http.ContentType;
2728
import org.apache.hc.core5.http.io.entity.StringEntity;
29+
import org.slf4j.MDC;
2830

2931
@Slf4j
3032
class OrchestrationHttpExecutor {
@@ -45,7 +47,6 @@ <T> T execute(
4547
@Nonnull final List<Header> customHeaders) {
4648
try {
4749
val json = JACKSON.writeValueAsString(payload);
48-
log.debug("Successfully serialized request into JSON payload");
4950
val request = new HttpPost(path);
5051
request.setEntity(new StringEntity(json, ContentType.APPLICATION_JSON));
5152
customHeaders.forEach(h -> request.addHeader(h.getName(), h.getValue()));
@@ -55,6 +56,9 @@ <T> T execute(
5556
val handler =
5657
new ClientResponseHandler<>(responseType, OrchestrationError.Synchronous.class, FACTORY)
5758
.objectMapper(JACKSON);
59+
MDC.put("endpoint", path);
60+
MDC.put("mode", "synchronous");
61+
logRequestStart();
5862
return client.execute(request, handler);
5963

6064
} catch (JsonProcessingException e) {
@@ -66,6 +70,8 @@ <T> T execute(
6670
| IOException e) {
6771
throw new OrchestrationClientException(
6872
"Request to Orchestration service failed for " + path, e);
73+
} finally {
74+
MDC.clear();
6975
}
7076
}
7177

@@ -81,7 +87,9 @@ Stream<OrchestrationChatCompletionDelta> stream(
8187
customHeaders.forEach(h -> request.addHeader(h.getName(), h.getValue()));
8288

8389
val client = getHttpClient();
84-
90+
MDC.put("endpoint", path);
91+
MDC.put("mode", "streaming");
92+
logRequestStart();
8593
return new ClientStreamingHandler<>(
8694
OrchestrationChatCompletionDelta.class, OrchestrationError.Streaming.class, FACTORY)
8795
.objectMapper(JACKSON)
@@ -93,13 +101,24 @@ Stream<OrchestrationChatCompletionDelta> stream(
93101
} catch (IOException e) {
94102
throw new OrchestrationClientException(
95103
"Streaming request to the Orchestration service failed", e);
104+
} finally {
105+
MDC.clear();
96106
}
97107
}
98108

99109
@Nonnull
100110
private HttpClient getHttpClient() {
101111
val destination = destinationSupplier.get();
102-
log.debug("Using destination {} to connect to orchestration service", destination);
112+
MDC.put("destination", destination.getUri().toASCIIString());
103113
return ApacheHttpClient5Accessor.getHttpClient(destination);
104114
}
115+
116+
private static void logRequestStart() {
117+
val reqId = UUID.randomUUID().toString().substring(0, 8);
118+
MDC.put("reqId", reqId);
119+
MDC.put("service", "Orchestration");
120+
121+
val msg = "[reqId={}] Starting Orchestration {} request to {}, destination={}";
122+
log.debug(msg, reqId, MDC.get("mode"), MDC.get("endpoint"), MDC.get("destination"));
123+
}
105124
}

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

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
import java.util.List;
1616
import java.util.Map;
1717
import java.util.function.Function;
18+
import java.util.stream.Collectors;
1819
import javax.annotation.Nonnull;
1920
import lombok.extern.slf4j.Slf4j;
2021
import lombok.val;
@@ -72,8 +73,17 @@ public ChatResponse call(@Nonnull final Prompt prompt) {
7273

7374
if (ToolCallingChatOptions.isInternalToolExecutionEnabled(prompt.getOptions())
7475
&& response.hasToolCalls()) {
76+
77+
if (log.isDebugEnabled()) {
78+
val tools = response.getResult().getOutput().getToolCalls();
79+
val toolsStr = tools.stream().map(ToolCall::name).collect(Collectors.joining(", "));
80+
log.debug("Executing {} tool call(s) - {}", tools.size(), toolsStr);
81+
}
82+
7583
val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response);
84+
7685
// Send the tool execution result back to the model.
86+
log.debug("Re-invoking LLM with tool execution results.");
7787
return call(new Prompt(toolExecutionResult.conversationHistory(), prompt.getOptions()));
7888
}
7989
return response;

0 commit comments

Comments
 (0)