mini-erp/mini-backend/docs/logging-plan.md

Plan: logging real por sesión de usuario

Problema actual (diagnosticado)

• main.py:32 fuerza setup_logging(environment="debug") siempre — el modo "production" (JSON estructurado) de logger_config.py nunca se activa, sin importar el entorno real de despliegue.
• core/sap.py, core/api_gateway.py y routers/auth.py usan print() en vez del logger real. Esto significa:
  • No queda nada en el archivo rotativo logs/backend.log (solo en la consola / docker compose logs).
  • No tiene formato JSON buscable, ni request_id de correlación.
• Grave: routers/auth.py imprime la contraseña (apellido) en texto plano dos veces:
  • línea ~27: print(f"Contraseña (Apellido) recibida: {empLastName}")
  • línea ~45: print(f"Apellido en SAP: {employee_data.get('LastName')}")

Objetivo

Además de arreglar lo anterior, dejar un log por sesión de usuario conectado: que cada línea de log quede etiquetada con qué empleado (emp_id + nombre) hizo qué acción (GET /Items, POST /BusinessPartners, etc.), en JSON, para poder cargarlo después en un monitor/dashboard y buscar acciones por usuario.

Diseño

context.py ya tiene un ContextVar para el request_id que se inyecta automáticamente en cada log a través de logger_config.JsonFormatter. Se replica el mismo patrón para el usuario conectado, así todo log queda etiquetado automáticamente sin tocar cada llamada individual.

1. context.py

Agregar un ContextVar para el usuario actual, mismo patrón que request_id_ctx:

current_user_ctx: ContextVar[dict] = ContextVar(
    "current_user", default={"emp_id": "-", "username": "-"}
)

def get_current_user() -> dict:
    return current_user_ctx.get()

def set_current_user(emp_id: str, username: str):
    current_user_ctx.set({"emp_id": emp_id, "username": username})

2. core/session.py

Agregar un helper que devuelva "Nombre Apellido" a partir de emp_id, leyendo el dict employee_sessions que ya existe:

def get_employee_name(emp_id: str) -> str:
    session = employee_sessions.get(emp_id)
    if not session:
        return "-"
    return f"{session.get('first_name', '')} {session.get('last_name', '')}".strip()

3. main.py

En session_middleware, justo después de validar el token y obtener emp_id (donde hoy se hace request.state.emp_id = emp_id), setear el contexto de usuario:

from core.session import validate_and_refresh_session, get_employee_name
from context import set_current_user
...
emp_id = validate_and_refresh_session(token)
if not emp_id:
    ...
set_current_user(emp_id, get_employee_name(emp_id))
request.state.emp_id = emp_id

También en este archivo: dejar de forzar "debug" en setup_logging, leerlo de una variable de entorno nueva (por defecto "production", para que Docker quede bien sin configurar nada extra):

LOG_ENVIRONMENT = os.getenv("LOG_ENVIRONMENT", "production")
...
@asynccontextmanager
async def lifespan(app: FastAPI):
    setup_logging(environment=LOG_ENVIRONMENT)
    yield

4. logger_config.py

Extender JsonFormatter para incluir emp_id/username desde el contexto en cada línea, y soportar campos extra estructurados (http_method, endpoint, status_code) cuando el log los trae vía extra={...}:

from context import get_request_id, get_current_user

class JsonFormatter(logging.Formatter):
    EXTRA_FIELDS = ("http_method", "endpoint", "status_code")

    def format(self, record):
        user = get_current_user()
        log_record = {
            "timestamp": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
            "level": record.levelname,
            "request_id": get_request_id(),
            "emp_id": user["emp_id"],
            "username": user["username"],
            "message": record.getMessage(),
            "module": record.module,
            "function": record.funcName,
            "line": record.lineno,
        }
        for field in self.EXTRA_FIELDS:
            if hasattr(record, field):
                log_record[field] = getattr(record, field)
        if record.exc_info:
            log_record["exception"] = self.formatException(record.exc_info)
        return json.dumps(log_record)

Resultado esperado por línea, por ejemplo:

{"timestamp": "2026-08-14T...", "level": "INFO", "request_id": "...", "emp_id": "11", "username": "Juan Pérez", "http_method": "GET", "endpoint": "Items", "status_code": 200, "message": "Solicitud SAP completada", "module": "sap", "function": "forward_to_sapb1", "line": 137}

5. core/sap.py / core/api_gateway.py

Reemplazar cada print(...) por logger.info/warning/error(...), agregando extra={"http_method": method, "endpoint": endpoint_path, "status_code": response.status_code} en las líneas de request/respuesta, para que queden como campos estructurados y no solo texto libre. Quitar la variable I = " " (indentación para prints, ya no hace falta) y los emojis (el nivel del log ya indica severidad).

6. routers/auth.py

• Agregar logger = logging.getLogger(__name__).
• Reemplazar todos los print() por logger.info/warning/error(...).
• No loguear nunca empLastName ni employee_data.get('LastName') — solo el emp_id y si el login fue exitoso o no.
• En cuanto se confirma el empleado (login exitoso), llamar set_current_user(empId, f"{first_name} {last_name}") para que el propio log del login quede etiquetado también (el middleware no aplica a /api/Login porque no requiere token todavía).

7. docker-compose.yml

Agregar volumen para que el log persista en el host aunque se reconstruya el contenedor (si no, se perdería cada --build, igual que pasaba con .env antes de agregar su volumen):

  backend:
    volumes:
      - ./mini-backend/menu_permissions.json:/app/menu_permissions.json:ro
      - ./mini-backend/logs:/app/logs

Verificación al implementar

1. Levantar el backend (local o Docker).
2. Loguearse con un usuario de prueba y hacer un par de llamadas reales (GET a algún catálogo, POST/PATCH a algo).
3. Revisar logs/backend.log: cada línea debe traer emp_id, username, http_method, endpoint, status_code correctos.
4. grep de la contraseña de prueba sobre todo logs/backend.log (y la salida de consola) para confirmar que no aparece en ningún lado.
5. Confirmar que docker compose build sigue funcionando sin errores.