Skip to content

refactor(llm): enhance RAG and LLM debug logging for observability #3073

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
marevol merged 1 commit into from
Mar 15, 2026
Merged

refactor(llm): enhance RAG and LLM debug logging for observability #3073

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 5 additions & 2 deletions src/main/java/org/codelibs/fess/chat/ChatClient.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -443,6 +443,8 @@ public ChatResult streamChatEnhanced(final String sessionId, final String userMe
searchRequestedTime = querySearchResult.getRequestedTime();
callback.onPhaseComplete(ChatPhaseCallback.PHASE_SEARCH);

logger.info("[RAG] Search completed. query={}, resultCount={}, elapsedTime={}ms", query, searchResults.size(),
System.currentTimeMillis() - phaseStartTime);
if (logger.isDebugEnabled()) {
logger.debug("[RAG] Phase {} completed. query={}, resultCount={}, phaseElapsedTime={}ms",
ChatPhaseCallback.PHASE_SEARCH, query, searchResults.size(), System.currentTimeMillis() - phaseStartTime);
Expand Down Expand Up @@ -542,8 +544,9 @@ public ChatResult streamChatEnhanced(final String sessionId, final String userMe

session.addMessage(assistantMessage);

logger.info("[RAG] Enhanced chat completed. sessionId={}, intent={}, sourcesCount={}, responseLength={}, elapsedTime={}ms",
session.getSessionId(), intentResult.getIntent(), sources.size(), fullResponse.length(),
logger.info(
"[RAG] Enhanced chat completed. sessionId={}, userId={}, intent={}, sourcesCount={}, responseLength={}, elapsedTime={}ms",
session.getSessionId(), userId, intentResult.getIntent(), sources.size(), fullResponse.length(),
System.currentTimeMillis() - startTime);

return new ChatResult(session.getSessionId(), assistantMessage, sources);
Expand Down
24 changes: 24 additions & 0 deletions src/main/java/org/codelibs/fess/llm/AbstractLlmClient.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -401,6 +401,10 @@ protected LlmChatResponse chatWithConcurrencyControl(final LlmChatRequest reques
if (concurrencyLimiter == null) {
return chat(request);
}
if (logger.isDebugEnabled()) {
logger.debug("[LLM] Acquiring concurrency permit. name={}, availablePermits={}, maxConcurrent={}", getName(),
concurrencyLimiter.availablePermits(), getMaxConcurrentRequests());
}
try {
if (!concurrencyLimiter.tryAcquire(getConcurrencyWaitTimeoutMs(), TimeUnit.MILLISECONDS)) {
logger.warn("[LLM] Concurrency limit exceeded. name={}, maxConcurrent={}, waitTimeout={}ms", getName(),
Expand Down Expand Up @@ -431,6 +435,10 @@ protected void streamChatWithConcurrencyControl(final LlmChatRequest request, fi
streamChat(request, callback);
return;
}
if (logger.isDebugEnabled()) {
logger.debug("[LLM] Acquiring concurrency permit. name={}, availablePermits={}, maxConcurrent={}", getName(),
concurrencyLimiter.availablePermits(), getMaxConcurrentRequests());
}
try {
if (!concurrencyLimiter.tryAcquire(getConcurrencyWaitTimeoutMs(), TimeUnit.MILLISECONDS)) {
logger.warn("[LLM] Concurrency limit exceeded. name={}, maxConcurrent={}, waitTimeout={}ms", getName(),
Expand Down Expand Up @@ -550,6 +558,10 @@ public IntentDetectionResult detectIntent(final String userMessage) {
applyPromptTypeParams(request, "intent");

final LlmChatResponse response = chatWithConcurrencyControl(request);
if (logger.isDebugEnabled()) {
logger.debug("[RAG:INTENT] LLM response. promptTokens={}, completionTokens={}, totalTokens={}, finishReason={}",
response.getPromptTokens(), response.getCompletionTokens(), response.getTotalTokens(), response.getFinishReason());
}
if (isEmptyContentWithLengthFinish(response)) {
logger.warn(
"[RAG:INTENT] Empty content with finish_reason=length detected (possible reasoning model token exhaustion). Falling back to search. userMessage={}",
Expand Down Expand Up @@ -593,6 +605,10 @@ public IntentDetectionResult detectIntent(final String userMessage, final List<L
applyPromptTypeParams(request, "intent");

final LlmChatResponse response = chatWithConcurrencyControl(request);
if (logger.isDebugEnabled()) {
logger.debug("[RAG:INTENT] LLM response. promptTokens={}, completionTokens={}, totalTokens={}, finishReason={}",
response.getPromptTokens(), response.getCompletionTokens(), response.getTotalTokens(), response.getFinishReason());
}
if (isEmptyContentWithLengthFinish(response)) {
logger.warn(
"[RAG:INTENT] Empty content with finish_reason=length detected (possible reasoning model token exhaustion). Falling back to search. userMessage={}",
Expand Down Expand Up @@ -641,6 +657,10 @@ public RelevanceEvaluationResult evaluateResults(final String userMessage, final
applyPromptTypeParams(request, "evaluation");

final LlmChatResponse response = chatWithConcurrencyControl(request);
if (logger.isDebugEnabled()) {
logger.debug("[RAG:EVAL] LLM response. promptTokens={}, completionTokens={}, totalTokens={}, finishReason={}",
response.getPromptTokens(), response.getCompletionTokens(), response.getTotalTokens(), response.getFinishReason());
}
if (isEmptyContentWithLengthFinish(response)) {
logger.warn(
"[RAG:EVAL] Empty content with finish_reason=length detected (possible reasoning model token exhaustion). Falling back to all relevant. userMessage={}",
Expand Down Expand Up @@ -1120,6 +1140,10 @@ protected void addHistoryWithBudget(final LlmChatRequest request, final List<Llm
for (int i = startIndex; i < history.size(); i++) {
request.addMessage(history.get(i));
}
if (logger.isDebugEnabled()) {
logger.debug("[RAG:ANSWER] History included. totalHistory={}, includedCount={}, startIndex={}, usedChars={}, budgetChars={}",
history.size(), history.size() - startIndex, startIndex, budgetChars - remaining, budgetChars);
}
}

// --- JSON parsing utilities ---
Expand Down
6 changes: 2 additions & 4 deletions src/main/java/org/codelibs/fess/llm/LlmClientManager.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -163,8 +163,7 @@ public LlmChatResponse chat(final LlmChatRequest request) {
}
final LlmChatResponse response = client.chat(request);
if (logger.isDebugEnabled()) {
logger.debug("[LLM] LLM chat request completed. llmType={}, contentLength={}, elapsedTime={}ms", llmType,
response.getContent() != null ? response.getContent().length() : 0, System.currentTimeMillis() - startTime);
logger.debug("[LLM] LLM chat request completed. llmType={}", llmType);
}
return response;
} catch (final LlmException e) {
Expand Down Expand Up @@ -201,8 +200,7 @@ public void streamChat(final LlmChatRequest request, final LlmStreamCallback cal
}
client.streamChat(request, callback);
if (logger.isDebugEnabled()) {
logger.debug("[LLM] LLM streaming chat request completed. llmType={}, elapsedTime={}ms", llmType,
System.currentTimeMillis() - startTime);
logger.debug("[LLM] LLM streaming chat request completed. llmType={}", llmType);
}
} catch (final LlmException e) {
logger.warn("[LLM] Stream chat request failed. llmType={}, error={}, elapsedTime={}ms", llmType, e.getMessage(),
Expand Down
Loading