Merge pull request 'logs: логируем время' (#2) from logs into test

Reviewed-on: #2
Reviewed-by: Raykov-MS <RaykovMS@avt.rshb.ru>

api/src/api/v1/forms.py

@@ -1,3 +1,4 @@
+import logging
 import time
 from typing import Optional
 
@@ -20,6 +21,9 @@ SHEETS_WITH_SECTIONS = {"AHR", "CAP", "OPER"}
 FORM1_DIRECTION_REQUIRED_SHEETS = {"AHR", "CAP"}
 
 
+logger = logging.getLogger()
+
+
 def _rows_to_sheet_response(result: list[tuple]) -> list[SheetResponse]:
     return [
         SheetResponse(
@@ -153,6 +157,20 @@ async def get_sheet(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "get_sheet",
+        "form_id": form_id,
+        "sheet": sheet,
+        "direction": direction,
+        "sections": sections,
+        "user": current_user.id,
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(
             count=len(result),
             result=_rows_to_sheet_response(result),
@@ -200,6 +218,22 @@ async def update_cell(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "update_form_cell",
+        "form_id": form_id,
+        "sheet": sheet,
+        "direction": direction,
+        "sections": sections,
+        "user": current_user.id,
+        "line_id": cell_body.line_id, 
+        "column": cell_body.column, 
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(
             count=len(result),
             result=_rows_to_sheet_response(result),
@@ -247,6 +281,21 @@ async def update_cells(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "update_form_cells",
+        "form_id": form_id,
+        "sheet": sheet,
+        "direction": direction,
+        "sections": sections,
+        "user": current_user.id,
+        "count": len(cells_body.changes)
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(
             count=len(result),
             result=_rows_to_sheet_response(result),
@@ -296,6 +345,21 @@ async def add_line(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "add_form_line",
+        "form_id": form_id,
+        "sheet": sheet,
+        "direction": body.direction,
+        "user": current_user.id,
+        "expense_item_id": body.expense_item_id
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(
             count=len(result),
             result=_rows_to_sheet_response(result),
@@ -337,6 +401,21 @@ async def delete_line(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "del_form_line",
+        "form_id": form_id,
+        "sheet": sheet,
+        "direction": direction,
+        "user": current_user.id,
+        "line_id": row_id,
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
+
     return BaseListResponse(
         count=len(result),
         result=_rows_to_sheet_response(result),
@@ -370,6 +449,18 @@ async def add_form(
 
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "add_form",
+        "form_type_code": form.form_type_code,
+        "user": current_user.id,
+        "count_orgs": len(form.org_unit_ids),
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
 
     return BaseListResponse(
         result=[BudgetFormResponse.model_validate(new_form) for new_form in new_forms],

api/src/api/v1/projects.py

@@ -1,3 +1,4 @@
+import logging
 import time
 from typing import Optional
 
@@ -20,6 +21,9 @@ from src.domain.schemas import (
 from src.services.project_service import ProjectService
 
 
+logger = logging.getLogger()
+
+
 router = APIRouter(tags=["forms"])
 FORM3_ALLOWED_SECTIONS = {"q1", "q2", "q3", "q4", "year"}
 
@@ -96,6 +100,20 @@ async def get_project_report(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "get_project_report",
+        "project_id": project_id,
+        "year": year,
+        "report_type": report_type,
+        "sections": sections,
+        "user": current_user.id,
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(count=len(rows), result=_rows_to_payload(rows))
 
 
@@ -118,6 +136,19 @@ async def get_rf_rollup(
     )
     db_ms = (time.perf_counter() - t0) * 1000
     response.headers["X-DB-Time-Ms"] = f"{db_ms:.2f}"
+    extra={
+        "type": "db_time",
+        "time_ms": f"{db_ms:.2f}", 
+        "handler": "get_project_report",
+        "branch_id": branch_id,
+        "year": year,
+        "sections": sections,
+        "user": current_user.id,
+    }
+    logger.info(
+        f"db_time: {extra}", 
+        extra=extra,
+    )
     return BaseListResponse(count=len(rows), result=_rows_to_payload(rows))
 
 

api/src/api/v1/websocket.py

@@ -4,6 +4,8 @@ from dataclasses import asdict
 import dataclasses
 import enum
 from json import dumps, loads
+import logging
+import time
 from typing import Any, Optional
 
 #
@@ -26,6 +28,9 @@ from src.db.session import SessionLocal
 from src.services.user_service import UserService
 
 
+logger = logging.getLogger()
+
+
 @asynccontextmanager
 async def get_db_session(user_id: int | None = None):
     """Контекстный менеджер для получения сессии базы данных."""
@@ -770,12 +775,25 @@ async def process_websocket(
 
                 async with get_db_session(user_id=user_id) as db:
                     processor = processor_cls(db)
+                    t0 = time.perf_counter()
                     data["result"] = await processor.process(
                         event_data=data, 
                         user_id=user_id,
                         **kwargs_process
                     )
                     await db.commit()
+                    db_ms = (time.perf_counter() - t0) * 1000
+
+                    extra = {
+                        "type": "db_time",
+                        "time_ms": f"{db_ms:.2f}", 
+                        "event": data.get("event"),
+                    }
+                    extra.update(data)
+                    logger.info(
+                        f"db_time: {extra}", 
+                        extra=extra,
+                    )
                 
                 if data.get("event") == "row_deleted":
                     manager.release_locks_for_row(

api/src/main.py

@@ -1,4 +1,5 @@
 import asyncio
+import logging
 import os
 from contextlib import asynccontextmanager
 from datetime import datetime, timezone
@@ -20,6 +21,10 @@ from src.core.exception_handlers import register_exception_handlers
 from src.db.base import engine
 from src.db.session import create_tables
 
+
+
+logging.basicConfig(level=logging.INFO)
+
 # if not settings.DEBUG:
 #     from raisa_fastapi_protected_api import (
 #         AuthorizationMiddleware,