FessのAI検索モードのログレベルを整理

FessのAI検索モード(RAG/LLM機能)では、各コンポーネントのログ出力が統一されておらず、運用時のトラブルシューティングやログ分析がしにくい状況でした。今回、ログレベルとプレフィックスを整理して、運用しやすくしました。

変更の背景

AI検索モードでは、チャットリクエストの処理、LLMクライアントの管理、意図検出、検索結果の評価など、複数のコンポーネントが連携して動作します。しかし、これまでのログ出力にはいくつかの問題がありました。

  • ログメッセージにプレフィックスが付いていないものがあり、RAG/LLM関連のログをフィルタリングしにくい
  • チャット完了時のログがdebugレベルだったため、本番環境でレイテンシやトークン使用量を把握するにはdebugログを有効にする必要があった
  • エラーログでLlmExceptionと予期しない例外が区別されていなかった
  • LLMクライアントのライフサイクルイベント(初期化・シャットダウン)がログに記録されていなかった

ログプレフィックスの統一

すべてのRAG/LLM関連のログメッセージに、以下のプレフィックスを付けるようにしました。

プレフィックス用途
[RAG]チャット処理全般(リクエスト、レスポンス、エラー)
[LLM]LLMクライアントの管理(初期化、シャットダウン、同時実行制御)
[RAG:INTENT]意図検出(ユーザーの質問の意図を判定する処理)
[RAG:EVAL]検索結果の評価(検索結果の関連性を判定する処理)

これにより、grep '[RAG]'grep '[LLM]'でログを簡単にフィルタリングできるようになりました。

ログレベルの見直し

debug → info への昇格

チャット完了時のログをdebugからinfoレベルに変更しました。これにより、本番環境でもレイテンシやソース数などの重要なメトリクスを確認できます。

[RAG] Chat completed. sessionId=xxx, sourcesCount=5, elapsedTime=1234ms
[RAG] Stream chat completed. sessionId=xxx, sourcesCount=3, elapsedTime=2345ms
[RAG] Enhanced chat completed. sessionId=xxx, intent=SEARCH, sourcesCount=5, responseLength=500, elapsedTime=3456ms

意図検出や検索結果評価の完了ログもinfoレベルで出力するようにしました。

[RAG:INTENT] Intent detected. intent=SEARCH, query=xxx, elapsedTime=500ms
[RAG:EVAL] Evaluation completed. hasRelevant=true, relevantCount=3, totalResults=10, elapsedTime=300ms

LLMクライアントのライフサイクルログの追加

LLMクライアントの初期化・シャットダウン時にinfoレベルでログを出力するようにしました。

[LLM] OpenAI initialized. model=gpt-4, timeout=30000ms, maxConcurrent=5
[LLM] OpenAI shutting down.

同時実行制限とリクエスト中断のwarnログ追加

同時実行制限の超過やリクエスト中断時にwarnレベルでログを出力するようにしました。

[LLM] Concurrency limit exceeded. name=OpenAI, maxConcurrent=5, waitTimeout=10000ms
[LLM] Request interrupted while waiting for concurrency permit. name=OpenAI

エラーログの改善

LlmExceptionと予期しない例外を区別してログ出力するようにしました。

  • LlmException: LLMサービス側の既知のエラー。スタックトレースなしでメッセージのみ出力(warnレベル)
  • 予期しない例外: プログラムのバグなど。スタックトレース付きで出力(warnレベル)
if (e instanceof LlmException) {
    logger.warn("[RAG] LLM error during chat. sessionId={}, error={}", session.getSessionId(), e.getMessage());
} else {
    logger.warn("[RAG] Unexpected error during chat. sessionId={}, error={}", session.getSessionId(), e.getMessage(), e);
}

LLMの既知のエラーではスタックトレースを省略することで、ログの可読性が向上します。

まとめ

今回の変更は、ログ出力の整理のみで動作の変更はありません。運用時に以下のメリットがあります。

  • プレフィックスベースのフィルタリングで、RAG/LLM関連のログを素早く抽出可能
  • debugログを有効にしなくても、チャット処理のレイテンシやソース数などのメトリクスを確認可能
  • LLMクライアントのライフサイクルイベントを追跡可能
  • エラーの種類に応じた適切なログ出力で、トラブルシューティングが効率化

Fessの検索ログにLLMモデル情報をアクセスタイプとして記録する 

FessのAI検索モードを利用した検索が、検索ログ上ではどのモデルで処理されたのか区別できなかった。そこで、AI検索モードのエンドポイントの検索ログにLLMモデル名をアクセスタイプとして記録するようにした。

背景

Fessの検索ログには、検索がどのインターフェースから行われたかを示す「アクセスタイプ」が記録される。従来は以下の定義済みタイプのみが使われていた。

  • WEB — Web画面からの検索
  • JSON — JSON APIからの検索
  • XML — XML(GSA互換)APIからの検索
  • ADMIN — 管理画面からの検索
  • OTHER — その他

