feat: improve operation diagnostics and API logging

tests/test_release_help.py

@@ -59,6 +59,18 @@ class DeployNoticeTests(unittest.IsolatedAsyncioTestCase):
 
 
 class UserFacingErrorTests(unittest.IsolatedAsyncioTestCase):
+    async def test_failure_log_has_traceback_and_operation_id(self):
+        message = AsyncMock()
+        with bot.diagnostic_operation() as operation_id:
+            with self.assertLogs(bot.logger, level="ERROR") as captured:
+                try:
+                    raise ValueError("provider failure")
+                except ValueError as exc:
+                    await bot.report_error(message, "генерация поста", exc)
+        self.assertIn(f"operation_id={operation_id}", "\n".join(captured.output))
+        self.assertIn("Traceback (most recent call last)", "\n".join(captured.output))
+        self.assertIn("provider failure", "\n".join(captured.output))
+
     async def test_production_error_is_generic_without_exception_details(self):
         message = AsyncMock()
         with patch.object(bot, "DEPLOY_ENV", "production"):

tests/test_voice_stt.py

@@ -1,3 +1,4 @@
+import json
 import unittest
 from unittest.mock import patch
 
@@ -20,6 +21,9 @@ class FakeResponse:
     async def json(self, content_type=None):
         return self.payload
 
+    async def text(self):
+        return json.dumps(self.payload)
+
 
 class FakeClientSession:
     def __init__(self, response, **kwargs):

tests/test_writer_features.py

@@ -42,7 +42,9 @@ class FakeResponse:
     async def text(self):
         if isinstance(self.payload, bytes):
             return self.payload.decode("utf-8", errors="replace")
-        return str(self.payload)
+        if isinstance(self.payload, str):
+            return self.payload
+        return json.dumps(self.payload)
 
 
 
@@ -171,13 +173,14 @@ class ApinexTests(unittest.IsolatedAsyncioTestCase):
         self.assertEqual(detail["stage"], "screenshot_ocr")
 
     async def test_chat_api_failure_is_logged(self):
-        fake_session = FakeClientSession(FakeResponse(401, {}))
-        with patch.object(apinex_client.aiohttp, "ClientSession", return_value=fake_session):
-            with self.assertRaisesRegex(RuntimeError, "HTTP 401"):
-                await apinex_client.chat_text(
-                    "APINEX_POST_WRITER_MODEL", "private system prompt", "request",
-                    stage="post_generation", user_id=45, prompt_name="post_writer",
-                )
+        fake_session = FakeClientSession(FakeResponse(401, {"error": {"message": "invalid key"}}))
+        with self.assertLogs(apinex_client.logger, level="ERROR") as captured:
+            with patch.object(apinex_client.aiohttp, "ClientSession", return_value=fake_session):
+                with self.assertRaisesRegex(RuntimeError, "HTTP 401"):
+                    await apinex_client.chat_text(
+                        "APINEX_POST_WRITER_MODEL", "private system prompt", "request",
+                        stage="post_generation", user_id=45, prompt_name="post_writer",
+                    )
         logs = user_store.list_api_call_logs(limit=1, user_id=45)
         detail = user_store.get_api_call_log(logs[0]["id"] if isinstance(logs[0]["id"], int) else -1)
         self.assertIsNotNone(detail)
@@ -185,6 +188,50 @@ class ApinexTests(unittest.IsolatedAsyncioTestCase):
         self.assertEqual(detail["status_code"], 401)
         self.assertNotIn("private system prompt", str(detail["request_json"]))
         self.assertEqual(json.loads(str(detail["request_json"]))["prompt"]["name"], "post_writer")
