From 98d7f9f093a3b1938263b4bf1ba253fd74f8893f Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Fri, 7 Nov 2025 15:59:32 +0100 Subject: [PATCH 01/12] Apply additional review suggestion --- docs/adrs/006-logging-strategy.md | 36 +++++++++++++++++++++++++++++++ 1 file changed, 36 insertions(+) create mode 100644 docs/adrs/006-logging-strategy.md diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md new file mode 100644 index 000000000..0072a5e27 --- /dev/null +++ b/docs/adrs/006-logging-strategy.md @@ -0,0 +1,36 @@ +# Logging Strategy + +## Status: Proposed + +## Context + +We would like to log useful information that in future helps us and the user debug and resolve problems quickly. + +Currently, the user would have to enable wire logs to show information that enables us to assist them. +We also identified than there is benefit to show a story of what is happening behind the scenes to the user which informs them on application progress. +We want to rely on application level logs from ai sdk for the same. + +## Guidelines + +- Don't log any sensitive information eg: names, ids etc. The general rule to follow is to avoid logging request or response payloads. +- Logs must contain useful and non-redundant information to keep them concise and to the point. +- Keep per-request log below INFO level to avoid littering the output and further making it difficult to identify related logs +- Prefer to keep one-time logs in a single application run at INFO level. +- Make use of MDC as appropriate and deliberate about clearing the context. +- MDC must not be cleared as a whole but only by key basis to avoid unintentionally clearing context items that merit a longer lifespan +- To be deliberate about logging, we limit logging out of generated classes, consequently limiting logs produced from modules like document-grounding, prompt-registry. +- Limit unnecessary warning logs to also avoid littering the console logging +- MDC is currently leveraged to contain and transport information when logging is performed on a different block down the flow of control chain. We need special care on where the context is set. Any per-request context set in MDC is clearing up at response completion. Consequently, setting per-request context outside of blocks/objects that are not invoked/consumed per-request can lead to incomplete MDC states which will in turn corrupt logs produced. +- We are generally inclined towards descriptive and human-readable logs and ideally contain, service invoked, endpoint etc and request logging. We do not expect machine readability of logs but still following "metric=value" patterns for the sake of extensibility and readability of them. +- We may also correlate request level logs with request identifier reqId to assist debugging. +- In the case for logging information not simply read but involve computation or inference cost, we must deliberately deflect the effort based on log level or other available context. +- Centralize MDC handling. Using magic string as keys or values for the context may be lost in maintenance and add towards collaborative effort. We may wrap the access in a format that explicitly declares context keys and assist discoverability of all expected context items, so they are not lost in refactoring effort. +- The responsibility of MDC context clearing lies with the class that sets the context for the sake of readability. +- Explicitly log at request start and don't purely rely on logging at response time. A request may take long or even fail. Additionally, inferring response metrics even for a success case may be non-trivial eg: duration for streaming. The most critical benefit is immediate visibility for the user about the effect of their action for even long-running requests. Additionally, this avoids the the scenario where the surface error is ambiguous and needs investigation of stack-trace. + +### Unattended +- Unit test logging +- Logback +- logging pattern +- Separate logging into per request and per application runtime. +- A separate section for MDC Handling \ No newline at end of file From 07ce6be1b967a934e40792a1eeb7eac6032b167c Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 10 Nov 2025 11:28:53 +0100 Subject: [PATCH 02/12] First draft --- docs/adrs/006-logging-strategy.md | 129 +++++++++++++++++++++++------- 1 file changed, 102 insertions(+), 27 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 0072a5e27..ecb8b4d61 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -1,36 +1,111 @@ # Logging Strategy -## Status: Proposed +## Status + +Proposed ## Context -We would like to log useful information that in future helps us and the user debug and resolve problems quickly. +The AI SDK identified some challenges with debugging and problem resolution that can be addressed with better logging. +Typically, users had to enable wire logs to access information necessary for troubleshooting which along with helpful log surfaces a large volume of unrelated one. +Additionally, we identified the need to improve visibility into what's happening behind the scenes about application progress to the user. + +Key challenges that drove this decision: + +- **Debugging difficulties**: Limited visibility into request flows and processing steps +- **Security concerns**: Risk of accidentally logging sensitive information +- **User experience**: Users needed better insight into long-running AI operations +- **Trace ownership**: Reliance on external parties for troubleshooting details -Currently, the user would have to enable wire logs to show information that enables us to assist them. -We also identified than there is benefit to show a story of what is happening behind the scenes to the user which informs them on application progress. -We want to rely on application level logs from ai sdk for the same. +## Decision + +Devise and follow a comprehensive logging guidelines that prioritizes **debugging capability** and **user visibility** while maintaining **security** and **performance**. The approach emphasizes descriptive, human-readable logs with structured request tracking through MDC (Mapped Diagnostic Context). ## Guidelines -- Don't log any sensitive information eg: names, ids etc. The general rule to follow is to avoid logging request or response payloads. -- Logs must contain useful and non-redundant information to keep them concise and to the point. -- Keep per-request log below INFO level to avoid littering the output and further making it difficult to identify related logs -- Prefer to keep one-time logs in a single application run at INFO level. -- Make use of MDC as appropriate and deliberate about clearing the context. -- MDC must not be cleared as a whole but only by key basis to avoid unintentionally clearing context items that merit a longer lifespan -- To be deliberate about logging, we limit logging out of generated classes, consequently limiting logs produced from modules like document-grounding, prompt-registry. -- Limit unnecessary warning logs to also avoid littering the console logging -- MDC is currently leveraged to contain and transport information when logging is performed on a different block down the flow of control chain. We need special care on where the context is set. Any per-request context set in MDC is clearing up at response completion. Consequently, setting per-request context outside of blocks/objects that are not invoked/consumed per-request can lead to incomplete MDC states which will in turn corrupt logs produced. -- We are generally inclined towards descriptive and human-readable logs and ideally contain, service invoked, endpoint etc and request logging. We do not expect machine readability of logs but still following "metric=value" patterns for the sake of extensibility and readability of them. -- We may also correlate request level logs with request identifier reqId to assist debugging. -- In the case for logging information not simply read but involve computation or inference cost, we must deliberately deflect the effort based on log level or other available context. -- Centralize MDC handling. Using magic string as keys or values for the context may be lost in maintenance and add towards collaborative effort. We may wrap the access in a format that explicitly declares context keys and assist discoverability of all expected context items, so they are not lost in refactoring effort. -- The responsibility of MDC context clearing lies with the class that sets the context for the sake of readability. -- Explicitly log at request start and don't purely rely on logging at response time. A request may take long or even fail. Additionally, inferring response metrics even for a success case may be non-trivial eg: duration for streaming. The most critical benefit is immediate visibility for the user about the effect of their action for even long-running requests. Additionally, this avoids the the scenario where the surface error is ambiguous and needs investigation of stack-trace. - -### Unattended -- Unit test logging -- Logback -- logging pattern -- Separate logging into per request and per application runtime. -- A separate section for MDC Handling \ No newline at end of file +### 1. Content and Security + +* **Avoid sensitive information.** + Do not log any personally identifiable or confidential data such as names, IDs, tokens, or payload content. As a general rule, avoid logging full request or response bodies. + +* **Keep logs concise and relevant.** + Every log should convey meaningful information without redundancy. Avoid verbose, repetitive, or cosmetic details. + +* **Use descriptive, human-readable formats.** + Logs should read naturally and provide enough context for a developer to understand what happened without consulting the code. Include details such as the invoked service, endpoint etc. as applicable. + +* **Maintain extensible readability.** + While logs are intended for humans, follow the `metric=value` pattern where practical. This improves future extensibility and allows easier parsing if machine analysis becomes necessary. + +* **Correlate related logs.** + Include a request identifier (e.g., `reqId`) in per-request logs to assist with correlation and debugging. + +--- + +### 2. Log Levels and Scope + +* **Per-request logs.** + Keep per-request logs **below INFO level** (e.g., DEBUG or TRACE) to prevent cluttering normal application output. + +* **Application runtime logs.** + Prefer **INFO level** for one-time or startup/shutdown logs that occur once per application run. + +* **Avoid unnecessary warnings.** + Use the WARNING level only for actionable or genuinely concerning conditions. Do not use it as a placeholder or for expected transient states. + +* **Explicit request lifecycle logging.** + Always log at **request start** to provide immediate visibility that an operation has begun. Do not rely solely on response-time logging — requests may fail, hang, or take long durations (e.g., streaming cases). This helps users understand that their request is being processed even before a result is available. + +* **Performance-aware logging.** + If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) to avoid unnecessary overhead when that level is disabled. + +--- + +### 3. MDC (Mapped Diagnostic Context) + +* **Purpose and usage.** + MDC is used to carry contextual information (e.g., `reqId`, `endpoint`, `service`) across execution blocks within the same thread. + +* **Setting and clearing context.** + Set MDC values deliberately and close to their scope of relevance. Per-request MDC context must be cleared when the response completes. Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. + +* **Granular clearing only.** + Never clear the entire MDC context. Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. + +* **Centralized MDC management.** + Avoid using magic strings for MDC keys or values. Define them in a dedicated structure or utility (e.g., `MdcKeys` class) to ensure discoverability and prevent errors during refactoring. + +* **Responsibility and ownership.** + The component or class that sets MDC context values is also responsible for clearing them. This maintains clarity and ensures proper lifecycle management. + +--- + +### 4. Logging Boundaries and Generation + +* **Deliberate logging boundaries.** + Generated code (such as those in modules like *document-grounding* or *prompt-registry*) should log minimally and preferably avoid. Logging should be centralized in higher-level components to maintain consistency and reduce noise. + +## Alternatives + +### Logging Framework Options + +1. **slf4j-simple** (previous): Simple but limited configuration and poor production suitability +2. **logback-classic** (chosen): Industry standard with rich configuration, performance, and features + +### Log Format Approaches + +1. **Structured JSON logging**: Machine-readable but harder for human debugging +2. **Descriptive human-readable** (chosen): Prioritizes developer and user experience while maintaining some structure + +## Consequences + +### Positive + +- **Improved debugging**: Comprehensive request tracking enables faster problem resolution +- **Better user experience**: Users can see progress of long-running AI operations +- **Security compliance**: Systematic approach prevents accidental logging of sensitive data + +### Negative + +- **Increased debug log volume**: More detailed logging may increase storage and processing overhead +- **Development overhead**: Developers must be mindful of proper MDC management as improper MDC handling could lead to incorrect request correlation \ No newline at end of file From ee61c272e91e3ebf2977c80871b27361888a75b1 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 10 Nov 2025 12:57:44 +0100 Subject: [PATCH 03/12] Remove low value section and improve formatting --- docs/adrs/006-logging-strategy.md | 75 ++++++++++++++----------------- 1 file changed, 34 insertions(+), 41 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index ecb8b4d61..013181707 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -7,7 +7,7 @@ Proposed ## Context The AI SDK identified some challenges with debugging and problem resolution that can be addressed with better logging. -Typically, users had to enable wire logs to access information necessary for troubleshooting which along with helpful log surfaces a large volume of unrelated one. +Typically, users had to enable wire logs to access information necessary for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated ones. Additionally, we identified the need to improve visibility into what's happening behind the scenes about application progress to the user. Key challenges that drove this decision: @@ -19,27 +19,34 @@ Key challenges that drove this decision: ## Decision -Devise and follow a comprehensive logging guidelines that prioritizes **debugging capability** and **user visibility** while maintaining **security** and **performance**. The approach emphasizes descriptive, human-readable logs with structured request tracking through MDC (Mapped Diagnostic Context). +Devise and follow comprehensive logging guidelines that prioritize **debugging capability** and **user visibility** while maintaining **security** and **performance**. +The approach emphasizes descriptive, human-readable logs with structured request tracking through MDC (Mapped Diagnostic Context). ## Guidelines ### 1. Content and Security * **Avoid sensitive information.** - Do not log any personally identifiable or confidential data such as names, IDs, tokens, or payload content. As a general rule, avoid logging full request or response bodies. + As a general rule, avoid logging full request or response bodies. + Do not log any personally identifiable or confidential data such as names, IDs, tokens, or payload content. * **Keep logs concise and relevant.** - Every log should convey meaningful information without redundancy. Avoid verbose, repetitive, or cosmetic details. + Every log should convey meaningful information without redundancy. + Avoid verbose, repetitive, or cosmetic details. * **Use descriptive, human-readable formats.** - Logs should read naturally and provide enough context for a developer to understand what happened without consulting the code. Include details such as the invoked service, endpoint etc. as applicable. - -* **Maintain extensible readability.** - While logs are intended for humans, follow the `metric=value` pattern where practical. This improves future extensibility and allows easier parsing if machine analysis becomes necessary. + Logs should read naturally and provide enough context for a developer to understand what happened without consulting the code. + While descriptiveness is a priority, follow the `metric=value` pattern where practical to include additional details with extensibility in mind. + Check out the example below. + ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, size=1,2KB.``` * **Correlate related logs.** Include a request identifier (e.g., `reqId`) in per-request logs to assist with correlation and debugging. +* **Exception logging security.** + When logging exceptions, use standard logging methods (e.g., `log.error("Operation failed", exception)`) rather than serializing exception objects. + Exception objects may contain custom fields with sensitive data that could be exposed through JSON serialization or custom `toString()` implementations. + --- ### 2. Log Levels and Scope @@ -51,13 +58,17 @@ Devise and follow a comprehensive logging guidelines that prioritizes **debuggin Prefer **INFO level** for one-time or startup/shutdown logs that occur once per application run. * **Avoid unnecessary warnings.** - Use the WARNING level only for actionable or genuinely concerning conditions. Do not use it as a placeholder or for expected transient states. + Use the WARNING level only for actionable or genuinely concerning conditions. + Do not use it as a placeholder or for expected transient states. * **Explicit request lifecycle logging.** - Always log at **request start** to provide immediate visibility that an operation has begun. Do not rely solely on response-time logging — requests may fail, hang, or take long durations (e.g., streaming cases). This helps users understand that their request is being processed even before a result is available. + Always log at **request start** to provide immediate visibility that an operation has begun. + This helps users understand that their request is being processed even before a result is available. + Do not rely solely on response-time logging — requests may fail, hang, or take long durations. + This approach also avoids the need for stack-trace investigation when surface error responses are ambiguous. * **Performance-aware logging.** - If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) to avoid unnecessary overhead when that level is disabled. + If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) or other available context to avoid unnecessary overhead when that level is disabled. --- @@ -67,45 +78,27 @@ Devise and follow a comprehensive logging guidelines that prioritizes **debuggin MDC is used to carry contextual information (e.g., `reqId`, `endpoint`, `service`) across execution blocks within the same thread. * **Setting and clearing context.** - Set MDC values deliberately and close to their scope of relevance. Per-request MDC context must be cleared when the response completes. Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. + Set MDC values deliberately and close to their scope of relevance. + Per-request MDC context must be cleared when the response completes. + Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. + Setting per-request context outside of blocks or objects that are not invoked per-request can lead to incomplete MDC states which will corrupt logs produced. * **Granular clearing only.** - Never clear the entire MDC context. Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. + Never clear the entire MDC context. + Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. * **Centralized MDC management.** - Avoid using magic strings for MDC keys or values. Define them in a dedicated structure or utility (e.g., `MdcKeys` class) to ensure discoverability and prevent errors during refactoring. + Avoid using magic strings for MDC keys or values. + Define them in a dedicated structure or utility (e.g., `MdcKeys` class) to ensure discoverability and prevent errors during refactoring. * **Responsibility and ownership.** - The component or class that sets MDC context values is also responsible for clearing them. This maintains clarity and ensures proper lifecycle management. + The component or class that sets MDC context values is also responsible for clearing them. + This maintains clarity and ensures proper lifecycle management. --- ### 4. Logging Boundaries and Generation * **Deliberate logging boundaries.** - Generated code (such as those in modules like *document-grounding* or *prompt-registry*) should log minimally and preferably avoid. Logging should be centralized in higher-level components to maintain consistency and reduce noise. - -## Alternatives - -### Logging Framework Options - -1. **slf4j-simple** (previous): Simple but limited configuration and poor production suitability -2. **logback-classic** (chosen): Industry standard with rich configuration, performance, and features - -### Log Format Approaches - -1. **Structured JSON logging**: Machine-readable but harder for human debugging -2. **Descriptive human-readable** (chosen): Prioritizes developer and user experience while maintaining some structure - -## Consequences - -### Positive - -- **Improved debugging**: Comprehensive request tracking enables faster problem resolution -- **Better user experience**: Users can see progress of long-running AI operations -- **Security compliance**: Systematic approach prevents accidental logging of sensitive data - -### Negative - -- **Increased debug log volume**: More detailed logging may increase storage and processing overhead -- **Development overhead**: Developers must be mindful of proper MDC management as improper MDC handling could lead to incorrect request correlation \ No newline at end of file + Generated code (such as those in modules like *document-grounding* or *prompt-registry*) should log minimally or preferably be avoided entirely. + Logging should be centralized in higher-level components to maintain consistency and reduce noise. From 899d7e6774368c1154ed5257b03aa09ec1e89379 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 10 Nov 2025 13:05:36 +0100 Subject: [PATCH 04/12] cleaning up --- docs/adrs/006-logging-strategy.md | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 013181707..a493e286b 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -38,12 +38,13 @@ The approach emphasizes descriptive, human-readable logs with structured request Logs should read naturally and provide enough context for a developer to understand what happened without consulting the code. While descriptiveness is a priority, follow the `metric=value` pattern where practical to include additional details with extensibility in mind. Check out the example below. + ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, size=1,2KB.``` -* **Correlate related logs.** +* **Correlate logs.** Include a request identifier (e.g., `reqId`) in per-request logs to assist with correlation and debugging. -* **Exception logging security.** +* **Exception logging.** When logging exceptions, use standard logging methods (e.g., `log.error("Operation failed", exception)`) rather than serializing exception objects. Exception objects may contain custom fields with sensitive data that could be exposed through JSON serialization or custom `toString()` implementations. @@ -61,14 +62,14 @@ The approach emphasizes descriptive, human-readable logs with structured request Use the WARNING level only for actionable or genuinely concerning conditions. Do not use it as a placeholder or for expected transient states. -* **Explicit request lifecycle logging.** +* **Explicit request logging.** Always log at **request start** to provide immediate visibility that an operation has begun. This helps users understand that their request is being processed even before a result is available. Do not rely solely on response-time logging — requests may fail, hang, or take long durations. This approach also avoids the need for stack-trace investigation when surface error responses are ambiguous. * **Performance-aware logging.** - If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) or other available context to avoid unnecessary overhead when that level is disabled. + If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) or other available context to avoid unnecessary overhead. --- @@ -81,7 +82,6 @@ The approach emphasizes descriptive, human-readable logs with structured request Set MDC values deliberately and close to their scope of relevance. Per-request MDC context must be cleared when the response completes. Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. - Setting per-request context outside of blocks or objects that are not invoked per-request can lead to incomplete MDC states which will corrupt logs produced. * **Granular clearing only.** Never clear the entire MDC context. @@ -89,7 +89,7 @@ The approach emphasizes descriptive, human-readable logs with structured request * **Centralized MDC management.** Avoid using magic strings for MDC keys or values. - Define them in a dedicated structure or utility (e.g., `MdcKeys` class) to ensure discoverability and prevent errors during refactoring. + Define them in a dedicated structure or utility (e.g., `RequestlogContext` class) to ensure discoverability and prevent errors during refactoring. * **Responsibility and ownership.** The component or class that sets MDC context values is also responsible for clearing them. From 598f64b1334c5029e2cc314d22626c687c8d769d Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 10 Nov 2025 13:38:20 +0100 Subject: [PATCH 05/12] Paraphrasing --- docs/adrs/006-logging-strategy.md | 49 +++++++++++++++---------------- 1 file changed, 24 insertions(+), 25 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index a493e286b..fcc72fd37 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -2,42 +2,41 @@ ## Status -Proposed +Accepted ## Context The AI SDK identified some challenges with debugging and problem resolution that can be addressed with better logging. -Typically, users had to enable wire logs to access information necessary for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated ones. -Additionally, we identified the need to improve visibility into what's happening behind the scenes about application progress to the user. +Typically, users have to enable wire logs for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated ones. +Additionally, we identified the need to improve visibility into application progress to the user. -Key challenges that drove this decision: +Key drivers for this decision include: -- **Debugging difficulties**: Limited visibility into request flows and processing steps -- **Security concerns**: Risk of accidentally logging sensitive information -- **User experience**: Users needed better insight into long-running AI operations -- **Trace ownership**: Reliance on external parties for troubleshooting details +- **Debugging difficulties**: Limited visibility into request flows. +- **Security risks**: Accidental logging of sensitive data. +- **Poor user experience**: Lack of insight into application progress. +- **Troubleshooting dependency**: Reliance on external parties for critical details. ## Decision -Devise and follow comprehensive logging guidelines that prioritize **debugging capability** and **user visibility** while maintaining **security** and **performance**. -The approach emphasizes descriptive, human-readable logs with structured request tracking through MDC (Mapped Diagnostic Context). +We will implement and enforce comprehensive logging guidelines that prioritize **debugging capability** and **user visibility**. +This approach mandates descriptive, human-readable logs with structured request tracking through Mapped Diagnostic Context (MDC). ## Guidelines -### 1. Content and Security +### 1. Log Content and Security -* **Avoid sensitive information.** - As a general rule, avoid logging full request or response bodies. - Do not log any personally identifiable or confidential data such as names, IDs, tokens, or payload content. +- **Do not log sensitive information.** + Never log full request or response bodies. + Ensure that personally identifiable or confidential data—such as names, IDs, tokens, or payload content—is always excluded from logs. -* **Keep logs concise and relevant.** - Every log should convey meaningful information without redundancy. - Avoid verbose, repetitive, or cosmetic details. +- **Write concise and relevant logs.** + Every log must convey meaningful information. + Avoid verbose, repetitive, or purely cosmetic details. -* **Use descriptive, human-readable formats.** - Logs should read naturally and provide enough context for a developer to understand what happened without consulting the code. - While descriptiveness is a priority, follow the `metric=value` pattern where practical to include additional details with extensibility in mind. - Check out the example below. +- **Use descriptive, human-readable formats.** + Logs must be clear enough for a developer to understand what happened without checking the code. + Use the `metric=value` pattern to include structured details with extensibility in mind. ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, size=1,2KB.``` @@ -56,10 +55,10 @@ The approach emphasizes descriptive, human-readable logs with structured request Keep per-request logs **below INFO level** (e.g., DEBUG or TRACE) to prevent cluttering normal application output. * **Application runtime logs.** - Prefer **INFO level** for one-time or startup/shutdown logs that occur once per application run. + Prefer **INFO level** only for one-time or startup/shutdown logs that occur once per application run. * **Avoid unnecessary warnings.** - Use the WARNING level only for actionable or genuinely concerning conditions. + Use the WARN level only for actionable or genuinely concerning conditions. Do not use it as a placeholder or for expected transient states. * **Explicit request logging.** @@ -69,7 +68,7 @@ The approach emphasizes descriptive, human-readable logs with structured request This approach also avoids the need for stack-trace investigation when surface error responses are ambiguous. * **Performance-aware logging.** - If a log statement requires computation or inference to generate information, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) or other available context to avoid unnecessary overhead. + If a log statement requires expensive computation, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) to prevent performance degradation. --- @@ -89,7 +88,7 @@ The approach emphasizes descriptive, human-readable logs with structured request * **Centralized MDC management.** Avoid using magic strings for MDC keys or values. - Define them in a dedicated structure or utility (e.g., `RequestlogContext` class) to ensure discoverability and prevent errors during refactoring. + Define them in a dedicated structure or utility (e.g., `RequestLogContext` class) to ensure discoverability and prevent errors during refactoring. * **Responsibility and ownership.** The component or class that sets MDC context values is also responsible for clearing them. From 1d4b0b8f49e9ce79a94db8a714352887efc7a0d7 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Tue, 11 Nov 2025 11:03:12 +0100 Subject: [PATCH 06/12] Review suggestions - adding . at the end - reqId explanation - 'size' renaming in log for clarity - MDc examplee - "object creation" with example instead of vague computaiton - remove mention of "placeholder" warnings --- .../ai/sdk/core/AiCoreServiceKeyAccessor.java | 2 +- .../sap/ai/sdk/core/DeploymentResolver.java | 2 +- .../core/common/ClientResponseHandler.java | 2 +- .../core/common/ClientStreamingHandler.java | 2 +- .../core/common/IterableStreamConverter.java | 6 +- .../ai/sdk/core/common/RequestLogContext.java | 2 +- docs/adrs/006-logging-strategy.md | 64 +++++++++++++++++-- .../openai/OpenAiChatCompletionResponse.java | 2 +- .../foundationmodels/openai/OpenAiTool.java | 2 +- .../openai/spring/OpenAiChatModel.java | 4 +- .../spring/OrchestrationChatModel.java | 2 +- 11 files changed, 70 insertions(+), 20 deletions(-) diff --git a/core/src/main/java/com/sap/ai/sdk/core/AiCoreServiceKeyAccessor.java b/core/src/main/java/com/sap/ai/sdk/core/AiCoreServiceKeyAccessor.java index 49f122090..eb79086fe 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/AiCoreServiceKeyAccessor.java +++ b/core/src/main/java/com/sap/ai/sdk/core/AiCoreServiceKeyAccessor.java @@ -52,7 +52,7 @@ public List getServiceBindings() throws ServiceBindingAccessExce throw new ServiceBindingAccessException("Failed to load service key from environment", e); } if (serviceKey == null) { - log.debug("No service key found in environment variable {}", ENV_VAR_KEY); + log.debug("No service key found in environment variable {}.", ENV_VAR_KEY); return List.of(); } final String logMessage = 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 f42725cc5..78c233b61 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,7 +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); + 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 9744b88fd..b156d9ee2 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 @@ -91,7 +91,7 @@ private T parseSuccess(@Nonnull final ClassicHttpResponse response) throws E { try { return objectMapper.readValue(content, successType); } catch (final JsonProcessingException e) { - log.error("Failed to parse response to type {}", successType); + log.error("Failed to parse response to type {}.", successType); throw exceptionFactory.build("Failed to parse response", e).setHttpResponse(response); } } diff --git a/core/src/main/java/com/sap/ai/sdk/core/common/ClientStreamingHandler.java b/core/src/main/java/com/sap/ai/sdk/core/common/ClientStreamingHandler.java index cd4ca676b..42be3df31 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/common/ClientStreamingHandler.java +++ b/core/src/main/java/com/sap/ai/sdk/core/common/ClientStreamingHandler.java @@ -85,7 +85,7 @@ public Stream handleStreamingResponse(@Nonnull final ClassicHttpResponse resp } return objectMapper.treeToValue(jsonNode, successType); } catch (final IOException e) { - log.error("Failed to parse delta chunk to type {}", successType); + log.error("Failed to parse delta chunk to type {}.", successType); final String message = "Failed to parse delta chunk"; throw exceptionFactory.build(message, e).setHttpResponse(response); } diff --git a/core/src/main/java/com/sap/ai/sdk/core/common/IterableStreamConverter.java b/core/src/main/java/com/sap/ai/sdk/core/common/IterableStreamConverter.java index 12ec15fac..3a6515b90 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/common/IterableStreamConverter.java +++ b/core/src/main/java/com/sap/ai/sdk/core/common/IterableStreamConverter.java @@ -35,8 +35,8 @@ class IterableStreamConverter implements Iterator { static final int BUFFER_SIZE = 8192; private static final String ERR_CONTENT = "Failed to read response content."; - private static final String ERR_INTERRUPTED = "Parsing response content was interrupted"; - private static final String ERR_CLOSE = "Could not close input stream with error: {} (ignored)"; + private static final String ERR_INTERRUPTED = "Parsing response content was interrupted."; + private static final String ERR_CLOSE = "Could not close input stream with error: {} (ignored)."; /** Read next entry for Stream or {@code null} when no further entry can be read. */ private final Callable readHandler; @@ -70,7 +70,7 @@ public boolean hasNext() { } catch (final Exception e) { isDone = true; stopHandler.run(); - log.debug("Reading next element failed with error {})", e.getClass().getSimpleName()); + log.debug("Reading next element failed with error {}.", e.getClass().getSimpleName()); throw errorHandler.apply(e); } return !isDone; diff --git a/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java b/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java index 9be187bcd..19d218dc3 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java +++ b/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java @@ -77,7 +77,7 @@ public static void logRequestStart() { val reqId = UUID.randomUUID().toString().substring(0, 8); RequestLogContext.setRequestId(reqId); - val message = "[reqId={}] Starting {} {} request to {}, destination={}"; + val message = "[reqId={}] Starting {} {} request to {}, destination={}."; log.debug( message, reqId, diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index fcc72fd37..e1ff11063 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -38,10 +38,12 @@ This approach mandates descriptive, human-readable logs with structured request Logs must be clear enough for a developer to understand what happened without checking the code. Use the `metric=value` pattern to include structured details with extensibility in mind. - ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, size=1,2KB.``` + ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, responseSize=1.2KB.``` * **Correlate logs.** Include a request identifier (e.g., `reqId`) in per-request logs to assist with correlation and debugging. + In this SDK, a "request" represents a single AI service operation (e.g., one chat completion call, one embedding generation). + The `reqId` is generated for each AI service call and is distinct from any HTTP request tracking in user's application framework. * **Exception logging.** When logging exceptions, use standard logging methods (e.g., `log.error("Operation failed", exception)`) rather than serializing exception objects. @@ -59,7 +61,7 @@ This approach mandates descriptive, human-readable logs with structured request * **Avoid unnecessary warnings.** Use the WARN level only for actionable or genuinely concerning conditions. - Do not use it as a placeholder or for expected transient states. + Expected transient states (retries, fallbacks, cache misses) should not generate a warning. * **Explicit request logging.** Always log at **request start** to provide immediate visibility that an operation has begun. @@ -67,8 +69,34 @@ This approach mandates descriptive, human-readable logs with structured request Do not rely solely on response-time logging — requests may fail, hang, or take long durations. This approach also avoids the need for stack-trace investigation when surface error responses are ambiguous. + ```[reqId=e3eaa45c] Starting OpenAI synchronous request to /v1/chat/completions, destination=.``` + * **Performance-aware logging.** - If a log statement requires expensive computation, guard it with a log-level check (e.g., `if (log.isDebugEnabled())`) to prevent performance degradation. + If a log statement requires any object creation, guard it with a log-level check to prevent performance degradation. + + ``` java + Optional maybeDestination; + Destination fallbackDestination = /* existing instance */; + + // Bad: Creates objects or invokes methods even when logging is disabled + log.debug("Destination: {}", maybeDestination.toString()); + log.debug("Destination: {}", maybeDestination.orElseGet(() -> new Destination())); + log.debug("Destination: {}", maybeDestination.orElseGet(this::getFallback)); + log.debug("Destination: {}", maybeDestination.orElse(getFallback())); + + // Good: No object creation or method invocation + log.debug("Destination: {}", maybeDestination); + log.debug("Destination: {}", maybeDestination.orElse(fallbackDestination)); + + // Good: Guard object creation + if (log.isDebugEnabled()) { + log.debug("Destination: {}", maybeDestination.orElse(getFallback())); + } + + // Exception: Singletons require no guarding (no object creation) + Optional> maybeDestinations; + log.debug("Destinations: {}", maybeDestinations.orElse(Collections.emptyList())); + ``` --- @@ -82,13 +110,35 @@ This approach mandates descriptive, human-readable logs with structured request Per-request MDC context must be cleared when the response completes. Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. -* **Granular clearing only.** - Never clear the entire MDC context. - Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. - * **Centralized MDC management.** Avoid using magic strings for MDC keys or values. Define them in a dedicated structure or utility (e.g., `RequestLogContext` class) to ensure discoverability and prevent errors during refactoring. + ```java + // Bad: Magic strings scattered in code + MDC.put("service", "OpenAI"); + log.debug("Service {}", MDC.get("service")); + + // Good: Centralized in utility class + RequestLogContext.setService(Service.OPENAI); + log.debug("Service {}", RequestLogContext.get(MdcKeys.SERVICE)); + ``` + +* **Granular clearing only.** + Never clear the entire MDC context. + Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. + ```java + // Bad: Risk clearing useful context entries from other components + MDC.clear(); + + // Good: Clear only your own entries, centralized in utility class + class RequestLogContext { + //... + static void clear(){ + MDC.remove(MdcKeys.REQUEST_ID); + MDC.remove(MdcKeys.SERVICE); + } + } + ``` * **Responsibility and ownership.** The component or class that sets MDC context values is also responsible for clearing them. 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 1cd42e86c..07246ced4 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 @@ -116,7 +116,7 @@ public List executeTools() { 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); + 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/OpenAiTool.java b/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiTool.java index f37751183..af14b1be5 100644 --- a/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiTool.java +++ b/foundation-models/openai/src/main/java/com/sap/ai/sdk/foundationmodels/openai/OpenAiTool.java @@ -193,7 +193,7 @@ private static Map executeInternal( if (toolCall instanceof OpenAiFunctionCall functionCall) { final var tool = toolMap.get(functionCall.getName()); if (tool == null) { - log.warn("Tool not found for function call: {}", functionCall.getName()); + log.warn("Tool not found for function call: {}.", functionCall.getName()); continue; } final var toolResult = executeFunction(tool, functionCall); 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 280bbee7c..3d6784018 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 @@ -71,7 +71,7 @@ public ChatResponse call(@Nonnull final Prompt prompt) { 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); + 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."); @@ -219,7 +219,7 @@ private static List extractTools(final ToolCallingChatOption val tool = new ChatCompletionTool().type(toolType).function(toolFunction); tools.add(tool); } catch (JsonProcessingException e) { - log.warn("Failed to add tool to the chat request: {}", e.getMessage()); + log.warn("Failed to add tool to the chat request: {}.", e.getMessage()); } } return tools; 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 ababae33c..44310e005 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 @@ -77,7 +77,7 @@ public ChatResponse call(@Nonnull final Prompt prompt) { 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); + log.debug("Executing {} tool call(s) - {}.", tools.size(), toolsStr); } val toolExecutionResult = toolCallingManager.executeToolCalls(prompt, response); From 2add86350bf4a26ba60983308345fdd1837f7c06 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal <36329474+rpanackal@users.noreply.github.com> Date: Tue, 11 Nov 2025 11:04:16 +0100 Subject: [PATCH 07/12] Apply suggestions from code review content improvment Co-authored-by: Jonas-Isr --- docs/adrs/006-logging-strategy.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index fcc72fd37..96ffb8468 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -8,7 +8,7 @@ Accepted The AI SDK identified some challenges with debugging and problem resolution that can be addressed with better logging. Typically, users have to enable wire logs for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated ones. -Additionally, we identified the need to improve visibility into application progress to the user. +Additionally, we identified the need to improve visibility into the application progress to the user. Key drivers for this decision include: @@ -28,7 +28,7 @@ This approach mandates descriptive, human-readable logs with structured request - **Do not log sensitive information.** Never log full request or response bodies. - Ensure that personally identifiable or confidential data—such as names, IDs, tokens, or payload content—is always excluded from logs. + Ensure that personally identifiable or confidential data — such as names, IDs, tokens, or payload content — is always excluded from logs. - **Write concise and relevant logs.** Every log must convey meaningful information. From a055cdb81fb0456c9b7fdd7da27bb4bafe166c26 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Tue, 11 Nov 2025 14:48:10 +0100 Subject: [PATCH 08/12] Include review suggestion - add formatting rules - caution MDC use on thread switch - logging framework information - clarify what "request" means --- .../ai/sdk/core/common/RequestLogContext.java | 20 +++--- .../common/IterableStreamConverterTest.java | 2 +- docs/adrs/006-logging-strategy.md | 62 ++++++++++++++----- 3 files changed, 57 insertions(+), 27 deletions(-) diff --git a/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java b/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java index 19d218dc3..ddedf1f8f 100644 --- a/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java +++ b/core/src/main/java/com/sap/ai/sdk/core/common/RequestLogContext.java @@ -23,8 +23,8 @@ @Beta public class RequestLogContext { - private static void setRequestId(@Nonnull final String requestId) { - MDC.put(MdcKeys.REQUEST_ID, requestId); + private static void setCallId(@Nonnull final String callId) { + MDC.put(MdcKeys.CALL_ID, callId); } /** @@ -65,7 +65,7 @@ public static void setService(@Nonnull final Service service) { /** Clear all MDC request context information. */ public static void clear() { - MDC.remove(MdcKeys.REQUEST_ID); + MDC.remove(MdcKeys.CALL_ID); MDC.remove(MdcKeys.ENDPOINT); MDC.remove(MdcKeys.DESTINATION); MDC.remove(MdcKeys.MODE); @@ -74,13 +74,13 @@ public static void clear() { /** Log the start of a request with generated request ID. */ public static void logRequestStart() { - val reqId = UUID.randomUUID().toString().substring(0, 8); - RequestLogContext.setRequestId(reqId); + val callId = UUID.randomUUID().toString().substring(0, 8); + RequestLogContext.setCallId(callId); - val message = "[reqId={}] Starting {} {} request to {}, destination={}."; + val message = "[callId={}] Starting {} {} request to {}, destination={}."; log.debug( message, - reqId, + callId, MDC.get(MdcKeys.SERVICE), MDC.get(MdcKeys.MODE), MDC.get(MdcKeys.ENDPOINT), @@ -105,13 +105,13 @@ public static void logResponseSuccess(@Nonnull final ClassicHttpResponse respons .filter(length -> length >= 0) .map(length -> "%.1fKB".formatted(length / 1024.0)) .orElse("unknown"); - val message = "[reqId={}] {} request completed successfully with duration={}, size={}."; - log.debug(message, MDC.get(MdcKeys.REQUEST_ID), MDC.get(MdcKeys.SERVICE), duration, sizeInfo); + val message = "[callId={}] {} request completed successfully with duration={}, size={}."; + log.debug(message, MDC.get(MdcKeys.CALL_ID), MDC.get(MdcKeys.SERVICE), duration, sizeInfo); } @UtilityClass private static class MdcKeys { - private static final String REQUEST_ID = "reqId"; + private static final String CALL_ID = "callId"; private static final String ENDPOINT = "endpoint"; private static final String DESTINATION = "destination"; private static final String MODE = "mode"; diff --git a/core/src/test/java/com/sap/ai/sdk/core/common/IterableStreamConverterTest.java b/core/src/test/java/com/sap/ai/sdk/core/common/IterableStreamConverterTest.java index 3823849d2..31d4dba0a 100644 --- a/core/src/test/java/com/sap/ai/sdk/core/common/IterableStreamConverterTest.java +++ b/core/src/test/java/com/sap/ai/sdk/core/common/IterableStreamConverterTest.java @@ -106,7 +106,7 @@ void testLinesThrows() { final var sut = IterableStreamConverter.lines(response, new TestClientExceptionFactory()); assertThatThrownBy(sut::count) .isInstanceOf(TestClientException.class) - .hasMessage("Parsing response content was interrupted") + .hasMessage("Parsing response content was interrupted.") .cause() .isInstanceOf(IOException.class) .hasMessage("Ups!"); diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 1f6e5b11e..528c9a283 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -21,34 +21,42 @@ Key drivers for this decision include: We will implement and enforce comprehensive logging guidelines that prioritize **debugging capability** and **user visibility**. This approach mandates descriptive, human-readable logs with structured request tracking through Mapped Diagnostic Context (MDC). +The SDK uses SLF4J API for all logging statements. ## Guidelines ### 1. Log Content and Security -- **Do not log sensitive information.** +* **Do not log sensitive information.** Never log full request or response bodies. Ensure that personally identifiable or confidential data — such as names, IDs, tokens, or payload content — is always excluded from logs. -- **Write concise and relevant logs.** +* **Write concise and relevant logs.** Every log must convey meaningful information. Avoid verbose, repetitive, or purely cosmetic details. -- **Use descriptive, human-readable formats.** - Logs must be clear enough for a developer to understand what happened without checking the code. - Use the `metric=value` pattern to include structured details with extensibility in mind. +* **Use descriptive, human-readable and standard formats.** + - Logs must be clear enough for a developer to understand what happened without checking the code. + - Start log messages with a capital letter (exceptions include case-sensitive identifiers) and end with a period (`.`). + - Avoid newlines (`\n`) and emojis within log messages to prevent parsing and encoding concerns. + - Use the `metric=value` pattern to include structured details with extensibility in mind. - ```[reqId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, responseSize=1.2KB.``` + ``` + [callId=e3eaa45c] OpenAI request completed successfully with duration=1628ms, responseSize=1.2KB. + ``` * **Correlate logs.** - Include a request identifier (e.g., `reqId`) in per-request logs to assist with correlation and debugging. - In this SDK, a "request" represents a single AI service operation (e.g., one chat completion call, one embedding generation). - The `reqId` is generated for each AI service call and is distinct from any HTTP request tracking in user's application framework. + Include a call identifier (e.g., `callId`) in outgoing per-request logs to assist with correlation and debugging. + Throughout this document, the term 'request' refers to a single SDK operation that calls an AI service (e.g., `OrchestrationClient.chatCompletion()`, `OpenAiClient.embed()`), distinct from HTTP requests to the user's application. * **Exception logging.** When logging exceptions, use standard logging methods (e.g., `log.error("Operation failed", exception)`) rather than serializing exception objects. Exception objects may contain custom fields with sensitive data that could be exposed through JSON serialization or custom `toString()` implementations. +* **Logging framework** + Write all logging statements against the SLF4J API. + The AI SDK relies on `logback-classic` as the provided runtime implementation. + --- ### 2. Log Levels and Scope @@ -69,10 +77,12 @@ This approach mandates descriptive, human-readable logs with structured request Do not rely solely on response-time logging — requests may fail, hang, or take long durations. This approach also avoids the need for stack-trace investigation when surface error responses are ambiguous. - ```[reqId=e3eaa45c] Starting OpenAI synchronous request to /v1/chat/completions, destination=.``` + ``` + [callId=e3eaa45c] Starting OpenAI synchronous request to /v1/chat/completions, destination=. + ``` * **Performance-aware logging.** - If a log statement requires any object creation, guard it with a log-level check to prevent performance degradation. + If a log statement requires computation (such as object creation or method invocation), guard it with a log-level check to prevent performance degradation. ``` java Optional maybeDestination; @@ -84,7 +94,7 @@ This approach mandates descriptive, human-readable logs with structured request log.debug("Destination: {}", maybeDestination.orElseGet(this::getFallback)); log.debug("Destination: {}", maybeDestination.orElse(getFallback())); - // Good: No object creation or method invocation + // Good: No additional computation log.debug("Destination: {}", maybeDestination); log.debug("Destination: {}", maybeDestination.orElse(fallbackDestination)); @@ -103,11 +113,11 @@ This approach mandates descriptive, human-readable logs with structured request ### 3. MDC (Mapped Diagnostic Context) * **Purpose and usage.** - MDC is used to carry contextual information (e.g., `reqId`, `endpoint`, `service`) across execution blocks within the same thread. + MDC is used to carry contextual information (e.g., `callId`, `endpoint`, `service`) across execution blocks within the same thread. * **Setting and clearing context.** Set MDC values deliberately and close to their scope of relevance. - Per-request MDC context must be cleared when the response completes. + Per-request MDC context must be cleared appropriately when the response completes. Avoid setting per-request values in long-lived objects that outlive the request lifecycle, as this can result in corrupted or incomplete log context. * **Centralized MDC management.** @@ -124,7 +134,7 @@ This approach mandates descriptive, human-readable logs with structured request ``` * **Granular clearing only.** - Never clear the entire MDC context. + Never clear the entire MDC context, as this will remove entries set by the application developer or other libraries. Instead, remove entries key-by-key to preserve unrelated context items that may remain valid for longer periods. ```java // Bad: Risk clearing useful context entries from other components @@ -134,7 +144,7 @@ This approach mandates descriptive, human-readable logs with structured request class RequestLogContext { //... static void clear(){ - MDC.remove(MdcKeys.REQUEST_ID); + MDC.remove(MdcKeys.CALL_ID); MDC.remove(MdcKeys.SERVICE); } } @@ -144,6 +154,26 @@ This approach mandates descriptive, human-readable logs with structured request The component or class that sets MDC context values is also responsible for clearing them. This maintains clarity and ensures proper lifecycle management. +* **Safe consumption.** + Since MDC uses `ThreadLocal` storage, any new thread (created implicitly or explicitly) will not have access to the parent thread's MDC context. + Always audit for possible thread switches that may lead to corrupted logs due to invalid MDC. + Below is an example contrasting safe usage (logging in the calling thread) with unsafe usage (logging in callbacks): + + ```java + // Thread A + RequestLogContext.setCallId("abc123"); + log.debug("[callId={}] Starting request", RequestLogContext.get(MdcKeys.CALL_ID)); + + // Bad: Logging within callbacks executed in other threads + client.executeAsync(() -> { + // Thread B: RequestLogContext.get(MdcKeys.CALL_ID) is null + log.debug("[callId={}] Processing", RequestLogContext.get(MdcKeys.CALL_ID)); + }); + + // Good: Thread A's context has been restored + log.debug("[callId={}] Completed request", RequestLogContext.get(MdcKeys.CALL_ID)); + ``` + --- ### 4. Logging Boundaries and Generation From cc51a554cea59d85f5edadb70bb882a53d35fda0 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Tue, 11 Nov 2025 14:54:07 +0100 Subject: [PATCH 09/12] fix test --- .../com/sap/ai/sdk/core/common/RequestLogContextTest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/src/test/java/com/sap/ai/sdk/core/common/RequestLogContextTest.java b/core/src/test/java/com/sap/ai/sdk/core/common/RequestLogContextTest.java index 2d792c42e..dca093cb9 100644 --- a/core/src/test/java/com/sap/ai/sdk/core/common/RequestLogContextTest.java +++ b/core/src/test/java/com/sap/ai/sdk/core/common/RequestLogContextTest.java @@ -25,14 +25,14 @@ void testRequestLogContextLifecycle() { assertThat(MDC.get("destination")).isEqualTo("http://localhost:8000"); RequestLogContext.logRequestStart(); - assertThat(MDC.get("reqId")).isNotNull().hasSize(8); + assertThat(MDC.get("callId")).isNotNull().hasSize(8); RequestLogContext.clear(); assertThat(MDC.get("service")).isNull(); assertThat(MDC.get("mode")).isNull(); assertThat(MDC.get("endpoint")).isNull(); assertThat(MDC.get("destination")).isNull(); - assertThat(MDC.get("reqId")).isNull(); + assertThat(MDC.get("callId")).isNull(); assertThat(MDC.get("consumer-key")).isEqualTo("consumer-value"); } } From 1f624eb9c938185ba1f1b979498ffd8ae902128a Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 17 Nov 2025 13:19:02 +0100 Subject: [PATCH 10/12] clarify MDC context propagation --- docs/adrs/006-logging-strategy.md | 25 +++++++++++++++++-------- 1 file changed, 17 insertions(+), 8 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 528c9a283..29f8c46e2 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -50,7 +50,7 @@ The SDK uses SLF4J API for all logging statements. Throughout this document, the term 'request' refers to a single SDK operation that calls an AI service (e.g., `OrchestrationClient.chatCompletion()`, `OpenAiClient.embed()`), distinct from HTTP requests to the user's application. * **Exception logging.** - When logging exceptions, use standard logging methods (e.g., `log.error("Operation failed", exception)`) rather than serializing exception objects. + When logging exceptions, use standard logging methods (e.g., `log.debug("Connection lost.", exception)`) rather than serializing exception objects. Exception objects may contain custom fields with sensitive data that could be exposed through JSON serialization or custom `toString()` implementations. * **Logging framework** @@ -156,24 +156,33 @@ The SDK uses SLF4J API for all logging statements. * **Safe consumption.** Since MDC uses `ThreadLocal` storage, any new thread (created implicitly or explicitly) will not have access to the parent thread's MDC context. - Always audit for possible thread switches that may lead to corrupted logs due to invalid MDC. - Below is an example contrasting safe usage (logging in the calling thread) with unsafe usage (logging in callbacks): + Always audit for thread switches through async operations, resilience patterns etc., as these may lead to corrupted logs due to invalid MDC. ```java // Thread A RequestLogContext.setCallId("abc123"); log.debug("[callId={}] Starting request", RequestLogContext.get(MdcKeys.CALL_ID)); - // Bad: Logging within callbacks executed in other threads + // Problem: Async callback runs in Thread B without original MDC context client.executeAsync(() -> { - // Thread B: RequestLogContext.get(MdcKeys.CALL_ID) is null + // Thread B: RequestLogContext.get(MdcKeys.CALL_ID) returns null log.debug("[callId={}] Processing", RequestLogContext.get(MdcKeys.CALL_ID)); }); - - // Good: Thread A's context has been restored - log.debug("[callId={}] Completed request", RequestLogContext.get(MdcKeys.CALL_ID)); ``` + To maintain logging context across thread boundaries, manually propagate the MDC context: + + ```java + // Capture parent thread's MDC context + Map context = MDC.getCopyOfContextMap(); + + client.executeAsync(() -> { + // Restore the captured context in new thread + MDC.setContextMap(context); + // Thread B: RequestLogContext.get(MdcKeys.CALL_ID) returns abc123 + log.debug("[callId={}] Processing", RequestLogContext.get(MdcKeys.CALL_ID)); + }); + ``` --- ### 4. Logging Boundaries and Generation From 3c7569a10de17987fb0f9ae681eabe8e84dc60bc Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal Date: Mon, 24 Nov 2025 16:00:15 +0100 Subject: [PATCH 11/12] remove MDC consumption example --- docs/adrs/006-logging-strategy.md | 16 ++-------------- 1 file changed, 2 insertions(+), 14 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 29f8c46e2..30647f424 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -156,7 +156,6 @@ The SDK uses SLF4J API for all logging statements. * **Safe consumption.** Since MDC uses `ThreadLocal` storage, any new thread (created implicitly or explicitly) will not have access to the parent thread's MDC context. - Always audit for thread switches through async operations, resilience patterns etc., as these may lead to corrupted logs due to invalid MDC. ```java // Thread A @@ -169,20 +168,9 @@ The SDK uses SLF4J API for all logging statements. log.debug("[callId={}] Processing", RequestLogContext.get(MdcKeys.CALL_ID)); }); ``` + Be vigilant about thread switches through async operations and resilience patterns, as you may have to manually propagate MDC context to maintain logging continuity. + Refer to the following resource for more information on [MDC handling with thread pools](https://stackoverflow.com/questions/6073019/how-to-use-mdc-with-thread-pools). - To maintain logging context across thread boundaries, manually propagate the MDC context: - - ```java - // Capture parent thread's MDC context - Map context = MDC.getCopyOfContextMap(); - - client.executeAsync(() -> { - // Restore the captured context in new thread - MDC.setContextMap(context); - // Thread B: RequestLogContext.get(MdcKeys.CALL_ID) returns abc123 - log.debug("[callId={}] Processing", RequestLogContext.get(MdcKeys.CALL_ID)); - }); - ``` --- ### 4. Logging Boundaries and Generation From c37e665d29ae20ee215361fc0ed7a69ec2b4ddf1 Mon Sep 17 00:00:00 2001 From: Roshin Rajan Panackal <36329474+rpanackal@users.noreply.github.com> Date: Mon, 24 Nov 2025 16:06:28 +0100 Subject: [PATCH 12/12] Apply suggestion from @Jonas-Isr Co-authored-by: Jonas-Isr --- docs/adrs/006-logging-strategy.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/adrs/006-logging-strategy.md b/docs/adrs/006-logging-strategy.md index 30647f424..21ee7868d 100644 --- a/docs/adrs/006-logging-strategy.md +++ b/docs/adrs/006-logging-strategy.md @@ -7,8 +7,8 @@ Accepted ## Context The AI SDK identified some challenges with debugging and problem resolution that can be addressed with better logging. -Typically, users have to enable wire logs for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated ones. -Additionally, we identified the need to improve visibility into the application progress to the user. +Typically, users have to enable wire logs for troubleshooting which, along with helpful logs, surfaces a large volume of unrelated noise. +Additionally, we identified the need to improve visibility into the application progress for the user. Key drivers for this decision include: