From bac2a7a7808dd55ef09a78effb6724418fac94fa Mon Sep 17 00:00:00 2001 From: tsygankoviva Date: Thu, 25 Jun 2026 16:00:46 +0300 Subject: [PATCH] =?UTF-8?q?logs:=20=D0=BB=D0=BE=D0=B3=D0=B8=D1=80=D1=83?= =?UTF-8?q?=D0=B5=D0=BC=20=D0=B2=D1=80=D0=B5=D0=BC=D1=8F?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- api/src/api/v1/forms.py | 91 +++++++++++++++++++++++++++++++++++++ api/src/api/v1/projects.py | 31 +++++++++++++ api/src/api/v1/websocket.py | 18 ++++++++ api/src/main.py | 5 ++ 4 files changed, 145 insertions(+) diff --git a/api/src/api/v1/forms.py b/api/src/api/v1/forms.py index a14880b..78365cc 100644 --- a/api/src/api/v1/forms.py +++ b/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), @@ -206,6 +224,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), @@ -261,6 +295,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), @@ -310,6 +359,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), @@ -351,6 +415,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), @@ -384,6 +463,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], diff --git a/api/src/api/v1/projects.py b/api/src/api/v1/projects.py index 326a50c..b5291c4 100644 --- a/api/src/api/v1/projects.py +++ b/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)) diff --git a/api/src/api/v1/websocket.py b/api/src/api/v1/websocket.py index a9609be..d23a114 100644 --- a/api/src/api/v1/websocket.py +++ b/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( diff --git a/api/src/main.py b/api/src/main.py index 0045713..1fc02e3 100644 --- a/api/src/main.py +++ b/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,