+        self.assertEqual(
+            json.loads(str(detail["response_json"])),
+            {"provider_error_body": {"error": {"message": "invalid key"}}},
+        )
+        self.assertIsInstance(detail["duration_ms"], int)
+        self.assertIn('"provider_error_body"', "\n".join(captured.output))
+
+    async def test_empty_model_response_logs_raw_response_and_operation_id(self):
+        response = {"choices": [{"message": {"content": ""}, "finish_reason": "stop"}]}
+        fake_session = FakeClientSession(FakeResponse(200, response))
+        with (
+            patch.object(apinex_client.aiohttp, "ClientSession", return_value=fake_session),
+            apinex_client.diagnostic_operation() as operation_id,
+        ):
+            with self.assertRaisesRegex(RuntimeError, "empty model response"):
+                await apinex_client.chat_text(
+                    "APINEX_POST_WRITER_MODEL", "system", "request", stage="intent_classification", user_id=46
+                )
+        logs = user_store.list_api_call_logs(limit=1, user_id=46)
+        detail = user_store.get_api_call_log(logs[0]["id"] if isinstance(logs[0]["id"], int) else -1)
+        self.assertIsNotNone(detail)
+        assert detail is not None
+        self.assertEqual(detail["operation_id"], operation_id)
+        self.assertEqual(json.loads(str(detail["response_json"])), response)
+        self.assertEqual(detail["status_code"], 200)
+        self.assertIsInstance(detail["duration_ms"], int)
+
+    async def test_api_log_redacts_secrets_but_keeps_token_limits(self):
+        await apinex_client._record_api_call(
+            stage="test", model="model", prompt_name="test", system_prompt="",
+            request={"max_tokens": 1800, "api_key": "private-key"},
+            response={"authorization": "Bearer private-token", "detail": "Bearer private-token"},
+        )
+        log = user_store.list_api_call_logs(limit=1)[0]
+        log_id = log["id"]
+        self.assertIsInstance(log_id, int)
+        detail = user_store.get_api_call_log(log_id if isinstance(log_id, int) else -1)
+        assert detail is not None
+        request = json.loads(str(detail["request_json"]))
+        response = json.loads(str(detail["response_json"]))
+        self.assertEqual(request["max_tokens"], 1800)
+        self.assertEqual(request["api_key"], "[REDACTED]")
+        self.assertEqual(response["authorization"], "[REDACTED]")
+        self.assertEqual(response["detail"], "Bearer [REDACTED]")
 
     async def test_writer_preserves_multiline_post_without_labels(self):
         multiline_post = "Привет!\n\nВот новость ☕"
@@ -371,6 +418,28 @@ class ScreenshotToneWorkflowTests(unittest.IsolatedAsyncioTestCase):
 
 
 class StorageTests(unittest.TestCase):
+    def test_api_log_schema_migrates_existing_database(self):
+        import sqlite3
+        import tempfile
+        from pathlib import Path
+
+        with tempfile.TemporaryDirectory() as temp_dir:
+            db = str(Path(temp_dir) / "old.sqlite3")
+            with sqlite3.connect(db) as connection:
+                connection.execute(
+                    """CREATE TABLE api_call_logs (
+                        id INTEGER PRIMARY KEY AUTOINCREMENT, telegram_user_id INTEGER, stage TEXT NOT NULL,
+                        model TEXT NOT NULL DEFAULT '', prompt_sha256 TEXT NOT NULL DEFAULT '', request_json TEXT NOT NULL,
+                        response_json TEXT NOT NULL DEFAULT '', status_code INTEGER, error TEXT NOT NULL DEFAULT '',
+                        created_at TEXT NOT NULL DEFAULT CURRENT_TIMESTAMP
+                    )"""
+                )
+            user_store.init_db(db)
+            with sqlite3.connect(db) as connection:
+                columns = {row[1] for row in connection.execute("PRAGMA table_info(api_call_logs)")}
+            self.assertIn("operation_id", columns)
+            self.assertIn("duration_ms", columns)
+
     def test_user_tone_isolated_per_id(self):
         import tempfile
         from pathlib import Path
@@ -400,11 +469,15 @@ class StorageTests(unittest.TestCase):
                 user_id=12,
                 status_code=502,
                 error="HTTP 502",
+                operation_id="op-123",
+                duration_ms=250,
                 db_path=db,
             )
             summary = user_store.list_api_call_logs(limit=5, user_id=12, db_path=db)
             self.assertEqual(summary[0]["id"], log_id)
             self.assertNotIn("request_json", summary[0])
+            self.assertEqual(summary[0]["operation_id"], "op-123")
+            self.assertEqual(summary[0]["duration_ms"], 250)
             detail = user_store.get_api_call_log(log_id, db)
             self.assertIsNotNone(detail)
             assert detail is not None