AI検索モード経由の検索もこの仕組みで記録されるが、これまではアクセスタイプが設定されていなかったため、デフォルトのWEBとして扱われていた。これでは、通常のWeb検索とAI検索モード経由の検索を検索ログから区別できない。

変更内容

ChatApiManagerでアクセスタイプを設定

ChatApiManagerprocessChat()processChatStream()の両メソッドで、リクエスト属性にLLMモデル名をアクセスタイプとして設定するようにした。

request.setAttribute(Constants.SEARCH_LOG_ACCESS_TYPE,
        ComponentUtil.getFessConfig().getSystemProperty("rag.llm.name", "ollama"));

モデル名はシステムプロパティrag.llm.nameから取得する。未設定の場合は"ollama"がデフォルト値となる。

SearchLogHelperでカスタムアクセスタイプに対応

従来のSearchLogHelperでは、アクセスタイプの判定が定義済み定数との一致チェックのみだったため、LLMモデル名のような任意の文字列を扱えなかった。今回、定義済みタイプに一致しない場合でも、空でない文字列であればそのままアクセスタイプとして記録するように変更した。

protected String determineAccessType(final Object accessType) {
    if (Constants.SEARCH_LOG_ACCESS_TYPE_JSON.equals(accessType)) {
        return Constants.SEARCH_LOG_ACCESS_TYPE_JSON;
    } else if (Constants.SEARCH_LOG_ACCESS_TYPE_GSA.equals(accessType)) {
        return Constants.SEARCH_LOG_ACCESS_TYPE_GSA;
    } else if (Constants.SEARCH_LOG_ACCESS_TYPE_OTHER.equals(accessType)) {
        return Constants.SEARCH_LOG_ACCESS_TYPE_OTHER;
    } else if (Constants.SEARCH_LOG_ACCESS_TYPE_ADMIN.equals(accessType)) {
        return Constants.SEARCH_LOG_ACCESS_TYPE_ADMIN;
    } else if (accessType instanceof String && StringUtil.isNotBlank((String) accessType)) {
        return (String) accessType;
    }
    return Constants.SEARCH_LOG_ACCESS_TYPE_WEB;
}

SearchLogHelperのリファクタリング

あわせて、SearchLogHelperaddSearchLog()メソッドをテストしやすい構造にリファクタリングした。

  • SearchLogContext内部クラスを導入し、ComponentUtilへの依存を分離
  • addSearchLog()createSearchLogContext()createSearchLog()に分割
  • determineAccessType()をprotectedメソッドとして抽出

これにより、モックコンポーネントの登録なしにアクセスタイプ判定のユニットテストが書けるようになった。

使い方

AI検索モードで使用するLLMのモデル名をrag.llm.nameシステムプロパティに設定する。

rag.llm.name=openai

この設定で、AI検索モード経由の検索ログのアクセスタイプがopenaiとして記録される。検索ログの分析時に、どのLLMモデルが使われた検索なのかを簡単に識別できるようになる。

FessのAI検索モードのログをfess-llm.logに分離  

FessのAI検索モード(RAG)を使っていると、LLM関連のログがfess.logに混ざってしまい、問題の切り分けがしづらいことがあった。そこで、LLM関連のログを専用のfess-llm.logに分離し、管理画面からログレベルを変更できるようにしました。

なぜ分離したのか

AI検索モードではLLMとのやり取りが発生するため、デバッグ時にはそれなりの量のログが出力される。これが通常の検索やクロールのログと一緒にfess.logに書き込まれると、必要な情報を探すのが大変になる。LLM関連のログを別ファイルに分けることで、AI検索モードの問題調査がやりやすくなる。

変更内容

fess-llm.logの追加

log4j2.xmlLlmFileというRollingFileアペンダーを追加し、以下の4パッケージのログをfess-llm.logに出力するようにした。

  • org.codelibs.fess.llm
  • org.codelibs.fess.chat
  • org.codelibs.fess.api.chat
  • org.codelibs.fess.app.web.chat

これらのロガーにはadditivity="false"を設定しているので、LLM関連のログはfess.logには出力されなくなる。ログのローテーション設定は既存のfess.logと同じ(時間+サイズベース、gzip圧縮)にしてある。

管理画面からのログレベル変更

管理画面の「一般設定」→「ログ設定」セクションに、LLM用のログレベルセレクターを追加した。選択できるレベルは以下の通り。

  • OFF
  • ERROR
  • WARN
  • INFO(デフォルト)
  • DEBUG
  • TRACE

ログレベルの変更はサーバーの再起動なしで即座に反映される。SystemHelpersetLlmLogLevel()メソッドで、Log4j2のConfigurator.setLevel()を使って対象パッケージのログレベルを動的に変更している。

システムプロパティ

fess.llm.log.levelというシステムプロパティでも初期ログレベルを指定できる。未設定の場合はINFOがデフォルトになる。

既存環境への影響

既存のログファイルへの影響はない。fess-llm.logは新規に追加されるファイルで、デフォルトのログレベルはINFOなので、特に設定を変更しなくてもそのまま使える。