From ae997914c29753ba167380d5b25bab1f07f7408e Mon Sep 17 00:00:00 2001 From: zukki259 Date: Mon, 24 Aug 2026 00:08:44 +0900 Subject: [PATCH] Make Discord reminder failures diagnosable MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit リマインドが「⚠️ 応答の生成に失敗しました」だけを返して原因が追えなかった ため、失敗経路を個別に捕まえてログにも残るようにする。 ロギング: uvicorn は自分のロガーしか設定しないため、アプリ側の logging.getLogger(__name__) は logging.lastResort 送りになっていた。 WARNING 未満が全て消え、出力にレベルもタイムスタンプもロガー名も付かず、 logger.info("Reminder created: ...") すら残らない状態だった。 main.py で basicConfig を呼び、LOG_LEVEL（既定 INFO）で制御する。 reminders.py: - choices[0].message の取り出しを個別に捕捉する。tool calling 非対応の エンドポイントは例外を投げずに choices が空の応答を返すことがあり、 ここで落ちると on_message の汎用ハンドラに流れて原因が消える - ツール実行を _run_tool() に切り出し、DBエラーを専用の文言で返す。 併せてDBセッションをツール1回分だけ開くようにした。LLMとの往復のあいだ 握り続けると SQLite のロックを長時間保持し、同時に走るAPIリクエストと 競合して "database is locked" を起こしうるため - tool_choice="auto" を渡すのをやめた。Bedrock はこの引数に非対応で、 今まで通っていたのは app.core.llm が litellm.drop_params=True を 立てている副作用に過ぎず、import 順が変われば壊れる。tools を渡した ときの既定が "auto" なので省いても挙動は変わらない - どのモデルで何を処理したかを INFO で残す CLAUDE.md には Lightsail への接続方法（作業ツリーにあった未コミット分）も 含む。 Co-Authored-By: Claude Opus 5 --- CLAUDE.md | 9 ++ backend/.env.example | 2 + backend/app/core/config.py | 3 + backend/app/core/discord/reminders.py | 118 +++++++++++++++++--------- backend/app/main.py | 13 ++- 5 files changed, 103 insertions(+), 42 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index a547d8f..32be099 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -153,6 +153,7 @@ LLM に渡すコンテキストは `app/core/memory_kb/memory.py` の `get_conte | `LOCAL_KB_MIN_SCORE` | `0.75` | ローカル KB を注入するコサイン類似度の下限 | | `CORS_ORIGINS` | `http://localhost:5173` | 許可する CORS オリジン | | `DEBUG` | `false` | LiteLLM デバッグログの有効化 | +| `LOG_LEVEL` | `INFO` | アプリ側ロガーの出力レベル。`main.py` の `basicConfig` に渡す | | `OPENAI_API_KEY` | — | OpenAI API キー | | `OPENAI_API_BASE` / `OPENAI_BASE_URL` | — | OpenAI 互換エンドポイントの接続先（ローカルの llama-server / Ollama 用）。設定したままだと `gpt-*` を選んでも本家 OpenAI に繋がらない。GUI 設定画面から実行時変更可 | | `ANTHROPIC_API_KEY` | — | Anthropic API キー | @@ -168,3 +169,11 @@ LLM に渡すコンテキストは `app/core/memory_kb/memory.py` の `get_conte | `REMINDER_MODEL` | — | リマインドの日時解釈に使うモデル（未設定なら `WEATHER_NOTIFY_MODEL` → `DEFAULT_MODEL`。tool calling 対応が必須） | | `SITE_PASSWORD` | — | サイト全体を保護する共有パスワード（未設定なら無認証） | | `SESSION_SECRET_KEY` | 起動毎に自動生成 | ログインセッション Cookie の署名鍵 | + +## AWS Lightsail環境 + +以下のコマンドで、lightsail上の環境に入ることができる。 + +```bash +ssh lightsail-playchat +``` diff --git a/backend/.env.example b/backend/.env.example index 4821e91..bf43cbd 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -87,3 +87,5 @@ REMINDER_MODEL= DATABASE_URL=sqlite:///./playchat.db MEMORY_SUMMARIZE_THRESHOLD=20 CORS_ORIGINS=http://localhost:5173 +# アプリ側ログの出力レベル（DEBUG / INFO / WARNING / ERROR） +LOG_LEVEL=INFO diff --git a/backend/app/core/config.py b/backend/app/core/config.py index cfd9ade..424bbbd 100644 --- a/backend/app/core/config.py +++ b/backend/app/core/config.py @@ -9,6 +9,9 @@ DEFAULT_MODEL: str = os.getenv("DEFAULT_MODEL", "gpt-4o") MEMORY_SUMMARIZE_THRESHOLD: int = int(os.getenv("MEMORY_SUMMARIZE_THRESHOLD", "20")) CORS_ORIGINS: list[str] = os.getenv("CORS_ORIGINS", "http://localhost:5173").split(",") DEBUG: bool = os.getenv("DEBUG", "false").lower() in ("1", "true", "yes") +# アプリ側ロガーの出力レベル。未設定だと logging.lastResort（WARNING以上・書式なし）に +# 落ちて logger.info が全部消えるため、main.py で明示的に設定する。 +LOG_LEVEL: str = os.getenv("LOG_LEVEL", "INFO").upper() # GUI設定画面（/api/settings）を保護する簡易パスワード。未設定の場合、設定画面は常に403で拒否する。 SETTINGS_PASSWORD: str | None = os.getenv("SETTINGS_PASSWORD") diff --git a/backend/app/core/discord/reminders.py b/backend/app/core/discord/reminders.py index 9fba293..d509c6d 100644 --- a/backend/app/core/discord/reminders.py +++ b/backend/app/core/discord/reminders.py @@ -245,6 +245,28 @@ def execute_reminder_tool(db, name: str, args: dict, ctx: ReminderContext) -> st return f"エラー: 未知のツール {name}" +class _ToolFailure(Exception): + """ツール実行そのものが失敗した（DBエラーなど）。モデルに投げ返さず即座に諦めるための印。""" + + +def _run_tool(name: str, args: dict, ctx: ReminderContext) -> str: + """ツール1回分だけDBセッションを開いて実行する。 + + LLMとの往復のあいだセッションを握り続けると、SQLite のロックを数秒〜数十秒 + 保持することになり、同時に走る API リクエストと競合して "database is locked" + を起こしうる。開いて閉じるのをツール単位にすることでそれを避ける。 + """ + db = SessionLocal() + try: + return execute_reminder_tool(db, name, args, ctx) + except Exception as e: + logger.exception("Reminder tool %s failed (args=%r)", name, args) + db.rollback() + raise _ToolFailure(name) from e + finally: + db.close() + + def _system_prompt() -> str: now = _local_now() weekday = "月火水木金土日"[now.weekday()] @@ -272,52 +294,66 @@ async def handle_reminder_request(content: str, ctx: ReminderContext, max_rounds {"role": "user", "content": content}, ] used_model = _model() - db = SessionLocal() - try: - for _ in range(max_rounds): - try: - response = await litellm.acompletion( - model=used_model, - messages=messages, - tools=REMINDER_TOOLS, - tool_choice="auto", - ) - except Exception: - logger.exception("Reminder LLM call failed [model=%s]", used_model) - return "⚠️ リマインドの登録に失敗しました。時間を変えてもう一度試してみてください。" + logger.info("Reminder request from %s [model=%s]: %s", ctx.user_name, used_model, content) + for round_no in range(1, max_rounds + 1): + try: + # tool_choice は渡さない。Bedrock が非対応で UnsupportedParamsError になり、 + # それを握り潰しているのは app.core.llm の litellm.drop_params=True という + # 別モジュールの副作用に過ぎない。tools を渡したときの既定が "auto" なので + # 省いても挙動は変わらず、その隠れた依存だけが消える。 + response = await litellm.acompletion( + model=used_model, + messages=messages, + tools=REMINDER_TOOLS, + ) + except Exception: + logger.exception("Reminder LLM call failed [model=%s round=%d]", used_model, round_no) + return "⚠️ リマインドの登録に失敗しました。時間を変えてもう一度試してみてください。" + + # tool calling 非対応のエンドポイントは、例外を投げずに choices が空だったり + # 形の違う応答を返すことがある。ここで落ちると原因が分からなくなるので個別に捕まえる。 + try: choice_message = response.choices[0].message - tool_calls = getattr(choice_message, "tool_calls", None) - if not tool_calls: - reply = (choice_message.content or "").strip() - return reply or "⚠️ リマインドの内容をうまく読み取れませんでした。日時と用件を教えてください。" + except (AttributeError, IndexError, KeyError, TypeError): + logger.exception( + "Unexpected completion shape [model=%s round=%d]: %r", used_model, round_no, response, + ) + return "⚠️ モデルからの応答を解釈できませんでした。tool calling に対応したモデルか確認してください。" - messages.append({ - "role": "assistant", - "content": choice_message.content or "", - "tool_calls": [ - { - "id": tc.id, - "type": "function", - "function": {"name": tc.function.name, "arguments": tc.function.arguments}, - } - for tc in tool_calls - ], - }) + tool_calls = getattr(choice_message, "tool_calls", None) + if not tool_calls: + reply = (choice_message.content or "").strip() + logger.info("Reminder request finished without tools [round=%d]", round_no) + return reply or "⚠️ リマインドの内容をうまく読み取れませんでした。日時と用件を教えてください。" - for tc in tool_calls: - try: - args = json.loads(tc.function.arguments or "{}") - except json.JSONDecodeError: - args = {} - result = execute_reminder_tool(db, tc.function.name, args, ctx) - messages.append({"role": "tool", "tool_call_id": tc.id, "content": result}) + messages.append({ + "role": "assistant", + "content": choice_message.content or "", + "tool_calls": [ + { + "id": tc.id, + "type": "function", + "function": {"name": tc.function.name, "arguments": tc.function.arguments}, + } + for tc in tool_calls + ], + }) - # max_rounds 使い切ってもツールを呼び続けている＝堂々巡り。登録自体は済んでいる可能性がある。 - logger.warning("Reminder tool loop exceeded %d rounds", max_rounds) - return "⚠️ うまく処理しきれませんでした。登録できているかは「リマインド一覧」と聞いて確認してください。" - finally: - db.close() + for tc in tool_calls: + try: + args = json.loads(tc.function.arguments or "{}") + except json.JSONDecodeError: + args = {} + try: + result = _run_tool(tc.function.name, args, ctx) + except _ToolFailure: + return "⚠️ リマインドの保存に失敗しました（データベースエラー）。サーバーのログを確認してください。" + messages.append({"role": "tool", "tool_call_id": tc.id, "content": result}) + + # max_rounds 使い切ってもツールを呼び続けている＝堂々巡り。登録自体は済んでいる可能性がある。 + logger.warning("Reminder tool loop exceeded %d rounds [model=%s]", max_rounds, used_model) + return "⚠️ うまく処理しきれませんでした。登録できているかは「リマインド一覧」と聞いて確認してください。" async def deliver_due_reminders() -> None: diff --git a/backend/app/main.py b/backend/app/main.py index 66aa601..5a0ded5 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -1,4 +1,5 @@ import asyncio +import logging from contextlib import asynccontextmanager from fastapi import Depends, FastAPI @@ -9,7 +10,7 @@ from app.api import chat, knowledge_base, logs, memory, notes, system from app.api import models as models_api from app.api import settings as settings_api from app.core import settings_store -from app.core.config import CORS_ORIGINS +from app.core.config import CORS_ORIGINS, LOG_LEVEL from app.core.site_auth import require_site_session from app.core.discord.discord_bot import start_discord_bot from app.core.discord.scheduler import start_scheduler @@ -17,6 +18,16 @@ from app.core.memory_kb.word_memory import seed_from_history from app.db.database import SessionLocal, init_db from app.db.models import Message, ModelPreset +# uvicorn は自分のロガーしか設定しないため、アプリ側の logging.getLogger(__name__) は +# 何もしないと logging.lastResort 送りになる。それだと WARNING 未満が消えるうえ、 +# 出力にレベルもタイムスタンプもロガー名も付かず、ログから障害を追えない。 +logging.basicConfig( + level=LOG_LEVEL, + format="%(asctime)s %(levelname)-8s %(name)s: %(message)s", +) +# LiteLLM は自前のハンドラを持つので、root にも流すと同じ行が二重に出る。 +logging.getLogger("LiteLLM").propagate = False + # ModelSelector.vue に元々ハードコードされていたプリセット。初回起動時のみDBへシードする。 _DEFAULT_MODEL_PRESETS = [ ("GPT-5.5", "gpt-5.5"),