# AI 调用中间过程日志记录方案 > 解决"日志只能看到用户发起的请求与最终返回，看不到中间 RAG 检索与 Tool 调用过程"的可观测性问题。 ## 1. 问题背景项目使用自定义 `MyLoggerAdvisor`（实现 `CallAdvisor` + `StreamAdvisor`）记录对话日志，但实际运行发现： - ✅ 能看到：用户发起的信息（`Ai Request`） - ✅ 能看到：模型最终返回（`Ai Response`） - ❌ 看不到：中间 RAG 检索的查询文本、命中文档 - ❌ 看不到：中间 Tool 调用的入参、执行结果、耗时 ## 2. 根因分析 | 环节 | 发生位置 | 为何日志不可见 | | --- | --- | --- | | RAG 检索 | `QuestionAnswerAdvisor.before()` 内部 | Advisor 链只记录外层请求/响应，检索发生在顾问内部，`MyLoggerAdvisor` 无法感知 | | 云端检索 | `RetrievalAugmentationAdvisor` 内部 | 同上，检索逻辑被封装在顾问内部 | | Tool 调用循环 | `DefaultChatClient` 内部（`toolCallingManager` 执行循环） | 工具循环在 Advisor 链之外执行，根本不进入 Advisor 拦截点 | 结论：**Advisor 拦截点天然覆盖不到"请求与响应之间的中间过程"**，需要另寻挂载点。 ## 3. 方案对比与选型 | 方案 | 思路 | 优点 | 缺点 | | --- | --- | --- | --- | | A. 装饰器模式 | 包装 `ToolCallback` / `VectorStore` / `DocumentRetriever`，转发前后打日志 | 不改核心逻辑、零侵入、可观测点精准 | 需手动接线（3 处） | | B. Micrometer Observation | 注册 ObservationHandler 监听 AI 调用事件 | 官方机制、覆盖全 | 只能看到模型调用级别事件，仍看不到工具入参/检索命中等细节 | | C. Debug 日志开关 | 打开 Spring AI 内部 debug 日志 | 零代码 | 日志量爆炸、格式不可控、易淹没关键信息 | **选型结论：方案 A（装饰器模式）** —— 在不改变原有逻辑的前提下，把三个关键组件各包一层"日志外衣"，精确输出中间过程。 ## 4. 实现方案：装饰器模式 ### 4.1 日志链路总览 ``` MyLoggerAdvisor（外层请求/响应） │ ├── QuestionAnswerAdvisor（本地 RAG） │ └── LoggingVectorStore ──► PgVectorStore （[向量检索] 查询/命中/耗时） │ ├── RetrievalAugmentationAdvisor（云端 RAG） │ └── LoggingDocumentRetriever ──► DashScopeDocumentRetriever （[云端检索] 查询/命中/耗时） │ └── Tool 调用循环（ChatClient 内部） └── LoggingToolCallback ──► 原始 ToolCallback （[Tool调用] 入参/结果/耗时） ``` ### 4.2 装饰器一：LoggingToolCallback（工具调用日志） **文件**：`src/main/java/com/xiaokai/kimoaiagent/tools/LoggingToolCallback.java` 实现 `ToolCallback` 接口，转发全部方法，仅在核心的 `call()` 前后记录日志： - 调用前：`[Tool调用] 工具: {}, 入参: {}` - 成功后：`[Tool调用] 工具: {}, 执行成功, 耗时: {}ms, 结果: {}` - 失败后：`[Tool调用] 工具: {}, 执行失败, 耗时: {}ms, 错误: {}`（记录后继续抛出） ```java @Slf4j public class LoggingToolCallback implements ToolCallback { /** 被包装的原始工具回调，负责实际执行工具逻辑 */ private final ToolCallback delegate; public LoggingToolCallback(ToolCallback delegate) { this.delegate = delegate; } @Override public ToolDefinition getToolDefinition() { return delegate.getToolDefinition(); } @Override public ToolMetadata getToolMetadata() { return delegate.getToolMetadata(); } @Override public String call(String toolInput) { return this.call(toolInput, null); } @Override public String call(String toolInput, ToolContext toolContext) { String toolName = delegate.getToolDefinition().name(); long startTime = System.currentTimeMillis(); // 记录工具调用开始信息 log.info("[Tool调用] 工具: {}, 入参: {}", toolName, toolInput); try { // 根据是否携带上下文选择对应的执行入口 String result = (toolContext == null) ? delegate.call(toolInput) : delegate.call(toolInput, toolContext); // 记录工具调用成功信息及耗时 log.info("[Tool调用] 工具: {}, 执行成功, 耗时: {}ms, 结果: {}", toolName, System.currentTimeMillis() - startTime, result); return result; } catch (Exception e) { // 记录工具调用失败信息及耗时 log.error("[Tool调用] 工具: {}, 执行失败, 耗时: {}ms, 错误: {}", toolName, System.currentTimeMillis() - startTime, e.getMessage(), e); throw e; } } } ``` ### 4.3 装饰器二：LoggingVectorStore（本地向量库日志） **文件**：`src/main/java/com/xiaokai/kimoaiagent/rag/LoggingVectorStore.java` 实现 `VectorStore` 接口，覆盖全部操作： - `add`：`[向量库] 写入文档: {} 篇, 耗时: {}ms` - `delete(List)`：`[向量库] 按ID删除文档: {} 篇, 耗时: {}ms` - `delete(Expression)`：`[向量库] 按过滤条件删除文档, 过滤条件: {}, 耗时: {}ms` - `similaritySearch`：`[向量检索] 查询: {}, topK: {}, 阈值: {}, 命中: {} 篇, 耗时: {}ms` + 逐条输出命中文档 `id/score/内容摘要` ```java @Slf4j public class LoggingVectorStore implements VectorStore { /** 被包装的原始向量存储，负责实际执行文档读写与检索 */ private final VectorStore delegate; public LoggingVectorStore(VectorStore delegate) { this.delegate = delegate; } @Override public void add(List documents) { long startTime = System.currentTimeMillis(); delegate.add(documents); // 记录文档写入数量与耗时 log.info("[向量库] 写入文档: {} 篇, 耗时: {}ms", documents.size(), System.currentTimeMillis() - startTime); } @Override public void delete(List idList) { long startTime = System.currentTimeMillis(); delegate.delete(idList); // 记录文档删除数量与耗时 log.info("[向量库] 按ID删除文档: {} 篇, 耗时: {}ms", idList.size(), System.currentTimeMillis() - startTime); } @Override public void delete(Filter.Expression filterExpression) { long startTime = System.currentTimeMillis(); delegate.delete(filterExpression); // 记录过滤删除操作与耗时 log.info("[向量库] 按过滤条件删除文档, 过滤条件: {}, 耗时: {}ms", filterExpression, System.currentTimeMillis() - startTime); } @Override public List similaritySearch(SearchRequest request) { long startTime = System.currentTimeMillis(); List documents = delegate.similaritySearch(request); // 记录检索请求与命中数量 log.info("[向量检索] 查询: {}, topK: {}, 阈值: {}, 命中: {} 篇, 耗时: {}ms", request.getQuery(), request.getTopK(), request.getSimilarityThreshold(), documents.size(), System.currentTimeMillis() - startTime); // 逐条输出命中文档的 ID、相似度分数与内容摘要 for (Document document : documents) { log.info("[向量检索] 命中文档 - id: {}, score: {}, 内容: {}", document.getId(), document.getScore(), truncate(document.getText(), 200)); } return documents; } /** * 截断长文本，保留前指定长度的字符用于日志输出 */ private String truncate(String text, int maxLength) { if (text == null || text.length() <= maxLength) { return text; } return text.substring(0, maxLength) + "..."; } } ``` ### 4.4 装饰器三：LoggingDocumentRetriever（云端检索日志） **文件**：`src/main/java/com/xiaokai/kimoaiagent/rag/LoggingDocumentRetriever.java` 实现 `DocumentRetriever` 接口（`Function>` 的语义接口），仅包装核心 `retrieve()`： - `[云端检索] 查询: {}, 命中: {} 篇, 耗时: {}ms` - 逐条输出命中文档 `id/内容摘要` ```java @Slf4j public class LoggingDocumentRetriever implements DocumentRetriever { /** 被包装的原始文档检索器，负责实际执行检索逻辑 */ private final DocumentRetriever delegate; public LoggingDocumentRetriever(DocumentRetriever delegate) { this.delegate = delegate; } @Override public List retrieve(Query query) { long startTime = System.currentTimeMillis(); List documents = delegate.retrieve(query); // 记录检索查询与命中数量 log.info("[云端检索] 查询: {}, 命中: {} 篇, 耗时: {}ms", query.text(), documents.size(), System.currentTimeMillis() - startTime); // 逐条输出命中文档的 ID 与内容摘要 for (Document document : documents) { log.info("[云端检索] 命中文档 - id: {}, 内容: {}", document.getId(), truncate(document.getText(), 200)); } return documents; } /** 截断长文本，保留前指定长度的字符用于日志输出 */ private String truncate(String text, int maxLength) { if (text == null || text.length() <= maxLength) { return text; } return text.substring(0, maxLength) + "..."; } } ``` ### 4.5 接线配置（三处） **① 工具回调接线** —— `src/test/java/com/xiaokai/kimoaiagent/tools/ToolRegistration.java` 在 `allTools()` 中，将 `ToolCallbacks.from(...)` 生成的数组整体包装为 `LoggingToolCallback`： ```java // 将工具实例统一包装为 ToolCallback 数组 ToolCallback[] toolCallbacks = ToolCallbacks.from( fileOperationTool, webSearchTool, webScrapingTool, resourceDownloadTool, terminalOperationTool, pdfGenerationTool ); // 使用日志装饰器包装全部工具回调，记录每次工具调用的入参与执行结果 return Arrays.stream(toolCallbacks) .map(LoggingToolCallback::new) .toArray(ToolCallback[]::new); ``` > 注意：此配置类位于 `src/test/java` 目录，是当前测试链路中的工具注册中心。 **② 本地向量库接线** —— `src/main/java/com/xiaokai/kimoaiagent/rag/PgVectorVectorStoreConfig.java` 先构建 `PgVectorStore`，再包一层 `LoggingVectorStore` 返回： ```java @Bean public VectorStore pgVectorVectorStore(@Qualifier("pgJdbcTemplate") JdbcTemplate pgJdbcTemplate, EmbeddingModel dashscopeEmbeddingModel) { // 构建向量存储：1024 维向量 + 余弦距离 + HNSW 索引，并自动初始化 schema 与向量表 PgVectorStore pgVectorStore = PgVectorStore.builder(pgJdbcTemplate, dashscopeEmbeddingModel) .dimensions(1024) .distanceType(PgVectorStore.PgDistanceType.COSINE_DISTANCE) .indexType(PgVectorStore.PgIndexType.HNSW) .initializeSchema(true) .schemaName("public") .vectorTableName("vector_store") .maxDocumentBatchSize(10000) .build(); // 使用日志装饰器包装向量存储，记录文档写入与相似度检索过程 return new LoggingVectorStore(pgVectorStore); } ``` **③ 云端检索接线** —— `src/main/java/com/xiaokai/kimoaiagent/rag/LoveAppRagCloudAdvisorConfig.java` 构建 `DashScopeDocumentRetriever` 时套上 `LoggingDocumentRetriever`： ```java // 构建文档检索器：基于 DashScope 云端知识库，按索引名绑定恋爱大师知识库 DocumentRetriever documentRetriever = new LoggingDocumentRetriever(new DashScopeDocumentRetriever(dashScopeApi, DashScopeDocumentRetrieverOptions.builder().withIndexName(KNOWLEDGE_INDEX).build())); ``` ## 5. 日志效果示例 ``` Ai Request: ChatClientRequest[prompt=...] ← MyLoggerAdvisor（原有） [向量检索] 查询: 婚后关系不亲密怎么办, topK: 5, 阈值: 0.0, 命中: 3 篇, 耗时: 45ms [向量检索] 命中文档 - id: 550e8400-e29b-41d4-a716-446655440000, score: 0.82, 内容: 婚后亲密关系维护建议... [云端检索] 查询: 婚后关系不亲密怎么办, 命中: 2 篇, 耗时: 210ms [云端检索] 命中文档 - id: xxx, 内容: 婚姻保鲜的心理学方法... [Tool调用] 工具: webSearchTool, 入参: {"query":"星空情侣壁纸"} [Tool调用] 工具: webSearchTool, 执行成功, 耗时: 1200ms, 结果: {...} [Tool调用] 工具: resourceDownloadTool, 入参: {"url":"https://..."} [Tool调用] 工具: resourceDownloadTool, 执行成功, 耗时: 890ms, 结果: 图片已保存至... Ai Response: ChatClientResponse[...] ← MyLoggerAdvisor（原有） ``` ## 6. 相关文件清单 | 类型 | 文件路径 | 说明 | | --- | --- | --- | | 新建 | `src/main/java/com/xiaokai/kimoaiagent/tools/LoggingToolCallback.java` | 工具调用日志装饰器 | | 新建 | `src/main/java/com/xiaokai/kimoaiagent/rag/LoggingVectorStore.java` | 本地向量库日志装饰器 | | 新建 | `src/main/java/com/xiaokai/kimoaiagent/rag/LoggingDocumentRetriever.java` | 云端检索日志装饰器 | | 修改 | `src/test/java/com/xiaokai/kimoaiagent/tools/ToolRegistration.java` | 包装全部工具回调 | | 修改 | `src/main/java/com/xiaokai/kimoaiagent/rag/PgVectorVectorStoreConfig.java` | 包装 PgVectorStore | | 修改 | `src/main/java/com/xiaokai/kimoaiagent/rag/LoveAppRagCloudAdvisorConfig.java` | 包装 DashScopeDocumentRetriever | | 未改 | `src/main/java/com/xiaokai/kimoaiagent/advisor/MyLoggerAdvisor.java` | 外层请求/响应日志（保留原样） | ## 7. 可选延伸若还想看**模型在工具循环中每一轮的完整 prompt**（比 Tool 调用日志更细一层），可再包一层 `ChatModel` 装饰器：实现 `ChatModel` 接口，包装 `DashScopeChatModel`，在 `call(Prompt)` 前后记录每轮完整请求与响应。当前方案已满足"入参/结果/耗时"级别的可观测性，是否需要更细粒度取决于后续排查需求。

如何判断字符串缓冲区是被单个线程使用还是多个线程使用？